Feb 12 18:44:03 living-room volumio[1227]: Searching plugin music_service/spop Feb 12 18:44:03 living-room volumio[1227]: info: CoreCommandRouter::executeOnPlugin: spop , search Feb 12 18:44:04 living-room volumio[1227]: info: All search sources collected, pushing search results Feb 12 18:44:10 living-room volumio[1227]: Searching plugin music_service/spop Feb 12 18:44:10 living-room volumio[1227]: info: CoreCommandRouter::executeOnPlugin: spop , search Feb 12 18:44:11 living-room volumio[1227]: info: All search sources collected, pushing search results Feb 12 18:44:11 living-room volumio[1227]: Searching plugin music_service/spop Feb 12 18:44:11 living-room volumio[1227]: info: CoreCommandRouter::executeOnPlugin: spop , search Feb 12 18:44:12 living-room volumio[1227]: info: All search sources collected, pushing search results Feb 12 18:44:14 living-room volumio[1227]: Searching plugin music_service/spop Feb 12 18:44:14 living-room volumio[1227]: info: CoreCommandRouter::executeOnPlugin: spop , search Feb 12 18:44:15 living-room volumio[1227]: info: All search sources collected, pushing search results Feb 12 18:44:16 living-room volumio[1227]: Searching plugin music_service/spop Feb 12 18:44:16 living-room volumio[1227]: info: CoreCommandRouter::executeOnPlugin: spop , search Feb 12 18:44:17 living-room volumio[1227]: info: All search sources collected, pushing search results Feb 12 18:44:18 living-room volumio[1227]: Searching plugin music_service/spop Feb 12 18:44:18 living-room volumio[1227]: info: CoreCommandRouter::executeOnPlugin: spop , search Feb 12 18:44:18 living-room volumio[1227]: info: All search sources collected, pushing search results Feb 12 18:44:18 living-room go-librespot[3158]: time="2026-02-12T18:44:18+01:00" level=trace msg="sent dealer ping" Feb 12 18:44:19 living-room go-librespot[3158]: time="2026-02-12T18:44:19+01:00" level=trace msg="received dealer pong" Feb 12 18:44:21 living-room volumio[1227]: Searching plugin music_service/spop Feb 12 18:44:21 living-room volumio[1227]: info: CoreCommandRouter::executeOnPlugin: spop , search Feb 12 18:44:22 living-room volumio[1227]: info: All search sources collected, pushing search results Feb 12 18:44:23 living-room volumio[1227]: Searching plugin music_service/spop Feb 12 18:44:23 living-room volumio[1227]: info: CoreCommandRouter::executeOnPlugin: spop , search Feb 12 18:44:24 living-room volumio[1227]: info: All search sources collected, pushing search results Feb 12 18:44:25 living-room go-librespot[3158]: time="2026-02-12T18:44:25+01:00" level=trace msg="received accesspoint ping" Feb 12 18:44:25 living-room go-librespot[3158]: time="2026-02-12T18:44:25+01:00" level=trace msg="received accesspoint pong ack" Feb 12 18:44:37 living-room volumio[1227]: info: CorePlayQueue::getTrack 2 Feb 12 18:44:37 living-room volumio[1227]: info: CorePlayQueue::getTrack 3 Feb 12 18:44:37 living-room volumio[1227]: info: Prefetching next song Feb 12 18:44:37 living-room volumio[1227]: info: [1770918277208] ControllerSpotify::prefetch Feb 12 18:44:37 living-room volumio[1227]: info: Sending Spotify command with payload to local API: /player/add_to_queue Feb 12 18:44:37 living-room go-librespot[3158]: time="2026-02-12T18:44:37+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 12 18:44:37 living-room go-librespot[3158]: time="2026-02-12T18:44:37+01:00" level=debug msg="prefetching next track" uri="spotify:track:0sObxZUKqdPfgjG9ahSlP5" Feb 12 18:44:37 living-room go-librespot[3158]: time="2026-02-12T18:44:37+01:00" level=debug msg="selected format OGG_VORBIS_320 (6d07ec26f567420654f51c32879da9a40f3f1d4c)" uri="spotify:track:0sObxZUKqdPfgjG9ahSlP5" Feb 12 18:44:37 living-room go-librespot[3158]: time="2026-02-12T18:44:37+01:00" level=debug msg="requested aes key for file 6d07ec26f567420654f51c32879da9a40f3f1d4c, gid: 0sObxZUKqdPfgjG9ahSlP5" Feb 12 18:44:37 living-room go-librespot[3158]: time="2026-02-12T18:44:37+01:00" level=trace msg="found 2 cdn urls" uri="spotify:track:0sObxZUKqdPfgjG9ahSlP5" Feb 12 18:44:37 living-room go-librespot[3158]: time="2026-02-12T18:44:37+01:00" level=debug msg="fetched first chunk of 24, total size is 12147664 bytes" uri="spotify:track:0sObxZUKqdPfgjG9ahSlP5" Feb 12 18:44:37 living-room go-librespot[3158]: time="2026-02-12T18:44:37+01:00" level=info msg="prefetched track \"The Pursuit of Vikings\" (duration: 270253ms)" uri="spotify:track:0sObxZUKqdPfgjG9ahSlP5" Feb 12 18:44:37 living-room go-librespot[3158]: time="2026-02-12T18:44:37+01:00" level=debug msg="fetched chunk 1/23, size: 524288" uri="spotify:track:0sObxZUKqdPfgjG9ahSlP5" Feb 12 18:44:37 living-room go-librespot[3158]: time="2026-02-12T18:44:37+01:00" level=debug msg="fetched chunk 3/23, size: 524288" uri="spotify:track:0sObxZUKqdPfgjG9ahSlP5" Feb 12 18:44:37 living-room go-librespot[3158]: time="2026-02-12T18:44:37+01:00" level=debug msg="fetched chunk 2/23, size: 524288" uri="spotify:track:0sObxZUKqdPfgjG9ahSlP5" Feb 12 18:44:40 living-room go-librespot[3158]: time="2026-02-12T18:44:40+01:00" level=trace msg="emitting websocket event: not_playing" Feb 12 18:44:40 living-room go-librespot[3158]: time="2026-02-12T18:44:40+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:0sObxZUKqdPfgjG9ahSlP5" Feb 12 18:44:40 living-room volumio[1227]: SPOTIFY: received: {"type":"not_playing","data":{"context_uri":"spotify:track:2DR9AzDhYeStkHupvU08FC","uri":"spotify:track:2DR9AzDhYeStkHupvU08FC","play_origin":"go-librespot"}} Feb 12 18:44:40 living-room volumio[1227]: error: Failed to decode event: not_playing Feb 12 18:44:40 living-room go-librespot[3158]: time="2026-02-12T18:44:40+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 12 18:44:40 living-room go-librespot[3158]: time="2026-02-12T18:44:40+01:00" level=trace msg="emitting websocket event: will_play" Feb 12 18:44:40 living-room go-librespot[3158]: time="2026-02-12T18:44:40+01:00" level=info msg="loaded track \"The Pursuit of Vikings\" (paused: false, position: 0ms, duration: 270253ms, prefetched: true)" uri="spotify:track:0sObxZUKqdPfgjG9ahSlP5" Feb 12 18:44:40 living-room volumio[1227]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:2DR9AzDhYeStkHupvU08FC","uri":"spotify:track:0sObxZUKqdPfgjG9ahSlP5","play_origin":"go-librespot"}} Feb 12 18:44:40 living-room go-librespot[3158]: time="2026-02-12T18:44:40+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 12 18:44:40 living-room go-librespot[3158]: time="2026-02-12T18:44:40+01:00" level=trace msg="scheduling prefetch in 241s" Feb 12 18:44:40 living-room go-librespot[3158]: time="2026-02-12T18:44:40+01:00" level=trace msg="emitting websocket event: metadata" Feb 12 18:44:40 living-room volumio[1227]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:0sObxZUKqdPfgjG9ahSlP5","name":"The Pursuit of Vikings","artist_names":["Amon Amarth"],"album_name":"Fate of Norns","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0295e7594a7df822c720d45867","position":0,"duration":270253,"release_date":"year:2004","track_number":4,"disc_number":1}} Feb 12 18:44:40 living-room go-librespot[3158]: time="2026-02-12T18:44:40+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 12 18:44:40 living-room go-librespot[3158]: time="2026-02-12T18:44:40+01:00" level=trace msg="emitting websocket event: playing" Feb 12 18:44:40 living-room volumio[1227]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:track:2DR9AzDhYeStkHupvU08FC","uri":"spotify:track:0sObxZUKqdPfgjG9ahSlP5","resume":false,"play_origin":"go-librespot"}} Feb 12 18:44:40 living-room volumio[1227]: SPOTIFY: PUSH STATE SPOTIFY Feb 12 18:44:40 living-room volumio[1227]: SPOTIFY: {"status":"play","service":"spop","title":"The Pursuit of Vikings","artist":"Amon Amarth","album":"Fate of Norns","albumart":"https://i.scdn.co/image/ab67616d00001e0295e7594a7df822c720d45867","uri":"spotify:track:0sObxZUKqdPfgjG9ahSlP5","trackType":"spotify","seek":0,"duration":270,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Feb 12 18:44:40 living-room volumio[1227]: info: CoreCommandRouter::servicePushState Feb 12 18:44:40 living-room volumio[1227]: info: CorePlayQueue::getTrack 2 Feb 12 18:44:40 living-room volumio[1227]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"The Pursuit of Vikings","artist":"Amon Amarth","album":"Fate of Norns","albumart":"https://i.scdn.co/image/ab67616d00001e0295e7594a7df822c720d45867","uri":"spotify:track:0sObxZUKqdPfgjG9ahSlP5","trackType":"spotify","seek":0,"duration":270,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Feb 12 18:44:40 living-room volumio[1227]: verbose: CURRENT POSITION 2 Feb 12 18:44:40 living-room volumio[1227]: info: CoreStateMachine::syncState stateService play Feb 12 18:44:40 living-room volumio[1227]: info: CoreStateMachine::syncState currentStatus play Feb 12 18:44:40 living-room volumio[1227]: info: Received an update from plugin. extracting info from payload Feb 12 18:44:40 living-room volumio[1227]: info: CoreStateMachine::pushState Feb 12 18:44:40 living-room volumio[1227]: info: CorePlayQueue::getTrack 2 Feb 12 18:44:40 living-room volumio[1227]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 12 18:44:40 living-room volumio[1227]: info: CoreCommandRouter::volumioPushState Feb 12 18:44:40 living-room volumio[1227]: info: CoreStateMachine::pushState Feb 12 18:44:40 living-room volumio[1227]: info: CorePlayQueue::getTrack 2 Feb 12 18:44:40 living-room volumio[1227]: info: CoreCommandRouter::volumioPushState Feb 12 18:44:40 living-room volumio[1227]: SPOTIFY: RECEIVED VOLUMIO VOLUME 25 Feb 12 18:44:40 living-room volumio[1227]: SPOTIFY: SPOTIFY VOLUME 24 Feb 12 18:44:40 living-room volumio[1227]: SPOTIFY: VOLUMIO VOLUME 25 Feb 12 18:44:40 living-room volumio[1227]: SPOTIFY: DELTA VOLUME ENOUGH: false Feb 12 18:44:40 living-room volumio[1227]: SPOTIFY: RECEIVED VOLUMIO VOLUME 25 Feb 12 18:44:40 living-room volumio[1227]: SPOTIFY: SPOTIFY VOLUME 24 Feb 12 18:44:40 living-room volumio[1227]: SPOTIFY: VOLUMIO VOLUME 25 Feb 12 18:44:40 living-room volumio[1227]: SPOTIFY: DELTA VOLUME ENOUGH: false Feb 12 18:44:40 living-room volumio[1227]: SPOTIFY: PUSH STATE SPOTIFY Feb 12 18:44:40 living-room volumio[1227]: SPOTIFY: {"status":"play","service":"spop","title":"The Pursuit of Vikings","artist":"Amon Amarth","album":"Fate of Norns","albumart":"https://i.scdn.co/image/ab67616d00001e0295e7594a7df822c720d45867","uri":"spotify:track:0sObxZUKqdPfgjG9ahSlP5","trackType":"spotify","seek":0,"duration":270,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Feb 12 18:44:40 living-room volumio[1227]: info: CoreCommandRouter::servicePushState Feb 12 18:44:40 living-room volumio[1227]: info: CorePlayQueue::getTrack 2 Feb 12 18:44:40 living-room volumio[1227]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"The Pursuit of Vikings","artist":"Amon Amarth","album":"Fate of Norns","albumart":"https://i.scdn.co/image/ab67616d00001e0295e7594a7df822c720d45867","uri":"spotify:track:0sObxZUKqdPfgjG9ahSlP5","trackType":"spotify","seek":0,"duration":270,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Feb 12 18:44:40 living-room volumio[1227]: verbose: CURRENT POSITION 2 Feb 12 18:44:40 living-room volumio[1227]: info: CoreStateMachine::syncState stateService play Feb 12 18:44:40 living-room volumio[1227]: info: CoreStateMachine::syncState currentStatus play Feb 12 18:44:40 living-room volumio[1227]: info: Received an update from plugin. extracting info from payload Feb 12 18:44:40 living-room volumio[1227]: info: CoreStateMachine::pushState Feb 12 18:44:40 living-room volumio[1227]: info: CorePlayQueue::getTrack 2 Feb 12 18:44:40 living-room volumio[1227]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 12 18:44:40 living-room volumio[1227]: info: CoreCommandRouter::volumioPushState Feb 12 18:44:40 living-room volumio[1227]: info: CoreStateMachine::pushState Feb 12 18:44:40 living-room volumio[1227]: info: CorePlayQueue::getTrack 2 Feb 12 18:44:40 living-room volumio[1227]: info: CoreCommandRouter::volumioPushState Feb 12 18:44:40 living-room volumio[1227]: SPOTIFY: RECEIVED VOLUMIO VOLUME 25 Feb 12 18:44:40 living-room volumio[1227]: SPOTIFY: SPOTIFY VOLUME 24 Feb 12 18:44:40 living-room volumio[1227]: SPOTIFY: VOLUMIO VOLUME 25 Feb 12 18:44:40 living-room volumio[1227]: SPOTIFY: DELTA VOLUME ENOUGH: false Feb 12 18:44:40 living-room volumio[1227]: SPOTIFY: RECEIVED VOLUMIO VOLUME 25 Feb 12 18:44:40 living-room volumio[1227]: SPOTIFY: SPOTIFY VOLUME 24 Feb 12 18:44:40 living-room volumio[1227]: SPOTIFY: VOLUMIO VOLUME 25 Feb 12 18:44:40 living-room volumio[1227]: SPOTIFY: DELTA VOLUME ENOUGH: false Feb 12 18:44:41 living-room volumio[1227]: Searching plugin music_service/spop Feb 12 18:44:41 living-room volumio[1227]: info: CoreCommandRouter::executeOnPlugin: spop , search Feb 12 18:44:41 living-room volumio[1227]: info: CoreStateMachine::startPlaybackTimer Feb 12 18:44:41 living-room volumio[1227]: info: CorePlayQueue::getTrack 3 Feb 12 18:44:42 living-room volumio[1227]: info: CoreStateMachine::pushState Feb 12 18:44:42 living-room volumio[1227]: info: CorePlayQueue::getTrack 3 Feb 12 18:44:42 living-room volumio[1227]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 12 18:44:42 living-room volumio[1227]: info: CoreCommandRouter::volumioPushState Feb 12 18:44:42 living-room volumio[1227]: SPOTIFY: RECEIVED VOLUMIO VOLUME 25 Feb 12 18:44:42 living-room volumio[1227]: SPOTIFY: SPOTIFY VOLUME 24 Feb 12 18:44:42 living-room volumio[1227]: SPOTIFY: VOLUMIO VOLUME 25 Feb 12 18:44:42 living-room volumio[1227]: SPOTIFY: DELTA VOLUME ENOUGH: false Feb 12 18:44:42 living-room volumio[1227]: info: All search sources collected, pushing search results Feb 12 18:44:46 living-room volumio[1227]: Searching plugin music_service/spop Feb 12 18:44:46 living-room volumio[1227]: info: CoreCommandRouter::executeOnPlugin: spop , search Feb 12 18:44:47 living-room volumio[1227]: info: All search sources collected, pushing search results Feb 12 18:44:48 living-room go-librespot[3158]: time="2026-02-12T18:44:48+01:00" level=trace msg="sent dealer ping" Feb 12 18:44:49 living-room go-librespot[3158]: time="2026-02-12T18:44:49+01:00" level=trace msg="received dealer pong" Feb 12 18:44:51 living-room go-librespot[3158]: time="2026-02-12T18:44:51+01:00" level=debug msg="fetched chunk 4/23, size: 524288" uri="spotify:track:0sObxZUKqdPfgjG9ahSlP5" Feb 12 18:45:03 living-room go-librespot[3158]: time="2026-02-12T18:45:03+01:00" level=debug msg="fetched chunk 5/23, size: 524288" uri="spotify:track:0sObxZUKqdPfgjG9ahSlP5" Feb 12 18:45:05 living-room volumio[1227]: Searching plugin music_service/spop Feb 12 18:45:05 living-room volumio[1227]: info: CoreCommandRouter::executeOnPlugin: spop , search Feb 12 18:45:06 living-room volumio[1227]: info: All search sources collected, pushing search results Feb 12 18:45:09 living-room volumio[1227]: Searching plugin music_service/spop Feb 12 18:45:09 living-room volumio[1227]: info: CoreCommandRouter::executeOnPlugin: spop , search Feb 12 18:45:09 living-room volumio[1227]: info: All search sources collected, pushing search results Feb 12 18:45:11 living-room volumio[1227]: Searching plugin music_service/spop Feb 12 18:45:11 living-room volumio[1227]: info: CoreCommandRouter::executeOnPlugin: spop , search Feb 12 18:45:11 living-room volumio[1227]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Feb 12 18:45:11 living-room volumio[1227]: info: In handleBrowseUri, curUri=spotify:artist:3X2N4k3yp1MpIWzNYj1JQy Feb 12 18:45:11 living-room volumio[1227]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Feb 12 18:45:11 living-room volumio[1227]: info: In handleBrowseUri, curUri=spotify:artist:3X2N4k3yp1MpIWzNYj1JQy Feb 12 18:45:12 living-room volumio[1227]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Feb 12 18:45:12 living-room volumio[1227]: info: In handleBrowseUri, curUri=spotify:artist:3X2N4k3yp1MpIWzNYj1JQy Feb 12 18:45:12 living-room volumio[1227]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 12 18:45:12 living-room volumio[1227]: TypeError: Cannot read properties of undefined (reading 'url') Feb 12 18:45:12 living-room volumio[1227]: at /data/plugins/music_service/spop/index.js:2449:60 Feb 12 18:45:12 living-room volumio[1227]: at process.processTicksAndRejections (node:internal/process/task_queues:95:5) Feb 12 18:45:12 living-room volumio[1227]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 12 18:45:12 living-room sudo[18300]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-02-12 18:44' Feb 12 18:45:12 living-room sudo[18300]: 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="b05a530ca81d05eb9a84d0acf82089f0a60b8ee6" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="4ad85e2147d972f0b838d33c21382d2d813b2ae8" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu Dec 25 09:13:19 UTC 2025" VOLUMIO_VERSION="4.084" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="792f09af7488531aecd1aadcaa9b175e"