Dec 09 20:30:00 volumio go-librespot[1552]: time="2025-12-09T20:30:00+01:00" level=debug msg="fetched chunk 25/30, size: 524288" uri="spotify:track:60J5rX4gzm3BnINRI6r5Dh" Dec 09 20:30:08 volumio go-librespot[1552]: time="2025-12-09T20:30:08+01:00" level=trace msg="sent dealer ping" Dec 09 20:30:08 volumio go-librespot[1552]: time="2025-12-09T20:30:08+01:00" level=trace msg="received dealer pong" Dec 09 20:30:12 volumio go-librespot[1552]: time="2025-12-09T20:30:12+01:00" level=debug msg="fetched chunk 26/30, size: 524288" uri="spotify:track:60J5rX4gzm3BnINRI6r5Dh" Dec 09 20:30:24 volumio go-librespot[1552]: time="2025-12-09T20:30:24+01:00" level=debug msg="fetched chunk 27/30, size: 524288" uri="spotify:track:60J5rX4gzm3BnINRI6r5Dh" Dec 09 20:30:35 volumio go-librespot[1552]: time="2025-12-09T20:30:35+01:00" level=debug msg="fetched chunk 28/30, size: 524288" uri="spotify:track:60J5rX4gzm3BnINRI6r5Dh" Dec 09 20:30:38 volumio go-librespot[1552]: time="2025-12-09T20:30:38+01:00" level=trace msg="sent dealer ping" Dec 09 20:30:38 volumio go-librespot[1552]: time="2025-12-09T20:30:38+01:00" level=trace msg="received dealer pong" Dec 09 20:30:47 volumio go-librespot[1552]: time="2025-12-09T20:30:47+01:00" level=debug msg="fetched chunk 29/30, size: 524288" uri="spotify:track:60J5rX4gzm3BnINRI6r5Dh" Dec 09 20:31:00 volumio go-librespot[1552]: time="2025-12-09T20:31:00+01:00" level=debug msg="fetched chunk 30/30, size: 89784" uri="spotify:track:60J5rX4gzm3BnINRI6r5Dh" Dec 09 20:31:00 volumio go-librespot[1552]: time="2025-12-09T20:31:00+01:00" level=trace msg="received accesspoint ping" Dec 09 20:31:01 volumio go-librespot[1552]: time="2025-12-09T20:31:01+01:00" level=trace msg="received accesspoint pong ack" Dec 09 20:31:08 volumio go-librespot[1552]: time="2025-12-09T20:31:08+01:00" level=trace msg="sent dealer ping" Dec 09 20:31:08 volumio go-librespot[1552]: time="2025-12-09T20:31:08+01:00" level=trace msg="received dealer pong" Dec 09 20:31:10 volumio go-librespot[1552]: time="2025-12-09T20:31:10+01:00" level=debug msg="prefetching next track" uri="spotify:track:6sXuVJcafs6Pkg49YFK9ro" Dec 09 20:31:15 volumio go-librespot[1552]: time="2025-12-09T20:31:15+01:00" level=debug msg="selected format OGG_VORBIS_320 (592b70a572d12ecc19ab9a800a357fdf1990e0fc)" uri="spotify:track:6sXuVJcafs6Pkg49YFK9ro" Dec 09 20:31:15 volumio go-librespot[1552]: time="2025-12-09T20:31:15+01:00" level=debug msg="requested aes key for file 592b70a572d12ecc19ab9a800a357fdf1990e0fc, gid: 6sXuVJcafs6Pkg49YFK9ro" Dec 09 20:31:15 volumio go-librespot[1552]: time="2025-12-09T20:31:15+01:00" level=trace msg="found 2 cdn urls" uri="spotify:track:6sXuVJcafs6Pkg49YFK9ro" Dec 09 20:31:16 volumio go-librespot[1552]: time="2025-12-09T20:31:16+01:00" level=debug msg="fetched first chunk of 22, total size is 11179940 bytes" uri="spotify:track:6sXuVJcafs6Pkg49YFK9ro" Dec 09 20:31:16 volumio go-librespot[1552]: time="2025-12-09T20:31:16+01:00" level=info msg="prefetched track \"I Am Beyond\" (duration: 267880ms)" uri="spotify:track:6sXuVJcafs6Pkg49YFK9ro" Dec 09 20:31:16 volumio go-librespot[1552]: time="2025-12-09T20:31:16+01:00" level=debug msg="fetched chunk 1/21, size: 524288" uri="spotify:track:6sXuVJcafs6Pkg49YFK9ro" Dec 09 20:31:16 volumio go-librespot[1552]: time="2025-12-09T20:31:16+01:00" level=debug msg="fetched chunk 3/21, size: 524288" uri="spotify:track:6sXuVJcafs6Pkg49YFK9ro" Dec 09 20:31:17 volumio go-librespot[1552]: time="2025-12-09T20:31:17+01:00" level=debug msg="fetched chunk 2/21, size: 524288" uri="spotify:track:6sXuVJcafs6Pkg49YFK9ro" Dec 09 20:31:38 volumio go-librespot[1552]: time="2025-12-09T20:31:38+01:00" level=trace msg="sent dealer ping" Dec 09 20:31:39 volumio go-librespot[1552]: time="2025-12-09T20:31:39+01:00" level=trace msg="received dealer pong" Dec 09 20:31:39 volumio go-librespot[1552]: time="2025-12-09T20:31:39+01:00" level=trace msg="emitting websocket event: not_playing" Dec 09 20:31:39 volumio go-librespot[1552]: time="2025-12-09T20:31:39+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:6sXuVJcafs6Pkg49YFK9ro" Dec 09 20:31:39 volumio volumio[1283]: SPOTIFY: received: {"type":"not_playing","data":{"context_uri":"spotify:artist:3G5hGmHXhRi8zuIfLAeoPg","uri":"spotify:track:60J5rX4gzm3BnINRI6r5Dh","play_origin":"free-tier-artist"}} Dec 09 20:31:39 volumio volumio[1283]: error: Failed to decode event: not_playing Dec 09 20:31:40 volumio go-librespot[1552]: time="2025-12-09T20:31:40+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 09 20:31:40 volumio go-librespot[1552]: time="2025-12-09T20:31:40+01:00" level=trace msg="emitting websocket event: will_play" Dec 09 20:31:40 volumio go-librespot[1552]: time="2025-12-09T20:31:40+01:00" level=info msg="loaded track \"I Am Beyond\" (paused: false, position: 0ms, duration: 267880ms, prefetched: true)" uri="spotify:track:6sXuVJcafs6Pkg49YFK9ro" Dec 09 20:31:40 volumio volumio[1283]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:artist:3G5hGmHXhRi8zuIfLAeoPg","uri":"spotify:track:6sXuVJcafs6Pkg49YFK9ro","play_origin":"free-tier-artist"}} Dec 09 20:31:40 volumio go-librespot[1552]: time="2025-12-09T20:31:40+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 09 20:31:40 volumio go-librespot[1552]: time="2025-12-09T20:31:40+01:00" level=trace msg="scheduling prefetch in 238s" Dec 09 20:31:40 volumio go-librespot[1552]: time="2025-12-09T20:31:40+01:00" level=trace msg="emitting websocket event: metadata" Dec 09 20:31:40 volumio volumio[1283]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:6sXuVJcafs6Pkg49YFK9ro","name":"I Am Beyond","artist_names":["Black Breath"],"album_name":"Heavy Breathing","album_cover_url":"https://i.scdn.co/image/ab67616d00001e020cc1c64ec0554c93f46428ee","position":0,"duration":267880,"release_date":"year:2010 month:3 day:30","track_number":4,"disc_number":1}} Dec 09 20:31:40 volumio go-librespot[1552]: time="2025-12-09T20:31:40+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 09 20:31:40 volumio go-librespot[1552]: time="2025-12-09T20:31:40+01:00" level=trace msg="emitting websocket event: playing" Dec 09 20:31:40 volumio volumio[1283]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:artist:3G5hGmHXhRi8zuIfLAeoPg","uri":"spotify:track:6sXuVJcafs6Pkg49YFK9ro","resume":false,"play_origin":"free-tier-artist"}} Dec 09 20:31:40 volumio volumio[1283]: SPOTIFY: PUSH STATE SPOTIFY Dec 09 20:31:40 volumio volumio[1283]: SPOTIFY: {"status":"play","service":"spop","title":"I Am Beyond","artist":"Black Breath","album":"Heavy Breathing","albumart":"https://i.scdn.co/image/ab67616d00001e020cc1c64ec0554c93f46428ee","uri":"spotify:track:6sXuVJcafs6Pkg49YFK9ro","trackType":"spotify","seek":0,"duration":267,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Dec 09 20:31:40 volumio volumio[1283]: info: CoreCommandRouter::servicePushState Dec 09 20:31:40 volumio volumio[1283]: info: CoreStateMachine::pushState Dec 09 20:31:40 volumio volumio[1283]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 09 20:31:40 volumio volumio[1283]: info: CoreCommandRouter::volumioPushState Dec 09 20:31:40 volumio volumio[1283]: SPOTIFY: PUSH STATE SPOTIFY Dec 09 20:31:40 volumio volumio[1283]: SPOTIFY: {"status":"play","service":"spop","title":"I Am Beyond","artist":"Black Breath","album":"Heavy Breathing","albumart":"https://i.scdn.co/image/ab67616d00001e020cc1c64ec0554c93f46428ee","uri":"spotify:track:6sXuVJcafs6Pkg49YFK9ro","trackType":"spotify","seek":0,"duration":267,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Dec 09 20:31:40 volumio volumio[1283]: info: CoreCommandRouter::servicePushState Dec 09 20:31:40 volumio volumio[1283]: info: CoreStateMachine::pushState Dec 09 20:31:40 volumio volumio[1283]: info: CoreCommandRouter::volumioPushState Dec 09 20:31:50 volumio volumio[1283]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 09 20:31:50 volumio volumio[1283]: ConnectionError: Connection error in fetching pairing code Dec 09 20:31:50 volumio volumio[1283]: at PairingCodeRequestService._PairingCodeRequestService_getCodeAndEmit (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/lib/app/PairingCodeRequestService.js:126:17) Dec 09 20:31:50 volumio volumio[1283]: at process.processTicksAndRejections (node:internal/process/task_queues:95:5) { Dec 09 20:31:50 volumio volumio[1283]: cause: TypeError: fetch failed Dec 09 20:31:50 volumio volumio[1283]: at Object.fetch (node:internal/deps/undici/undici:11576:11) Dec 09 20:31:50 volumio volumio[1283]: at process.processTicksAndRejections (node:internal/process/task_queues:95:5) Dec 09 20:31:50 volumio volumio[1283]: at async PairingCodeRequestService._PairingCodeRequestService_getCodeAndEmit (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/lib/app/PairingCodeRequestService.js:120:20) { Dec 09 20:31:50 volumio volumio[1283]: cause: ConnectTimeoutError: Connect Timeout Error (attempted address: www.youtube.com:443, timeout: 10000ms) Dec 09 20:31:50 volumio volumio[1283]: at onConnectTimeout (/data/plugins/music_service/bandcamp/node_modules/undici/lib/core/connect.js:237:24) Dec 09 20:31:50 volumio volumio[1283]: at Immediate._onImmediate (/data/plugins/music_service/bandcamp/node_modules/undici/lib/core/connect.js:206:11) Dec 09 20:31:50 volumio volumio[1283]: at process.processImmediate (node:internal/timers:478:21) { Dec 09 20:31:50 volumio volumio[1283]: code: 'UND_ERR_CONNECT_TIMEOUT' Dec 09 20:31:50 volumio volumio[1283]: } Dec 09 20:31:50 volumio volumio[1283]: }, Dec 09 20:31:50 volumio volumio[1283]: info: { Dec 09 20:31:50 volumio volumio[1283]: url: 'https://www.youtube.com/api/lounge/pairing/get_pairing_code?ctx=pair' Dec 09 20:31:50 volumio volumio[1283]: } Dec 09 20:31:50 volumio volumio[1283]: } Dec 09 20:31:50 volumio volumio[1283]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 09 20:31:50 volumio sudo[18253]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-09 20:30' Dec 09 20:31:50 volumio sudo[18253]: 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"