Sep 15 23:09:00 volumio volumio[1072]: info: CoreCommandRouter::volumioGetState Sep 15 23:09:00 volumio volumio[1072]: info: Listing playlists Sep 15 23:09:00 volumio volumio[1072]: info: Listing playlists Sep 15 23:09:02 volumio go-librespot[1605]: time="2025-09-15T23:09:02+02:00" level=trace msg="sent dealer ping" Sep 15 23:09:02 volumio go-librespot[1605]: time="2025-09-15T23:09:02+02:00" level=trace msg="received dealer pong" Sep 15 23:09:04 volumio go-librespot[1605]: time="2025-09-15T23:09:04+02:00" level=debug msg="fetched chunk 10/12, size: 524288" uri="spotify:track:7dZ4UpEKMGIultDdt0jRzS" Sep 15 23:09:10 volumio volumio[1072]: info: CoreCommandRouter::volumioGetState Sep 15 23:09:16 volumio go-librespot[1605]: time="2025-09-15T23:09:16+02:00" level=debug msg="fetched chunk 11/12, size: 524288" uri="spotify:track:7dZ4UpEKMGIultDdt0jRzS" Sep 15 23:09:20 volumio volumio[1072]: info: CoreCommandRouter::volumioGetState Sep 15 23:09:20 volumio volumio[1072]: info: Listing playlists Sep 15 23:09:20 volumio volumio[1072]: info: Listing playlists Sep 15 23:09:28 volumio go-librespot[1605]: time="2025-09-15T23:09:28+02:00" level=debug msg="fetched chunk 12/12, size: 493387" uri="spotify:track:7dZ4UpEKMGIultDdt0jRzS" Sep 15 23:09:30 volumio volumio[1072]: info: CoreCommandRouter::volumioGetState Sep 15 23:09:32 volumio go-librespot[1605]: time="2025-09-15T23:09:32+02:00" level=trace msg="sent dealer ping" Sep 15 23:09:32 volumio go-librespot[1605]: time="2025-09-15T23:09:32+02:00" level=trace msg="received dealer pong" Sep 15 23:09:33 volumio go-librespot[1605]: time="2025-09-15T23:09:33+02:00" level=trace msg="received accesspoint ping" Sep 15 23:09:33 volumio nmbd[1053]: [2025/09/15 23:09:33.076105, 0] ../../source3/nmbd/nmbd_namequery.c:109(query_name_response) Sep 15 23:09:33 volumio nmbd[1053]: query_name_response: Multiple (2) responses received for a query on subnet 192.168.1.142 for name WORKGROUP<1d>. Sep 15 23:09:33 volumio nmbd[1053]: This response was from IP 192.168.1.213, reporting an IP address of 192.168.1.213. Sep 15 23:09:33 volumio go-librespot[1605]: time="2025-09-15T23:09:33+02:00" level=trace msg="received accesspoint pong ack" Sep 15 23:09:36 volumio systemd[1]: Starting setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service... Sep 15 23:09:36 volumio dbus-daemon[647]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.62740' (uid=0 pid=2114 comm="timedatectl show --property=NTPSynchronized --valu") Sep 15 23:09:36 volumio systemd[1]: Starting systemd-timedated.service - Time & Date Service... Sep 15 23:09:36 volumio dbus-daemon[647]: [system] Successfully activated service 'org.freedesktop.timedate1' Sep 15 23:09:36 volumio systemd[1]: Started systemd-timedated.service - Time & Date Service. Sep 15 23:09:36 volumio setdatetime-helper.sh[2113]: Time is already synchronized. Sep 15 23:09:36 volumio systemd[1]: setdatetime-helper.timer.service: Deactivated successfully. Sep 15 23:09:36 volumio systemd[1]: Finished setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service. Sep 15 23:09:40 volumio volumio[1072]: info: CoreCommandRouter::volumioGetState Sep 15 23:09:40 volumio volumio[1072]: info: Listing playlists Sep 15 23:09:40 volumio volumio[1072]: info: Listing playlists Sep 15 23:09:48 volumio go-librespot[1605]: time="2025-09-15T23:09:48+02:00" level=debug msg="prefetching next track" uri="spotify:track:2oxFYjDFaJ1ph1vO04EsZw" Sep 15 23:09:48 volumio go-librespot[1605]: time="2025-09-15T23:09:48+02:00" level=debug msg="renewing login5 access token" Sep 15 23:09:49 volumio go-librespot[1605]: time="2025-09-15T23:09:49+02:00" level=info msg="authenticated Login5" username="se*****yo" Sep 15 23:09:49 volumio go-librespot[1605]: time="2025-09-15T23:09:49+02:00" level=debug msg="selected format OGG_VORBIS_320 (04eb34df5a9395732a7a226e0e7c594dcb285ebc)" uri="spotify:track:2oxFYjDFaJ1ph1vO04EsZw" Sep 15 23:09:49 volumio go-librespot[1605]: time="2025-09-15T23:09:49+02:00" level=debug msg="requested aes key for file 04eb34df5a9395732a7a226e0e7c594dcb285ebc, gid: 2oxFYjDFaJ1ph1vO04EsZw" Sep 15 23:09:49 volumio go-librespot[1605]: time="2025-09-15T23:09:49+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:2oxFYjDFaJ1ph1vO04EsZw" Sep 15 23:09:49 volumio go-librespot[1605]: time="2025-09-15T23:09:49+02:00" level=debug msg="fetched first chunk of 13, total size is 6779704 bytes" uri="spotify:track:2oxFYjDFaJ1ph1vO04EsZw" Sep 15 23:09:49 volumio go-librespot[1605]: time="2025-09-15T23:09:49+02:00" level=info msg="prefetched track \"Cleaned Out\" (duration: 187387ms)" uri="spotify:track:2oxFYjDFaJ1ph1vO04EsZw" Sep 15 23:09:49 volumio go-librespot[1605]: time="2025-09-15T23:09:49+02:00" level=debug msg="fetched chunk 1/12, size: 524288" uri="spotify:track:2oxFYjDFaJ1ph1vO04EsZw" Sep 15 23:09:49 volumio go-librespot[1605]: time="2025-09-15T23:09:49+02:00" level=debug msg="fetched chunk 2/12, size: 524288" uri="spotify:track:2oxFYjDFaJ1ph1vO04EsZw" Sep 15 23:09:49 volumio go-librespot[1605]: time="2025-09-15T23:09:49+02:00" level=debug msg="fetched chunk 3/12, size: 524288" uri="spotify:track:2oxFYjDFaJ1ph1vO04EsZw" Sep 15 23:09:50 volumio volumio[1072]: info: CoreCommandRouter::volumioGetState Sep 15 23:10:00 volumio volumio[1072]: info: CoreCommandRouter::volumioGetState Sep 15 23:10:00 volumio volumio[1072]: info: Listing playlists Sep 15 23:10:00 volumio volumio[1072]: info: Listing playlists Sep 15 23:10:02 volumio go-librespot[1605]: time="2025-09-15T23:10:02+02:00" level=trace msg="sent dealer ping" Sep 15 23:10:02 volumio go-librespot[1605]: time="2025-09-15T23:10:02+02:00" level=trace msg="received dealer pong" Sep 15 23:10:06 volumio systemd[1]: systemd-timedated.service: Deactivated successfully. Sep 15 23:10:10 volumio volumio[1072]: info: CoreCommandRouter::volumioGetState Sep 15 23:10:18 volumio go-librespot[1605]: time="2025-09-15T23:10:18+02:00" level=trace msg="emitting websocket event: not_playing" Sep 15 23:10:18 volumio go-librespot[1605]: time="2025-09-15T23:10:18+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:2oxFYjDFaJ1ph1vO04EsZw" Sep 15 23:10:18 volumio volumio[1072]: SPOTIFY: received: {"type":"not_playing","data":{"uri":"spotify:track:7dZ4UpEKMGIultDdt0jRzS","play_origin":"playlist"}} Sep 15 23:10:18 volumio volumio[1072]: error: Failed to decode event: not_playing Sep 15 23:10:18 volumio go-librespot[1605]: time="2025-09-15T23:10:18+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 15 23:10:18 volumio go-librespot[1605]: time="2025-09-15T23:10:18+02:00" level=trace msg="emitting websocket event: will_play" Sep 15 23:10:18 volumio volumio[1072]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:2oxFYjDFaJ1ph1vO04EsZw","play_origin":"playlist"}} Sep 15 23:10:18 volumio go-librespot[1605]: time="2025-09-15T23:10:18+02:00" level=info msg="loaded track \"Cleaned Out\" (paused: false, position: 0ms, duration: 187387ms, prefetched: true)" uri="spotify:track:2oxFYjDFaJ1ph1vO04EsZw" Sep 15 23:10:18 volumio go-librespot[1605]: time="2025-09-15T23:10:18+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 15 23:10:18 volumio go-librespot[1605]: time="2025-09-15T23:10:18+02:00" level=trace msg="scheduling prefetch in 157s" Sep 15 23:10:18 volumio go-librespot[1605]: time="2025-09-15T23:10:18+02:00" level=trace msg="emitting websocket event: metadata" Sep 15 23:10:18 volumio volumio[1072]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:2oxFYjDFaJ1ph1vO04EsZw","name":"Cleaned Out","artist_names":["The Tibbs"],"album_name":"Cleaned Out","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02bdac4d591e13abc9a4da9a37","position":0,"duration":187387,"release_date":"year:2014 month:6 day:23","track_number":1,"disc_number":1}} Sep 15 23:10:19 volumio go-librespot[1605]: time="2025-09-15T23:10:19+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 15 23:10:19 volumio go-librespot[1605]: time="2025-09-15T23:10:19+02:00" level=trace msg="emitting websocket event: playing" Sep 15 23:10:19 volumio volumio[1072]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:2oxFYjDFaJ1ph1vO04EsZw","resume":false,"play_origin":"playlist"}} Sep 15 23:10:19 volumio volumio[1072]: SPOTIFY: PUSH STATE SPOTIFY Sep 15 23:10:19 volumio volumio[1072]: SPOTIFY: {"status":"play","service":"spop","title":"Cleaned Out","artist":"The Tibbs","album":"Cleaned Out","albumart":"https://i.scdn.co/image/ab67616d00001e02bdac4d591e13abc9a4da9a37","uri":"spotify:track:2oxFYjDFaJ1ph1vO04EsZw","trackType":"spotify","seek":0,"duration":187,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Sep 15 23:10:19 volumio volumio[1072]: info: CoreCommandRouter::servicePushState Sep 15 23:10:19 volumio volumio[1072]: info: CoreStateMachine::pushState Sep 15 23:10:19 volumio volumio[1072]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 15 23:10:19 volumio volumio[1072]: info: CoreCommandRouter::volumioPushState Sep 15 23:10:19 volumio volumio[1072]: SPOTIFY: RECEIVED VOLUMIO VOLUME 35 Sep 15 23:10:19 volumio volumio[1072]: info: [LastFM] Current track has sufficient metadata: title (Cleaned Out) and artist (The Tibbs) passed on explicitly Sep 15 23:10:19 volumio volumio[1072]: SPOTIFY: PUSH STATE SPOTIFY Sep 15 23:10:19 volumio volumio[1072]: SPOTIFY: {"status":"play","service":"spop","title":"Cleaned Out","artist":"The Tibbs","album":"Cleaned Out","albumart":"https://i.scdn.co/image/ab67616d00001e02bdac4d591e13abc9a4da9a37","uri":"spotify:track:2oxFYjDFaJ1ph1vO04EsZw","trackType":"spotify","seek":0,"duration":187,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Sep 15 23:10:19 volumio volumio[1072]: info: CoreCommandRouter::servicePushState Sep 15 23:10:19 volumio volumio[1072]: info: CoreStateMachine::pushState Sep 15 23:10:19 volumio volumio[1072]: info: CoreCommandRouter::volumioPushState Sep 15 23:10:19 volumio volumio[1072]: SPOTIFY: RECEIVED VOLUMIO VOLUME 35 Sep 15 23:10:20 volumio volumio[1072]: info: CoreCommandRouter::volumioGetState Sep 15 23:10:20 volumio volumio[1072]: info: Listing playlists Sep 15 23:10:20 volumio volumio[1072]: info: Listing playlists Sep 15 23:10:28 volumio volumio[1072]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 15 23:10:28 volumio volumio[1072]: TypeError: Cannot read properties of undefined (reading '@') Sep 15 23:10:28 volumio volumio[1072]: at Object.callback (/data/plugins/user_interface/lastfm/node_modules/simple-lastfm/lib/index.js:342:14) Sep 15 23:10:28 volumio volumio[1072]: at /data/plugins/user_interface/lastfm/node_modules/simple-lastfm/lib/index.js:60:13 Sep 15 23:10:28 volumio volumio[1072]: at Parser. (/data/plugins/user_interface/lastfm/node_modules/xml2js/lib/parser.js:322:18) Sep 15 23:10:28 volumio volumio[1072]: at Parser.emit (node:events:514:28) Sep 15 23:10:28 volumio volumio[1072]: at SAXParser.onerror (/data/plugins/user_interface/lastfm/node_modules/xml2js/lib/parser.js:133:26) Sep 15 23:10:28 volumio volumio[1072]: at emit (/data/plugins/user_interface/lastfm/node_modules/sax/lib/sax.js:631:35) Sep 15 23:10:28 volumio volumio[1072]: at error (/data/plugins/user_interface/lastfm/node_modules/sax/lib/sax.js:660:5) Sep 15 23:10:28 volumio volumio[1072]: at strictFail (/data/plugins/user_interface/lastfm/node_modules/sax/lib/sax.js:684:7) Sep 15 23:10:28 volumio volumio[1072]: at closeTag (/data/plugins/user_interface/lastfm/node_modules/sax/lib/sax.js:878:9) Sep 15 23:10:28 volumio volumio[1072]: at SAXParser.write (/data/plugins/user_interface/lastfm/node_modules/sax/lib/sax.js:1460:13) Sep 15 23:10:28 volumio volumio[1072]: at exports.Parser.Parser.parseString (/data/plugins/user_interface/lastfm/node_modules/xml2js/lib/parser.js:337:31) Sep 15 23:10:28 volumio volumio[1072]: at Parser.parseString (/data/plugins/user_interface/lastfm/node_modules/xml2js/lib/parser.js:5:59) Sep 15 23:10:28 volumio volumio[1072]: at IncomingMessage. (/data/plugins/user_interface/lastfm/node_modules/simple-lastfm/lib/index.js:58:14) Sep 15 23:10:28 volumio volumio[1072]: at IncomingMessage.emit (node:events:526:35) Sep 15 23:10:28 volumio volumio[1072]: at endReadableNT (node:internal/streams/readable:1376:12) Sep 15 23:10:28 volumio volumio[1072]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) Sep 15 23:10:28 volumio volumio[1072]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 15 23:10:28 volumio sudo[2229]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-09-15 23:09' Sep 15 23:10:28 volumio sudo[2229]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm 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="477d19cd2b4ebf4b4c802be78e00bbb657e83aea" 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 Aug 2 17:34:53 UTC 2025" VOLUMIO_VERSION="4.021" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="6199706cbb86ad1289fc7190b8a00601"