Feb 21 19:55:00 volumio volumio[1302]: info: CoreCommandRouter::getUIConfigOnPlugin Feb 21 19:55:19 volumio go-librespot[19491]: time="2026-02-21T19:55:19+02:00" level=trace msg="sent dealer ping" Feb 21 19:55:19 volumio go-librespot[19491]: time="2026-02-21T19:55:19+02:00" level=trace msg="received dealer pong" Feb 21 19:55:49 volumio go-librespot[19491]: time="2026-02-21T19:55:49+02:00" level=trace msg="sent dealer ping" Feb 21 19:55:49 volumio go-librespot[19491]: time="2026-02-21T19:55:49+02:00" level=trace msg="received dealer pong" Feb 21 19:55:50 volumio go-librespot[19491]: time="2026-02-21T19:55:50+02:00" level=trace msg="received accesspoint ping" Feb 21 19:55:50 volumio go-librespot[19491]: time="2026-02-21T19:55:50+02:00" level=trace msg="received accesspoint pong ack" Feb 21 19:55:53 volumio volumio[1302]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Feb 21 19:55:53 volumio volumio[1302]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Feb 21 19:55:53 volumio volumio[1302]: info: Creating Spotify config file Feb 21 19:55:53 volumio volumio[1302]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 19:55:53 volumio volumio[1302]: info: Spotify config file written Feb 21 19:55:53 volumio sudo[24741]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 21 19:55:53 volumio sudo[24741]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 21 19:55:53 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Feb 21 19:55:53 volumio systemd[1]: go-librespot-daemon.service: Killing process 19500 (go-librespot) with signal SIGKILL. Feb 21 19:55:53 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Feb 21 19:55:53 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 21 19:55:53 volumio volumio[1302]: info: Connection to go-librespot Websocket closed Feb 21 19:55:53 volumio volumio[1302]: info: Connection to go-librespot Websocket closed Feb 21 19:55:53 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 21 19:55:53 volumio go-librespot[24743]: go-librespot daemon starting... Feb 21 19:55:53 volumio sudo[24741]: pam_unix(sudo:session): session closed for user root Feb 21 19:55:53 volumio go-librespot[24744]: time="2026-02-21T19:55:53+02:00" level=info msg="running go-librespot 0.6.2" Feb 21 19:55:53 volumio go-librespot[24744]: time="2026-02-21T19:55:53+02:00" level=debug msg="app state loaded" Feb 21 19:55:53 volumio go-librespot[24744]: time="2026-02-21T19:55:53+02:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 21 19:55:53 volumio go-librespot[24744]: time="2026-02-21T19:55:53+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Feb 21 19:55:53 volumio go-librespot[24744]: time="2026-02-21T19:55:53+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 21 19:55:53 volumio go-librespot[24744]: time="2026-02-21T19:55:53+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 21 19:55:53 volumio go-librespot[24744]: time="2026-02-21T19:55:53+02:00" level=info msg="zeroconf server listening on port 46135" Feb 21 19:55:54 volumio go-librespot[24744]: time="2026-02-21T19:55:54+02:00" level=debug msg="obtained new client token: AADpIVCaXRBJWZ0MV3QcLcuvtpfteucZslbxPY8N33u+Q8OzJbcQgzJQJAeQc4LaCADU3FmaiquNXKL18re4hDjfzq3VmDWKrZjjMQacADpqtQ9+y5phWT+ZpA+nW4EUdYG/sGyRL6Hx9Y49WhhI8A0C1dnY83k5zpxmeYyHXWzibffgQivYKNoqXiTqrK5KX+iZdsB+yr/9YPUxd65Ui6bCw/jGjf9dQ1uyRtBdulNb4gdFGQ3Gog==" Feb 21 19:55:54 volumio go-librespot[24744]: time="2026-02-21T19:55:54+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Feb 21 19:55:54 volumio go-librespot[24744]: time="2026-02-21T19:55:54+02:00" level=debug msg="completed keyexchange" Feb 21 19:55:54 volumio go-librespot[24744]: time="2026-02-21T19:55:54+02:00" level=debug msg="completed challenge" Feb 21 19:55:54 volumio go-librespot[24744]: time="2026-02-21T19:55:54+02:00" level=info msg="authenticated AP" username="11*******84" Feb 21 19:55:54 volumio go-librespot[24744]: time="2026-02-21T19:55:54+02:00" level=info msg="authenticated Login5" username="11*******84" Feb 21 19:55:54 volumio go-librespot[24744]: time="2026-02-21T19:55:54+02:00" level=debug msg="initializing zeroconf session" username="11*******84" Feb 21 19:55:54 volumio go-librespot[24744]: time="2026-02-21T19:55:54+02:00" level=debug msg="dealer connection opened" Feb 21 19:55:54 volumio go-librespot[24744]: time="2026-02-21T19:55:54+02:00" level=trace msg="starting accesspoint recv loop" Feb 21 19:55:54 volumio go-librespot[24744]: time="2026-02-21T19:55:54+02:00" level=trace msg="starting dealer recv loop" Feb 21 19:55:54 volumio go-librespot[24744]: time="2026-02-21T19:55:54+02:00" level=trace msg="received accesspoint ping" Feb 21 19:55:54 volumio go-librespot[24744]: time="2026-02-21T19:55:54+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Feb 21 19:55:54 volumio go-librespot[24744]: time="2026-02-21T19:55:54+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Feb 21 19:55:54 volumio go-librespot[24744]: time="2026-02-21T19:55:54+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Feb 21 19:55:54 volumio go-librespot[24744]: time="2026-02-21T19:55:54+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Feb 21 19:55:54 volumio go-librespot[24744]: time="2026-02-21T19:55:54+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Feb 21 19:55:54 volumio go-librespot[24744]: time="2026-02-21T19:55:54+02:00" level=debug msg="received connection id: NDE2OWUyYjUtY2Nj...QjIzOUY1RkJDRA==" Feb 21 19:55:54 volumio volumio[1302]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Feb 21 19:55:54 volumio volumio[1302]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Feb 21 19:55:54 volumio volumio[1302]: info: Creating Spotify config file Feb 21 19:55:54 volumio volumio[1302]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 19:55:54 volumio volumio[1302]: info: Spotify config file written Feb 21 19:55:54 volumio sudo[24756]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 21 19:55:54 volumio sudo[24756]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 21 19:55:54 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Feb 21 19:55:54 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Feb 21 19:55:54 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 21 19:55:54 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 21 19:55:54 volumio go-librespot[24758]: go-librespot daemon starting... Feb 21 19:55:54 volumio sudo[24756]: pam_unix(sudo:session): session closed for user root Feb 21 19:55:54 volumio go-librespot[24759]: time="2026-02-21T19:55:54+02:00" level=info msg="running go-librespot 0.6.2" Feb 21 19:55:54 volumio go-librespot[24759]: time="2026-02-21T19:55:54+02:00" level=debug msg="app state loaded" Feb 21 19:55:54 volumio go-librespot[24759]: time="2026-02-21T19:55:54+02:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 21 19:55:55 volumio go-librespot[24759]: time="2026-02-21T19:55:55+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 21 19:55:55 volumio go-librespot[24759]: time="2026-02-21T19:55:55+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 21 19:55:55 volumio go-librespot[24759]: time="2026-02-21T19:55:55+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 21 19:55:55 volumio go-librespot[24759]: time="2026-02-21T19:55:55+02:00" level=info msg="zeroconf server listening on port 32805" Feb 21 19:55:55 volumio go-librespot[24759]: time="2026-02-21T19:55:55+02:00" level=debug msg="obtained new client token: AABX+7Z5IFd4mJrc1xBv3zpto39E5a4iVT8Kabw2ON4ihvykuUZiBo/icCLsXrd092qMtGpyEtZ8UeNjxP2DYDJui8z7sfodfZMrSU8ge3HO78XswxlQFCwWusNMHglAU6GEZQadFP4jrsHPZ5Mjo8eed1VupggV91+bzu42aAz2dATTTnPwkp7v2H/pzAXFZCJhzN5yK1eMEN+t6I8Dy2iovxjv5wKv+aQz3/FLDw8UwTSRSfqtsCww" Feb 21 19:55:55 volumio go-librespot[24759]: time="2026-02-21T19:55:55+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Feb 21 19:55:55 volumio go-librespot[24759]: time="2026-02-21T19:55:55+02:00" level=debug msg="completed keyexchange" Feb 21 19:55:55 volumio go-librespot[24759]: time="2026-02-21T19:55:55+02:00" level=debug msg="completed challenge" Feb 21 19:55:55 volumio go-librespot[24759]: time="2026-02-21T19:55:55+02:00" level=info msg="authenticated AP" username="11*******84" Feb 21 19:55:55 volumio volumio[1302]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Feb 21 19:55:55 volumio volumio[1302]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Feb 21 19:55:55 volumio volumio[1302]: info: Creating Spotify config file Feb 21 19:55:55 volumio volumio[1302]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 19:55:55 volumio volumio[1302]: info: Spotify config file written Feb 21 19:55:55 volumio sudo[24770]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 21 19:55:55 volumio sudo[24770]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 21 19:55:55 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Feb 21 19:55:55 volumio systemd[1]: go-librespot-daemon.service: Killing process 24768 (go-librespot) with signal SIGKILL. Feb 21 19:55:55 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Feb 21 19:55:55 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 21 19:55:56 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 21 19:55:56 volumio go-librespot[24772]: go-librespot daemon starting... Feb 21 19:55:56 volumio sudo[24770]: pam_unix(sudo:session): session closed for user root Feb 21 19:55:56 volumio go-librespot[24773]: time="2026-02-21T19:55:56+02:00" level=info msg="running go-librespot 0.6.2" Feb 21 19:55:56 volumio go-librespot[24773]: time="2026-02-21T19:55:56+02:00" level=debug msg="app state loaded" Feb 21 19:55:56 volumio go-librespot[24773]: time="2026-02-21T19:55:56+02:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 21 19:55:56 volumio go-librespot[24773]: time="2026-02-21T19:55:56+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Feb 21 19:55:56 volumio go-librespot[24773]: time="2026-02-21T19:55:56+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 21 19:55:56 volumio go-librespot[24773]: time="2026-02-21T19:55:56+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 21 19:55:56 volumio go-librespot[24773]: time="2026-02-21T19:55:56+02:00" level=info msg="zeroconf server listening on port 39993" Feb 21 19:55:56 volumio go-librespot[24773]: time="2026-02-21T19:55:56+02:00" level=debug msg="obtained new client token: AABN6awtpEqaJSbC8uaHdquX+ropc2uKFPv3drgtg9+Mo58LZTQ50nlUrLhHl2jU9HzW6FaFuAwJZs5saEGd33cXbPhiWEG19hNUJWUbmNr8kcfJxMAYKDP3Tb2mu9EJB2MRFeqSW5RlrmVOVhxFJ7Tko0/FdmdnUweszAKvQLPf9H+X99D2HE0IMMSdkjoEmCEAQsqx75FR4RdriCjLsFxam6pdZGmGHINI3DNaDDawqkVdEPbGKQiD" Feb 21 19:55:56 volumio volumio[1302]: info: Initializing connection to go-librespot Websocket Feb 21 19:55:56 volumio go-librespot[24773]: time="2026-02-21T19:55:56+02:00" level=debug msg="new websocket client" Feb 21 19:55:56 volumio volumio[1302]: info: Connection to go-librespot Websocket established Feb 21 19:55:56 volumio volumio[1302]: info: go-librespot daemon successfully initialized Feb 21 19:55:56 volumio go-librespot[24773]: time="2026-02-21T19:55:56+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Feb 21 19:55:56 volumio go-librespot[24773]: time="2026-02-21T19:55:56+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: read tcp 192.168.37.195:52086->104.199.65.9:4070: read: connection reset by peer" Feb 21 19:55:57 volumio go-librespot[24773]: time="2026-02-21T19:55:57+02:00" level=debug msg="connected to ap-gew1.spotify.com:443" Feb 21 19:55:57 volumio go-librespot[24773]: time="2026-02-21T19:55:57+02:00" level=debug msg="completed keyexchange" Feb 21 19:55:57 volumio go-librespot[24773]: time="2026-02-21T19:55:57+02:00" level=debug msg="completed challenge" Feb 21 19:55:57 volumio go-librespot[24773]: time="2026-02-21T19:55:57+02:00" level=info msg="authenticated AP" username="11*******84" Feb 21 19:55:57 volumio go-librespot[24773]: time="2026-02-21T19:55:57+02:00" level=info msg="authenticated Login5" username="11*******84" Feb 21 19:55:57 volumio go-librespot[24773]: time="2026-02-21T19:55:57+02:00" level=debug msg="initializing zeroconf session" username="11*******84" Feb 21 19:55:57 volumio volumio[1302]: info: go-librespot daemon successfully initialized Feb 21 19:55:58 volumio go-librespot[24773]: time="2026-02-21T19:55:58+02:00" level=debug msg="dealer connection opened" Feb 21 19:55:58 volumio go-librespot[24773]: time="2026-02-21T19:55:58+02:00" level=trace msg="starting accesspoint recv loop" Feb 21 19:55:58 volumio go-librespot[24773]: time="2026-02-21T19:55:58+02:00" level=trace msg="starting dealer recv loop" Feb 21 19:55:58 volumio go-librespot[24773]: time="2026-02-21T19:55:58+02:00" level=trace msg="received accesspoint ping" Feb 21 19:55:58 volumio go-librespot[24773]: time="2026-02-21T19:55:58+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Feb 21 19:55:58 volumio go-librespot[24773]: time="2026-02-21T19:55:58+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Feb 21 19:55:58 volumio go-librespot[24773]: time="2026-02-21T19:55:58+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Feb 21 19:55:58 volumio go-librespot[24773]: time="2026-02-21T19:55:58+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Feb 21 19:55:58 volumio go-librespot[24773]: time="2026-02-21T19:55:58+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Feb 21 19:55:58 volumio go-librespot[24773]: time="2026-02-21T19:55:58+02:00" level=debug msg="received connection id: Y2I3MGYwOWUtM2E0...NTE0QTY5NEYzNQ==" Feb 21 19:55:58 volumio go-librespot[24773]: time="2026-02-21T19:55:58+02:00" level=trace msg="received accesspoint pong ack" Feb 21 19:55:58 volumio go-librespot[24773]: time="2026-02-21T19:55:58+02:00" level=debug msg="put connect state because NEW_DEVICE" Feb 21 19:55:59 volumio volumio[1302]: info: go-librespot daemon successfully initialized Feb 21 19:55:59 volumio volumio[1302]: info: Getting Spotify volume Feb 21 19:55:59 volumio volumio[1302]: info: Spotify volume: 100 Feb 21 19:55:59 volumio volumio[1302]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 10 Feb 21 19:55:59 volumio volumio[1302]: info: Initializing connection to go-librespot Websocket Feb 21 19:55:59 volumio go-librespot[24773]: time="2026-02-21T19:55:59+02:00" level=debug msg="new websocket client" Feb 21 19:55:59 volumio volumio[1302]: info: CoreCommandRouter::volumioGetState Feb 21 19:55:59 volumio volumio[1302]: info: CorePlayQueue::getTrack 2 Feb 21 19:55:59 volumio volumio[1302]: info: Connection to go-librespot Websocket established Feb 21 19:55:59 volumio volumio[1302]: SPOTIFY: RECEIVED VOLUMIO VOLUME 79 Feb 21 19:55:59 volumio volumio[1302]: SPOTIFY: SPOTIFY VOLUME 100 Feb 21 19:55:59 volumio volumio[1302]: SPOTIFY: VOLUMIO VOLUME 79 Feb 21 19:55:59 volumio volumio[1302]: SPOTIFY: DELTA VOLUME ENOUGH: true Feb 21 19:55:59 volumio volumio[1302]: info: Setting Spotify Volume from Volumio: 79 Feb 21 19:56:00 volumio volumio[1302]: info: CoreCommandRouter::volumioPlay Feb 21 19:56:00 volumio volumio[1302]: info: CoreStateMachine::play index undefined Feb 21 19:56:00 volumio volumio[1302]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 21 19:56:00 volumio volumio[1302]: info: CorePlayQueue::getTrack 2 Feb 21 19:56:00 volumio volumio[1302]: info: CoreStateMachine::startPlaybackTimer Feb 21 19:56:00 volumio volumio[1302]: info: CorePlayQueue::getTrack 2 Feb 21 19:56:00 volumio volumio[1302]: info: [1771696560218] ControllerSpotify::clearAddPlayTrack Feb 21 19:56:00 volumio volumio[1302]: info: Sending Spotify command with payload to local API: /player/play Feb 21 19:56:00 volumio go-librespot[24773]: time="2026-02-21T19:56:00+02:00" level=debug msg="resolved context of track" uri="spotify:track:60dGXq7vINvaL4fGlBdo01" Feb 21 19:56:00 volumio go-librespot[24773]: time="2026-02-21T19:56:00+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:60dGXq7vINvaL4fGlBdo01" Feb 21 19:56:00 volumio go-librespot[24773]: time="2026-02-21T19:56:00+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:60dGXq7vINvaL4fGlBdo01" Feb 21 19:56:00 volumio go-librespot[24773]: time="2026-02-21T19:56:00+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 21 19:56:00 volumio go-librespot[24773]: time="2026-02-21T19:56:00+02:00" level=trace msg="emitting websocket event: will_play" Feb 21 19:56:00 volumio volumio[1302]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:60dGXq7vINvaL4fGlBdo01","uri":"spotify:track:60dGXq7vINvaL4fGlBdo01","play_origin":"go-librespot"}} Feb 21 19:56:00 volumio volumio[1302]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:60dGXq7vINvaL4fGlBdo01","uri":"spotify:track:60dGXq7vINvaL4fGlBdo01","play_origin":"go-librespot"}} Feb 21 19:56:00 volumio go-librespot[24773]: time="2026-02-21T19:56:00+02:00" level=debug msg="selected format OGG_VORBIS_320 (5ed8f2f3c9336d01db4e2a91d0f190323240ed97)" uri="spotify:track:60dGXq7vINvaL4fGlBdo01" Feb 21 19:56:00 volumio go-librespot[24773]: time="2026-02-21T19:56:00+02:00" level=debug msg="requested aes key for file 5ed8f2f3c9336d01db4e2a91d0f190323240ed97, gid: 60dGXq7vINvaL4fGlBdo01" Feb 21 19:56:00 volumio go-librespot[24773]: time="2026-02-21T19:56:00+02:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:60dGXq7vINvaL4fGlBdo01: failed retrieving audio key: failed retrieving aes key with code 1" Feb 21 19:56:00 volumio volumio[1302]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Feb 21 19:56:00 volumio volumio[1302]: info: Initializing connection to go-librespot Websocket Feb 21 19:56:00 volumio go-librespot[24773]: time="2026-02-21T19:56:00+02:00" level=debug msg="new websocket client" Feb 21 19:56:00 volumio volumio[1302]: info: Connection to go-librespot Websocket established Feb 21 19:56:00 volumio volumio[1302]: info: CoreCommandRouter::volumioPlay Feb 21 19:56:00 volumio volumio[1302]: info: CoreStateMachine::play index undefined Feb 21 19:56:00 volumio volumio[1302]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 21 19:56:00 volumio volumio[1302]: info: CorePlayQueue::getTrack 2 Feb 21 19:56:00 volumio volumio[1302]: info: CoreStateMachine::startPlaybackTimer Feb 21 19:56:00 volumio volumio[1302]: info: CorePlayQueue::getTrack 2 Feb 21 19:56:00 volumio volumio[1302]: info: [1771696560986] ControllerSpotify::clearAddPlayTrack Feb 21 19:56:00 volumio volumio[1302]: info: Sending Spotify command with payload to local API: /player/play Feb 21 19:56:01 volumio volumio[1302]: SPOTIFY: SETTING SPOTIFY VOLUME 79 Feb 21 19:56:01 volumio volumio[1302]: info: Sending Spotify command with payload to local API: /player/volume Feb 21 19:56:01 volumio go-librespot[24773]: time="2026-02-21T19:56:01+02:00" level=debug msg="resolved context of track" uri="spotify:track:60dGXq7vINvaL4fGlBdo01" Feb 21 19:56:01 volumio go-librespot[24773]: time="2026-02-21T19:56:01+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:60dGXq7vINvaL4fGlBdo01" Feb 21 19:56:01 volumio go-librespot[24773]: time="2026-02-21T19:56:01+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:60dGXq7vINvaL4fGlBdo01" Feb 21 19:56:01 volumio go-librespot[24773]: time="2026-02-21T19:56:01+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 21 19:56:01 volumio go-librespot[24773]: time="2026-02-21T19:56:01+02:00" level=trace msg="emitting websocket event: will_play" Feb 21 19:56:01 volumio volumio[1302]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:60dGXq7vINvaL4fGlBdo01","uri":"spotify:track:60dGXq7vINvaL4fGlBdo01","play_origin":"go-librespot"}} Feb 21 19:56:01 volumio volumio[1302]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:60dGXq7vINvaL4fGlBdo01","uri":"spotify:track:60dGXq7vINvaL4fGlBdo01","play_origin":"go-librespot"}} Feb 21 19:56:01 volumio volumio[1302]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:60dGXq7vINvaL4fGlBdo01","uri":"spotify:track:60dGXq7vINvaL4fGlBdo01","play_origin":"go-librespot"}} Feb 21 19:56:01 volumio go-librespot[24773]: time="2026-02-21T19:56:01+02:00" level=debug msg="selected format OGG_VORBIS_320 (5ed8f2f3c9336d01db4e2a91d0f190323240ed97)" uri="spotify:track:60dGXq7vINvaL4fGlBdo01" Feb 21 19:56:01 volumio go-librespot[24773]: time="2026-02-21T19:56:01+02:00" level=debug msg="requested aes key for file 5ed8f2f3c9336d01db4e2a91d0f190323240ed97, gid: 60dGXq7vINvaL4fGlBdo01" Feb 21 19:56:01 volumio go-librespot[24773]: time="2026-02-21T19:56:01+02:00" level=debug msg="update volume requested to 51772/65535" Feb 21 19:56:01 volumio go-librespot[24773]: time="2026-02-21T19:56:01+02:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:60dGXq7vINvaL4fGlBdo01: failed retrieving audio key: failed retrieving aes key with code 1" Feb 21 19:56:01 volumio volumio[1302]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Feb 21 19:56:01 volumio go-librespot[24773]: time="2026-02-21T19:56:01+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Feb 21 19:56:01 volumio go-librespot[24773]: time="2026-02-21T19:56:01+02:00" level=trace msg="emitting websocket event: volume" Feb 21 19:56:01 volumio volumio[1302]: SPOTIFY: received: {"type":"volume","data":{"value":79,"max":100}} Feb 21 19:56:01 volumio volumio[1302]: SPOTIFY: RECEIVED SPOTIFY VOLUME 79 Feb 21 19:56:01 volumio volumio[1302]: SPOTIFY: received: {"type":"volume","data":{"value":79,"max":100}} Feb 21 19:56:01 volumio volumio[1302]: SPOTIFY: RECEIVED SPOTIFY VOLUME 79 Feb 21 19:56:01 volumio volumio[1302]: SPOTIFY: received: {"type":"volume","data":{"value":79,"max":100}} Feb 21 19:56:01 volumio volumio[1302]: SPOTIFY: RECEIVED SPOTIFY VOLUME 79 Feb 21 19:56:02 volumio volumio[1302]: info: Initializing connection to go-librespot Websocket Feb 21 19:56:02 volumio go-librespot[24773]: time="2026-02-21T19:56:02+02:00" level=debug msg="new websocket client" Feb 21 19:56:02 volumio volumio[1302]: info: Connection to go-librespot Websocket established Feb 21 19:56:02 volumio volumio[1302]: info: Getting Spotify volume Feb 21 19:56:02 volumio volumio[1302]: info: Spotify volume: 79 Feb 21 19:56:02 volumio volumio[1302]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 10 Feb 21 19:56:02 volumio volumio[1302]: info: CoreCommandRouter::volumioGetState Feb 21 19:56:02 volumio volumio[1302]: info: CorePlayQueue::getTrack 2 Feb 21 19:56:02 volumio volumio[1302]: SPOTIFY: RECEIVED VOLUMIO VOLUME 79 Feb 21 19:56:03 volumio volumio[1302]: info: CoreCommandRouter::volumioPrevious Feb 21 19:56:03 volumio volumio[1302]: info: CoreStateMachine::previous Feb 21 19:56:03 volumio volumio[1302]: info: CoreStateMachine::updateTrackBlock Feb 21 19:56:03 volumio volumio[1302]: info: CorePlayQueue::getTrackBlock Feb 21 19:56:03 volumio volumio[1302]: info: CoreStateMachine::pushState Feb 21 19:56:03 volumio volumio[1302]: info: CorePlayQueue::getTrack 1 Feb 21 19:56:03 volumio volumio[1302]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 21 19:56:03 volumio volumio[1302]: info: CoreCommandRouter::volumioPushState Feb 21 19:56:03 volumio volumio[1302]: info: FusionDsp - Volumio is not playing Feb 21 19:56:03 volumio volumio[1302]: info: FusionDsp - Clipped samples monitor stopped Feb 21 19:56:03 volumio volumio[1302]: info: Display-configuration --- Volumio status=stop timeout=120 noifplay=true screensavertype=dpms Feb 21 19:56:03 volumio volumio[1302]: SPOTIFY: RECEIVED VOLUMIO VOLUME 79 Feb 21 19:56:03 volumio volumio[1302]: info: Getting Spotify volume Feb 21 19:56:03 volumio volumio[1302]: info: Spotify volume: 79 Feb 21 19:56:03 volumio volumio[1302]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 10 Feb 21 19:56:03 volumio volumio[1302]: info: CoreCommandRouter::volumioGetState Feb 21 19:56:03 volumio volumio[1302]: info: CorePlayQueue::getTrack 1 Feb 21 19:56:03 volumio volumio[1302]: SPOTIFY: RECEIVED VOLUMIO VOLUME 79 Feb 21 19:56:04 volumio volumio[1302]: info: CoreCommandRouter::volumioPrevious Feb 21 19:56:04 volumio volumio[1302]: info: CoreStateMachine::previous Feb 21 19:56:04 volumio volumio[1302]: info: CoreStateMachine::updateTrackBlock Feb 21 19:56:04 volumio volumio[1302]: info: CorePlayQueue::getTrackBlock Feb 21 19:56:04 volumio volumio[1302]: info: CoreStateMachine::pushState Feb 21 19:56:04 volumio volumio[1302]: info: CorePlayQueue::getTrack 0 Feb 21 19:56:04 volumio volumio[1302]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 21 19:56:04 volumio volumio[1302]: info: CoreCommandRouter::volumioPushState Feb 21 19:56:04 volumio volumio[1302]: info: FusionDsp - Volumio is not playing Feb 21 19:56:04 volumio volumio[1302]: info: FusionDsp - Clipped samples monitor stopped Feb 21 19:56:04 volumio volumio[1302]: info: Display-configuration --- Volumio status=stop timeout=120 noifplay=true screensavertype=dpms Feb 21 19:56:04 volumio volumio[1302]: SPOTIFY: RECEIVED VOLUMIO VOLUME 79 Feb 21 19:56:05 volumio volumio[1302]: info: Getting Spotify volume Feb 21 19:56:05 volumio volumio[1302]: info: Spotify volume: 79 Feb 21 19:56:05 volumio volumio[1302]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 10 Feb 21 19:56:05 volumio volumio[1302]: info: CoreCommandRouter::volumioGetState Feb 21 19:56:05 volumio volumio[1302]: info: CorePlayQueue::getTrack 0 Feb 21 19:56:05 volumio volumio[1302]: SPOTIFY: RECEIVED VOLUMIO VOLUME 79 Feb 21 19:56:05 volumio volumio[1302]: info: CoreCommandRouter::volumioPlay Feb 21 19:56:05 volumio volumio[1302]: info: CoreStateMachine::play index undefined Feb 21 19:56:05 volumio volumio[1302]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 21 19:56:05 volumio volumio[1302]: info: CorePlayQueue::getTrack 0 Feb 21 19:56:05 volumio volumio[1302]: info: CoreStateMachine::startPlaybackTimer Feb 21 19:56:05 volumio volumio[1302]: info: CorePlayQueue::getTrack 0 Feb 21 19:56:05 volumio volumio[1302]: info: [1771696565818] ControllerSpotify::clearAddPlayTrack Feb 21 19:56:05 volumio volumio[1302]: info: Sending Spotify command with payload to local API: /player/play Feb 21 19:56:05 volumio go-librespot[24773]: time="2026-02-21T19:56:05+02:00" level=debug msg="resolved context of track" uri="spotify:track:2iUFMaHe6sucVzQAQZFH1s" Feb 21 19:56:05 volumio go-librespot[24773]: time="2026-02-21T19:56:05+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:2iUFMaHe6sucVzQAQZFH1s" Feb 21 19:56:05 volumio go-librespot[24773]: time="2026-02-21T19:56:05+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:2iUFMaHe6sucVzQAQZFH1s" Feb 21 19:56:06 volumio go-librespot[24773]: time="2026-02-21T19:56:06+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 21 19:56:06 volumio go-librespot[24773]: time="2026-02-21T19:56:06+02:00" level=trace msg="emitting websocket event: will_play" Feb 21 19:56:06 volumio volumio[1302]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:2iUFMaHe6sucVzQAQZFH1s","uri":"spotify:track:2iUFMaHe6sucVzQAQZFH1s","play_origin":"go-librespot"}} Feb 21 19:56:06 volumio volumio[1302]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:2iUFMaHe6sucVzQAQZFH1s","uri":"spotify:track:2iUFMaHe6sucVzQAQZFH1s","play_origin":"go-librespot"}} Feb 21 19:56:06 volumio volumio[1302]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:2iUFMaHe6sucVzQAQZFH1s","uri":"spotify:track:2iUFMaHe6sucVzQAQZFH1s","play_origin":"go-librespot"}} Feb 21 19:56:06 volumio volumio[1302]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:2iUFMaHe6sucVzQAQZFH1s","uri":"spotify:track:2iUFMaHe6sucVzQAQZFH1s","play_origin":"go-librespot"}} Feb 21 19:56:06 volumio go-librespot[24773]: time="2026-02-21T19:56:06+02:00" level=debug msg="selected format OGG_VORBIS_320 (1666a3ad8ba0c728625824ff85f39dea56b2b998)" uri="spotify:track:2iUFMaHe6sucVzQAQZFH1s" Feb 21 19:56:06 volumio go-librespot[24773]: time="2026-02-21T19:56:06+02:00" level=debug msg="requested aes key for file 1666a3ad8ba0c728625824ff85f39dea56b2b998, gid: 2iUFMaHe6sucVzQAQZFH1s" Feb 21 19:56:06 volumio go-librespot[24773]: time="2026-02-21T19:56:06+02:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:2iUFMaHe6sucVzQAQZFH1s: failed retrieving audio key: failed retrieving aes key with code 1" Feb 21 19:56:06 volumio volumio[1302]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Feb 21 19:56:06 volumio volumio[1302]: info: CoreCommandRouter::volumioPlay Feb 21 19:56:06 volumio volumio[1302]: info: CoreStateMachine::play index undefined Feb 21 19:56:06 volumio volumio[1302]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 21 19:56:06 volumio volumio[1302]: info: CorePlayQueue::getTrack 0 Feb 21 19:56:06 volumio volumio[1302]: info: CoreStateMachine::startPlaybackTimer Feb 21 19:56:06 volumio volumio[1302]: info: CorePlayQueue::getTrack 0 Feb 21 19:56:06 volumio volumio[1302]: info: [1771696566634] ControllerSpotify::clearAddPlayTrack Feb 21 19:56:06 volumio volumio[1302]: info: Sending Spotify command with payload to local API: /player/play Feb 21 19:56:06 volumio go-librespot[24773]: time="2026-02-21T19:56:06+02:00" level=debug msg="resolved context of track" uri="spotify:track:2iUFMaHe6sucVzQAQZFH1s" Feb 21 19:56:06 volumio go-librespot[24773]: time="2026-02-21T19:56:06+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:2iUFMaHe6sucVzQAQZFH1s" Feb 21 19:56:06 volumio go-librespot[24773]: time="2026-02-21T19:56:06+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:2iUFMaHe6sucVzQAQZFH1s" Feb 21 19:56:06 volumio go-librespot[24773]: time="2026-02-21T19:56:06+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 21 19:56:06 volumio go-librespot[24773]: time="2026-02-21T19:56:06+02:00" level=trace msg="emitting websocket event: will_play" Feb 21 19:56:06 volumio volumio[1302]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:2iUFMaHe6sucVzQAQZFH1s","uri":"spotify:track:2iUFMaHe6sucVzQAQZFH1s","play_origin":"go-librespot"}} Feb 21 19:56:06 volumio volumio[1302]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:2iUFMaHe6sucVzQAQZFH1s","uri":"spotify:track:2iUFMaHe6sucVzQAQZFH1s","play_origin":"go-librespot"}} Feb 21 19:56:06 volumio volumio[1302]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:2iUFMaHe6sucVzQAQZFH1s","uri":"spotify:track:2iUFMaHe6sucVzQAQZFH1s","play_origin":"go-librespot"}} Feb 21 19:56:06 volumio volumio[1302]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:2iUFMaHe6sucVzQAQZFH1s","uri":"spotify:track:2iUFMaHe6sucVzQAQZFH1s","play_origin":"go-librespot"}} Feb 21 19:56:07 volumio go-librespot[24773]: time="2026-02-21T19:56:07+02:00" level=debug msg="selected format OGG_VORBIS_320 (1666a3ad8ba0c728625824ff85f39dea56b2b998)" uri="spotify:track:2iUFMaHe6sucVzQAQZFH1s" Feb 21 19:56:07 volumio go-librespot[24773]: time="2026-02-21T19:56:07+02:00" level=debug msg="requested aes key for file 1666a3ad8ba0c728625824ff85f39dea56b2b998, gid: 2iUFMaHe6sucVzQAQZFH1s" Feb 21 19:56:07 volumio go-librespot[24773]: time="2026-02-21T19:56:07+02:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:2iUFMaHe6sucVzQAQZFH1s: failed retrieving audio key: failed retrieving aes key with code 1" Feb 21 19:56:07 volumio volumio[1302]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Feb 21 19:56:07 volumio volumio[1302]: info: CoreCommandRouter::volumioPlay Feb 21 19:56:07 volumio volumio[1302]: info: CoreStateMachine::play index undefined Feb 21 19:56:07 volumio volumio[1302]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 21 19:56:07 volumio volumio[1302]: info: CorePlayQueue::getTrack 0 Feb 21 19:56:07 volumio volumio[1302]: info: CoreStateMachine::startPlaybackTimer Feb 21 19:56:07 volumio volumio[1302]: info: CorePlayQueue::getTrack 0 Feb 21 19:56:07 volumio volumio[1302]: info: [1771696567202] ControllerSpotify::clearAddPlayTrack Feb 21 19:56:07 volumio volumio[1302]: info: Sending Spotify command with payload to local API: /player/play Feb 21 19:56:07 volumio go-librespot[24773]: time="2026-02-21T19:56:07+02:00" level=debug msg="resolved context of track" uri="spotify:track:2iUFMaHe6sucVzQAQZFH1s" Feb 21 19:56:07 volumio go-librespot[24773]: time="2026-02-21T19:56:07+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:2iUFMaHe6sucVzQAQZFH1s" Feb 21 19:56:07 volumio go-librespot[24773]: time="2026-02-21T19:56:07+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:2iUFMaHe6sucVzQAQZFH1s" Feb 21 19:56:07 volumio go-librespot[24773]: time="2026-02-21T19:56:07+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 21 19:56:07 volumio go-librespot[24773]: time="2026-02-21T19:56:07+02:00" level=trace msg="emitting websocket event: will_play" Feb 21 19:56:07 volumio volumio[1302]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:2iUFMaHe6sucVzQAQZFH1s","uri":"spotify:track:2iUFMaHe6sucVzQAQZFH1s","play_origin":"go-librespot"}} Feb 21 19:56:07 volumio volumio[1302]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:2iUFMaHe6sucVzQAQZFH1s","uri":"spotify:track:2iUFMaHe6sucVzQAQZFH1s","play_origin":"go-librespot"}} Feb 21 19:56:07 volumio volumio[1302]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:2iUFMaHe6sucVzQAQZFH1s","uri":"spotify:track:2iUFMaHe6sucVzQAQZFH1s","play_origin":"go-librespot"}} Feb 21 19:56:07 volumio volumio[1302]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:2iUFMaHe6sucVzQAQZFH1s","uri":"spotify:track:2iUFMaHe6sucVzQAQZFH1s","play_origin":"go-librespot"}} Feb 21 19:56:07 volumio volumio[1302]: info: CoreCommandRouter::volumioPlay Feb 21 19:56:07 volumio volumio[1302]: info: CoreStateMachine::play index undefined Feb 21 19:56:07 volumio volumio[1302]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 21 19:56:07 volumio volumio[1302]: info: CorePlayQueue::getTrack 0 Feb 21 19:56:07 volumio volumio[1302]: info: CoreStateMachine::startPlaybackTimer Feb 21 19:56:07 volumio volumio[1302]: info: CorePlayQueue::getTrack 0 Feb 21 19:56:07 volumio volumio[1302]: info: [1771696567450] ControllerSpotify::clearAddPlayTrack Feb 21 19:56:07 volumio volumio[1302]: info: Sending Spotify command with payload to local API: /player/play Feb 21 19:56:07 volumio go-librespot[24773]: time="2026-02-21T19:56:07+02:00" level=debug msg="selected format OGG_VORBIS_320 (1666a3ad8ba0c728625824ff85f39dea56b2b998)" uri="spotify:track:2iUFMaHe6sucVzQAQZFH1s" Feb 21 19:56:07 volumio go-librespot[24773]: time="2026-02-21T19:56:07+02:00" level=debug msg="requested aes key for file 1666a3ad8ba0c728625824ff85f39dea56b2b998, gid: 2iUFMaHe6sucVzQAQZFH1s" Feb 21 19:56:07 volumio go-librespot[24773]: time="2026-02-21T19:56:07+02:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:2iUFMaHe6sucVzQAQZFH1s: failed retrieving audio key: failed retrieving aes key with code 1" Feb 21 19:56:07 volumio volumio[1302]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Feb 21 19:56:07 volumio volumio[1302]: info: CoreCommandRouter::volumioPlay Feb 21 19:56:07 volumio volumio[1302]: info: CoreStateMachine::play index undefined Feb 21 19:56:07 volumio volumio[1302]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 21 19:56:07 volumio volumio[1302]: info: CorePlayQueue::getTrack 0 Feb 21 19:56:07 volumio volumio[1302]: info: CoreStateMachine::startPlaybackTimer Feb 21 19:56:07 volumio volumio[1302]: info: CorePlayQueue::getTrack 0 Feb 21 19:56:07 volumio volumio[1302]: info: [1771696567674] ControllerSpotify::clearAddPlayTrack Feb 21 19:56:07 volumio volumio[1302]: info: Sending Spotify command with payload to local API: /player/play Feb 21 19:56:07 volumio go-librespot[24773]: time="2026-02-21T19:56:07+02:00" level=debug msg="resolved context of track" uri="spotify:track:2iUFMaHe6sucVzQAQZFH1s" Feb 21 19:56:07 volumio go-librespot[24773]: time="2026-02-21T19:56:07+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:2iUFMaHe6sucVzQAQZFH1s" Feb 21 19:56:07 volumio go-librespot[24773]: time="2026-02-21T19:56:07+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:2iUFMaHe6sucVzQAQZFH1s" Feb 21 19:56:07 volumio go-librespot[24773]: time="2026-02-21T19:56:07+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 21 19:56:07 volumio go-librespot[24773]: time="2026-02-21T19:56:07+02:00" level=trace msg="emitting websocket event: will_play" Feb 21 19:56:07 volumio volumio[1302]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:2iUFMaHe6sucVzQAQZFH1s","uri":"spotify:track:2iUFMaHe6sucVzQAQZFH1s","play_origin":"go-librespot"}} Feb 21 19:56:07 volumio volumio[1302]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:2iUFMaHe6sucVzQAQZFH1s","uri":"spotify:track:2iUFMaHe6sucVzQAQZFH1s","play_origin":"go-librespot"}} Feb 21 19:56:07 volumio volumio[1302]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:2iUFMaHe6sucVzQAQZFH1s","uri":"spotify:track:2iUFMaHe6sucVzQAQZFH1s","play_origin":"go-librespot"}} Feb 21 19:56:07 volumio volumio[1302]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:2iUFMaHe6sucVzQAQZFH1s","uri":"spotify:track:2iUFMaHe6sucVzQAQZFH1s","play_origin":"go-librespot"}} Feb 21 19:56:08 volumio volumio[1302]: info: CoreCommandRouter::volumioPlay Feb 21 19:56:08 volumio volumio[1302]: info: CoreStateMachine::play index undefined Feb 21 19:56:08 volumio volumio[1302]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 21 19:56:08 volumio volumio[1302]: info: CorePlayQueue::getTrack 0 Feb 21 19:56:08 volumio volumio[1302]: info: CoreStateMachine::startPlaybackTimer Feb 21 19:56:08 volumio volumio[1302]: info: CorePlayQueue::getTrack 0 Feb 21 19:56:08 volumio volumio[1302]: info: [1771696568139] ControllerSpotify::clearAddPlayTrack Feb 21 19:56:08 volumio volumio[1302]: info: Sending Spotify command with payload to local API: /player/play Feb 21 19:56:08 volumio go-librespot[24773]: time="2026-02-21T19:56:08+02:00" level=debug msg="selected format OGG_VORBIS_320 (1666a3ad8ba0c728625824ff85f39dea56b2b998)" uri="spotify:track:2iUFMaHe6sucVzQAQZFH1s" Feb 21 19:56:08 volumio go-librespot[24773]: time="2026-02-21T19:56:08+02:00" level=debug msg="requested aes key for file 1666a3ad8ba0c728625824ff85f39dea56b2b998, gid: 2iUFMaHe6sucVzQAQZFH1s" Feb 21 19:56:08 volumio go-librespot[24773]: time="2026-02-21T19:56:08+02:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:2iUFMaHe6sucVzQAQZFH1s: failed retrieving audio key: failed retrieving aes key with code 1" Feb 21 19:56:08 volumio volumio[1302]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Feb 21 19:56:08 volumio go-librespot[24773]: time="2026-02-21T19:56:08+02:00" level=debug msg="resolved context of track" uri="spotify:track:2iUFMaHe6sucVzQAQZFH1s" Feb 21 19:56:08 volumio go-librespot[24773]: time="2026-02-21T19:56:08+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:2iUFMaHe6sucVzQAQZFH1s" Feb 21 19:56:08 volumio go-librespot[24773]: time="2026-02-21T19:56:08+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:2iUFMaHe6sucVzQAQZFH1s" Feb 21 19:56:08 volumio go-librespot[24773]: time="2026-02-21T19:56:08+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 21 19:56:08 volumio go-librespot[24773]: time="2026-02-21T19:56:08+02:00" level=trace msg="emitting websocket event: will_play" Feb 21 19:56:08 volumio volumio[1302]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:2iUFMaHe6sucVzQAQZFH1s","uri":"spotify:track:2iUFMaHe6sucVzQAQZFH1s","play_origin":"go-librespot"}} Feb 21 19:56:08 volumio volumio[1302]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:2iUFMaHe6sucVzQAQZFH1s","uri":"spotify:track:2iUFMaHe6sucVzQAQZFH1s","play_origin":"go-librespot"}} Feb 21 19:56:08 volumio volumio[1302]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:2iUFMaHe6sucVzQAQZFH1s","uri":"spotify:track:2iUFMaHe6sucVzQAQZFH1s","play_origin":"go-librespot"}} Feb 21 19:56:08 volumio volumio[1302]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:2iUFMaHe6sucVzQAQZFH1s","uri":"spotify:track:2iUFMaHe6sucVzQAQZFH1s","play_origin":"go-librespot"}} Feb 21 19:56:08 volumio go-librespot[24773]: time="2026-02-21T19:56:08+02:00" level=debug msg="selected format OGG_VORBIS_320 (1666a3ad8ba0c728625824ff85f39dea56b2b998)" uri="spotify:track:2iUFMaHe6sucVzQAQZFH1s" Feb 21 19:56:08 volumio go-librespot[24773]: time="2026-02-21T19:56:08+02:00" level=debug msg="requested aes key for file 1666a3ad8ba0c728625824ff85f39dea56b2b998, gid: 2iUFMaHe6sucVzQAQZFH1s" Feb 21 19:56:08 volumio go-librespot[24773]: time="2026-02-21T19:56:08+02:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:2iUFMaHe6sucVzQAQZFH1s: failed retrieving audio key: failed retrieving aes key with code 1" Feb 21 19:56:08 volumio volumio[1302]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Feb 21 19:56:08 volumio go-librespot[24773]: time="2026-02-21T19:56:08+02:00" level=debug msg="resolved context of track" uri="spotify:track:2iUFMaHe6sucVzQAQZFH1s" Feb 21 19:56:08 volumio go-librespot[24773]: time="2026-02-21T19:56:08+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:2iUFMaHe6sucVzQAQZFH1s" Feb 21 19:56:08 volumio go-librespot[24773]: time="2026-02-21T19:56:08+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:2iUFMaHe6sucVzQAQZFH1s" Feb 21 19:56:08 volumio go-librespot[24773]: time="2026-02-21T19:56:08+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 21 19:56:08 volumio go-librespot[24773]: time="2026-02-21T19:56:08+02:00" level=trace msg="emitting websocket event: will_play" Feb 21 19:56:08 volumio volumio[1302]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:2iUFMaHe6sucVzQAQZFH1s","uri":"spotify:track:2iUFMaHe6sucVzQAQZFH1s","play_origin":"go-librespot"}} Feb 21 19:56:08 volumio volumio[1302]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:2iUFMaHe6sucVzQAQZFH1s","uri":"spotify:track:2iUFMaHe6sucVzQAQZFH1s","play_origin":"go-librespot"}} Feb 21 19:56:08 volumio volumio[1302]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:2iUFMaHe6sucVzQAQZFH1s","uri":"spotify:track:2iUFMaHe6sucVzQAQZFH1s","play_origin":"go-librespot"}} Feb 21 19:56:08 volumio volumio[1302]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:2iUFMaHe6sucVzQAQZFH1s","uri":"spotify:track:2iUFMaHe6sucVzQAQZFH1s","play_origin":"go-librespot"}} Feb 21 19:56:09 volumio go-librespot[24773]: time="2026-02-21T19:56:09+02:00" level=debug msg="selected format OGG_VORBIS_320 (1666a3ad8ba0c728625824ff85f39dea56b2b998)" uri="spotify:track:2iUFMaHe6sucVzQAQZFH1s" Feb 21 19:56:09 volumio go-librespot[24773]: time="2026-02-21T19:56:09+02:00" level=debug msg="requested aes key for file 1666a3ad8ba0c728625824ff85f39dea56b2b998, gid: 2iUFMaHe6sucVzQAQZFH1s" Feb 21 19:56:09 volumio go-librespot[24773]: time="2026-02-21T19:56:09+02:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:2iUFMaHe6sucVzQAQZFH1s: failed retrieving audio key: failed retrieving aes key with code 1" Feb 21 19:56:09 volumio volumio[1302]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Feb 21 19:56:15 volumio volumio[1302]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Feb 21 19:56:15 volumio volumio[1302]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Feb 21 19:56:15 volumio volumio[1302]: info: Creating Spotify config file Feb 21 19:56:15 volumio volumio[1302]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 19:56:15 volumio volumio[1302]: info: Spotify config file written Feb 21 19:56:15 volumio sudo[24844]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 21 19:56:15 volumio sudo[24844]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 21 19:56:15 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Feb 21 19:56:15 volumio systemd[1]: go-librespot-daemon.service: Killing process 24782 (go-librespot) with signal SIGKILL. Feb 21 19:56:15 volumio volumio[1302]: info: Connection to go-librespot Websocket closed Feb 21 19:56:15 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Feb 21 19:56:15 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 21 19:56:15 volumio volumio[1302]: info: Connection to go-librespot Websocket closed Feb 21 19:56:15 volumio volumio[1302]: info: Connection to go-librespot Websocket closed Feb 21 19:56:15 volumio volumio[1302]: info: Connection to go-librespot Websocket closed Feb 21 19:56:15 volumio volumio[1302]: info: Connection to go-librespot Websocket closed Feb 21 19:56:16 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 21 19:56:16 volumio sudo[24844]: pam_unix(sudo:session): session closed for user root Feb 21 19:56:16 volumio go-librespot[24846]: go-librespot daemon starting... Feb 21 19:56:16 volumio go-librespot[24848]: time="2026-02-21T19:56:16+02:00" level=info msg="running go-librespot 0.6.2" Feb 21 19:56:16 volumio go-librespot[24848]: time="2026-02-21T19:56:16+02:00" level=debug msg="app state loaded" Feb 21 19:56:16 volumio go-librespot[24848]: time="2026-02-21T19:56:16+02:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 21 19:56:16 volumio go-librespot[24848]: time="2026-02-21T19:56:16+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Feb 21 19:56:16 volumio go-librespot[24848]: time="2026-02-21T19:56:16+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 21 19:56:16 volumio go-librespot[24848]: time="2026-02-21T19:56:16+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 21 19:56:16 volumio go-librespot[24848]: time="2026-02-21T19:56:16+02:00" level=info msg="zeroconf server listening on port 42969" Feb 21 19:56:16 volumio go-librespot[24848]: time="2026-02-21T19:56:16+02:00" level=debug msg="obtained new client token: AAAI9Mc8gQtqUMOvzNfvB/illLTQikN39MsVt6XjiLWJWBW6s4KNN7WccbA6KF0GaVwpjUpwT69s3phscuGB/yJJ1mkosVxMWT6h+Jla7KneS866DKzLdlYmsp+g+JxphuGtl3ooybxK31x/1wgsvIMGVimFWV0lPDlWm2Gc4kFRBb4ozAiGPkPUhm7LwZr5+XKldQ0v3rRnISGt4hm78zQU1G0VpD9HuxAOIx1RMuN29Bnz4Y+MD7ad" Feb 21 19:56:16 volumio go-librespot[24848]: time="2026-02-21T19:56:16+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Feb 21 19:56:16 volumio go-librespot[24848]: time="2026-02-21T19:56:16+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Feb 21 19:56:17 volumio go-librespot[24848]: time="2026-02-21T19:56:17+02:00" level=debug msg="connected to ap-gew1.spotify.com:443" Feb 21 19:56:17 volumio go-librespot[24848]: time="2026-02-21T19:56:17+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Feb 21 19:56:18 volumio go-librespot[24848]: time="2026-02-21T19:56:18+02:00" level=debug msg="connected to ap-gew1.spotify.com:80" Feb 21 19:56:18 volumio go-librespot[24848]: time="2026-02-21T19:56:18+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: read tcp 192.168.37.195:37072->104.199.65.9:80: read: connection reset by peer" Feb 21 19:56:18 volumio volumio[1302]: info: CoreCommandRouter::volumioPlay Feb 21 19:56:18 volumio volumio[1302]: info: CoreStateMachine::play index undefined Feb 21 19:56:18 volumio volumio[1302]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 21 19:56:18 volumio volumio[1302]: info: CorePlayQueue::getTrack 0 Feb 21 19:56:18 volumio volumio[1302]: info: CoreStateMachine::startPlaybackTimer Feb 21 19:56:18 volumio volumio[1302]: info: CorePlayQueue::getTrack 0 Feb 21 19:56:18 volumio volumio[1302]: info: [1771696578650] ControllerSpotify::clearAddPlayTrack Feb 21 19:56:18 volumio volumio[1302]: info: Sending Spotify command with payload to local API: /player/play Feb 21 19:56:18 volumio go-librespot[24848]: time="2026-02-21T19:56:18+02:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Feb 21 19:56:18 volumio volumio[1302]: info: Initializing connection to go-librespot Websocket Feb 21 19:56:18 volumio go-librespot[24848]: time="2026-02-21T19:56:18+02:00" level=debug msg="new websocket client" Feb 21 19:56:18 volumio volumio[1302]: info: Connection to go-librespot Websocket established Feb 21 19:56:19 volumio volumio[1302]: info: go-librespot daemon successfully initialized Feb 21 19:56:19 volumio go-librespot[24848]: time="2026-02-21T19:56:19+02:00" level=debug msg="completed keyexchange" Feb 21 19:56:19 volumio go-librespot[24848]: time="2026-02-21T19:56:19+02:00" level=debug msg="completed challenge" Feb 21 19:56:19 volumio go-librespot[24848]: time="2026-02-21T19:56:19+02:00" level=info msg="authenticated AP" username="11*******84" Feb 21 19:56:19 volumio volumio[1302]: info: CoreCommandRouter::volumioPlay Feb 21 19:56:19 volumio volumio[1302]: info: CoreStateMachine::play index undefined Feb 21 19:56:19 volumio volumio[1302]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 21 19:56:19 volumio volumio[1302]: info: CorePlayQueue::getTrack 0 Feb 21 19:56:19 volumio volumio[1302]: info: CoreStateMachine::startPlaybackTimer Feb 21 19:56:19 volumio volumio[1302]: info: CorePlayQueue::getTrack 0 Feb 21 19:56:19 volumio volumio[1302]: info: [1771696579522] ControllerSpotify::clearAddPlayTrack Feb 21 19:56:19 volumio volumio[1302]: info: Sending Spotify command with payload to local API: /player/play Feb 21 19:56:19 volumio go-librespot[24848]: time="2026-02-21T19:56:19+02:00" level=info msg="authenticated Login5" username="11*******84" Feb 21 19:56:19 volumio go-librespot[24848]: time="2026-02-21T19:56:19+02:00" level=debug msg="initializing zeroconf session" username="11*******84" Feb 21 19:56:19 volumio go-librespot[24848]: time="2026-02-21T19:56:19+02:00" level=debug msg="dealer connection opened" Feb 21 19:56:19 volumio go-librespot[24848]: time="2026-02-21T19:56:19+02:00" level=trace msg="starting accesspoint recv loop" Feb 21 19:56:19 volumio go-librespot[24848]: time="2026-02-21T19:56:19+02:00" level=trace msg="starting dealer recv loop" Feb 21 19:56:19 volumio go-librespot[24848]: time="2026-02-21T19:56:19+02:00" level=trace msg="received accesspoint ping" Feb 21 19:56:19 volumio go-librespot[24848]: time="2026-02-21T19:56:19+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Feb 21 19:56:19 volumio go-librespot[24848]: time="2026-02-21T19:56:19+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Feb 21 19:56:19 volumio volumio[1302]: info: CoreCommandRouter::volumioPlay Feb 21 19:56:19 volumio volumio[1302]: info: CoreStateMachine::play index undefined Feb 21 19:56:19 volumio volumio[1302]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 21 19:56:19 volumio volumio[1302]: info: CorePlayQueue::getTrack 0 Feb 21 19:56:19 volumio volumio[1302]: info: CoreStateMachine::startPlaybackTimer Feb 21 19:56:19 volumio volumio[1302]: info: CorePlayQueue::getTrack 0 Feb 21 19:56:19 volumio volumio[1302]: info: [1771696579998] ControllerSpotify::clearAddPlayTrack Feb 21 19:56:19 volumio volumio[1302]: info: Sending Spotify command with payload to local API: /player/play Feb 21 19:56:20 volumio go-librespot[24848]: time="2026-02-21T19:56:20+02:00" level=debug msg="resolved context of track" uri="spotify:track:2iUFMaHe6sucVzQAQZFH1s" Feb 21 19:56:20 volumio go-librespot[24848]: time="2026-02-21T19:56:20+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:2iUFMaHe6sucVzQAQZFH1s" Feb 21 19:56:20 volumio go-librespot[24848]: time="2026-02-21T19:56:20+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:2iUFMaHe6sucVzQAQZFH1s" Feb 21 19:56:20 volumio go-librespot[24848]: time="2026-02-21T19:56:20+02:00" level=debug msg="put state request failed with status 400: Require at least one of callback url or connection id" Feb 21 19:56:20 volumio volumio[1302]: info: CoreCommandRouter::volumioPrevious Feb 21 19:56:20 volumio volumio[1302]: info: CoreStateMachine::previous Feb 21 19:56:21 volumio go-librespot[24848]: time="2026-02-21T19:56:21+02:00" level=debug msg="put state request failed with status 400: Require at least one of callback url or connection id" Feb 21 19:56:21 volumio volumio[1302]: info: Display-configuration --- → Sleep (DPMS) triggered after 120s Feb 21 19:56:21 volumio volumio[1302]: info: Display-configuration --- sleepScreen: DPMS - screen off in 120s Feb 21 19:56:21 volumio volumio[1302]: info: Getting Spotify volume Feb 21 19:56:21 volumio volumio[1302]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 10 Feb 21 19:56:21 volumio volumio[1302]: info: CoreCommandRouter::volumioGetState Feb 21 19:56:21 volumio volumio[1302]: info: CorePlayQueue::getTrack 0 Feb 21 19:56:22 volumio volumio[1302]: SPOTIFY: RECEIVED VOLUMIO VOLUME 79 Feb 21 19:56:22 volumio volumio[1302]: info: Initializing connection to go-librespot Websocket Feb 21 19:56:22 volumio go-librespot[24848]: time="2026-02-21T19:56:22+02:00" level=debug msg="new websocket client" Feb 21 19:56:22 volumio volumio[1302]: info: Connection to go-librespot Websocket established Feb 21 19:56:22 volumio go-librespot[24848]: time="2026-02-21T19:56:22+02:00" level=debug msg="put state request failed with status 400: Require at least one of callback url or connection id" Feb 21 19:56:22 volumio go-librespot[24848]: time="2026-02-21T19:56:22+02:00" level=error msg="failed put state after update" error="put state request failed with status 400: Require at least one of callback url or connection id" Feb 21 19:56:22 volumio go-librespot[24848]: time="2026-02-21T19:56:22+02:00" level=trace msg="emitting websocket event: will_play" Feb 21 19:56:22 volumio volumio[1302]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:2iUFMaHe6sucVzQAQZFH1s","uri":"spotify:track:2iUFMaHe6sucVzQAQZFH1s","play_origin":"go-librespot"}} Feb 21 19:56:22 volumio volumio[1302]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:2iUFMaHe6sucVzQAQZFH1s","uri":"spotify:track:2iUFMaHe6sucVzQAQZFH1s","play_origin":"go-librespot"}} Feb 21 19:56:22 volumio volumio[1302]: info: CoreCommandRouter::volumioNext Feb 21 19:56:22 volumio volumio[1302]: info: CoreStateMachine::next Feb 21 19:56:22 volumio volumio[1302]: info: CoreStateMachine::stop Feb 21 19:56:22 volumio volumio[1302]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 21 19:56:22 volumio volumio[1302]: info: CoreStateMachine::play index undefined Feb 21 19:56:22 volumio volumio[1302]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 21 19:56:22 volumio volumio[1302]: info: CorePlayQueue::getTrack 1 Feb 21 19:56:22 volumio volumio[1302]: info: CoreStateMachine::startPlaybackTimer Feb 21 19:56:22 volumio volumio[1302]: info: CorePlayQueue::getTrack 1 Feb 21 19:56:22 volumio volumio[1302]: info: [1771696582466] ControllerSpotify::clearAddPlayTrack Feb 21 19:56:22 volumio volumio[1302]: info: Sending Spotify command with payload to local API: /player/play Feb 21 19:56:22 volumio volumio[1302]: info: CoreStateMachine::updateTrackBlock Feb 21 19:56:22 volumio volumio[1302]: info: CorePlayQueue::getTrackBlock Feb 21 19:56:22 volumio go-librespot[24848]: time="2026-02-21T19:56:22+02:00" level=debug msg="selected format OGG_VORBIS_320 (1666a3ad8ba0c728625824ff85f39dea56b2b998)" uri="spotify:track:2iUFMaHe6sucVzQAQZFH1s" Feb 21 19:56:22 volumio go-librespot[24848]: time="2026-02-21T19:56:22+02:00" level=debug msg="requested aes key for file 1666a3ad8ba0c728625824ff85f39dea56b2b998, gid: 2iUFMaHe6sucVzQAQZFH1s" Feb 21 19:56:23 volumio volumio[1302]: info: CoreCommandRouter::volumioNext Feb 21 19:56:23 volumio volumio[1302]: info: CoreStateMachine::next Feb 21 19:56:23 volumio volumio[1302]: info: CoreStateMachine::stop Feb 21 19:56:23 volumio volumio[1302]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 21 19:56:23 volumio volumio[1302]: info: CoreStateMachine::play index undefined Feb 21 19:56:23 volumio volumio[1302]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 21 19:56:23 volumio volumio[1302]: info: CorePlayQueue::getTrack 2 Feb 21 19:56:23 volumio volumio[1302]: info: CoreStateMachine::startPlaybackTimer Feb 21 19:56:23 volumio volumio[1302]: info: CorePlayQueue::getTrack 2 Feb 21 19:56:23 volumio volumio[1302]: info: [1771696583195] ControllerSpotify::clearAddPlayTrack Feb 21 19:56:23 volumio volumio[1302]: info: Sending Spotify command with payload to local API: /player/play Feb 21 19:56:23 volumio volumio[1302]: info: CoreStateMachine::updateTrackBlock Feb 21 19:56:23 volumio volumio[1302]: info: CorePlayQueue::getTrackBlock Feb 21 19:56:23 volumio volumio[1302]: info: CoreCommandRouter::volumioNext Feb 21 19:56:23 volumio volumio[1302]: info: CoreStateMachine::next Feb 21 19:56:23 volumio volumio[1302]: info: CoreStateMachine::stop Feb 21 19:56:23 volumio volumio[1302]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 21 19:56:23 volumio volumio[1302]: info: CoreStateMachine::play index undefined Feb 21 19:56:23 volumio volumio[1302]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 21 19:56:23 volumio volumio[1302]: info: CorePlayQueue::getTrack 3 Feb 21 19:56:23 volumio volumio[1302]: info: CoreStateMachine::startPlaybackTimer Feb 21 19:56:23 volumio volumio[1302]: info: CorePlayQueue::getTrack 3 Feb 21 19:56:23 volumio volumio[1302]: info: [1771696583651] ControllerSpotify::clearAddPlayTrack Feb 21 19:56:23 volumio volumio[1302]: info: Sending Spotify command with payload to local API: /player/play Feb 21 19:56:23 volumio volumio[1302]: info: CoreStateMachine::updateTrackBlock Feb 21 19:56:23 volumio volumio[1302]: info: CorePlayQueue::getTrackBlock Feb 21 19:56:24 volumio volumio[1302]: info: CoreCommandRouter::volumioNext Feb 21 19:56:24 volumio volumio[1302]: info: CoreStateMachine::next Feb 21 19:56:24 volumio volumio[1302]: info: CoreStateMachine::stop Feb 21 19:56:24 volumio volumio[1302]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 21 19:56:24 volumio volumio[1302]: info: CoreStateMachine::play index undefined Feb 21 19:56:24 volumio volumio[1302]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 21 19:56:24 volumio volumio[1302]: info: CorePlayQueue::getTrack 4 Feb 21 19:56:24 volumio volumio[1302]: info: CoreStateMachine::startPlaybackTimer Feb 21 19:56:24 volumio volumio[1302]: info: CorePlayQueue::getTrack 4 Feb 21 19:56:24 volumio volumio[1302]: info: [1771696584123] ControllerSpotify::clearAddPlayTrack Feb 21 19:56:24 volumio volumio[1302]: info: Sending Spotify command with payload to local API: /player/play Feb 21 19:56:24 volumio volumio[1302]: info: CoreStateMachine::updateTrackBlock Feb 21 19:56:24 volumio volumio[1302]: info: CorePlayQueue::getTrackBlock Feb 21 19:56:24 volumio volumio[1302]: info: CoreCommandRouter::volumioPrevious Feb 21 19:56:24 volumio volumio[1302]: info: CoreStateMachine::previous Feb 21 19:56:24 volumio volumio[1302]: info: CoreStateMachine::updateTrackBlock Feb 21 19:56:24 volumio volumio[1302]: info: CorePlayQueue::getTrackBlock Feb 21 19:56:24 volumio volumio[1302]: info: CoreStateMachine::pushState Feb 21 19:56:24 volumio volumio[1302]: info: CorePlayQueue::getTrack 3 Feb 21 19:56:24 volumio volumio[1302]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 21 19:56:24 volumio volumio[1302]: info: CoreCommandRouter::volumioPushState Feb 21 19:56:24 volumio volumio[1302]: info: FusionDsp - Volumio is not playing Feb 21 19:56:24 volumio volumio[1302]: info: FusionDsp - Clipped samples monitor stopped Feb 21 19:56:24 volumio volumio[1302]: info: Display-configuration --- Volumio status=stop timeout=120 noifplay=true screensavertype=dpms Feb 21 19:56:24 volumio volumio[1302]: SPOTIFY: RECEIVED VOLUMIO VOLUME 79 Feb 21 19:56:25 volumio volumio[1302]: info: Getting Spotify volume Feb 21 19:56:25 volumio volumio[1302]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 10 Feb 21 19:56:25 volumio volumio[1302]: info: CoreCommandRouter::volumioGetState Feb 21 19:56:25 volumio volumio[1302]: info: CorePlayQueue::getTrack 3 Feb 21 19:56:25 volumio volumio[1302]: SPOTIFY: RECEIVED VOLUMIO VOLUME 79 Feb 21 19:56:26 volumio volumio[1302]: info: CoreCommandRouter::volumioPlay Feb 21 19:56:26 volumio volumio[1302]: info: CoreStateMachine::play index undefined Feb 21 19:56:26 volumio volumio[1302]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 21 19:56:26 volumio volumio[1302]: info: CorePlayQueue::getTrack 3 Feb 21 19:56:26 volumio volumio[1302]: info: CoreStateMachine::startPlaybackTimer Feb 21 19:56:26 volumio volumio[1302]: info: CorePlayQueue::getTrack 3 Feb 21 19:56:26 volumio volumio[1302]: info: [1771696586830] ControllerSpotify::clearAddPlayTrack Feb 21 19:56:26 volumio volumio[1302]: info: Sending Spotify command with payload to local API: /player/play Feb 21 19:56:28 volumio volumio[1302]: info: CoreCommandRouter::volumioPlay Feb 21 19:56:28 volumio volumio[1302]: info: CoreStateMachine::play index undefined Feb 21 19:56:28 volumio volumio[1302]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 21 19:56:28 volumio volumio[1302]: info: CorePlayQueue::getTrack 3 Feb 21 19:56:28 volumio volumio[1302]: info: CoreStateMachine::startPlaybackTimer Feb 21 19:56:28 volumio volumio[1302]: info: CorePlayQueue::getTrack 3 Feb 21 19:56:28 volumio volumio[1302]: info: [1771696588362] ControllerSpotify::clearAddPlayTrack Feb 21 19:56:28 volumio volumio[1302]: info: Sending Spotify command with payload to local API: /player/play Feb 21 19:56:36 volumio volumio[1302]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Feb 21 19:56:36 volumio volumio[1302]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Feb 21 19:56:36 volumio volumio[1302]: info: Creating Spotify config file Feb 21 19:56:36 volumio volumio[1302]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 19:56:36 volumio volumio[1302]: info: Spotify config file written Feb 21 19:56:36 volumio sudo[24911]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 21 19:56:36 volumio sudo[24911]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 21 19:56:36 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Feb 21 19:56:36 volumio systemd[1]: go-librespot-daemon.service: Killing process 24853 (go-librespot) with signal SIGKILL. Feb 21 19:56:36 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Feb 21 19:56:36 volumio volumio[1302]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up Feb 21 19:56:36 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 21 19:56:36 volumio volumio[1302]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up Feb 21 19:56:36 volumio volumio[1302]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 21 19:56:36 volumio volumio[1302]: Error: socket hang up Feb 21 19:56:36 volumio volumio[1302]: at connResetException (node:internal/errors:720:14) Feb 21 19:56:36 volumio volumio[1302]: at Socket.socketOnEnd (node:_http_client:519:23) Feb 21 19:56:36 volumio volumio[1302]: at Socket.emit (node:events:526:35) Feb 21 19:56:36 volumio volumio[1302]: at endReadableNT (node:internal/streams/readable:1376:12) Feb 21 19:56:36 volumio volumio[1302]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Feb 21 19:56:36 volumio volumio[1302]: code: 'ECONNRESET', Feb 21 19:56:36 volumio volumio[1302]: response: undefined Feb 21 19:56:36 volumio volumio[1302]: } Feb 21 19:56:36 volumio volumio[1302]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 21 19:56:36 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 21 19:56:36 volumio sudo[24911]: pam_unix(sudo:session): session closed for user root Feb 21 19:56:36 volumio go-librespot[24914]: go-librespot daemon starting... Feb 21 19:56:36 volumio go-librespot[24926]: time="2026-02-21T19:56:36+02:00" level=info msg="running go-librespot 0.6.2" Feb 21 19:56:36 volumio go-librespot[24926]: time="2026-02-21T19:56:36+02:00" level=debug msg="app state loaded" Feb 21 19:56:36 volumio go-librespot[24926]: time="2026-02-21T19:56:36+02:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 21 19:56:36 volumio sudo[24937]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-02-21 19:55' Feb 21 19:56:36 volumio sudo[24937]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) 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="a78d359cf1dc63ac74e9d151015afd30d31a709a" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="c1ffe93b2136013fc1b5903a4ed7e3f34e0a7bec" VOLUMIO_ARCH="x64" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu Feb 5 14:31:57 UTC 2026" VOLUMIO_VERSION="4.096" VOLUMIO_HARDWARE="x86_amd64" VOLUMIO_DEVICENAME="x86_64" VOLUMIO_HASH="6759e875c98b942866984e844891d6c1"