Oct 17 09:31:14 volumio volumio[1474]: info: CorePlayQueue::getTrack 0 Oct 17 09:31:14 volumio volumio[1474]: info: CorePlayQueue::getTrack 1 Oct 17 09:31:14 volumio volumio[1474]: info: Prefetching next song Oct 17 09:31:14 volumio volumio[1474]: info: [1792222274416] ControllerSpotify::prefetch Oct 17 09:31:14 volumio volumio[1474]: info: Sending Spotify command with payload to local API: /player/add_to_queue Oct 17 09:31:14 volumio go-librespot[1917]: time="2026-10-17T09:31:14+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 17 09:31:14 volumio go-librespot[1917]: time="2026-10-17T09:31:14+02:00" level=trace msg="prefetch as soon as possible" Oct 17 09:31:14 volumio go-librespot[1917]: time="2026-10-17T09:31:14+02:00" level=debug msg="prefetching next track" uri="spotify:track:4DQbYa6yBye49Yg1ui0hfO" Oct 17 09:31:14 volumio go-librespot[1917]: time="2026-10-17T09:31:14+02:00" level=debug msg="selected format OGG_VORBIS_320 (ceb1bca5fe2a3355b0c2e6db2b1795b20df8da6f)" uri="spotify:track:4DQbYa6yBye49Yg1ui0hfO" Oct 17 09:31:14 volumio go-librespot[1917]: time="2026-10-17T09:31:14+02:00" level=debug msg="requested aes key for file ceb1bca5fe2a3355b0c2e6db2b1795b20df8da6f, gid: 4DQbYa6yBye49Yg1ui0hfO" Oct 17 09:31:14 volumio go-librespot[1917]: time="2026-10-17T09:31:14+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:4DQbYa6yBye49Yg1ui0hfO" Oct 17 09:31:15 volumio go-librespot[1917]: time="2026-10-17T09:31:15+02:00" level=debug msg="fetched first chunk of 14, total size is 6950040 bytes" uri="spotify:track:4DQbYa6yBye49Yg1ui0hfO" Oct 17 09:31:15 volumio go-librespot[1917]: time="2026-10-17T09:31:15+02:00" level=info msg="prefetched track \"Justa Jonesin'\" (duration: 164602ms)" uri="spotify:track:4DQbYa6yBye49Yg1ui0hfO" Oct 17 09:31:15 volumio go-librespot[1917]: time="2026-10-17T09:31:15+02:00" level=debug msg="fetched chunk 1/13, size: 524288" uri="spotify:track:4DQbYa6yBye49Yg1ui0hfO" Oct 17 09:31:15 volumio go-librespot[1917]: time="2026-10-17T09:31:15+02:00" level=debug msg="fetched chunk 2/13, size: 524288" uri="spotify:track:4DQbYa6yBye49Yg1ui0hfO" Oct 17 09:31:15 volumio go-librespot[1917]: time="2026-10-17T09:31:15+02:00" level=debug msg="fetched chunk 3/13, size: 524288" uri="spotify:track:4DQbYa6yBye49Yg1ui0hfO" Oct 17 09:31:18 volumio volumio[1474]: info: CoreStateMachine::startPlaybackTimer Oct 17 09:31:18 volumio volumio[1474]: info: CorePlayQueue::getTrack 1 Oct 17 09:31:19 volumio go-librespot[1917]: time="2026-10-17T09:31:19+02:00" level=trace msg="emitting websocket event: not_playing" Oct 17 09:31:19 volumio go-librespot[1917]: time="2026-10-17T09:31:19+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:4DQbYa6yBye49Yg1ui0hfO" Oct 17 09:31:19 volumio volumio[1474]: SPOTIFY: received: {"type":"not_playing","data":{"context_uri":"spotify:track:1WzAeadSKJhqykZFbJNmQv","uri":"spotify:track:1WzAeadSKJhqykZFbJNmQv","play_origin":"go-librespot"}} Oct 17 09:31:19 volumio volumio[1474]: error: Failed to decode event: not_playing Oct 17 09:31:19 volumio go-librespot[1917]: time="2026-10-17T09:31:19+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 17 09:31:19 volumio go-librespot[1917]: time="2026-10-17T09:31:19+02:00" level=trace msg="emitting websocket event: will_play" Oct 17 09:31:19 volumio go-librespot[1917]: time="2026-10-17T09:31:19+02:00" level=debug msg="track has no narration" uri="spotify:track:4DQbYa6yBye49Yg1ui0hfO" Oct 17 09:31:19 volumio go-librespot[1917]: time="2026-10-17T09:31:19+02:00" level=info msg="loaded track \"Justa Jonesin'\" (paused: false, position: 0ms, duration: 164602ms, prefetched: true)" uri="spotify:track:4DQbYa6yBye49Yg1ui0hfO" Oct 17 09:31:19 volumio volumio[1474]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:1WzAeadSKJhqykZFbJNmQv","uri":"spotify:track:4DQbYa6yBye49Yg1ui0hfO","play_origin":"go-librespot"}} Oct 17 09:31:19 volumio volumio[1474]: info: CoreStateMachine::pushState Oct 17 09:31:19 volumio volumio[1474]: info: CorePlayQueue::getTrack 1 Oct 17 09:31:19 volumio volumio[1474]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 17 09:31:19 volumio volumio[1474]: info: CoreCommandRouter::volumioPushState Oct 17 09:31:19 volumio go-librespot[1917]: time="2026-10-17T09:31:19+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 17 09:31:19 volumio go-librespot[1917]: time="2026-10-17T09:31:19+02:00" level=trace msg="scheduling prefetch in 135s" Oct 17 09:31:19 volumio go-librespot[1917]: time="2026-10-17T09:31:19+02:00" level=trace msg="emitting websocket event: metadata" Oct 17 09:31:19 volumio volumio[1474]: SPOTIFY: received: {"type":"metadata","data":{"album_cover_url":"https://i.scdn.co/image/ab67616d00001e0237631efd49e94bc947fa4445","album_name":"Justa Jonesin'","artist_names":["Zach Top"],"bit_depth":null,"bitrate":320,"codec":"vorbis","disc_number":1,"duration":164602,"format":"OGG_VORBIS_320","name":"Justa Jonesin'","position":0,"release_date":"year:2023 month:7 day:19","sample_rate":44100,"track_number":1,"uri":"spotify:track:4DQbYa6yBye49Yg1ui0hfO"}} Oct 17 09:31:19 volumio go-librespot[1917]: time="2026-10-17T09:31:19+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 17 09:31:19 volumio go-librespot[1917]: time="2026-10-17T09:31:19+02:00" level=trace msg="emitting websocket event: playing" Oct 17 09:31:19 volumio volumio[1474]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:track:1WzAeadSKJhqykZFbJNmQv","uri":"spotify:track:4DQbYa6yBye49Yg1ui0hfO","resume":false,"play_origin":"go-librespot"}} Oct 17 09:31:19 volumio volumio[1474]: SPOTIFY: PUSH STATE SPOTIFY Oct 17 09:31:19 volumio volumio[1474]: SPOTIFY: {"status":"play","service":"spop","title":"Justa Jonesin'","artist":"Zach Top","album":"Justa Jonesin'","albumart":"https://i.scdn.co/image/ab67616d00001e0237631efd49e94bc947fa4445","uri":"spotify:track:4DQbYa6yBye49Yg1ui0hfO","trackType":"spotify","seek":0,"duration":164,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 17 09:31:19 volumio volumio[1474]: info: CoreCommandRouter::servicePushState Oct 17 09:31:19 volumio volumio[1474]: info: CorePlayQueue::getTrack 1 Oct 17 09:31:19 volumio volumio[1474]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Justa Jonesin'","artist":"Zach Top","album":"Justa Jonesin'","albumart":"https://i.scdn.co/image/ab67616d00001e0237631efd49e94bc947fa4445","uri":"spotify:track:4DQbYa6yBye49Yg1ui0hfO","trackType":"spotify","seek":0,"duration":164,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 17 09:31:19 volumio volumio[1474]: verbose: CURRENT POSITION 1 Oct 17 09:31:19 volumio volumio[1474]: info: CoreStateMachine::syncState stateService play Oct 17 09:31:19 volumio volumio[1474]: info: CoreStateMachine::syncState currentStatus play Oct 17 09:31:19 volumio volumio[1474]: info: Received an update from plugin. extracting info from payload Oct 17 09:31:19 volumio volumio[1474]: info: CoreStateMachine::pushState Oct 17 09:31:19 volumio volumio[1474]: info: CorePlayQueue::getTrack 1 Oct 17 09:31:19 volumio volumio[1474]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 17 09:31:19 volumio volumio[1474]: info: CoreCommandRouter::volumioPushState Oct 17 09:31:19 volumio volumio[1474]: info: CoreStateMachine::pushState Oct 17 09:31:19 volumio volumio[1474]: info: CorePlayQueue::getTrack 1 Oct 17 09:31:19 volumio volumio[1474]: info: CoreCommandRouter::volumioPushState Oct 17 09:31:19 volumio volumio[1474]: SPOTIFY: PUSH STATE SPOTIFY Oct 17 09:31:19 volumio volumio[1474]: SPOTIFY: {"status":"play","service":"spop","title":"Justa Jonesin'","artist":"Zach Top","album":"Justa Jonesin'","albumart":"https://i.scdn.co/image/ab67616d00001e0237631efd49e94bc947fa4445","uri":"spotify:track:4DQbYa6yBye49Yg1ui0hfO","trackType":"spotify","seek":0,"duration":164,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 17 09:31:19 volumio volumio[1474]: info: CoreCommandRouter::servicePushState Oct 17 09:31:19 volumio volumio[1474]: info: CorePlayQueue::getTrack 1 Oct 17 09:31:19 volumio volumio[1474]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Justa Jonesin'","artist":"Zach Top","album":"Justa Jonesin'","albumart":"https://i.scdn.co/image/ab67616d00001e0237631efd49e94bc947fa4445","uri":"spotify:track:4DQbYa6yBye49Yg1ui0hfO","trackType":"spotify","seek":0,"duration":164,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 17 09:31:19 volumio volumio[1474]: verbose: CURRENT POSITION 1 Oct 17 09:31:19 volumio volumio[1474]: info: CoreStateMachine::syncState stateService play Oct 17 09:31:19 volumio volumio[1474]: info: CoreStateMachine::syncState currentStatus play Oct 17 09:31:19 volumio volumio[1474]: info: Received an update from plugin. extracting info from payload Oct 17 09:31:19 volumio volumio[1474]: info: CoreStateMachine::pushState Oct 17 09:31:19 volumio volumio[1474]: info: CorePlayQueue::getTrack 1 Oct 17 09:31:19 volumio volumio[1474]: info: CoreCommandRouter::volumioPushState Oct 17 09:31:19 volumio volumio[1474]: info: CoreStateMachine::pushState Oct 17 09:31:19 volumio volumio[1474]: info: CorePlayQueue::getTrack 1 Oct 17 09:31:19 volumio volumio[1474]: info: CoreCommandRouter::volumioPushState Oct 17 09:31:31 volumio go-librespot[1917]: time="2026-10-17T09:31:31+02:00" level=debug msg="fetched chunk 4/13, size: 524288" uri="spotify:track:4DQbYa6yBye49Yg1ui0hfO" Oct 17 09:31:43 volumio go-librespot[1917]: time="2026-10-17T09:31:43+02:00" level=debug msg="fetched chunk 5/13, size: 524288" uri="spotify:track:4DQbYa6yBye49Yg1ui0hfO" Oct 17 09:31:55 volumio go-librespot[1917]: time="2026-10-17T09:31:55+02:00" level=debug msg="fetched chunk 6/13, size: 524288" uri="spotify:track:4DQbYa6yBye49Yg1ui0hfO" Oct 17 09:32:08 volumio go-librespot[1917]: time="2026-10-17T09:32:08+02:00" level=debug msg="fetched chunk 7/13, size: 524288" uri="spotify:track:4DQbYa6yBye49Yg1ui0hfO" Oct 17 09:32:08 volumio volumio[1474]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Oct 17 09:32:08 volumio volumio[1474]: info: In handleBrowseUri, curUri=spotify:user:spotify:playlist:37i9dQZF1DWUN2ernEEdZ0 Oct 17 09:32:08 volumio go-librespot[1917]: time="2026-10-17T09:32:08+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 139" Oct 17 09:32:08 volumio go-librespot[1917]: time="2026-10-17T09:32:08+02:00" level=debug msg="skipping dealer message" uri="hm://playlist/v2/playlist/37i9dQZF1DWUN2ernEEdZ0" Oct 17 09:32:09 volumio go-librespot[1917]: time="2026-10-17T09:32:09+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 139" Oct 17 09:32:09 volumio go-librespot[1917]: time="2026-10-17T09:32:09+02:00" level=debug msg="skipping dealer message" uri="hm://playlist/v2/playlist/37i9dQZF1DWUN2ernEEdZ0" Oct 17 09:32:10 volumio volumio[1474]: error: An error occurred while exploding listing Spotify playlist tracks TypeError: Cannot read properties of null (reading 'name') Oct 17 09:32:21 volumio go-librespot[1917]: time="2026-10-17T09:32:21+02:00" level=debug msg="fetched chunk 8/13, size: 524288" uri="spotify:track:4DQbYa6yBye49Yg1ui0hfO" Oct 17 09:32:31 volumio ntpd[1225]: DNS: dns_probe: 0.debian.pool.ntp.org, cast_flags:8, flags:101 Oct 17 09:32:31 volumio ntpd[1225]: DNS: dns_check: processing 0.debian.pool.ntp.org, 8, 101 Oct 17 09:32:31 volumio ntpd[1225]: DNS: Pool taking: 81.169.228.94 Oct 17 09:32:31 volumio ntpd[1225]: DNS: Pool taking: 116.203.218.109 Oct 17 09:32:31 volumio ntpd[1225]: DNS: Pool taking: 139.144.71.56 Oct 17 09:32:31 volumio ntpd[1225]: DNS: Pool taking: 90.187.112.137 Oct 17 09:32:31 volumio ntpd[1225]: DNS: dns_take_status: 0.debian.pool.ntp.org=>good, 8 Oct 17 09:32:33 volumio go-librespot[1917]: time="2026-10-17T09:32:33+02:00" level=debug msg="fetched chunk 9/13, size: 524288" uri="spotify:track:4DQbYa6yBye49Yg1ui0hfO" Oct 17 09:32:45 volumio go-librespot[1917]: time="2026-10-17T09:32:45+02:00" level=debug msg="fetched chunk 10/13, size: 524288" uri="spotify:track:4DQbYa6yBye49Yg1ui0hfO" Oct 17 09:32:47 volumio volumio[1474]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Oct 17 09:32:47 volumio volumio[1474]: info: In handleBrowseUri, curUri=spotify:user:spotify:playlist:2aOTP6TDNTqm5DNUmo1Sq3 Oct 17 09:32:47 volumio volumio[1474]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 17 09:32:47 volumio volumio[1474]: TypeError: Cannot read properties of null (reading '0') Oct 17 09:32:47 volumio volumio[1474]: at /data/plugins/music_service/spop/index.js:3418:56 Oct 17 09:32:47 volumio volumio[1474]: at process.processTicksAndRejections (node:internal/process/task_queues:95:5) Oct 17 09:32:47 volumio volumio[1474]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 17 09:32:47 volumio sudo[4165]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-10-17 09:31' Oct 17 09:32:47 volumio sudo[4165]: 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="18952480e8d8c63f22208e9007a0f47a9563eae6" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="0e58f1861fa88e02087981b8d91f7511f0e7011b" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue Mar 24 17:20:52 UTC 2026" VOLUMIO_VERSION="4.119" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="d0c2fd9dbc5e70e58c32413c12353563"