Feb 17 17:11:00 volumio volumio[1355]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Feb 17 17:11:00 volumio volumio[1355]: info: In handleBrowseUri, curUri=spotify:album:2ANVost0y2y52ema1E9xAZ Feb 17 17:11:01 volumio volumio[1355]: info: Preload queue cleared Feb 17 17:11:01 volumio volumio[1355]: info: Preloading song: spotify:track:1hu2s7qkm5bo03eODpRQO3 Feb 17 17:11:01 volumio volumio[1355]: info: Preloading song: spotify:track:6XYbMGvtl6tlPoGWaiH7EY Feb 17 17:11:01 volumio volumio[1355]: info: Preloading song: spotify:track:4IT6vDuKprKl6jyVndlY8V Feb 17 17:11:01 volumio volumio[1355]: info: Preloading song: spotify:track:2LlQb7Uoj1kKyGhlkBf9aC Feb 17 17:11:01 volumio volumio[1355]: info: Preloading song: spotify:track:3BovdzfaX4jb5KFQwoPfAw Feb 17 17:11:01 volumio volumio[1355]: info: Preloading song: spotify:track:7J1uxwnxfQLu4APicE5Rnj Feb 17 17:11:01 volumio volumio[1355]: info: Preloading song: spotify:track:4cgjA7B4fJBHyB9Ya2bu0t Feb 17 17:11:01 volumio volumio[1355]: info: Preloading song: spotify:track:1CgmY8fVN7kstVDZmsdM5k Feb 17 17:11:01 volumio volumio[1355]: info: Preloading song: spotify:track:07L1pzoVerhRSSaDGZHrKy Feb 17 17:11:01 volumio volumio[1355]: info: Exploding uri spotify:track:1hu2s7qkm5bo03eODpRQO3 in service spop Feb 17 17:11:01 volumio volumio[1355]: SPOTIFY: EXPLODING URI:spotify:track:1hu2s7qkm5bo03eODpRQO3 Feb 17 17:11:01 volumio volumio[1355]: info: No valid Plugin REST Endpoint Feb 17 17:11:01 volumio volumio[1355]: info: Exploding uri spotify:track:6XYbMGvtl6tlPoGWaiH7EY in service spop Feb 17 17:11:01 volumio volumio[1355]: SPOTIFY: EXPLODING URI:spotify:track:6XYbMGvtl6tlPoGWaiH7EY Feb 17 17:11:01 volumio volumio[1355]: info: Exploding uri spotify:track:4IT6vDuKprKl6jyVndlY8V in service spop Feb 17 17:11:01 volumio volumio[1355]: SPOTIFY: EXPLODING URI:spotify:track:4IT6vDuKprKl6jyVndlY8V Feb 17 17:11:01 volumio volumio[1355]: info: Exploding uri spotify:track:2LlQb7Uoj1kKyGhlkBf9aC in service spop Feb 17 17:11:01 volumio volumio[1355]: SPOTIFY: EXPLODING URI:spotify:track:2LlQb7Uoj1kKyGhlkBf9aC Feb 17 17:11:01 volumio volumio[1355]: info: Exploding uri spotify:track:3BovdzfaX4jb5KFQwoPfAw in service spop Feb 17 17:11:01 volumio volumio[1355]: SPOTIFY: EXPLODING URI:spotify:track:3BovdzfaX4jb5KFQwoPfAw Feb 17 17:11:01 volumio volumio[1355]: info: Exploding uri spotify:track:7J1uxwnxfQLu4APicE5Rnj in service spop Feb 17 17:11:01 volumio volumio[1355]: SPOTIFY: EXPLODING URI:spotify:track:7J1uxwnxfQLu4APicE5Rnj Feb 17 17:11:01 volumio volumio[1355]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:1hu2s7qkm5bo03eODpRQO3","service":"spop","name":"Wanna Be Startin' Somethin'","artist":"Michael Jackson","album":"Thriller","type":"song","duration":363,"albumart":"https://i.scdn.co/image/ab67616d0000b27332a7d87248d1b75463483df5","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Feb 17 17:11:01 volumio volumio[1355]: info: Exploding uri spotify:track:4cgjA7B4fJBHyB9Ya2bu0t in service spop Feb 17 17:11:01 volumio volumio[1355]: SPOTIFY: EXPLODING URI:spotify:track:4cgjA7B4fJBHyB9Ya2bu0t Feb 17 17:11:01 volumio volumio[1355]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6XYbMGvtl6tlPoGWaiH7EY","service":"spop","name":"Baby Be Mine","artist":"Michael Jackson","album":"Thriller","type":"song","duration":260,"albumart":"https://i.scdn.co/image/ab67616d0000b27332a7d87248d1b75463483df5","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Feb 17 17:11:01 volumio volumio[1355]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:4IT6vDuKprKl6jyVndlY8V","service":"spop","name":"The Girl Is Mine (with Paul McCartney)","artist":"Michael Jackson","album":"Thriller","type":"song","duration":222,"albumart":"https://i.scdn.co/image/ab67616d0000b27332a7d87248d1b75463483df5","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Feb 17 17:11:01 volumio volumio[1355]: info: Exploding uri spotify:track:1CgmY8fVN7kstVDZmsdM5k in service spop Feb 17 17:11:01 volumio volumio[1355]: SPOTIFY: EXPLODING URI:spotify:track:1CgmY8fVN7kstVDZmsdM5k Feb 17 17:11:01 volumio volumio[1355]: info: Exploding uri spotify:track:07L1pzoVerhRSSaDGZHrKy in service spop Feb 17 17:11:01 volumio volumio[1355]: SPOTIFY: EXPLODING URI:spotify:track:07L1pzoVerhRSSaDGZHrKy Feb 17 17:11:01 volumio volumio[1355]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:2LlQb7Uoj1kKyGhlkBf9aC","service":"spop","name":"Thriller","artist":"Michael Jackson","album":"Thriller","type":"song","duration":358,"albumart":"https://i.scdn.co/image/ab67616d0000b27332a7d87248d1b75463483df5","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Feb 17 17:11:01 volumio volumio[1355]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:3BovdzfaX4jb5KFQwoPfAw","service":"spop","name":"Beat It","artist":"Michael Jackson","album":"Thriller","type":"song","duration":258,"albumart":"https://i.scdn.co/image/ab67616d0000b27332a7d87248d1b75463483df5","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Feb 17 17:11:01 volumio volumio[1355]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:7J1uxwnxfQLu4APicE5Rnj","service":"spop","name":"Billie Jean","artist":"Michael Jackson","album":"Thriller","type":"song","duration":293,"albumart":"https://i.scdn.co/image/ab67616d0000b27332a7d87248d1b75463483df5","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Feb 17 17:11:01 volumio volumio[1355]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:4cgjA7B4fJBHyB9Ya2bu0t","service":"spop","name":"Human Nature","artist":"Michael Jackson","album":"Thriller","type":"song","duration":245,"albumart":"https://i.scdn.co/image/ab67616d0000b27332a7d87248d1b75463483df5","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Feb 17 17:11:01 volumio volumio[1355]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:1CgmY8fVN7kstVDZmsdM5k","service":"spop","name":"P.Y.T. (Pretty Young Thing)","artist":"Michael Jackson","album":"Thriller","type":"song","duration":238,"albumart":"https://i.scdn.co/image/ab67616d0000b27332a7d87248d1b75463483df5","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Feb 17 17:11:01 volumio volumio[1355]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:07L1pzoVerhRSSaDGZHrKy","service":"spop","name":"The Lady in My Life","artist":"Michael Jackson","album":"Thriller","type":"song","duration":298,"albumart":"https://i.scdn.co/image/ab67616d0000b27332a7d87248d1b75463483df5","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Feb 17 17:11:02 volumio volumio[1355]: info: Preload queue cleared Feb 17 17:11:02 volumio volumio[1355]: info: CoreCommandRouter::volumioReplaceandPlayItems Feb 17 17:11:02 volumio volumio[1355]: info: CoreStateMachine::ClearQueue Feb 17 17:11:02 volumio volumio[1355]: info: CoreStateMachine::stop Feb 17 17:11:02 volumio volumio[1355]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 17 17:11:02 volumio volumio[1355]: info: CorePlayQueue::clearPlayQueue Feb 17 17:11:02 volumio volumio[1355]: info: CorePlayQueue::saveQueue Feb 17 17:11:02 volumio volumio[1355]: info: CoreCommandRouter::volumioPushQueue Feb 17 17:11:02 volumio volumio[1355]: info: CoreStateMachine::addQueueItems Feb 17 17:11:02 volumio volumio[1355]: info: CorePlayQueue::addQueueItems Feb 17 17:11:02 volumio volumio[1355]: info: Preload queue cleared Feb 17 17:11:02 volumio volumio[1355]: info: Adding Item to queue: spotify:track:1hu2s7qkm5bo03eODpRQO3 Feb 17 17:11:02 volumio volumio[1355]: info: Using cached record of: spotify:track:1hu2s7qkm5bo03eODpRQO3 Feb 17 17:11:02 volumio volumio[1355]: info: CoreCommandRouter::volumioPushQueue Feb 17 17:11:02 volumio volumio[1355]: info: CorePlayQueue::saveQueue Feb 17 17:11:02 volumio volumio[1355]: info: CoreStateMachine::updateTrackBlock Feb 17 17:11:02 volumio volumio[1355]: info: CorePlayQueue::getTrackBlock Feb 17 17:11:02 volumio volumio[1355]: info: CoreCommandRouter::volumioPlay Feb 17 17:11:02 volumio volumio[1355]: info: CoreStateMachine::play index 0 Feb 17 17:11:02 volumio volumio[1355]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 17 17:11:02 volumio volumio[1355]: info: CoreStateMachine::addQueueItems Feb 17 17:11:02 volumio volumio[1355]: info: CorePlayQueue::addQueueItems Feb 17 17:11:02 volumio volumio[1355]: info: Preload queue cleared Feb 17 17:11:02 volumio volumio[1355]: info: Adding Item to queue: spotify:track:6XYbMGvtl6tlPoGWaiH7EY Feb 17 17:11:02 volumio volumio[1355]: info: Using cached record of: spotify:track:6XYbMGvtl6tlPoGWaiH7EY Feb 17 17:11:02 volumio volumio[1355]: info: Adding Item to queue: spotify:track:4IT6vDuKprKl6jyVndlY8V Feb 17 17:11:02 volumio volumio[1355]: info: Using cached record of: spotify:track:4IT6vDuKprKl6jyVndlY8V Feb 17 17:11:02 volumio volumio[1355]: info: Adding Item to queue: spotify:track:2LlQb7Uoj1kKyGhlkBf9aC Feb 17 17:11:02 volumio volumio[1355]: info: Using cached record of: spotify:track:2LlQb7Uoj1kKyGhlkBf9aC Feb 17 17:11:02 volumio volumio[1355]: info: Adding Item to queue: spotify:track:3BovdzfaX4jb5KFQwoPfAw Feb 17 17:11:02 volumio volumio[1355]: info: Using cached record of: spotify:track:3BovdzfaX4jb5KFQwoPfAw Feb 17 17:11:02 volumio volumio[1355]: info: Adding Item to queue: spotify:track:7J1uxwnxfQLu4APicE5Rnj Feb 17 17:11:02 volumio volumio[1355]: info: Using cached record of: spotify:track:7J1uxwnxfQLu4APicE5Rnj Feb 17 17:11:02 volumio volumio[1355]: info: Adding Item to queue: spotify:track:4cgjA7B4fJBHyB9Ya2bu0t Feb 17 17:11:02 volumio volumio[1355]: info: Using cached record of: spotify:track:4cgjA7B4fJBHyB9Ya2bu0t Feb 17 17:11:02 volumio volumio[1355]: info: Adding Item to queue: spotify:track:1CgmY8fVN7kstVDZmsdM5k Feb 17 17:11:02 volumio volumio[1355]: info: Using cached record of: spotify:track:1CgmY8fVN7kstVDZmsdM5k Feb 17 17:11:02 volumio volumio[1355]: info: Adding Item to queue: spotify:track:07L1pzoVerhRSSaDGZHrKy Feb 17 17:11:02 volumio volumio[1355]: info: Using cached record of: spotify:track:07L1pzoVerhRSSaDGZHrKy Feb 17 17:11:02 volumio volumio[1355]: info: CoreStateMachine::stop Feb 17 17:11:02 volumio volumio[1355]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 17 17:11:02 volumio volumio[1355]: info: CoreCommandRouter::volumioPushQueue Feb 17 17:11:02 volumio volumio[1355]: info: CorePlayQueue::saveQueue Feb 17 17:11:02 volumio volumio[1355]: info: CoreStateMachine::play index undefined Feb 17 17:11:02 volumio volumio[1355]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 17 17:11:02 volumio volumio[1355]: info: CoreStateMachine::updateTrackBlock Feb 17 17:11:02 volumio volumio[1355]: info: CorePlayQueue::getTrackBlock Feb 17 17:11:02 volumio volumio[1355]: info: CorePlayQueue::getTrack 0 Feb 17 17:11:02 volumio volumio[1355]: info: CoreStateMachine::startPlaybackTimer Feb 17 17:11:02 volumio volumio[1355]: info: CorePlayQueue::getTrack 0 Feb 17 17:11:02 volumio volumio[1355]: info: [1771328462741] ControllerSpotify::clearAddPlayTrack Feb 17 17:11:02 volumio volumio[1355]: info: Sending Spotify command with payload to local API: /player/play Feb 17 17:11:02 volumio go-librespot[3902]: time="2026-02-17T17:11:02+05:30" level=debug msg="resolved context of track" uri="spotify:track:1hu2s7qkm5bo03eODpRQO3" Feb 17 17:11:02 volumio go-librespot[3902]: time="2026-02-17T17:11:02+05:30" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:1hu2s7qkm5bo03eODpRQO3" Feb 17 17:11:02 volumio go-librespot[3902]: time="2026-02-17T17:11:02+05:30" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:1hu2s7qkm5bo03eODpRQO3" Feb 17 17:11:03 volumio go-librespot[3902]: time="2026-02-17T17:11:03+05:30" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 17 17:11:03 volumio go-librespot[3902]: time="2026-02-17T17:11:03+05:30" level=trace msg="emitting websocket event: will_play" Feb 17 17:11:03 volumio volumio[1355]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:1hu2s7qkm5bo03eODpRQO3","uri":"spotify:track:1hu2s7qkm5bo03eODpRQO3","play_origin":"go-librespot"}} Feb 17 17:11:03 volumio volumio[1355]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:1hu2s7qkm5bo03eODpRQO3","uri":"spotify:track:1hu2s7qkm5bo03eODpRQO3","play_origin":"go-librespot"}} Feb 17 17:11:03 volumio volumio[1355]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:1hu2s7qkm5bo03eODpRQO3","uri":"spotify:track:1hu2s7qkm5bo03eODpRQO3","play_origin":"go-librespot"}} Feb 17 17:11:03 volumio volumio[1355]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:1hu2s7qkm5bo03eODpRQO3","uri":"spotify:track:1hu2s7qkm5bo03eODpRQO3","play_origin":"go-librespot"}} Feb 17 17:11:03 volumio go-librespot[3902]: time="2026-02-17T17:11:03+05:30" level=debug msg="selected format OGG_VORBIS_320 (efad81219f414a3cff18a40b15e8a813a4c00fad)" uri="spotify:track:1hu2s7qkm5bo03eODpRQO3" Feb 17 17:11:03 volumio go-librespot[3902]: time="2026-02-17T17:11:03+05:30" level=debug msg="requested aes key for file efad81219f414a3cff18a40b15e8a813a4c00fad, gid: 1hu2s7qkm5bo03eODpRQO3" Feb 17 17:11:03 volumio go-librespot[3902]: time="2026-02-17T17:11:03+05:30" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:1hu2s7qkm5bo03eODpRQO3: failed retrieving audio key: failed retrieving aes key with code 1" Feb 17 17:11:03 volumio volumio[1355]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Feb 17 17:11:09 volumio volumio[1355]: info: CoreCommandRouter::volumioGetState Feb 17 17:11:09 volumio volumio[1355]: info: CorePlayQueue::getTrack 0 Feb 17 17:11:16 volumio go-librespot[3902]: time="2026-02-17T17:11:16+05:30" level=trace msg="sent dealer ping" Feb 17 17:11:16 volumio go-librespot[3902]: time="2026-02-17T17:11:16+05:30" level=trace msg="received dealer pong" Feb 17 17:11:39 volumio volumio[1355]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Feb 17 17:11:39 volumio volumio[1355]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Feb 17 17:11:42 volumio volumio[1355]: info: CoreCommandRouter::getUIConfigOnPlugin Feb 17 17:11:46 volumio go-librespot[3902]: time="2026-02-17T17:11:46+05:30" level=trace msg="sent dealer ping" Feb 17 17:11:46 volumio go-librespot[3902]: time="2026-02-17T17:11:46+05:30" level=trace msg="received dealer pong" Feb 17 17:12:06 volumio volumio[1355]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Feb 17 17:12:06 volumio volumio[1355]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Feb 17 17:12:06 volumio volumio[1355]: info: Creating Spotify config file Feb 17 17:12:06 volumio volumio[1355]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 17:12:06 volumio volumio[1355]: info: Spotify config file written Feb 17 17:12:06 volumio sudo[4078]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 17 17:12:06 volumio sudo[4078]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 17 17:12:06 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Feb 17 17:12:06 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Feb 17 17:12:06 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 17 17:12:06 volumio volumio[1355]: info: Connection to go-librespot Websocket closed Feb 17 17:12:06 volumio volumio[1355]: info: Connection to go-librespot Websocket closed Feb 17 17:12:06 volumio volumio[1355]: info: Connection to go-librespot Websocket closed Feb 17 17:12:06 volumio volumio[1355]: info: Connection to go-librespot Websocket closed Feb 17 17:12:06 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 17 17:12:06 volumio sudo[4078]: pam_unix(sudo:session): session closed for user root Feb 17 17:12:06 volumio go-librespot[4080]: go-librespot daemon starting... Feb 17 17:12:06 volumio go-librespot[4081]: time="2026-02-17T17:12:06+05:30" level=info msg="running go-librespot 0.6.2" Feb 17 17:12:06 volumio go-librespot[4081]: time="2026-02-17T17:12:06+05:30" level=debug msg="app state loaded" Feb 17 17:12:06 volumio go-librespot[4081]: time="2026-02-17T17:12:06+05:30" level=info msg="api server listening on 127.0.0.1:9879" Feb 17 17:12:06 volumio go-librespot[4081]: time="2026-02-17T17:12:06+05:30" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Feb 17 17:12:06 volumio go-librespot[4081]: time="2026-02-17T17:12:06+05:30" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Feb 17 17:12:06 volumio go-librespot[4081]: time="2026-02-17T17:12:06+05:30" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Feb 17 17:12:06 volumio go-librespot[4081]: time="2026-02-17T17:12:06+05:30" level=info msg="zeroconf server listening on port 43339" Feb 17 17:12:06 volumio go-librespot[4081]: time="2026-02-17T17:12:06+05:30" level=debug msg="obtained new client token: AABx0Br5cBe+frNiyokBxmyyWbpGkAW69Mj4ezRSwIz7MXsmEAisXq6sgEewOwrmsILRueZjbv/Oq9y5GdtoPSvnMHxQjn93p7s9egeiUVt4ISqGMhgXhPtgJ3RqomreggwQ/zZnYy+7u7o3X7xCo4gzxsqA6D7UpZ0yCBA/Friau83AC4Ctbbrb4d8rkIAEQGJDHhuyJMMJpsCiZ/SXmqzDhiAn7CqbYPDEvUi2pYRGZ9tBah4+YyqtMw==" Feb 17 17:12:06 volumio go-librespot[4081]: time="2026-02-17T17:12:06+05:30" level=debug msg="connected to ap-gae2.spotify.com:4070" Feb 17 17:12:06 volumio go-librespot[4081]: time="2026-02-17T17:12:06+05:30" level=warning msg="failed connecting to accesspoint, retrying" error="failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Feb 17 17:12:07 volumio go-librespot[4081]: time="2026-02-17T17:12:07+05:30" level=debug msg="connected to ap-gae2.spotify.com:443" Feb 17 17:12:07 volumio go-librespot[4081]: time="2026-02-17T17:12:07+05:30" level=debug msg="completed keyexchange" Feb 17 17:12:07 volumio go-librespot[4081]: time="2026-02-17T17:12:07+05:30" level=debug msg="completed challenge" Feb 17 17:12:07 volumio go-librespot[4081]: time="2026-02-17T17:12:07+05:30" level=info msg="authenticated AP" username="31************************ki" Feb 17 17:12:08 volumio go-librespot[4081]: time="2026-02-17T17:12:08+05:30" level=info msg="authenticated Login5" username="31************************ki" Feb 17 17:12:08 volumio go-librespot[4081]: time="2026-02-17T17:12:08+05:30" level=debug msg="initializing zeroconf session" username="31************************ki" Feb 17 17:12:08 volumio go-librespot[4081]: time="2026-02-17T17:12:08+05:30" level=debug msg="dealer connection opened" Feb 17 17:12:08 volumio go-librespot[4081]: time="2026-02-17T17:12:08+05:30" level=trace msg="starting accesspoint recv loop" Feb 17 17:12:08 volumio go-librespot[4081]: time="2026-02-17T17:12:08+05:30" level=trace msg="starting dealer recv loop" Feb 17 17:12:08 volumio go-librespot[4081]: time="2026-02-17T17:12:08+05:30" level=trace msg="received accesspoint ping" Feb 17 17:12:08 volumio go-librespot[4081]: time="2026-02-17T17:12:08+05:30" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Feb 17 17:12:08 volumio go-librespot[4081]: time="2026-02-17T17:12:08+05:30" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Feb 17 17:12:08 volumio go-librespot[4081]: time="2026-02-17T17:12:08+05:30" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Feb 17 17:12:08 volumio go-librespot[4081]: time="2026-02-17T17:12:08+05:30" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Feb 17 17:12:08 volumio go-librespot[4081]: time="2026-02-17T17:12:08+05:30" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Feb 17 17:12:08 volumio go-librespot[4081]: time="2026-02-17T17:12:08+05:30" level=debug msg="received connection id: NmIwZmY0ZGItNzMx...QTA1QzlGNDhFNg==" Feb 17 17:12:08 volumio go-librespot[4081]: time="2026-02-17T17:12:08+05:30" level=trace msg="received accesspoint pong ack" Feb 17 17:12:08 volumio go-librespot[4081]: time="2026-02-17T17:12:08+05:30" level=debug msg="put connect state because NEW_DEVICE" Feb 17 17:12:09 volumio volumio[1355]: info: Initializing connection to go-librespot Websocket Feb 17 17:12:09 volumio go-librespot[4081]: time="2026-02-17T17:12:09+05:30" level=debug msg="new websocket client" Feb 17 17:12:09 volumio volumio[1355]: info: Connection to go-librespot Websocket established Feb 17 17:12:09 volumio volumio[1355]: info: go-librespot daemon successfully initialized Feb 17 17:12:12 volumio volumio[1355]: info: Getting Spotify volume Feb 17 17:12:12 volumio volumio[1355]: info: Spotify volume: 100 Feb 17 17:12:12 volumio volumio[1355]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Feb 17 17:12:12 volumio volumio[1355]: info: CoreCommandRouter::volumioGetState Feb 17 17:12:12 volumio volumio[1355]: info: CorePlayQueue::getTrack 0 Feb 17 17:12:12 volumio volumio[1355]: SPOTIFY: RECEIVED VOLUMIO VOLUME 27 Feb 17 17:12:12 volumio volumio[1355]: SPOTIFY: SPOTIFY VOLUME 100 Feb 17 17:12:12 volumio volumio[1355]: SPOTIFY: VOLUMIO VOLUME 27 Feb 17 17:12:12 volumio volumio[1355]: SPOTIFY: DELTA VOLUME ENOUGH: true Feb 17 17:12:12 volumio volumio[1355]: info: Setting Spotify Volume from Volumio: 27 Feb 17 17:12:12 volumio volumio[1355]: info: Initializing connection to go-librespot Websocket Feb 17 17:12:12 volumio go-librespot[4081]: time="2026-02-17T17:12:12+05:30" level=debug msg="new websocket client" Feb 17 17:12:12 volumio volumio[1355]: info: Connection to go-librespot Websocket established Feb 17 17:12:13 volumio volumio[1355]: SPOTIFY: SETTING SPOTIFY VOLUME 27 Feb 17 17:12:13 volumio volumio[1355]: info: Sending Spotify command with payload to local API: /player/volume Feb 17 17:12:13 volumio go-librespot[4081]: time="2026-02-17T17:12:13+05:30" level=debug msg="update volume requested to 17694/65535" Feb 17 17:12:14 volumio go-librespot[4081]: time="2026-02-17T17:12:14+05:30" level=debug msg="put connect state because VOLUME_CHANGED" Feb 17 17:12:14 volumio go-librespot[4081]: time="2026-02-17T17:12:14+05:30" level=trace msg="emitting websocket event: volume" Feb 17 17:12:14 volumio volumio[1355]: SPOTIFY: received: {"type":"volume","data":{"value":27,"max":100}} Feb 17 17:12:14 volumio volumio[1355]: SPOTIFY: RECEIVED SPOTIFY VOLUME 27 Feb 17 17:12:14 volumio volumio[1355]: SPOTIFY: received: {"type":"volume","data":{"value":27,"max":100}} Feb 17 17:12:14 volumio volumio[1355]: SPOTIFY: RECEIVED SPOTIFY VOLUME 27 Feb 17 17:12:15 volumio volumio[1355]: info: Getting Spotify volume Feb 17 17:12:15 volumio volumio[1355]: info: Spotify volume: 27 Feb 17 17:12:15 volumio volumio[1355]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Feb 17 17:12:15 volumio volumio[1355]: info: CoreCommandRouter::volumioGetState Feb 17 17:12:15 volumio volumio[1355]: info: CorePlayQueue::getTrack 0 Feb 17 17:12:15 volumio volumio[1355]: SPOTIFY: RECEIVED VOLUMIO VOLUME 27 Feb 17 17:12:24 volumio volumio[1355]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Feb 17 17:12:24 volumio volumio[1355]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Feb 17 17:12:24 volumio volumio[1355]: info: Creating Spotify config file Feb 17 17:12:24 volumio volumio[1355]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 17:12:24 volumio volumio[1355]: info: Spotify config file written Feb 17 17:12:24 volumio sudo[4120]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 17 17:12:24 volumio sudo[4120]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 17 17:12:24 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Feb 17 17:12:24 volumio systemd[1]: go-librespot-daemon.service: Killing process 4083 (go-librespot) with signal SIGKILL. Feb 17 17:12:24 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Feb 17 17:12:24 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 17 17:12:24 volumio volumio[1355]: info: Connection to go-librespot Websocket closed Feb 17 17:12:24 volumio volumio[1355]: info: Connection to go-librespot Websocket closed Feb 17 17:12:24 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 17 17:12:24 volumio go-librespot[4122]: go-librespot daemon starting... Feb 17 17:12:24 volumio sudo[4120]: pam_unix(sudo:session): session closed for user root Feb 17 17:12:24 volumio go-librespot[4123]: time="2026-02-17T17:12:24+05:30" level=info msg="running go-librespot 0.6.2" Feb 17 17:12:24 volumio go-librespot[4123]: time="2026-02-17T17:12:24+05:30" level=debug msg="app state loaded" Feb 17 17:12:24 volumio go-librespot[4123]: time="2026-02-17T17:12:24+05:30" level=info msg="api server listening on 127.0.0.1:9879" Feb 17 17:12:24 volumio volumio[1355]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Feb 17 17:12:24 volumio volumio[1355]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Feb 17 17:12:24 volumio volumio[1355]: info: Creating Spotify config file Feb 17 17:12:24 volumio volumio[1355]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 17:12:24 volumio volumio[1355]: info: Spotify config file written Feb 17 17:12:24 volumio sudo[4131]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 17 17:12:24 volumio sudo[4131]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 17 17:12:24 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Feb 17 17:12:24 volumio systemd[1]: go-librespot-daemon.service: Killing process 4128 (go-librespot) with signal SIGKILL. Feb 17 17:12:24 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Feb 17 17:12:24 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 17 17:12:24 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 17 17:12:24 volumio go-librespot[4133]: go-librespot daemon starting... Feb 17 17:12:24 volumio sudo[4131]: pam_unix(sudo:session): session closed for user root Feb 17 17:12:24 volumio go-librespot[4134]: time="2026-02-17T17:12:24+05:30" level=info msg="running go-librespot 0.6.2" Feb 17 17:12:24 volumio go-librespot[4134]: time="2026-02-17T17:12:24+05:30" level=debug msg="app state loaded" Feb 17 17:12:24 volumio go-librespot[4134]: time="2026-02-17T17:12:24+05:30" level=info msg="api server listening on 127.0.0.1:9879" Feb 17 17:12:24 volumio volumio[1355]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Feb 17 17:12:24 volumio volumio[1355]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Feb 17 17:12:24 volumio volumio[1355]: info: Creating Spotify config file Feb 17 17:12:24 volumio volumio[1355]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 17:12:24 volumio volumio[1355]: info: Spotify config file written Feb 17 17:12:24 volumio sudo[4144]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 17 17:12:24 volumio sudo[4144]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 17 17:12:24 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Feb 17 17:12:24 volumio systemd[1]: go-librespot-daemon.service: Killing process 4137 (go-librespot) with signal SIGKILL. Feb 17 17:12:24 volumio systemd[1]: go-librespot-daemon.service: Killing process 4141 (go-librespot) with signal SIGKILL. Feb 17 17:12:24 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Feb 17 17:12:24 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 17 17:12:24 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 17 17:12:24 volumio go-librespot[4146]: go-librespot daemon starting... Feb 17 17:12:24 volumio sudo[4144]: pam_unix(sudo:session): session closed for user root Feb 17 17:12:24 volumio go-librespot[4147]: time="2026-02-17T17:12:24+05:30" level=info msg="running go-librespot 0.6.2" Feb 17 17:12:24 volumio go-librespot[4147]: time="2026-02-17T17:12:24+05:30" level=debug msg="app state loaded" Feb 17 17:12:24 volumio go-librespot[4147]: time="2026-02-17T17:12:24+05:30" level=info msg="api server listening on 127.0.0.1:9879" Feb 17 17:12:24 volumio volumio[1355]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Feb 17 17:12:24 volumio volumio[1355]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Feb 17 17:12:24 volumio volumio[1355]: info: Creating Spotify config file Feb 17 17:12:24 volumio volumio[1355]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 17:12:24 volumio volumio[1355]: info: Spotify config file written Feb 17 17:12:24 volumio sudo[4155]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 17 17:12:24 volumio sudo[4155]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 17 17:12:24 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Feb 17 17:12:24 volumio systemd[1]: go-librespot-daemon.service: Killing process 4151 (go-librespot) with signal SIGKILL. Feb 17 17:12:24 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Feb 17 17:12:24 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 17 17:12:24 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 17 17:12:24 volumio go-librespot[4157]: go-librespot daemon starting... Feb 17 17:12:24 volumio sudo[4155]: pam_unix(sudo:session): session closed for user root Feb 17 17:12:24 volumio go-librespot[4158]: time="2026-02-17T17:12:24+05:30" level=info msg="running go-librespot 0.6.2" Feb 17 17:12:24 volumio go-librespot[4158]: time="2026-02-17T17:12:24+05:30" level=debug msg="app state loaded" Feb 17 17:12:24 volumio go-librespot[4158]: time="2026-02-17T17:12:24+05:30" level=info msg="api server listening on 127.0.0.1:9879" Feb 17 17:12:24 volumio go-librespot[4158]: time="2026-02-17T17:12:24+05:30" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Feb 17 17:12:24 volumio go-librespot[4158]: time="2026-02-17T17:12:24+05:30" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Feb 17 17:12:24 volumio go-librespot[4158]: time="2026-02-17T17:12:24+05:30" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Feb 17 17:12:24 volumio go-librespot[4158]: time="2026-02-17T17:12:24+05:30" level=info msg="zeroconf server listening on port 38167" Feb 17 17:12:25 volumio go-librespot[4158]: time="2026-02-17T17:12:25+05:30" level=debug msg="obtained new client token: AAA2ESBk/fLWsT6rhYlHtomwKQdJSnLHDEfECNjPixaFZGkTGoR7AqiDFV0S2XMwVEBrpC/NzkFT6lmztf5exSsDuFd4UkB3rfVvBfdlbGxRi/ss5aB1jmlhcMnaRssjJo8KRg3Ip8ixtqLGVfvzpJM/oX+ikyZe0ZKT/Gyvs9Tz11cT8Gl9z3R4uhbb7HrQp8GJtNASLw9EGvnRGkr9YmWXABfnK3WhfKS2OcHqduzGpdg2hNce/pg=" Feb 17 17:12:25 volumio go-librespot[4158]: time="2026-02-17T17:12:25+05:30" level=debug msg="connected to ap-gae2.spotify.com:4070" Feb 17 17:12:25 volumio go-librespot[4158]: time="2026-02-17T17:12:25+05:30" level=debug msg="completed keyexchange" Feb 17 17:12:25 volumio go-librespot[4158]: time="2026-02-17T17:12:25+05:30" level=debug msg="completed challenge" Feb 17 17:12:25 volumio go-librespot[4158]: time="2026-02-17T17:12:25+05:30" level=info msg="authenticated AP" username="31************************ki" Feb 17 17:12:25 volumio go-librespot[4158]: time="2026-02-17T17:12:25+05:30" level=info msg="authenticated Login5" username="31************************ki" Feb 17 17:12:25 volumio go-librespot[4158]: time="2026-02-17T17:12:25+05:30" level=debug msg="initializing zeroconf session" username="31************************ki" Feb 17 17:12:26 volumio go-librespot[4158]: time="2026-02-17T17:12:26+05:30" level=debug msg="dealer connection opened" Feb 17 17:12:26 volumio go-librespot[4158]: time="2026-02-17T17:12:26+05:30" level=trace msg="starting accesspoint recv loop" Feb 17 17:12:26 volumio go-librespot[4158]: time="2026-02-17T17:12:26+05:30" level=trace msg="starting dealer recv loop" Feb 17 17:12:26 volumio go-librespot[4158]: time="2026-02-17T17:12:26+05:30" level=trace msg="received accesspoint ping" Feb 17 17:12:26 volumio go-librespot[4158]: time="2026-02-17T17:12:26+05:30" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Feb 17 17:12:26 volumio go-librespot[4158]: time="2026-02-17T17:12:26+05:30" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Feb 17 17:12:26 volumio go-librespot[4158]: time="2026-02-17T17:12:26+05:30" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Feb 17 17:12:26 volumio go-librespot[4158]: time="2026-02-17T17:12:26+05:30" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Feb 17 17:12:26 volumio go-librespot[4158]: time="2026-02-17T17:12:26+05:30" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Feb 17 17:12:26 volumio go-librespot[4158]: time="2026-02-17T17:12:26+05:30" level=debug msg="received connection id: MmNkMDJhYjItMTNj...NjNFMzNCODk1NA==" Feb 17 17:12:26 volumio go-librespot[4158]: time="2026-02-17T17:12:26+05:30" level=trace msg="received accesspoint pong ack" Feb 17 17:12:26 volumio go-librespot[4158]: time="2026-02-17T17:12:26+05:30" level=debug msg="put connect state because NEW_DEVICE" Feb 17 17:12:27 volumio volumio[1355]: info: Initializing connection to go-librespot Websocket Feb 17 17:12:27 volumio go-librespot[4158]: time="2026-02-17T17:12:27+05:30" level=debug msg="new websocket client" Feb 17 17:12:27 volumio volumio[1355]: info: Connection to go-librespot Websocket established Feb 17 17:12:27 volumio volumio[1355]: info: go-librespot daemon successfully initialized Feb 17 17:12:27 volumio volumio[1355]: info: go-librespot daemon successfully initialized Feb 17 17:12:27 volumio volumio[1355]: info: go-librespot daemon successfully initialized Feb 17 17:12:27 volumio volumio[1355]: info: go-librespot daemon successfully initialized Feb 17 17:12:30 volumio volumio[1355]: info: Getting Spotify volume Feb 17 17:12:30 volumio volumio[1355]: info: Spotify volume: 100 Feb 17 17:12:30 volumio volumio[1355]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Feb 17 17:12:30 volumio volumio[1355]: info: CoreCommandRouter::volumioGetState Feb 17 17:12:30 volumio volumio[1355]: info: CorePlayQueue::getTrack 0 Feb 17 17:12:30 volumio volumio[1355]: SPOTIFY: RECEIVED VOLUMIO VOLUME 27 Feb 17 17:12:30 volumio volumio[1355]: SPOTIFY: SPOTIFY VOLUME 100 Feb 17 17:12:30 volumio volumio[1355]: SPOTIFY: VOLUMIO VOLUME 27 Feb 17 17:12:30 volumio volumio[1355]: SPOTIFY: DELTA VOLUME ENOUGH: true Feb 17 17:12:30 volumio volumio[1355]: info: Setting Spotify Volume from Volumio: 27 Feb 17 17:12:30 volumio volumio[1355]: info: Initializing connection to go-librespot Websocket Feb 17 17:12:30 volumio go-librespot[4158]: time="2026-02-17T17:12:30+05:30" level=debug msg="new websocket client" Feb 17 17:12:30 volumio volumio[1355]: info: Connection to go-librespot Websocket established Feb 17 17:12:30 volumio volumio[1355]: info: Initializing connection to go-librespot Websocket Feb 17 17:12:30 volumio go-librespot[4158]: time="2026-02-17T17:12:30+05:30" level=debug msg="new websocket client" Feb 17 17:12:30 volumio volumio[1355]: info: Connection to go-librespot Websocket established Feb 17 17:12:30 volumio volumio[1355]: info: Initializing connection to go-librespot Websocket Feb 17 17:12:30 volumio go-librespot[4158]: time="2026-02-17T17:12:30+05:30" level=debug msg="new websocket client" Feb 17 17:12:30 volumio volumio[1355]: info: Connection to go-librespot Websocket established Feb 17 17:12:30 volumio volumio[1355]: info: Initializing connection to go-librespot Websocket Feb 17 17:12:30 volumio go-librespot[4158]: time="2026-02-17T17:12:30+05:30" level=debug msg="new websocket client" Feb 17 17:12:30 volumio volumio[1355]: info: Connection to go-librespot Websocket established Feb 17 17:12:31 volumio volumio[1355]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Feb 17 17:12:31 volumio volumio[1355]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Feb 17 17:12:31 volumio volumio[1355]: info: Creating Spotify config file Feb 17 17:12:31 volumio volumio[1355]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 17:12:31 volumio volumio[1355]: info: Spotify config file written Feb 17 17:12:31 volumio sudo[4169]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 17 17:12:31 volumio sudo[4169]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 17 17:12:31 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Feb 17 17:12:31 volumio systemd[1]: go-librespot-daemon.service: Killing process 4162 (go-librespot) with signal SIGKILL. Feb 17 17:12:31 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Feb 17 17:12:31 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 17 17:12:31 volumio volumio[1355]: info: Connection to go-librespot Websocket closed Feb 17 17:12:31 volumio volumio[1355]: info: Connection to go-librespot Websocket closed Feb 17 17:12:31 volumio volumio[1355]: info: Connection to go-librespot Websocket closed Feb 17 17:12:31 volumio volumio[1355]: info: Connection to go-librespot Websocket closed Feb 17 17:12:31 volumio volumio[1355]: info: Connection to go-librespot Websocket closed Feb 17 17:12:31 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 17 17:12:31 volumio go-librespot[4171]: go-librespot daemon starting... Feb 17 17:12:31 volumio sudo[4169]: pam_unix(sudo:session): session closed for user root Feb 17 17:12:31 volumio go-librespot[4172]: time="2026-02-17T17:12:31+05:30" level=info msg="running go-librespot 0.6.2" Feb 17 17:12:31 volumio go-librespot[4172]: time="2026-02-17T17:12:31+05:30" level=debug msg="app state loaded" Feb 17 17:12:31 volumio go-librespot[4172]: time="2026-02-17T17:12:31+05:30" level=info msg="api server listening on 127.0.0.1:9879" Feb 17 17:12:31 volumio go-librespot[4172]: time="2026-02-17T17:12:31+05:30" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Feb 17 17:12:31 volumio go-librespot[4172]: time="2026-02-17T17:12:31+05:30" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Feb 17 17:12:31 volumio go-librespot[4172]: time="2026-02-17T17:12:31+05:30" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Feb 17 17:12:31 volumio go-librespot[4172]: time="2026-02-17T17:12:31+05:30" level=info msg="zeroconf server listening on port 44381" Feb 17 17:12:31 volumio go-librespot[4172]: time="2026-02-17T17:12:31+05:30" level=debug msg="obtained new client token: AAAPynkLfLnfWoUuEH20jITJAzLlaHHf2rTW4/ot7dSdT7m7ZzZwEEj+gDlo/UgbmZTdx5sDl1Wqye46K616sDG5Ew8W+UCdjMso3RtXcVNvw/djBl3+9l+W0JCZKuBMxjhlzLL1jBY5uxqoNJPONSd9++z1a+GmUCJS6DCMsaXaC8tcONwVBSWnV5qB7lfTP0h+03CrjIKrq4CGbP+LHXXdIE6HAO3UOyELPLXkgn9mQ7Qm8E7He68EJA==" Feb 17 17:12:31 volumio volumio[1355]: SPOTIFY: SETTING SPOTIFY VOLUME 27 Feb 17 17:12:31 volumio volumio[1355]: info: Sending Spotify command with payload to local API: /player/volume Feb 17 17:12:31 volumio volumio[1355]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Feb 17 17:12:31 volumio volumio[1355]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Feb 17 17:12:31 volumio volumio[1355]: info: Creating Spotify config file Feb 17 17:12:31 volumio volumio[1355]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 17:12:31 volumio volumio[1355]: info: Spotify config file written Feb 17 17:12:31 volumio sudo[4196]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 17 17:12:31 volumio sudo[4196]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 17 17:12:31 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Feb 17 17:12:31 volumio systemd[1]: go-librespot-daemon.service: Killing process 4174 (go-librespot) with signal SIGKILL. Feb 17 17:12:31 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Feb 17 17:12:31 volumio volumio[1355]: error: Failed to send command to Spotify local API: /player/volume: Error: socket hang up Feb 17 17:12:31 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 17 17:12:31 volumio systemd[1]: go-librespot-daemon.service: Start request repeated too quickly. Feb 17 17:12:31 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'start-limit-hit'. Feb 17 17:12:31 volumio systemd[1]: Failed to start go-librespot-daemon.service - go-librespot Daemon. Feb 17 17:12:31 volumio sudo[4196]: pam_unix(sudo:session): session closed for user root Feb 17 17:12:31 volumio volumio[1355]: error: Cannot start Go-librespot Daemon: Error: Command failed: /usr/bin/sudo systemctl restart go-librespot-daemon.service Feb 17 17:12:31 volumio volumio[1355]: Job for go-librespot-daemon.service failed because start of the service was attempted too often. Feb 17 17:12:31 volumio volumio[1355]: See "systemctl status go-librespot-daemon.service" and "journalctl -xeu go-librespot-daemon.service" for details. Feb 17 17:12:31 volumio volumio[1355]: To force a start use "systemctl reset-failed go-librespot-daemon.service" Feb 17 17:12:31 volumio volumio[1355]: followed by "systemctl start go-librespot-daemon.service" again. Feb 17 17:12:31 volumio volumio[1355]: error: Error initializing go-librespot daemon: Error: Command failed: /usr/bin/sudo systemctl restart go-librespot-daemon.service Feb 17 17:12:31 volumio volumio[1355]: Job for go-librespot-daemon.service failed because start of the service was attempted too often. Feb 17 17:12:31 volumio volumio[1355]: See "systemctl status go-librespot-daemon.service" and "journalctl -xeu go-librespot-daemon.service" for details. Feb 17 17:12:31 volumio volumio[1355]: To force a start use "systemctl reset-failed go-librespot-daemon.service" Feb 17 17:12:31 volumio volumio[1355]: followed by "systemctl start go-librespot-daemon.service" again. Feb 17 17:12:31 volumio volumio[1355]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Feb 17 17:12:31 volumio volumio[1355]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Feb 17 17:12:31 volumio volumio[1355]: info: Creating Spotify config file Feb 17 17:12:31 volumio volumio[1355]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 17:12:31 volumio volumio[1355]: info: Spotify config file written Feb 17 17:12:32 volumio sudo[4199]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 17 17:12:32 volumio sudo[4199]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 17 17:12:32 volumio systemd[1]: go-librespot-daemon.service: Start request repeated too quickly. Feb 17 17:12:32 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'start-limit-hit'. Feb 17 17:12:32 volumio systemd[1]: Failed to start go-librespot-daemon.service - go-librespot Daemon. Feb 17 17:12:32 volumio sudo[4199]: pam_unix(sudo:session): session closed for user root Feb 17 17:12:32 volumio volumio[1355]: error: Cannot start Go-librespot Daemon: Error: Command failed: /usr/bin/sudo systemctl restart go-librespot-daemon.service Feb 17 17:12:32 volumio volumio[1355]: Job for go-librespot-daemon.service failed because start of the service was attempted too often. Feb 17 17:12:32 volumio volumio[1355]: See "systemctl status go-librespot-daemon.service" and "journalctl -xeu go-librespot-daemon.service" for details. Feb 17 17:12:32 volumio volumio[1355]: To force a start use "systemctl reset-failed go-librespot-daemon.service" Feb 17 17:12:32 volumio volumio[1355]: followed by "systemctl start go-librespot-daemon.service" again. Feb 17 17:12:32 volumio volumio[1355]: error: Error initializing go-librespot daemon: Error: Command failed: /usr/bin/sudo systemctl restart go-librespot-daemon.service Feb 17 17:12:32 volumio volumio[1355]: Job for go-librespot-daemon.service failed because start of the service was attempted too often. Feb 17 17:12:32 volumio volumio[1355]: See "systemctl status go-librespot-daemon.service" and "journalctl -xeu go-librespot-daemon.service" for details. Feb 17 17:12:32 volumio volumio[1355]: To force a start use "systemctl reset-failed go-librespot-daemon.service" Feb 17 17:12:32 volumio volumio[1355]: followed by "systemctl start go-librespot-daemon.service" again. Feb 17 17:12:33 volumio volumio[1355]: info: Getting Spotify volume Feb 17 17:12:33 volumio volumio[1355]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 17 17:12:33 volumio volumio[1355]: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 17 17:12:33 volumio volumio[1355]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Feb 17 17:12:33 volumio volumio[1355]: errno: -111, Feb 17 17:12:33 volumio volumio[1355]: code: 'ECONNREFUSED', Feb 17 17:12:33 volumio volumio[1355]: syscall: 'connect', Feb 17 17:12:33 volumio volumio[1355]: address: '127.0.0.1', Feb 17 17:12:33 volumio volumio[1355]: port: 9879, Feb 17 17:12:33 volumio volumio[1355]: response: undefined Feb 17 17:12:33 volumio volumio[1355]: } Feb 17 17:12:33 volumio volumio[1355]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 17 17:12:33 volumio sudo[4215]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-02-17 17:11' Feb 17 17:12:33 volumio sudo[4215]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="a78d359cf1dc63ac74e9d151015afd30d31a709a" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="c1ffe93b2136013fc1b5903a4ed7e3f34e0a7bec" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu Feb 5 14:07:07 UTC 2026" VOLUMIO_VERSION="4.096" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="5e37060f9823263a753eb5e84030104f"