May 30 14:09:00 volumio volumio[1078]: info: Connection to go-librespot Websocket closed May 30 14:09:00 volumio volumio[1078]: info: Connection to go-librespot Websocket closed May 30 14:09:00 volumio go-librespot[2064]: time="2026-05-30T14:09:00+02:00" 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]" May 30 14:09:00 volumio go-librespot[2064]: time="2026-05-30T14:09:00+02:00" 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]" May 30 14:09:00 volumio go-librespot[2064]: time="2026-05-30T14:09:00+02:00" 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]" May 30 14:09:00 volumio go-librespot[2064]: time="2026-05-30T14:09:00+02:00" level=info msg="zeroconf server listening on port 41769" May 30 14:09:00 volumio volumio[1078]: verbose: New Socket.io Connection to 192.168.18.152 from 192.168.18.6 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/148.0.0.0 Safari/537.36 Edg/148.0.0.0 Engine version: 3 Transport: polling Total Clients: 6 May 30 14:09:00 volumio volumio[1078]: info: New Spotify access tokenBQDgUUTN1C... May 30 14:09:00 volumio volumio[1078]: info: Spotify credentials grant success - running version from March 24, 2019 May 30 14:09:00 volumio go-librespot[2064]: time="2026-05-30T14:09:00+02:00" level=debug msg="obtained new client token: AAA906k2N8Gdi0vGnfRVR78oVmZfLTaYSMsw9qFV4oMGAFvKOZQ0Av0QfPQvjxibvSGZLOcrkz7/q+y/t/vXAQhvkKQAMsEGQQKBRur+ZWIg24QGwlzYhhSHEwy3Rphe9D9sZAVn/TV014upUavvgbNvtYbQjWTUG/Q27Fff2ZKNaSsPNrvagektsxBet34xZQWDByg6l/HVi6V1y2AMeatSALx5l3vHJM3T/9pi7wyddpdyeNsU2bc=" May 30 14:09:00 volumio go-librespot[2064]: time="2026-05-30T14:09:00+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" May 30 14:09:00 volumio go-librespot[2064]: time="2026-05-30T14:09:00+02:00" level=debug msg="completed keyexchange" May 30 14:09:00 volumio go-librespot[2064]: time="2026-05-30T14:09:00+02:00" level=debug msg="completed challenge" May 30 14:09:00 volumio go-librespot[2064]: time="2026-05-30T14:09:00+02:00" level=info msg="authenticated AP" username="31************************ke" May 30 14:09:00 volumio go-librespot[2064]: time="2026-05-30T14:09:00+02:00" level=info msg="authenticated Login5" username="31************************ke" May 30 14:09:00 volumio go-librespot[2064]: time="2026-05-30T14:09:00+02:00" level=debug msg="stored credentials" username="31************************ke" May 30 14:09:00 volumio go-librespot[2064]: time="2026-05-30T14:09:00+02:00" level=debug msg="initializing zeroconf session" username="31************************ke" May 30 14:09:00 volumio volumio[1078]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled May 30 14:09:00 volumio volumio[1078]: info: CoreCommandRouter::volumioGetVisibleSources May 30 14:09:00 volumio volumio[1078]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 30 14:09:00 volumio volumio[1078]: info: CoreCommandRouter::volumioGetState May 30 14:09:00 volumio volumio[1078]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback May 30 14:09:00 volumio volumio[1078]: info: CoreCommandRouter::getUIConfigOnPlugin May 30 14:09:00 volumio volumio[1078]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom May 30 14:09:00 volumio volumio[1078]: info: Received Get System Info May 30 14:09:00 volumio volumio[1078]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 30 14:09:00 volumio volumio[1078]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 30 14:09:00 volumio volumio[1078]: info: Discovery: Getting this device information May 30 14:09:00 volumio volumio[1078]: info: CoreCommandRouter::volumioGetState May 30 14:09:00 volumio volumio[1078]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 30 14:09:00 volumio volumio[1078]: info: CoreCommandRouter::volumioGetState May 30 14:09:00 volumio volumio[1078]: info: Listing playlists May 30 14:09:00 volumio volumio[1078]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings May 30 14:09:00 volumio volumio[1078]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings May 30 14:09:01 volumio go-librespot[2064]: time="2026-05-30T14:09:01+02:00" level=debug msg="dealer connection opened" May 30 14:09:01 volumio go-librespot[2064]: time="2026-05-30T14:09:01+02:00" level=trace msg="starting accesspoint recv loop" May 30 14:09:01 volumio go-librespot[2064]: time="2026-05-30T14:09:01+02:00" level=trace msg="starting dealer recv loop" May 30 14:09:01 volumio go-librespot[2064]: time="2026-05-30T14:09:01+02:00" level=trace msg="received accesspoint ping" May 30 14:09:01 volumio go-librespot[2064]: time="2026-05-30T14:09:01+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" May 30 14:09:01 volumio go-librespot[2064]: time="2026-05-30T14:09:01+02:00" level=debug msg="received connection id: ZjI5MzQ2YWEtN2Fm...RUM4MTE4ODFDQw==" May 30 14:09:01 volumio go-librespot[2064]: time="2026-05-30T14:09:01+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" May 30 14:09:01 volumio volumio[1078]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache May 30 14:09:01 volumio volumio[1078]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 30 14:09:01 volumio volumio[1078]: info: Received Get System Info May 30 14:09:01 volumio volumio[1078]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 30 14:09:01 volumio volumio[1078]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 30 14:09:01 volumio volumio[1078]: info: Discovery: Getting this device information May 30 14:09:01 volumio volumio[1078]: info: CoreCommandRouter::volumioGetState May 30 14:09:01 volumio volumio[1078]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 30 14:09:01 volumio go-librespot[2064]: time="2026-05-30T14:09:01+02:00" level=debug msg="put connect state because NEW_DEVICE" May 30 14:09:01 volumio go-librespot[2064]: time="2026-05-30T14:09:01+02:00" level=debug msg="update volume requested to 65535/65535" May 30 14:09:01 volumio go-librespot[2064]: time="2026-05-30T14:09:01+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" May 30 14:09:01 volumio go-librespot[2064]: time="2026-05-30T14:09:01+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" May 30 14:09:01 volumio go-librespot[2064]: time="2026-05-30T14:09:01+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" May 30 14:09:01 volumio go-librespot[2064]: time="2026-05-30T14:09:01+02:00" level=trace msg="received accesspoint pong ack" May 30 14:09:01 volumio go-librespot[2064]: time="2026-05-30T14:09:01+02:00" level=debug msg="put connect state because VOLUME_CHANGED" May 30 14:09:01 volumio go-librespot[2064]: time="2026-05-30T14:09:01+02:00" level=trace msg="emitting websocket event: volume" May 30 14:09:01 volumio volumio[1078]: SPOTIFY: User informations: {"account_id":"TcBDc5ELBi","country":"ES","display_name":"Lineagecrisma","email":"lineagecrisma@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/31acwbvefmrgskcaz2ojfmbdwlke"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/31acwbvefmrgskcaz2ojfmbdwlke","id":"31acwbvefmrgskcaz2ojfmbdwlke","images":[],"product":"premium","type":"user","uri":"spotify:user:31acwbvefmrgskcaz2ojfmbdwlke"} May 30 14:09:01 volumio volumio[1078]: info: Spotify Successfully logged in May 30 14:09:01 volumio volumio[1078]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 30 14:09:01 volumio volumio[1078]: info: [1780142941492] CoreMusicLibrary::Adding element Spotify May 30 14:09:01 volumio volumio[1078]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 30 14:09:01 volumio volumio[1078]: Cannot find translation for source Spotify May 30 14:09:01 volumio volumio[1078]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 30 14:09:01 volumio volumio[1078]: info: Received Get System Info May 30 14:09:01 volumio volumio[1078]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 30 14:09:01 volumio volumio[1078]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 30 14:09:01 volumio volumio[1078]: info: Discovery: Getting this device information May 30 14:09:01 volumio volumio[1078]: info: CoreCommandRouter::volumioGetState May 30 14:09:01 volumio volumio[1078]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 30 14:09:02 volumio volumio[1078]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard May 30 14:09:03 volumio volumio[1078]: info: Initializing connection to go-librespot Websocket May 30 14:09:03 volumio volumio[1078]: info: go-librespot daemon successfully initialized May 30 14:09:03 volumio go-librespot[2064]: time="2026-05-30T14:09:03+02:00" level=debug msg="new websocket client" May 30 14:09:03 volumio volumio[1078]: info: Connection to go-librespot Websocket established May 30 14:09:06 volumio volumio[1078]: info: Initializing connection to go-librespot Websocket May 30 14:09:06 volumio go-librespot[2064]: time="2026-05-30T14:09:06+02:00" level=debug msg="new websocket client" May 30 14:09:06 volumio volumio[1078]: info: Connection to go-librespot Websocket established May 30 14:09:06 volumio volumio[1078]: info: Getting Spotify volume May 30 14:09:06 volumio volumio[1078]: info: Spotify volume: 100 May 30 14:09:06 volumio volumio[1078]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 May 30 14:09:06 volumio volumio[1078]: info: CoreCommandRouter::volumioGetState May 30 14:09:09 volumio volumio[1078]: info: Getting Spotify volume May 30 14:09:09 volumio volumio[1078]: info: Spotify volume: 100 May 30 14:09:09 volumio volumio[1078]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 May 30 14:09:09 volumio volumio[1078]: info: CoreCommandRouter::volumioGetState May 30 14:09:10 volumio volumio[1078]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted May 30 14:09:16 volumio go-librespot[2064]: time="2026-05-30T14:09:16+02:00" level=debug msg="handling transfer player command from 97684b78b25c8276bfd2917f262244c75f588125" May 30 14:09:16 volumio go-librespot[2064]: time="2026-05-30T14:09:16+02:00" level=debug msg="resolved context of track" uri="spotify:list:popular-release-segments-main-roles:artist_5sm0jQ1mq0dusiLtDJ2b4R" May 30 14:09:16 volumio go-librespot[2064]: time="2026-05-30T14:09:16+02:00" level=trace msg="fetched new page 0 with 60 items (list: 60)" uri="spotify:list:popular-release-segments-main-roles:artist_5sm0jQ1mq0dusiLtDJ2b4R" May 30 14:09:16 volumio go-librespot[2064]: time="2026-05-30T14:09:16+02:00" level=debug msg="loading track (paused: true, position: 9113ms)" uri="spotify:track:1HFfMOxCAT4GAwaPfCdmUs" May 30 14:09:16 volumio go-librespot[2064]: time="2026-05-30T14:09:16+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 30 14:09:16 volumio go-librespot[2064]: time="2026-05-30T14:09:16+02:00" level=trace msg="emitting websocket event: will_play" May 30 14:09:16 volumio volumio[1078]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:list:popular-release-segments-main-roles:artist_5sm0jQ1mq0dusiLtDJ2b4R","uri":"spotify:track:1HFfMOxCAT4GAwaPfCdmUs","play_origin":"com.spotify.gaia"}} May 30 14:09:16 volumio volumio[1078]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:list:popular-release-segments-main-roles:artist_5sm0jQ1mq0dusiLtDJ2b4R","uri":"spotify:track:1HFfMOxCAT4GAwaPfCdmUs","play_origin":"com.spotify.gaia"}} May 30 14:09:16 volumio go-librespot[2064]: time="2026-05-30T14:09:16+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 411" May 30 14:09:16 volumio go-librespot[2064]: time="2026-05-30T14:09:16+02:00" level=debug msg="selected format OGG_VORBIS_160 (0a3d5036789061da0374bf9b3f9032f010087903)" uri="spotify:track:1HFfMOxCAT4GAwaPfCdmUs" May 30 14:09:16 volumio go-librespot[2064]: time="2026-05-30T14:09:16+02:00" level=debug msg="requested aes key for file 0a3d5036789061da0374bf9b3f9032f010087903, gid: 1HFfMOxCAT4GAwaPfCdmUs" May 30 14:09:16 volumio go-librespot[2064]: time="2026-05-30T14:09:16+02:00" level=warning msg="failed handling dealer request" error="failed loading current track (transfer): failed creating stream for spotify:track:1HFfMOxCAT4GAwaPfCdmUs: failed retrieving audio key: failed retrieving aes key with code 1" May 30 14:09:16 volumio go-librespot[2064]: time="2026-05-30T14:09:16+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update May 30 14:09:16 volumio go-librespot[2064]: time="2026-05-30T14:09:16+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update May 30 14:09:17 volumio go-librespot[2064]: time="2026-05-30T14:09:17+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1498" May 30 14:09:17 volumio go-librespot[2064]: time="2026-05-30T14:09:17+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update May 30 14:09:17 volumio go-librespot[2064]: time="2026-05-30T14:09:17+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1251" May 30 14:09:17 volumio volumio[1078]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings May 30 14:09:17 volumio volumio[1078]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined May 30 14:09:17 volumio volumio[1078]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates May 30 14:09:17 volumio volumio[1078]: info: Received Get System Version May 30 14:09:17 volumio volumio[1078]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 30 14:09:17 volumio volumio[1078]: info: Received Get System Info May 30 14:09:17 volumio volumio[1078]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 30 14:09:17 volumio volumio[1078]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 30 14:09:17 volumio volumio[1078]: info: Discovery: Getting this device information May 30 14:09:17 volumio volumio[1078]: info: CoreCommandRouter::volumioGetState May 30 14:09:17 volumio volumio[1078]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 30 14:09:19 volumio go-librespot[2064]: time="2026-05-30T14:09:19+02:00" level=debug msg="handling resume player command from 97684b78b25c8276bfd2917f262244c75f588125" May 30 14:09:19 volumio go-librespot[2064]: time="2026-05-30T14:09:19+02:00" level=warning msg="failed handling dealer request" error="no primary stream" May 30 14:09:23 volumio go-librespot[2064]: time="2026-05-30T14:09:23+02:00" level=debug msg="handling resume player command from 97684b78b25c8276bfd2917f262244c75f588125" May 30 14:09:23 volumio go-librespot[2064]: time="2026-05-30T14:09:23+02:00" level=warning msg="failed handling dealer request" error="no primary stream" May 30 14:09:24 volumio go-librespot[2064]: time="2026-05-30T14:09:24+02:00" level=debug msg="handling resume player command from 97684b78b25c8276bfd2917f262244c75f588125" May 30 14:09:24 volumio go-librespot[2064]: time="2026-05-30T14:09:24+02:00" level=warning msg="failed handling dealer request" error="no primary stream" May 30 14:09:24 volumio go-librespot[2064]: time="2026-05-30T14:09:24+02:00" level=debug msg="handling resume player command from 97684b78b25c8276bfd2917f262244c75f588125" May 30 14:09:24 volumio go-librespot[2064]: time="2026-05-30T14:09:24+02:00" level=warning msg="failed handling dealer request" error="no primary stream" May 30 14:09:24 volumio go-librespot[2064]: time="2026-05-30T14:09:24+02:00" level=debug msg="handling resume player command from 97684b78b25c8276bfd2917f262244c75f588125" May 30 14:09:24 volumio go-librespot[2064]: time="2026-05-30T14:09:24+02:00" level=warning msg="failed handling dealer request" error="no primary stream" May 30 14:09:25 volumio go-librespot[2064]: time="2026-05-30T14:09:25+02:00" level=debug msg="handling resume player command from 97684b78b25c8276bfd2917f262244c75f588125" May 30 14:09:25 volumio go-librespot[2064]: time="2026-05-30T14:09:25+02:00" level=warning msg="failed handling dealer request" error="no primary stream" May 30 14:09:25 volumio go-librespot[2064]: time="2026-05-30T14:09:25+02:00" level=debug msg="handling resume player command from 97684b78b25c8276bfd2917f262244c75f588125" May 30 14:09:25 volumio go-librespot[2064]: time="2026-05-30T14:09:25+02:00" level=warning msg="failed handling dealer request" error="no primary stream" May 30 14:09:29 volumio go-librespot[2064]: time="2026-05-30T14:09:29+02:00" level=debug msg="handling resume player command from 97684b78b25c8276bfd2917f262244c75f588125" May 30 14:09:29 volumio go-librespot[2064]: time="2026-05-30T14:09:29+02:00" level=warning msg="failed handling dealer request" error="no primary stream" May 30 14:09:30 volumio go-librespot[2064]: time="2026-05-30T14:09:30+02:00" level=debug msg="handling resume player command from 97684b78b25c8276bfd2917f262244c75f588125" May 30 14:09:30 volumio go-librespot[2064]: time="2026-05-30T14:09:30+02:00" level=warning msg="failed handling dealer request" error="no primary stream" May 30 14:09:31 volumio go-librespot[2064]: time="2026-05-30T14:09:31+02:00" level=trace msg="sent dealer ping" May 30 14:09:31 volumio go-librespot[2064]: time="2026-05-30T14:09:31+02:00" level=trace msg="received dealer pong" May 30 14:09:37 volumio go-librespot[2064]: time="2026-05-30T14:09:37+02:00" level=info msg="playback was transferred to Web Player (Microsoft Edge)" May 30 14:09:37 volumio go-librespot[2064]: time="2026-05-30T14:09:37+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update May 30 14:09:37 volumio go-librespot[2064]: time="2026-05-30T14:09:37+02:00" level=debug msg="put connect state inactive" May 30 14:09:37 volumio go-librespot[2064]: time="2026-05-30T14:09:37+02:00" level=trace msg="emitting websocket event: inactive" May 30 14:09:37 volumio volumio[1078]: SPOTIFY: received: {"type":"inactive","data":null} May 30 14:09:37 volumio volumio[1078]: error: Failed to decode event: inactive May 30 14:09:37 volumio volumio[1078]: SPOTIFY: received: {"type":"inactive","data":null} May 30 14:09:37 volumio volumio[1078]: error: Failed to decode event: inactive May 30 14:09:37 volumio go-librespot[2064]: time="2026-05-30T14:09:37+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 323" May 30 14:09:37 volumio go-librespot[2064]: time="2026-05-30T14:09:37+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 323" May 30 14:09:37 volumio go-librespot[2064]: time="2026-05-30T14:09:37+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1490" May 30 14:09:37 volumio go-librespot[2064]: time="2026-05-30T14:09:37+02:00" level=error msg="failed receiving dealer message" error="failed to read: use of closed network connection" May 30 14:09:37 volumio go-librespot[2064]: time="2026-05-30T14:09:37+02:00" level=debug msg="dealer recv loop stopped" May 30 14:09:37 volumio go-librespot[2064]: time="2026-05-30T14:09:37+02:00" level=debug msg="obtained new client token: AAAb2P0Oo1x5pCCWSpql+YcvZRUCEtvQkTGQQe0Z7iTyPJSHjEGAYZ2BVFhAvRpiDOoP8K/vzbQ6h/b3TgSw7vqWbKgbXkrPCkHh7r2Ui7Fjd/s10yZWfzjwa1tccKfW+BQPjZebBCsAyJD89GCYFSKC7vF+7Bp4X9KV1bFP5dTvQnZf4tNOSgDSgd6dl2QRM24MdsQ11dkfmVcPZ0BhrEfYL8LKdO0hiK9TQD4HEbdQ4ZVgmaV9U88=" May 30 14:09:37 volumio go-librespot[2064]: time="2026-05-30T14:09:37+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" May 30 14:09:37 volumio go-librespot[2064]: time="2026-05-30T14:09:37+02:00" level=debug msg="completed keyexchange" May 30 14:09:37 volumio go-librespot[2064]: time="2026-05-30T14:09:37+02:00" level=debug msg="completed challenge" May 30 14:09:37 volumio go-librespot[2064]: time="2026-05-30T14:09:37+02:00" level=info msg="authenticated AP" username="31************************ke" May 30 14:09:37 volumio go-librespot[2064]: time="2026-05-30T14:09:37+02:00" level=info msg="authenticated Login5" username="31************************ke" May 30 14:09:37 volumio go-librespot[2064]: time="2026-05-30T14:09:37+02:00" level=debug msg="restored session after logout" username="31************************ke" May 30 14:09:37 volumio go-librespot[2064]: time="2026-05-30T14:09:37+02:00" level=debug msg="dealer connection opened" May 30 14:09:37 volumio go-librespot[2064]: time="2026-05-30T14:09:37+02:00" level=trace msg="starting accesspoint recv loop" May 30 14:09:37 volumio go-librespot[2064]: time="2026-05-30T14:09:37+02:00" level=trace msg="starting dealer recv loop" May 30 14:09:37 volumio go-librespot[2064]: time="2026-05-30T14:09:37+02:00" level=trace msg="received accesspoint ping" May 30 14:09:37 volumio go-librespot[2064]: time="2026-05-30T14:09:37+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" May 30 14:09:37 volumio go-librespot[2064]: time="2026-05-30T14:09:37+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" May 30 14:09:37 volumio go-librespot[2064]: time="2026-05-30T14:09:37+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" May 30 14:09:37 volumio go-librespot[2064]: time="2026-05-30T14:09:37+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" May 30 14:09:37 volumio go-librespot[2064]: time="2026-05-30T14:09:37+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" May 30 14:09:37 volumio go-librespot[2064]: time="2026-05-30T14:09:37+02:00" level=debug msg="received connection id: MzBlYTY3MzktZGMz...M0IwQzFCM0VGRg==" May 30 14:09:37 volumio go-librespot[2064]: time="2026-05-30T14:09:37+02:00" level=trace msg="received accesspoint pong ack" May 30 14:09:37 volumio go-librespot[2064]: time="2026-05-30T14:09:37+02:00" level=debug msg="put connect state because NEW_DEVICE" May 30 14:09:37 volumio go-librespot[2064]: time="2026-05-30T14:09:37+02:00" level=debug msg="update volume requested to 65535/65535" May 30 14:09:38 volumio go-librespot[2064]: time="2026-05-30T14:09:38+02:00" level=debug msg="put connect state because VOLUME_CHANGED" May 30 14:09:38 volumio go-librespot[2064]: time="2026-05-30T14:09:38+02:00" level=trace msg="emitting websocket event: volume" May 30 14:09:38 volumio volumio[1078]: SPOTIFY: received: {"type":"volume","data":{"value":100,"max":100}} May 30 14:09:38 volumio volumio[1078]: SPOTIFY: RECEIVED SPOTIFY VOLUME 100 May 30 14:09:38 volumio volumio[1078]: info: Setting Volumio Volume from Spotify: 100 May 30 14:09:38 volumio volumio[1078]: info: VolumeController::SetAlsaVolume100 May 30 14:09:38 volumio volumio[1078]: info: CoreStateMachine::pushState May 30 14:09:38 volumio volumio[1078]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 30 14:09:38 volumio volumio[1078]: info: CoreCommandRouter::volumioPushState May 30 14:09:38 volumio volumio5-onboarding[1322]: time=2026-05-30T14:09:38.067+02:00 level=WARN msg="received unknown player status" component=volumio status="" May 30 14:09:38 volumio volumio[1078]: SPOTIFY: received: {"type":"volume","data":{"value":100,"max":100}} May 30 14:09:38 volumio volumio[1078]: SPOTIFY: RECEIVED SPOTIFY VOLUME 100 May 30 14:09:49 volumio volumio[1078]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] May 30 14:09:49 volumio volumio[1078]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings May 30 14:09:49 volumio volumio[1078]: info: Creating Spotify config file May 30 14:09:49 volumio volumio[1078]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 30 14:09:49 volumio volumio[1078]: info: Spotify config file written May 30 14:09:49 volumio sudo[2184]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service May 30 14:09:49 volumio sudo[2184]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 30 14:09:49 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... May 30 14:09:49 volumio systemd[1]: go-librespot-daemon.service: Killing process 2068 (go-librespot) with signal SIGKILL. May 30 14:09:49 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. May 30 14:09:49 volumio volumio[1078]: info: Connection to go-librespot Websocket closed May 30 14:09:49 volumio volumio[1078]: info: Connection to go-librespot Websocket closed May 30 14:09:49 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 30 14:09:49 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 30 14:09:49 volumio go-librespot[2186]: go-librespot daemon starting... May 30 14:09:49 volumio sudo[2184]: pam_unix(sudo:session): session closed for user root May 30 14:09:49 volumio go-librespot[2187]: time="2026-05-30T14:09:49+02:00" level=info msg="running go-librespot 0.6.2" May 30 14:09:49 volumio go-librespot[2187]: time="2026-05-30T14:09:49+02:00" level=debug msg="app state loaded" May 30 14:09:49 volumio go-librespot[2187]: time="2026-05-30T14:09:49+02:00" level=info msg="api server listening on 127.0.0.1:9879" May 30 14:09:49 volumio go-librespot[2187]: time="2026-05-30T14:09:49+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" May 30 14:09:49 volumio go-librespot[2187]: time="2026-05-30T14:09:49+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" May 30 14:09:49 volumio go-librespot[2187]: time="2026-05-30T14:09:49+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" May 30 14:09:49 volumio go-librespot[2187]: time="2026-05-30T14:09:49+02:00" level=info msg="zeroconf server listening on port 42505" May 30 14:09:49 volumio go-librespot[2187]: time="2026-05-30T14:09:49+02:00" level=debug msg="obtained new client token: AACfApr6RVbw4O/gTTY0m0O9MDt3ovWZY0MLoPpCstwxIo+PSka89w14Y9uvH2FyZjIrSZEtQdZsW572SWK5ID052sb4WgGlOdaTZxb9AMQOr6GOy97f4jpaF5yYb42xYyFzggynlugPncq6tGKEuMdhfCWSSfIVsQ0IYApE7LHsZgwinbSP+jJwqTCqngvW9pr7BL1gkamEVilVwy3QhlFio7kQy7tKO/P7WPw+Jd9oDrdsA0huTts=" May 30 14:09:49 volumio go-librespot[2187]: time="2026-05-30T14:09:49+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" May 30 14:09:49 volumio go-librespot[2187]: time="2026-05-30T14:09:49+02:00" level=debug msg="completed keyexchange" May 30 14:09:49 volumio go-librespot[2187]: time="2026-05-30T14:09:49+02:00" level=debug msg="completed challenge" May 30 14:09:49 volumio go-librespot[2187]: time="2026-05-30T14:09:49+02:00" level=info msg="authenticated AP" username="31************************ke" May 30 14:09:50 volumio go-librespot[2187]: time="2026-05-30T14:09:50+02:00" level=info msg="authenticated Login5" username="31************************ke" May 30 14:09:50 volumio go-librespot[2187]: time="2026-05-30T14:09:50+02:00" level=debug msg="initializing zeroconf session" username="31************************ke" May 30 14:09:50 volumio go-librespot[2187]: time="2026-05-30T14:09:50+02:00" level=debug msg="dealer connection opened" May 30 14:09:50 volumio go-librespot[2187]: time="2026-05-30T14:09:50+02:00" level=trace msg="starting accesspoint recv loop" May 30 14:09:50 volumio go-librespot[2187]: time="2026-05-30T14:09:50+02:00" level=trace msg="starting dealer recv loop" May 30 14:09:50 volumio go-librespot[2187]: time="2026-05-30T14:09:50+02:00" level=trace msg="received accesspoint ping" May 30 14:09:50 volumio go-librespot[2187]: time="2026-05-30T14:09:50+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" May 30 14:09:50 volumio go-librespot[2187]: time="2026-05-30T14:09:50+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" May 30 14:09:50 volumio go-librespot[2187]: time="2026-05-30T14:09:50+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" May 30 14:09:50 volumio go-librespot[2187]: time="2026-05-30T14:09:50+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" May 30 14:09:50 volumio go-librespot[2187]: time="2026-05-30T14:09:50+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" May 30 14:09:50 volumio go-librespot[2187]: time="2026-05-30T14:09:50+02:00" level=debug msg="received connection id: MThmNDg1MzAtZjM1...ODM0MTBGNEUxNw==" May 30 14:09:50 volumio go-librespot[2187]: time="2026-05-30T14:09:50+02:00" level=trace msg="received accesspoint pong ack" May 30 14:09:50 volumio go-librespot[2187]: time="2026-05-30T14:09:50+02:00" level=debug msg="put connect state because NEW_DEVICE" May 30 14:09:50 volumio go-librespot[2187]: time="2026-05-30T14:09:50+02:00" level=debug msg="update volume requested to 65535/65535" May 30 14:09:50 volumio go-librespot[2187]: time="2026-05-30T14:09:50+02:00" level=debug msg="put connect state because VOLUME_CHANGED" May 30 14:09:50 volumio go-librespot[2187]: time="2026-05-30T14:09:50+02:00" level=trace msg="emitting websocket event: volume" May 30 14:09:52 volumio volumio[1078]: info: Initializing connection to go-librespot Websocket May 30 14:09:52 volumio go-librespot[2187]: time="2026-05-30T14:09:52+02:00" level=debug msg="new websocket client" May 30 14:09:52 volumio volumio[1078]: info: Connection to go-librespot Websocket established May 30 14:09:52 volumio volumio[1078]: info: go-librespot daemon successfully initialized May 30 14:09:55 volumio volumio[1078]: info: Getting Spotify volume May 30 14:09:55 volumio volumio[1078]: info: Spotify volume: 100 May 30 14:09:55 volumio volumio[1078]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 May 30 14:09:55 volumio volumio[1078]: info: CoreCommandRouter::volumioGetState May 30 14:09:55 volumio volumio[1078]: info: Initializing connection to go-librespot Websocket May 30 14:09:55 volumio go-librespot[2187]: time="2026-05-30T14:09:55+02:00" level=debug msg="new websocket client" May 30 14:09:55 volumio volumio[1078]: info: Connection to go-librespot Websocket established May 30 14:09:57 volumio volumio[1078]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] May 30 14:09:57 volumio volumio[1078]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings May 30 14:09:57 volumio volumio[1078]: info: Creating Spotify config file May 30 14:09:57 volumio volumio[1078]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 30 14:09:57 volumio volumio[1078]: info: Spotify config file written May 30 14:09:57 volumio sudo[2216]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service May 30 14:09:57 volumio sudo[2216]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 30 14:09:57 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... May 30 14:09:57 volumio systemd[1]: go-librespot-daemon.service: Killing process 2195 (go-librespot) with signal SIGKILL. May 30 14:09:57 volumio volumio[1078]: info: Connection to go-librespot Websocket closed May 30 14:09:57 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. May 30 14:09:57 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 30 14:09:57 volumio volumio[1078]: info: Connection to go-librespot Websocket closed May 30 14:09:57 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 30 14:09:57 volumio go-librespot[2218]: go-librespot daemon starting... May 30 14:09:57 volumio sudo[2216]: pam_unix(sudo:session): session closed for user root May 30 14:09:57 volumio go-librespot[2219]: time="2026-05-30T14:09:57+02:00" level=info msg="running go-librespot 0.6.2" May 30 14:09:57 volumio go-librespot[2219]: time="2026-05-30T14:09:57+02:00" level=debug msg="app state loaded" May 30 14:09:57 volumio go-librespot[2219]: time="2026-05-30T14:09:57+02:00" level=info msg="api server listening on 127.0.0.1:9879" May 30 14:09:57 volumio go-librespot[2219]: time="2026-05-30T14:09:57+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" May 30 14:09:57 volumio go-librespot[2219]: time="2026-05-30T14:09:57+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" May 30 14:09:57 volumio go-librespot[2219]: time="2026-05-30T14:09:57+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" May 30 14:09:57 volumio go-librespot[2219]: time="2026-05-30T14:09:57+02:00" level=info msg="zeroconf server listening on port 43917" May 30 14:09:57 volumio go-librespot[2219]: time="2026-05-30T14:09:57+02:00" level=debug msg="obtained new client token: AAAdhUjduotxPg/xkWS+Ri9M8ejGElfeicXcg5kOkDIWUmA0BzWYp+3ooZyUhETJ9a/xwanGqQvR8ZQz80MnejFgsKe1MPbpCncVZAiqAyoRcoutS/PpMpFi8O8VuHHvXFiK3prB0ne0vcOj9pg3SIddBNzcdQuPvA6OGShXmSUE62p0nQNifeNVzwd0dbH2QLi+CWtQ2SQN9RFslOQIOW5fZipujWQ/7T9JpLNnTtil4FJK1sfD1JM=" May 30 14:09:57 volumio go-librespot[2219]: time="2026-05-30T14:09:57+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" May 30 14:09:57 volumio go-librespot[2219]: time="2026-05-30T14:09:57+02:00" level=debug msg="completed keyexchange" May 30 14:09:57 volumio go-librespot[2219]: time="2026-05-30T14:09:57+02:00" level=debug msg="completed challenge" May 30 14:09:57 volumio go-librespot[2219]: time="2026-05-30T14:09:57+02:00" level=info msg="authenticated AP" username="31************************ke" May 30 14:09:57 volumio go-librespot[2219]: time="2026-05-30T14:09:57+02:00" level=info msg="authenticated Login5" username="31************************ke" May 30 14:09:57 volumio go-librespot[2219]: time="2026-05-30T14:09:57+02:00" level=debug msg="initializing zeroconf session" username="31************************ke" May 30 14:09:58 volumio go-librespot[2219]: time="2026-05-30T14:09:58+02:00" level=debug msg="dealer connection opened" May 30 14:09:58 volumio go-librespot[2219]: time="2026-05-30T14:09:58+02:00" level=trace msg="starting accesspoint recv loop" May 30 14:09:58 volumio go-librespot[2219]: time="2026-05-30T14:09:58+02:00" level=trace msg="starting dealer recv loop" May 30 14:09:58 volumio go-librespot[2219]: time="2026-05-30T14:09:58+02:00" level=trace msg="received accesspoint ping" May 30 14:09:58 volumio go-librespot[2219]: time="2026-05-30T14:09:58+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" May 30 14:09:58 volumio go-librespot[2219]: time="2026-05-30T14:09:58+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" May 30 14:09:58 volumio go-librespot[2219]: time="2026-05-30T14:09:58+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" May 30 14:09:58 volumio go-librespot[2219]: time="2026-05-30T14:09:58+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" May 30 14:09:58 volumio go-librespot[2219]: time="2026-05-30T14:09:58+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" May 30 14:09:58 volumio go-librespot[2219]: time="2026-05-30T14:09:58+02:00" level=debug msg="received connection id: NWJiMGE2YjAtNTI5...MUE5N0RFMzdFQw==" May 30 14:09:58 volumio go-librespot[2219]: time="2026-05-30T14:09:58+02:00" level=trace msg="received accesspoint pong ack" May 30 14:09:58 volumio go-librespot[2219]: time="2026-05-30T14:09:58+02:00" level=debug msg="put connect state because NEW_DEVICE" May 30 14:09:58 volumio go-librespot[2219]: time="2026-05-30T14:09:58+02:00" level=debug msg="update volume requested to 65535/65535" May 30 14:09:58 volumio volumio[1078]: info: Getting Spotify volume May 30 14:09:58 volumio volumio[1078]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 May 30 14:09:58 volumio go-librespot[2219]: time="2026-05-30T14:09:58+02:00" level=debug msg="put connect state because VOLUME_CHANGED" May 30 14:09:58 volumio go-librespot[2219]: time="2026-05-30T14:09:58+02:00" level=trace msg="emitting websocket event: volume" May 30 14:09:58 volumio volumio[1078]: info: Spotify volume: 100 May 30 14:09:58 volumio volumio[1078]: info: CoreCommandRouter::volumioGetState May 30 14:10:00 volumio volumio[1078]: info: Initializing connection to go-librespot Websocket May 30 14:10:00 volumio go-librespot[2219]: time="2026-05-30T14:10:00+02:00" level=debug msg="new websocket client" May 30 14:10:00 volumio volumio[1078]: info: Connection to go-librespot Websocket established May 30 14:10:00 volumio volumio[1078]: info: go-librespot daemon successfully initialized May 30 14:10:03 volumio volumio[1078]: info: Getting Spotify volume May 30 14:10:03 volumio volumio[1078]: info: Spotify volume: 100 May 30 14:10:03 volumio volumio[1078]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 May 30 14:10:03 volumio volumio[1078]: info: CoreCommandRouter::volumioGetState May 30 14:10:03 volumio volumio[1078]: info: Initializing connection to go-librespot Websocket May 30 14:10:03 volumio go-librespot[2219]: time="2026-05-30T14:10:03+02:00" level=debug msg="new websocket client" May 30 14:10:03 volumio volumio[1078]: info: Connection to go-librespot Websocket established May 30 14:10:03 volumio ntpd[955]: CLOCK: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized May 30 14:10:06 volumio volumio[1078]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] May 30 14:10:06 volumio volumio[1078]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings May 30 14:10:06 volumio volumio[1078]: info: Creating Spotify config file May 30 14:10:06 volumio volumio[1078]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 30 14:10:06 volumio volumio[1078]: info: Spotify config file written May 30 14:10:06 volumio sudo[2251]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service May 30 14:10:06 volumio sudo[2251]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 30 14:10:06 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... May 30 14:10:06 volumio systemd[1]: go-librespot-daemon.service: Killing process 2224 (go-librespot) with signal SIGKILL. May 30 14:10:06 volumio volumio[1078]: info: Connection to go-librespot Websocket closed May 30 14:10:06 volumio volumio[1078]: info: Connection to go-librespot Websocket closed May 30 14:10:06 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. May 30 14:10:06 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 30 14:10:06 volumio volumio[1078]: info: Getting Spotify volume May 30 14:10:06 volumio volumio[1078]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 30 14:10:06 volumio volumio[1078]: Error: connect ECONNREFUSED 127.0.0.1:9879 May 30 14:10:06 volumio volumio[1078]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { May 30 14:10:06 volumio volumio[1078]: errno: -111, May 30 14:10:06 volumio volumio[1078]: code: 'ECONNREFUSED', May 30 14:10:06 volumio volumio[1078]: syscall: 'connect', May 30 14:10:06 volumio volumio[1078]: address: '127.0.0.1', May 30 14:10:06 volumio volumio[1078]: port: 9879, May 30 14:10:06 volumio volumio[1078]: response: undefined May 30 14:10:06 volumio volumio[1078]: } May 30 14:10:06 volumio volumio[1078]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 30 14:10:06 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 30 14:10:06 volumio go-librespot[2253]: go-librespot daemon starting... May 30 14:10:06 volumio sudo[2251]: pam_unix(sudo:session): session closed for user root May 30 14:10:06 volumio go-librespot[2257]: time="2026-05-30T14:10:06+02:00" level=info msg="running go-librespot 0.6.2" May 30 14:10:06 volumio go-librespot[2257]: time="2026-05-30T14:10:06+02:00" level=debug msg="app state loaded" May 30 14:10:06 volumio go-librespot[2257]: time="2026-05-30T14:10:06+02:00" level=info msg="api server listening on 127.0.0.1:9879" May 30 14:10:06 volumio go-librespot[2257]: time="2026-05-30T14:10:06+02:00" 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]" May 30 14:10:06 volumio go-librespot[2257]: time="2026-05-30T14:10:06+02:00" 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]" May 30 14:10:06 volumio go-librespot[2257]: time="2026-05-30T14:10:06+02:00" 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]" May 30 14:10:06 volumio go-librespot[2257]: time="2026-05-30T14:10:06+02:00" level=info msg="zeroconf server listening on port 40049" May 30 14:10:06 volumio go-librespot[2257]: time="2026-05-30T14:10:06+02:00" level=debug msg="obtained new client token: AAD37Gfi8BJZ3KDra2zs6azJ3y7wg1rhtNGem0j7B3DgP4CDmvUCYsNd5KlqhIW6HzJb4EQVbsUQE6tu+5ix9LBbU5tVTloA7mTw9KJetPZLS8kRvn4dV15PnPPieV7XzyuNzIFhIg76W2aONvEjij51dgZMdYKQ0gFgDNsFApJYv0sk+OI2rauMTuOFvWHTqDUCUP11O96STS0YdWa6NoGwqNd9GT8m4vSpLM2SYpjgCuwIsHPTtw0=" May 30 14:10:06 volumio go-librespot[2257]: time="2026-05-30T14:10:06+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" May 30 14:10:06 volumio go-librespot[2257]: time="2026-05-30T14:10:06+02:00" level=debug msg="completed keyexchange" May 30 14:10:06 volumio go-librespot[2257]: time="2026-05-30T14:10:06+02:00" level=debug msg="completed challenge" May 30 14:10:06 volumio go-librespot[2257]: time="2026-05-30T14:10:06+02:00" level=info msg="authenticated AP" username="31************************ke" May 30 14:10:07 volumio sudo[2277]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-05-30 14:09' May 30 14:10:07 volumio sudo[2277]: 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="18952480e8d8c63f22208e9007a0f47a9563eae6" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="0e58f1861fa88e02087981b8d91f7511f0e7011b" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue Mar 24 17:20:52 UTC 2026" VOLUMIO_VERSION="4.119" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="d0c2fd9dbc5e70e58c32413c12353563"