-- Logs begin at Wed 2025-10-29 02:00:00 CET, end at Wed 2025-10-29 16:51:21 CET. -- Oct 29 16:50:09 sala go-librespot[1032]: time="2025-10-29T16:50:09+01:00" level=trace msg="sent dealer ping" Oct 29 16:50:09 sala go-librespot[1032]: time="2025-10-29T16:50:09+01:00" level=trace msg="received dealer pong" Oct 29 16:50:11 sala go-librespot[1032]: time="2025-10-29T16:50:11+01:00" level=debug msg="fetched chunk 7/7, size: 414020" uri="spotify:track:3ZtaDLM4iqd5Pk8J4nCIit" Oct 29 16:50:39 sala go-librespot[1032]: time="2025-10-29T16:50:39+01:00" level=trace msg="sent dealer ping" Oct 29 16:50:39 sala go-librespot[1032]: time="2025-10-29T16:50:39+01:00" level=trace msg="received dealer pong" Oct 29 16:50:43 sala go-librespot[1032]: time="2025-10-29T16:50:43+01:00" level=debug msg="prefetching next track" uri="spotify:track:44pEkKrgliq1ALPjpySN7U" Oct 29 16:50:43 sala go-librespot[1032]: time="2025-10-29T16:50:43+01:00" level=debug msg="selected format OGG_VORBIS_320 (e28a468c5abe45e16d2cc3df75c0d896d1f0950d)" uri="spotify:track:44pEkKrgliq1ALPjpySN7U" Oct 29 16:50:43 sala go-librespot[1032]: time="2025-10-29T16:50:43+01:00" level=debug msg="requested aes key for file e28a468c5abe45e16d2cc3df75c0d896d1f0950d, gid: 44pEkKrgliq1ALPjpySN7U" Oct 29 16:50:43 sala go-librespot[1032]: time="2025-10-29T16:50:43+01:00" level=trace msg="found 2 cdn urls" uri="spotify:track:44pEkKrgliq1ALPjpySN7U" Oct 29 16:50:43 sala go-librespot[1032]: time="2025-10-29T16:50:43+01:00" level=debug msg="fetched first chunk of 8, total size is 3770040 bytes" uri="spotify:track:44pEkKrgliq1ALPjpySN7U" Oct 29 16:50:43 sala go-librespot[1032]: time="2025-10-29T16:50:43+01:00" level=info msg="prefetched track \"Piano Sonata No. 16 In C Major, K.545, IWM 416: II. Andante\" (duration: 124255ms)" uri="spotify:track:44pEkKrgliq1ALPjpySN7U" Oct 29 16:50:43 sala go-librespot[1032]: time="2025-10-29T16:50:43+01:00" level=debug msg="fetched chunk 3/7, size: 524288" uri="spotify:track:44pEkKrgliq1ALPjpySN7U" Oct 29 16:50:43 sala go-librespot[1032]: time="2025-10-29T16:50:43+01:00" level=debug msg="fetched chunk 1/7, size: 524288" uri="spotify:track:44pEkKrgliq1ALPjpySN7U" Oct 29 16:50:43 sala go-librespot[1032]: time="2025-10-29T16:50:43+01:00" level=debug msg="fetched chunk 2/7, size: 524288" uri="spotify:track:44pEkKrgliq1ALPjpySN7U" Oct 29 16:51:09 sala go-librespot[1032]: time="2025-10-29T16:51:09+01:00" level=trace msg="sent dealer ping" Oct 29 16:51:09 sala go-librespot[1032]: time="2025-10-29T16:51:09+01:00" level=trace msg="received dealer pong" Oct 29 16:51:12 sala go-librespot[1032]: time="2025-10-29T16:51:12+01:00" level=trace msg="emitting websocket event: not_playing" Oct 29 16:51:12 sala go-librespot[1032]: time="2025-10-29T16:51:12+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:44pEkKrgliq1ALPjpySN7U" Oct 29 16:51:12 sala volumio[788]: SPOTIFY: received: {"type":"not_playing","data":{"uri":"spotify:track:3ZtaDLM4iqd5Pk8J4nCIit","play_origin":"playlist/ondemand"}} Oct 29 16:51:12 sala volumio[788]: error: Failed to decode event: not_playing Oct 29 16:51:12 sala go-librespot[1032]: time="2025-10-29T16:51:12+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 29 16:51:12 sala go-librespot[1032]: time="2025-10-29T16:51:12+01:00" level=trace msg="emitting websocket event: will_play" Oct 29 16:51:12 sala go-librespot[1032]: time="2025-10-29T16:51:12+01:00" level=info msg="loaded track \"Piano Sonata No. 16 In C Major, K.545, IWM 416: II. Andante\" (paused: false, position: 0ms, duration: 124255ms, prefetched: true)" uri="spotify:track:44pEkKrgliq1ALPjpySN7U" Oct 29 16:51:12 sala volumio[788]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:44pEkKrgliq1ALPjpySN7U","play_origin":"playlist/ondemand"}} Oct 29 16:51:12 sala go-librespot[1032]: time="2025-10-29T16:51:12+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 29 16:51:12 sala go-librespot[1032]: time="2025-10-29T16:51:12+01:00" level=trace msg="scheduling prefetch in 95s" Oct 29 16:51:12 sala go-librespot[1032]: time="2025-10-29T16:51:12+01:00" level=trace msg="emitting websocket event: metadata" Oct 29 16:51:12 sala volumio[788]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:44pEkKrgliq1ALPjpySN7U","name":"Piano Sonata No. 16 In C Major, K.545, IWM 416: II. Andante","artist_names":["Wolfgang Amadeus Mozart","Moony's Music Box"],"album_name":"Mozart Dreams","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02b1b4da7af96542ba36a7776a","position":0,"duration":124255,"release_date":"year:2024 month:5 day:24","track_number":4,"disc_number":1}} Oct 29 16:51:12 sala go-librespot[1032]: time="2025-10-29T16:51:12+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 29 16:51:12 sala go-librespot[1032]: time="2025-10-29T16:51:12+01:00" level=trace msg="emitting websocket event: playing" Oct 29 16:51:12 sala volumio[788]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:44pEkKrgliq1ALPjpySN7U","resume":false,"play_origin":"playlist/ondemand"}} Oct 29 16:51:12 sala volumio[788]: SPOTIFY: PUSH STATE SPOTIFY Oct 29 16:51:12 sala volumio[788]: SPOTIFY: {"status":"play","service":"spop","title":"Piano Sonata No. 16 In C Major, K.545, IWM 416: II. Andante","artist":"Wolfgang Amadeus Mozart, Moony's Music Box","album":"Mozart Dreams","albumart":"https://i.scdn.co/image/ab67616d00001e02b1b4da7af96542ba36a7776a","uri":"spotify:track:44pEkKrgliq1ALPjpySN7U","trackType":"spotify","seek":0,"duration":124,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Oct 29 16:51:12 sala volumio[788]: info: CoreCommandRouter::servicePushState Oct 29 16:51:12 sala volumio[788]: info: CoreStateMachine::pushState Oct 29 16:51:12 sala volumio[788]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 29 16:51:12 sala volumio[788]: info: CoreCommandRouter::volumioPushState Oct 29 16:51:12 sala volumio[788]: info: MRS: Pushing multiroomSync output update for this device Oct 29 16:51:12 sala volumio[788]: info: MRS: Pushing multiroomSync output Oct 29 16:51:12 sala volumio[788]: info: CoreCommandRouter::volumioGetState Oct 29 16:51:12 sala volumio[788]: info: [LastFM] Current track has sufficient metadata: title (Piano Sonata No. 16 In C Major, K.545, IWM 416: II. Andante) and artist (Wolfgang Amadeus Mozart, Moony's Music Box) passed on explicitly Oct 29 16:51:12 sala volumio[788]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Oct 29 16:51:12 sala volumio[788]: SPOTIFY: PUSH STATE SPOTIFY Oct 29 16:51:12 sala volumio[788]: SPOTIFY: {"status":"play","service":"spop","title":"Piano Sonata No. 16 In C Major, K.545, IWM 416: II. Andante","artist":"Wolfgang Amadeus Mozart, Moony's Music Box","album":"Mozart Dreams","albumart":"https://i.scdn.co/image/ab67616d00001e02b1b4da7af96542ba36a7776a","uri":"spotify:track:44pEkKrgliq1ALPjpySN7U","trackType":"spotify","seek":0,"duration":124,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Oct 29 16:51:12 sala volumio[788]: info: CoreCommandRouter::servicePushState Oct 29 16:51:12 sala volumio[788]: info: CoreStateMachine::pushState Oct 29 16:51:12 sala volumio[788]: info: CoreCommandRouter::volumioPushState Oct 29 16:51:12 sala volumio[788]: info: MRS: Pushing multiroomSync output update for this device Oct 29 16:51:12 sala volumio[788]: info: MRS: Pushing multiroomSync output Oct 29 16:51:12 sala volumio[788]: info: CoreCommandRouter::volumioGetState Oct 29 16:51:12 sala volumio[788]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Oct 29 16:51:21 sala volumio[788]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 29 16:51:21 sala volumio[788]: TypeError: Cannot read property '@' of undefined Oct 29 16:51:21 sala volumio[788]: at Object.callback (/data/plugins/user_interface/lastfm/node_modules/simple-lastfm/lib/index.js:342:14) Oct 29 16:51:21 sala volumio[788]: at /data/plugins/user_interface/lastfm/node_modules/simple-lastfm/lib/index.js:60:13 Oct 29 16:51:21 sala volumio[788]: at Parser. (/data/plugins/user_interface/lastfm/node_modules/xml2js/lib/parser.js:308:18) Oct 29 16:51:21 sala volumio[788]: at Parser.emit (events.js:315:20) Oct 29 16:51:21 sala volumio[788]: at SAXParser.onerror (/data/plugins/user_interface/lastfm/node_modules/xml2js/lib/parser.js:123:26) Oct 29 16:51:21 sala volumio[788]: at emit (/data/plugins/user_interface/lastfm/node_modules/sax/lib/sax.js:624:35) Oct 29 16:51:21 sala volumio[788]: at error (/data/plugins/user_interface/lastfm/node_modules/sax/lib/sax.js:653:5) Oct 29 16:51:21 sala volumio[788]: at strictFail (/data/plugins/user_interface/lastfm/node_modules/sax/lib/sax.js:677:7) Oct 29 16:51:21 sala volumio[788]: at closeTag (/data/plugins/user_interface/lastfm/node_modules/sax/lib/sax.js:871:9) Oct 29 16:51:21 sala volumio[788]: at SAXParser.write (/data/plugins/user_interface/lastfm/node_modules/sax/lib/sax.js:1436:13) Oct 29 16:51:21 sala volumio[788]: at Parser.exports.Parser.Parser.parseString (/data/plugins/user_interface/lastfm/node_modules/xml2js/lib/parser.js:323:31) Oct 29 16:51:21 sala volumio[788]: at Parser.parseString (/data/plugins/user_interface/lastfm/node_modules/xml2js/lib/parser.js:5:59) Oct 29 16:51:21 sala volumio[788]: at IncomingMessage. (/data/plugins/user_interface/lastfm/node_modules/simple-lastfm/lib/index.js:58:14) Oct 29 16:51:21 sala volumio[788]: at IncomingMessage.emit (events.js:327:22) Oct 29 16:51:21 sala volumio[788]: at endReadableNT (internal/streams/readable.js:1327:12) Oct 29 16:51:21 sala volumio[788]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Oct 29 16:51:21 sala volumio[788]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 29 16:51:21 sala sudo[24549]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-10-29 16:50 Oct 29 16:51:21 sala sudo[24549]: 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"