-- Logs begin at Thu 2019-02-14 10:11:58 GMT, end at Sun 2024-12-01 18:39:01 GMT. -- Dec 01 18:38:00 localhost kernel: usb 3-2: USB disconnect, device number 8 Dec 01 18:38:01 localhost kernel: usb 3-2: new full-speed USB device number 9 using xhci-hcd Dec 01 18:38:01 localhost kernel: usb 3-2: New USB device found, idVendor=1a86, idProduct=e5e3, bcdDevice= 0.00 Dec 01 18:38:01 localhost kernel: usb 3-2: New USB device strings: Mfr=1, Product=2, SerialNumber=0 Dec 01 18:38:01 localhost kernel: usb 3-2: Product: USB2IIC_CTP_CONTROL Dec 01 18:38:01 localhost kernel: usb 3-2: Manufacturer: wch.cn Dec 01 18:38:01 localhost kernel: input: wch.cn USB2IIC_CTP_CONTROL as /devices/platform/axi/1000120000.pcie/1f00300000.usb/xhci-hcd.1/usb3/3-2/3-2:1.0/0003:1A86:E5E3.0008/input/input13 Dec 01 18:38:01 localhost kernel: hid-multitouch 0003:1A86:E5E3.0008: input,hidraw0: USB HID v1.00 Device [wch.cn USB2IIC_CTP_CONTROL] on usb-xhci-hcd.1-2/input0 Dec 01 18:38:01 localhost systemd-udevd[6932]: Process '/usr/sbin/th-cmd --socket /var/run/thd.socket --passfd --udev' failed with exit code 1. Dec 01 18:38:01 localhost systemd-udevd[6933]: Process '/usr/sbin/th-cmd --socket /var/run/thd.socket --passfd --udev' failed with exit code 1. Dec 01 18:38:02 localhost volumio[1201]: info: Getting Spotify volume Dec 01 18:38:02 localhost volumio[1201]: info: Spotify volume: 100 Dec 01 18:38:02 localhost volumio[1201]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 13 Dec 01 18:38:02 localhost volumio[1201]: info: CoreCommandRouter::volumioGetState Dec 01 18:38:02 localhost volumio[1201]: info: CorePlayQueue::getTrack 1 Dec 01 18:38:02 localhost volumio[1201]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Dec 01 18:38:08 localhost go-librespot[6923]: time="2024-12-01T18:38:08Z" level=debug msg="handling transfer player command from e5eb37b5a9195e0aa8aad9588c5bfcd7f81f46c7" Dec 01 18:38:08 localhost go-librespot[6923]: time="2024-12-01T18:38:08Z" level=debug msg="resolved context of track" uri="spotify:user:gsingle:collection" Dec 01 18:38:08 localhost go-librespot[6923]: time="2024-12-01T18:38:08Z" level=trace msg="fetched new page 0 with 33 items (list: 33)" uri="spotify:user:gsingle:collection" Dec 01 18:38:08 localhost go-librespot[6923]: time="2024-12-01T18:38:08Z" level=debug msg="loading track (paused: false, position: 23977ms)" uri="spotify:track:6SDQETfHW9JT9p99S3nB44" Dec 01 18:38:08 localhost go-librespot[6923]: time="2024-12-01T18:38:08Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 01 18:38:08 localhost go-librespot[6923]: time="2024-12-01T18:38:08Z" level=trace msg="emitting websocket event: will_play" Dec 01 18:38:08 localhost volumio[1201]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:6SDQETfHW9JT9p99S3nB44","play_origin":"collection-songs"}} Dec 01 18:38:08 localhost go-librespot[6923]: time="2024-12-01T18:38:08Z" level=debug msg="selected format OGG_VORBIS_320 (7864d7162aeab8bafe94834456d248f12931e211)" uri="spotify:track:6SDQETfHW9JT9p99S3nB44" Dec 01 18:38:08 localhost go-librespot[6923]: time="2024-12-01T18:38:08Z" level=debug msg="requested aes key for file 7864d7162aeab8bafe94834456d248f12931e211, gid: 6SDQETfHW9JT9p99S3nB44" Dec 01 18:38:08 localhost go-librespot[6923]: time="2024-12-01T18:38:08Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241" Dec 01 18:38:08 localhost go-librespot[6923]: time="2024-12-01T18:38:08Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1282" Dec 01 18:38:09 localhost go-librespot[6923]: time="2024-12-01T18:38:09Z" level=debug msg="fetched first chunk of 17, total size is 8618060 bytes" uri="spotify:track:6SDQETfHW9JT9p99S3nB44" Dec 01 18:38:09 localhost go-librespot[6923]: time="2024-12-01T18:38:09Z" level=debug msg="fetched chunk 1/16, size: 524288" uri="spotify:track:6SDQETfHW9JT9p99S3nB44" Dec 01 18:38:09 localhost go-librespot[6923]: time="2024-12-01T18:38:09Z" level=trace msg="seek to 23977ms (diff: 48ms, samples: 1057385, bytes: 885698)" uri="spotify:track:6SDQETfHW9JT9p99S3nB44" Dec 01 18:38:09 localhost go-librespot[6923]: time="2024-12-01T18:38:09Z" level=debug msg="created new output device" Dec 01 18:38:09 localhost go-librespot[6923]: time="2024-12-01T18:38:09Z" level=info msg="loaded track \"Time - Alan Walker Remix - Extended Version\" (paused: false, position: 23977ms, duration: 215625ms, prefetched: false)" uri="spotify:track:6SDQETfHW9JT9p99S3nB44" Dec 01 18:38:09 localhost go-librespot[6923]: go-librespot: pcm_meter.c:1216: snd_pcm_scope_s16_get_channel_buffer: Assertion `s16->buf_areas' failed. Dec 01 18:38:09 localhost go-librespot[6923]: Aborted Dec 01 18:38:09 localhost volumio[1201]: info: Connection to go-librespot Websocket closed Dec 01 18:38:09 localhost systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=134/n/a Dec 01 18:38:09 localhost systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 01 18:38:12 localhost volumio[1201]: info: Initializing connection to go-librespot Websocket Dec 01 18:38:12 localhost volumio[1201]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 01 18:38:12 localhost systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Dec 01 18:38:12 localhost systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Dec 01 18:38:12 localhost systemd[1]: Stopped go-librespot Daemon. Dec 01 18:38:12 localhost systemd[1]: Started go-librespot Daemon. Dec 01 18:38:12 localhost go-librespot[6961]: Librespot-go daemon starting... Dec 01 18:38:12 localhost go-librespot[6961]: time="2024-12-01T18:38:12Z" level=info msg="generated new device id: 0202d6da3a6b541c5fabaa599a8380768b46d208" Dec 01 18:38:12 localhost go-librespot[6961]: time="2024-12-01T18:38:12Z" level=debug msg="stored credentials found for gsingle" Dec 01 18:38:12 localhost go-librespot[6961]: time="2024-12-01T18:38:12Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Dec 01 18:38:12 localhost go-librespot[6961]: time="2024-12-01T18:38:12Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 01 18:38:12 localhost go-librespot[6961]: time="2024-12-01T18:38:12Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 01 18:38:12 localhost go-librespot[6961]: time="2024-12-01T18:38:12Z" level=debug msg="zeroconf server listening on port 35537" Dec 01 18:38:12 localhost go-librespot[6961]: time="2024-12-01T18:38:12Z" level=debug msg="obtained new client token: AADM1dNO3alexeTad+Lth8dTHH/pWVWIHZ2xGkkUIzrz1dSz6tIrSxpR2OpBpbu6bno2AcozeCg9ONT2pBfQVtUi+NdbN3OktlBp0mCN4JVdpfe5TU0SilJzYNoz+Lep9LRlzeBN0w/rSJGU5lK1yw1utSaAobgRl/WwuoaX+2/0wF1fJtt6ct3ZvqLL7hw4edDfNjSRmE5q8ac+S6wUsc5/5Me7DYNe1INIfcFkuSyZ0bAmz+qL4jXKsbUasaM=" Dec 01 18:38:12 localhost go-librespot[6961]: time="2024-12-01T18:38:12Z" level=info msg="connected to ap-gew1.spotify.com:4070" Dec 01 18:38:12 localhost go-librespot[6961]: time="2024-12-01T18:38:12Z" level=debug msg="completed keyexchange" Dec 01 18:38:13 localhost go-librespot[6961]: time="2024-12-01T18:38:13Z" level=debug msg="completed challenge" Dec 01 18:38:13 localhost go-librespot[6961]: time="2024-12-01T18:38:13Z" level=debug msg="authenticated as gsingle" Dec 01 18:38:13 localhost go-librespot[6961]: time="2024-12-01T18:38:13Z" level=debug msg="authenticated as gsingle" Dec 01 18:38:13 localhost go-librespot[6961]: time="2024-12-01T18:38:13Z" level=debug msg="dealer connection opened" Dec 01 18:38:13 localhost go-librespot[6961]: time="2024-12-01T18:38:13Z" level=debug msg="initializing zeroconf session, username: gsingle" Dec 01 18:38:13 localhost go-librespot[6961]: time="2024-12-01T18:38:13Z" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Dec 01 18:38:13 localhost go-librespot[6961]: time="2024-12-01T18:38:13Z" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Dec 01 18:38:13 localhost go-librespot[6961]: time="2024-12-01T18:38:13Z" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Dec 01 18:38:13 localhost go-librespot[6961]: time="2024-12-01T18:38:13Z" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Dec 01 18:38:13 localhost go-librespot[6961]: time="2024-12-01T18:38:13Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Dec 01 18:38:13 localhost go-librespot[6961]: time="2024-12-01T18:38:13Z" level=debug msg="autoplay enabled: false" Dec 01 18:38:13 localhost go-librespot[6961]: time="2024-12-01T18:38:13Z" level=debug msg="received connection id: NGFjMDQxZGQtNTBlNC00ODZkLWIwZTUtZmJjMWM0M2MwZWUyK2RlYWxlcit0Y3A6Ly8wYWNhNDE5Yi5pcC5nZXcxLnNwb3RpZnkubmV0OjU3MDArRjdBODcwODlEM0Q5QTU1MjNFRDhCMUQyNzFCMDgzMjM4MzI5OEI2RkMyNDcxNkVGNzJGMEYyQzE1NEJCODE0NA==" Dec 01 18:38:13 localhost volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 01 18:38:13 localhost volumio[1201]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 01 18:38:13 localhost volumio[1201]: info: Discovery: Getting this device information Dec 01 18:38:13 localhost volumio[1201]: info: CoreCommandRouter::volumioGetState Dec 01 18:38:13 localhost volumio[1201]: info: CorePlayQueue::getTrack 1 Dec 01 18:38:13 localhost volumio[1201]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 01 18:38:13 localhost go-librespot[6961]: time="2024-12-01T18:38:13Z" level=debug msg="put connect state because NEW_DEVICE" Dec 01 18:38:15 localhost volumio[1201]: info: Initializing connection to go-librespot Websocket Dec 01 18:38:15 localhost volumio[1201]: info: Connection to go-librespot Websocket established Dec 01 18:38:15 localhost go-librespot[6961]: time="2024-12-01T18:38:15Z" level=debug msg="new websocket client" Dec 01 18:38:18 localhost volumio[1201]: info: Getting Spotify volume Dec 01 18:38:18 localhost volumio[1201]: info: Spotify volume: 100 Dec 01 18:38:18 localhost volumio[1201]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 13 Dec 01 18:38:18 localhost volumio[1201]: info: CoreCommandRouter::volumioGetState Dec 01 18:38:18 localhost volumio[1201]: info: CorePlayQueue::getTrack 1 Dec 01 18:38:18 localhost volumio[1201]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Dec 01 18:38:33 localhost sudo[7005]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 01 18:38:33 localhost sudo[7005]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 01 18:38:33 localhost sudo[7005]: pam_unix(sudo:session): session closed for user root Dec 01 18:38:33 localhost sudo[7008]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 01 18:38:33 localhost sudo[7008]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 01 18:38:33 localhost sudo[7008]: pam_unix(sudo:session): session closed for user root Dec 01 18:38:33 localhost volumio[1201]: verbose: New Socket.io Connection to 192.168.56.172 from 192.168.56.176 UA: Mozilla/5.0 (Linux; Android 14; SM-S928B Build/UP1A.231005.007; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/131.0.6778.39 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 13 Dec 01 18:38:33 localhost sudo[7025]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 01 18:38:33 localhost sudo[7025]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 01 18:38:33 localhost sudo[7025]: pam_unix(sudo:session): session closed for user root Dec 01 18:38:33 localhost sudo[7028]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 01 18:38:33 localhost sudo[7028]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 01 18:38:33 localhost sudo[7028]: pam_unix(sudo:session): session closed for user root Dec 01 18:38:33 localhost volumio[1201]: verbose: New Socket.io Connection to 192.168.56.172 from 192.168.56.176 UA: Mozilla/5.0 (Linux; Android 14; SM-S928B Build/UP1A.231005.007; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/131.0.6778.39 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 14 Dec 01 18:38:33 localhost volumio[1201]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Dec 01 18:38:33 localhost volumio[1201]: info: CoreCommandRouter::volumioGetVisibleSources Dec 01 18:38:33 localhost volumio[1201]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 01 18:38:33 localhost volumio[1201]: info: CoreCommandRouter::volumioGetState Dec 01 18:38:33 localhost volumio[1201]: info: CorePlayQueue::getTrack 1 Dec 01 18:38:33 localhost volumio[1201]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Dec 01 18:38:33 localhost volumio[1201]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Dec 01 18:38:33 localhost volumio[1201]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Dec 01 18:38:33 localhost volumio[1201]: info: Received Get System Info Dec 01 18:38:33 localhost volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 01 18:38:33 localhost volumio[1201]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 01 18:38:33 localhost volumio[1201]: info: Discovery: Getting this device information Dec 01 18:38:33 localhost volumio[1201]: info: CoreCommandRouter::volumioGetState Dec 01 18:38:33 localhost volumio[1201]: info: CorePlayQueue::getTrack 1 Dec 01 18:38:33 localhost volumio[1201]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 01 18:38:33 localhost volumio[1201]: info: CoreCommandRouter::volumioGetState Dec 01 18:38:33 localhost volumio[1201]: info: CorePlayQueue::getTrack 1 Dec 01 18:38:33 localhost volumio[1201]: info: Listing playlists Dec 01 18:38:33 localhost volumio[1201]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Dec 01 18:38:33 localhost volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Dec 01 18:38:33 localhost volumio[1201]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Dec 01 18:38:34 localhost volumio[1201]: info: CoreCommandRouter::volumioPlay Dec 01 18:38:34 localhost volumio[1201]: info: CoreStateMachine::play index undefined Dec 01 18:38:34 localhost volumio[1201]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 01 18:38:34 localhost volumio[1201]: info: CorePlayQueue::getTrack 1 Dec 01 18:38:34 localhost volumio[1201]: info: CoreStateMachine::startPlaybackTimer Dec 01 18:38:34 localhost volumio[1201]: info: CorePlayQueue::getTrack 1 Dec 01 18:38:34 localhost volumio[1201]: info: [1733078314791] ControllerSpotify::clearAddPlayTrack Dec 01 18:38:34 localhost volumio[1201]: info: Sending Spotify command with payload to local API: /player/play Dec 01 18:38:34 localhost go-librespot[6961]: time="2024-12-01T18:38:34Z" level=debug msg="resolved context of track" uri="spotify:track:2oKH22tSUiqdjDSUhnWz0t" Dec 01 18:38:34 localhost go-librespot[6961]: time="2024-12-01T18:38:34Z" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:2oKH22tSUiqdjDSUhnWz0t" Dec 01 18:38:34 localhost go-librespot[6961]: time="2024-12-01T18:38:34Z" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:2oKH22tSUiqdjDSUhnWz0t" Dec 01 18:38:34 localhost volumio[1201]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Dec 01 18:38:34 localhost go-librespot[6961]: time="2024-12-01T18:38:34Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 01 18:38:34 localhost go-librespot[6961]: time="2024-12-01T18:38:34Z" level=trace msg="emitting websocket event: will_play" Dec 01 18:38:34 localhost volumio[1201]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:2oKH22tSUiqdjDSUhnWz0t","play_origin":"go-librespot"}} Dec 01 18:38:34 localhost go-librespot[6961]: time="2024-12-01T18:38:34Z" level=debug msg="selected format OGG_VORBIS_320 (5e0f68dcfa68776fcfa6bc8a99085fa3c6f060b2)" uri="spotify:track:2oKH22tSUiqdjDSUhnWz0t" Dec 01 18:38:34 localhost go-librespot[6961]: time="2024-12-01T18:38:34Z" level=debug msg="requested aes key for file 5e0f68dcfa68776fcfa6bc8a99085fa3c6f060b2, gid: 2oKH22tSUiqdjDSUhnWz0t" Dec 01 18:38:34 localhost go-librespot[6961]: time="2024-12-01T18:38:34Z" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Dec 01 18:38:34 localhost go-librespot[6961]: time="2024-12-01T18:38:34Z" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Dec 01 18:38:34 localhost go-librespot[6961]: time="2024-12-01T18:38:34Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241" Dec 01 18:38:34 localhost go-librespot[6961]: time="2024-12-01T18:38:34Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1282" Dec 01 18:38:35 localhost go-librespot[6961]: time="2024-12-01T18:38:35Z" level=debug msg="fetched first chunk of 15, total size is 7369168 bytes" uri="spotify:track:2oKH22tSUiqdjDSUhnWz0t" Dec 01 18:38:35 localhost go-librespot[6961]: time="2024-12-01T18:38:35Z" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" uri="spotify:track:2oKH22tSUiqdjDSUhnWz0t" Dec 01 18:38:35 localhost go-librespot[6961]: time="2024-12-01T18:38:35Z" level=debug msg="created new output device" Dec 01 18:38:35 localhost go-librespot[6961]: time="2024-12-01T18:38:35Z" level=info msg="loaded track \"house in the streetlight\" (paused: false, position: 0ms, duration: 175113ms, prefetched: false)" uri="spotify:track:2oKH22tSUiqdjDSUhnWz0t" Dec 01 18:38:35 localhost go-librespot[6961]: go-librespot: pcm_meter.c:1216: snd_pcm_scope_s16_get_channel_buffer: Assertion `s16->buf_areas' failed. Dec 01 18:38:35 localhost go-librespot[6961]: Aborted Dec 01 18:38:35 localhost systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=134/n/a Dec 01 18:38:35 localhost volumio[1201]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 01 18:38:35 localhost systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 01 18:38:35 localhost volumio[1201]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up Dec 01 18:38:35 localhost volumio[1201]: info: Received Get System Info Dec 01 18:38:35 localhost volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 01 18:38:35 localhost volumio[1201]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 01 18:38:35 localhost volumio[1201]: info: Discovery: Getting this device information Dec 01 18:38:35 localhost volumio[1201]: info: CoreCommandRouter::volumioGetState Dec 01 18:38:35 localhost volumio[1201]: info: CorePlayQueue::getTrack 1 Dec 01 18:38:35 localhost volumio[1201]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 01 18:38:35 localhost volumio[1201]: info: Connection to go-librespot Websocket closed Dec 01 18:38:35 localhost volumio[1201]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 01 18:38:35 localhost volumio[1201]: info: Received Get System Info Dec 01 18:38:35 localhost volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 01 18:38:35 localhost volumio[1201]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 01 18:38:35 localhost volumio[1201]: info: Discovery: Getting this device information Dec 01 18:38:35 localhost volumio[1201]: info: CoreCommandRouter::volumioGetState Dec 01 18:38:35 localhost volumio[1201]: info: CorePlayQueue::getTrack 1 Dec 01 18:38:35 localhost volumio[1201]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 01 18:38:38 localhost volumio[1201]: info: Initializing connection to go-librespot Websocket Dec 01 18:38:38 localhost volumio[1201]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 01 18:38:38 localhost systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Dec 01 18:38:38 localhost systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Dec 01 18:38:38 localhost systemd[1]: Stopped go-librespot Daemon. Dec 01 18:38:38 localhost systemd[1]: Started go-librespot Daemon. Dec 01 18:38:38 localhost go-librespot[7036]: Librespot-go daemon starting... Dec 01 18:38:38 localhost go-librespot[7036]: time="2024-12-01T18:38:38Z" level=info msg="generated new device id: 2955f3e31e3c87167c8a8f737773098f5ea44287" Dec 01 18:38:38 localhost go-librespot[7036]: time="2024-12-01T18:38:38Z" level=debug msg="stored credentials found for gsingle" Dec 01 18:38:38 localhost go-librespot[7036]: time="2024-12-01T18:38:38Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Dec 01 18:38:38 localhost go-librespot[7036]: time="2024-12-01T18:38:38Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 01 18:38:38 localhost go-librespot[7036]: time="2024-12-01T18:38:38Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 01 18:38:38 localhost go-librespot[7036]: time="2024-12-01T18:38:38Z" level=debug msg="zeroconf server listening on port 42147" Dec 01 18:38:38 localhost go-librespot[7036]: time="2024-12-01T18:38:38Z" level=debug msg="obtained new client token: AADIOH02ZZvcd/8YluoVEfqSbvRePv0fhSulMlSwZxOnkTVjom8ggIswgvESbCeq3QRIAPEq6C1FOA3wSB24X1THa1kQylCKjRPajdt7+jX7qVoxQ0OpTaOeKSE4S1A7NZMjTLQ9uj01KjXbeKn/ghtGunzQSrSjnwaM9dTnJzGoXxEvxhYDSvrsB2QYCdePdhEP4pyBqmCN2cvfLGUSlpj4UYR8ij/9wGHCtrGeEiDwvHmD3WUYGMoKbD73J6s=" Dec 01 18:38:38 localhost go-librespot[7036]: time="2024-12-01T18:38:38Z" level=info msg="connected to ap-gew1.spotify.com:4070" Dec 01 18:38:38 localhost go-librespot[7036]: time="2024-12-01T18:38:38Z" level=debug msg="completed keyexchange" Dec 01 18:38:39 localhost go-librespot[7036]: time="2024-12-01T18:38:39Z" level=debug msg="completed challenge" Dec 01 18:38:39 localhost go-librespot[7036]: time="2024-12-01T18:38:39Z" level=debug msg="authenticated as gsingle" Dec 01 18:38:39 localhost go-librespot[7036]: time="2024-12-01T18:38:39Z" level=debug msg="authenticated as gsingle" Dec 01 18:38:39 localhost go-librespot[7036]: time="2024-12-01T18:38:39Z" level=debug msg="dealer connection opened" Dec 01 18:38:39 localhost go-librespot[7036]: time="2024-12-01T18:38:39Z" level=debug msg="initializing zeroconf session, username: gsingle" Dec 01 18:38:39 localhost go-librespot[7036]: time="2024-12-01T18:38:39Z" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Dec 01 18:38:39 localhost go-librespot[7036]: time="2024-12-01T18:38:39Z" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Dec 01 18:38:39 localhost go-librespot[7036]: time="2024-12-01T18:38:39Z" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Dec 01 18:38:39 localhost go-librespot[7036]: time="2024-12-01T18:38:39Z" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Dec 01 18:38:39 localhost go-librespot[7036]: time="2024-12-01T18:38:39Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Dec 01 18:38:39 localhost go-librespot[7036]: time="2024-12-01T18:38:39Z" level=debug msg="autoplay enabled: false" Dec 01 18:38:39 localhost go-librespot[7036]: time="2024-12-01T18:38:39Z" level=debug msg="received connection id: MTFlOWM0YzQtODQ5ZC00NjZhLWJmNjgtNDEzMTZmN2EyZGI3K2RlYWxlcit0Y3A6Ly8wYWNhNDA1NC5pcC5nZXcxLnNwb3RpZnkubmV0OjU3MDArQjc5QjA1NDExOTkzNTFCMDMyMzRFQjMyOUIxNDRBRDEzNDRGM0ZBNUIyRjYwMzA1NDgwOTYwRTRCRDMxMEZFNA==" Dec 01 18:38:39 localhost go-librespot[7036]: time="2024-12-01T18:38:39Z" level=debug msg="put connect state because NEW_DEVICE" Dec 01 18:38:41 localhost volumio[1201]: info: Initializing connection to go-librespot Websocket Dec 01 18:38:41 localhost go-librespot[7036]: time="2024-12-01T18:38:41Z" level=debug msg="new websocket client" Dec 01 18:38:41 localhost volumio[1201]: info: Connection to go-librespot Websocket established Dec 01 18:38:43 localhost volumio[1201]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Dec 01 18:38:43 localhost volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 01 18:38:43 localhost volumio[1201]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 01 18:38:43 localhost volumio[1201]: info: Discovery: Getting this device information Dec 01 18:38:43 localhost volumio[1201]: info: CoreCommandRouter::volumioGetState Dec 01 18:38:43 localhost volumio[1201]: info: CorePlayQueue::getTrack 1 Dec 01 18:38:43 localhost volumio[1201]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 01 18:38:44 localhost volumio[1201]: info: Getting Spotify volume Dec 01 18:38:44 localhost volumio[1201]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 15 Dec 01 18:38:44 localhost volumio[1201]: info: Spotify volume: 100 Dec 01 18:38:44 localhost volumio[1201]: info: CoreCommandRouter::volumioGetState Dec 01 18:38:44 localhost volumio[1201]: info: CorePlayQueue::getTrack 1 Dec 01 18:38:44 localhost volumio[1201]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Dec 01 18:38:47 localhost sudo[7064]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 01 18:38:47 localhost sudo[7064]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 01 18:38:47 localhost sudo[7064]: pam_unix(sudo:session): session closed for user root Dec 01 18:38:47 localhost sudo[7067]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 01 18:38:47 localhost sudo[7067]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 01 18:38:47 localhost sudo[7067]: pam_unix(sudo:session): session closed for user root Dec 01 18:38:47 localhost volumio[1201]: verbose: New Socket.io Connection to 192.168.56.172 from 192.168.56.176 UA: Mozilla/5.0 (Linux; Android 14; SM-S928B Build/UP1A.231005.007; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/131.0.6778.39 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 15 Dec 01 18:38:47 localhost volumio[1201]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Dec 01 18:38:48 localhost sudo[7070]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 01 18:38:48 localhost sudo[7070]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 01 18:38:48 localhost sudo[7070]: pam_unix(sudo:session): session closed for user root Dec 01 18:38:48 localhost sudo[7073]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 01 18:38:48 localhost sudo[7073]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 01 18:38:48 localhost sudo[7073]: pam_unix(sudo:session): session closed for user root Dec 01 18:38:48 localhost volumio[1201]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Dec 01 18:38:48 localhost volumio[1201]: verbose: New Socket.io Connection to 192.168.56.172 from 192.168.56.176 UA: Mozilla/5.0 (Linux; Android 14; SM-S928B Build/UP1A.231005.007; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/131.0.6778.39 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 16 Dec 01 18:38:48 localhost volumio[1201]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Dec 01 18:38:48 localhost volumio[1201]: info: CoreCommandRouter::volumioGetVisibleSources Dec 01 18:38:48 localhost volumio[1201]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 01 18:38:48 localhost volumio[1201]: info: CoreCommandRouter::volumioGetState Dec 01 18:38:48 localhost volumio[1201]: info: CorePlayQueue::getTrack 1 Dec 01 18:38:48 localhost volumio[1201]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Dec 01 18:38:48 localhost volumio[1201]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Dec 01 18:38:48 localhost volumio[1201]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Dec 01 18:38:48 localhost volumio[1201]: info: Received Get System Info Dec 01 18:38:48 localhost volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 01 18:38:48 localhost volumio[1201]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 01 18:38:48 localhost volumio[1201]: info: Discovery: Getting this device information Dec 01 18:38:48 localhost volumio[1201]: info: CoreCommandRouter::volumioGetState Dec 01 18:38:48 localhost volumio[1201]: info: CorePlayQueue::getTrack 1 Dec 01 18:38:48 localhost volumio[1201]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 01 18:38:48 localhost volumio[1201]: info: CoreCommandRouter::volumioGetState Dec 01 18:38:48 localhost volumio[1201]: info: CorePlayQueue::getTrack 1 Dec 01 18:38:48 localhost volumio[1201]: info: Listing playlists Dec 01 18:38:48 localhost volumio[1201]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Dec 01 18:38:48 localhost volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Dec 01 18:38:48 localhost volumio[1201]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Dec 01 18:38:49 localhost volumio[1201]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Dec 01 18:38:49 localhost volumio[1201]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 01 18:38:49 localhost volumio[1201]: info: Received Get System Info Dec 01 18:38:49 localhost volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 01 18:38:49 localhost volumio[1201]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 01 18:38:49 localhost volumio[1201]: info: Discovery: Getting this device information Dec 01 18:38:49 localhost volumio[1201]: info: CoreCommandRouter::volumioGetState Dec 01 18:38:49 localhost volumio[1201]: info: CorePlayQueue::getTrack 1 Dec 01 18:38:49 localhost volumio[1201]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 01 18:38:50 localhost volumio[1201]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 01 18:38:50 localhost volumio[1201]: info: Received Get System Info Dec 01 18:38:50 localhost volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 01 18:38:50 localhost volumio[1201]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 01 18:38:50 localhost volumio[1201]: info: Discovery: Getting this device information Dec 01 18:38:50 localhost volumio[1201]: info: CoreCommandRouter::volumioGetState Dec 01 18:38:50 localhost volumio[1201]: info: CorePlayQueue::getTrack 1 Dec 01 18:38:50 localhost volumio[1201]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 01 18:38:54 localhost volumio[1201]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 01 18:38:54 localhost volumio[1201]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 01 18:38:54 localhost volumio[1201]: info: Retrieving Cloud Streaming UI Dec 01 18:38:54 localhost volumio[1201]: info: Getting Tidal Cloud Configuration Dec 01 18:38:54 localhost volumio[1201]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 01 18:38:54 localhost volumio[1201]: info: Getting Qobuz Cloud Configuration Dec 01 18:38:54 localhost volumio[1201]: info: Asking plugin for UI Config Dec 01 18:38:54 localhost volumio[1201]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 01 18:38:54 localhost volumio[1201]: info: Getting Spotify Cloud Configuration Dec 01 18:38:54 localhost volumio[1201]: info: Asking plugin for UI Config Dec 01 18:38:54 localhost volumio[1201]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 01 18:38:54 localhost volumio[1201]: info: Saving Spotify Acccount Dec 01 18:38:54 localhost volumio[1201]: info: Got it Dec 01 18:38:54 localhost volumio[1201]: error: Could not retrieve Spotify Config from plugin Spotify: no section found Dec 01 18:38:54 localhost volumio[1201]: info: Got Tidal Cloud Configuration Dec 01 18:38:54 localhost volumio[1201]: info: Got it Dec 01 18:38:54 localhost volumio[1201]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 01 18:38:54 localhost volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Dec 01 18:38:54 localhost volumio[1201]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Dec 01 18:38:54 localhost volumio[1201]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 01 18:38:54 localhost volumio[1201]: info: CoreCommandRouter::volumioGetBrowseSources Dec 01 18:38:54 localhost volumio[1201]: info: CoreCommandRouter::volumioGetBrowseSources Dec 01 18:38:54 localhost volumio[1201]: info: CoreCommandRouter::volumioGetBrowseSources Dec 01 18:38:54 localhost volumio[1201]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Dec 01 18:38:54 localhost volumio[1201]: info: CoreCommandRouter::executeOnPlugin: networkfs , listShares Dec 01 18:38:58 localhost volumio[1201]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Dec 01 18:38:58 localhost volumio[1201]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Dec 01 18:38:58 localhost volumio[1201]: info: Disabling MyMusic plugin upnp Dec 01 18:38:58 localhost sudo[7142]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop upmpdcli.service Dec 01 18:38:58 localhost sudo[7142]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 01 18:38:58 localhost volumio[1201]: error: Upnp client error: Error: This socket has been ended by the other party Dec 01 18:38:58 localhost systemd[1]: Stopping UPnP Renderer front-end to MPD... Dec 01 18:38:58 localhost volumio[1201]: ------------------------------------ BT MESSAGE: BT STATUS: running Dec 01 18:39:01 localhost volumio[1201]: info: Enabling MyMusic plugin upnp Dec 01 18:39:01 localhost volumio[1201]: info: Enabling plugin upnp Dec 01 18:39:01 localhost volumio[1201]: info: Loading plugin "upnp"... Dec 01 18:39:01 localhost volumio[1201]: info: [1733078341107] Starting Upmpd Daemon Dec 01 18:39:01 localhost volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 01 18:39:01 localhost volumio[1201]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 01 18:39:01 localhost volumio[1201]: Error: listen EADDRINUSE: address already in use :::6599 Dec 01 18:39:01 localhost volumio[1201]: at Server.setupListenHandle [as _listen2] (net.js:1318:16) Dec 01 18:39:01 localhost volumio[1201]: at listenInCluster (net.js:1366:12) Dec 01 18:39:01 localhost volumio[1201]: at Server.listen (net.js:1452:7) Dec 01 18:39:01 localhost volumio[1201]: at UpnpInterface.onVolumioStart (/volumio/app/plugins/audio_interface/upnp/index.js:78:17) Dec 01 18:39:01 localhost volumio[1201]: at PluginManager.loadCorePlugin (/volumio/app/pluginmanager.js:255:38) Dec 01 18:39:01 localhost volumio[1201]: at Promise._successFn (/volumio/app/pluginmanager.js:1855:19) Dec 01 18:39:01 localhost volumio[1201]: at nextTickCallback (/volumio/node_modules/kew/kew.js:47:28) Dec 01 18:39:01 localhost volumio[1201]: at processTicksAndRejections (internal/process/task_queues.js:75:11) { Dec 01 18:39:01 localhost volumio[1201]: code: 'EADDRINUSE', Dec 01 18:39:01 localhost volumio[1201]: errno: -98, Dec 01 18:39:01 localhost volumio[1201]: syscall: 'listen', Dec 01 18:39:01 localhost volumio[1201]: address: '::', Dec 01 18:39:01 localhost volumio[1201]: port: 6599 Dec 01 18:39:01 localhost volumio[1201]: } Dec 01 18:39:01 localhost volumio[1201]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 01 18:39:01 localhost sudo[7153]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-12-01 18:38 Dec 01 18:39:01 localhost sudo[7153]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="70bcab5180cf11352f5a5197ade215ea8ee93db0" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="678d37490b3eb2102ce7c6d7a6dc3cf042ff2347" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri 08 Nov 2024 06:51:56 PM CET" VOLUMIO_VERSION="3.779" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="b9009e0280f50389e80a537357ff3961"