Feb 07 10:59:01 volumio go-librespot[3416]: time="2026-02-07T10:59:01Z" level=debug msg="handling transfer player command from 0a832b9640734674858bf2b5abb41ed10795b322" Feb 07 10:59:01 volumio go-librespot[3416]: time="2026-02-07T10:59:01Z" level=debug msg="resolved context of track" uri="spotify:playlist:4w0ko2zuY3AeNp5snuQNnV" Feb 07 10:59:01 volumio go-librespot[3416]: time="2026-02-07T10:59:01Z" level=trace msg="fetched new page 0 with 2908 items (list: 2908)" uri="spotify:playlist:4w0ko2zuY3AeNp5snuQNnV" Feb 07 10:59:01 volumio go-librespot[3416]: time="2026-02-07T10:59:01Z" level=debug msg="shuffled context with seed 68486019414583353 (len: 2908, keep: 2763)" uri="spotify:playlist:4w0ko2zuY3AeNp5snuQNnV" Feb 07 10:59:01 volumio go-librespot[3416]: time="2026-02-07T10:59:01Z" level=debug msg="loading track (paused: true, position: 3251ms)" uri="spotify:track:2qFeCtMEna8XdO1ubA5pqS" Feb 07 10:59:01 volumio go-librespot[3416]: time="2026-02-07T10:59:01Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 07 10:59:01 volumio go-librespot[3416]: time="2026-02-07T10:59:01Z" level=trace msg="emitting websocket event: will_play" Feb 07 10:59:01 volumio volumio[1239]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:playlist:4w0ko2zuY3AeNp5snuQNnV","uri":"spotify:track:2qFeCtMEna8XdO1ubA5pqS","play_origin":"playlist"}} Feb 07 10:59:01 volumio volumio[1239]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:playlist:4w0ko2zuY3AeNp5snuQNnV","uri":"spotify:track:2qFeCtMEna8XdO1ubA5pqS","play_origin":"playlist"}} Feb 07 10:59:01 volumio go-librespot[3416]: time="2026-02-07T10:59:01Z" level=debug msg="selected format OGG_VORBIS_320 (24761cf1ea05e52e0008ae93a481f2f059598c83)" uri="spotify:track:2qFeCtMEna8XdO1ubA5pqS" Feb 07 10:59:01 volumio go-librespot[3416]: time="2026-02-07T10:59:01Z" level=debug msg="requested aes key for file 24761cf1ea05e52e0008ae93a481f2f059598c83, gid: 2qFeCtMEna8XdO1ubA5pqS" Feb 07 10:59:01 volumio go-librespot[3416]: time="2026-02-07T10:59:01Z" level=warning msg="failed handling dealer request" error="failed loading current track (transfer): failed creating stream for spotify:track:2qFeCtMEna8XdO1ubA5pqS: failed retrieving audio key: failed retrieving aes key with code 1" Feb 07 10:59:03 volumio go-librespot[3416]: time="2026-02-07T10:59:03Z" level=debug msg="handling resume player command from 0a832b9640734674858bf2b5abb41ed10795b322" Feb 07 10:59:03 volumio go-librespot[3416]: time="2026-02-07T10:59:03Z" level=warning msg="failed handling dealer request" error="no primary stream" Feb 07 10:59:06 volumio go-librespot[3416]: time="2026-02-07T10:59:06Z" level=debug msg="handling resume player command from 0a832b9640734674858bf2b5abb41ed10795b322" Feb 07 10:59:06 volumio go-librespot[3416]: time="2026-02-07T10:59:06Z" level=warning msg="failed handling dealer request" error="no primary stream" Feb 07 10:59:11 volumio go-librespot[3416]: time="2026-02-07T10:59:11Z" level=debug msg="handling resume player command from 0a832b9640734674858bf2b5abb41ed10795b322" Feb 07 10:59:11 volumio go-librespot[3416]: time="2026-02-07T10:59:11Z" level=warning msg="failed handling dealer request" error="no primary stream" Feb 07 10:59:13 volumio go-librespot[3416]: time="2026-02-07T10:59:13Z" level=debug msg="update volume requested to 65535/65535" Feb 07 10:59:13 volumio go-librespot[3416]: time="2026-02-07T10:59:13Z" level=debug msg="put connect state because VOLUME_CHANGED" Feb 07 10:59:13 volumio go-librespot[3416]: time="2026-02-07T10:59:13Z" level=trace msg="emitting websocket event: volume" Feb 07 10:59:13 volumio volumio[1239]: SPOTIFY: received: {"type":"volume","data":{"value":100,"max":100}} Feb 07 10:59:13 volumio volumio[1239]: SPOTIFY: RECEIVED SPOTIFY VOLUME 100 Feb 07 10:59:13 volumio volumio[1239]: SPOTIFY: received: {"type":"volume","data":{"value":100,"max":100}} Feb 07 10:59:13 volumio volumio[1239]: SPOTIFY: RECEIVED SPOTIFY VOLUME 100 Feb 07 10:59:14 volumio go-librespot[3416]: time="2026-02-07T10:59:14Z" level=debug msg="update volume requested to 62914/65535" Feb 07 10:59:15 volumio go-librespot[3416]: time="2026-02-07T10:59:15Z" level=debug msg="put connect state because VOLUME_CHANGED" Feb 07 10:59:15 volumio go-librespot[3416]: time="2026-02-07T10:59:15Z" level=trace msg="emitting websocket event: volume" Feb 07 10:59:15 volumio volumio[1239]: SPOTIFY: received: {"type":"volume","data":{"value":96,"max":100}} Feb 07 10:59:15 volumio volumio[1239]: SPOTIFY: RECEIVED SPOTIFY VOLUME 96 Feb 07 10:59:15 volumio volumio[1239]: info: Setting Volumio Volume from Spotify: 96 Feb 07 10:59:15 volumio volumio[1239]: info: VolumeController::SetAlsaVolume96 Feb 07 10:59:15 volumio volumio[1239]: info: CoreStateMachine::pushState Feb 07 10:59:15 volumio volumio[1239]: info: CorePlayQueue::getTrack 0 Feb 07 10:59:15 volumio volumio[1239]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 07 10:59:15 volumio volumio[1239]: info: CoreCommandRouter::volumioPushState Feb 07 10:59:15 volumio volumio[1239]: SPOTIFY: received: {"type":"volume","data":{"value":96,"max":100}} Feb 07 10:59:15 volumio volumio[1239]: SPOTIFY: RECEIVED SPOTIFY VOLUME 96 Feb 07 10:59:15 volumio volumio[1239]: SPOTIFY: RECEIVED VOLUMIO VOLUME 96 Feb 07 10:59:15 volumio go-librespot[3416]: time="2026-02-07T10:59:15Z" level=debug msg="update volume requested to 60292/65535" Feb 07 10:59:15 volumio go-librespot[3416]: time="2026-02-07T10:59:15Z" level=debug msg="put connect state because VOLUME_CHANGED" Feb 07 10:59:15 volumio go-librespot[3416]: time="2026-02-07T10:59:15Z" level=trace msg="emitting websocket event: volume" Feb 07 10:59:15 volumio volumio[1239]: SPOTIFY: received: {"type":"volume","data":{"value":92,"max":100}} Feb 07 10:59:15 volumio volumio[1239]: SPOTIFY: RECEIVED SPOTIFY VOLUME 92 Feb 07 10:59:15 volumio volumio[1239]: info: Setting Volumio Volume from Spotify: 92 Feb 07 10:59:15 volumio volumio[1239]: info: VolumeController::SetAlsaVolume92 Feb 07 10:59:15 volumio volumio[1239]: info: CoreStateMachine::pushState Feb 07 10:59:15 volumio volumio[1239]: info: CorePlayQueue::getTrack 0 Feb 07 10:59:15 volumio volumio[1239]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 07 10:59:15 volumio volumio[1239]: info: CoreCommandRouter::volumioPushState Feb 07 10:59:15 volumio volumio[1239]: SPOTIFY: received: {"type":"volume","data":{"value":92,"max":100}} Feb 07 10:59:15 volumio volumio[1239]: SPOTIFY: RECEIVED SPOTIFY VOLUME 92 Feb 07 10:59:15 volumio volumio[1239]: SPOTIFY: RECEIVED VOLUMIO VOLUME 92 Feb 07 10:59:15 volumio go-librespot[3416]: time="2026-02-07T10:59:15Z" level=debug msg="update volume requested to 49807/65535" Feb 07 10:59:15 volumio go-librespot[3416]: time="2026-02-07T10:59:15Z" level=debug msg="put connect state because VOLUME_CHANGED" Feb 07 10:59:15 volumio go-librespot[3416]: time="2026-02-07T10:59:15Z" level=trace msg="emitting websocket event: volume" Feb 07 10:59:15 volumio volumio[1239]: SPOTIFY: received: {"type":"volume","data":{"value":76,"max":100}} Feb 07 10:59:15 volumio volumio[1239]: SPOTIFY: RECEIVED SPOTIFY VOLUME 76 Feb 07 10:59:15 volumio volumio[1239]: info: Setting Volumio Volume from Spotify: 76 Feb 07 10:59:15 volumio volumio[1239]: info: VolumeController::SetAlsaVolume76 Feb 07 10:59:15 volumio volumio[1239]: info: CoreStateMachine::pushState Feb 07 10:59:15 volumio volumio[1239]: info: CorePlayQueue::getTrack 0 Feb 07 10:59:15 volumio volumio[1239]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 07 10:59:15 volumio volumio[1239]: info: CoreCommandRouter::volumioPushState Feb 07 10:59:15 volumio volumio[1239]: SPOTIFY: received: {"type":"volume","data":{"value":76,"max":100}} Feb 07 10:59:15 volumio volumio[1239]: SPOTIFY: RECEIVED SPOTIFY VOLUME 76 Feb 07 10:59:15 volumio volumio[1239]: SPOTIFY: RECEIVED VOLUMIO VOLUME 76 Feb 07 10:59:16 volumio go-librespot[3416]: time="2026-02-07T10:59:16Z" level=debug msg="update volume requested to 52428/65535" Feb 07 10:59:16 volumio go-librespot[3416]: time="2026-02-07T10:59:16Z" level=debug msg="put connect state because VOLUME_CHANGED" Feb 07 10:59:16 volumio go-librespot[3416]: time="2026-02-07T10:59:16Z" level=trace msg="emitting websocket event: volume" Feb 07 10:59:16 volumio volumio[1239]: SPOTIFY: received: {"type":"volume","data":{"value":80,"max":100}} Feb 07 10:59:16 volumio volumio[1239]: SPOTIFY: RECEIVED SPOTIFY VOLUME 80 Feb 07 10:59:16 volumio volumio[1239]: info: Setting Volumio Volume from Spotify: 80 Feb 07 10:59:16 volumio volumio[1239]: info: VolumeController::SetAlsaVolume80 Feb 07 10:59:16 volumio volumio[1239]: info: CoreStateMachine::pushState Feb 07 10:59:16 volumio volumio[1239]: info: CorePlayQueue::getTrack 0 Feb 07 10:59:16 volumio volumio[1239]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 07 10:59:16 volumio volumio[1239]: info: CoreCommandRouter::volumioPushState Feb 07 10:59:16 volumio volumio[1239]: SPOTIFY: received: {"type":"volume","data":{"value":80,"max":100}} Feb 07 10:59:16 volumio volumio[1239]: SPOTIFY: RECEIVED SPOTIFY VOLUME 80 Feb 07 10:59:16 volumio volumio[1239]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80 Feb 07 10:59:16 volumio go-librespot[3416]: time="2026-02-07T10:59:16Z" level=debug msg="update volume requested to 55049/65535" Feb 07 10:59:16 volumio go-librespot[3416]: time="2026-02-07T10:59:16Z" level=debug msg="put connect state because VOLUME_CHANGED" Feb 07 10:59:16 volumio go-librespot[3416]: time="2026-02-07T10:59:16Z" level=trace msg="emitting websocket event: volume" Feb 07 10:59:16 volumio volumio[1239]: SPOTIFY: received: {"type":"volume","data":{"value":84,"max":100}} Feb 07 10:59:16 volumio volumio[1239]: SPOTIFY: RECEIVED SPOTIFY VOLUME 84 Feb 07 10:59:16 volumio volumio[1239]: info: Setting Volumio Volume from Spotify: 84 Feb 07 10:59:16 volumio volumio[1239]: info: VolumeController::SetAlsaVolume84 Feb 07 10:59:16 volumio volumio[1239]: info: CoreStateMachine::pushState Feb 07 10:59:16 volumio volumio[1239]: info: CorePlayQueue::getTrack 0 Feb 07 10:59:16 volumio volumio[1239]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 07 10:59:16 volumio volumio[1239]: info: CoreCommandRouter::volumioPushState Feb 07 10:59:16 volumio volumio[1239]: SPOTIFY: received: {"type":"volume","data":{"value":84,"max":100}} Feb 07 10:59:16 volumio volumio[1239]: SPOTIFY: RECEIVED SPOTIFY VOLUME 84 Feb 07 10:59:16 volumio volumio[1239]: SPOTIFY: RECEIVED VOLUMIO VOLUME 84 Feb 07 10:59:16 volumio go-librespot[3416]: time="2026-02-07T10:59:16Z" level=debug msg="update volume requested to 60292/65535" Feb 07 10:59:16 volumio go-librespot[3416]: time="2026-02-07T10:59:16Z" level=debug msg="put connect state because VOLUME_CHANGED" Feb 07 10:59:16 volumio go-librespot[3416]: time="2026-02-07T10:59:16Z" level=trace msg="emitting websocket event: volume" Feb 07 10:59:16 volumio volumio[1239]: SPOTIFY: received: {"type":"volume","data":{"value":92,"max":100}} Feb 07 10:59:16 volumio volumio[1239]: SPOTIFY: RECEIVED SPOTIFY VOLUME 92 Feb 07 10:59:16 volumio volumio[1239]: info: Setting Volumio Volume from Spotify: 92 Feb 07 10:59:16 volumio volumio[1239]: info: VolumeController::SetAlsaVolume92 Feb 07 10:59:17 volumio volumio[1239]: info: CoreStateMachine::pushState Feb 07 10:59:17 volumio volumio[1239]: info: CorePlayQueue::getTrack 0 Feb 07 10:59:17 volumio volumio[1239]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 07 10:59:17 volumio volumio[1239]: info: CoreCommandRouter::volumioPushState Feb 07 10:59:17 volumio volumio[1239]: SPOTIFY: received: {"type":"volume","data":{"value":92,"max":100}} Feb 07 10:59:17 volumio volumio[1239]: SPOTIFY: RECEIVED SPOTIFY VOLUME 92 Feb 07 10:59:17 volumio volumio[1239]: SPOTIFY: RECEIVED VOLUMIO VOLUME 92 Feb 07 10:59:21 volumio go-librespot[3416]: time="2026-02-07T10:59:21Z" level=trace msg="received accesspoint ping" Feb 07 10:59:21 volumio go-librespot[3416]: time="2026-02-07T10:59:21Z" level=trace msg="received accesspoint pong ack" Feb 07 10:59:21 volumio go-librespot[3416]: time="2026-02-07T10:59:21Z" level=trace msg="sent dealer ping" Feb 07 10:59:21 volumio go-librespot[3416]: time="2026-02-07T10:59:21Z" level=trace msg="received dealer pong" Feb 07 10:59:21 volumio ntpd[879]: PROTO: 87.106.36.214 unlink local addr 192.168.2.113 -> Feb 07 10:59:51 volumio go-librespot[3416]: time="2026-02-07T10:59:51Z" level=trace msg="sent dealer ping" Feb 07 10:59:51 volumio go-librespot[3416]: time="2026-02-07T10:59:51Z" level=trace msg="received dealer pong" Feb 07 11:00:03 volumio go-librespot[3416]: time="2026-02-07T11:00:03Z" level=info msg="playback was transferred to " Feb 07 11:00:03 volumio go-librespot[3416]: time="2026-02-07T11:00:03Z" level=debug msg="put connect state inactive" Feb 07 11:00:03 volumio go-librespot[3416]: time="2026-02-07T11:00:03Z" level=trace msg="emitting websocket event: inactive" Feb 07 11:00:03 volumio volumio[1239]: SPOTIFY: received: {"type":"inactive","data":null} Feb 07 11:00:03 volumio volumio[1239]: error: Failed to decode event: inactive Feb 07 11:00:03 volumio volumio[1239]: SPOTIFY: received: {"type":"inactive","data":null} Feb 07 11:00:03 volumio volumio[1239]: error: Failed to decode event: inactive Feb 07 11:00:03 volumio go-librespot[3416]: time="2026-02-07T11:00:03Z" level=debug msg="dealer connection closed" Feb 07 11:00:03 volumio go-librespot[3416]: time="2026-02-07T11:00:03Z" level=debug msg="dealer recv loop stopped" Feb 07 11:00:03 volumio go-librespot[3416]: time="2026-02-07T11:00:03Z" level=debug msg="obtained new client token: AAA7QF7/wNngn4VaJkwU6GM01MZhvC8qDzLDYXqlwPhUSAbPVwhR7rvXCMZH+gNwZiRPOdbqLbPtYQ27IPmUVkx/GUXes91JzF9ECplFnq0Xqpi5vbV3sgatX8xFAs2m8jCw6mXKFHlZTP/99MlP7QpFRS1X1Lxh9aKGYmrKaapQeI6WxVkBIV5sXdUB29PyutmPf6wh2TXzj8QgB76Is6ieX8vpn3XCfjuEUMOHLFaOrwX6TtSGjRg=" Feb 07 11:00:03 volumio go-librespot[3416]: time="2026-02-07T11:00:03Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Feb 07 11:00:03 volumio go-librespot[3416]: time="2026-02-07T11:00:03Z" level=warning msg="failed connecting to accesspoint, retrying" error="failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Feb 07 11:00:03 volumio go-librespot[3416]: time="2026-02-07T11:00:03Z" level=debug msg="connected to ap-gew1.spotify.com:443" Feb 07 11:00:03 volumio go-librespot[3416]: time="2026-02-07T11:00:03Z" level=warning msg="failed connecting to accesspoint, retrying" error="failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Feb 07 11:00:04 volumio go-librespot[3416]: time="2026-02-07T11:00:04Z" level=debug msg="connected to ap-gew1.spotify.com:80" Feb 07 11:00:04 volumio go-librespot[3416]: time="2026-02-07T11:00:04Z" level=warning msg="failed connecting to accesspoint, retrying" error="failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: read tcp 192.168.2.113:52996->104.199.65.9:80: read: connection reset by peer" Feb 07 11:00:04 volumio go-librespot[3416]: time="2026-02-07T11:00:04Z" level=debug msg="connected to ap-gue1.spotify.com:4070" Feb 07 11:00:05 volumio go-librespot[3416]: time="2026-02-07T11:00:05Z" level=debug msg="completed keyexchange" Feb 07 11:00:05 volumio go-librespot[3416]: time="2026-02-07T11:00:05Z" level=debug msg="completed challenge" Feb 07 11:00:05 volumio go-librespot[3416]: time="2026-02-07T11:00:05Z" level=info msg="authenticated AP" username="ga*********************h1" Feb 07 11:00:05 volumio go-librespot[3416]: time="2026-02-07T11:00:05Z" level=info msg="authenticated Login5" username="ga*********************h1" Feb 07 11:00:05 volumio go-librespot[3416]: time="2026-02-07T11:00:05Z" level=debug msg="restored session after logout" username="ga*********************h1" Feb 07 11:00:05 volumio go-librespot[3416]: time="2026-02-07T11:00:05Z" level=debug msg="dealer connection opened" Feb 07 11:00:05 volumio go-librespot[3416]: time="2026-02-07T11:00:05Z" level=trace msg="starting accesspoint recv loop" Feb 07 11:00:05 volumio go-librespot[3416]: time="2026-02-07T11:00:05Z" level=trace msg="received accesspoint ping" Feb 07 11:00:05 volumio go-librespot[3416]: time="2026-02-07T11:00:05Z" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Feb 07 11:00:05 volumio go-librespot[3416]: time="2026-02-07T11:00:05Z" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Feb 07 11:00:05 volumio go-librespot[3416]: time="2026-02-07T11:00:05Z" level=trace msg="starting dealer recv loop" Feb 07 11:00:05 volumio go-librespot[3416]: time="2026-02-07T11:00:05Z" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Feb 07 11:00:05 volumio go-librespot[3416]: time="2026-02-07T11:00:05Z" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Feb 07 11:00:05 volumio go-librespot[3416]: time="2026-02-07T11:00:05Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Feb 07 11:00:05 volumio go-librespot[3416]: time="2026-02-07T11:00:05Z" level=debug msg="received connection id: YjEwOThjNzMtMjMx...NTY0MzMzREFGQQ==" Feb 07 11:00:05 volumio go-librespot[3416]: time="2026-02-07T11:00:05Z" level=debug msg="put connect state because NEW_DEVICE" Feb 07 11:00:05 volumio go-librespot[3416]: time="2026-02-07T11:00:05Z" level=trace msg="received accesspoint pong ack" Feb 07 11:00:20 volumio volumio[1239]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Feb 07 11:00:20 volumio volumio[1239]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Feb 07 11:00:20 volumio volumio[1239]: info: Creating Spotify config file Feb 07 11:00:20 volumio volumio[1239]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 07 11:00:20 volumio volumio[1239]: info: Spotify config file written Feb 07 11:00:20 volumio sudo[3738]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 07 11:00:20 volumio sudo[3738]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 07 11:00:20 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Feb 07 11:00:20 volumio systemd[1]: go-librespot-daemon.service: Killing process 3421 (go-librespot) with signal SIGKILL. Feb 07 11:00:20 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Feb 07 11:00:20 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 07 11:00:20 volumio systemd[1]: go-librespot-daemon.service: Consumed 1.290s CPU time. Feb 07 11:00:20 volumio volumio[1239]: info: Connection to go-librespot Websocket closed Feb 07 11:00:20 volumio volumio[1239]: info: Connection to go-librespot Websocket closed Feb 07 11:00:20 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 07 11:00:20 volumio go-librespot[3740]: go-librespot daemon starting... Feb 07 11:00:20 volumio sudo[3738]: pam_unix(sudo:session): session closed for user root Feb 07 11:00:20 volumio go-librespot[3741]: time="2026-02-07T11:00:20Z" level=info msg="running go-librespot 0.6.2" Feb 07 11:00:20 volumio go-librespot[3741]: time="2026-02-07T11:00:20Z" level=debug msg="app state loaded" Feb 07 11:00:20 volumio go-librespot[3741]: time="2026-02-07T11:00:20Z" level=info msg="api server listening on 127.0.0.1:9879" Feb 07 11:00:21 volumio go-librespot[3741]: time="2026-02-07T11:00:21Z" 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 07 11:00:21 volumio go-librespot[3741]: time="2026-02-07T11:00:21Z" 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 07 11:00:21 volumio go-librespot[3741]: time="2026-02-07T11:00:21Z" 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 07 11:00:21 volumio go-librespot[3741]: time="2026-02-07T11:00:21Z" level=info msg="zeroconf server listening on port 46331" Feb 07 11:00:21 volumio go-librespot[3741]: time="2026-02-07T11:00:21Z" level=debug msg="obtained new client token: AAD5CCpm8QXjHlH7cQzP3i6WF8HrULGr8ieR0n0BoJGkp+ZPDOk6qLaMXkDOX2DAOjiv2fPxFgCw2/wdWKA1pGmX/HzySCBTD1manKPE755Z15CW34DYkFgr7IibnjqboscTOwVCX8ZcTWXZJLEG6IAG7524FtBHeZcIDFZcfBy1+HRD/nHl//hhgo8EVQ8cb9RmGgcA/8PosyrEbmeN3aHDH7cm1iJy+J4Dl5cP1b3qxXeo1emnxM8=" Feb 07 11:00:21 volumio go-librespot[3741]: time="2026-02-07T11:00:21Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Feb 07 11:00:21 volumio go-librespot[3741]: time="2026-02-07T11:00:21Z" level=warning msg="failed connecting to accesspoint, retrying" error="failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Feb 07 11:00:21 volumio go-librespot[3741]: time="2026-02-07T11:00:21Z" level=debug msg="connected to ap-gew1.spotify.com:443" Feb 07 11:00:21 volumio go-librespot[3741]: time="2026-02-07T11:00:21Z" level=warning msg="failed connecting to accesspoint, retrying" error="failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: read tcp 192.168.2.113:39546->104.199.65.9:443: read: connection reset by peer" Feb 07 11:00:22 volumio volumio[1239]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Feb 07 11:00:22 volumio volumio[1239]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Feb 07 11:00:22 volumio volumio[1239]: info: Creating Spotify config file Feb 07 11:00:22 volumio volumio[1239]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 07 11:00:22 volumio volumio[1239]: info: Spotify config file written Feb 07 11:00:22 volumio sudo[3752]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 07 11:00:22 volumio sudo[3752]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 07 11:00:22 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Feb 07 11:00:22 volumio systemd[1]: go-librespot-daemon.service: Killing process 3744 (go-librespot) with signal SIGKILL. Feb 07 11:00:22 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Feb 07 11:00:22 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 07 11:00:22 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 07 11:00:22 volumio go-librespot[3755]: go-librespot daemon starting... Feb 07 11:00:22 volumio sudo[3752]: pam_unix(sudo:session): session closed for user root Feb 07 11:00:22 volumio go-librespot[3757]: time="2026-02-07T11:00:22Z" level=info msg="running go-librespot 0.6.2" Feb 07 11:00:22 volumio go-librespot[3757]: time="2026-02-07T11:00:22Z" level=debug msg="app state loaded" Feb 07 11:00:22 volumio go-librespot[3757]: time="2026-02-07T11:00:22Z" level=info msg="api server listening on 127.0.0.1:9879" Feb 07 11:00:22 volumio go-librespot[3757]: time="2026-02-07T11:00:22Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Feb 07 11:00:22 volumio go-librespot[3757]: time="2026-02-07T11:00:22Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 07 11:00:22 volumio go-librespot[3757]: time="2026-02-07T11:00:22Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 07 11:00:22 volumio go-librespot[3757]: time="2026-02-07T11:00:22Z" level=info msg="zeroconf server listening on port 36113" Feb 07 11:00:22 volumio go-librespot[3757]: time="2026-02-07T11:00:22Z" level=debug msg="obtained new client token: AAC6FEXJUbvSUZ2S68ta2xFvMV/7UB6RTljDr4LxgBULdmXHTj4N+SSbjhE23wS3Y6e8sLHtvBnpPr+sDMSv14hy1PbzLOdLdPEPi/39XQu46cYmJPSqweu7qAKqPFWmFcrpJn5xVw/FLn0f/rD7DVqLcxkNWquMaIAElyde3ujVcv6QaH8nApe0RgkqZ17/5XrxwscXMfApRQsUwU/2U2MSIaLqovInsjb4/cnkQNEFuhJy7ZXvutTRJg==" Feb 07 11:00:22 volumio go-librespot[3757]: time="2026-02-07T11:00:22Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Feb 07 11:00:22 volumio go-librespot[3757]: time="2026-02-07T11:00:22Z" level=debug msg="completed keyexchange" Feb 07 11:00:22 volumio go-librespot[3757]: time="2026-02-07T11:00:22Z" level=debug msg="completed challenge" Feb 07 11:00:22 volumio go-librespot[3757]: time="2026-02-07T11:00:22Z" level=info msg="authenticated AP" username="ga*********************h1" Feb 07 11:00:22 volumio go-librespot[3757]: time="2026-02-07T11:00:22Z" level=info msg="authenticated Login5" username="ga*********************h1" Feb 07 11:00:22 volumio go-librespot[3757]: time="2026-02-07T11:00:22Z" level=debug msg="initializing zeroconf session" username="ga*********************h1" Feb 07 11:00:22 volumio go-librespot[3757]: time="2026-02-07T11:00:22Z" level=debug msg="dealer connection opened" Feb 07 11:00:22 volumio go-librespot[3757]: time="2026-02-07T11:00:22Z" level=trace msg="starting accesspoint recv loop" Feb 07 11:00:22 volumio go-librespot[3757]: time="2026-02-07T11:00:22Z" level=trace msg="starting dealer recv loop" Feb 07 11:00:22 volumio go-librespot[3757]: time="2026-02-07T11:00:22Z" level=trace msg="received accesspoint ping" Feb 07 11:00:22 volumio go-librespot[3757]: time="2026-02-07T11:00:22Z" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Feb 07 11:00:22 volumio go-librespot[3757]: time="2026-02-07T11:00:22Z" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Feb 07 11:00:22 volumio go-librespot[3757]: time="2026-02-07T11:00:22Z" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Feb 07 11:00:22 volumio go-librespot[3757]: time="2026-02-07T11:00:22Z" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Feb 07 11:00:22 volumio go-librespot[3757]: time="2026-02-07T11:00:22Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Feb 07 11:00:22 volumio go-librespot[3757]: time="2026-02-07T11:00:22Z" level=debug msg="received connection id: YzQwMTg3NmItODRk...QzNFMjRBRUVBOA==" Feb 07 11:00:22 volumio go-librespot[3757]: time="2026-02-07T11:00:22Z" level=trace msg="received accesspoint pong ack" Feb 07 11:00:22 volumio go-librespot[3757]: time="2026-02-07T11:00:22Z" level=debug msg="put connect state because NEW_DEVICE" Feb 07 11:00:23 volumio volumio[1239]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Feb 07 11:00:23 volumio volumio[1239]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Feb 07 11:00:23 volumio volumio[1239]: info: Creating Spotify config file Feb 07 11:00:23 volumio volumio[1239]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 07 11:00:23 volumio volumio[1239]: info: Spotify config file written Feb 07 11:00:23 volumio sudo[3782]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 07 11:00:23 volumio sudo[3782]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 07 11:00:23 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Feb 07 11:00:23 volumio systemd[1]: go-librespot-daemon.service: Killing process 3759 (go-librespot) with signal SIGKILL. Feb 07 11:00:23 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Feb 07 11:00:23 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 07 11:00:23 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 07 11:00:23 volumio go-librespot[3784]: go-librespot daemon starting... Feb 07 11:00:23 volumio sudo[3782]: pam_unix(sudo:session): session closed for user root Feb 07 11:00:23 volumio go-librespot[3785]: time="2026-02-07T11:00:23Z" level=info msg="running go-librespot 0.6.2" Feb 07 11:00:23 volumio go-librespot[3785]: time="2026-02-07T11:00:23Z" level=debug msg="app state loaded" Feb 07 11:00:23 volumio go-librespot[3785]: time="2026-02-07T11:00:23Z" level=info msg="api server listening on 127.0.0.1:9879" Feb 07 11:00:23 volumio volumio[1239]: info: Initializing connection to go-librespot Websocket Feb 07 11:00:23 volumio go-librespot[3785]: time="2026-02-07T11:00:23Z" level=debug msg="new websocket client" Feb 07 11:00:23 volumio volumio[1239]: info: Connection to go-librespot Websocket established Feb 07 11:00:23 volumio volumio[1239]: info: go-librespot daemon successfully initialized Feb 07 11:00:23 volumio go-librespot[3785]: time="2026-02-07T11:00:23Z" 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-gew4.spotify.com:80]" Feb 07 11:00:23 volumio go-librespot[3785]: time="2026-02-07T11:00:23Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Feb 07 11:00:23 volumio go-librespot[3785]: time="2026-02-07T11:00:23Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Feb 07 11:00:23 volumio go-librespot[3785]: time="2026-02-07T11:00:23Z" level=info msg="zeroconf server listening on port 44477" Feb 07 11:00:23 volumio go-librespot[3785]: time="2026-02-07T11:00:23Z" level=debug msg="obtained new client token: AABnYB6VyK28YJO5D2ZKIJqCGkmTvLNwGgoUZFq0Bpx9TtzjmTpn42WV9gHtKudXMRJs8WLJoTkn0412bAf8NE4ZYz2AFegEoasYRg1ncdlA5Xb7vJzrJRn6dd/z2WUPCWIMC3GB8PxukVCJL8Z+Qw7+PJcZpxYsAR/3LgGXMD5N6gq1+Haeh3uaIPncsb0PRk0Fs/SPWi0+0K7reoD8MuKuvQzZnAR5OPjnVKiVfuO0OvjTjEboQWDMvA==" Feb 07 11:00:23 volumio go-librespot[3785]: time="2026-02-07T11:00:23Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Feb 07 11:00:23 volumio go-librespot[3785]: time="2026-02-07T11:00:23Z" level=warning msg="failed connecting to accesspoint, retrying" error="failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Feb 07 11:00:24 volumio go-librespot[3785]: time="2026-02-07T11:00:24Z" level=debug msg="connected to ap-gew1.spotify.com:443" Feb 07 11:00:24 volumio go-librespot[3785]: time="2026-02-07T11:00:24Z" level=warning msg="failed connecting to accesspoint, retrying" error="failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Feb 07 11:00:24 volumio go-librespot[3785]: time="2026-02-07T11:00:24Z" level=debug msg="connected to ap-gew1.spotify.com:80" Feb 07 11:00:24 volumio go-librespot[3785]: time="2026-02-07T11:00:24Z" level=warning msg="failed connecting to accesspoint, retrying" error="failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Feb 07 11:00:25 volumio volumio[1239]: info: go-librespot daemon successfully initialized Feb 07 11:00:25 volumio go-librespot[3785]: time="2026-02-07T11:00:25Z" level=debug msg="connected to ap-guc3.spotify.com:4070" Feb 07 11:00:25 volumio go-librespot[3785]: time="2026-02-07T11:00:25Z" level=debug msg="completed keyexchange" Feb 07 11:00:25 volumio go-librespot[3785]: time="2026-02-07T11:00:25Z" level=debug msg="completed challenge" Feb 07 11:00:25 volumio go-librespot[3785]: time="2026-02-07T11:00:25Z" level=info msg="authenticated AP" username="ga*********************h1" Feb 07 11:00:25 volumio go-librespot[3785]: time="2026-02-07T11:00:25Z" level=info msg="authenticated Login5" username="ga*********************h1" Feb 07 11:00:25 volumio go-librespot[3785]: time="2026-02-07T11:00:25Z" level=debug msg="initializing zeroconf session" username="ga*********************h1" Feb 07 11:00:25 volumio go-librespot[3785]: time="2026-02-07T11:00:25Z" level=debug msg="dealer connection opened" Feb 07 11:00:25 volumio go-librespot[3785]: time="2026-02-07T11:00:25Z" level=trace msg="starting accesspoint recv loop" Feb 07 11:00:25 volumio go-librespot[3785]: time="2026-02-07T11:00:25Z" level=trace msg="starting dealer recv loop" Feb 07 11:00:25 volumio go-librespot[3785]: time="2026-02-07T11:00:25Z" level=trace msg="received accesspoint ping" Feb 07 11:00:25 volumio go-librespot[3785]: time="2026-02-07T11:00:25Z" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Feb 07 11:00:25 volumio go-librespot[3785]: time="2026-02-07T11:00:25Z" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Feb 07 11:00:25 volumio go-librespot[3785]: time="2026-02-07T11:00:25Z" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Feb 07 11:00:25 volumio go-librespot[3785]: time="2026-02-07T11:00:25Z" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Feb 07 11:00:25 volumio go-librespot[3785]: time="2026-02-07T11:00:25Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Feb 07 11:00:25 volumio go-librespot[3785]: time="2026-02-07T11:00:25Z" level=debug msg="received connection id: YTFhYjRlNzQtYTc1...RUY0OEMxMjJEOQ==" Feb 07 11:00:25 volumio go-librespot[3785]: time="2026-02-07T11:00:25Z" level=debug msg="put connect state because NEW_DEVICE" Feb 07 11:00:26 volumio go-librespot[3785]: time="2026-02-07T11:00:26Z" level=trace msg="received accesspoint pong ack" Feb 07 11:00:26 volumio volumio[1239]: info: go-librespot daemon successfully initialized Feb 07 11:00:26 volumio volumio[1239]: info: Getting Spotify volume Feb 07 11:00:26 volumio volumio[1239]: info: Spotify volume: 100 Feb 07 11:00:26 volumio volumio[1239]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Feb 07 11:00:26 volumio volumio[1239]: info: Initializing connection to go-librespot Websocket Feb 07 11:00:26 volumio go-librespot[3785]: time="2026-02-07T11:00:26Z" level=debug msg="new websocket client" Feb 07 11:00:26 volumio volumio[1239]: info: Connection to go-librespot Websocket established Feb 07 11:00:26 volumio volumio[1239]: info: CoreCommandRouter::volumioGetState Feb 07 11:00:26 volumio volumio[1239]: info: CorePlayQueue::getTrack 0 Feb 07 11:00:26 volumio volumio[1239]: SPOTIFY: RECEIVED VOLUMIO VOLUME 92 Feb 07 11:00:26 volumio volumio[1239]: SPOTIFY: SPOTIFY VOLUME 100 Feb 07 11:00:26 volumio volumio[1239]: SPOTIFY: VOLUMIO VOLUME 92 Feb 07 11:00:26 volumio volumio[1239]: SPOTIFY: DELTA VOLUME ENOUGH: true Feb 07 11:00:26 volumio volumio[1239]: info: Setting Spotify Volume from Volumio: 92 Feb 07 11:00:28 volumio volumio[1239]: info: Initializing connection to go-librespot Websocket Feb 07 11:00:28 volumio go-librespot[3785]: time="2026-02-07T11:00:28Z" level=debug msg="new websocket client" Feb 07 11:00:28 volumio volumio[1239]: info: Connection to go-librespot Websocket established Feb 07 11:00:28 volumio volumio[1239]: SPOTIFY: SETTING SPOTIFY VOLUME 92 Feb 07 11:00:28 volumio volumio[1239]: info: Sending Spotify command with payload to local API: /player/volume Feb 07 11:00:28 volumio go-librespot[3785]: time="2026-02-07T11:00:28Z" level=debug msg="update volume requested to 60292/65535" Feb 07 11:00:28 volumio go-librespot[3785]: time="2026-02-07T11:00:28Z" level=debug msg="put connect state because VOLUME_CHANGED" Feb 07 11:00:28 volumio go-librespot[3785]: time="2026-02-07T11:00:28Z" level=trace msg="emitting websocket event: volume" Feb 07 11:00:28 volumio volumio[1239]: SPOTIFY: received: {"type":"volume","data":{"value":92,"max":100}} Feb 07 11:00:28 volumio volumio[1239]: SPOTIFY: RECEIVED SPOTIFY VOLUME 92 Feb 07 11:00:28 volumio volumio[1239]: SPOTIFY: received: {"type":"volume","data":{"value":92,"max":100}} Feb 07 11:00:28 volumio volumio[1239]: SPOTIFY: RECEIVED SPOTIFY VOLUME 92 Feb 07 11:00:28 volumio volumio[1239]: SPOTIFY: received: {"type":"volume","data":{"value":92,"max":100}} Feb 07 11:00:28 volumio volumio[1239]: SPOTIFY: RECEIVED SPOTIFY VOLUME 92 Feb 07 11:00:29 volumio volumio[1239]: info: Initializing connection to go-librespot Websocket Feb 07 11:00:29 volumio go-librespot[3785]: time="2026-02-07T11:00:29Z" level=debug msg="new websocket client" Feb 07 11:00:29 volumio volumio[1239]: info: Connection to go-librespot Websocket established Feb 07 11:00:29 volumio volumio[1239]: info: Getting Spotify volume Feb 07 11:00:29 volumio volumio[1239]: info: Spotify volume: 92 Feb 07 11:00:29 volumio volumio[1239]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Feb 07 11:00:29 volumio volumio[1239]: info: CoreCommandRouter::volumioGetState Feb 07 11:00:29 volumio volumio[1239]: info: CorePlayQueue::getTrack 0 Feb 07 11:00:29 volumio volumio[1239]: SPOTIFY: RECEIVED VOLUMIO VOLUME 92 Feb 07 11:00:31 volumio volumio[1239]: info: Getting Spotify volume Feb 07 11:00:31 volumio volumio[1239]: info: Spotify volume: 92 Feb 07 11:00:31 volumio volumio[1239]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Feb 07 11:00:31 volumio volumio[1239]: info: CoreCommandRouter::volumioGetState Feb 07 11:00:31 volumio volumio[1239]: info: CorePlayQueue::getTrack 0 Feb 07 11:00:31 volumio volumio[1239]: SPOTIFY: RECEIVED VOLUMIO VOLUME 92 Feb 07 11:00:32 volumio volumio[1239]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Feb 07 11:00:32 volumio volumio[1239]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Feb 07 11:00:32 volumio volumio[1239]: info: Creating Spotify config file Feb 07 11:00:32 volumio volumio[1239]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 07 11:00:32 volumio volumio[1239]: info: Spotify config file written Feb 07 11:00:32 volumio sudo[3799]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 07 11:00:32 volumio sudo[3799]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 07 11:00:32 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Feb 07 11:00:32 volumio systemd[1]: go-librespot-daemon.service: Killing process 3791 (go-librespot) with signal SIGKILL. Feb 07 11:00:32 volumio volumio[1239]: info: Connection to go-librespot Websocket closed Feb 07 11:00:32 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Feb 07 11:00:32 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 07 11:00:32 volumio volumio[1239]: info: Connection to go-librespot Websocket closed Feb 07 11:00:32 volumio volumio[1239]: info: Connection to go-librespot Websocket closed Feb 07 11:00:32 volumio volumio[1239]: info: Connection to go-librespot Websocket closed Feb 07 11:00:32 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 07 11:00:32 volumio go-librespot[3802]: go-librespot daemon starting... Feb 07 11:00:32 volumio volumio[1239]: info: Getting Spotify volume Feb 07 11:00:32 volumio sudo[3799]: pam_unix(sudo:session): session closed for user root Feb 07 11:00:32 volumio volumio[1239]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 07 11:00:32 volumio go-librespot[3803]: time="2026-02-07T11:00:32Z" level=info msg="running go-librespot 0.6.2" Feb 07 11:00:32 volumio go-librespot[3803]: time="2026-02-07T11:00:32Z" level=debug msg="app state loaded" Feb 07 11:00:32 volumio volumio[1239]: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 07 11:00:32 volumio volumio[1239]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Feb 07 11:00:32 volumio volumio[1239]: errno: -111, Feb 07 11:00:32 volumio volumio[1239]: code: 'ECONNREFUSED', Feb 07 11:00:32 volumio volumio[1239]: syscall: 'connect', Feb 07 11:00:32 volumio volumio[1239]: address: '127.0.0.1', Feb 07 11:00:32 volumio volumio[1239]: port: 9879, Feb 07 11:00:32 volumio volumio[1239]: response: undefined Feb 07 11:00:32 volumio volumio[1239]: } Feb 07 11:00:32 volumio volumio[1239]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 07 11:00:32 volumio go-librespot[3803]: time="2026-02-07T11:00:32Z" level=info msg="api server listening on 127.0.0.1:9879" Feb 07 11:00:32 volumio go-librespot[3803]: time="2026-02-07T11:00:32Z" 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 07 11:00:32 volumio go-librespot[3803]: time="2026-02-07T11:00:32Z" 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 07 11:00:32 volumio go-librespot[3803]: time="2026-02-07T11:00:32Z" 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 07 11:00:32 volumio go-librespot[3803]: time="2026-02-07T11:00:32Z" level=info msg="zeroconf server listening on port 33343" Feb 07 11:00:32 volumio go-librespot[3803]: time="2026-02-07T11:00:32Z" level=debug msg="obtained new client token: AACc9wV5XO6Zafv4RiS1arN0NbUfwXddC498GBSqqsFk2UhXaGokdlDjvzoT6Gx05O4s6rrDORAIwaG5CD3sZeEsAkR2cKP+4Ayhq5Yj7DL2aBnoNXQWapKSoCXP7rZokenUla7sPZUs5L9sirmuYFfF/cwxd4rJKbWsiby2Eo+hHdGpfM/Tgsdk5eVqK8g7Ksw+PXR0U3m9vqtcK12yiN+pnWOUuWlvECvUz2u1Z2jb16BK3iZf6ekjhw==" Feb 07 11:00:32 volumio go-librespot[3803]: time="2026-02-07T11:00:32Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Feb 07 11:00:32 volumio go-librespot[3803]: time="2026-02-07T11:00:32Z" level=debug msg="completed keyexchange" Feb 07 11:00:32 volumio go-librespot[3803]: time="2026-02-07T11:00:32Z" level=debug msg="completed challenge" Feb 07 11:00:33 volumio go-librespot[3803]: time="2026-02-07T11:00:33Z" level=info msg="authenticated AP" username="ga*********************h1" Feb 07 11:00:33 volumio go-librespot[3803]: time="2026-02-07T11:00:33Z" level=info msg="authenticated Login5" username="ga*********************h1" Feb 07 11:00:33 volumio go-librespot[3803]: time="2026-02-07T11:00:33Z" level=debug msg="initializing zeroconf session" username="ga*********************h1" Feb 07 11:00:33 volumio go-librespot[3803]: time="2026-02-07T11:00:33Z" level=debug msg="dealer connection opened" Feb 07 11:00:33 volumio go-librespot[3803]: time="2026-02-07T11:00:33Z" level=trace msg="starting accesspoint recv loop" Feb 07 11:00:33 volumio go-librespot[3803]: time="2026-02-07T11:00:33Z" level=trace msg="starting dealer recv loop" Feb 07 11:00:33 volumio go-librespot[3803]: time="2026-02-07T11:00:33Z" level=trace msg="received accesspoint ping" Feb 07 11:00:33 volumio go-librespot[3803]: time="2026-02-07T11:00:33Z" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Feb 07 11:00:33 volumio go-librespot[3803]: time="2026-02-07T11:00:33Z" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Feb 07 11:00:33 volumio go-librespot[3803]: time="2026-02-07T11:00:33Z" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Feb 07 11:00:33 volumio go-librespot[3803]: time="2026-02-07T11:00:33Z" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Feb 07 11:00:33 volumio go-librespot[3803]: time="2026-02-07T11:00:33Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Feb 07 11:00:33 volumio go-librespot[3803]: time="2026-02-07T11:00:33Z" level=debug msg="received connection id: ZjBmZmY4YTQtYmE3...RjUwNDUxRTExMw==" Feb 07 11:00:33 volumio go-librespot[3803]: time="2026-02-07T11:00:33Z" level=trace msg="received accesspoint pong ack" Feb 07 11:00:33 volumio go-librespot[3803]: time="2026-02-07T11:00:33Z" level=debug msg="put connect state because NEW_DEVICE" Feb 07 11:00:33 volumio sudo[3840]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-02-07 10:59' Feb 07 11:00:33 volumio sudo[3840]: 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="b05a530ca81d05eb9a84d0acf82089f0a60b8ee6" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="4ad85e2147d972f0b838d33c21382d2d813b2ae8" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu Dec 25 09:13:19 UTC 2025" VOLUMIO_VERSION="4.084" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="792f09af7488531aecd1aadcaa9b175e"