Dec 28 12:49:04 volumio go-librespot[1802]: time="2025-12-28T12:49:04-08:00" level=debug msg="fetched chunk 8/9, size: 524288" uri="spotify:track:0qsBDkTancugPHNto7EVD7" Dec 28 12:49:12 volumio go-librespot[1802]: time="2025-12-28T12:49:12-08:00" level=trace msg="sent dealer ping" Dec 28 12:49:12 volumio go-librespot[1802]: time="2025-12-28T12:49:12-08:00" level=trace msg="received dealer pong" Dec 28 12:49:17 volumio go-librespot[1802]: time="2025-12-28T12:49:17-08:00" level=debug msg="fetched chunk 9/9, size: 469203" uri="spotify:track:0qsBDkTancugPHNto7EVD7" Dec 28 12:49:22 volumio volumio[1177]: Searching plugin music_service/spop Dec 28 12:49:22 volumio volumio[1177]: info: CoreCommandRouter::executeOnPlugin: spop , search Dec 28 12:49:23 volumio volumio[1177]: info: All search sources collected, pushing search results Dec 28 12:49:25 volumio volumio[1177]: Searching plugin music_service/spop Dec 28 12:49:25 volumio volumio[1177]: info: CoreCommandRouter::executeOnPlugin: spop , search Dec 28 12:49:26 volumio volumio[1177]: info: All search sources collected, pushing search results Dec 28 12:49:26 volumio volumio[1177]: Searching plugin music_service/spop Dec 28 12:49:26 volumio volumio[1177]: info: CoreCommandRouter::executeOnPlugin: spop , search Dec 28 12:49:27 volumio volumio[1177]: info: All search sources collected, pushing search results Dec 28 12:49:27 volumio volumio[1177]: Searching plugin music_service/spop Dec 28 12:49:27 volumio volumio[1177]: info: CoreCommandRouter::executeOnPlugin: spop , search Dec 28 12:49:28 volumio volumio[1177]: info: All search sources collected, pushing search results Dec 28 12:49:29 volumio volumio[1177]: Searching plugin music_service/spop Dec 28 12:49:29 volumio volumio[1177]: info: CoreCommandRouter::executeOnPlugin: spop , search Dec 28 12:49:30 volumio volumio[1177]: info: All search sources collected, pushing search results Dec 28 12:49:35 volumio volumio[1177]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Dec 28 12:49:35 volumio volumio[1177]: info: In handleBrowseUri, curUri=spotify:artist:7JEdNVgHaznUZTAHVXm9MK Dec 28 12:49:36 volumio volumio[1177]: info: Preload queue cleared Dec 28 12:49:36 volumio volumio[1177]: info: Preloading song: spotify:track:2FNVelIwYB7yOdZSMgUmpT Dec 28 12:49:36 volumio volumio[1177]: info: Preloading song: spotify:track:2sEgzfMZNvnI1FYqZDcQ2E Dec 28 12:49:36 volumio volumio[1177]: info: Preloading song: spotify:track:2xoqWqtsjDojUd4X4eRn6g Dec 28 12:49:36 volumio volumio[1177]: info: Preloading song: spotify:track:6Y5q3Dzx32lHUwBnhWPkKT Dec 28 12:49:36 volumio volumio[1177]: info: Preloading song: spotify:track:6VrtaXyEKVEx9uC0c3yrDU Dec 28 12:49:36 volumio volumio[1177]: info: Preloading song: spotify:track:4pmR31A0OUWZOn6K7ELzW0 Dec 28 12:49:36 volumio volumio[1177]: info: Preloading song: spotify:track:241fnIafRw22s7kKWNe3Zk Dec 28 12:49:36 volumio volumio[1177]: info: Preloading song: spotify:track:7sRq4qVZs81CshBaDn5YMo Dec 28 12:49:36 volumio volumio[1177]: info: Preloading song: spotify:track:3cC0OtAzAYtR3u8rWvfEN8 Dec 28 12:49:36 volumio volumio[1177]: info: Preloading song: spotify:track:0xO6WDT1HRK0KcbbQDGqVK Dec 28 12:49:36 volumio volumio[1177]: info: Preload queue cleared Dec 28 12:49:36 volumio volumio[1177]: info: Preload queue cleared Dec 28 12:49:36 volumio volumio[1177]: info: No valid Plugin REST Endpoint Dec 28 12:49:36 volumio volumio[1177]: info: No valid Plugin REST Endpoint Dec 28 12:49:36 volumio volumio[1177]: info: No valid Plugin REST Endpoint Dec 28 12:49:36 volumio volumio[1177]: info: No valid Plugin REST Endpoint Dec 28 12:49:36 volumio volumio[1177]: info: No valid Plugin REST Endpoint Dec 28 12:49:36 volumio volumio[1177]: info: No valid Plugin REST Endpoint Dec 28 12:49:36 volumio volumio[1177]: info: No valid Plugin REST Endpoint Dec 28 12:49:36 volumio volumio[1177]: info: No valid Plugin REST Endpoint Dec 28 12:49:36 volumio volumio[1177]: info: No valid Plugin REST Endpoint Dec 28 12:49:36 volumio volumio[1177]: info: No valid Plugin REST Endpoint Dec 28 12:49:36 volumio volumio[1177]: info: No valid Plugin REST Endpoint Dec 28 12:49:42 volumio go-librespot[1802]: time="2025-12-28T12:49:42-08:00" level=trace msg="received accesspoint ping" Dec 28 12:49:42 volumio go-librespot[1802]: time="2025-12-28T12:49:42-08:00" level=trace msg="received accesspoint pong ack" Dec 28 12:49:42 volumio go-librespot[1802]: time="2025-12-28T12:49:42-08:00" level=trace msg="sent dealer ping" Dec 28 12:49:42 volumio go-librespot[1802]: time="2025-12-28T12:49:42-08:00" level=trace msg="received dealer pong" Dec 28 12:50:00 volumio volumio[1177]: info: CorePlayQueue::getTrack 9 Dec 28 12:50:00 volumio volumio[1177]: info: CorePlayQueue::getTrack 10 Dec 28 12:50:00 volumio volumio[1177]: info: Prefetching next song Dec 28 12:50:00 volumio volumio[1177]: info: [1766955000036] ControllerSpotify::prefetch Dec 28 12:50:00 volumio volumio[1177]: info: Sending Spotify command with payload to local API: /player/add_to_queue Dec 28 12:50:00 volumio go-librespot[1802]: time="2025-12-28T12:50:00-08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 28 12:50:00 volumio go-librespot[1802]: time="2025-12-28T12:50:00-08:00" level=debug msg="prefetching next track" uri="spotify:track:7LrNgICKUxDqXF1hmGcMB3" Dec 28 12:50:00 volumio go-librespot[1802]: time="2025-12-28T12:50:00-08:00" level=debug msg="selected format OGG_VORBIS_320 (817a76d5069eeeb894d607e3ac16c451bd727ef8)" uri="spotify:track:7LrNgICKUxDqXF1hmGcMB3" Dec 28 12:50:00 volumio go-librespot[1802]: time="2025-12-28T12:50:00-08:00" level=debug msg="requested aes key for file 817a76d5069eeeb894d607e3ac16c451bd727ef8, gid: 7LrNgICKUxDqXF1hmGcMB3" Dec 28 12:50:00 volumio go-librespot[1802]: time="2025-12-28T12:50:00-08:00" level=trace msg="found 2 cdn urls" uri="spotify:track:7LrNgICKUxDqXF1hmGcMB3" Dec 28 12:50:00 volumio go-librespot[1802]: time="2025-12-28T12:50:00-08:00" level=debug msg="fetched first chunk of 12, total size is 6136064 bytes" uri="spotify:track:7LrNgICKUxDqXF1hmGcMB3" Dec 28 12:50:00 volumio go-librespot[1802]: time="2025-12-28T12:50:00-08:00" level=info msg="prefetched track \"Save My Soul\" (duration: 165853ms)" uri="spotify:track:7LrNgICKUxDqXF1hmGcMB3" Dec 28 12:50:00 volumio go-librespot[1802]: time="2025-12-28T12:50:00-08:00" level=debug msg="fetched chunk 3/11, size: 524288" uri="spotify:track:7LrNgICKUxDqXF1hmGcMB3" Dec 28 12:50:00 volumio go-librespot[1802]: time="2025-12-28T12:50:00-08:00" level=debug msg="fetched chunk 1/11, size: 524288" uri="spotify:track:7LrNgICKUxDqXF1hmGcMB3" Dec 28 12:50:00 volumio go-librespot[1802]: time="2025-12-28T12:50:00-08:00" level=debug msg="fetched chunk 2/11, size: 524288" uri="spotify:track:7LrNgICKUxDqXF1hmGcMB3" Dec 28 12:50:04 volumio go-librespot[1802]: time="2025-12-28T12:50:04-08:00" level=trace msg="emitting websocket event: not_playing" Dec 28 12:50:04 volumio go-librespot[1802]: time="2025-12-28T12:50:04-08:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:7LrNgICKUxDqXF1hmGcMB3" Dec 28 12:50:04 volumio volumio[1177]: SPOTIFY: received: {"type":"not_playing","data":{"context_uri":"spotify:track:0qsBDkTancugPHNto7EVD7","uri":"spotify:track:0qsBDkTancugPHNto7EVD7","play_origin":"go-librespot"}} Dec 28 12:50:04 volumio volumio[1177]: error: Failed to decode event: not_playing Dec 28 12:50:04 volumio go-librespot[1802]: time="2025-12-28T12:50:04-08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 28 12:50:04 volumio go-librespot[1802]: time="2025-12-28T12:50:04-08:00" level=trace msg="emitting websocket event: will_play" Dec 28 12:50:04 volumio go-librespot[1802]: time="2025-12-28T12:50:04-08:00" level=info msg="loaded track \"Save My Soul\" (paused: false, position: 0ms, duration: 165853ms, prefetched: true)" uri="spotify:track:7LrNgICKUxDqXF1hmGcMB3" Dec 28 12:50:04 volumio volumio[1177]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:0qsBDkTancugPHNto7EVD7","uri":"spotify:track:7LrNgICKUxDqXF1hmGcMB3","play_origin":"go-librespot"}} Dec 28 12:50:04 volumio go-librespot[1802]: time="2025-12-28T12:50:04-08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 28 12:50:04 volumio go-librespot[1802]: time="2025-12-28T12:50:04-08:00" level=trace msg="scheduling prefetch in 135s" Dec 28 12:50:04 volumio go-librespot[1802]: time="2025-12-28T12:50:04-08:00" level=trace msg="emitting websocket event: metadata" Dec 28 12:50:04 volumio volumio[1177]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:7LrNgICKUxDqXF1hmGcMB3","name":"Save My Soul","artist_names":["Stephen Dowd"],"album_name":"Save My Soul","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02aacfe328094fe0618f7d2fee","position":0,"duration":165853,"release_date":"year:2025 month:9 day:26","track_number":1,"disc_number":1}} Dec 28 12:50:04 volumio go-librespot[1802]: time="2025-12-28T12:50:04-08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 28 12:50:04 volumio go-librespot[1802]: time="2025-12-28T12:50:04-08:00" level=trace msg="emitting websocket event: playing" Dec 28 12:50:04 volumio volumio[1177]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:track:0qsBDkTancugPHNto7EVD7","uri":"spotify:track:7LrNgICKUxDqXF1hmGcMB3","resume":false,"play_origin":"go-librespot"}} Dec 28 12:50:04 volumio volumio[1177]: SPOTIFY: PUSH STATE SPOTIFY Dec 28 12:50:04 volumio volumio[1177]: SPOTIFY: {"status":"play","service":"spop","title":"Save My Soul","artist":"Stephen Dowd","album":"Save My Soul","albumart":"https://i.scdn.co/image/ab67616d00001e02aacfe328094fe0618f7d2fee","uri":"spotify:track:7LrNgICKUxDqXF1hmGcMB3","trackType":"spotify","seek":0,"duration":165,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 28 12:50:04 volumio volumio[1177]: info: CoreCommandRouter::servicePushState Dec 28 12:50:04 volumio volumio[1177]: info: CorePlayQueue::getTrack 9 Dec 28 12:50:04 volumio volumio[1177]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Save My Soul","artist":"Stephen Dowd","album":"Save My Soul","albumart":"https://i.scdn.co/image/ab67616d00001e02aacfe328094fe0618f7d2fee","uri":"spotify:track:7LrNgICKUxDqXF1hmGcMB3","trackType":"spotify","seek":0,"duration":165,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 28 12:50:04 volumio volumio[1177]: verbose: CURRENT POSITION 9 Dec 28 12:50:04 volumio volumio[1177]: info: CoreStateMachine::syncState stateService play Dec 28 12:50:04 volumio volumio[1177]: info: CoreStateMachine::syncState currentStatus play Dec 28 12:50:04 volumio volumio[1177]: info: Received an update from plugin. extracting info from payload Dec 28 12:50:04 volumio volumio[1177]: info: CoreStateMachine::pushState Dec 28 12:50:04 volumio volumio[1177]: info: CorePlayQueue::getTrack 9 Dec 28 12:50:04 volumio volumio[1177]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 28 12:50:04 volumio volumio[1177]: info: CoreCommandRouter::volumioPushState Dec 28 12:50:04 volumio volumio[1177]: info: CoreStateMachine::pushState Dec 28 12:50:04 volumio volumio[1177]: info: CorePlayQueue::getTrack 9 Dec 28 12:50:04 volumio volumio[1177]: info: CoreCommandRouter::volumioPushState Dec 28 12:50:04 volumio volumio[1177]: info: CoreStateMachine::startPlaybackTimer Dec 28 12:50:04 volumio volumio[1177]: info: CorePlayQueue::getTrack 10 Dec 28 12:50:04 volumio volumio[1177]: SPOTIFY: PUSH STATE SPOTIFY Dec 28 12:50:04 volumio volumio[1177]: SPOTIFY: {"status":"play","service":"spop","title":"Save My Soul","artist":"Stephen Dowd","album":"Save My Soul","albumart":"https://i.scdn.co/image/ab67616d00001e02aacfe328094fe0618f7d2fee","uri":"spotify:track:7LrNgICKUxDqXF1hmGcMB3","trackType":"spotify","seek":0,"duration":165,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 28 12:50:04 volumio volumio[1177]: info: CoreCommandRouter::servicePushState Dec 28 12:50:04 volumio volumio[1177]: info: CorePlayQueue::getTrack 10 Dec 28 12:50:04 volumio volumio[1177]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Save My Soul","artist":"Stephen Dowd","album":"Save My Soul","albumart":"https://i.scdn.co/image/ab67616d00001e02aacfe328094fe0618f7d2fee","uri":"spotify:track:7LrNgICKUxDqXF1hmGcMB3","trackType":"spotify","seek":0,"duration":165,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 28 12:50:04 volumio volumio[1177]: verbose: CURRENT POSITION 10 Dec 28 12:50:04 volumio volumio[1177]: info: CoreStateMachine::syncState stateService play Dec 28 12:50:04 volumio volumio[1177]: info: CoreStateMachine::syncState currentStatus play Dec 28 12:50:04 volumio volumio[1177]: info: Received an update from plugin. extracting info from payload Dec 28 12:50:04 volumio volumio[1177]: info: CoreStateMachine::pushState Dec 28 12:50:04 volumio volumio[1177]: info: CorePlayQueue::getTrack 10 Dec 28 12:50:04 volumio volumio[1177]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 28 12:50:04 volumio volumio[1177]: info: CoreCommandRouter::volumioPushState Dec 28 12:50:04 volumio volumio[1177]: info: CoreStateMachine::pushState Dec 28 12:50:04 volumio volumio[1177]: info: CorePlayQueue::getTrack 10 Dec 28 12:50:04 volumio volumio[1177]: info: CoreCommandRouter::volumioPushState Dec 28 12:50:04 volumio volumio[1177]: info: CoreStateMachine::pushState Dec 28 12:50:04 volumio volumio[1177]: info: CorePlayQueue::getTrack 10 Dec 28 12:50:04 volumio volumio[1177]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 28 12:50:04 volumio volumio[1177]: info: CoreCommandRouter::volumioPushState Dec 28 12:50:10 volumio volumio[1177]: Searching plugin music_service/spop Dec 28 12:50:10 volumio volumio[1177]: info: CoreCommandRouter::executeOnPlugin: spop , search Dec 28 12:50:10 volumio volumio[1177]: info: All search sources collected, pushing search results Dec 28 12:50:12 volumio go-librespot[1802]: time="2025-12-28T12:50:12-08:00" level=trace msg="sent dealer ping" Dec 28 12:50:12 volumio go-librespot[1802]: time="2025-12-28T12:50:12-08:00" level=trace msg="received dealer pong" Dec 28 12:50:18 volumio go-librespot[1802]: time="2025-12-28T12:50:18-08:00" level=debug msg="fetched chunk 4/11, size: 524288" uri="spotify:track:7LrNgICKUxDqXF1hmGcMB3" Dec 28 12:50:24 volumio volumio[1177]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Dec 28 12:50:24 volumio volumio[1177]: info: In handleBrowseUri, curUri=spotify:artist:5PQDpuTn9WS0JWNG0633kU Dec 28 12:50:25 volumio volumio[1177]: info: Preload queue cleared Dec 28 12:50:25 volumio volumio[1177]: info: Preloading song: spotify:track:3RXcJJDu8CkPBXYFoYGOBA Dec 28 12:50:25 volumio volumio[1177]: info: Preload queue cleared Dec 28 12:50:25 volumio volumio[1177]: info: Preload queue cleared Dec 28 12:50:25 volumio volumio[1177]: info: No valid Plugin REST Endpoint Dec 28 12:50:25 volumio volumio[1177]: info: No valid Plugin REST Endpoint Dec 28 12:50:25 volumio volumio[1177]: info: No valid Plugin REST Endpoint Dec 28 12:50:25 volumio volumio[1177]: info: No valid Plugin REST Endpoint Dec 28 12:50:25 volumio volumio[1177]: info: No valid Plugin REST Endpoint Dec 28 12:50:25 volumio volumio[1177]: info: No valid Plugin REST Endpoint Dec 28 12:50:25 volumio volumio[1177]: info: No valid Plugin REST Endpoint Dec 28 12:50:25 volumio volumio[1177]: info: No valid Plugin REST Endpoint Dec 28 12:50:25 volumio volumio[1177]: info: No valid Plugin REST Endpoint Dec 28 12:50:25 volumio volumio[1177]: info: No valid Plugin REST Endpoint Dec 28 12:50:25 volumio volumio[1177]: info: No valid Plugin REST Endpoint Dec 28 12:50:32 volumio go-librespot[1802]: time="2025-12-28T12:50:32-08:00" level=debug msg="fetched chunk 5/11, size: 524288" uri="spotify:track:7LrNgICKUxDqXF1hmGcMB3" Dec 28 12:50:41 volumio volumio[1177]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Dec 28 12:50:41 volumio volumio[1177]: info: In handleBrowseUri, curUri=spotify:artist:0JYHGziEgdaA7cueN3VvlQ Dec 28 12:50:41 volumio volumio[1177]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 28 12:50:41 volumio volumio[1177]: TypeError: Cannot read properties of undefined (reading 'url') Dec 28 12:50:41 volumio volumio[1177]: at /data/plugins/music_service/spop/index.js:2449:60 Dec 28 12:50:41 volumio volumio[1177]: at process.processTicksAndRejections (node:internal/process/task_queues:95:5) Dec 28 12:50:41 volumio volumio[1177]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 28 12:50:41 volumio sudo[9026]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-28 12:49' Dec 28 12:50:41 volumio sudo[9026]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Debian GNU/Linux 12 (bookworm)" NAME="Debian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="cfdc872d40b979cca36352a7333c940c38dc64b5" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="6cbc2303e10f00c3a01cb7f02c6d12448bd32c62" VOLUMIO_ARCH="x64" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri Dec 5 21:07:15 UTC 2025" VOLUMIO_VERSION="4.073" VOLUMIO_HARDWARE="x86_amd64" VOLUMIO_DEVICENAME="x86_64" VOLUMIO_HASH="4b5c74f40f473b90a542bf010b97924b"