-- Logs begin at Sat 2024-08-10 13:35:22 CEST, end at Mon 2024-08-19 20:05:27 CEST. -- Aug 19 20:04:06 volumio volumio[8209]: info: Preload queue cleared Aug 19 20:04:06 volumio volumio[8209]: info: CoreCommandRouter::volumioReplaceandPlayItems Aug 19 20:04:06 volumio volumio[8209]: info: CoreStateMachine::ClearQueue Aug 19 20:04:06 volumio volumio[8209]: info: CoreStateMachine::stop Aug 19 20:04:06 volumio volumio[8209]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 19 20:04:06 volumio volumio[8209]: info: CorePlayQueue::clearPlayQueue Aug 19 20:04:06 volumio volumio[8209]: info: CorePlayQueue::saveQueue Aug 19 20:04:06 volumio volumio[8209]: info: CoreCommandRouter::volumioPushQueue Aug 19 20:04:06 volumio volumio[8209]: info: CoreStateMachine::addQueueItems Aug 19 20:04:06 volumio volumio[8209]: info: CorePlayQueue::addQueueItems Aug 19 20:04:06 volumio volumio[8209]: info: Preload queue cleared Aug 19 20:04:06 volumio volumio[8209]: info: Adding Item to queue: spotify:track:3rFmrtpcBfak5TkuzrMlcy Aug 19 20:04:06 volumio volumio[8209]: info: Using cached record of: spotify:track:3rFmrtpcBfak5TkuzrMlcy Aug 19 20:04:06 volumio volumio[8209]: info: Adding Item to queue: spotify:track:3mh8dAddMus7Mgod3sgMhg Aug 19 20:04:06 volumio volumio[8209]: info: Using cached record of: spotify:track:3mh8dAddMus7Mgod3sgMhg Aug 19 20:04:06 volumio volumio[8209]: info: Adding Item to queue: spotify:track:4Pd8oZfp4Cz8XEjoDBgcwM Aug 19 20:04:06 volumio volumio[8209]: info: Using cached record of: spotify:track:4Pd8oZfp4Cz8XEjoDBgcwM Aug 19 20:04:06 volumio volumio[8209]: info: Adding Item to queue: spotify:track:53KdWqUKxIrTOmpOBtOyFX Aug 19 20:04:06 volumio volumio[8209]: info: Using cached record of: spotify:track:53KdWqUKxIrTOmpOBtOyFX Aug 19 20:04:06 volumio volumio[8209]: info: Adding Item to queue: spotify:track:2zZl1SVWLdY8MXEOS36WmA Aug 19 20:04:06 volumio volumio[8209]: info: Using cached record of: spotify:track:2zZl1SVWLdY8MXEOS36WmA Aug 19 20:04:06 volumio volumio[8209]: info: Adding Item to queue: spotify:track:4oEUGxT90NT1TGYCcqx2Mi Aug 19 20:04:06 volumio volumio[8209]: info: Using cached record of: spotify:track:4oEUGxT90NT1TGYCcqx2Mi Aug 19 20:04:06 volumio volumio[8209]: info: Adding Item to queue: spotify:track:7eVoTiw6TVqWmvcojgvnEk Aug 19 20:04:06 volumio volumio[8209]: info: Using cached record of: spotify:track:7eVoTiw6TVqWmvcojgvnEk Aug 19 20:04:06 volumio volumio[8209]: info: Adding Item to queue: spotify:track:4eBIZcq5VnXl2a7a0japoW Aug 19 20:04:06 volumio volumio[8209]: info: Using cached record of: spotify:track:4eBIZcq5VnXl2a7a0japoW Aug 19 20:04:06 volumio volumio[8209]: info: Adding Item to queue: spotify:track:6bgykvPNkRNYcwwt2sg01k Aug 19 20:04:06 volumio volumio[8209]: info: Using cached record of: spotify:track:6bgykvPNkRNYcwwt2sg01k Aug 19 20:04:06 volumio volumio[8209]: info: Adding Item to queue: spotify:track:1XpHw3cYKVvQflS8G7ERCL Aug 19 20:04:06 volumio volumio[8209]: info: Using cached record of: spotify:track:1XpHw3cYKVvQflS8G7ERCL Aug 19 20:04:06 volumio volumio[8209]: info: Adding Item to queue: spotify:track:3owhrbmmKk6DRbTUjz2sGZ Aug 19 20:04:06 volumio volumio[8209]: info: Using cached record of: spotify:track:3owhrbmmKk6DRbTUjz2sGZ Aug 19 20:04:06 volumio volumio[8209]: info: Adding Item to queue: spotify:track:0EY7PcSH6GerqEbs30eIUN Aug 19 20:04:06 volumio volumio[8209]: info: Using cached record of: spotify:track:0EY7PcSH6GerqEbs30eIUN Aug 19 20:04:06 volumio volumio[8209]: info: Adding Item to queue: spotify:track:3z4Ct1zZxKXZZAUdgViVKv Aug 19 20:04:06 volumio volumio[8209]: info: Using cached record of: spotify:track:3z4Ct1zZxKXZZAUdgViVKv Aug 19 20:04:06 volumio volumio[8209]: info: Adding Item to queue: spotify:track:4Wxu5XjcdF6LpNHE3ljuuO Aug 19 20:04:06 volumio volumio[8209]: info: Using cached record of: spotify:track:4Wxu5XjcdF6LpNHE3ljuuO Aug 19 20:04:06 volumio volumio[8209]: info: CoreCommandRouter::volumioPushQueue Aug 19 20:04:06 volumio volumio[8209]: info: CorePlayQueue::saveQueue Aug 19 20:04:06 volumio volumio[8209]: info: CoreStateMachine::updateTrackBlock Aug 19 20:04:06 volumio volumio[8209]: info: CorePlayQueue::getTrackBlock Aug 19 20:04:06 volumio volumio[8209]: info: CoreCommandRouter::volumioPlay Aug 19 20:04:06 volumio volumio[8209]: info: CoreStateMachine::play index 7 Aug 19 20:04:06 volumio volumio[8209]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 19 20:04:06 volumio volumio[8209]: info: CoreStateMachine::stop Aug 19 20:04:06 volumio volumio[8209]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 19 20:04:06 volumio volumio[8209]: info: CoreStateMachine::play index undefined Aug 19 20:04:06 volumio volumio[8209]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 19 20:04:06 volumio volumio[8209]: info: CorePlayQueue::getTrack 7 Aug 19 20:04:06 volumio volumio[8209]: info: CoreStateMachine::startPlaybackTimer Aug 19 20:04:06 volumio volumio[8209]: info: CorePlayQueue::getTrack 7 Aug 19 20:04:06 volumio volumio[8209]: info: [1724090646941] ControllerSpotify::clearAddPlayTrack Aug 19 20:04:06 volumio volumio[8209]: info: Sending Spotify command with payload to local API: /player/play Aug 19 20:04:14 volumio volumio[8209]: info: CoreCommandRouter::volumioGetState Aug 19 20:04:14 volumio volumio[8209]: info: CorePlayQueue::getTrack 7 Aug 19 20:04:15 volumio go-librespot[8457]: time="2024-08-19T20:04:15+02:00" level=warning msg="failed fetching new endpoint for dealer" error="failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=dealer\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Aug 19 20:04:24 volumio go-librespot[8457]: time="2024-08-19T20:04:24+02:00" level=debug msg="re-established dealer connection" Aug 19 20:04:26 volumio go-librespot[8457]: time="2024-08-19T20:04:26+02:00" level=error msg="failed receiving packet" error="failed reading packet header: read tcp 192.168.178.37:39478->34.158.0.131:443: read: connection reset by peer" Aug 19 20:04:26 volumio go-librespot[8457]: time="2024-08-19T20:04:26+02:00" level=debug msg="completed keyexchange" Aug 19 20:04:26 volumio go-librespot[8457]: time="2024-08-19T20:04:26+02:00" level=debug msg="completed challenge" Aug 19 20:04:26 volumio go-librespot[8457]: time="2024-08-19T20:04:26+02:00" level=debug msg="authenticated as rocqqoxbqr2vt9yo7ckmuz0ji" Aug 19 20:04:26 volumio go-librespot[8457]: time="2024-08-19T20:04:26+02:00" level=debug msg="re-established accesspoint connection" Aug 19 20:04:26 volumio go-librespot[8457]: time="2024-08-19T20:04:26+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Aug 19 20:04:26 volumio go-librespot[8457]: time="2024-08-19T20:04:26+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Aug 19 20:04:26 volumio go-librespot[8457]: time="2024-08-19T20:04:26+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 19 20:04:26 volumio go-librespot[8457]: time="2024-08-19T20:04:26+02:00" level=trace msg="scheduling prefetch in 171s" Aug 19 20:04:26 volumio go-librespot[8457]: time="2024-08-19T20:04:26+02:00" level=debug msg="pause track at 0ms" Aug 19 20:04:27 volumio go-librespot[8457]: time="2024-08-19T20:04:27+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 19 20:04:27 volumio go-librespot[8457]: time="2024-08-19T20:04:27+02:00" level=trace msg="emitting websocket event: not_playing" Aug 19 20:04:27 volumio go-librespot[8457]: time="2024-08-19T20:04:27+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:4eBIZcq5VnXl2a7a0japoW" Aug 19 20:04:27 volumio volumio[8209]: SPOTIFY: received: {"type":"not_playing","data":{"uri":"spotify:track:7eVoTiw6TVqWmvcojgvnEk","play_origin":"go-librespot"}} Aug 19 20:04:27 volumio volumio[8209]: error: Failed to decode event: not_playing Aug 19 20:04:27 volumio go-librespot[8457]: time="2024-08-19T20:04:27+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 19 20:04:27 volumio go-librespot[8457]: time="2024-08-19T20:04:27+02:00" level=trace msg="emitting websocket event: will_play" Aug 19 20:04:27 volumio volumio[8209]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:4eBIZcq5VnXl2a7a0japoW","play_origin":"go-librespot"}} Aug 19 20:04:27 volumio go-librespot[8457]: time="2024-08-19T20:04:27+02:00" level=debug msg="selected format OGG_VORBIS_320 (49dc26a37989e6dbc160e307eb6b784abe6ede76)" uri="spotify:track:4eBIZcq5VnXl2a7a0japoW" Aug 19 20:04:27 volumio go-librespot[8457]: time="2024-08-19T20:04:27+02:00" level=debug msg="requested aes key for file 49dc26a37989e6dbc160e307eb6b784abe6ede76, gid: 4eBIZcq5VnXl2a7a0japoW" Aug 19 20:04:29 volumio volumio[8209]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 19 20:04:29 volumio volumio[8209]: info: Received Get System Info Aug 19 20:04:29 volumio volumio[8209]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 19 20:04:29 volumio volumio[8209]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 19 20:04:29 volumio volumio[8209]: info: Discovery: Getting this device information Aug 19 20:04:29 volumio volumio[8209]: info: CoreCommandRouter::volumioGetState Aug 19 20:04:29 volumio volumio[8209]: info: CorePlayQueue::getTrack 7 Aug 19 20:04:29 volumio volumio[8209]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 19 20:05:25 volumio go-librespot[8457]: time="2024-08-19T20:05:25+02:00" level=error msg="did not receive last pong from dealer, 32s passed" Aug 19 20:05:26 volumio volumio[8209]: info: CoreCommandRouter::volumioGetState Aug 19 20:05:26 volumio volumio[8209]: info: CorePlayQueue::getTrack 7 Aug 19 20:05:27 volumio volumio[8209]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 19 20:05:27 volumio volumio[8209]: Error: connect ETIMEDOUT 130.211.19.189:80 Aug 19 20:05:27 volumio volumio[8209]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) { Aug 19 20:05:27 volumio volumio[8209]: errno: -110, Aug 19 20:05:27 volumio volumio[8209]: code: 'ETIMEDOUT', Aug 19 20:05:27 volumio volumio[8209]: syscall: 'connect', Aug 19 20:05:27 volumio volumio[8209]: address: '130.211.19.189', Aug 19 20:05:27 volumio volumio[8209]: port: 80 Aug 19 20:05:27 volumio volumio[8209]: } Aug 19 20:05:27 volumio volumio[8209]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 19 20:05:27 volumio sudo[7826]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-08-19 20:04 Aug 19 20:05:27 volumio sudo[7826]: 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"