-- Logs begin at Sun 2026-06-28 16:05:32 CEST, end at Sun 2026-08-30 15:14:41 CEST. -- Aug 30 15:13:11 volumio go-librespot[1455]: time="2026-08-30T15:13:11+02:00" level=debug msg="fetched chunk 16/19, size: 524288" uri="spotify:track:5Mmk2ii6laakqfeCT7OnVD" Aug 30 15:13:13 volumio autossh[15071]: starting ssh (count 10) Aug 30 15:13:13 volumio autossh[15071]: ssh child pid is 15298 Aug 30 15:13:13 volumio volumiossh-tunnel[15070]: ssh: connect to host eu9.myvolumio.org port 2222: Connection refused Aug 30 15:13:13 volumio autossh[15071]: ssh exited with error status 255; restarting ssh Aug 30 15:13:14 volumio go-librespot[1455]: time="2026-08-30T15:13:14+02:00" level=trace msg="received accesspoint ping" Aug 30 15:13:14 volumio go-librespot[1455]: time="2026-08-30T15:13:14+02:00" level=trace msg="received accesspoint pong ack" Aug 30 15:13:14 volumio go-librespot[1455]: time="2026-08-30T15:13:14+02:00" level=trace msg="sent dealer ping" Aug 30 15:13:14 volumio go-librespot[1455]: time="2026-08-30T15:13:14+02:00" level=trace msg="received dealer pong" Aug 30 15:13:24 volumio go-librespot[1455]: time="2026-08-30T15:13:24+02:00" level=debug msg="fetched chunk 17/19, size: 524288" uri="spotify:track:5Mmk2ii6laakqfeCT7OnVD" Aug 30 15:13:36 volumio go-librespot[1455]: time="2026-08-30T15:13:36+02:00" level=debug msg="fetched chunk 18/19, size: 524288" uri="spotify:track:5Mmk2ii6laakqfeCT7OnVD" Aug 30 15:13:44 volumio go-librespot[1455]: time="2026-08-30T15:13:44+02:00" level=trace msg="sent dealer ping" Aug 30 15:13:44 volumio go-librespot[1455]: time="2026-08-30T15:13:44+02:00" level=trace msg="received dealer pong" Aug 30 15:13:45 volumio autossh[15071]: starting ssh (count 11) Aug 30 15:13:45 volumio autossh[15071]: ssh child pid is 15345 Aug 30 15:13:49 volumio go-librespot[1455]: time="2026-08-30T15:13:49+02:00" level=debug msg="fetched chunk 19/19, size: 448664" uri="spotify:track:5Mmk2ii6laakqfeCT7OnVD" Aug 30 15:14:05 volumio volumiossh-tunnel[15070]: Warning: Permanently added '[eu9.myvolumio.org]:2222,[164.92.213.40]:2222' (RSA) to the list of known hosts. Aug 30 15:14:14 volumio go-librespot[1455]: time="2026-08-30T15:14:14+02:00" level=trace msg="sent dealer ping" Aug 30 15:14:14 volumio go-librespot[1455]: time="2026-08-30T15:14:14+02:00" level=trace msg="received dealer pong" Aug 30 15:14:41 volumio go-librespot[1455]: time="2026-08-30T15:14:41+02:00" level=trace msg="emitting websocket event: not_playing" Aug 30 15:14:41 volumio go-librespot[1455]: time="2026-08-30T15:14:41+02:00" level=debug msg="loading track (paused: true, position: 0ms)" uri="spotify:track:5Mmk2ii6laakqfeCT7OnVD" Aug 30 15:14:41 volumio volumio[1056]: error: Failed to decode event: not_playing Aug 30 15:14:41 volumio go-librespot[1455]: time="2026-08-30T15:14:41+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 30 15:14:41 volumio go-librespot[1455]: time="2026-08-30T15:14:41+02:00" level=trace msg="emitting websocket event: will_play" Aug 30 15:14:41 volumio go-librespot[1455]: time="2026-08-30T15:14:41+02:00" level=debug msg="selected format OGG_VORBIS_320 (8e175c149054a2cadc6a1765445abf7ef975616f)" uri="spotify:track:5Mmk2ii6laakqfeCT7OnVD" Aug 30 15:14:41 volumio go-librespot[1455]: time="2026-08-30T15:14:41+02:00" level=debug msg="requested aes key for file 8e175c149054a2cadc6a1765445abf7ef975616f, gid: 5Mmk2ii6laakqfeCT7OnVD" Aug 30 15:14:41 volumio volumio[1056]: info: Tunnel connection is inactive, restarting it Aug 30 15:14:41 volumio volumio[1056]: info: Starting Tunnel 1 Aug 30 15:14:41 volumio volumio[1056]: info: Starting Tunnel Connection Checker Aug 30 15:14:41 volumio go-librespot[1455]: time="2026-08-30T15:14:41+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:5Mmk2ii6laakqfeCT7OnVD" Aug 30 15:14:41 volumio go-librespot[1455]: time="2026-08-30T15:14:41+02:00" level=debug msg="fetched first chunk of 20, total size is 10410136 bytes" uri="spotify:track:5Mmk2ii6laakqfeCT7OnVD" Aug 30 15:14:41 volumio go-librespot[1455]: time="2026-08-30T15:14:41+02:00" level=info msg="loaded track \"Thong Song\" (paused: true, position: 0ms, duration: 253733ms, prefetched: false)" uri="spotify:track:5Mmk2ii6laakqfeCT7OnVD" Aug 30 15:14:41 volumio sudo[15481]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart sshtunnel.service Aug 30 15:14:41 volumio sudo[15481]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 30 15:14:41 volumio autossh[15071]: received signal to exit (15) Aug 30 15:14:41 volumio systemd[1]: Stopping MyVolumio SSH Tunnel... Aug 30 15:14:41 volumio systemd[1]: sshtunnel.service: Main process exited, code=killed, status=15/TERM Aug 30 15:14:41 volumio systemd[1]: sshtunnel.service: Succeeded. Aug 30 15:14:41 volumio systemd[1]: Stopped MyVolumio SSH Tunnel. Aug 30 15:14:41 volumio volumio[1056]: ------------------------------------ BT MESSAGE: BT STATUS: running Aug 30 15:14:41 volumio volumio[1056]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Aug 30 15:14:41 volumio go-librespot[1455]: time="2026-08-30T15:14:41+02:00" level=debug msg="fetched chunk 1/19, size: 524288" uri="spotify:track:5Mmk2ii6laakqfeCT7OnVD" Aug 30 15:14:41 volumio go-librespot[1455]: time="2026-08-30T15:14:41+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 30 15:14:41 volumio go-librespot[1455]: time="2026-08-30T15:14:41+02:00" level=trace msg="emitting websocket event: metadata" Aug 30 15:14:41 volumio go-librespot[1455]: time="2026-08-30T15:14:41+02:00" level=trace msg="emitting websocket event: stopped" Aug 30 15:14:41 volumio volumio[1056]: info: CoreCommandRouter::servicePushState Aug 30 15:14:41 volumio volumio[1056]: info: CoreStateMachine::pushState Aug 30 15:14:41 volumio volumio[1056]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 30 15:14:41 volumio volumio[1056]: info: CoreCommandRouter::volumioPushState Aug 30 15:14:41 volumio volumio[1056]: info: MRS: Pushing multiroomSync output update for this device Aug 30 15:14:41 volumio volumio[1056]: info: MRS: Pushing multiroomSync output Aug 30 15:14:41 volumio volumio[1056]: info: CoreCommandRouter::volumioGetState Aug 30 15:14:41 volumio volumio[1056]: info: CorePlayQueue::getTrack 0 Aug 30 15:14:41 volumio volumio[1056]: verbose: STATE SERVICE {"status":"stop","service":"spop","title":"Thong Song","artist":"Sisqo","album":"Unleash The Dragon","albumart":"https://i.scdn.co/image/ab67616d00001e02227393028d2b83ced8e74d9b","uri":"spotify:track:5Mmk2ii6laakqfeCT7OnVD","trackType":"spotify","seek":0,"duration":253,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":true,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Aug 30 15:14:41 volumio volumio[1056]: verbose: CURRENT POSITION 0 Aug 30 15:14:41 volumio volumio[1056]: info: CoreStateMachine::syncState stateService stop Aug 30 15:14:41 volumio volumio[1056]: info: CoreStateMachine::syncState currentStatus play Aug 30 15:14:41 volumio volumio[1056]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 30 15:14:41 volumio volumio[1056]: TypeError: Cannot read property 'service' of null Aug 30 15:14:41 volumio volumio[1056]: at CoreStateMachine.syncState (/volumio/app/statemachine.js:820:50) Aug 30 15:14:41 volumio volumio[1056]: at CoreCommandRouter.servicePushState (/volumio/app/index.js:414:28) Aug 30 15:14:41 volumio volumio[1056]: at ControllerSpotify.pushState (/data/plugins/music_service/spop/index.js:431:31) Aug 30 15:14:41 volumio volumio[1056]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:328:14) Aug 30 15:14:41 volumio volumio[1056]: at WebSocket.message (/data/plugins/music_service/spop/index.js:198:14) Aug 30 15:14:41 volumio volumio[1056]: at WebSocket.emit (events.js:315:20) Aug 30 15:14:41 volumio volumio[1056]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1225:20) Aug 30 15:14:41 volumio volumio[1056]: at Receiver.emit (events.js:315:20) Aug 30 15:14:41 volumio volumio[1056]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Aug 30 15:14:41 volumio volumio[1056]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Aug 30 15:14:41 volumio volumio[1056]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Aug 30 15:14:41 volumio volumio[1056]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Aug 30 15:14:41 volumio volumio[1056]: at writeOrBuffer (internal/streams/writable.js:358:12) Aug 30 15:14:41 volumio volumio[1056]: at Receiver.Writable.write (internal/streams/writable.js:303:10) Aug 30 15:14:41 volumio volumio[1056]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1360:35) Aug 30 15:14:41 volumio volumio[1056]: at Socket.emit (events.js:315:20) Aug 30 15:14:41 volumio volumio[1056]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 30 15:14:41 volumio systemd[1]: Started MyVolumio SSH Tunnel. Aug 30 15:14:41 volumio sudo[15481]: pam_unix(sudo:session): session closed for user root Aug 30 15:14:41 volumio autossh[15485]: port set to 0, monitoring disabled Aug 30 15:14:41 volumio autossh[15485]: starting ssh (count 1) Aug 30 15:14:41 volumio autossh[15485]: ssh child pid is 15489 Aug 30 15:14:41 volumio go-librespot[1455]: time="2026-08-30T15:14:41+02:00" level=debug msg="fetched chunk 2/19, size: 524288" uri="spotify:track:5Mmk2ii6laakqfeCT7OnVD" Aug 30 15:14:41 volumio go-librespot[1455]: time="2026-08-30T15:14:41+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 30 15:14:41 volumio go-librespot[1455]: time="2026-08-30T15:14:41+02:00" level=trace msg="emitting websocket event: paused" Aug 30 15:14:41 volumio go-librespot[1455]: time="2026-08-30T15:14:41+02:00" level=debug msg="fetched chunk 3/19, size: 524288" uri="spotify:track:5Mmk2ii6laakqfeCT7OnVD" Aug 30 15:14:41 volumio volumiossh-tunnel[15483]: Warning: Permanently added '[eu9.myvolumio.org]:2222,[164.92.213.40]:2222' (RSA) to the list of known hosts. Aug 30 15:14:41 volumio sudo[15498]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2026-08-30 15:13 Aug 30 15:14:41 volumio sudo[15498]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster 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="e9612ec5034fb2e958508aaefbca2962fd6f6654" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="464fc672d77d3df6ee72b331d36cdf1fa936e1ec" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri 27 Feb 2026 10:59:40 AM CET" VOLUMIO_VERSION="3.912" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="37c6ab864cb114e1344d540995c69f86"