-- Logs begin at Wed 2024-08-21 00:32:09 BST, end at Wed 2024-08-21 20:10:36 BST. -- Aug 21 20:09:02 volumio kernel: CIFS: __readahead_batch() returned 965/1024 Aug 21 20:09:17 volumio volumio[14378]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 21 20:09:17 volumio volumio[14378]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 21 20:09:17 volumio volumio[14378]: info: Discovery: Getting this device information Aug 21 20:09:17 volumio volumio[14378]: info: CoreCommandRouter::volumioGetState Aug 21 20:09:17 volumio volumio[14378]: info: CorePlayQueue::getTrack 7 Aug 21 20:09:17 volumio volumio[14378]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 21 20:09:47 volumio volumio[14378]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 21 20:09:47 volumio volumio[14378]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 21 20:09:47 volumio volumio[14378]: info: Discovery: Getting this device information Aug 21 20:09:47 volumio volumio[14378]: info: CoreCommandRouter::volumioGetState Aug 21 20:09:47 volumio volumio[14378]: info: CorePlayQueue::getTrack 7 Aug 21 20:09:47 volumio volumio[14378]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 21 20:09:55 volumio volumio[14378]: info: CorePlayQueue::getTrack 7 Aug 21 20:09:55 volumio volumio[14378]: info: CorePlayQueue::getTrack 0 Aug 21 20:09:55 volumio volumio[14378]: info: Prefetching next song Aug 21 20:09:55 volumio volumio[14378]: info: DOING PREFETCH IN MPD Aug 21 20:09:55 volumio volumio[14378]: verbose: ControllerMpd::sendMpdCommand add "NAS/Thor_Cifs/Slipknot/Iowa (2014)/1 - (515).flac" Aug 21 20:09:55 volumio volumio[14378]: info: Aug 21 20:09:55 volumio volumio[14378]: ---------------------------- MPD announces system playlist update Aug 21 20:09:55 volumio volumio[14378]: info: Ignoring MPD Status Update Aug 21 20:09:55 volumio volumio[14378]: info: sendMpdCommand add "NAS/Thor_Cifs/Slipknot/Iowa (2014)/1 - (515).flac" took 2 milliseconds Aug 21 20:09:55 volumio volumio[14378]: verbose: ControllerMpd::sendMpdCommand consume 1 Aug 21 20:09:55 volumio volumio[14378]: info: ------------------------------ 2ms Aug 21 20:09:55 volumio volumio[14378]: info: sendMpdCommand consume 1 took 2 milliseconds Aug 21 20:09:55 volumio volumio[14378]: info: Aug 21 20:09:55 volumio volumio[14378]: ---------------------------- MPD announces system playlist update Aug 21 20:09:55 volumio volumio[14378]: info: Ignoring MPD Status Update Aug 21 20:09:55 volumio volumio[14378]: info: Aug 21 20:09:55 volumio volumio[14378]: ---------------------------- MPD announces system playlist update Aug 21 20:09:55 volumio volumio[14378]: info: Ignoring MPD Status Update Aug 21 20:09:55 volumio volumio[14378]: info: Aug 21 20:09:55 volumio volumio[14378]: ---------------------------- MPD announces system playlist update Aug 21 20:09:55 volumio volumio[14378]: info: Ignoring MPD Status Update Aug 21 20:09:55 volumio volumio[14378]: info: ------------------------------ 3ms Aug 21 20:09:55 volumio volumio[14378]: info: ------------------------------ 3ms Aug 21 20:09:55 volumio volumio[14378]: info: ------------------------------ 2ms Aug 21 20:09:57 volumio go-librespot[14582]: time="2024-08-21T20:09:57+01:00" level=error msg="did not receive last pong from dealer, 60s passed" Aug 21 20:09:59 volumio volumio[14378]: info: Aug 21 20:09:59 volumio volumio[14378]: ---------------------------- MPD announces system playlist update Aug 21 20:09:59 volumio volumio[14378]: info: Ignoring MPD Status Update Aug 21 20:09:59 volumio volumio[14378]: info: Aug 21 20:09:59 volumio volumio[14378]: ---------------------------- MPD announces state update: player Aug 21 20:09:59 volumio volumio[14378]: info: ControllerMpd::getState Aug 21 20:09:59 volumio volumio[14378]: verbose: ControllerMpd::sendMpdCommand status Aug 21 20:09:59 volumio volumio[14378]: info: Aug 21 20:09:59 volumio volumio[14378]: ---------------------------- MPD announces system playlist update Aug 21 20:09:59 volumio volumio[14378]: info: Ignoring MPD Status Update Aug 21 20:09:59 volumio volumio[14378]: info: Aug 21 20:09:59 volumio volumio[14378]: ---------------------------- MPD announces state update: player Aug 21 20:09:59 volumio volumio[14378]: info: ControllerMpd::getState Aug 21 20:09:59 volumio volumio[14378]: verbose: ControllerMpd::sendMpdCommand status Aug 21 20:09:59 volumio volumio[14378]: info: Aug 21 20:09:59 volumio volumio[14378]: ---------------------------- MPD announces system playlist update Aug 21 20:09:59 volumio volumio[14378]: info: Ignoring MPD Status Update Aug 21 20:09:59 volumio volumio[14378]: info: Aug 21 20:09:59 volumio volumio[14378]: ---------------------------- MPD announces state update: player Aug 21 20:09:59 volumio volumio[14378]: info: ControllerMpd::getState Aug 21 20:09:59 volumio volumio[14378]: verbose: ControllerMpd::sendMpdCommand status Aug 21 20:09:59 volumio volumio[14378]: info: Aug 21 20:09:59 volumio volumio[14378]: ---------------------------- MPD announces system playlist update Aug 21 20:09:59 volumio volumio[14378]: info: Ignoring MPD Status Update Aug 21 20:09:59 volumio volumio[14378]: info: Aug 21 20:09:59 volumio volumio[14378]: ---------------------------- MPD announces state update: player Aug 21 20:09:59 volumio volumio[14378]: info: ControllerMpd::getState Aug 21 20:09:59 volumio volumio[14378]: verbose: ControllerMpd::sendMpdCommand status Aug 21 20:09:59 volumio volumio[14378]: info: ------------------------------ 5ms Aug 21 20:09:59 volumio volumio[14378]: info: sendMpdCommand status took 4 milliseconds Aug 21 20:09:59 volumio volumio[14378]: info: ------------------------------ 4ms Aug 21 20:09:59 volumio volumio[14378]: info: sendMpdCommand status took 3 milliseconds Aug 21 20:09:59 volumio volumio[14378]: info: ------------------------------ 3ms Aug 21 20:09:59 volumio volumio[14378]: info: sendMpdCommand status took 3 milliseconds Aug 21 20:09:59 volumio volumio[14378]: info: ------------------------------ 2ms Aug 21 20:09:59 volumio volumio[14378]: info: sendMpdCommand status took 2 milliseconds Aug 21 20:09:59 volumio volumio[14378]: verbose: ControllerMpd::parseState Aug 21 20:09:59 volumio volumio[14378]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 21 20:09:59 volumio volumio[14378]: verbose: ControllerMpd::parseState Aug 21 20:09:59 volumio volumio[14378]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 21 20:09:59 volumio volumio[14378]: verbose: ControllerMpd::parseState Aug 21 20:09:59 volumio volumio[14378]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 21 20:09:59 volumio volumio[14378]: verbose: ControllerMpd::parseState Aug 21 20:09:59 volumio volumio[14378]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 21 20:09:59 volumio volumio[14378]: info: sendMpdCommand playlistinfo took 2 milliseconds Aug 21 20:09:59 volumio volumio[14378]: info: sendMpdCommand playlistinfo took 1 milliseconds Aug 21 20:09:59 volumio volumio[14378]: info: sendMpdCommand playlistinfo took 1 milliseconds Aug 21 20:09:59 volumio volumio[14378]: info: sendMpdCommand playlistinfo took 1 milliseconds Aug 21 20:09:59 volumio volumio[14378]: verbose: ControllerMpd::parseTrackInfo Aug 21 20:09:59 volumio volumio[14378]: verbose: ControllerMpd::parseTrackInfo Aug 21 20:09:59 volumio volumio[14378]: verbose: ControllerMpd::parseTrackInfo Aug 21 20:09:59 volumio volumio[14378]: verbose: ControllerMpd::parseTrackInfo Aug 21 20:09:59 volumio volumio[14378]: info: ControllerMpd::pushState Aug 21 20:09:59 volumio volumio[14378]: info: CoreCommandRouter::servicePushState Aug 21 20:09:59 volumio volumio[14378]: info: CorePlayQueue::getTrack 7 Aug 21 20:09:59 volumio volumio[14378]: verbose: STATE SERVICE {"status":"play","position":0,"seek":105,"duration":60,"samplerate":"96 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"2811 Kbps","isStreaming":false,"title":"(515)","artist":"Slipknot","album":"Iowa","uri":"NAS/Thor_Cifs/Slipknot/Iowa (2014)/1 - (515).flac","trackType":"flac"} Aug 21 20:09:59 volumio volumio[14378]: verbose: CURRENT POSITION 7 Aug 21 20:09:59 volumio volumio[14378]: info: CoreStateMachine::syncState stateService play Aug 21 20:09:59 volumio volumio[14378]: info: CoreStateMachine::syncState currentStatus play Aug 21 20:09:59 volumio volumio[14378]: info: Received an update from plugin. extracting info from payload Aug 21 20:09:59 volumio volumio[14378]: info: CoreStateMachine::pushState Aug 21 20:09:59 volumio volumio[14378]: info: CorePlayQueue::getTrack 7 Aug 21 20:09:59 volumio volumio[14378]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 21 20:09:59 volumio volumio[14378]: info: CoreCommandRouter::volumioPushState Aug 21 20:09:59 volumio volumio[14378]: info: CoreStateMachine::pushState Aug 21 20:09:59 volumio volumio[14378]: info: CorePlayQueue::getTrack 7 Aug 21 20:09:59 volumio volumio[14378]: info: CoreCommandRouter::volumioPushState Aug 21 20:09:59 volumio volumio[14378]: info: ControllerMpd::pushState Aug 21 20:09:59 volumio volumio[14378]: info: CoreCommandRouter::servicePushState Aug 21 20:09:59 volumio volumio[14378]: info: CorePlayQueue::getTrack 7 Aug 21 20:09:59 volumio volumio[14378]: verbose: STATE SERVICE {"status":"play","position":0,"seek":105,"duration":60,"samplerate":"96 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"2811 Kbps","isStreaming":false,"title":"(515)","artist":"Slipknot","album":"Iowa","uri":"NAS/Thor_Cifs/Slipknot/Iowa (2014)/1 - (515).flac","trackType":"flac"} Aug 21 20:09:59 volumio volumio[14378]: verbose: CURRENT POSITION 7 Aug 21 20:09:59 volumio volumio[14378]: info: CoreStateMachine::syncState stateService play Aug 21 20:09:59 volumio volumio[14378]: info: CoreStateMachine::syncState currentStatus play Aug 21 20:09:59 volumio volumio[14378]: info: Received an update from plugin. extracting info from payload Aug 21 20:09:59 volumio volumio[14378]: info: CoreStateMachine::pushState Aug 21 20:09:59 volumio volumio[14378]: info: CorePlayQueue::getTrack 7 Aug 21 20:09:59 volumio volumio[14378]: info: CoreCommandRouter::volumioPushState Aug 21 20:09:59 volumio volumio[14378]: info: CoreStateMachine::pushState Aug 21 20:09:59 volumio volumio[14378]: info: CorePlayQueue::getTrack 7 Aug 21 20:09:59 volumio volumio[14378]: info: CoreCommandRouter::volumioPushState Aug 21 20:09:59 volumio volumio[14378]: info: ControllerMpd::pushState Aug 21 20:09:59 volumio volumio[14378]: info: CoreCommandRouter::servicePushState Aug 21 20:09:59 volumio volumio[14378]: info: CorePlayQueue::getTrack 7 Aug 21 20:09:59 volumio volumio[14378]: verbose: STATE SERVICE {"status":"play","position":0,"seek":105,"duration":60,"samplerate":"96 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"2811 Kbps","isStreaming":false,"title":"(515)","artist":"Slipknot","album":"Iowa","uri":"NAS/Thor_Cifs/Slipknot/Iowa (2014)/1 - (515).flac","trackType":"flac"} Aug 21 20:09:59 volumio volumio[14378]: verbose: CURRENT POSITION 7 Aug 21 20:09:59 volumio volumio[14378]: info: CoreStateMachine::syncState stateService play Aug 21 20:09:59 volumio volumio[14378]: info: CoreStateMachine::syncState currentStatus play Aug 21 20:09:59 volumio volumio[14378]: info: Received an update from plugin. extracting info from payload Aug 21 20:09:59 volumio volumio[14378]: info: CoreStateMachine::pushState Aug 21 20:09:59 volumio volumio[14378]: info: CorePlayQueue::getTrack 7 Aug 21 20:09:59 volumio volumio[14378]: info: CoreCommandRouter::volumioPushState Aug 21 20:09:59 volumio volumio[14378]: info: CoreStateMachine::pushState Aug 21 20:09:59 volumio volumio[14378]: info: CorePlayQueue::getTrack 7 Aug 21 20:09:59 volumio volumio[14378]: info: CoreCommandRouter::volumioPushState Aug 21 20:09:59 volumio volumio[14378]: info: ControllerMpd::pushState Aug 21 20:09:59 volumio volumio[14378]: info: CoreCommandRouter::servicePushState Aug 21 20:09:59 volumio volumio[14378]: info: CorePlayQueue::getTrack 7 Aug 21 20:09:59 volumio volumio[14378]: verbose: STATE SERVICE {"status":"play","position":0,"seek":105,"duration":60,"samplerate":"96 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"2811 Kbps","isStreaming":false,"title":"(515)","artist":"Slipknot","album":"Iowa","uri":"NAS/Thor_Cifs/Slipknot/Iowa (2014)/1 - (515).flac","trackType":"flac"} Aug 21 20:09:59 volumio volumio[14378]: verbose: CURRENT POSITION 7 Aug 21 20:09:59 volumio volumio[14378]: info: CoreStateMachine::syncState stateService play Aug 21 20:09:59 volumio volumio[14378]: info: CoreStateMachine::syncState currentStatus play Aug 21 20:09:59 volumio volumio[14378]: info: Received an update from plugin. extracting info from payload Aug 21 20:09:59 volumio volumio[14378]: info: CoreStateMachine::pushState Aug 21 20:09:59 volumio volumio[14378]: info: CorePlayQueue::getTrack 7 Aug 21 20:09:59 volumio volumio[14378]: info: CoreCommandRouter::volumioPushState Aug 21 20:09:59 volumio volumio[14378]: info: CoreStateMachine::pushState Aug 21 20:09:59 volumio volumio[14378]: info: CorePlayQueue::getTrack 7 Aug 21 20:09:59 volumio volumio[14378]: info: CoreCommandRouter::volumioPushState Aug 21 20:09:59 volumio volumio[14378]: info: ------------------------------ 21ms Aug 21 20:09:59 volumio volumio[14378]: info: ------------------------------ 22ms Aug 21 20:09:59 volumio volumio[14378]: info: ------------------------------ 21ms Aug 21 20:09:59 volumio volumio[14378]: info: ------------------------------ 20ms Aug 21 20:09:59 volumio volumio[14378]: info: CoreStateMachine::startPlaybackTimer Aug 21 20:09:59 volumio volumio[14378]: info: CorePlayQueue::getTrack 0 Aug 21 20:10:00 volumio volumio[14378]: info: CoreStateMachine::pushState Aug 21 20:10:00 volumio volumio[14378]: info: CorePlayQueue::getTrack 0 Aug 21 20:10:00 volumio volumio[14378]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 21 20:10:00 volumio volumio[14378]: info: CoreCommandRouter::volumioPushState Aug 21 20:10:00 volumio volumio[14378]: info: [LastFM] Current track has sufficient metadata: title ((515)) and artist (Slipknot) passed on explicitly Aug 21 20:10:02 volumio go-librespot[14582]: time="2024-08-21T20:10:02+01:00" level=error msg="failed receiving dealer message" error="failed to get reader: WebSocket closed: sent close frame: status = StatusServiceRestart and reason = \"\"" Aug 21 20:10:02 volumio go-librespot[14582]: time="2024-08-21T20:10:02+01:00" level=debug msg="renewing login5 access token" Aug 21 20:10:03 volumio kernel: CIFS: __readahead_batch() returned 521/1024 Aug 21 20:10:17 volumio volumio[14378]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 21 20:10:17 volumio volumio[14378]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 21 20:10:17 volumio volumio[14378]: info: Discovery: Getting this device information Aug 21 20:10:17 volumio volumio[14378]: info: CoreCommandRouter::volumioGetState Aug 21 20:10:17 volumio volumio[14378]: info: CorePlayQueue::getTrack 0 Aug 21 20:10:17 volumio volumio[14378]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 21 20:10:21 volumio go-librespot[14582]: time="2024-08-21T20:10:21+01:00" level=debug msg="renewing login5 access token" Aug 21 20:10:27 volumio go-librespot[14582]: time="2024-08-21T20:10:27+01:00" level=error msg="did not receive last pong from dealer, 90s passed" Aug 21 20:10:33 volumio go-librespot[14582]: time="2024-08-21T20:10:33+01:00" level=debug msg="authenticated as 1181596045" Aug 21 20:10:33 volumio go-librespot[14582]: time="2024-08-21T20:10:33+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 21 20:10:33 volumio go-librespot[14582]: time="2024-08-21T20:10:33+01:00" level=debug msg="re-established dealer connection" Aug 21 20:10:33 volumio go-librespot[14582]: time="2024-08-21T20:10:33+01:00" level=debug msg="received connection id: NTg1ODY2MjUtN2M2Mi00OGYwLTg1YjQtM2QxOTlhZDA1YjBiK2RlYWxlcit0Y3A6Ly8wYWNhNDE5Yy5pcC5nZXcxLnNwb3RpZnkubmV0OjU3MDArNDM2ODg4NkQ5NkFDRTZDNUZFNERBNTU3ODgzNjc2NzJDQjBGMkFCRDc0MTdDQUI3RjgyNkEyNjlGQkVFRDFBNw==" Aug 21 20:10:33 volumio go-librespot[14582]: time="2024-08-21T20:10:33+01:00" level=debug msg="put connect state because NEW_DEVICE" Aug 21 20:10:35 volumio volumio[14378]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 21 20:10:35 volumio volumio[14378]: Error: getaddrinfo ENOTFOUND ws.audioscrobbler.com Aug 21 20:10:35 volumio volumio[14378]: at GetAddrInfoReqWrap.onlookup [as oncomplete] (dns.js:67:26) { Aug 21 20:10:35 volumio volumio[14378]: errno: -3007, Aug 21 20:10:35 volumio volumio[14378]: code: 'ENOTFOUND', Aug 21 20:10:35 volumio volumio[14378]: syscall: 'getaddrinfo', Aug 21 20:10:35 volumio volumio[14378]: hostname: 'ws.audioscrobbler.com' Aug 21 20:10:35 volumio volumio[14378]: } Aug 21 20:10:35 volumio volumio[14378]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 21 20:10:36 volumio sudo[7997]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-08-21 20:09 Aug 21 20:10:36 volumio sudo[7997]: 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="5fd3886148e72a9cecd88a772d1f6079fb64d11a" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="8bb23b009e91ae4c7ecd678f193e7d3b281fca0c" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Mon 22 Jul 2024 07:17:01 PM CEST" VOLUMIO_VERSION="3.742" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="2782e52360f70dfab079c82951ebbbb1"