-- Logs begin at Thu 2019-02-14 11:11:59 CET, end at Sat 2026-08-29 21:56:41 CEST. -- Aug 29 21:55:03 volumio kernel: brcmfmac: brcmf_set_channel: set chanspec 0x100e fail, reason -52 Aug 29 21:55:03 volumio kernel: brcmfmac: brcmf_set_channel: set chanspec 0xd022 fail, reason -52 Aug 29 21:55:03 volumio kernel: brcmfmac: brcmf_set_channel: set chanspec 0xd026 fail, reason -52 Aug 29 21:55:04 volumio kernel: brcmfmac: brcmf_set_channel: set chanspec 0xd02a fail, reason -52 Aug 29 21:55:04 volumio kernel: brcmfmac: brcmf_set_channel: set chanspec 0xd02e fail, reason -52 Aug 29 21:55:05 volumio kernel: brcmfmac: brcmf_set_channel: set chanspec 0xd090 fail, reason -52 Aug 29 21:55:05 volumio kernel: brcmfmac: brcmf_set_channel: set chanspec 0xd095 fail, reason -52 Aug 29 21:55:05 volumio kernel: brcmfmac: brcmf_set_channel: set chanspec 0xd099 fail, reason -52 Aug 29 21:55:05 volumio kernel: brcmfmac: brcmf_set_channel: set chanspec 0xd09d fail, reason -52 Aug 29 21:55:05 volumio kernel: brcmfmac: brcmf_set_channel: set chanspec 0xd0a1 fail, reason -52 Aug 29 21:55:05 volumio kernel: brcmfmac: brcmf_set_channel: set chanspec 0xd0a5 fail, reason -52 Aug 29 21:55:06 volumio dhcpcd[922]: wlan1: carrier acquired Aug 29 21:55:06 volumio dhcpcd[922]: wlan1: IAID eb:af:45:48 Aug 29 21:55:06 volumio systemd-udevd[1779]: Process '/sbin/crda' failed with exit code 255. Aug 29 21:55:06 volumio dhcpcd[922]: wlan1: soliciting an IPv6 router Aug 29 21:55:06 volumio dhcpcd[922]: wlan1: rebinding lease of 192.168.178.20 Aug 29 21:55:06 volumio dhcpcd[922]: wlan1: probing address 192.168.178.20/24 Aug 29 21:55:09 volumio wpa_supplicant[894]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=CORE type=WORLD Aug 29 21:55:10 volumio systemd[1]: systemd-timedated.service: Succeeded. Aug 29 21:55:11 volumio volumio[1006]: error: MyVolumio got a network error: A network error (such as timeout, interrupted connection or unreachable host) has occurred. Aug 29 21:55:11 volumio volumio[1006]: info: Retrying Login Due to Network Error Aug 29 21:55:12 volumio dhcpcd[922]: wlan1: leased 192.168.178.20 for 3600 seconds Aug 29 21:55:12 volumio avahi-daemon[646]: Joining mDNS multicast group on interface wlan1.IPv4 with address 192.168.178.20. Aug 29 21:55:12 volumio dhcpcd[922]: wlan1: adding route to 192.168.178.0/24 Aug 29 21:55:12 volumio dhcpcd[922]: wlan1: adding default route via 192.168.178.1 Aug 29 21:55:12 volumio avahi-daemon[646]: New relevant interface wlan1.IPv4 for mDNS. Aug 29 21:55:12 volumio avahi-daemon[646]: Registering new address record for 192.168.178.20 on wlan1.IPv4. Aug 29 21:55:12 volumio go-librespot[1589]: time="2026-08-29T21:55:12+02:00" level=trace msg="sent dealer ping" Aug 29 21:55:14 volumio ntpd[783]: Listen normally on 5 wlan1 192.168.178.20:123 Aug 29 21:55:14 volumio ntpd[783]: new interface(s) found: waking up resolver Aug 29 21:55:21 volumio volumio[1006]: info: MyVolumio login type: Token Aug 29 21:55:23 volumio volumio[1364]: ..................................................................................................................................++++ Aug 29 21:55:23 volumio volumio[1364]: e is 65537 (0x010001) Aug 29 21:55:23 volumio volumio[1364]: writing RSA key Aug 29 21:55:42 volumio go-librespot[1589]: time="2026-08-29T21:55:42+02:00" level=trace msg="sent dealer ping" Aug 29 21:55:51 volumio volumio[1006]: error: MyVolumio got a network error: A network error (such as timeout, interrupted connection or unreachable host) has occurred. Aug 29 21:55:51 volumio volumio[1006]: info: Retrying Login Due to Network Error Aug 29 21:55:58 volumio ntpd[783]: error resolving pool 1.debian.pool.ntp.org: System error (-11) Aug 29 21:56:01 volumio volumio[1006]: info: MyVolumio login type: Token Aug 29 21:56:12 volumio go-librespot[1589]: time="2026-08-29T21:56:12+02:00" level=error msg="did not receive last pong from dealer, 60s passed" Aug 29 21:56:24 volumio go-librespot[1589]: time="2026-08-29T21:56:24+02:00" level=warning msg="failed creating chunked reader, trying next url" error="failed requesting first chunk: Get \"https://audio4-fa.scdn.co/audio/6267cc828fea06d82dcdf60170446119c75e6a88?1788119685_03Hxoq7QzysfOulmZsrMqNkba6FzR2n7jpdzkLXIUK8=\": dial tcp: lookup audio4-fa.scdn.co: device or resource busy" host=audio4-fa.scdn.co uri="spotify:track:7JgNAnCjJvL8hBR1kmCOFF" Aug 29 21:56:26 volumio ntpd[783]: error resolving pool 0.debian.pool.ntp.org: System error (-11) Aug 29 21:56:31 volumio volumio[1006]: error: MyVolumio got a network error: A network error (such as timeout, interrupted connection or unreachable host) has occurred. Aug 29 21:56:31 volumio volumio[1006]: info: Retrying Login Due to Network Error Aug 29 21:56:35 volumio volumio[1006]: info: Discovery: adding 72d67098-c795-4cb6-a34a-e861d1ae83d1 Aug 29 21:56:35 volumio volumio[1006]: info: Discovery: Found device Volumio Aug 29 21:56:35 volumio volumio[1006]: info: CoreCommandRouter::volumioGetState Aug 29 21:56:35 volumio volumio[1006]: info: CorePlayQueue::getTrack 0 Aug 29 21:56:35 volumio volumio[1006]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 Aug 29 21:56:36 volumio volumio[1006]: info: Discovery: this is already registered, 72d67098-c795-4cb6-a34a-e861d1ae83d1 Aug 29 21:56:36 volumio volumio[1006]: info: Discovery: Found device Volumio Aug 29 21:56:36 volumio volumio[1006]: info: CoreCommandRouter::volumioGetState Aug 29 21:56:36 volumio volumio[1006]: info: CorePlayQueue::getTrack 0 Aug 29 21:56:39 volumio go-librespot[1589]: time="2026-08-29T21:56:39+02:00" level=debug msg="fetched first chunk of 20, total size is 10110312 bytes" uri="spotify:track:7JgNAnCjJvL8hBR1kmCOFF" Aug 29 21:56:39 volumio go-librespot[1589]: time="2026-08-29T21:56:39+02:00" level=debug msg="fetched chunk 1/19, size: 524288" uri="spotify:track:7JgNAnCjJvL8hBR1kmCOFF" Aug 29 21:56:39 volumio go-librespot[1589]: time="2026-08-29T21:56:39+02:00" level=debug msg="fetched chunk 2/19, size: 524288" uri="spotify:track:7JgNAnCjJvL8hBR1kmCOFF" Aug 29 21:56:39 volumio go-librespot[1589]: time="2026-08-29T21:56:39+02:00" level=debug msg="fetched chunk 3/19, size: 524288" uri="spotify:track:7JgNAnCjJvL8hBR1kmCOFF" Aug 29 21:56:39 volumio go-librespot[1589]: time="2026-08-29T21:56:39+02:00" level=trace msg="seek to 48654ms (diff: 161ms, samples: 2145641, bytes: 1776227)" uri="spotify:track:7JgNAnCjJvL8hBR1kmCOFF" Aug 29 21:56:39 volumio go-librespot[1589]: time="2026-08-29T21:56:39+02:00" level=debug msg="created new output device" Aug 29 21:56:39 volumio go-librespot[1589]: time="2026-08-29T21:56:39+02:00" level=info msg="loaded track \"Worth It.\" (paused: true, position: 48654ms, duration: 246813ms, prefetched: false)" uri="spotify:track:7JgNAnCjJvL8hBR1kmCOFF" Aug 29 21:56:39 volumio go-librespot[1589]: time="2026-08-29T21:56:39+02:00" level=error msg="failed put state after update" error="context deadline exceeded" Aug 29 21:56:39 volumio go-librespot[1589]: time="2026-08-29T21:56:39+02:00" level=trace msg="emitting websocket event: metadata" Aug 29 21:56:39 volumio go-librespot[1589]: time="2026-08-29T21:56:39+02:00" level=trace msg="emitting websocket event: active" Aug 29 21:56:39 volumio go-librespot[1589]: time="2026-08-29T21:56:39+02:00" level=debug msg="sending successful reply for dealer request" Aug 29 21:56:39 volumio volumio[1006]: info: Aligning Spotify Volume to Volumio Volume Aug 29 21:56:39 volumio volumio[1006]: info: CoreCommandRouter::volumioGetState Aug 29 21:56:39 volumio volumio[1006]: info: CorePlayQueue::getTrack 0 Aug 29 21:56:39 volumio volumio[1006]: info: Setting Spotify Volume from Volumio: 83 Aug 29 21:56:39 volumio go-librespot[1589]: time="2026-08-29T21:56:39+02:00" level=error msg="failed sending dealer reply" error="failed sending dealer reply: failed to write msg: use of closed network connection" uri="hm://connect-state/v1/player/command" Aug 29 21:56:39 volumio go-librespot[1589]: time="2026-08-29T21:56:39+02:00" level=error msg="failed receiving dealer message" error="failed to get reader: use of closed network connection" Aug 29 21:56:39 volumio go-librespot[1589]: time="2026-08-29T21:56:39+02:00" level=debug msg="fetched chunk 6/19, size: 524288" uri="spotify:track:7JgNAnCjJvL8hBR1kmCOFF" Aug 29 21:56:40 volumio go-librespot[1589]: time="2026-08-29T21:56:40+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 29 21:56:40 volumio go-librespot[1589]: time="2026-08-29T21:56:40+02:00" level=trace msg="emitting websocket event: paused" Aug 29 21:56:40 volumio volumio[1006]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 29 21:56:40 volumio go-librespot[1589]: time="2026-08-29T21:56:40+02:00" level=debug msg="fetched chunk 5/19, size: 524288" uri="spotify:track:7JgNAnCjJvL8hBR1kmCOFF" Aug 29 21:56:40 volumio go-librespot[1589]: time="2026-08-29T21:56:40+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1240" Aug 29 21:56:40 volumio go-librespot[1589]: time="2026-08-29T21:56:40+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 435" Aug 29 21:56:40 volumio volumio[1006]: TypeError: Cannot read property 'service' of undefined Aug 29 21:56:40 volumio volumio[1006]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:345:50) Aug 29 21:56:40 volumio volumio[1006]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:279:18) Aug 29 21:56:40 volumio volumio[1006]: at WebSocket.message (/data/plugins/music_service/spop/index.js:198:14) Aug 29 21:56:40 volumio volumio[1006]: at WebSocket.emit (events.js:315:20) Aug 29 21:56:40 volumio volumio[1006]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1225:20) Aug 29 21:56:40 volumio volumio[1006]: at Receiver.emit (events.js:315:20) Aug 29 21:56:40 volumio volumio[1006]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Aug 29 21:56:40 volumio volumio[1006]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Aug 29 21:56:40 volumio volumio[1006]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Aug 29 21:56:40 volumio volumio[1006]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Aug 29 21:56:40 volumio volumio[1006]: at writeOrBuffer (internal/streams/writable.js:358:12) Aug 29 21:56:40 volumio volumio[1006]: at Receiver.Writable.write (internal/streams/writable.js:303:10) Aug 29 21:56:40 volumio volumio[1006]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1360:35) Aug 29 21:56:40 volumio volumio[1006]: at Socket.emit (events.js:315:20) Aug 29 21:56:40 volumio volumio[1006]: at addChunk (internal/streams/readable.js:309:12) Aug 29 21:56:40 volumio volumio[1006]: at readableAddChunk (internal/streams/readable.js:284:9) Aug 29 21:56:40 volumio volumio[1006]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 29 21:56:40 volumio go-librespot[1589]: time="2026-08-29T21:56:40+02:00" level=debug msg="fetched chunk 4/19, size: 524288" uri="spotify:track:7JgNAnCjJvL8hBR1kmCOFF" Aug 29 21:56:40 volumio ntpd[783]: Soliciting pool server 192.42.116.40 Aug 29 21:56:40 volumio go-librespot[1589]: time="2026-08-29T21:56:40+02:00" level=debug msg="dealer connection opened" Aug 29 21:56:40 volumio go-librespot[1589]: time="2026-08-29T21:56:40+02:00" level=debug msg="re-established dealer connection" Aug 29 21:56:40 volumio go-librespot[1589]: time="2026-08-29T21:56:40+02:00" level=debug msg="received connection id: YTllNWNiOGQtODBm...OEFDNzM4MUY5Qw==" Aug 29 21:56:40 volumio ntpd[783]: Soliciting pool server 193.123.56.220 Aug 29 21:56:40 volumio ntpd[783]: Soliciting pool server 212.34.149.56 Aug 29 21:56:40 volumio go-librespot[1589]: time="2026-08-29T21:56:40+02:00" level=debug msg="put connect state because NEW_DEVICE" Aug 29 21:56:40 volumio ntpd[783]: Soliciting pool server 192.42.116.10 Aug 29 21:56:40 volumio ntpd[783]: Soliciting pool server 192.42.116.140 Aug 29 21:56:40 volumio ntpd[783]: Soliciting pool server 195.123.221.21 Aug 29 21:56:41 volumio ntpd[783]: Soliciting pool server 195.35.113.80 Aug 29 21:56:41 volumio ntpd[783]: Soliciting pool server 178.239.19.56 Aug 29 21:56:41 volumio ntpd[783]: Soliciting pool server 178.239.19.58 Aug 29 21:56:41 volumio sudo[2053]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2026-08-29 21:55 Aug 29 21:56:41 volumio sudo[2053]: 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"