-- Logs begin at Thu 2019-02-14 10:11:59 UTC, end at Tue 2024-08-27 16:00:47 UTC. -- Aug 27 15:59:03 volumio systemd[1]: Starting Daily apt download activities... Aug 27 15:59:03 volumio volumio[934]: info: mDNS: A device disapperared from network Aug 27 15:59:03 volumio volumio[934]: info: mDNS Browse raised the following error TypeError: Cannot read property 'toLowerCase' of undefined Aug 27 15:59:03 volumio volumio[934]: info: mDNS: A device disapperared from network Aug 27 15:59:03 volumio volumio[934]: info: mDNS Browse raised the following error TypeError: Cannot read property 'toLowerCase' of undefined Aug 27 15:59:03 volumio volumio[934]: info: mDNS: A device disapperared from network Aug 27 15:59:03 volumio volumio[934]: info: mDNS Browse raised the following error TypeError: Cannot read property 'toLowerCase' of undefined Aug 27 15:59:03 volumio volumio[934]: info: mDNS: A device disapperared from network Aug 27 15:59:03 volumio volumio[934]: info: mDNS Browse raised the following error TypeError: Cannot read property 'toLowerCase' of undefined Aug 27 15:59:03 volumio volumio[934]: info: mDNS: A device disapperared from network Aug 27 15:59:03 volumio volumio[934]: info: mDNS Browse raised the following error TypeError: Cannot read property 'toLowerCase' of undefined Aug 27 15:59:03 volumio volumio[934]: info: mDNS: A device disapperared from network Aug 27 15:59:03 volumio volumio[934]: info: mDNS Browse raised the following error TypeError: Cannot read property 'toLowerCase' of undefined Aug 27 15:59:03 volumio volumio[934]: info: mDNS: A device disapperared from network Aug 27 15:59:03 volumio volumio[934]: info: mDNS Browse raised the following error TypeError: Cannot read property 'toLowerCase' of undefined Aug 27 15:59:03 volumio volumio[934]: info: mDNS: A device disapperared from network Aug 27 15:59:03 volumio volumio[934]: info: mDNS Browse raised the following error TypeError: Cannot read property 'toLowerCase' of undefined Aug 27 15:59:03 volumio volumio[934]: info: mDNS: A device disapperared from network Aug 27 15:59:03 volumio volumio[934]: info: mDNS Browse raised the following error TypeError: Cannot read property 'toLowerCase' of undefined Aug 27 15:59:03 volumio volumio[934]: info: mDNS: A device disapperared from network Aug 27 15:59:03 volumio volumio[934]: info: mDNS Browse raised the following error TypeError: Cannot read property 'toLowerCase' of undefined Aug 27 15:59:04 volumio go-librespot[1133]: time="2024-08-27T15:59:04Z" level=debug msg="obtained new client token: AACbKHumVlctMQXOBWACdWd2O5InEIz75cdKt1Plsb3Ny1jxmwYt6WMHgWePfO/kTk+hqXiS3FZxQaI5i3eVWcX+F1C0bU/2rZje2GKO8vAuZNb6ruPPKY1r9oTUWAiOrsXBAK7G71YgvXhX/DL8eN9LypwUT3bWEiFSUZBXg9qbiLxpkjbcSDZXEEzY9OfFYPRZIE3D65BfzFXJ+Ii/8DtR2xm1iZJmKzFwSwnB8iAjRPe7ReXXOe23htVrf3M=" Aug 27 15:59:04 volumio volumio[934]: info: Initializing connection to go-librespot Websocket Aug 27 15:59:04 volumio ntpd[996]: Soliciting pool server 188.165.224.178 Aug 27 15:59:04 volumio systemd[1]: apt-daily.service: Succeeded. Aug 27 15:59:04 volumio systemd[1]: Started Daily apt download activities. Aug 27 15:59:04 volumio systemd[1]: Starting Daily apt upgrade and clean activities... Aug 27 15:59:05 volumio systemd[1]: apt-daily-upgrade.service: Succeeded. Aug 27 15:59:05 volumio systemd[1]: Started Daily apt upgrade and clean activities. Aug 27 15:59:05 volumio volumio-remote-updater[474]: [2024-08-27 15:59:05] [connect] Successful connection Aug 27 15:59:05 volumio volumio-remote-updater[474]: [2024-08-27 15:59:05] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1724774345 101 Aug 27 15:59:05 volumio volumio[934]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Total Clients: 2 Aug 27 15:59:06 volumio volumio[934]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 27 15:59:06 volumio ntpd[996]: Soliciting pool server 51.68.44.27 Aug 27 15:59:06 volumio volumio[934]: info: Discovery: adding be4221ea-6182-4cf9-afa1-3c11a9ddc094 Aug 27 15:59:06 volumio volumio[934]: info: mDNS: Found device TEST Aug 27 15:59:06 volumio volumio[934]: info: Discovery: adding b7942f68-3aec-4d7e-805f-7ea2b4db3678 Aug 27 15:59:06 volumio volumio[934]: info: mDNS: Found device Volumio Aug 27 15:59:06 volumio volumio[934]: info: CoreCommandRouter::volumioGetState Aug 27 15:59:06 volumio volumio[934]: info: CorePlayQueue::getTrack 0 Aug 27 15:59:07 volumio volumio[934]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 27 15:59:07 volumio ntpd[996]: Soliciting pool server 95.81.173.8 Aug 27 15:59:07 volumio volumio[934]: info: CoreCommandRouter::executeOnPlugin: my_volumio , setMyVolumioToken Aug 27 15:59:08 volumio ntpd[996]: Soliciting pool server 162.159.200.123 Aug 27 15:59:08 volumio volumio[934]: info: CoreCommandRouter::executeOnPlugin: my_volumio , setMyVolumioToken Aug 27 15:59:09 volumio ntpd[996]: Soliciting pool server 176.31.180.205 Aug 27 15:59:09 volumio go-librespot[1133]: time="2024-08-27T15:59:09Z" 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-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Aug 27 15:59:10 volumio ntpd[996]: Soliciting pool server 2001:418:3ff::53 Aug 27 15:59:11 volumio ntpd[996]: Soliciting pool server 37.59.63.125 Aug 27 15:59:12 volumio volumio[1202]: ..............................................................................++++ Aug 27 15:59:14 volumio go-librespot[1133]: time="2024-08-27T15:59:14Z" level=debug msg="completed keyexchange" Aug 27 15:59:15 volumio go-librespot[1133]: time="2024-08-27T15:59:15Z" level=debug msg="completed challenge" Aug 27 15:59:15 volumio go-librespot[1133]: time="2024-08-27T15:59:15Z" level=debug msg="authenticated as 315ataumopucfkq3gm2h7qfphqna" Aug 27 15:59:16 volumio volumio[934]: verbose: New Socket.io Connection to 10.161.59.248:3000 from 10.161.59.88 UA: node-XMLHttpRequest Total Clients: 3 Aug 27 15:59:16 volumio volumio[934]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket Aug 27 15:59:16 volumio volumio[934]: info: CoreCommandRouter::volumioGetState Aug 27 15:59:16 volumio volumio[934]: info: CorePlayQueue::getTrack 0 Aug 27 15:59:16 volumio ntpd[996]: Soliciting pool server 45.13.105.44 Aug 27 15:59:16 volumio volumio[934]: verbose: New Socket.io Connection to 10.161.59.248:3000 from 10.161.59.78 UA: node-XMLHttpRequest Total Clients: 4 Aug 27 15:59:16 volumio volumio[934]: info: Discovery: this is already registered, b7942f68-3aec-4d7e-805f-7ea2b4db3678 Aug 27 15:59:16 volumio volumio[934]: info: mDNS: Found device Volumio Aug 27 15:59:16 volumio volumio[934]: info: CoreCommandRouter::volumioGetState Aug 27 15:59:16 volumio volumio[934]: info: CorePlayQueue::getTrack 0 Aug 27 15:59:16 volumio volumio[934]: info: Discovery: this is already registered, be4221ea-6182-4cf9-afa1-3c11a9ddc094 Aug 27 15:59:16 volumio volumio[934]: info: mDNS: Found device TEST Aug 27 15:59:16 volumio volumio[934]: info: CoreCommandRouter::volumioGetState Aug 27 15:59:16 volumio volumio[934]: info: CorePlayQueue::getTrack 0 Aug 27 15:59:16 volumio volumio[934]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket Aug 27 15:59:16 volumio volumio[934]: info: CoreCommandRouter::volumioGetState Aug 27 15:59:16 volumio volumio[934]: info: CorePlayQueue::getTrack 0 Aug 27 15:59:17 volumio volumio[934]: verbose: New Socket.io Connection to 10.161.59.248:3000 from 10.161.59.98 UA: node-XMLHttpRequest Total Clients: 5 Aug 27 15:59:17 volumio volumio[934]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket Aug 27 15:59:17 volumio volumio[934]: info: CoreCommandRouter::volumioGetState Aug 27 15:59:17 volumio volumio[934]: info: CorePlayQueue::getTrack 0 Aug 27 15:59:17 volumio volumio[934]: error: MyVolumio Plugin failed to start in a timely fashion Aug 27 15:59:17 volumio volumio[934]: info: BOOT COMPLETED Aug 27 15:59:17 volumio volumio[934]: [Metrics] CommandRouter: 30s 60.02ms Aug 27 15:59:17 volumio volumio[934]: info: CoreCommandRouter::volumiosetStartupVolume Aug 27 15:59:17 volumio volumio[934]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 27 15:59:17 volumio volumio[934]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 27 15:59:17 volumio volumio[934]: info: CoreCommandRouter::Close All Modals sent Aug 27 15:59:17 volumio volumio[934]: info: CoreCommandRouter::Close All Modals sent Aug 27 15:59:17 volumio volumio[934]: verbose: New Socket.io Connection to 10.161.59.248:3000 from 10.161.59.68 UA: node-XMLHttpRequest Total Clients: 6 Aug 27 15:59:17 volumio volumio[934]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket Aug 27 15:59:17 volumio volumio[934]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Aug 27 15:59:17 volumio volumio[934]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Aug 27 15:59:17 volumio volumio[934]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Aug 27 15:59:17 volumio volumio[934]: info: Received Get System Version Aug 27 15:59:17 volumio volumio[934]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 27 15:59:18 volumio volumio[934]: info: CoreCommandRouter::volumioGetState Aug 27 15:59:18 volumio volumio[934]: info: CorePlayQueue::getTrack 0 Aug 27 15:59:18 volumio volumio[934]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Aug 27 15:59:18 volumio volumio[934]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Aug 27 15:59:18 volumio volumio[934]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Aug 27 15:59:19 volumio volumio[934]: verbose: New Socket.io Connection to 10.161.59.248:3000 from 10.161.59.28 UA: node-XMLHttpRequest Total Clients: 7 Aug 27 15:59:19 volumio volumio[934]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket Aug 27 15:59:19 volumio volumio[934]: info: CoreCommandRouter::volumioGetState Aug 27 15:59:19 volumio volumio[934]: info: CorePlayQueue::getTrack 0 Aug 27 15:59:19 volumio volumio[934]: verbose: New Socket.io Connection to 10.161.59.248:3000 from 10.161.59.48 UA: node-XMLHttpRequest Total Clients: 8 Aug 27 15:59:19 volumio volumio[934]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket Aug 27 15:59:19 volumio volumio[934]: info: CoreCommandRouter::volumioGetState Aug 27 15:59:19 volumio volumio[934]: info: CorePlayQueue::getTrack 0 Aug 27 15:59:20 volumio go-librespot[1133]: time="2024-08-27T15:59:20Z" level=debug msg="authenticated as 315ataumopucfkq3gm2h7qfphqna" Aug 27 15:59:20 volumio go-librespot[1133]: time="2024-08-27T15:59:20Z" 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]" Aug 27 15:59:20 volumio go-librespot[1133]: time="2024-08-27T15:59:20Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 27 15:59:21 volumio ntpd[996]: Soliciting pool server 51.38.81.135 Aug 27 15:59:22 volumio volumio[934]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 Aug 27 15:59:23 volumio volumio[934]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Aug 27 15:59:23 volumio volumio[934]: SPOTIFY: BQDkez347vvapHSdtd1eI4y6Wp_3P9E8zs5VrquUzMIKAf7J17SEkidZbUnLIZ2d6eHCEu-vVpJOLx5XPfk60-dk-WylebTLZ_tdqUzox2XHUxdl1yjn53ficsKUBuQ-1SGY3kQmCUzVrH-e19aNVPuZntmb6EmHjVfLOvZqLNN8MrDYJkDLcO2vU30V67qp_sUi3iV1FbQbwyebG_hZHSMZCJjK7SUcHLSDaE2nw-mqSB_rDlU7TmtgddTJ1aqZpPFnMsil7Q1zmvwCDlU Aug 27 15:59:23 volumio volumio[934]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Aug 27 15:59:23 volumio volumio[934]: info: New Spotify access token = BQDkez347vvapHSdtd1eI4y6Wp_3P9E8zs5VrquUzMIKAf7J17SEkidZbUnLIZ2d6eHCEu-vVpJOLx5XPfk60-dk-WylebTLZ_tdqUzox2XHUxdl1yjn53ficsKUBuQ-1SGY3kQmCUzVrH-e19aNVPuZntmb6EmHjVfLOvZqLNN8MrDYJkDLcO2vU30V67qp_sUi3iV1FbQbwyebG_hZHSMZCJjK7SUcHLSDaE2nw-mqSB_rDlU7TmtgddTJ1aqZpPFnMsil7Q1zmvwCDlU Aug 27 15:59:23 volumio volumio[934]: info: Spotify credentials grant success - running version from March 24, 2019 Aug 27 15:59:23 volumio volumio[934]: verbose: New Socket.io Connection to 10.161.59.248:3000 from 10.161.59.38 UA: node-XMLHttpRequest Total Clients: 10 Aug 27 15:59:23 volumio volumio[934]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket Aug 27 15:59:23 volumio volumio[934]: info: CoreCommandRouter::volumioGetState Aug 27 15:59:23 volumio volumio[934]: info: CorePlayQueue::getTrack 0 Aug 27 15:59:25 volumio go-librespot[1133]: time="2024-08-27T15:59:25Z" level=debug msg="dealer connection opened" Aug 27 15:59:25 volumio go-librespot[1133]: time="2024-08-27T15:59:25Z" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Aug 27 15:59:25 volumio go-librespot[1133]: time="2024-08-27T15:59:25Z" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Aug 27 15:59:25 volumio go-librespot[1133]: time="2024-08-27T15:59:25Z" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Aug 27 15:59:25 volumio go-librespot[1133]: time="2024-08-27T15:59:25Z" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Aug 27 15:59:25 volumio go-librespot[1133]: time="2024-08-27T15:59:25Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 513" Aug 27 15:59:25 volumio go-librespot[1133]: time="2024-08-27T15:59:25Z" level=debug msg="received connection id: ZDI0YjE3NzQtN2VmYy00ZjY2LThjMTUtM2E0YTZhMjg1NTVmK2RlYWxlcit0Y3A6Ly8wYWNhNDE3Yi5pcC5nZXcxLnNwb3RpZnkubmV0OjU3MDArN0EzNEYwNzc1RjkzNjMxQzFCRkU5RTVFNTE0NDg3OTAyMTc2QkEwRTVENUIwQUEyMzEwNjk5NkRERDgyOEQ4RQ==" Aug 27 15:59:26 volumio volumio[934]: info: Discovery: this is already registered, be4221ea-6182-4cf9-afa1-3c11a9ddc094 Aug 27 15:59:26 volumio volumio[934]: info: mDNS: Found device TEST Aug 27 15:59:26 volumio volumio[934]: info: CoreCommandRouter::volumioGetState Aug 27 15:59:26 volumio volumio[934]: info: CorePlayQueue::getTrack 0 Aug 27 15:59:27 volumio volumio[934]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 27 15:59:27 volumio volumio[934]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 27 15:59:29 volumio volumio[1202]: ..............................................................................................................................++++ Aug 27 15:59:29 volumio volumio[1202]: e is 65537 (0x010001) Aug 27 15:59:29 volumio volumio[1202]: writing RSA key Aug 27 15:59:31 volumio go-librespot[1133]: time="2024-08-27T15:59:31Z" level=debug msg="put connect state because NEW_DEVICE" Aug 27 15:59:38 volumio volumio[934]: info: Discovery: this is already registered, be4221ea-6182-4cf9-afa1-3c11a9ddc094 Aug 27 15:59:38 volumio volumio[934]: info: mDNS: Found device TEST Aug 27 15:59:38 volumio volumio[934]: info: CoreCommandRouter::volumioGetState Aug 27 15:59:38 volumio volumio[934]: info: CorePlayQueue::getTrack 0 Aug 27 15:59:42 volumio volumio[934]: info: Discovery: this is already registered, be4221ea-6182-4cf9-afa1-3c11a9ddc094 Aug 27 15:59:42 volumio volumio[934]: info: mDNS: Found device TEST Aug 27 15:59:42 volumio volumio[934]: info: CoreCommandRouter::volumioGetState Aug 27 15:59:42 volumio volumio[934]: info: CorePlayQueue::getTrack 0 Aug 27 15:59:48 volumio volumio[934]: info: Discovery: this is already registered, be4221ea-6182-4cf9-afa1-3c11a9ddc094 Aug 27 15:59:48 volumio volumio[934]: info: mDNS: Found device TEST Aug 27 15:59:48 volumio volumio[934]: info: CoreCommandRouter::volumioGetState Aug 27 15:59:48 volumio volumio[934]: info: CorePlayQueue::getTrack 0 Aug 27 15:59:52 volumio volumio[934]: info: Discovery: this is already registered, be4221ea-6182-4cf9-afa1-3c11a9ddc094 Aug 27 15:59:52 volumio volumio[934]: info: mDNS: Found device TEST Aug 27 15:59:52 volumio volumio[934]: info: CoreCommandRouter::volumioGetState Aug 27 15:59:52 volumio volumio[934]: info: CorePlayQueue::getTrack 0 Aug 27 15:59:58 volumio volumio[934]: info: Discovery: this is already registered, be4221ea-6182-4cf9-afa1-3c11a9ddc094 Aug 27 15:59:58 volumio volumio[934]: info: mDNS: Found device TEST Aug 27 15:59:58 volumio volumio[934]: info: CoreCommandRouter::volumioGetState Aug 27 15:59:58 volumio volumio[934]: info: CorePlayQueue::getTrack 0 Aug 27 16:00:00 volumio volumio[934]: info: CoreCommandRouter::volumioPlay Aug 27 16:00:00 volumio volumio[934]: verbose: UNSET VOLATILE Aug 27 16:00:00 volumio volumio[934]: info: CoreStateMachine::play index undefined Aug 27 16:00:00 volumio volumio[934]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 27 16:00:00 volumio volumio[934]: info: CorePlayQueue::getTrack 0 Aug 27 16:00:00 volumio volumio[934]: info: CoreStateMachine::startPlaybackTimer Aug 27 16:00:00 volumio volumio[934]: info: CorePlayQueue::getTrack 0 Aug 27 16:00:00 volumio volumio[934]: verbose: ControllerMpd::clearAddPlayTracks USB/USB_DISK/Best Movie Soundtracks 2021 (The Most Beautiful, Epic & Awesome Scores).mp3 Aug 27 16:00:00 volumio volumio[934]: verbose: ControllerMpd::sendMpdCommand stop Aug 27 16:00:00 volumio volumio[934]: info: sendMpdCommand stop took 3 milliseconds Aug 27 16:00:00 volumio volumio[934]: verbose: ControllerMpd::sendMpdCommand clear Aug 27 16:00:00 volumio volumio[934]: info: Aug 27 16:00:00 volumio volumio[934]: ---------------------------- MPD announces system playlist update Aug 27 16:00:00 volumio volumio[934]: info: Ignoring MPD Status Update Aug 27 16:00:00 volumio volumio[934]: info: sendMpdCommand clear took 4 milliseconds Aug 27 16:00:00 volumio volumio[934]: verbose: ControllerMpd::sendMpdCommand add "USB/USB_DISK/Best Movie Soundtracks 2021 (The Most Beautiful, Epic & Awesome Scores).mp3" Aug 27 16:00:00 volumio volumio[934]: error: updateQueue error: null Aug 27 16:00:00 volumio volumio[934]: info: Aug 27 16:00:00 volumio volumio[934]: ---------------------------- MPD announces system playlist update Aug 27 16:00:00 volumio volumio[934]: info: Ignoring MPD Status Update Aug 27 16:00:00 volumio volumio[934]: info: ------------------------------ 8ms Aug 27 16:00:00 volumio volumio[934]: info: sendMpdCommand add "USB/USB_DISK/Best Movie Soundtracks 2021 (The Most Beautiful, Epic & Awesome Scores).mp3" took 5 milliseconds Aug 27 16:00:00 volumio volumio[934]: verbose: ControllerMpd::sendMpdCommand play Aug 27 16:00:00 volumio volumio[934]: info: ------------------------------ 6ms Aug 27 16:00:00 volumio volumio[934]: info: sendMpdCommand play took 4 milliseconds Aug 27 16:00:00 volumio volumio[934]: info: Aug 27 16:00:00 volumio volumio[934]: ---------------------------- MPD announces state update: player Aug 27 16:00:00 volumio volumio[934]: info: ControllerMpd::getState Aug 27 16:00:00 volumio volumio[934]: verbose: ControllerMpd::sendMpdCommand status Aug 27 16:00:00 volumio volumio[934]: info: Aug 27 16:00:00 volumio volumio[934]: ---------------------------- MPD announces state update: player Aug 27 16:00:00 volumio volumio[934]: info: sendMpdCommand status took 4 milliseconds Aug 27 16:00:00 volumio volumio[934]: info: ControllerMpd::getState Aug 27 16:00:00 volumio volumio[934]: verbose: ControllerMpd::sendMpdCommand status Aug 27 16:00:00 volumio volumio[934]: verbose: ControllerMpd::parseState Aug 27 16:00:00 volumio volumio[934]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 27 16:00:00 volumio volumio[934]: info: sendMpdCommand status took 6 milliseconds Aug 27 16:00:00 volumio volumio[934]: info: sendMpdCommand playlistinfo took 4 milliseconds Aug 27 16:00:00 volumio volumio[934]: verbose: ControllerMpd::parseState Aug 27 16:00:00 volumio volumio[934]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 27 16:00:00 volumio volumio[934]: verbose: ControllerMpd::parseTrackInfo Aug 27 16:00:00 volumio volumio[934]: info: ControllerMpd::pushState Aug 27 16:00:00 volumio volumio[934]: info: CoreCommandRouter::servicePushState Aug 27 16:00:00 volumio volumio[934]: info: CorePlayQueue::getTrack 0 Aug 27 16:00:00 volumio volumio[934]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":9380,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Best Movie Soundtracks 2021 (The Most Beautiful, Epic & Awesome Scores).mp3","artist":null,"album":null,"uri":"USB/USB_DISK/Best Movie Soundtracks 2021 (The Most Beautiful, Epic & Awesome Scores).mp3","trackType":"mp3"} Aug 27 16:00:00 volumio volumio[934]: verbose: CURRENT POSITION 0 Aug 27 16:00:00 volumio volumio[934]: info: CoreStateMachine::syncState stateService play Aug 27 16:00:00 volumio volumio[934]: info: CoreStateMachine::syncState currentStatus stop Aug 27 16:00:00 volumio volumio[934]: info: CoreStateMachine::pushState Aug 27 16:00:00 volumio volumio[934]: info: CorePlayQueue::getTrack 0 Aug 27 16:00:00 volumio volumio[934]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 27 16:00:00 volumio volumio[934]: info: CoreCommandRouter::volumioPushState Aug 27 16:00:00 volumio volumio[934]: info: ------------------------------ 60ms Aug 27 16:00:00 volumio volumio[934]: info: sendMpdCommand playlistinfo took 41 milliseconds Aug 27 16:00:00 volumio volumio[934]: verbose: ControllerMpd::parseTrackInfo Aug 27 16:00:00 volumio volumio[934]: info: ControllerMpd::pushState Aug 27 16:00:00 volumio volumio[934]: info: CoreCommandRouter::servicePushState Aug 27 16:00:00 volumio volumio[934]: info: CorePlayQueue::getTrack 0 Aug 27 16:00:00 volumio volumio[934]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":9380,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Best Movie Soundtracks 2021 (The Most Beautiful, Epic & Awesome Scores).mp3","artist":null,"album":null,"uri":"USB/USB_DISK/Best Movie Soundtracks 2021 (The Most Beautiful, Epic & Awesome Scores).mp3","trackType":"mp3"} Aug 27 16:00:00 volumio volumio[934]: verbose: CURRENT POSITION 0 Aug 27 16:00:00 volumio volumio[934]: info: CoreStateMachine::syncState stateService play Aug 27 16:00:00 volumio volumio[934]: info: CoreStateMachine::syncState currentStatus play Aug 27 16:00:00 volumio volumio[934]: info: Received an update from plugin. extracting info from payload Aug 27 16:00:00 volumio volumio[934]: info: CoreStateMachine::pushState Aug 27 16:00:00 volumio volumio[934]: info: CorePlayQueue::getTrack 0 Aug 27 16:00:00 volumio volumio[934]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 27 16:00:00 volumio volumio[934]: info: CoreCommandRouter::volumioPushState Aug 27 16:00:00 volumio volumio[934]: info: CoreStateMachine::pushState Aug 27 16:00:00 volumio volumio[934]: info: CorePlayQueue::getTrack 0 Aug 27 16:00:00 volumio volumio[934]: info: CoreCommandRouter::volumioPushState Aug 27 16:00:00 volumio volumio[934]: info: ------------------------------ 111ms Aug 27 16:00:02 volumio volumio[934]: info: Discovery: this is already registered, b7942f68-3aec-4d7e-805f-7ea2b4db3678 Aug 27 16:00:02 volumio volumio[934]: info: mDNS: Found device Volumio Aug 27 16:00:02 volumio volumio[934]: info: CoreCommandRouter::volumioGetState Aug 27 16:00:02 volumio volumio[934]: info: CorePlayQueue::getTrack 0 Aug 27 16:00:08 volumio volumio[934]: info: Discovery: this is already registered, be4221ea-6182-4cf9-afa1-3c11a9ddc094 Aug 27 16:00:08 volumio volumio[934]: info: mDNS: Found device TEST Aug 27 16:00:08 volumio volumio[934]: info: CoreCommandRouter::volumioGetState Aug 27 16:00:08 volumio volumio[934]: info: CorePlayQueue::getTrack 0 Aug 27 16:00:12 volumio volumio[934]: info: Discovery: this is already registered, b7942f68-3aec-4d7e-805f-7ea2b4db3678 Aug 27 16:00:12 volumio volumio[934]: info: mDNS: Found device Volumio Aug 27 16:00:12 volumio volumio[934]: info: CoreCommandRouter::volumioGetState Aug 27 16:00:12 volumio volumio[934]: info: CorePlayQueue::getTrack 0 Aug 27 16:00:18 volumio volumio[934]: info: Discovery: this is already registered, be4221ea-6182-4cf9-afa1-3c11a9ddc094 Aug 27 16:00:18 volumio volumio[934]: info: mDNS: Found device TEST Aug 27 16:00:18 volumio volumio[934]: info: CoreCommandRouter::volumioGetState Aug 27 16:00:18 volumio volumio[934]: info: CorePlayQueue::getTrack 0 Aug 27 16:00:22 volumio volumio[934]: info: Discovery: this is already registered, be4221ea-6182-4cf9-afa1-3c11a9ddc094 Aug 27 16:00:22 volumio volumio[934]: info: mDNS: Found device TEST Aug 27 16:00:22 volumio volumio[934]: info: CoreCommandRouter::volumioGetState Aug 27 16:00:22 volumio volumio[934]: info: CorePlayQueue::getTrack 0 Aug 27 16:00:28 volumio volumio[934]: info: Discovery: this is already registered, be4221ea-6182-4cf9-afa1-3c11a9ddc094 Aug 27 16:00:28 volumio volumio[934]: info: mDNS: Found device TEST Aug 27 16:00:28 volumio volumio[934]: info: CoreCommandRouter::volumioGetState Aug 27 16:00:28 volumio volumio[934]: info: CorePlayQueue::getTrack 0 Aug 27 16:00:29 volumio go-librespot[1133]: time="2024-08-27T16:00:29Z" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Aug 27 16:00:29 volumio go-librespot[1133]: time="2024-08-27T16:00:29Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 250" Aug 27 16:00:31 volumio volumio[934]: info: CoreCommandRouter::volumioPause Aug 27 16:00:31 volumio volumio[934]: info: CoreStateMachine::pause Aug 27 16:00:31 volumio volumio[934]: info: CoreStateMachine::stPlaybackTimer Aug 27 16:00:31 volumio volumio[934]: info: CoreStateMachine::servicePause Aug 27 16:00:31 volumio volumio[934]: info: CorePlayQueue::getTrack 0 Aug 27 16:00:31 volumio volumio[934]: info: CoreCommandRouter::servicePause Aug 27 16:00:31 volumio volumio[934]: info: ControllerMpd::pause Aug 27 16:00:31 volumio volumio[934]: verbose: ControllerMpd::sendMpdCommand pause Aug 27 16:00:31 volumio volumio[934]: info: sendMpdCommand pause took 125 milliseconds Aug 27 16:00:31 volumio volumio[934]: info: Aug 27 16:00:31 volumio volumio[934]: ---------------------------- MPD announces state update: player Aug 27 16:00:31 volumio volumio[934]: info: ControllerMpd::getState Aug 27 16:00:31 volumio volumio[934]: verbose: ControllerMpd::sendMpdCommand status Aug 27 16:00:31 volumio volumio[934]: info: sendMpdCommand status took 2 milliseconds Aug 27 16:00:31 volumio volumio[934]: verbose: ControllerMpd::parseState Aug 27 16:00:31 volumio volumio[934]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 27 16:00:31 volumio volumio[934]: info: sendMpdCommand playlistinfo took 2 milliseconds Aug 27 16:00:31 volumio volumio[934]: verbose: ControllerMpd::parseTrackInfo Aug 27 16:00:31 volumio volumio[934]: info: ControllerMpd::pushState Aug 27 16:00:31 volumio volumio[934]: info: CoreCommandRouter::servicePushState Aug 27 16:00:31 volumio volumio[934]: info: CorePlayQueue::getTrack 0 Aug 27 16:00:31 volumio volumio[934]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":31485,"duration":9380,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"320 Kbps","isStreaming":false,"title":"Best Movie Soundtracks 2021 (The Most Beautiful, Epic & Awesome Scores).mp3","artist":null,"album":null,"uri":"USB/USB_DISK/Best Movie Soundtracks 2021 (The Most Beautiful, Epic & Awesome Scores).mp3","trackType":"mp3"} Aug 27 16:00:31 volumio volumio[934]: verbose: CURRENT POSITION 0 Aug 27 16:00:31 volumio volumio[934]: info: CoreStateMachine::syncState stateService pause Aug 27 16:00:31 volumio volumio[934]: info: CoreStateMachine::syncState currentStatus pause Aug 27 16:00:31 volumio volumio[934]: info: CoreStateMachine::pushState Aug 27 16:00:31 volumio volumio[934]: info: CorePlayQueue::getTrack 0 Aug 27 16:00:31 volumio volumio[934]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 27 16:00:31 volumio volumio[934]: info: CoreCommandRouter::volumioPushState Aug 27 16:00:31 volumio volumio[934]: info: CoreStateMachine::stPlaybackTimer Aug 27 16:00:31 volumio volumio[934]: info: ------------------------------ 45ms Aug 27 16:00:32 volumio volumio[934]: info: Discovery: this is already registered, be4221ea-6182-4cf9-afa1-3c11a9ddc094 Aug 27 16:00:32 volumio volumio[934]: info: mDNS: Found device TEST Aug 27 16:00:32 volumio volumio[934]: info: CoreCommandRouter::volumioGetState Aug 27 16:00:32 volumio volumio[934]: info: CorePlayQueue::getTrack 0 Aug 27 16:00:38 volumio volumio[934]: info: Discovery: this is already registered, be4221ea-6182-4cf9-afa1-3c11a9ddc094 Aug 27 16:00:38 volumio volumio[934]: info: mDNS: Found device TEST Aug 27 16:00:38 volumio volumio[934]: info: CoreCommandRouter::volumioGetState Aug 27 16:00:38 volumio volumio[934]: info: CorePlayQueue::getTrack 0 Aug 27 16:00:40 volumio go-librespot[1133]: time="2024-08-27T16:00:40Z" level=debug msg="handling transfer player command from aabfd61dd42e3d5eb8cb77f13346e73953c02c9f" Aug 27 16:00:41 volumio go-librespot[1133]: time="2024-08-27T16:00:41Z" level=trace msg="fetched new page 0 with 296 items (list: 296)" Aug 27 16:00:41 volumio go-librespot[1133]: time="2024-08-27T16:00:41Z" level=debug msg="loading track spotify:track:6PrKZUXJPmBiobMN44yR8Y (paused: true, position: 44705ms)" Aug 27 16:00:41 volumio go-librespot[1133]: time="2024-08-27T16:00:41Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 27 16:00:41 volumio go-librespot[1133]: time="2024-08-27T16:00:41Z" level=trace msg="emitting websocket event: will_play" Aug 27 16:00:41 volumio go-librespot[1133]: time="2024-08-27T16:00:41Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241" Aug 27 16:00:41 volumio go-librespot[1133]: time="2024-08-27T16:00:41Z" level=debug msg="selected format OGG_VORBIS_320 for spotify:track:6PrKZUXJPmBiobMN44yR8Y" Aug 27 16:00:41 volumio go-librespot[1133]: time="2024-08-27T16:00:41Z" level=debug msg="requested aes key for file 30781b6cef717c1d8c83e613c1edccc08b307532, gid: 6PrKZUXJPmBiobMN44yR8Y" Aug 27 16:00:41 volumio go-librespot[1133]: time="2024-08-27T16:00:41Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1400" Aug 27 16:00:41 volumio go-librespot[1133]: time="2024-08-27T16:00:41Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1154" Aug 27 16:00:42 volumio volumio[934]: info: Discovery: this is already registered, be4221ea-6182-4cf9-afa1-3c11a9ddc094 Aug 27 16:00:42 volumio volumio[934]: info: mDNS: Found device TEST Aug 27 16:00:42 volumio volumio[934]: info: CoreCommandRouter::volumioGetState Aug 27 16:00:42 volumio volumio[934]: info: CorePlayQueue::getTrack 0 Aug 27 16:00:42 volumio go-librespot[1133]: time="2024-08-27T16:00:42Z" level=debug msg="new websocket client" Aug 27 16:00:42 volumio volumio[934]: info: Connection to go-librespot Websocket established Aug 27 16:00:45 volumio volumio[934]: info: Getting Spotify volume Aug 27 16:00:46 volumio go-librespot[1133]: time="2024-08-27T16:00:46Z" level=debug msg="fetched first chunk of 16, total size is 7896764 bytes" Aug 27 16:00:46 volumio go-librespot[1133]: time="2024-08-27T16:00:46Z" level=debug msg="fetched chunk 2/15, size: 524288" Aug 27 16:00:46 volumio go-librespot[1133]: time="2024-08-27T16:00:46Z" level=debug msg="fetched chunk 1/15, size: 524288" Aug 27 16:00:46 volumio go-librespot[1133]: time="2024-08-27T16:00:46Z" level=debug msg="fetched chunk 3/15, size: 524288" Aug 27 16:00:46 volumio go-librespot[1133]: time="2024-08-27T16:00:46Z" level=trace msg="seek to 44705ms (diff: 130ms, samples: 1971490, bytes: 1699550)" Aug 27 16:00:46 volumio go-librespot[1133]: time="2024-08-27T16:00:46Z" level=info msg="loaded track \"The Ecstasy Of Gold - 2004 Remaster\" (uri: spotify:track:6PrKZUXJPmBiobMN44yR8Y, paused: true, position: 44705ms, duration: 203226ms)" Aug 27 16:00:46 volumio go-librespot[1133]: time="2024-08-27T16:00:46Z" level=debug msg="fetched chunk 4/15, size: 524288" Aug 27 16:00:46 volumio go-librespot[1133]: time="2024-08-27T16:00:46Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 27 16:00:46 volumio go-librespot[1133]: time="2024-08-27T16:00:46Z" level=trace msg="emitting websocket event: metadata" Aug 27 16:00:46 volumio go-librespot[1133]: time="2024-08-27T16:00:46Z" level=trace msg="emitting websocket event: active" Aug 27 16:00:46 volumio go-librespot[1133]: time="2024-08-27T16:00:46Z" level=debug msg="sending successful reply for delaer request" Aug 27 16:00:46 volumio go-librespot[1133]: time="2024-08-27T16:00:46Z" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Aug 27 16:00:46 volumio go-librespot[1133]: time="2024-08-27T16:00:46Z" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Aug 27 16:00:46 volumio go-librespot[1133]: time="2024-08-27T16:00:46Z" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Aug 27 16:00:46 volumio volumio[934]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:6PrKZUXJPmBiobMN44yR8Y","name":"The Ecstasy Of Gold - 2004 Remaster","artist_names":["Ennio Morricone"],"album_name":"The Good, The Bad And The Ugly [Original Motion Picture Soundtrack / (Remastered \u0026 Expanded)]","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0288eb37784eee4c3651807406","position":44705,"duration":203226,"release_date":"year:1967","track_number":20,"disc_number":1}} Aug 27 16:00:46 volumio volumio[934]: SPOTIFY: received: {"type":"active","data":null} Aug 27 16:00:46 volumio volumio[934]: info: Aligning Spotify Volume to Volumio Volume Aug 27 16:00:46 volumio volumio[934]: info: CoreCommandRouter::volumioGetState Aug 27 16:00:46 volumio volumio[934]: info: CorePlayQueue::getTrack 0 Aug 27 16:00:46 volumio volumio[934]: info: Setting Spotify Volume from Volumio: 65 Aug 27 16:00:46 volumio go-librespot[1133]: time="2024-08-27T16:00:46Z" level=debug msg="fetched chunk 5/15, size: 524288" Aug 27 16:00:46 volumio go-librespot[1133]: time="2024-08-27T16:00:46Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 27 16:00:46 volumio go-librespot[1133]: time="2024-08-27T16:00:46Z" level=trace msg="emitting websocket event: paused" Aug 27 16:00:46 volumio volumio[934]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:6PrKZUXJPmBiobMN44yR8Y","play_origin":"playlist"}} Aug 27 16:00:46 volumio volumio[934]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 27 16:00:46 volumio go-librespot[1133]: time="2024-08-27T16:00:46Z" level=debug msg="fetched chunk 6/15, size: 524288" Aug 27 16:00:46 volumio volumio[934]: TypeError: Cannot read property 'service' of undefined Aug 27 16:00:46 volumio volumio[934]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:336:50) Aug 27 16:00:46 volumio volumio[934]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:270:18) Aug 27 16:00:46 volumio volumio[934]: at WebSocket.message (/data/plugins/music_service/spop/index.js:189:14) Aug 27 16:00:46 volumio volumio[934]: at WebSocket.emit (events.js:315:20) Aug 27 16:00:46 volumio volumio[934]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1209:20) Aug 27 16:00:46 volumio volumio[934]: at Receiver.emit (events.js:315:20) Aug 27 16:00:46 volumio volumio[934]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:594:14) Aug 27 16:00:46 volumio volumio[934]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Aug 27 16:00:46 volumio volumio[934]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Aug 27 16:00:46 volumio volumio[934]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Aug 27 16:00:46 volumio volumio[934]: at writeOrBuffer (internal/streams/writable.js:358:12) Aug 27 16:00:46 volumio volumio[934]: at Receiver.Writable.write (internal/streams/writable.js:303:10) Aug 27 16:00:46 volumio volumio[934]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1303:35) Aug 27 16:00:46 volumio volumio[934]: at Socket.emit (events.js:315:20) Aug 27 16:00:46 volumio volumio[934]: at addChunk (internal/streams/readable.js:309:12) Aug 27 16:00:46 volumio volumio[934]: at readableAddChunk (internal/streams/readable.js:284:9) Aug 27 16:00:47 volumio volumio[934]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 27 16:00:47 volumio sudo[1442]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-08-27 15:59 Aug 27 16:00:47 volumio sudo[1442]: 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="e5f8795c07ba36ff2b02d7ba0a21c7a0f29b897e" VOLUMIO_FE_VERSION="473d8facbed5f9754db84a81b093baace7aa4b64" VOLUMIO_FE3_VERSION="934cddf6d46478e7a53a8d3664cd346f4de7cb34" VOLUMIO_BE_VERSION="359b2717b79cfc72b7d1c918d0fc2885a93bca70" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Mon 24 Jan 2022 10:51:57 AM CET" VOLUMIO_VERSION="3.198" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="74e6a9ad035e912732893c8d6b060b17"