-- Logs begin at Sat 2026-09-26 21:43:57 CEST, end at Fri 2026-10-02 13:15:49 CEST. -- Oct 02 13:14:03 hifibarry go-librespot[19762]: time="2026-10-02T13:14:03+02:00" level=debug msg="fetched chunk 19/24, size: 524288" uri="spotify:track:1Z5Uc9jMuuVQxtRZTforfX" Oct 02 13:14:11 hifibarry go-librespot[19762]: time="2026-10-02T13:14:11+02:00" level=trace msg="sent dealer ping" Oct 02 13:14:11 hifibarry go-librespot[19762]: time="2026-10-02T13:14:11+02:00" level=trace msg="received dealer pong" Oct 02 13:14:15 hifibarry go-librespot[19762]: time="2026-10-02T13:14:15+02:00" level=debug msg="fetched chunk 20/24, size: 524288" uri="spotify:track:1Z5Uc9jMuuVQxtRZTforfX" Oct 02 13:14:27 hifibarry go-librespot[19762]: time="2026-10-02T13:14:27+02:00" level=debug msg="fetched chunk 21/24, size: 524288" uri="spotify:track:1Z5Uc9jMuuVQxtRZTforfX" Oct 02 13:14:39 hifibarry go-librespot[19762]: time="2026-10-02T13:14:39+02:00" level=debug msg="fetched chunk 22/24, size: 524288" uri="spotify:track:1Z5Uc9jMuuVQxtRZTforfX" Oct 02 13:14:41 hifibarry go-librespot[19762]: time="2026-10-02T13:14:41+02:00" level=trace msg="sent dealer ping" Oct 02 13:14:41 hifibarry go-librespot[19762]: time="2026-10-02T13:14:41+02:00" level=trace msg="received dealer pong" Oct 02 13:14:42 hifibarry go-librespot[19762]: time="2026-10-02T13:14:42+02:00" level=trace msg="received accesspoint ping" Oct 02 13:14:42 hifibarry go-librespot[19762]: time="2026-10-02T13:14:42+02:00" level=trace msg="received accesspoint pong ack" Oct 02 13:14:51 hifibarry go-librespot[19762]: time="2026-10-02T13:14:51+02:00" level=debug msg="fetched chunk 23/24, size: 524288" uri="spotify:track:1Z5Uc9jMuuVQxtRZTforfX" Oct 02 13:15:03 hifibarry go-librespot[19762]: time="2026-10-02T13:15:03+02:00" level=debug msg="fetched chunk 24/24, size: 394612" uri="spotify:track:1Z5Uc9jMuuVQxtRZTforfX" Oct 02 13:15:11 hifibarry go-librespot[19762]: time="2026-10-02T13:15:11+02:00" level=trace msg="sent dealer ping" Oct 02 13:15:11 hifibarry go-librespot[19762]: time="2026-10-02T13:15:11+02:00" level=trace msg="received dealer pong" Oct 02 13:15:16 hifibarry go-librespot[19762]: time="2026-10-02T13:15:16+02:00" level=debug msg="prefetching next track" uri="spotify:track:3ujwIruj897uySuJuwoPQN" Oct 02 13:15:16 hifibarry go-librespot[19762]: time="2026-10-02T13:15:16+02:00" level=debug msg="selected format OGG_VORBIS_320 (23e22d146b1370fca71bfc830f5de5854c4191e1)" uri="spotify:track:3ujwIruj897uySuJuwoPQN" Oct 02 13:15:16 hifibarry go-librespot[19762]: time="2026-10-02T13:15:16+02:00" level=debug msg="requested aes key for file 23e22d146b1370fca71bfc830f5de5854c4191e1, gid: 3ujwIruj897uySuJuwoPQN" Oct 02 13:15:16 hifibarry go-librespot[19762]: time="2026-10-02T13:15:16+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:3ujwIruj897uySuJuwoPQN" Oct 02 13:15:16 hifibarry go-librespot[19762]: time="2026-10-02T13:15:16+02:00" level=debug msg="fetched first chunk of 23, total size is 11946432 bytes" uri="spotify:track:3ujwIruj897uySuJuwoPQN" Oct 02 13:15:16 hifibarry go-librespot[19762]: time="2026-10-02T13:15:16+02:00" level=info msg="prefetched track \"Force Of Nature\" (duration: 291693ms)" uri="spotify:track:3ujwIruj897uySuJuwoPQN" Oct 02 13:15:16 hifibarry go-librespot[19762]: time="2026-10-02T13:15:16+02:00" level=debug msg="fetched chunk 2/22, size: 524288" uri="spotify:track:3ujwIruj897uySuJuwoPQN" Oct 02 13:15:16 hifibarry go-librespot[19762]: time="2026-10-02T13:15:16+02:00" level=debug msg="fetched chunk 3/22, size: 524288" uri="spotify:track:3ujwIruj897uySuJuwoPQN" Oct 02 13:15:16 hifibarry go-librespot[19762]: time="2026-10-02T13:15:16+02:00" level=debug msg="fetched chunk 1/22, size: 524288" uri="spotify:track:3ujwIruj897uySuJuwoPQN" Oct 02 13:15:41 hifibarry go-librespot[19762]: time="2026-10-02T13:15:41+02:00" level=trace msg="sent dealer ping" Oct 02 13:15:41 hifibarry go-librespot[19762]: time="2026-10-02T13:15:41+02:00" level=trace msg="received dealer pong" Oct 02 13:15:45 hifibarry go-librespot[19762]: time="2026-10-02T13:15:45+02:00" level=trace msg="emitting websocket event: not_playing" Oct 02 13:15:45 hifibarry go-librespot[19762]: time="2026-10-02T13:15:45+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:3ujwIruj897uySuJuwoPQN" Oct 02 13:15:45 hifibarry volumio[19572]: SPOTIFY: received: {"type":"not_playing","data":{"context_uri":"spotify:playlist:37i9dQZF1DXbP9O5gwI0xP","uri":"spotify:track:1Z5Uc9jMuuVQxtRZTforfX","play_origin":"playlist/ondemand"}} Oct 02 13:15:45 hifibarry volumio[19572]: error: Failed to decode event: not_playing Oct 02 13:15:45 hifibarry go-librespot[19762]: time="2026-10-02T13:15:45+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 02 13:15:45 hifibarry go-librespot[19762]: time="2026-10-02T13:15:45+02:00" level=trace msg="emitting websocket event: will_play" Oct 02 13:15:45 hifibarry go-librespot[19762]: time="2026-10-02T13:15:45+02:00" level=info msg="loaded track \"Force Of Nature\" (paused: false, position: 0ms, duration: 291693ms, prefetched: true)" uri="spotify:track:3ujwIruj897uySuJuwoPQN" Oct 02 13:15:45 hifibarry volumio[19572]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:playlist:37i9dQZF1DXbP9O5gwI0xP","uri":"spotify:track:3ujwIruj897uySuJuwoPQN","play_origin":"playlist/ondemand"}} Oct 02 13:15:45 hifibarry go-librespot[19762]: time="2026-10-02T13:15:45+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 02 13:15:45 hifibarry go-librespot[19762]: time="2026-10-02T13:15:45+02:00" level=trace msg="scheduling prefetch in 262s" Oct 02 13:15:45 hifibarry go-librespot[19762]: time="2026-10-02T13:15:45+02:00" level=trace msg="emitting websocket event: metadata" Oct 02 13:15:45 hifibarry volumio[19572]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:3ujwIruj897uySuJuwoPQN","name":"Force Of Nature","artist_names":["Oasis"],"album_name":"Heathen Chemistry","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02bd14866d69108524bc32fb37","position":0,"duration":291693,"release_date":"year:2002 month:7 day:1","track_number":2,"disc_number":1}} Oct 02 13:15:45 hifibarry go-librespot[19762]: time="2026-10-02T13:15:45+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 02 13:15:45 hifibarry go-librespot[19762]: time="2026-10-02T13:15:45+02:00" level=trace msg="emitting websocket event: playing" Oct 02 13:15:45 hifibarry volumio[19572]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:playlist:37i9dQZF1DXbP9O5gwI0xP","uri":"spotify:track:3ujwIruj897uySuJuwoPQN","resume":false,"play_origin":"playlist/ondemand"}} Oct 02 13:15:45 hifibarry volumio[19572]: SPOTIFY: PUSH STATE SPOTIFY Oct 02 13:15:45 hifibarry volumio[19572]: SPOTIFY: {"status":"play","service":"spop","title":"Force Of Nature","artist":"Oasis","album":"Heathen Chemistry","albumart":"https://i.scdn.co/image/ab67616d00001e02bd14866d69108524bc32fb37","uri":"spotify:track:3ujwIruj897uySuJuwoPQN","trackType":"spotify","seek":0,"duration":291,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":true,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Oct 02 13:15:45 hifibarry volumio[19572]: info: CoreCommandRouter::servicePushState Oct 02 13:15:45 hifibarry volumio[19572]: info: CoreStateMachine::pushState Oct 02 13:15:45 hifibarry volumio[19572]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 02 13:15:45 hifibarry volumio[19572]: info: CoreCommandRouter::volumioPushState Oct 02 13:15:45 hifibarry volumio[19572]: info: [LastFM] Current track has sufficient metadata: title (Force Of Nature) and artist (Oasis) passed on explicitly Oct 02 13:15:45 hifibarry volumio[19572]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Oct 02 13:15:46 hifibarry volumio[19572]: SPOTIFY: PUSH STATE SPOTIFY Oct 02 13:15:46 hifibarry volumio[19572]: SPOTIFY: {"status":"play","service":"spop","title":"Force Of Nature","artist":"Oasis","album":"Heathen Chemistry","albumart":"https://i.scdn.co/image/ab67616d00001e02bd14866d69108524bc32fb37","uri":"spotify:track:3ujwIruj897uySuJuwoPQN","trackType":"spotify","seek":1000,"duration":291,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":true,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Oct 02 13:15:46 hifibarry volumio[19572]: info: CoreCommandRouter::servicePushState Oct 02 13:15:46 hifibarry volumio[19572]: info: CoreStateMachine::pushState Oct 02 13:15:46 hifibarry volumio[19572]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 02 13:15:46 hifibarry volumio[19572]: info: CoreCommandRouter::volumioPushState Oct 02 13:15:46 hifibarry volumio[19572]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Oct 02 13:15:49 hifibarry volumio[19572]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 02 13:15:49 hifibarry volumio[19572]: TypeError: Cannot read property '@' of null Oct 02 13:15:49 hifibarry volumio[19572]: at Object.callback (/data/plugins/user_interface/lastfm/node_modules/simple-lastfm/lib/index.js:342:14) Oct 02 13:15:49 hifibarry volumio[19572]: at /data/plugins/user_interface/lastfm/node_modules/simple-lastfm/lib/index.js:60:13 Oct 02 13:15:49 hifibarry volumio[19572]: at Parser. (/data/plugins/user_interface/lastfm/node_modules/xml2js/lib/parser.js:304:18) Oct 02 13:15:49 hifibarry volumio[19572]: at Parser.emit (events.js:315:20) Oct 02 13:15:49 hifibarry volumio[19572]: at Parser.exports.Parser.Parser.parseString (/data/plugins/user_interface/lastfm/node_modules/xml2js/lib/parser.js:314:16) Oct 02 13:15:49 hifibarry volumio[19572]: at Parser.parseString (/data/plugins/user_interface/lastfm/node_modules/xml2js/lib/parser.js:5:59) Oct 02 13:15:49 hifibarry volumio[19572]: at IncomingMessage. (/data/plugins/user_interface/lastfm/node_modules/simple-lastfm/lib/index.js:58:14) Oct 02 13:15:49 hifibarry volumio[19572]: at IncomingMessage.emit (events.js:327:22) Oct 02 13:15:49 hifibarry volumio[19572]: at endReadableNT (internal/streams/readable.js:1327:12) Oct 02 13:15:49 hifibarry volumio[19572]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Oct 02 13:15:49 hifibarry volumio[19572]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 02 13:15:49 hifibarry sudo[30907]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2026-10-02 13:14 Oct 02 13:15:49 hifibarry sudo[30907]: 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="cc50ad4a2058d01de272214eb33827883bd2b7d8" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="502750e5d54ecf269d25125b622bfabc030fb553" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Wed 12 Nov 2025 06:58:02 PM CET" VOLUMIO_VERSION="3.874" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="4ae6504ed6f22e44c01a6e93b16badbd"