Dec 19 16:39:06 volumio go-librespot[1548]: time="2025-12-19T16:39:06+01:00" level=trace msg="sent dealer ping" Dec 19 16:39:06 volumio go-librespot[1548]: time="2025-12-19T16:39:06+01:00" level=trace msg="received dealer pong" Dec 19 16:39:09 volumio go-librespot[1548]: time="2025-12-19T16:39:09+01:00" level=debug msg="fetched chunk 4/7, size: 524288" uri="spotify:track:1YO8nTZ9gJBgquHQKlcUUx" Dec 19 16:39:23 volumio go-librespot[1548]: time="2025-12-19T16:39:23+01:00" level=debug msg="fetched chunk 5/7, size: 524288" uri="spotify:track:1YO8nTZ9gJBgquHQKlcUUx" Dec 19 16:39:36 volumio go-librespot[1548]: time="2025-12-19T16:39:36+01:00" level=trace msg="sent dealer ping" Dec 19 16:39:36 volumio go-librespot[1548]: time="2025-12-19T16:39:36+01:00" level=trace msg="received dealer pong" Dec 19 16:39:37 volumio go-librespot[1548]: time="2025-12-19T16:39:37+01:00" level=debug msg="fetched chunk 6/7, size: 524288" uri="spotify:track:1YO8nTZ9gJBgquHQKlcUUx" Dec 19 16:39:50 volumio go-librespot[1548]: time="2025-12-19T16:39:50+01:00" level=debug msg="fetched chunk 7/7, size: 485058" uri="spotify:track:1YO8nTZ9gJBgquHQKlcUUx" Dec 19 16:39:52 volumio volumio[1167]: Searching plugin music_service/spop Dec 19 16:39:52 volumio volumio[1167]: info: CoreCommandRouter::executeOnPlugin: spop , search Dec 19 16:39:53 volumio volumio[1167]: info: All search sources collected, pushing search results Dec 19 16:39:54 volumio volumio[1167]: Searching plugin music_service/spop Dec 19 16:39:54 volumio volumio[1167]: info: CoreCommandRouter::executeOnPlugin: spop , search Dec 19 16:39:54 volumio volumio[1167]: info: All search sources collected, pushing search results Dec 19 16:39:56 volumio volumio[1167]: Searching plugin music_service/spop Dec 19 16:39:56 volumio volumio[1167]: info: CoreCommandRouter::executeOnPlugin: spop , search Dec 19 16:39:57 volumio volumio[1167]: info: All search sources collected, pushing search results Dec 19 16:39:57 volumio volumio[1167]: Searching plugin music_service/spop Dec 19 16:39:57 volumio volumio[1167]: info: CoreCommandRouter::executeOnPlugin: spop , search Dec 19 16:39:58 volumio volumio[1167]: info: All search sources collected, pushing search results Dec 19 16:39:58 volumio volumio[1167]: Searching plugin music_service/spop Dec 19 16:39:58 volumio volumio[1167]: info: CoreCommandRouter::executeOnPlugin: spop , search Dec 19 16:39:59 volumio volumio[1167]: info: All search sources collected, pushing search results Dec 19 16:40:02 volumio volumio[1167]: Searching plugin music_service/spop Dec 19 16:40:02 volumio volumio[1167]: info: CoreCommandRouter::executeOnPlugin: spop , search Dec 19 16:40:03 volumio volumio[1167]: info: All search sources collected, pushing search results Dec 19 16:40:06 volumio go-librespot[1548]: time="2025-12-19T16:40:06+01:00" level=trace msg="sent dealer ping" Dec 19 16:40:06 volumio go-librespot[1548]: time="2025-12-19T16:40:06+01:00" level=trace msg="received dealer pong" Dec 19 16:40:36 volumio go-librespot[1548]: time="2025-12-19T16:40:36+01:00" level=trace msg="sent dealer ping" Dec 19 16:40:36 volumio go-librespot[1548]: time="2025-12-19T16:40:36+01:00" level=trace msg="received dealer pong" Dec 19 16:40:37 volumio go-librespot[1548]: time="2025-12-19T16:40:37+01:00" level=trace msg="received accesspoint ping" Dec 19 16:40:37 volumio go-librespot[1548]: time="2025-12-19T16:40:37+01:00" level=trace msg="received accesspoint pong ack" Dec 19 16:40:39 volumio volumio[1167]: info: CorePlayQueue::getTrack 0 Dec 19 16:40:39 volumio volumio[1167]: info: CorePlayQueue::getTrack 1 Dec 19 16:40:39 volumio volumio[1167]: info: Prefetching next song Dec 19 16:40:39 volumio volumio[1167]: info: [1766158839512] ControllerSpotify::prefetch Dec 19 16:40:39 volumio volumio[1167]: info: Sending Spotify command with payload to local API: /player/add_to_queue Dec 19 16:40:39 volumio go-librespot[1548]: time="2025-12-19T16:40:39+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 19 16:40:39 volumio go-librespot[1548]: time="2025-12-19T16:40:39+01:00" level=debug msg="prefetching next track" uri="spotify:track:0C9zjzK1ZCHL5Cid66Izxr" Dec 19 16:40:39 volumio go-librespot[1548]: time="2025-12-19T16:40:39+01:00" level=debug msg="selected format OGG_VORBIS_320 (ada50be3c7570ece970698f8321683b2c5f45611)" uri="spotify:track:0C9zjzK1ZCHL5Cid66Izxr" Dec 19 16:40:39 volumio go-librespot[1548]: time="2025-12-19T16:40:39+01:00" level=debug msg="requested aes key for file ada50be3c7570ece970698f8321683b2c5f45611, gid: 0C9zjzK1ZCHL5Cid66Izxr" Dec 19 16:40:39 volumio go-librespot[1548]: time="2025-12-19T16:40:39+01:00" level=trace msg="found 2 cdn urls" uri="spotify:track:0C9zjzK1ZCHL5Cid66Izxr" Dec 19 16:40:39 volumio go-librespot[1548]: time="2025-12-19T16:40:39+01:00" level=debug msg="fetched first chunk of 23, total size is 11649073 bytes" uri="spotify:track:0C9zjzK1ZCHL5Cid66Izxr" Dec 19 16:40:39 volumio go-librespot[1548]: time="2025-12-19T16:40:39+01:00" level=info msg="prefetched track \"Holy Flaming Hammer of Unholy Cosmic Frost\" (duration: 275168ms)" uri="spotify:track:0C9zjzK1ZCHL5Cid66Izxr" Dec 19 16:40:40 volumio go-librespot[1548]: time="2025-12-19T16:40:40+01:00" level=debug msg="fetched chunk 1/22, size: 524288" uri="spotify:track:0C9zjzK1ZCHL5Cid66Izxr" Dec 19 16:40:40 volumio go-librespot[1548]: time="2025-12-19T16:40:40+01:00" level=debug msg="fetched chunk 3/22, size: 524288" uri="spotify:track:0C9zjzK1ZCHL5Cid66Izxr" Dec 19 16:40:40 volumio go-librespot[1548]: time="2025-12-19T16:40:40+01:00" level=debug msg="fetched chunk 2/22, size: 524288" uri="spotify:track:0C9zjzK1ZCHL5Cid66Izxr" Dec 19 16:40:43 volumio go-librespot[1548]: time="2025-12-19T16:40:43+01:00" level=trace msg="emitting websocket event: not_playing" Dec 19 16:40:43 volumio go-librespot[1548]: time="2025-12-19T16:40:43+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:0C9zjzK1ZCHL5Cid66Izxr" Dec 19 16:40:43 volumio volumio[1167]: SPOTIFY: received: {"type":"not_playing","data":{"context_uri":"spotify:track:1YO8nTZ9gJBgquHQKlcUUx","uri":"spotify:track:1YO8nTZ9gJBgquHQKlcUUx","play_origin":"go-librespot"}} Dec 19 16:40:43 volumio volumio[1167]: error: Failed to decode event: not_playing Dec 19 16:40:43 volumio go-librespot[1548]: time="2025-12-19T16:40:43+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 19 16:40:43 volumio go-librespot[1548]: time="2025-12-19T16:40:43+01:00" level=trace msg="emitting websocket event: will_play" Dec 19 16:40:43 volumio go-librespot[1548]: time="2025-12-19T16:40:43+01:00" level=info msg="loaded track \"Holy Flaming Hammer of Unholy Cosmic Frost\" (paused: false, position: 0ms, duration: 275168ms, prefetched: true)" uri="spotify:track:0C9zjzK1ZCHL5Cid66Izxr" Dec 19 16:40:43 volumio volumio[1167]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:1YO8nTZ9gJBgquHQKlcUUx","uri":"spotify:track:0C9zjzK1ZCHL5Cid66Izxr","play_origin":"go-librespot"}} Dec 19 16:40:43 volumio go-librespot[1548]: time="2025-12-19T16:40:43+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 19 16:40:43 volumio go-librespot[1548]: time="2025-12-19T16:40:43+01:00" level=trace msg="scheduling prefetch in 245s" Dec 19 16:40:43 volumio go-librespot[1548]: time="2025-12-19T16:40:43+01:00" level=trace msg="emitting websocket event: metadata" Dec 19 16:40:43 volumio volumio[1167]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:0C9zjzK1ZCHL5Cid66Izxr","name":"Holy Flaming Hammer of Unholy Cosmic Frost","artist_names":["Gloryhammer"],"album_name":"Return to the Kingdom of Fife","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0242ca5de38ac6144290fb41b3","position":0,"duration":275168,"release_date":"year:2023 month:6 day:2","track_number":2,"disc_number":1}} Dec 19 16:40:43 volumio go-librespot[1548]: time="2025-12-19T16:40:43+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 19 16:40:43 volumio go-librespot[1548]: time="2025-12-19T16:40:43+01:00" level=trace msg="emitting websocket event: playing" Dec 19 16:40:43 volumio volumio[1167]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:track:1YO8nTZ9gJBgquHQKlcUUx","uri":"spotify:track:0C9zjzK1ZCHL5Cid66Izxr","resume":false,"play_origin":"go-librespot"}} Dec 19 16:40:43 volumio volumio[1167]: SPOTIFY: PUSH STATE SPOTIFY Dec 19 16:40:43 volumio volumio[1167]: SPOTIFY: {"status":"play","service":"spop","title":"Holy Flaming Hammer of Unholy Cosmic Frost","artist":"Gloryhammer","album":"Return to the Kingdom of Fife","albumart":"https://i.scdn.co/image/ab67616d00001e0242ca5de38ac6144290fb41b3","uri":"spotify:track:0C9zjzK1ZCHL5Cid66Izxr","trackType":"spotify","seek":0,"duration":275,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 19 16:40:43 volumio volumio[1167]: info: CoreCommandRouter::servicePushState Dec 19 16:40:43 volumio volumio[1167]: info: CorePlayQueue::getTrack 0 Dec 19 16:40:43 volumio volumio[1167]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Holy Flaming Hammer of Unholy Cosmic Frost","artist":"Gloryhammer","album":"Return to the Kingdom of Fife","albumart":"https://i.scdn.co/image/ab67616d00001e0242ca5de38ac6144290fb41b3","uri":"spotify:track:0C9zjzK1ZCHL5Cid66Izxr","trackType":"spotify","seek":0,"duration":275,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 19 16:40:43 volumio volumio[1167]: verbose: CURRENT POSITION 0 Dec 19 16:40:43 volumio volumio[1167]: info: CoreStateMachine::syncState stateService play Dec 19 16:40:43 volumio volumio[1167]: info: CoreStateMachine::syncState currentStatus play Dec 19 16:40:43 volumio volumio[1167]: info: Received an update from plugin. extracting info from payload Dec 19 16:40:43 volumio volumio[1167]: info: CoreStateMachine::pushState Dec 19 16:40:43 volumio volumio[1167]: info: CorePlayQueue::getTrack 0 Dec 19 16:40:43 volumio volumio[1167]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 19 16:40:43 volumio volumio[1167]: info: CoreCommandRouter::volumioPushState Dec 19 16:40:43 volumio volumio[1167]: info: MRS: Pushing multiroomSync output update for this device Dec 19 16:40:43 volumio volumio[1167]: info: MRS: Pushing multiroomSync output Dec 19 16:40:43 volumio volumio[1167]: info: CoreCommandRouter::volumioGetState Dec 19 16:40:43 volumio volumio[1167]: info: CorePlayQueue::getTrack 0 Dec 19 16:40:43 volumio volumio[1167]: info: CoreStateMachine::pushState Dec 19 16:40:43 volumio volumio[1167]: info: CorePlayQueue::getTrack 0 Dec 19 16:40:43 volumio volumio[1167]: info: CoreCommandRouter::volumioPushState Dec 19 16:40:43 volumio volumio[1167]: info: MRS: Pushing multiroomSync output update for this device Dec 19 16:40:43 volumio volumio[1167]: info: MRS: Pushing multiroomSync output Dec 19 16:40:43 volumio volumio[1167]: info: CoreCommandRouter::volumioGetState Dec 19 16:40:43 volumio volumio[1167]: info: CorePlayQueue::getTrack 0 Dec 19 16:40:43 volumio volumio[1167]: info: FusionDsp - volume level for loudness 64 gain applied 3.33 Dec 19 16:40:43 volumio volumio[1167]: info: FusionDsp - If filter freq >samplerate/2 then disable it Dec 19 16:40:43 volumio volumio[1167]: info: FusionDsp - Loudness is ON true Dec 19 16:40:43 volumio volumio[1167]: info: FusionDsp - volume level for loudness 64 gain applied 3.33 Dec 19 16:40:43 volumio volumio[1167]: info: FusionDsp - If filter freq >samplerate/2 then disable it Dec 19 16:40:43 volumio volumio[1167]: info: FusionDsp - Loudness is ON true Dec 19 16:40:43 volumio volumio[1167]: SPOTIFY: RECEIVED VOLUMIO VOLUME 64 Dec 19 16:40:43 volumio volumio[1167]: SPOTIFY: RECEIVED VOLUMIO VOLUME 64 Dec 19 16:40:43 volumio volumio[1167]: SPOTIFY: PUSH STATE SPOTIFY Dec 19 16:40:43 volumio volumio[1167]: SPOTIFY: {"status":"play","service":"spop","title":"Holy Flaming Hammer of Unholy Cosmic Frost","artist":"Gloryhammer","album":"Return to the Kingdom of Fife","albumart":"https://i.scdn.co/image/ab67616d00001e0242ca5de38ac6144290fb41b3","uri":"spotify:track:0C9zjzK1ZCHL5Cid66Izxr","trackType":"spotify","seek":0,"duration":275,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 19 16:40:43 volumio volumio[1167]: info: CoreCommandRouter::servicePushState Dec 19 16:40:43 volumio volumio[1167]: info: CorePlayQueue::getTrack 0 Dec 19 16:40:43 volumio volumio[1167]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Holy Flaming Hammer of Unholy Cosmic Frost","artist":"Gloryhammer","album":"Return to the Kingdom of Fife","albumart":"https://i.scdn.co/image/ab67616d00001e0242ca5de38ac6144290fb41b3","uri":"spotify:track:0C9zjzK1ZCHL5Cid66Izxr","trackType":"spotify","seek":0,"duration":275,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 19 16:40:43 volumio volumio[1167]: verbose: CURRENT POSITION 0 Dec 19 16:40:43 volumio volumio[1167]: info: CoreStateMachine::syncState stateService play Dec 19 16:40:43 volumio volumio[1167]: info: CoreStateMachine::syncState currentStatus play Dec 19 16:40:43 volumio volumio[1167]: info: Received an update from plugin. extracting info from payload Dec 19 16:40:43 volumio volumio[1167]: info: CoreStateMachine::pushState Dec 19 16:40:43 volumio volumio[1167]: info: CorePlayQueue::getTrack 0 Dec 19 16:40:43 volumio volumio[1167]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 19 16:40:43 volumio volumio[1167]: info: CoreCommandRouter::volumioPushState Dec 19 16:40:43 volumio volumio[1167]: info: MRS: Pushing multiroomSync output update for this device Dec 19 16:40:43 volumio volumio[1167]: info: MRS: Pushing multiroomSync output Dec 19 16:40:43 volumio volumio[1167]: info: CoreCommandRouter::volumioGetState Dec 19 16:40:43 volumio volumio[1167]: info: CorePlayQueue::getTrack 0 Dec 19 16:40:43 volumio volumio[1167]: info: CoreStateMachine::pushState Dec 19 16:40:43 volumio volumio[1167]: info: CorePlayQueue::getTrack 0 Dec 19 16:40:43 volumio volumio[1167]: info: CoreCommandRouter::volumioPushState Dec 19 16:40:43 volumio volumio[1167]: info: MRS: Pushing multiroomSync output update for this device Dec 19 16:40:43 volumio volumio[1167]: info: MRS: Pushing multiroomSync output Dec 19 16:40:43 volumio volumio[1167]: info: CoreCommandRouter::volumioGetState Dec 19 16:40:43 volumio volumio[1167]: info: CorePlayQueue::getTrack 0 Dec 19 16:40:43 volumio volumio[1167]: info: FusionDsp - volume level for loudness 64 gain applied 3.33 Dec 19 16:40:43 volumio volumio[1167]: info: FusionDsp - If filter freq >samplerate/2 then disable it Dec 19 16:40:43 volumio volumio[1167]: info: FusionDsp - Loudness is ON true Dec 19 16:40:43 volumio volumio[1167]: info: FusionDsp - volume level for loudness 64 gain applied 3.33 Dec 19 16:40:43 volumio volumio[1167]: info: FusionDsp - If filter freq >samplerate/2 then disable it Dec 19 16:40:43 volumio volumio[1167]: info: FusionDsp - Loudness is ON true Dec 19 16:40:43 volumio volumio[1167]: SPOTIFY: RECEIVED VOLUMIO VOLUME 64 Dec 19 16:40:43 volumio volumio[1167]: SPOTIFY: RECEIVED VOLUMIO VOLUME 64 Dec 19 16:40:44 volumio volumio[1167]: info: CoreStateMachine::startPlaybackTimer Dec 19 16:40:44 volumio volumio[1167]: info: CorePlayQueue::getTrack 1 Dec 19 16:40:44 volumio volumio[1167]: info: CoreStateMachine::pushState Dec 19 16:40:44 volumio volumio[1167]: info: CorePlayQueue::getTrack 1 Dec 19 16:40:44 volumio volumio[1167]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 19 16:40:44 volumio volumio[1167]: info: CoreCommandRouter::volumioPushState Dec 19 16:40:44 volumio volumio[1167]: info: MRS: Pushing multiroomSync output update for this device Dec 19 16:40:44 volumio volumio[1167]: info: MRS: Pushing multiroomSync output Dec 19 16:40:44 volumio volumio[1167]: info: CoreCommandRouter::volumioGetState Dec 19 16:40:44 volumio volumio[1167]: info: CorePlayQueue::getTrack 1 Dec 19 16:40:44 volumio volumio[1167]: info: FusionDsp - volume level for loudness 64 gain applied 3.33 Dec 19 16:40:44 volumio volumio[1167]: info: FusionDsp - If filter freq >samplerate/2 then disable it Dec 19 16:40:44 volumio volumio[1167]: info: FusionDsp - Loudness is ON true Dec 19 16:40:44 volumio volumio[1167]: SPOTIFY: RECEIVED VOLUMIO VOLUME 64 Dec 19 16:40:45 volumio volumio[1167]: Searching plugin music_service/spop Dec 19 16:40:45 volumio volumio[1167]: info: CoreCommandRouter::executeOnPlugin: spop , search Dec 19 16:40:46 volumio volumio[1167]: info: All search sources collected, pushing search results Dec 19 16:40:48 volumio volumio[1167]: Searching plugin music_service/spop Dec 19 16:40:48 volumio volumio[1167]: info: CoreCommandRouter::executeOnPlugin: spop , search Dec 19 16:40:49 volumio volumio[1167]: info: All search sources collected, pushing search results Dec 19 16:40:54 volumio volumio[1167]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Dec 19 16:40:54 volumio volumio[1167]: info: In handleBrowseUri, curUri=spotify:artist:0kk9oYDv7gCoR4LtEP2AEm Dec 19 16:40:54 volumio volumio[1167]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 19 16:40:54 volumio volumio[1167]: TypeError: Cannot read properties of undefined (reading 'url') Dec 19 16:40:54 volumio volumio[1167]: at /data/plugins/music_service/spop/index.js:2449:60 Dec 19 16:40:54 volumio volumio[1167]: at process.processTicksAndRejections (node:internal/process/task_queues:95:5) Dec 19 16:40:54 volumio volumio[1167]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 19 16:40:54 volumio go-librespot[1548]: time="2025-12-19T16:40:54+01:00" level=debug msg="fetched chunk 4/22, size: 524288" uri="spotify:track:0C9zjzK1ZCHL5Cid66Izxr" Dec 19 16:40:55 volumio sudo[11182]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-19 16:39' Dec 19 16:40:55 volumio sudo[11182]: 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="cfdc872d40b979cca36352a7333c940c38dc64b5" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="6cbc2303e10f00c3a01cb7f02c6d12448bd32c62" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri Dec 5 20:42:14 UTC 2025" VOLUMIO_VERSION="4.073" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="67fdc5f60f00b7a328ccd8c4ad441086"