-- Logs begin at Thu 2019-02-14 11:11:59 CET, end at Mon 2025-11-03 09:30:45 CET. -- Nov 03 09:29:06 mxp02-pl go-librespot[1233]: time="2025-11-03T09:29:06+01:00" level=debug msg="fetched chunk 14/17, size: 524288" uri="spotify:track:2dgCLaj5roCIQcnpL7mG52" Nov 03 09:29:20 mxp02-pl go-librespot[1233]: time="2025-11-03T09:29:20+01:00" level=debug msg="fetched chunk 15/17, size: 524288" uri="spotify:track:2dgCLaj5roCIQcnpL7mG52" Nov 03 09:29:27 mxp02-pl go-librespot[1233]: time="2025-11-03T09:29:27+01:00" level=trace msg="sent dealer ping" Nov 03 09:29:27 mxp02-pl go-librespot[1233]: time="2025-11-03T09:29:27+01:00" level=trace msg="received dealer pong" Nov 03 09:29:27 mxp02-pl go-librespot[1233]: time="2025-11-03T09:29:27+01:00" level=trace msg="received accesspoint ping" Nov 03 09:29:27 mxp02-pl go-librespot[1233]: time="2025-11-03T09:29:27+01:00" level=trace msg="received accesspoint pong ack" Nov 03 09:29:32 mxp02-pl go-librespot[1233]: time="2025-11-03T09:29:32+01:00" level=debug msg="fetched chunk 16/17, size: 524288" uri="spotify:track:2dgCLaj5roCIQcnpL7mG52" Nov 03 09:29:42 mxp02-pl go-librespot[1233]: time="2025-11-03T09:29:42+01:00" level=debug msg="fetched chunk 17/17, size: 512411" uri="spotify:track:2dgCLaj5roCIQcnpL7mG52" Nov 03 09:29:57 mxp02-pl go-librespot[1233]: time="2025-11-03T09:29:57+01:00" level=trace msg="sent dealer ping" Nov 03 09:29:57 mxp02-pl go-librespot[1233]: time="2025-11-03T09:29:57+01:00" level=trace msg="received dealer pong" Nov 03 09:30:27 mxp02-pl go-librespot[1233]: time="2025-11-03T09:30:27+01:00" level=trace msg="sent dealer ping" Nov 03 09:30:27 mxp02-pl go-librespot[1233]: time="2025-11-03T09:30:27+01:00" level=trace msg="received dealer pong" Nov 03 09:30:38 mxp02-pl volumio[848]: info: CorePlayQueue::getTrack 10 Nov 03 09:30:38 mxp02-pl volumio[848]: info: CorePlayQueue::getTrack 11 Nov 03 09:30:38 mxp02-pl volumio[848]: info: Prefetching next song Nov 03 09:30:38 mxp02-pl volumio[848]: info: [1762158638663] ControllerSpotify::prefetch Nov 03 09:30:38 mxp02-pl volumio[848]: info: Sending Spotify command with payload to local API: /player/add_to_queue Nov 03 09:30:38 mxp02-pl go-librespot[1233]: time="2025-11-03T09:30:38+01:00" level=debug msg="renewing login5 access token" Nov 03 09:30:38 mxp02-pl go-librespot[1233]: time="2025-11-03T09:30:38+01:00" level=info msg="authenticated Login5" username="c3*********************6r" Nov 03 09:30:38 mxp02-pl go-librespot[1233]: time="2025-11-03T09:30:38+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 03 09:30:38 mxp02-pl go-librespot[1233]: time="2025-11-03T09:30:38+01:00" level=debug msg="prefetching next track" uri="spotify:track:6y5BbtRIpHrmASBZql2vK7" Nov 03 09:30:38 mxp02-pl go-librespot[1233]: time="2025-11-03T09:30:38+01:00" level=debug msg="selected format OGG_VORBIS_320 (9fe194d2c63caf6fa23af624864c7ffcfe990910)" uri="spotify:track:6y5BbtRIpHrmASBZql2vK7" Nov 03 09:30:38 mxp02-pl go-librespot[1233]: time="2025-11-03T09:30:38+01:00" level=debug msg="requested aes key for file 9fe194d2c63caf6fa23af624864c7ffcfe990910, gid: 6y5BbtRIpHrmASBZql2vK7" Nov 03 09:30:38 mxp02-pl go-librespot[1233]: time="2025-11-03T09:30:38+01:00" level=trace msg="found 2 cdn urls" uri="spotify:track:6y5BbtRIpHrmASBZql2vK7" Nov 03 09:30:39 mxp02-pl go-librespot[1233]: time="2025-11-03T09:30:39+01:00" level=debug msg="fetched first chunk of 25, total size is 12866101 bytes" uri="spotify:track:6y5BbtRIpHrmASBZql2vK7" Nov 03 09:30:39 mxp02-pl go-librespot[1233]: time="2025-11-03T09:30:39+01:00" level=info msg="prefetched track \"Billboard Heart\" (duration: 307200ms)" uri="spotify:track:6y5BbtRIpHrmASBZql2vK7" Nov 03 09:30:39 mxp02-pl go-librespot[1233]: time="2025-11-03T09:30:39+01:00" level=debug msg="fetched chunk 2/24, size: 524288" uri="spotify:track:6y5BbtRIpHrmASBZql2vK7" Nov 03 09:30:39 mxp02-pl go-librespot[1233]: time="2025-11-03T09:30:39+01:00" level=debug msg="fetched chunk 3/24, size: 524288" uri="spotify:track:6y5BbtRIpHrmASBZql2vK7" Nov 03 09:30:39 mxp02-pl go-librespot[1233]: time="2025-11-03T09:30:39+01:00" level=debug msg="fetched chunk 1/24, size: 524288" uri="spotify:track:6y5BbtRIpHrmASBZql2vK7" Nov 03 09:30:40 mxp02-pl go-librespot[1233]: time="2025-11-03T09:30:40+01:00" level=trace msg="emitting websocket event: not_playing" Nov 03 09:30:40 mxp02-pl go-librespot[1233]: time="2025-11-03T09:30:40+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:6y5BbtRIpHrmASBZql2vK7" Nov 03 09:30:40 mxp02-pl volumio[848]: SPOTIFY: received: {"type":"not_playing","data":{"uri":"spotify:track:2dgCLaj5roCIQcnpL7mG52","play_origin":"go-librespot"}} Nov 03 09:30:40 mxp02-pl volumio[848]: error: Failed to decode event: not_playing Nov 03 09:30:40 mxp02-pl go-librespot[1233]: time="2025-11-03T09:30:40+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 03 09:30:40 mxp02-pl go-librespot[1233]: time="2025-11-03T09:30:40+01:00" level=trace msg="emitting websocket event: will_play" Nov 03 09:30:40 mxp02-pl go-librespot[1233]: time="2025-11-03T09:30:40+01:00" level=info msg="loaded track \"Billboard Heart\" (paused: false, position: 0ms, duration: 307200ms, prefetched: true)" uri="spotify:track:6y5BbtRIpHrmASBZql2vK7" Nov 03 09:30:40 mxp02-pl volumio[848]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:6y5BbtRIpHrmASBZql2vK7","play_origin":"go-librespot"}} Nov 03 09:30:40 mxp02-pl go-librespot[1233]: time="2025-11-03T09:30:40+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 03 09:30:40 mxp02-pl go-librespot[1233]: time="2025-11-03T09:30:40+01:00" level=trace msg="scheduling prefetch in 277s" Nov 03 09:30:40 mxp02-pl go-librespot[1233]: time="2025-11-03T09:30:40+01:00" level=trace msg="emitting websocket event: metadata" Nov 03 09:30:40 mxp02-pl volumio[848]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:6y5BbtRIpHrmASBZql2vK7","name":"Billboard Heart","artist_names":["Deep Sea Diver"],"album_name":"Billboard Heart","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0265458cb2ba62c608edc097a1","position":0,"duration":307200,"release_date":"year:2025 month:2 day:28","track_number":1,"disc_number":1}} Nov 03 09:30:40 mxp02-pl go-librespot[1233]: time="2025-11-03T09:30:40+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 03 09:30:40 mxp02-pl go-librespot[1233]: time="2025-11-03T09:30:40+01:00" level=trace msg="emitting websocket event: playing" Nov 03 09:30:40 mxp02-pl volumio[848]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:6y5BbtRIpHrmASBZql2vK7","resume":false,"play_origin":"go-librespot"}} Nov 03 09:30:40 mxp02-pl volumio[848]: SPOTIFY: PUSH STATE SPOTIFY Nov 03 09:30:40 mxp02-pl volumio[848]: SPOTIFY: {"status":"play","service":"spop","title":"Billboard Heart","artist":"Deep Sea Diver","album":"Billboard Heart","albumart":"https://i.scdn.co/image/ab67616d00001e0265458cb2ba62c608edc097a1","uri":"spotify:track:6y5BbtRIpHrmASBZql2vK7","trackType":"spotify","seek":0,"duration":307,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Nov 03 09:30:40 mxp02-pl volumio[848]: info: CoreCommandRouter::servicePushState Nov 03 09:30:40 mxp02-pl volumio[848]: info: CorePlayQueue::getTrack 10 Nov 03 09:30:40 mxp02-pl volumio[848]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Billboard Heart","artist":"Deep Sea Diver","album":"Billboard Heart","albumart":"https://i.scdn.co/image/ab67616d00001e0265458cb2ba62c608edc097a1","uri":"spotify:track:6y5BbtRIpHrmASBZql2vK7","trackType":"spotify","seek":0,"duration":307,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Nov 03 09:30:40 mxp02-pl volumio[848]: verbose: CURRENT POSITION 10 Nov 03 09:30:40 mxp02-pl volumio[848]: info: CoreStateMachine::syncState stateService play Nov 03 09:30:40 mxp02-pl volumio[848]: info: CoreStateMachine::syncState currentStatus play Nov 03 09:30:40 mxp02-pl volumio[848]: info: Received an update from plugin. extracting info from payload Nov 03 09:30:40 mxp02-pl volumio[848]: info: CoreStateMachine::pushState Nov 03 09:30:40 mxp02-pl volumio[848]: info: CorePlayQueue::getTrack 10 Nov 03 09:30:40 mxp02-pl volumio[848]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 03 09:30:40 mxp02-pl volumio[848]: info: CoreCommandRouter::volumioPushState Nov 03 09:30:40 mxp02-pl volumio[848]: info: CoreStateMachine::pushState Nov 03 09:30:40 mxp02-pl volumio[848]: info: CorePlayQueue::getTrack 10 Nov 03 09:30:40 mxp02-pl volumio[848]: info: CoreCommandRouter::volumioPushState Nov 03 09:30:40 mxp02-pl volumio[848]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Nov 03 09:30:40 mxp02-pl volumio[848]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Nov 03 09:30:40 mxp02-pl volumio[848]: SPOTIFY: PUSH STATE SPOTIFY Nov 03 09:30:40 mxp02-pl volumio[848]: SPOTIFY: {"status":"play","service":"spop","title":"Billboard Heart","artist":"Deep Sea Diver","album":"Billboard Heart","albumart":"https://i.scdn.co/image/ab67616d00001e0265458cb2ba62c608edc097a1","uri":"spotify:track:6y5BbtRIpHrmASBZql2vK7","trackType":"spotify","seek":0,"duration":307,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Nov 03 09:30:40 mxp02-pl volumio[848]: info: CoreCommandRouter::servicePushState Nov 03 09:30:40 mxp02-pl volumio[848]: info: CorePlayQueue::getTrack 10 Nov 03 09:30:40 mxp02-pl volumio[848]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Billboard Heart","artist":"Deep Sea Diver","album":"Billboard Heart","albumart":"https://i.scdn.co/image/ab67616d00001e0265458cb2ba62c608edc097a1","uri":"spotify:track:6y5BbtRIpHrmASBZql2vK7","trackType":"spotify","seek":0,"duration":307,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Nov 03 09:30:40 mxp02-pl volumio[848]: verbose: CURRENT POSITION 10 Nov 03 09:30:40 mxp02-pl volumio[848]: info: CoreStateMachine::syncState stateService play Nov 03 09:30:40 mxp02-pl volumio[848]: info: CoreStateMachine::syncState currentStatus play Nov 03 09:30:40 mxp02-pl volumio[848]: info: Received an update from plugin. extracting info from payload Nov 03 09:30:40 mxp02-pl volumio[848]: info: CoreStateMachine::pushState Nov 03 09:30:40 mxp02-pl volumio[848]: info: CorePlayQueue::getTrack 10 Nov 03 09:30:40 mxp02-pl volumio[848]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 03 09:30:40 mxp02-pl volumio[848]: info: CoreCommandRouter::volumioPushState Nov 03 09:30:40 mxp02-pl volumio[848]: info: CoreStateMachine::pushState Nov 03 09:30:40 mxp02-pl volumio[848]: info: CorePlayQueue::getTrack 10 Nov 03 09:30:40 mxp02-pl volumio[848]: info: CoreCommandRouter::volumioPushState Nov 03 09:30:40 mxp02-pl volumio[848]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Nov 03 09:30:40 mxp02-pl volumio[848]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Nov 03 09:30:43 mxp02-pl volumio[848]: info: CoreStateMachine::startPlaybackTimer Nov 03 09:30:43 mxp02-pl volumio[848]: info: CorePlayQueue::getTrack 11 Nov 03 09:30:43 mxp02-pl volumio[848]: info: CoreStateMachine::pushState Nov 03 09:30:43 mxp02-pl volumio[848]: info: CorePlayQueue::getTrack 11 Nov 03 09:30:43 mxp02-pl volumio[848]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 03 09:30:43 mxp02-pl volumio[848]: info: CoreCommandRouter::volumioPushState Nov 03 09:30:43 mxp02-pl volumio[848]: info: [LastFM] Current track has sufficient metadata: title (Billboard Heart) and artist (Deep Sea Diver) passed on explicitly Nov 03 09:30:43 mxp02-pl volumio[848]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Nov 03 09:30:44 mxp02-pl volumio[848]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 03 09:30:44 mxp02-pl volumio[848]: TypeError: Cannot read property '@' of null Nov 03 09:30:44 mxp02-pl volumio[848]: at Object.callback (/data/plugins/user_interface/lastfm/node_modules/simple-lastfm/lib/index.js:342:14) Nov 03 09:30:44 mxp02-pl volumio[848]: at /data/plugins/user_interface/lastfm/node_modules/simple-lastfm/lib/index.js:60:13 Nov 03 09:30:44 mxp02-pl volumio[848]: at Parser. (/data/plugins/user_interface/lastfm/node_modules/xml2js/lib/parser.js:304:18) Nov 03 09:30:44 mxp02-pl volumio[848]: at Parser.emit (events.js:315:20) Nov 03 09:30:44 mxp02-pl volumio[848]: at Parser.exports.Parser.Parser.parseString (/data/plugins/user_interface/lastfm/node_modules/xml2js/lib/parser.js:314:16) Nov 03 09:30:44 mxp02-pl volumio[848]: at Parser.parseString (/data/plugins/user_interface/lastfm/node_modules/xml2js/lib/parser.js:5:59) Nov 03 09:30:44 mxp02-pl volumio[848]: at IncomingMessage. (/data/plugins/user_interface/lastfm/node_modules/simple-lastfm/lib/index.js:58:14) Nov 03 09:30:44 mxp02-pl volumio[848]: at IncomingMessage.emit (events.js:327:22) Nov 03 09:30:44 mxp02-pl volumio[848]: at endReadableNT (internal/streams/readable.js:1327:12) Nov 03 09:30:44 mxp02-pl volumio[848]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Nov 03 09:30:44 mxp02-pl volumio[848]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 03 09:30:45 mxp02-pl sudo[10007]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-11-03 09:29 Nov 03 09:30:45 mxp02-pl sudo[10007]: 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="29866754e5f1d7e4d0f581c10d9f22852f6f21db" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="fc4c820ddd3b5fc1a7a6b54ef112273ebd122010" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Sat 26 Jul 2025 10:25:36 AM CEST" VOLUMIO_VERSION="3.832" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="cf6e14681b2ecbbdc9a62186b0f3114c"