Jan 26 08:15:11 volumio go-librespot[1864]: time="2026-01-26T08:15:11-05:00" level=debug msg="prefetching next track" uri="spotify:track:6GSw4N2JiUEZgflck1NV1P" Jan 26 08:15:11 volumio go-librespot[1864]: time="2026-01-26T08:15:11-05:00" level=debug msg="selected format OGG_VORBIS_320 (e56707f492b1cc173ffd58decc65b0fc4ad0c6b8)" uri="spotify:track:6GSw4N2JiUEZgflck1NV1P" Jan 26 08:15:11 volumio go-librespot[1864]: time="2026-01-26T08:15:11-05:00" level=debug msg="requested aes key for file e56707f492b1cc173ffd58decc65b0fc4ad0c6b8, gid: 6GSw4N2JiUEZgflck1NV1P" Jan 26 08:15:11 volumio go-librespot[1864]: time="2026-01-26T08:15:11-05:00" level=trace msg="found 2 cdn urls" uri="spotify:track:6GSw4N2JiUEZgflck1NV1P" Jan 26 08:15:11 volumio go-librespot[1864]: time="2026-01-26T08:15:11-05:00" level=debug msg="fetched first chunk of 19, total size is 9713737 bytes" uri="spotify:track:6GSw4N2JiUEZgflck1NV1P" Jan 26 08:15:11 volumio go-librespot[1864]: time="2026-01-26T08:15:11-05:00" level=info msg="prefetched track \"Cape Forestier\" (duration: 232725ms)" uri="spotify:track:6GSw4N2JiUEZgflck1NV1P" Jan 26 08:15:11 volumio go-librespot[1864]: time="2026-01-26T08:15:11-05:00" level=debug msg="fetched chunk 1/18, size: 524288" uri="spotify:track:6GSw4N2JiUEZgflck1NV1P" Jan 26 08:15:11 volumio go-librespot[1864]: time="2026-01-26T08:15:11-05:00" level=debug msg="fetched chunk 3/18, size: 524288" uri="spotify:track:6GSw4N2JiUEZgflck1NV1P" Jan 26 08:15:11 volumio go-librespot[1864]: time="2026-01-26T08:15:11-05:00" level=debug msg="fetched chunk 2/18, size: 524288" uri="spotify:track:6GSw4N2JiUEZgflck1NV1P" Jan 26 08:15:11 volumio go-librespot[1864]: time="2026-01-26T08:15:11-05:00" level=trace msg="sent dealer ping" Jan 26 08:15:11 volumio go-librespot[1864]: time="2026-01-26T08:15:11-05:00" level=trace msg="received dealer pong" Jan 26 08:15:19 volumio volumio[1011]: info: CoreCommandRouter::volumioGetQueue Jan 26 08:15:19 volumio volumio[1011]: info: CoreStateMachine::getQueue Jan 26 08:15:19 volumio volumio[1011]: info: CorePlayQueue::getQueue Jan 26 08:15:32 volumio volumio[1011]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jan 26 08:15:32 volumio volumio[1011]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Jan 26 08:15:39 volumio volumio[1011]: info: CoreCommandRouter::getUIConfigOnPlugin Jan 26 08:15:40 volumio go-librespot[1864]: time="2026-01-26T08:15:40-05:00" level=trace msg="emitting websocket event: not_playing" Jan 26 08:15:40 volumio go-librespot[1864]: time="2026-01-26T08:15:40-05:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:6GSw4N2JiUEZgflck1NV1P" Jan 26 08:15:40 volumio volumio[1011]: SPOTIFY: received: {"type":"not_playing","data":{"context_uri":"spotify:user:31o5ayu5ns4dvru32krdrrebskym:collection","uri":"spotify:track:4YzF1S6hPBqkMv40lomByE","play_origin":"collection/songs"}} Jan 26 08:15:40 volumio volumio[1011]: error: Failed to decode event: not_playing Jan 26 08:15:40 volumio go-librespot[1864]: time="2026-01-26T08:15:40-05:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 26 08:15:40 volumio go-librespot[1864]: time="2026-01-26T08:15:40-05:00" level=trace msg="emitting websocket event: will_play" Jan 26 08:15:40 volumio go-librespot[1864]: time="2026-01-26T08:15:40-05:00" level=info msg="loaded track \"Cape Forestier\" (paused: false, position: 0ms, duration: 232725ms, prefetched: true)" uri="spotify:track:6GSw4N2JiUEZgflck1NV1P" Jan 26 08:15:40 volumio volumio[1011]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:user:31o5ayu5ns4dvru32krdrrebskym:collection","uri":"spotify:track:6GSw4N2JiUEZgflck1NV1P","play_origin":"collection/songs"}} Jan 26 08:15:40 volumio go-librespot[1864]: time="2026-01-26T08:15:40-05:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 26 08:15:40 volumio go-librespot[1864]: time="2026-01-26T08:15:40-05:00" level=trace msg="scheduling prefetch in 203s" Jan 26 08:15:40 volumio go-librespot[1864]: time="2026-01-26T08:15:40-05:00" level=trace msg="emitting websocket event: metadata" Jan 26 08:15:40 volumio volumio[1011]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:6GSw4N2JiUEZgflck1NV1P","name":"Cape Forestier","artist_names":["Angus \u0026 Julia Stone"],"album_name":"Cape Forestier","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02bbadd17c4a95e87130a8caf4","position":0,"duration":232725,"release_date":"year:2024 month:5 day:10","track_number":4,"disc_number":1}} Jan 26 08:15:40 volumio go-librespot[1864]: time="2026-01-26T08:15:40-05:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 26 08:15:40 volumio go-librespot[1864]: time="2026-01-26T08:15:40-05:00" level=trace msg="emitting websocket event: playing" Jan 26 08:15:40 volumio volumio[1011]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:user:31o5ayu5ns4dvru32krdrrebskym:collection","uri":"spotify:track:6GSw4N2JiUEZgflck1NV1P","resume":false,"play_origin":"collection/songs"}} Jan 26 08:15:40 volumio volumio[1011]: SPOTIFY: PUSH STATE SPOTIFY Jan 26 08:15:40 volumio volumio[1011]: SPOTIFY: {"status":"play","service":"spop","title":"Cape Forestier","artist":"Angus & Julia Stone","album":"Cape Forestier","albumart":"https://i.scdn.co/image/ab67616d00001e02bbadd17c4a95e87130a8caf4","uri":"spotify:track:6GSw4N2JiUEZgflck1NV1P","trackType":"spotify","seek":0,"duration":232,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Jan 26 08:15:40 volumio volumio[1011]: info: CoreCommandRouter::servicePushState Jan 26 08:15:40 volumio volumio[1011]: info: CoreStateMachine::pushState Jan 26 08:15:40 volumio volumio[1011]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 26 08:15:40 volumio volumio[1011]: info: CoreCommandRouter::volumioPushState Jan 26 08:15:41 volumio volumio[1011]: SPOTIFY: PUSH STATE SPOTIFY Jan 26 08:15:41 volumio volumio[1011]: SPOTIFY: {"status":"play","service":"spop","title":"Cape Forestier","artist":"Angus & Julia Stone","album":"Cape Forestier","albumart":"https://i.scdn.co/image/ab67616d00001e02bbadd17c4a95e87130a8caf4","uri":"spotify:track:6GSw4N2JiUEZgflck1NV1P","trackType":"spotify","seek":0,"duration":232,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Jan 26 08:15:41 volumio volumio[1011]: info: CoreCommandRouter::servicePushState Jan 26 08:15:41 volumio volumio[1011]: info: CoreStateMachine::pushState Jan 26 08:15:41 volumio volumio[1011]: info: CoreCommandRouter::volumioPushState Jan 26 08:15:41 volumio go-librespot[1864]: time="2026-01-26T08:15:41-05:00" level=trace msg="received accesspoint ping" Jan 26 08:15:41 volumio go-librespot[1864]: time="2026-01-26T08:15:41-05:00" level=trace msg="received accesspoint pong ack" Jan 26 08:15:41 volumio go-librespot[1864]: time="2026-01-26T08:15:41-05:00" level=trace msg="sent dealer ping" Jan 26 08:15:41 volumio go-librespot[1864]: time="2026-01-26T08:15:41-05:00" level=trace msg="received dealer pong" Jan 26 08:15:51 volumio volumio[1011]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Jan 26 08:15:51 volumio volumio[1011]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Jan 26 08:15:51 volumio volumio[1011]: info: Creating Spotify config file Jan 26 08:15:51 volumio volumio[1011]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 26 08:15:51 volumio volumio[1011]: info: Spotify config file written Jan 26 08:15:51 volumio sudo[4906]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 26 08:15:51 volumio sudo[4906]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 26 08:15:51 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jan 26 08:15:51 volumio volumio[1011]: info: Connection to go-librespot Websocket closed Jan 26 08:15:51 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jan 26 08:15:51 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 26 08:15:51 volumio systemd[1]: go-librespot-daemon.service: Consumed 41.485s CPU time. Jan 26 08:15:51 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 26 08:15:51 volumio go-librespot[4917]: go-librespot daemon starting... Jan 26 08:15:51 volumio sudo[4906]: pam_unix(sudo:session): session closed for user root Jan 26 08:15:51 volumio go-librespot[4925]: time="2026-01-26T08:15:51-05:00" level=info msg="running go-librespot 0.6.2" Jan 26 08:15:51 volumio go-librespot[4925]: time="2026-01-26T08:15:51-05:00" level=debug msg="app state loaded" Jan 26 08:15:51 volumio go-librespot[4925]: time="2026-01-26T08:15:51-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 26 08:15:52 volumio go-librespot[4925]: time="2026-01-26T08:15:52-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 26 08:15:52 volumio go-librespot[4925]: time="2026-01-26T08:15:52-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 26 08:15:52 volumio go-librespot[4925]: time="2026-01-26T08:15:52-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 26 08:15:52 volumio go-librespot[4925]: time="2026-01-26T08:15:52-05:00" level=info msg="zeroconf server listening on port 32911" Jan 26 08:15:52 volumio go-librespot[4925]: time="2026-01-26T08:15:52-05:00" level=debug msg="obtained new client token: AABZheg9mgyoEILdenKMscB+lU1C4ByS4HnA1JzUdX1Z1mUNS4sF91IyOmRfTeyJgl1jlgTdRkq6063zV0jDtGH5yXNBlPMSWSTj4g7U4cT5e23n1OEQUJ/yO4cg6Or957qjU0OH4UmNQ9FqO81sr3yL10ist0vyIrdoD5czqhZXKvBJuS1q0YxPRxnZbrh0u4zKw7VXDi17BIfl9I0g6cy3t5dNuOkqE2ZDr0rg+gs99CXoycjkcVc=" Jan 26 08:15:52 volumio go-librespot[4925]: time="2026-01-26T08:15:52-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 26 08:15:52 volumio go-librespot[4925]: time="2026-01-26T08:15:52-05:00" level=debug msg="completed keyexchange" Jan 26 08:15:52 volumio go-librespot[4925]: time="2026-01-26T08:15:52-05:00" level=debug msg="completed challenge" Jan 26 08:15:53 volumio go-librespot[4925]: time="2026-01-26T08:15:53-05:00" level=info msg="authenticated AP" username="31************************ym" Jan 26 08:15:53 volumio go-librespot[4925]: time="2026-01-26T08:15:53-05:00" level=info msg="authenticated Login5" username="31************************ym" Jan 26 08:15:53 volumio go-librespot[4925]: time="2026-01-26T08:15:53-05:00" level=debug msg="initializing zeroconf session" username="31************************ym" Jan 26 08:15:53 volumio go-librespot[4925]: time="2026-01-26T08:15:53-05:00" level=debug msg="dealer connection opened" Jan 26 08:15:53 volumio go-librespot[4925]: time="2026-01-26T08:15:53-05:00" level=trace msg="starting accesspoint recv loop" Jan 26 08:15:53 volumio go-librespot[4925]: time="2026-01-26T08:15:53-05:00" level=trace msg="starting dealer recv loop" Jan 26 08:15:53 volumio go-librespot[4925]: time="2026-01-26T08:15:53-05:00" level=trace msg="received accesspoint ping" Jan 26 08:15:53 volumio go-librespot[4925]: time="2026-01-26T08:15:53-05:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jan 26 08:15:53 volumio go-librespot[4925]: time="2026-01-26T08:15:53-05:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jan 26 08:15:53 volumio go-librespot[4925]: time="2026-01-26T08:15:53-05:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jan 26 08:15:53 volumio go-librespot[4925]: time="2026-01-26T08:15:53-05:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jan 26 08:15:53 volumio go-librespot[4925]: time="2026-01-26T08:15:53-05:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jan 26 08:15:53 volumio go-librespot[4925]: time="2026-01-26T08:15:53-05:00" level=debug msg="received connection id: YmUzZDYzMGMtMmNj...Njc4MzU3ODE2Nw==" Jan 26 08:15:53 volumio go-librespot[4925]: time="2026-01-26T08:15:53-05:00" level=trace msg="received accesspoint pong ack" Jan 26 08:15:53 volumio go-librespot[4925]: time="2026-01-26T08:15:53-05:00" level=debug msg="put connect state because NEW_DEVICE" Jan 26 08:15:54 volumio volumio[1011]: info: Initializing connection to go-librespot Websocket Jan 26 08:15:54 volumio go-librespot[4925]: time="2026-01-26T08:15:54-05:00" level=debug msg="new websocket client" Jan 26 08:15:54 volumio volumio[1011]: info: Connection to go-librespot Websocket established Jan 26 08:15:54 volumio volumio[1011]: info: go-librespot daemon successfully initialized Jan 26 08:15:57 volumio volumio[1011]: info: Getting Spotify volume Jan 26 08:15:57 volumio volumio[1011]: info: Spotify volume: 100 Jan 26 08:15:57 volumio volumio[1011]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Jan 26 08:15:57 volumio volumio[1011]: info: Initializing connection to go-librespot Websocket Jan 26 08:15:57 volumio go-librespot[4925]: time="2026-01-26T08:15:57-05:00" level=debug msg="new websocket client" Jan 26 08:15:57 volumio volumio[1011]: info: Connection to go-librespot Websocket established Jan 26 08:15:57 volumio volumio[1011]: info: CoreCommandRouter::volumioGetState Jan 26 08:16:00 volumio volumio[1011]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Jan 26 08:16:00 volumio volumio[1011]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Jan 26 08:16:00 volumio volumio[1011]: info: Creating Spotify config file Jan 26 08:16:00 volumio volumio[1011]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 26 08:16:00 volumio volumio[1011]: info: Spotify config file written Jan 26 08:16:00 volumio sudo[4943]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 26 08:16:00 volumio sudo[4943]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 26 08:16:00 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jan 26 08:16:00 volumio systemd[1]: go-librespot-daemon.service: Killing process 4929 (go-librespot) with signal SIGKILL. Jan 26 08:16:00 volumio volumio[1011]: info: Connection to go-librespot Websocket closed Jan 26 08:16:00 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jan 26 08:16:00 volumio volumio[1011]: info: Connection to go-librespot Websocket closed Jan 26 08:16:00 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 26 08:16:00 volumio volumio[1011]: info: Getting Spotify volume Jan 26 08:16:00 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 26 08:16:00 volumio go-librespot[4946]: go-librespot daemon starting... Jan 26 08:16:00 volumio volumio[1011]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 26 08:16:00 volumio sudo[4943]: pam_unix(sudo:session): session closed for user root Jan 26 08:16:00 volumio volumio[1011]: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 26 08:16:00 volumio volumio[1011]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Jan 26 08:16:00 volumio volumio[1011]: errno: -111, Jan 26 08:16:00 volumio volumio[1011]: code: 'ECONNREFUSED', Jan 26 08:16:00 volumio volumio[1011]: syscall: 'connect', Jan 26 08:16:00 volumio volumio[1011]: address: '127.0.0.1', Jan 26 08:16:00 volumio volumio[1011]: port: 9879, Jan 26 08:16:00 volumio volumio[1011]: response: undefined Jan 26 08:16:00 volumio volumio[1011]: } Jan 26 08:16:00 volumio volumio[1011]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 26 08:16:00 volumio go-librespot[4947]: time="2026-01-26T08:16:00-05:00" level=info msg="running go-librespot 0.6.2" Jan 26 08:16:00 volumio go-librespot[4947]: time="2026-01-26T08:16:00-05:00" level=debug msg="app state loaded" Jan 26 08:16:00 volumio go-librespot[4947]: time="2026-01-26T08:16:00-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 26 08:16:01 volumio go-librespot[4947]: time="2026-01-26T08:16:01-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 26 08:16:01 volumio go-librespot[4947]: time="2026-01-26T08:16:01-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 26 08:16:01 volumio go-librespot[4947]: time="2026-01-26T08:16:01-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 26 08:16:01 volumio go-librespot[4947]: time="2026-01-26T08:16:01-05:00" level=info msg="zeroconf server listening on port 45193" Jan 26 08:16:01 volumio go-librespot[4947]: time="2026-01-26T08:16:01-05:00" level=debug msg="obtained new client token: AABvrQS/6H1ZsbeWvXp6UfdWQve7dEcks14ku6ZST822cA9TsG142MpneM2OiCwzkLFJQKOgNTVzpsclCS+dl/sXRt7WpjaWRofmErsgGnUGkNxLjeDjmDrdYU/Nfoop4xqtZZRC23fFpOeyUbk5zXssOSxthVLCi5TwpM5zJhcU1GTflqVl0TVRZZybgV2TWER3qAsT7i3tNTyZgH/1o4Iu8mPN+WIsDaAlSS8oZ8ekH5jfwyNc" Jan 26 08:16:01 volumio sudo[4970]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-26 08:15' Jan 26 08:16:01 volumio sudo[4970]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 26 08:16:01 volumio go-librespot[4947]: time="2026-01-26T08:16:01-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" PRETTY_NAME="Debian GNU/Linux 12 (bookworm)" NAME="Debian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="b05a530ca81d05eb9a84d0acf82089f0a60b8ee6" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="4ad85e2147d972f0b838d33c21382d2d813b2ae8" VOLUMIO_ARCH="x64" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu Dec 25 09:38:19 UTC 2025" VOLUMIO_VERSION="4.084" VOLUMIO_HARDWARE="x86_amd64" VOLUMIO_DEVICENAME="x86_64" VOLUMIO_HASH="00e933ebe3692ad8aea9910d2289bf23"