Feb 23 21:33:07 volumio go-librespot[1502]: time="2026-02-23T21:33:07+09:00" level=trace msg="received accesspoint ping" Feb 23 21:33:07 volumio go-librespot[1502]: time="2026-02-23T21:33:07+09:00" level=trace msg="received accesspoint pong ack" Feb 23 21:33:07 volumio go-librespot[1502]: time="2026-02-23T21:33:07+09:00" level=trace msg="sent dealer ping" Feb 23 21:33:07 volumio go-librespot[1502]: time="2026-02-23T21:33:07+09:00" level=trace msg="received dealer pong" Feb 23 21:33:19 volumio systemd[1]: Starting setdatetime-helper.service - Time Synchronization Helper Service... Feb 23 21:33:21 volumio systemd[1]: setdatetime-helper.service: Deactivated successfully. Feb 23 21:33:21 volumio systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service. Feb 23 21:33:26 volumio volumio[1149]: info: CorePlayQueue::getTrack 7 Feb 23 21:33:26 volumio volumio[1149]: info: CorePlayQueue::getTrack 54 Feb 23 21:33:26 volumio volumio[1149]: info: Prefetching next song Feb 23 21:33:26 volumio volumio[1149]: info: [1771850006196] ControllerSpotify::prefetch Feb 23 21:33:26 volumio volumio[1149]: info: Sending Spotify command with payload to local API: /player/add_to_queue Feb 23 21:33:26 volumio go-librespot[1502]: time="2026-02-23T21:33:26+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 23 21:33:26 volumio go-librespot[1502]: time="2026-02-23T21:33:26+09:00" level=trace msg="prefetch as soon as possible" Feb 23 21:33:26 volumio go-librespot[1502]: time="2026-02-23T21:33:26+09:00" level=debug msg="prefetching next track" uri="spotify:track:4ETc1oFREuqQss7VQ1Y4mj" Feb 23 21:33:26 volumio go-librespot[1502]: time="2026-02-23T21:33:26+09:00" level=debug msg="selected format OGG_VORBIS_96 (e06ebf784d497ecda1b3f03369e1b7ff356c8c12)" uri="spotify:track:4ETc1oFREuqQss7VQ1Y4mj" Feb 23 21:33:26 volumio go-librespot[1502]: time="2026-02-23T21:33:26+09:00" level=debug msg="requested aes key for file e06ebf784d497ecda1b3f03369e1b7ff356c8c12, gid: 4ETc1oFREuqQss7VQ1Y4mj" Feb 23 21:33:26 volumio go-librespot[1502]: time="2026-02-23T21:33:26+09:00" level=trace msg="found 2 cdn urls" uri="spotify:track:4ETc1oFREuqQss7VQ1Y4mj" Feb 23 21:33:26 volumio go-librespot[1502]: time="2026-02-23T21:33:26+09:00" level=debug msg="fetched first chunk of 5, total size is 2342556 bytes" uri="spotify:track:4ETc1oFREuqQss7VQ1Y4mj" Feb 23 21:33:26 volumio go-librespot[1502]: time="2026-02-23T21:33:26+09:00" level=info msg="prefetched track \"花占い\" (duration: 207486ms)" uri="spotify:track:4ETc1oFREuqQss7VQ1Y4mj" Feb 23 21:33:26 volumio go-librespot[1502]: time="2026-02-23T21:33:26+09:00" level=debug msg="fetched chunk 2/4, size: 524288" uri="spotify:track:4ETc1oFREuqQss7VQ1Y4mj" Feb 23 21:33:26 volumio go-librespot[1502]: time="2026-02-23T21:33:26+09:00" level=debug msg="fetched chunk 1/4, size: 524288" uri="spotify:track:4ETc1oFREuqQss7VQ1Y4mj" Feb 23 21:33:27 volumio go-librespot[1502]: time="2026-02-23T21:33:27+09:00" level=debug msg="fetched chunk 3/4, size: 524288" uri="spotify:track:4ETc1oFREuqQss7VQ1Y4mj" Feb 23 21:33:28 volumio go-librespot[1502]: time="2026-02-23T21:33:28+09:00" level=trace msg="emitting websocket event: not_playing" Feb 23 21:33:28 volumio go-librespot[1502]: time="2026-02-23T21:33:28+09:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:4ETc1oFREuqQss7VQ1Y4mj" Feb 23 21:33:28 volumio volumio[1149]: SPOTIFY: received: {"type":"not_playing","data":{"context_uri":"spotify:track:6orDsQsMy7BaqGoRWw3fVN","uri":"spotify:track:6FhWelfRDMFZRtFUU6SIdC","play_origin":"go-librespot"}} Feb 23 21:33:28 volumio volumio[1149]: error: Failed to decode event: not_playing Feb 23 21:33:28 volumio go-librespot[1502]: time="2026-02-23T21:33:28+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 23 21:33:28 volumio go-librespot[1502]: time="2026-02-23T21:33:28+09:00" level=trace msg="emitting websocket event: will_play" Feb 23 21:33:28 volumio go-librespot[1502]: time="2026-02-23T21:33:28+09:00" level=info msg="loaded track \"花占い\" (paused: false, position: 0ms, duration: 207486ms, prefetched: true)" uri="spotify:track:4ETc1oFREuqQss7VQ1Y4mj" Feb 23 21:33:28 volumio volumio[1149]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:6orDsQsMy7BaqGoRWw3fVN","uri":"spotify:track:4ETc1oFREuqQss7VQ1Y4mj","play_origin":"go-librespot"}} Feb 23 21:33:28 volumio go-librespot[1502]: time="2026-02-23T21:33:28+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 23 21:33:28 volumio go-librespot[1502]: time="2026-02-23T21:33:28+09:00" level=trace msg="scheduling prefetch in 177s" Feb 23 21:33:28 volumio go-librespot[1502]: time="2026-02-23T21:33:28+09:00" level=trace msg="emitting websocket event: metadata" Feb 23 21:33:28 volumio volumio[1149]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:4ETc1oFREuqQss7VQ1Y4mj","name":"花占い","artist_names":["Vaundy"],"album_name":"replica","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02e0c3a68b9981c2e7b25f9737","position":0,"duration":207486,"release_date":"year:2023 month:11 day:15","track_number":6,"disc_number":2}} Feb 23 21:33:28 volumio go-librespot[1502]: time="2026-02-23T21:33:28+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 23 21:33:28 volumio go-librespot[1502]: time="2026-02-23T21:33:28+09:00" level=trace msg="emitting websocket event: playing" Feb 23 21:33:28 volumio volumio[1149]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:track:6orDsQsMy7BaqGoRWw3fVN","uri":"spotify:track:4ETc1oFREuqQss7VQ1Y4mj","resume":false,"play_origin":"go-librespot"}} Feb 23 21:33:28 volumio volumio[1149]: SPOTIFY: PUSH STATE SPOTIFY Feb 23 21:33:28 volumio volumio[1149]: SPOTIFY: {"status":"play","service":"spop","title":"花占い","artist":"Vaundy","album":"replica","albumart":"https://i.scdn.co/image/ab67616d00001e02e0c3a68b9981c2e7b25f9737","uri":"spotify:track:4ETc1oFREuqQss7VQ1Y4mj","trackType":"spotify","seek":0,"duration":207,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"96 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Feb 23 21:33:28 volumio volumio[1149]: info: CoreCommandRouter::servicePushState Feb 23 21:33:28 volumio volumio[1149]: info: CorePlayQueue::getTrack 7 Feb 23 21:33:28 volumio volumio[1149]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"花占い","artist":"Vaundy","album":"replica","albumart":"https://i.scdn.co/image/ab67616d00001e02e0c3a68b9981c2e7b25f9737","uri":"spotify:track:4ETc1oFREuqQss7VQ1Y4mj","trackType":"spotify","seek":0,"duration":207,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"96 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Feb 23 21:33:28 volumio volumio[1149]: verbose: CURRENT POSITION 7 Feb 23 21:33:28 volumio volumio[1149]: info: CoreStateMachine::syncState stateService play Feb 23 21:33:28 volumio volumio[1149]: info: CoreStateMachine::syncState currentStatus play Feb 23 21:33:28 volumio volumio[1149]: info: Received an update from plugin. extracting info from payload Feb 23 21:33:28 volumio volumio[1149]: info: CoreStateMachine::pushState Feb 23 21:33:28 volumio volumio[1149]: info: CorePlayQueue::getTrack 7 Feb 23 21:33:28 volumio volumio[1149]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 23 21:33:28 volumio volumio[1149]: info: CoreCommandRouter::volumioPushState Feb 23 21:33:28 volumio volumio[1149]: info: CoreStateMachine::pushState Feb 23 21:33:28 volumio volumio[1149]: info: CorePlayQueue::getTrack 7 Feb 23 21:33:28 volumio volumio[1149]: info: CoreCommandRouter::volumioPushState Feb 23 21:33:28 volumio volumio[1149]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 23 21:33:28 volumio volumio[1149]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 23 21:33:28 volumio volumio[1149]: SPOTIFY: PUSH STATE SPOTIFY Feb 23 21:33:28 volumio volumio[1149]: SPOTIFY: {"status":"play","service":"spop","title":"花占い","artist":"Vaundy","album":"replica","albumart":"https://i.scdn.co/image/ab67616d00001e02e0c3a68b9981c2e7b25f9737","uri":"spotify:track:4ETc1oFREuqQss7VQ1Y4mj","trackType":"spotify","seek":1000,"duration":207,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"96 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Feb 23 21:33:28 volumio volumio[1149]: info: CoreCommandRouter::servicePushState Feb 23 21:33:28 volumio volumio[1149]: info: CorePlayQueue::getTrack 7 Feb 23 21:33:28 volumio volumio[1149]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"花占い","artist":"Vaundy","album":"replica","albumart":"https://i.scdn.co/image/ab67616d00001e02e0c3a68b9981c2e7b25f9737","uri":"spotify:track:4ETc1oFREuqQss7VQ1Y4mj","trackType":"spotify","seek":1000,"duration":207,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"96 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Feb 23 21:33:28 volumio volumio[1149]: verbose: CURRENT POSITION 7 Feb 23 21:33:28 volumio volumio[1149]: info: CoreStateMachine::syncState stateService play Feb 23 21:33:28 volumio volumio[1149]: info: CoreStateMachine::syncState currentStatus play Feb 23 21:33:28 volumio volumio[1149]: info: Received an update from plugin. extracting info from payload Feb 23 21:33:28 volumio volumio[1149]: info: CoreStateMachine::pushState Feb 23 21:33:28 volumio volumio[1149]: info: CorePlayQueue::getTrack 7 Feb 23 21:33:28 volumio volumio[1149]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 23 21:33:28 volumio volumio[1149]: info: CoreCommandRouter::volumioPushState Feb 23 21:33:28 volumio volumio[1149]: info: CoreStateMachine::pushState Feb 23 21:33:28 volumio volumio[1149]: info: CorePlayQueue::getTrack 7 Feb 23 21:33:28 volumio volumio[1149]: info: CoreCommandRouter::volumioPushState Feb 23 21:33:28 volumio volumio[1149]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 23 21:33:28 volumio volumio[1149]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 23 21:33:30 volumio volumio[1149]: info: CoreStateMachine::startPlaybackTimer Feb 23 21:33:30 volumio volumio[1149]: info: CorePlayQueue::getTrack 54 Feb 23 21:33:31 volumio volumio[1149]: info: CoreStateMachine::pushState Feb 23 21:33:31 volumio volumio[1149]: info: CorePlayQueue::getTrack 54 Feb 23 21:33:31 volumio volumio[1149]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 23 21:33:31 volumio volumio[1149]: info: CoreCommandRouter::volumioPushState Feb 23 21:33:31 volumio volumio[1149]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 23 21:33:37 volumio go-librespot[1502]: time="2026-02-23T21:33:37+09:00" level=trace msg="sent dealer ping" Feb 23 21:33:37 volumio go-librespot[1502]: time="2026-02-23T21:33:37+09:00" level=trace msg="received dealer pong" Feb 23 21:34:00 volumio volumio[1149]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Feb 23 21:34:00 volumio volumio[1149]: info: In handleBrowseUri, curUri=spotify Feb 23 21:34:00 volumio volumio[1149]: info: Preload queue cleared Feb 23 21:34:00 volumio volumio[1149]: info: Preload queue cleared Feb 23 21:34:00 volumio volumio[1149]: info: Preload queue cleared Feb 23 21:34:00 volumio volumio[1149]: info: Preload queue cleared Feb 23 21:34:06 volumio volumio[1149]: Searching plugin music_service/spop Feb 23 21:34:06 volumio volumio[1149]: info: CoreCommandRouter::executeOnPlugin: spop , search Feb 23 21:34:07 volumio volumio[1149]: info: All search sources collected, pushing search results Feb 23 21:34:07 volumio go-librespot[1502]: time="2026-02-23T21:34:07+09:00" level=trace msg="sent dealer ping" Feb 23 21:34:07 volumio go-librespot[1502]: time="2026-02-23T21:34:07+09:00" level=trace msg="received dealer pong" Feb 23 21:34:12 volumio volumio[1149]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Feb 23 21:34:12 volumio volumio[1149]: info: In handleBrowseUri, curUri=spotify:artist:1QKkhBYoDQdMEaJNp2YuVD Feb 23 21:34:13 volumio volumio[1149]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 23 21:34:13 volumio volumio[1149]: TypeError: Cannot read properties of undefined (reading 'url') Feb 23 21:34:13 volumio volumio[1149]: at /data/plugins/music_service/spop/index.js:2446:60 Feb 23 21:34:13 volumio volumio[1149]: at process.processTicksAndRejections (node:internal/process/task_queues:95:5) Feb 23 21:34:13 volumio volumio[1149]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 23 21:34:13 volumio go-librespot[1502]: time="2026-02-23T21:34:13+09:00" level=debug msg="fetched chunk 4/4, size: 245404" uri="spotify:track:4ETc1oFREuqQss7VQ1Y4mj" Feb 23 21:34:14 volumio sudo[4774]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-02-23 21:33' Feb 23 21:34:14 volumio sudo[4774]: 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="a78d359cf1dc63ac74e9d151015afd30d31a709a" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="c1ffe93b2136013fc1b5903a4ed7e3f34e0a7bec" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu Feb 5 14:07:07 UTC 2026" VOLUMIO_VERSION="4.096" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="5e37060f9823263a753eb5e84030104f"