Mar 29 22:42:01 volumio volumio[3037]: [YOUTUBEJS][Player]: Failed to extract signature decipher function. Mar 29 22:42:01 volumio volumio[3037]: [YOUTUBEJS][Player]: Failed to extract n decipher function. Mar 29 22:42:01 volumio volumio[3037]: info: CALLMETHOD: music_service ytmusic configSaveDisclaimer [object Object] Mar 29 22:42:01 volumio volumio[3037]: info: CoreCommandRouter::executeOnPlugin: ytmusic , configSaveDisclaimer Mar 29 22:42:01 volumio volumio[3037]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 29 22:42:01 volumio volumio[3037]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 29 22:42:01 volumio volumio[3037]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Mar 29 22:42:01 volumio volumio[3037]: Upnp client error: Error: This socket has been ended by the other party Mar 29 22:42:02 volumio volumio[3037]: info: [ytmusic] Obtained session PO token using visitorData (expires in 43199 seconds) Mar 29 22:42:06 volumio volumio[3037]: [YOUTUBEJS][Player]: Failed to extract signature decipher function. Mar 29 22:42:06 volumio volumio[3037]: [YOUTUBEJS][Player]: Failed to extract n decipher function. Mar 29 22:42:06 volumio volumio[3037]: info: [ytmusic] Going to refresh session PO token in 43099 seconds Mar 29 22:42:06 volumio volumio[3037]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 29 22:42:06 volumio volumio[3037]: Upnp client error: Error: This socket has been ended by the other party Mar 29 22:42:08 volumio volumio[3037]: info: CALLMETHOD: music_service ytmusic showDisclaimer undefined Mar 29 22:42:08 volumio volumio[3037]: info: CoreCommandRouter::executeOnPlugin: ytmusic , showDisclaimer Mar 29 22:42:09 volumio volumio[3037]: info: CALLMETHOD: music_service ytmusic acceptDisclaimer Mar 29 22:42:09 volumio volumio[3037]: info: CoreCommandRouter::executeOnPlugin: ytmusic , acceptDisclaimer Mar 29 22:42:09 volumio volumio[3037]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 29 22:42:11 volumio volumio[3037]: info: CALLMETHOD: music_service ytmusic configSaveDisclaimer [object Object] Mar 29 22:42:11 volumio volumio[3037]: info: CoreCommandRouter::executeOnPlugin: ytmusic , configSaveDisclaimer Mar 29 22:42:11 volumio volumio[3037]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 29 22:42:13 volumio volumio[3037]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 29 22:42:13 volumio volumio[3037]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Mar 29 22:42:20 volumio volumio[3037]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 29 22:42:28 volumio volumio[3037]: info: Received OAUTH Data Mar 29 22:42:28 volumio volumio[3037]: info: Executing Spotify Oauth Login Mar 29 22:42:28 volumio volumio[3037]: info: Saving Spotify Refresh Token Mar 29 22:42:28 volumio sudo[17640]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 29 22:42:28 volumio sudo[17642]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 29 22:42:28 volumio sudo[17640]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 29 22:42:28 volumio sudo[17642]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 29 22:42:28 volumio sudo[17642]: pam_unix(sudo:session): session closed for user root Mar 29 22:42:28 volumio sudo[17640]: pam_unix(sudo:session): session closed for user root Mar 29 22:42:28 volumio volumio[3037]: verbose: New Socket.io Connection to 192.168.1.49 from 192.168.1.38 UA: Mozilla/5.0 (Linux; Android 13; SM-G781B Build/TP1A.220624.014; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/146.0.7680.119 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 6 Mar 29 22:42:28 volumio volumio[3037]: info: New Spotify access tokenBQAJYK1LMn... Mar 29 22:42:28 volumio volumio[3037]: info: Spotify credentials grant success - running version from March 24, 2019 Mar 29 22:42:29 volumio volumio[3037]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Mar 29 22:42:29 volumio volumio[3037]: info: CoreCommandRouter::volumioGetVisibleSources Mar 29 22:42:29 volumio volumio[3037]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 29 22:42:29 volumio volumio[3037]: info: CoreCommandRouter::volumioGetState Mar 29 22:42:29 volumio volumio[3037]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Mar 29 22:42:29 volumio volumio[3037]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 29 22:42:29 volumio volumio[3037]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Mar 29 22:42:29 volumio volumio[3037]: info: Received Get System Info Mar 29 22:42:29 volumio volumio[3037]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 29 22:42:29 volumio volumio[3037]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 29 22:42:29 volumio volumio[3037]: info: Discovery: Getting this device information Mar 29 22:42:29 volumio volumio[3037]: info: CoreCommandRouter::volumioGetState Mar 29 22:42:29 volumio volumio[3037]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 29 22:42:29 volumio volumio[3037]: info: CoreCommandRouter::volumioGetState Mar 29 22:42:29 volumio volumio[3037]: info: Listing playlists Mar 29 22:42:29 volumio volumio[3037]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Mar 29 22:42:29 volumio volumio[3037]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Mar 29 22:42:29 volumio volumio[3037]: SPOTIFY: User informations: {"country":"IN","display_name":"Lalucherian","email":"lalucherian61@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/31gqbxyizvaeic3hh5z2ubok44zu"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/31gqbxyizvaeic3hh5z2ubok44zu","id":"31gqbxyizvaeic3hh5z2ubok44zu","images":[{"height":300,"url":"https://platform-lookaside.fbsbx.com/platform/profilepic/?asid=3370248433256156&height=300&width=300&ext=1777357160&hash=AT_a_HFwZQULGDiFWPJ0Eoe2","width":300},{"height":64,"url":"https://platform-lookaside.fbsbx.com/platform/profilepic/?asid=3370248433256156&height=50&width=50&ext=1777357160&hash=AT-YRMSHjSRAJE04KX3WHcXN","width":64}],"product":"free","type":"user","uri":"spotify:user:31gqbxyizvaeic3hh5z2ubok44zu"} Mar 29 22:42:29 volumio volumio[3037]: info: Creating Spotify config file Mar 29 22:42:29 volumio volumio[3037]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 29 22:42:29 volumio volumio[3037]: info: Spotify config file written Mar 29 22:42:29 volumio sudo[17650]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 29 22:42:29 volumio sudo[17650]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 29 22:42:29 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 29 22:42:29 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 29 22:42:29 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 29 22:42:29 volumio volumio[3037]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Mar 29 22:42:29 volumio volumio[3037]: info: Connection to go-librespot Websocket closed Mar 29 22:42:29 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 29 22:42:29 volumio sudo[17650]: pam_unix(sudo:session): session closed for user root Mar 29 22:42:29 volumio go-librespot[17652]: go-librespot daemon starting... Mar 29 22:42:29 volumio go-librespot[17653]: time="2026-03-29T22:42:29+05:30" level=info msg="running go-librespot 0.7.1" Mar 29 22:42:29 volumio go-librespot[17653]: time="2026-03-29T22:42:29+05:30" level=debug msg="app state loaded" Mar 29 22:42:29 volumio go-librespot[17653]: time="2026-03-29T22:42:29+05:30" level=debug msg="stored credentials not found" Mar 29 22:42:29 volumio go-librespot[17653]: time="2026-03-29T22:42:29+05:30" level=info msg="api server listening on 127.0.0.1:9879" Mar 29 22:42:29 volumio volumio[3037]: info: New Spotify access tokenBQAbJdAXvj... Mar 29 22:42:29 volumio volumio[3037]: info: Spotify credentials grant success - running version from March 24, 2019 Mar 29 22:42:29 volumio go-librespot[17653]: time="2026-03-29T22:42:29+05:30" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Mar 29 22:42:29 volumio go-librespot[17653]: time="2026-03-29T22:42:29+05:30" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Mar 29 22:42:29 volumio go-librespot[17653]: time="2026-03-29T22:42:29+05:30" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Mar 29 22:42:29 volumio go-librespot[17653]: time="2026-03-29T22:42:29+05:30" level=info msg="zeroconf server listening on port 40729" Mar 29 22:42:29 volumio go-librespot[17653]: time="2026-03-29T22:42:29+05:30" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Mar 29 22:42:29 volumio volumio[3037]: SPOTIFY: User informations: {"country":"IN","display_name":"Lalucherian","email":"lalucherian61@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/31gqbxyizvaeic3hh5z2ubok44zu"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/31gqbxyizvaeic3hh5z2ubok44zu","id":"31gqbxyizvaeic3hh5z2ubok44zu","images":[{"height":300,"url":"https://platform-lookaside.fbsbx.com/platform/profilepic/?asid=3370248433256156&height=300&width=300&ext=1777357160&hash=AT_a_HFwZQULGDiFWPJ0Eoe2","width":300},{"height":64,"url":"https://platform-lookaside.fbsbx.com/platform/profilepic/?asid=3370248433256156&height=50&width=50&ext=1777357160&hash=AT-YRMSHjSRAJE04KX3WHcXN","width":64}],"product":"free","type":"user","uri":"spotify:user:31gqbxyizvaeic3hh5z2ubok44zu"} Mar 29 22:42:29 volumio volumio[3037]: info: Spotify Successfully logged in Mar 29 22:42:29 volumio volumio[3037]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 29 22:42:29 volumio volumio[3037]: info: [1774804349947] CoreMusicLibrary::Adding element Spotify Mar 29 22:42:29 volumio volumio[3037]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 29 22:42:29 volumio volumio[3037]: Cannot find translation for source SoundCloud Mar 29 22:42:29 volumio volumio[3037]: Cannot find translation for source YouTube2 Mar 29 22:42:29 volumio volumio[3037]: Cannot find translation for source YouTube Music Mar 29 22:42:29 volumio volumio[3037]: Cannot find translation for source Spotify Mar 29 22:42:30 volumio volumio[3037]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Mar 29 22:42:30 volumio volumio[3037]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 29 22:42:30 volumio volumio[3037]: info: Received Get System Info Mar 29 22:42:30 volumio volumio[3037]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 29 22:42:30 volumio volumio[3037]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 29 22:42:30 volumio volumio[3037]: info: Discovery: Getting this device information Mar 29 22:42:30 volumio volumio[3037]: info: CoreCommandRouter::volumioGetState Mar 29 22:42:30 volumio volumio[3037]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 29 22:42:30 volumio volumio[3037]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Mar 29 22:42:31 volumio go-librespot[17653]: time="2026-03-29T22:42:31+05:30" level=debug msg="obtained new client token: AAC46wXZqpmlQYX8D5gj80dKW0rX+Um2/aPr0R/zIdTVWuHsn2D/PXBWmKVsActP2864Qt7TWoznxTiTOTSJwhdwW5VfKXWzymOACSa0IbiGDcKDTbvXeYTFqNfA35wplQl6x8grhEA67YXXmpUg0cGvYUYUpDBLbj2vvo3CmwII4kJVRvTGvWE9Ko+K3vvYa1VeZOhvViEo4qguBlcLApEw5Q5aqrnCxcqVr9MSe0YQw3/vCH2nlo8=" Mar 29 22:42:31 volumio go-librespot[17653]: time="2026-03-29T22:42:31+05:30" level=debug msg="connected to ap-gae2.spotify.com:4070" Mar 29 22:42:31 volumio go-librespot[17653]: time="2026-03-29T22:42:31+05:30" level=debug msg="completed keyexchange" Mar 29 22:42:31 volumio go-librespot[17653]: time="2026-03-29T22:42:31+05:30" level=debug msg="completed challenge" Mar 29 22:42:31 volumio go-librespot[17653]: time="2026-03-29T22:42:31+05:30" level=info msg="authenticated AP" username="31************************zu" Mar 29 22:42:31 volumio go-librespot[17653]: time="2026-03-29T22:42:31+05:30" level=info msg="authenticated Login5" username="31************************zu" Mar 29 22:42:31 volumio go-librespot[17653]: time="2026-03-29T22:42:31+05:30" level=debug msg="stored credentials" username="31************************zu" Mar 29 22:42:31 volumio go-librespot[17653]: time="2026-03-29T22:42:31+05:30" level=debug msg="initializing zeroconf session" username="31************************zu" Mar 29 22:42:32 volumio go-librespot[17653]: time="2026-03-29T22:42:32+05:30" level=debug msg="dealer connection opened" Mar 29 22:42:32 volumio go-librespot[17653]: time="2026-03-29T22:42:32+05:30" level=trace msg="starting accesspoint recv loop" Mar 29 22:42:32 volumio go-librespot[17653]: time="2026-03-29T22:42:32+05:30" level=trace msg="starting dealer recv loop" Mar 29 22:42:32 volumio go-librespot[17653]: time="2026-03-29T22:42:32+05:30" level=trace msg="received accesspoint ping" Mar 29 22:42:32 volumio go-librespot[17653]: time="2026-03-29T22:42:32+05:30" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Mar 29 22:42:32 volumio go-librespot[17653]: time="2026-03-29T22:42:32+05:30" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Mar 29 22:42:32 volumio go-librespot[17653]: time="2026-03-29T22:42:32+05:30" level=debug msg="received connection id: YWQ2YTQ1YzgtYzBi...QzI4MDlFQkQ1QQ==" Mar 29 22:42:32 volumio volumio[3037]: info: Initializing connection to go-librespot Websocket Mar 29 22:42:32 volumio volumio[3037]: info: Connection to go-librespot Websocket established Mar 29 22:42:32 volumio go-librespot[17653]: time="2026-03-29T22:42:32+05:30" level=debug msg="new websocket client" Mar 29 22:42:32 volumio volumio[3037]: info: go-librespot daemon successfully initialized Mar 29 22:42:32 volumio go-librespot[17653]: time="2026-03-29T22:42:32+05:30" level=debug msg="put connect state because NEW_DEVICE" Mar 29 22:42:32 volumio go-librespot[17653]: time="2026-03-29T22:42:32+05:30" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Mar 29 22:42:32 volumio go-librespot[17653]: time="2026-03-29T22:42:32+05:30" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Mar 29 22:42:32 volumio go-librespot[17653]: time="2026-03-29T22:42:32+05:30" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Mar 29 22:42:32 volumio go-librespot[17653]: time="2026-03-29T22:42:32+05:30" level=trace msg="received accesspoint pong ack" Mar 29 22:42:32 volumio volumio[3037]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 29 22:42:32 volumio volumio[3037]: info: Received Get System Info Mar 29 22:42:32 volumio volumio[3037]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 29 22:42:32 volumio volumio[3037]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 29 22:42:32 volumio volumio[3037]: info: Discovery: Getting this device information Mar 29 22:42:32 volumio volumio[3037]: info: CoreCommandRouter::volumioGetState Mar 29 22:42:32 volumio volumio[3037]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 29 22:42:34 volumio volumio[3037]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 29 22:42:34 volumio volumio[3037]: info: Received Get System Info Mar 29 22:42:34 volumio volumio[3037]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 29 22:42:34 volumio volumio[3037]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 29 22:42:34 volumio volumio[3037]: info: Discovery: Getting this device information Mar 29 22:42:34 volumio volumio[3037]: info: CoreCommandRouter::volumioGetState Mar 29 22:42:34 volumio volumio[3037]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 29 22:42:34 volumio volumio[3037]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 29 22:42:34 volumio volumio[3037]: info: Received Get System Info Mar 29 22:42:34 volumio volumio[3037]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 29 22:42:34 volumio volumio[3037]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 29 22:42:34 volumio volumio[3037]: info: Discovery: Getting this device information Mar 29 22:42:34 volumio volumio[3037]: info: CoreCommandRouter::volumioGetState Mar 29 22:42:34 volumio volumio[3037]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 29 22:42:35 volumio volumio[3037]: info: Mar 29 22:42:35 volumio volumio[3037]: ---------------------------- MPD announces system playlist update Mar 29 22:42:35 volumio volumio[3037]: info: Ignoring MPD Status Update Mar 29 22:42:35 volumio volumio[3037]: info: Mar 29 22:42:35 volumio volumio[3037]: ---------------------------- MPD announces state update: player Mar 29 22:42:35 volumio volumio[3037]: info: ControllerMpd::getState Mar 29 22:42:35 volumio volumio[3037]: verbose: ControllerMpd::sendMpdCommand status Mar 29 22:42:35 volumio volumio[3037]: info: Mar 29 22:42:35 volumio volumio[3037]: ---------------------------- MPD announces system playlist update Mar 29 22:42:35 volumio volumio[3037]: info: Ignoring MPD Status Update Mar 29 22:42:35 volumio volumio[3037]: info: Mar 29 22:42:35 volumio volumio[3037]: ---------------------------- MPD announces state update: player Mar 29 22:42:35 volumio volumio[3037]: info: ControllerMpd::getState Mar 29 22:42:35 volumio volumio[3037]: verbose: ControllerMpd::sendMpdCommand status Mar 29 22:42:35 volumio volumio[3037]: info: Mar 29 22:42:35 volumio volumio[3037]: ---------------------------- MPD announces system playlist update Mar 29 22:42:35 volumio volumio[3037]: info: Ignoring MPD Status Update Mar 29 22:42:35 volumio volumio[3037]: info: Mar 29 22:42:35 volumio volumio[3037]: ---------------------------- MPD announces state update: player Mar 29 22:42:35 volumio volumio[3037]: info: ControllerMpd::getState Mar 29 22:42:35 volumio volumio[3037]: verbose: ControllerMpd::sendMpdCommand status Mar 29 22:42:35 volumio volumio[3037]: info: ------------------------------ 5ms Mar 29 22:42:35 volumio volumio[3037]: info: sendMpdCommand status took 4 milliseconds Mar 29 22:42:35 volumio volumio[3037]: info: ------------------------------ 3ms Mar 29 22:42:35 volumio volumio[3037]: verbose: ControllerMpd::parseState Mar 29 22:42:35 volumio volumio[3037]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 29 22:42:35 volumio volumio[3037]: info: sendMpdCommand status took 5 milliseconds Mar 29 22:42:35 volumio volumio[3037]: info: ------------------------------ 5ms Mar 29 22:42:35 volumio volumio[3037]: info: sendMpdCommand status took 3 milliseconds Mar 29 22:42:35 volumio volumio[3037]: info: sendMpdCommand playlistinfo took 2 milliseconds Mar 29 22:42:35 volumio volumio[3037]: verbose: ControllerMpd::parseState Mar 29 22:42:35 volumio volumio[3037]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 29 22:42:35 volumio volumio[3037]: verbose: ControllerMpd::parseState Mar 29 22:42:35 volumio volumio[3037]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 29 22:42:35 volumio volumio[3037]: verbose: ControllerMpd::parseTrackInfo Mar 29 22:42:35 volumio volumio[3037]: info: ControllerMpd::pushState Mar 29 22:42:35 volumio volumio[3037]: info: CoreCommandRouter::servicePushState Mar 29 22:42:35 volumio volumio[3037]: info: CorePlayQueue::getTrack 0 Mar 29 22:42:35 volumio volumio[3037]: verbose: STATE SERVICE {"status":"play","position":0,"seek":12317488,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Absolut Radio AI - der erste Stream von künstlicher Intelligenz","artist":"Absolut AI","album":null,"uri":"https://absolut-ai.live-sm.absolutradio.de/absolut-ai/stream/mp3","trackType":""} Mar 29 22:42:35 volumio volumio[3037]: verbose: CURRENT POSITION 0 Mar 29 22:42:35 volumio volumio[3037]: info: CoreStateMachine::syncState stateService play Mar 29 22:42:35 volumio volumio[3037]: info: CoreStateMachine::syncState currentStatus play Mar 29 22:42:35 volumio volumio[3037]: info: Received an update from plugin. extracting info from payload Mar 29 22:42:35 volumio volumio[3037]: info: CoreStateMachine::pushState Mar 29 22:42:35 volumio volumio[3037]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 29 22:42:35 volumio volumio[3037]: info: CoreCommandRouter::volumioPushState Mar 29 22:42:35 volumio volumio[3037]: info: CoreStateMachine::pushState Mar 29 22:42:35 volumio volumio[3037]: info: CoreCommandRouter::volumioPushState Mar 29 22:42:35 volumio volumio5-onboarding[1494]: time=2026-03-29T22:42:35.314+05:30 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02,192.168.1.38:49818 @ 0x295f1d0" state=STATUS_PLAYING positionMs=12316249 volume=30 Mar 29 22:42:35 volumio volumio5-onboarding[1494]: time=2026-03-29T22:42:35.314+05:30 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02,192.168.1.38:49818 @ 0x295f1d0" state=STATUS_PLAYING positionMs=12316249 volume=30 Mar 29 22:42:35 volumio volumio5-onboarding[1494]: time=2026-03-29T22:42:35.316+05:30 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.38:49818 @ 0x276c120" state=STATUS_PLAYING positionMs=12316249 volume=30 Mar 29 22:42:35 volumio volumio[3037]: info: ------------------------------ 18ms Mar 29 22:42:35 volumio volumio[3037]: info: sendMpdCommand playlistinfo took 11 milliseconds Mar 29 22:42:35 volumio volumio5-onboarding[1494]: time=2026-03-29T22:42:35.317+05:30 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02,192.168.1.38:49818 @ 0x295f1d0" id=https://absolut-ai.live-sm.absolutradio.de/absolut-ai/stream/mp3 title="Absolut Radio AI - der erste Stream von künstlicher Intelligenz" Mar 29 22:42:35 volumio volumio5-onboarding[1494]: time=2026-03-29T22:42:35.317+05:30 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.38:49818 @ 0x276c120" id=https://absolut-ai.live-sm.absolutradio.de/absolut-ai/stream/mp3 title="Absolut Radio AI - der erste Stream von künstlicher Intelligenz" Mar 29 22:42:35 volumio volumio5-onboarding[1494]: time=2026-03-29T22:42:35.316+05:30 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.38:49818 @ 0x276c120" state=STATUS_PLAYING positionMs=12316249 volume=30 Mar 29 22:42:35 volumio volumio[3037]: info: sendMpdCommand playlistinfo took 10 milliseconds Mar 29 22:42:35 volumio volumio[3037]: verbose: ControllerMpd::parseTrackInfo Mar 29 22:42:35 volumio volumio5-onboarding[1494]: time=2026-03-29T22:42:35.318+05:30 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02,192.168.1.38:49818 @ 0x295f1d0" id=https://absolut-ai.live-sm.absolutradio.de/absolut-ai/stream/mp3 title="Absolut Radio AI - der erste Stream von künstlicher Intelligenz" Mar 29 22:42:35 volumio volumio5-onboarding[1494]: time=2026-03-29T22:42:35.318+05:30 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.38:49818 @ 0x276c120" id=https://absolut-ai.live-sm.absolutradio.de/absolut-ai/stream/mp3 title="Absolut Radio AI - der erste Stream von künstlicher Intelligenz" Mar 29 22:42:35 volumio volumio[3037]: verbose: ControllerMpd::parseTrackInfo Mar 29 22:42:35 volumio volumio[3037]: info: ControllerMpd::pushState Mar 29 22:42:35 volumio volumio[3037]: info: CoreCommandRouter::servicePushState Mar 29 22:42:35 volumio volumio[3037]: info: CorePlayQueue::getTrack 0 Mar 29 22:42:35 volumio volumio[3037]: verbose: STATE SERVICE {"status":"play","position":0,"seek":12317488,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Absolut Radio AI - der erste Stream von künstlicher Intelligenz","artist":"Absolut AI","album":null,"uri":"https://absolut-ai.live-sm.absolutradio.de/absolut-ai/stream/mp3","trackType":""} Mar 29 22:42:35 volumio volumio[3037]: verbose: CURRENT POSITION 0 Mar 29 22:42:35 volumio volumio[3037]: info: CoreStateMachine::syncState stateService play Mar 29 22:42:35 volumio volumio[3037]: info: CoreStateMachine::syncState currentStatus play Mar 29 22:42:35 volumio volumio[3037]: info: Received an update from plugin. extracting info from payload Mar 29 22:42:35 volumio volumio[3037]: info: CoreStateMachine::pushState Mar 29 22:42:35 volumio volumio[3037]: info: CoreCommandRouter::volumioPushState Mar 29 22:42:35 volumio volumio[3037]: info: CoreStateMachine::pushState Mar 29 22:42:35 volumio volumio[3037]: info: CoreCommandRouter::volumioPushState Mar 29 22:42:35 volumio volumio[3037]: info: ControllerMpd::pushState Mar 29 22:42:35 volumio volumio[3037]: info: CoreCommandRouter::servicePushState Mar 29 22:42:35 volumio volumio[3037]: info: CorePlayQueue::getTrack 0 Mar 29 22:42:35 volumio volumio[3037]: verbose: STATE SERVICE {"status":"play","position":0,"seek":12317488,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Absolut Radio AI - der erste Stream von künstlicher Intelligenz","artist":"Absolut AI","album":null,"uri":"https://absolut-ai.live-sm.absolutradio.de/absolut-ai/stream/mp3","trackType":""} Mar 29 22:42:35 volumio volumio[3037]: verbose: CURRENT POSITION 0 Mar 29 22:42:35 volumio volumio[3037]: info: CoreStateMachine::syncState stateService play Mar 29 22:42:35 volumio volumio[3037]: info: CoreStateMachine::syncState currentStatus play Mar 29 22:42:35 volumio volumio[3037]: info: Received an update from plugin. extracting info from payload Mar 29 22:42:35 volumio volumio[3037]: info: CoreStateMachine::pushState Mar 29 22:42:35 volumio volumio[3037]: info: CoreCommandRouter::volumioPushState Mar 29 22:42:35 volumio volumio[3037]: info: CoreStateMachine::pushState Mar 29 22:42:35 volumio volumio[3037]: info: CoreCommandRouter::volumioPushState Mar 29 22:42:35 volumio volumio5-onboarding[1494]: time=2026-03-29T22:42:35.327+05:30 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02,192.168.1.38:49818 @ 0x295f1d0" state=STATUS_PLAYING positionMs=12316249 volume=30 Mar 29 22:42:35 volumio volumio5-onboarding[1494]: time=2026-03-29T22:42:35.328+05:30 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.38:49818 @ 0x276c120" state=STATUS_PLAYING positionMs=12316249 volume=30 Mar 29 22:42:35 volumio volumio5-onboarding[1494]: time=2026-03-29T22:42:35.329+05:30 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02,192.168.1.38:49818 @ 0x295f1d0" state=STATUS_PLAYING positionMs=12316249 volume=30 Mar 29 22:42:35 volumio volumio5-onboarding[1494]: time=2026-03-29T22:42:35.330+05:30 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02,192.168.1.38:49818 @ 0x295f1d0" id=https://absolut-ai.live-sm.absolutradio.de/absolut-ai/stream/mp3 title="Absolut Radio AI - der erste Stream von künstlicher Intelligenz" Mar 29 22:42:35 volumio volumio[3037]: info: ------------------------------ 32ms Mar 29 22:42:35 volumio volumio5-onboarding[1494]: time=2026-03-29T22:42:35.331+05:30 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.38:49818 @ 0x276c120" state=STATUS_PLAYING positionMs=12316249 volume=30 Mar 29 22:42:35 volumio volumio5-onboarding[1494]: time=2026-03-29T22:42:35.331+05:30 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02,192.168.1.38:49818 @ 0x295f1d0" state=STATUS_PLAYING positionMs=12316249 volume=30 Mar 29 22:42:35 volumio volumio5-onboarding[1494]: time=2026-03-29T22:42:35.331+05:30 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02,192.168.1.38:49818 @ 0x295f1d0" id=https://absolut-ai.live-sm.absolutradio.de/absolut-ai/stream/mp3 title="Absolut Radio AI - der erste Stream von künstlicher Intelligenz" Mar 29 22:42:35 volumio volumio5-onboarding[1494]: time=2026-03-29T22:42:35.331+05:30 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.38:49818 @ 0x276c120" state=STATUS_PLAYING positionMs=12316249 volume=30 Mar 29 22:42:35 volumio volumio5-onboarding[1494]: time=2026-03-29T22:42:35.332+05:30 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.38:49818 @ 0x276c120" id=https://absolut-ai.live-sm.absolutradio.de/absolut-ai/stream/mp3 title="Absolut Radio AI - der erste Stream von künstlicher Intelligenz" Mar 29 22:42:35 volumio volumio5-onboarding[1494]: time=2026-03-29T22:42:35.332+05:30 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02,192.168.1.38:49818 @ 0x295f1d0" id=https://absolut-ai.live-sm.absolutradio.de/absolut-ai/stream/mp3 title="Absolut Radio AI - der erste Stream von künstlicher Intelligenz" Mar 29 22:42:35 volumio volumio5-onboarding[1494]: time=2026-03-29T22:42:35.332+05:30 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.38:49818 @ 0x276c120" id=https://absolut-ai.live-sm.absolutradio.de/absolut-ai/stream/mp3 title="Absolut Radio AI - der erste Stream von künstlicher Intelligenz" Mar 29 22:42:35 volumio volumio5-onboarding[1494]: time=2026-03-29T22:42:35.332+05:30 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.38:49818 @ 0x276c120" id=https://absolut-ai.live-sm.absolutradio.de/absolut-ai/stream/mp3 title="Absolut Radio AI - der erste Stream von künstlicher Intelligenz" Mar 29 22:42:35 volumio volumio[3037]: info: ------------------------------ 30ms Mar 29 22:42:35 volumio volumio5-onboarding[1494]: time=2026-03-29T22:42:35.332+05:30 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02,192.168.1.38:49818 @ 0x295f1d0" state=STATUS_PLAYING positionMs=12316249 volume=30 Mar 29 22:42:35 volumio volumio5-onboarding[1494]: time=2026-03-29T22:42:35.333+05:30 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.38:49818 @ 0x276c120" state=STATUS_PLAYING positionMs=12316249 volume=30 Mar 29 22:42:35 volumio volumio5-onboarding[1494]: time=2026-03-29T22:42:35.333+05:30 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02,192.168.1.38:49818 @ 0x295f1d0" id=https://absolut-ai.live-sm.absolutradio.de/absolut-ai/stream/mp3 title="Absolut Radio AI - der erste Stream von künstlicher Intelligenz" Mar 29 22:42:35 volumio volumio5-onboarding[1494]: time=2026-03-29T22:42:35.333+05:30 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.38:49818 @ 0x276c120" id=https://absolut-ai.live-sm.absolutradio.de/absolut-ai/stream/mp3 title="Absolut Radio AI - der erste Stream von künstlicher Intelligenz" Mar 29 22:42:35 volumio volumio[3037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 30 Mar 29 22:42:35 volumio volumio[3037]: SPOTIFY: SPOTIFY VOLUME 31 Mar 29 22:42:35 volumio volumio[3037]: SPOTIFY: VOLUMIO VOLUME 30 Mar 29 22:42:35 volumio volumio[3037]: SPOTIFY: DELTA VOLUME ENOUGH: false Mar 29 22:42:35 volumio volumio[3037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 30 Mar 29 22:42:35 volumio volumio[3037]: SPOTIFY: SPOTIFY VOLUME 31 Mar 29 22:42:35 volumio volumio[3037]: SPOTIFY: VOLUMIO VOLUME 30 Mar 29 22:42:35 volumio volumio[3037]: SPOTIFY: DELTA VOLUME ENOUGH: false Mar 29 22:42:35 volumio volumio[3037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 30 Mar 29 22:42:35 volumio volumio[3037]: SPOTIFY: SPOTIFY VOLUME 31 Mar 29 22:42:35 volumio volumio[3037]: SPOTIFY: VOLUMIO VOLUME 30 Mar 29 22:42:35 volumio volumio[3037]: SPOTIFY: DELTA VOLUME ENOUGH: false Mar 29 22:42:35 volumio volumio[3037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 30 Mar 29 22:42:35 volumio volumio[3037]: SPOTIFY: SPOTIFY VOLUME 31 Mar 29 22:42:35 volumio volumio[3037]: SPOTIFY: VOLUMIO VOLUME 30 Mar 29 22:42:35 volumio volumio[3037]: SPOTIFY: DELTA VOLUME ENOUGH: false Mar 29 22:42:35 volumio volumio[3037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 30 Mar 29 22:42:35 volumio volumio[3037]: SPOTIFY: SPOTIFY VOLUME 31 Mar 29 22:42:35 volumio volumio[3037]: SPOTIFY: VOLUMIO VOLUME 30 Mar 29 22:42:35 volumio volumio[3037]: SPOTIFY: DELTA VOLUME ENOUGH: false Mar 29 22:42:35 volumio volumio[3037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 30 Mar 29 22:42:35 volumio volumio[3037]: SPOTIFY: SPOTIFY VOLUME 31 Mar 29 22:42:35 volumio volumio[3037]: SPOTIFY: VOLUMIO VOLUME 30 Mar 29 22:42:35 volumio volumio[3037]: SPOTIFY: DELTA VOLUME ENOUGH: false Mar 29 22:42:35 volumio volumio[3037]: info: Getting Spotify volume Mar 29 22:42:35 volumio volumio[3037]: info: Spotify volume: 100 Mar 29 22:42:35 volumio volumio[3037]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Mar 29 22:42:35 volumio volumio[3037]: info: Initializing connection to go-librespot Websocket Mar 29 22:42:35 volumio go-librespot[17653]: time="2026-03-29T22:42:35+05:30" level=debug msg="new websocket client" Mar 29 22:42:35 volumio volumio[3037]: info: Connection to go-librespot Websocket established Mar 29 22:42:35 volumio volumio[3037]: info: CoreCommandRouter::volumioGetState Mar 29 22:42:35 volumio volumio[3037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 30 Mar 29 22:42:35 volumio volumio[3037]: SPOTIFY: SPOTIFY VOLUME 100 Mar 29 22:42:35 volumio volumio[3037]: SPOTIFY: VOLUMIO VOLUME 30 Mar 29 22:42:35 volumio volumio[3037]: SPOTIFY: DELTA VOLUME ENOUGH: true Mar 29 22:42:35 volumio volumio[3037]: info: Setting Spotify Volume from Volumio: 30 Mar 29 22:42:36 volumio volumio[3037]: SPOTIFY: SETTING SPOTIFY VOLUME 30 Mar 29 22:42:36 volumio volumio[3037]: info: Sending Spotify command with payload to local API: /player/volume Mar 29 22:42:36 volumio go-librespot[17653]: time="2026-03-29T22:42:36+05:30" level=debug msg="update volume requested to 19660/65535" Mar 29 22:42:37 volumio go-librespot[17653]: time="2026-03-29T22:42:37+05:30" level=debug msg="put connect state because VOLUME_CHANGED" Mar 29 22:42:37 volumio go-librespot[17653]: time="2026-03-29T22:42:37+05:30" level=trace msg="emitting websocket event: volume" Mar 29 22:42:37 volumio volumio[3037]: SPOTIFY: received: {"type":"volume","data":{"value":30,"max":100}} Mar 29 22:42:37 volumio volumio[3037]: SPOTIFY: RECEIVED SPOTIFY VOLUME 30 Mar 29 22:42:37 volumio volumio[3037]: SPOTIFY: received: {"type":"volume","data":{"value":30,"max":100}} Mar 29 22:42:37 volumio volumio[3037]: SPOTIFY: RECEIVED SPOTIFY VOLUME 30 Mar 29 22:42:38 volumio volumio[3037]: info: Getting Spotify volume Mar 29 22:42:38 volumio volumio[3037]: info: Spotify volume: 30 Mar 29 22:42:38 volumio volumio[3037]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Mar 29 22:42:38 volumio volumio[3037]: info: CoreCommandRouter::volumioGetState Mar 29 22:42:38 volumio volumio[3037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 30 Mar 29 22:42:38 volumio volumio[3037]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Mar 29 22:42:43 volumio volumio[3037]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 29 22:42:43 volumio volumio[3037]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 29 22:42:43 volumio volumio[3037]: info: Creating Spotify config file Mar 29 22:42:43 volumio volumio[3037]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 29 22:42:43 volumio volumio[3037]: info: Spotify config file written Mar 29 22:42:43 volumio sudo[17708]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 29 22:42:43 volumio sudo[17708]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 29 22:42:43 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 29 22:42:43 volumio systemd[1]: go-librespot-daemon.service: Killing process 17658 (go-librespot) with signal SIGKILL. Mar 29 22:42:43 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 29 22:42:43 volumio volumio[3037]: info: Connection to go-librespot Websocket closed Mar 29 22:42:43 volumio volumio[3037]: info: Connection to go-librespot Websocket closed Mar 29 22:42:43 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 29 22:42:43 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 29 22:42:43 volumio sudo[17708]: pam_unix(sudo:session): session closed for user root Mar 29 22:42:43 volumio go-librespot[17710]: go-librespot daemon starting... Mar 29 22:42:43 volumio go-librespot[17711]: time="2026-03-29T22:42:43+05:30" level=info msg="running go-librespot 0.7.1" Mar 29 22:42:43 volumio go-librespot[17711]: time="2026-03-29T22:42:43+05:30" level=debug msg="app state loaded" Mar 29 22:42:43 volumio go-librespot[17711]: time="2026-03-29T22:42:43+05:30" level=info msg="api server listening on 127.0.0.1:9879" Mar 29 22:42:44 volumio go-librespot[17711]: time="2026-03-29T22:42:44+05:30" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Mar 29 22:42:44 volumio go-librespot[17711]: time="2026-03-29T22:42:44+05:30" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Mar 29 22:42:44 volumio go-librespot[17711]: time="2026-03-29T22:42:44+05:30" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Mar 29 22:42:44 volumio go-librespot[17711]: time="2026-03-29T22:42:44+05:30" level=info msg="zeroconf server listening on port 39717" Mar 29 22:42:44 volumio go-librespot[17711]: time="2026-03-29T22:42:44+05:30" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Mar 29 22:42:44 volumio go-librespot[17711]: time="2026-03-29T22:42:44+05:30" level=debug msg="obtained new client token: AADLHjcHRJL9mBZK5rVaAPggPGwdfiY7/fKMj5S1kIB1PO4uHVhseZfUfHqm3daJnJCFD7fK7BeSmbeUuJngpptWBLgjqUWyvp2fIqkKTnJcdB9PKQXhZtsrl/1biUpy22gb0SWbghiZ0bZsDoT3+iIebYK0RptWNnvrwMWhl5HaNJlW8Id1t6sEXwfGYbTMl5w/TQygp1IrfqizRn78BC72k18MUKd9/qAyYgX+IdFPZPjIhsqTqH5qpA==" Mar 29 22:42:44 volumio go-librespot[17711]: time="2026-03-29T22:42:44+05:30" level=debug msg="connected to ap-gae2.spotify.com:4070" Mar 29 22:42:44 volumio go-librespot[17711]: time="2026-03-29T22:42:44+05:30" level=debug msg="completed keyexchange" Mar 29 22:42:44 volumio go-librespot[17711]: time="2026-03-29T22:42:44+05:30" level=debug msg="completed challenge" Mar 29 22:42:44 volumio go-librespot[17711]: time="2026-03-29T22:42:44+05:30" level=info msg="authenticated AP" username="31************************zu" Mar 29 22:42:45 volumio go-librespot[17711]: time="2026-03-29T22:42:45+05:30" level=info msg="authenticated Login5" username="31************************zu" Mar 29 22:42:45 volumio go-librespot[17711]: time="2026-03-29T22:42:45+05:30" level=debug msg="initializing zeroconf session" username="31************************zu" Mar 29 22:42:45 volumio go-librespot[17711]: time="2026-03-29T22:42:45+05:30" level=debug msg="dealer connection opened" Mar 29 22:42:45 volumio go-librespot[17711]: time="2026-03-29T22:42:45+05:30" level=trace msg="starting accesspoint recv loop" Mar 29 22:42:45 volumio go-librespot[17711]: time="2026-03-29T22:42:45+05:30" level=trace msg="starting dealer recv loop" Mar 29 22:42:45 volumio go-librespot[17711]: time="2026-03-29T22:42:45+05:30" level=trace msg="received accesspoint ping" Mar 29 22:42:45 volumio go-librespot[17711]: time="2026-03-29T22:42:45+05:30" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Mar 29 22:42:45 volumio go-librespot[17711]: time="2026-03-29T22:42:45+05:30" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Mar 29 22:42:45 volumio go-librespot[17711]: time="2026-03-29T22:42:45+05:30" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Mar 29 22:42:45 volumio go-librespot[17711]: time="2026-03-29T22:42:45+05:30" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Mar 29 22:42:45 volumio go-librespot[17711]: time="2026-03-29T22:42:45+05:30" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Mar 29 22:42:45 volumio go-librespot[17711]: time="2026-03-29T22:42:45+05:30" level=debug msg="received connection id: OTFiODg1MWUtZTE1...MDExN0ZBMkE3RQ==" Mar 29 22:42:45 volumio go-librespot[17711]: time="2026-03-29T22:42:45+05:30" level=trace msg="received accesspoint pong ack" Mar 29 22:42:45 volumio go-librespot[17711]: time="2026-03-29T22:42:45+05:30" level=debug msg="put connect state because NEW_DEVICE" Mar 29 22:42:46 volumio volumio[3037]: info: Initializing connection to go-librespot Websocket Mar 29 22:42:46 volumio go-librespot[17711]: time="2026-03-29T22:42:46+05:30" level=debug msg="new websocket client" Mar 29 22:42:46 volumio volumio[3037]: info: Connection to go-librespot Websocket established Mar 29 22:42:46 volumio volumio[3037]: info: go-librespot daemon successfully initialized Mar 29 22:42:46 volumio volumio[3037]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 29 22:42:46 volumio volumio[3037]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 29 22:42:46 volumio volumio[3037]: info: Creating Spotify config file Mar 29 22:42:46 volumio volumio[3037]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 29 22:42:46 volumio volumio[3037]: info: Spotify config file written Mar 29 22:42:46 volumio sudo[17727]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 29 22:42:46 volumio sudo[17727]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 29 22:42:46 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 29 22:42:46 volumio systemd[1]: go-librespot-daemon.service: Killing process 17719 (go-librespot) with signal SIGKILL. Mar 29 22:42:46 volumio volumio[3037]: info: Connection to go-librespot Websocket closed Mar 29 22:42:46 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 29 22:42:46 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 29 22:42:47 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 29 22:42:47 volumio sudo[17727]: pam_unix(sudo:session): session closed for user root Mar 29 22:42:47 volumio go-librespot[17729]: go-librespot daemon starting... Mar 29 22:42:47 volumio go-librespot[17730]: time="2026-03-29T22:42:47+05:30" level=info msg="running go-librespot 0.7.1" Mar 29 22:42:47 volumio go-librespot[17730]: time="2026-03-29T22:42:47+05:30" level=debug msg="app state loaded" Mar 29 22:42:47 volumio go-librespot[17730]: time="2026-03-29T22:42:47+05:30" level=info msg="api server listening on 127.0.0.1:9879" Mar 29 22:42:47 volumio go-librespot[17730]: time="2026-03-29T22:42:47+05:30" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Mar 29 22:42:47 volumio go-librespot[17730]: time="2026-03-29T22:42:47+05:30" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Mar 29 22:42:47 volumio go-librespot[17730]: time="2026-03-29T22:42:47+05:30" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Mar 29 22:42:47 volumio go-librespot[17730]: time="2026-03-29T22:42:47+05:30" level=info msg="zeroconf server listening on port 41475" Mar 29 22:42:47 volumio go-librespot[17730]: time="2026-03-29T22:42:47+05:30" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Mar 29 22:42:47 volumio go-librespot[17730]: time="2026-03-29T22:42:47+05:30" level=debug msg="obtained new client token: AADXK2/x21tYlBRiwq7VD0R2KY8HjpOo+wUOVNDDdoJ2mR8ZOlpdgc9yKriOq6eadNtJuTfWW6FeAKREtgXMKeD6Ts2Z4Gd+gByR2BHnfzavJbRpXgy5kjfZdK3B0BTZfsvrdaDlP/nxJPuTI1DsG4zjbNs1mq5Vx+oV31EyYVB/POUbB/IduZtu9w5DVo6XDWWk/M+Y1OQBpbi2uqlUglBEaNeG7AGT1i4UqrEPQTm8Kgfl0SZFdecvDQ==" Mar 29 22:42:47 volumio go-librespot[17730]: time="2026-03-29T22:42:47+05:30" level=debug msg="connected to ap-gae2.spotify.com:4070" Mar 29 22:42:47 volumio go-librespot[17730]: time="2026-03-29T22:42:47+05:30" level=debug msg="completed keyexchange" Mar 29 22:42:47 volumio go-librespot[17730]: time="2026-03-29T22:42:47+05:30" level=debug msg="completed challenge" Mar 29 22:42:47 volumio go-librespot[17730]: time="2026-03-29T22:42:47+05:30" level=info msg="authenticated AP" username="31************************zu" Mar 29 22:42:48 volumio go-librespot[17730]: time="2026-03-29T22:42:48+05:30" level=info msg="authenticated Login5" username="31************************zu" Mar 29 22:42:48 volumio go-librespot[17730]: time="2026-03-29T22:42:48+05:30" level=debug msg="initializing zeroconf session" username="31************************zu" Mar 29 22:42:48 volumio go-librespot[17730]: time="2026-03-29T22:42:48+05:30" level=debug msg="dealer connection opened" Mar 29 22:42:48 volumio go-librespot[17730]: time="2026-03-29T22:42:48+05:30" level=trace msg="starting accesspoint recv loop" Mar 29 22:42:48 volumio go-librespot[17730]: time="2026-03-29T22:42:48+05:30" level=trace msg="starting dealer recv loop" Mar 29 22:42:48 volumio go-librespot[17730]: time="2026-03-29T22:42:48+05:30" level=trace msg="received accesspoint ping" Mar 29 22:42:48 volumio go-librespot[17730]: time="2026-03-29T22:42:48+05:30" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Mar 29 22:42:48 volumio go-librespot[17730]: time="2026-03-29T22:42:48+05:30" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Mar 29 22:42:48 volumio go-librespot[17730]: time="2026-03-29T22:42:48+05:30" level=debug msg="received connection id: ZWNjZDgyZWUtYTIx...NDNGRUFDQTNDNg==" Mar 29 22:42:48 volumio go-librespot[17730]: time="2026-03-29T22:42:48+05:30" level=debug msg="put connect state because NEW_DEVICE" Mar 29 22:42:48 volumio go-librespot[17730]: time="2026-03-29T22:42:48+05:30" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Mar 29 22:42:48 volumio go-librespot[17730]: time="2026-03-29T22:42:48+05:30" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Mar 29 22:42:48 volumio go-librespot[17730]: time="2026-03-29T22:42:48+05:30" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Mar 29 22:42:48 volumio go-librespot[17730]: time="2026-03-29T22:42:48+05:30" level=trace msg="received accesspoint pong ack" Mar 29 22:42:49 volumio volumio[3037]: info: Getting Spotify volume Mar 29 22:42:49 volumio volumio[3037]: info: Spotify volume: 100 Mar 29 22:42:49 volumio volumio[3037]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Mar 29 22:42:49 volumio volumio[3037]: info: CoreCommandRouter::volumioGetState Mar 29 22:42:49 volumio volumio[3037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 30 Mar 29 22:42:49 volumio volumio[3037]: SPOTIFY: SPOTIFY VOLUME 100 Mar 29 22:42:49 volumio volumio[3037]: SPOTIFY: VOLUMIO VOLUME 30 Mar 29 22:42:49 volumio volumio[3037]: SPOTIFY: DELTA VOLUME ENOUGH: true Mar 29 22:42:49 volumio volumio[3037]: info: Setting Spotify Volume from Volumio: 30 Mar 29 22:42:49 volumio volumio[3037]: info: Initializing connection to go-librespot Websocket Mar 29 22:42:49 volumio go-librespot[17730]: time="2026-03-29T22:42:49+05:30" level=debug msg="new websocket client" Mar 29 22:42:49 volumio volumio[3037]: info: Connection to go-librespot Websocket established Mar 29 22:42:49 volumio volumio[3037]: info: Initializing connection to go-librespot Websocket Mar 29 22:42:49 volumio go-librespot[17730]: time="2026-03-29T22:42:49+05:30" level=debug msg="new websocket client" Mar 29 22:42:49 volumio volumio[3037]: info: Connection to go-librespot Websocket established Mar 29 22:42:50 volumio volumio[3037]: info: go-librespot daemon successfully initialized Mar 29 22:42:50 volumio volumio[3037]: info: Mar 29 22:42:50 volumio volumio[3037]: ---------------------------- MPD announces system playlist update Mar 29 22:42:50 volumio volumio[3037]: info: Ignoring MPD Status Update Mar 29 22:42:50 volumio volumio[3037]: info: Mar 29 22:42:50 volumio volumio[3037]: ---------------------------- MPD announces state update: player Mar 29 22:42:50 volumio volumio[3037]: info: ControllerMpd::getState Mar 29 22:42:50 volumio volumio[3037]: verbose: ControllerMpd::sendMpdCommand status Mar 29 22:42:50 volumio volumio[3037]: info: Mar 29 22:42:50 volumio volumio[3037]: ---------------------------- MPD announces system playlist update Mar 29 22:42:50 volumio volumio[3037]: info: Ignoring MPD Status Update Mar 29 22:42:50 volumio volumio[3037]: info: Mar 29 22:42:50 volumio volumio[3037]: ---------------------------- MPD announces state update: player Mar 29 22:42:50 volumio volumio[3037]: info: ControllerMpd::getState Mar 29 22:42:50 volumio volumio[3037]: verbose: ControllerMpd::sendMpdCommand status Mar 29 22:42:50 volumio volumio[3037]: info: Mar 29 22:42:50 volumio volumio[3037]: ---------------------------- MPD announces system playlist update Mar 29 22:42:50 volumio volumio[3037]: info: Ignoring MPD Status Update Mar 29 22:42:50 volumio volumio[3037]: info: Mar 29 22:42:50 volumio volumio[3037]: ---------------------------- MPD announces state update: player Mar 29 22:42:50 volumio volumio[3037]: info: ControllerMpd::getState Mar 29 22:42:50 volumio volumio[3037]: verbose: ControllerMpd::sendMpdCommand status Mar 29 22:42:50 volumio volumio[3037]: info: ------------------------------ 6ms Mar 29 22:42:50 volumio volumio[3037]: info: sendMpdCommand status took 6 milliseconds Mar 29 22:42:50 volumio volumio[3037]: info: ------------------------------ 6ms Mar 29 22:42:50 volumio volumio[3037]: info: sendMpdCommand status took 5 milliseconds Mar 29 22:42:50 volumio volumio[3037]: verbose: ControllerMpd::parseState Mar 29 22:42:50 volumio volumio[3037]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 29 22:42:50 volumio volumio[3037]: verbose: ControllerMpd::parseState Mar 29 22:42:50 volumio volumio[3037]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 29 22:42:50 volumio volumio[3037]: info: ------------------------------ 7ms Mar 29 22:42:50 volumio volumio[3037]: info: sendMpdCommand status took 5 milliseconds Mar 29 22:42:50 volumio volumio[3037]: info: sendMpdCommand playlistinfo took 3 milliseconds Mar 29 22:42:50 volumio volumio[3037]: info: sendMpdCommand playlistinfo took 2 milliseconds Mar 29 22:42:50 volumio volumio[3037]: verbose: ControllerMpd::parseState Mar 29 22:42:50 volumio volumio[3037]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 29 22:42:50 volumio volumio[3037]: verbose: ControllerMpd::parseTrackInfo Mar 29 22:42:50 volumio volumio[3037]: verbose: ControllerMpd::parseTrackInfo Mar 29 22:42:50 volumio volumio[3037]: info: ControllerMpd::pushState Mar 29 22:42:50 volumio volumio[3037]: info: CoreCommandRouter::servicePushState Mar 29 22:42:50 volumio volumio[3037]: info: CorePlayQueue::getTrack 0 Mar 29 22:42:50 volumio volumio[3037]: verbose: STATE SERVICE {"status":"play","position":0,"seek":12332683,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"DAVID PUENTEZ & ALBERT NEVE - SUPERSTAR","artist":"Absolut AI","album":null,"uri":"https://absolut-ai.live-sm.absolutradio.de/absolut-ai/stream/mp3","trackType":""} Mar 29 22:42:50 volumio volumio[3037]: verbose: CURRENT POSITION 0 Mar 29 22:42:50 volumio volumio[3037]: info: CoreStateMachine::syncState stateService play Mar 29 22:42:50 volumio volumio[3037]: info: CoreStateMachine::syncState currentStatus play Mar 29 22:42:50 volumio volumio[3037]: info: Received an update from plugin. extracting info from payload Mar 29 22:42:50 volumio volumio[3037]: info: CoreStateMachine::pushState Mar 29 22:42:50 volumio volumio[3037]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 29 22:42:50 volumio volumio[3037]: info: CoreCommandRouter::volumioPushState Mar 29 22:42:50 volumio volumio[3037]: info: CoreStateMachine::pushState Mar 29 22:42:50 volumio volumio[3037]: info: CoreCommandRouter::volumioPushState Mar 29 22:42:50 volumio volumio[3037]: info: ControllerMpd::pushState Mar 29 22:42:50 volumio volumio[3037]: info: CoreCommandRouter::servicePushState Mar 29 22:42:50 volumio volumio[3037]: info: CorePlayQueue::getTrack 0 Mar 29 22:42:50 volumio volumio[3037]: verbose: STATE SERVICE {"status":"play","position":0,"seek":12332683,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"DAVID PUENTEZ & ALBERT NEVE - SUPERSTAR","artist":"Absolut AI","album":null,"uri":"https://absolut-ai.live-sm.absolutradio.de/absolut-ai/stream/mp3","trackType":""} Mar 29 22:42:50 volumio volumio[3037]: verbose: CURRENT POSITION 0 Mar 29 22:42:50 volumio volumio[3037]: info: CoreStateMachine::syncState stateService play Mar 29 22:42:50 volumio volumio[3037]: info: CoreStateMachine::syncState currentStatus play Mar 29 22:42:50 volumio volumio[3037]: info: Received an update from plugin. extracting info from payload Mar 29 22:42:50 volumio volumio[3037]: info: CoreStateMachine::pushState Mar 29 22:42:50 volumio volumio[3037]: info: CoreCommandRouter::volumioPushState Mar 29 22:42:50 volumio volumio[3037]: info: CoreStateMachine::pushState Mar 29 22:42:50 volumio volumio[3037]: info: CoreCommandRouter::volumioPushState Mar 29 22:42:50 volumio volumio5-onboarding[1494]: time=2026-03-29T22:42:50.526+05:30 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02,192.168.1.38:49818 @ 0x295f1d0" state=STATUS_PLAYING positionMs=12331515 volume=30 Mar 29 22:42:50 volumio volumio5-onboarding[1494]: time=2026-03-29T22:42:50.527+05:30 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.38:49818 @ 0x276c120" state=STATUS_PLAYING positionMs=12331515 volume=30 Mar 29 22:42:50 volumio volumio5-onboarding[1494]: time=2026-03-29T22:42:50.527+05:30 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02,192.168.1.38:49818 @ 0x295f1d0" id=https://absolut-ai.live-sm.absolutradio.de/absolut-ai/stream/mp3 title="DAVID PUENTEZ & ALBERT NEVE - SUPERSTAR" Mar 29 22:42:50 volumio volumio5-onboarding[1494]: time=2026-03-29T22:42:50.527+05:30 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.38:49818 @ 0x276c120" id=https://absolut-ai.live-sm.absolutradio.de/absolut-ai/stream/mp3 title="DAVID PUENTEZ & ALBERT NEVE - SUPERSTAR" Mar 29 22:42:50 volumio volumio5-onboarding[1494]: time=2026-03-29T22:42:50.528+05:30 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02,192.168.1.38:49818 @ 0x295f1d0" state=STATUS_PLAYING positionMs=12331515 volume=30 Mar 29 22:42:50 volumio volumio5-onboarding[1494]: time=2026-03-29T22:42:50.528+05:30 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.38:49818 @ 0x276c120" state=STATUS_PLAYING positionMs=12331515 volume=30 Mar 29 22:42:50 volumio volumio5-onboarding[1494]: time=2026-03-29T22:42:50.528+05:30 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02,192.168.1.38:49818 @ 0x295f1d0" id=https://absolut-ai.live-sm.absolutradio.de/absolut-ai/stream/mp3 title="DAVID PUENTEZ & ALBERT NEVE - SUPERSTAR" Mar 29 22:42:50 volumio volumio5-onboarding[1494]: time=2026-03-29T22:42:50.528+05:30 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.38:49818 @ 0x276c120" id=https://absolut-ai.live-sm.absolutradio.de/absolut-ai/stream/mp3 title="DAVID PUENTEZ & ALBERT NEVE - SUPERSTAR" Mar 29 22:42:50 volumio volumio5-onboarding[1494]: time=2026-03-29T22:42:50.529+05:30 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02,192.168.1.38:49818 @ 0x295f1d0" state=STATUS_PLAYING positionMs=12331515 volume=30 Mar 29 22:42:50 volumio volumio5-onboarding[1494]: time=2026-03-29T22:42:50.529+05:30 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.38:49818 @ 0x276c120" state=STATUS_PLAYING positionMs=12331515 volume=30 Mar 29 22:42:50 volumio volumio5-onboarding[1494]: time=2026-03-29T22:42:50.529+05:30 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02,192.168.1.38:49818 @ 0x295f1d0" id=https://absolut-ai.live-sm.absolutradio.de/absolut-ai/stream/mp3 title="DAVID PUENTEZ & ALBERT NEVE - SUPERSTAR" Mar 29 22:42:50 volumio volumio5-onboarding[1494]: time=2026-03-29T22:42:50.529+05:30 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.38:49818 @ 0x276c120" id=https://absolut-ai.live-sm.absolutradio.de/absolut-ai/stream/mp3 title="DAVID PUENTEZ & ALBERT NEVE - SUPERSTAR" Mar 29 22:42:50 volumio volumio5-onboarding[1494]: time=2026-03-29T22:42:50.530+05:30 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02,192.168.1.38:49818 @ 0x295f1d0" state=STATUS_PLAYING positionMs=12331515 volume=30 Mar 29 22:42:50 volumio volumio5-onboarding[1494]: time=2026-03-29T22:42:50.530+05:30 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.38:49818 @ 0x276c120" state=STATUS_PLAYING positionMs=12331515 volume=30 Mar 29 22:42:50 volumio volumio5-onboarding[1494]: time=2026-03-29T22:42:50.530+05:30 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02,192.168.1.38:49818 @ 0x295f1d0" id=https://absolut-ai.live-sm.absolutradio.de/absolut-ai/stream/mp3 title="DAVID PUENTEZ & ALBERT NEVE - SUPERSTAR" Mar 29 22:42:50 volumio volumio5-onboarding[1494]: time=2026-03-29T22:42:50.530+05:30 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.38:49818 @ 0x276c120" id=https://absolut-ai.live-sm.absolutradio.de/absolut-ai/stream/mp3 title="DAVID PUENTEZ & ALBERT NEVE - SUPERSTAR" Mar 29 22:42:50 volumio volumio[3037]: info: ------------------------------ 29ms Mar 29 22:42:50 volumio volumio[3037]: info: ------------------------------ 27ms Mar 29 22:42:50 volumio volumio[3037]: info: sendMpdCommand playlistinfo took 18 milliseconds Mar 29 22:42:50 volumio volumio[3037]: verbose: ControllerMpd::parseTrackInfo Mar 29 22:42:50 volumio volumio[3037]: info: ControllerMpd::pushState Mar 29 22:42:50 volumio volumio[3037]: info: CoreCommandRouter::servicePushState Mar 29 22:42:50 volumio volumio[3037]: info: CorePlayQueue::getTrack 0 Mar 29 22:42:50 volumio volumio[3037]: verbose: STATE SERVICE {"status":"play","position":0,"seek":12332683,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"DAVID PUENTEZ & ALBERT NEVE - SUPERSTAR","artist":"Absolut AI","album":null,"uri":"https://absolut-ai.live-sm.absolutradio.de/absolut-ai/stream/mp3","trackType":""} Mar 29 22:42:50 volumio volumio[3037]: verbose: CURRENT POSITION 0 Mar 29 22:42:50 volumio volumio[3037]: info: CoreStateMachine::syncState stateService play Mar 29 22:42:50 volumio volumio[3037]: info: CoreStateMachine::syncState currentStatus play Mar 29 22:42:50 volumio volumio[3037]: info: Received an update from plugin. extracting info from payload Mar 29 22:42:50 volumio volumio[3037]: info: CoreStateMachine::pushState Mar 29 22:42:50 volumio volumio[3037]: info: CoreCommandRouter::volumioPushState Mar 29 22:42:50 volumio volumio[3037]: info: CoreStateMachine::pushState Mar 29 22:42:50 volumio volumio[3037]: info: CoreCommandRouter::volumioPushState Mar 29 22:42:50 volumio volumio5-onboarding[1494]: time=2026-03-29T22:42:50.545+05:30 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02,192.168.1.38:49818 @ 0x295f1d0" state=STATUS_PLAYING positionMs=12331515 volume=30 Mar 29 22:42:50 volumio volumio5-onboarding[1494]: time=2026-03-29T22:42:50.546+05:30 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02,192.168.1.38:49818 @ 0x295f1d0" state=STATUS_PLAYING positionMs=12331515 volume=30 Mar 29 22:42:50 volumio volumio5-onboarding[1494]: time=2026-03-29T22:42:50.546+05:30 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.38:49818 @ 0x276c120" state=STATUS_PLAYING positionMs=12331515 volume=30 Mar 29 22:42:50 volumio volumio5-onboarding[1494]: time=2026-03-29T22:42:50.546+05:30 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02,192.168.1.38:49818 @ 0x295f1d0" id=https://absolut-ai.live-sm.absolutradio.de/absolut-ai/stream/mp3 title="DAVID PUENTEZ & ALBERT NEVE - SUPERSTAR" Mar 29 22:42:50 volumio volumio[3037]: info: ------------------------------ 37ms Mar 29 22:42:50 volumio volumio5-onboarding[1494]: time=2026-03-29T22:42:50.547+05:30 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.38:49818 @ 0x276c120" state=STATUS_PLAYING positionMs=12331515 volume=30 Mar 29 22:42:50 volumio volumio5-onboarding[1494]: time=2026-03-29T22:42:50.548+05:30 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02,192.168.1.38:49818 @ 0x295f1d0" id=https://absolut-ai.live-sm.absolutradio.de/absolut-ai/stream/mp3 title="DAVID PUENTEZ & ALBERT NEVE - SUPERSTAR" Mar 29 22:42:50 volumio volumio5-onboarding[1494]: time=2026-03-29T22:42:50.548+05:30 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.38:49818 @ 0x276c120" id=https://absolut-ai.live-sm.absolutradio.de/absolut-ai/stream/mp3 title="DAVID PUENTEZ & ALBERT NEVE - SUPERSTAR" Mar 29 22:42:50 volumio volumio5-onboarding[1494]: time=2026-03-29T22:42:50.548+05:30 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.38:49818 @ 0x276c120" id=https://absolut-ai.live-sm.absolutradio.de/absolut-ai/stream/mp3 title="DAVID PUENTEZ & ALBERT NEVE - SUPERSTAR" Mar 29 22:42:50 volumio volumio[3037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 30 Mar 29 22:42:50 volumio volumio[3037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 30 Mar 29 22:42:50 volumio volumio[3037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 30 Mar 29 22:42:50 volumio volumio[3037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 30 Mar 29 22:42:50 volumio volumio[3037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 30 Mar 29 22:42:50 volumio volumio[3037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 30 Mar 29 22:42:51 volumio volumio[3037]: SPOTIFY: SETTING SPOTIFY VOLUME 30 Mar 29 22:42:51 volumio volumio[3037]: info: Sending Spotify command with payload to local API: /player/volume Mar 29 22:42:51 volumio go-librespot[17730]: time="2026-03-29T22:42:51+05:30" level=debug msg="update volume requested to 19660/65535" Mar 29 22:42:51 volumio go-librespot[17730]: time="2026-03-29T22:42:51+05:30" level=debug msg="put connect state because VOLUME_CHANGED" Mar 29 22:42:51 volumio go-librespot[17730]: time="2026-03-29T22:42:51+05:30" level=trace msg="emitting websocket event: volume" Mar 29 22:42:51 volumio volumio[3037]: SPOTIFY: received: {"type":"volume","data":{"value":30,"max":100}} Mar 29 22:42:51 volumio volumio[3037]: SPOTIFY: RECEIVED SPOTIFY VOLUME 30 Mar 29 22:42:51 volumio volumio[3037]: SPOTIFY: received: {"type":"volume","data":{"value":30,"max":100}} Mar 29 22:42:51 volumio volumio[3037]: SPOTIFY: RECEIVED SPOTIFY VOLUME 30 Mar 29 22:42:52 volumio volumio[3037]: info: Getting Spotify volume Mar 29 22:42:52 volumio volumio[3037]: info: Spotify volume: 30 Mar 29 22:42:52 volumio volumio[3037]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Mar 29 22:42:52 volumio volumio[3037]: info: CoreCommandRouter::volumioGetState Mar 29 22:42:52 volumio volumio[3037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 30 Mar 29 22:42:52 volumio volumio[3037]: info: Getting Spotify volume Mar 29 22:42:52 volumio volumio[3037]: info: Spotify volume: 30 Mar 29 22:42:52 volumio volumio[3037]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Mar 29 22:42:53 volumio volumio[3037]: info: CoreCommandRouter::volumioGetState Mar 29 22:42:53 volumio volumio[3037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 30 Mar 29 22:42:53 volumio volumio[3037]: info: Initializing connection to go-librespot Websocket Mar 29 22:42:53 volumio go-librespot[17730]: time="2026-03-29T22:42:53+05:30" level=debug msg="new websocket client" Mar 29 22:42:53 volumio volumio[3037]: info: Connection to go-librespot Websocket established Mar 29 22:42:54 volumio volumio[3037]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 29 22:42:54 volumio volumio[3037]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 29 22:42:54 volumio volumio[3037]: info: Creating Spotify config file Mar 29 22:42:54 volumio volumio[3037]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 29 22:42:54 volumio volumio[3037]: info: Spotify config file written Mar 29 22:42:54 volumio sudo[17770]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 29 22:42:54 volumio sudo[17770]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 29 22:42:54 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 29 22:42:54 volumio volumio[3037]: info: Connection to go-librespot Websocket closed Mar 29 22:42:54 volumio volumio[3037]: info: Connection to go-librespot Websocket closed Mar 29 22:42:54 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 29 22:42:54 volumio volumio[3037]: info: Connection to go-librespot Websocket closed Mar 29 22:42:54 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 29 22:42:54 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 29 22:42:54 volumio sudo[17770]: pam_unix(sudo:session): session closed for user root Mar 29 22:42:54 volumio go-librespot[17772]: go-librespot daemon starting... Mar 29 22:42:54 volumio go-librespot[17773]: time="2026-03-29T22:42:54+05:30" level=info msg="running go-librespot 0.7.1" Mar 29 22:42:54 volumio go-librespot[17773]: time="2026-03-29T22:42:54+05:30" level=debug msg="app state loaded" Mar 29 22:42:54 volumio go-librespot[17773]: time="2026-03-29T22:42:54+05:30" level=info msg="api server listening on 127.0.0.1:9879" Mar 29 22:42:54 volumio go-librespot[17773]: time="2026-03-29T22:42:54+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]" Mar 29 22:42:54 volumio go-librespot[17773]: time="2026-03-29T22:42:54+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]" Mar 29 22:42:54 volumio go-librespot[17773]: time="2026-03-29T22:42:54+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]" Mar 29 22:42:54 volumio go-librespot[17773]: time="2026-03-29T22:42:54+05:30" level=info msg="zeroconf server listening on port 41795" Mar 29 22:42:54 volumio go-librespot[17773]: time="2026-03-29T22:42:54+05:30" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Mar 29 22:42:54 volumio volumio[3037]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 29 22:42:54 volumio volumio[3037]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 29 22:42:54 volumio volumio[3037]: info: Creating Spotify config file Mar 29 22:42:54 volumio volumio[3037]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 29 22:42:54 volumio volumio[3037]: info: Spotify config file written Mar 29 22:42:54 volumio sudo[17785]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 29 22:42:54 volumio sudo[17785]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 29 22:42:54 volumio go-librespot[17773]: time="2026-03-29T22:42:54+05:30" level=debug msg="obtained new client token: AABWYaj4WaFYhOaP8NNcR/iYvJ4bBWpCmKjmhb8UN8BVv9dNsGchJ0ngjPH8XQkMH9xUZ/LNn9FpDEcFsU3U6y3q4EZZIVScQfAzjfvJmWFnR6koqeM2v+oePLxv9PbNRb1H3MP0LbyiQuBVj48wwWXdiBqW1cYNw9SCXJycOAG7XjkxNnbe0Ncwtub+RWnCapcUJHQfDngOnJUsM/ASm5MXvch+r5r0jWzc0vYMSl0zT7QpmR5HepabZA==" Mar 29 22:42:54 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 29 22:42:54 volumio systemd[1]: go-librespot-daemon.service: Killing process 17774 (go-librespot) with signal SIGKILL. Mar 29 22:42:54 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 29 22:42:54 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 29 22:42:54 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 29 22:42:54 volumio go-librespot[17787]: go-librespot daemon starting... Mar 29 22:42:54 volumio sudo[17785]: pam_unix(sudo:session): session closed for user root Mar 29 22:42:54 volumio go-librespot[17788]: time="2026-03-29T22:42:54+05:30" level=info msg="running go-librespot 0.7.1" Mar 29 22:42:54 volumio go-librespot[17788]: time="2026-03-29T22:42:54+05:30" level=debug msg="app state loaded" Mar 29 22:42:54 volumio go-librespot[17788]: time="2026-03-29T22:42:54+05:30" level=info msg="api server listening on 127.0.0.1:9879" Mar 29 22:42:55 volumio go-librespot[17788]: time="2026-03-29T22:42:55+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]" Mar 29 22:42:55 volumio go-librespot[17788]: time="2026-03-29T22:42:55+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]" Mar 29 22:42:55 volumio go-librespot[17788]: time="2026-03-29T22:42:55+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]" Mar 29 22:42:55 volumio go-librespot[17788]: time="2026-03-29T22:42:55+05:30" level=info msg="zeroconf server listening on port 37109" Mar 29 22:42:55 volumio go-librespot[17788]: time="2026-03-29T22:42:55+05:30" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Mar 29 22:42:55 volumio volumio[3037]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 29 22:42:55 volumio volumio[3037]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 29 22:42:55 volumio volumio[3037]: info: Creating Spotify config file Mar 29 22:42:55 volumio volumio[3037]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 29 22:42:55 volumio volumio[3037]: info: Spotify config file written Mar 29 22:42:55 volumio go-librespot[17788]: time="2026-03-29T22:42:55+05:30" level=debug msg="obtained new client token: AAAiZoN7ff5jLFKSzIBYrKlb1tbj7U0SRe1muOa8IhJkGpHEej2cHs7EAVC3oIBOpSihEZaX75AwUfYycECsEcEKGo34yHASk/zgcpMgzb868ozNcIaXww0po3avTay7x7Dhci+wSp4zx85oe1OK4/E3nsK+gYHCdQoKpNRXrTH5SnHcj55CDoGHmzYWKD8HKPPT4ryka/KBpiyoz+imOJatuGdpivLklqVPeNUWdaQB+lJ+4hWrBW2LDQ==" Mar 29 22:42:55 volumio sudo[17798]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 29 22:42:55 volumio sudo[17798]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 29 22:42:55 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 29 22:42:55 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 29 22:42:55 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 29 22:42:55 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 29 22:42:55 volumio go-librespot[17800]: go-librespot daemon starting... Mar 29 22:42:55 volumio sudo[17798]: pam_unix(sudo:session): session closed for user root Mar 29 22:42:55 volumio go-librespot[17803]: time="2026-03-29T22:42:55+05:30" level=info msg="running go-librespot 0.7.1" Mar 29 22:42:55 volumio go-librespot[17803]: time="2026-03-29T22:42:55+05:30" level=debug msg="app state loaded" Mar 29 22:42:55 volumio go-librespot[17803]: time="2026-03-29T22:42:55+05:30" level=info msg="api server listening on 127.0.0.1:9879" Mar 29 22:42:56 volumio go-librespot[17803]: time="2026-03-29T22:42:56+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]" Mar 29 22:42:56 volumio go-librespot[17803]: time="2026-03-29T22:42:56+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]" Mar 29 22:42:56 volumio go-librespot[17803]: time="2026-03-29T22:42:56+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]" Mar 29 22:42:56 volumio go-librespot[17803]: time="2026-03-29T22:42:56+05:30" level=info msg="zeroconf server listening on port 36999" Mar 29 22:42:56 volumio volumio[3037]: info: Getting Spotify volume Mar 29 22:42:56 volumio go-librespot[17803]: time="2026-03-29T22:42:56+05:30" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Mar 29 22:42:56 volumio volumio[3037]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Mar 29 22:42:56 volumio volumio[3037]: info: CoreCommandRouter::volumioGetState Mar 29 22:42:56 volumio volumio[3037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 30 Mar 29 22:42:56 volumio go-librespot[17803]: time="2026-03-29T22:42:56+05:30" level=debug msg="obtained new client token: AABFwRN2BpH4AJTfHhHFUNm5iLOTeoC4d0TknpR2yiIzo1NdJZOgQShlvv3OcywVJX2pJHY07eKg9WXsx+ZeNB3VWoiXyC3htnBgK0+YH/0rpsfU+2XyoOtEVhLFoVAtLqT1I/yrnkhosq/FGhVamhZ4IjQSewKyEr+xR/jbqMDUBFp/jId1LmbfaS62Vs5AG9cuJT4Xr2LoNhX/LnzcIYbwuWFn+H4sQtvQVUovOwnPd+U0VH6BIsk=" Mar 29 22:42:56 volumio go-librespot[17803]: time="2026-03-29T22:42:56+05:30" level=debug msg="connected to ap-gae2.spotify.com:4070" Mar 29 22:42:56 volumio go-librespot[17803]: time="2026-03-29T22:42:56+05:30" level=debug msg="completed keyexchange" Mar 29 22:42:56 volumio go-librespot[17803]: time="2026-03-29T22:42:56+05:30" level=debug msg="completed challenge" Mar 29 22:42:56 volumio go-librespot[17803]: time="2026-03-29T22:42:56+05:30" level=info msg="authenticated AP" username="31************************zu" Mar 29 22:42:56 volumio go-librespot[17803]: time="2026-03-29T22:42:56+05:30" level=info msg="authenticated Login5" username="31************************zu" Mar 29 22:42:56 volumio go-librespot[17803]: time="2026-03-29T22:42:56+05:30" level=debug msg="initializing zeroconf session" username="31************************zu" Mar 29 22:42:57 volumio volumio[3037]: info: Initializing connection to go-librespot Websocket Mar 29 22:42:57 volumio go-librespot[17803]: time="2026-03-29T22:42:57+05:30" level=debug msg="new websocket client" Mar 29 22:42:57 volumio volumio[3037]: info: Connection to go-librespot Websocket established Mar 29 22:42:57 volumio volumio[3037]: info: go-librespot daemon successfully initialized Mar 29 22:42:57 volumio go-librespot[17803]: time="2026-03-29T22:42:57+05:30" level=debug msg="dealer connection opened" Mar 29 22:42:57 volumio go-librespot[17803]: time="2026-03-29T22:42:57+05:30" level=trace msg="starting accesspoint recv loop" Mar 29 22:42:57 volumio go-librespot[17803]: time="2026-03-29T22:42:57+05:30" level=trace msg="starting dealer recv loop" Mar 29 22:42:57 volumio go-librespot[17803]: time="2026-03-29T22:42:57+05:30" level=trace msg="received accesspoint ping" Mar 29 22:42:57 volumio go-librespot[17803]: time="2026-03-29T22:42:57+05:30" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Mar 29 22:42:57 volumio go-librespot[17803]: time="2026-03-29T22:42:57+05:30" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Mar 29 22:42:57 volumio go-librespot[17803]: time="2026-03-29T22:42:57+05:30" level=debug msg="received connection id: NTNlODYyMzYtODQ0...Q0U1NjFDNTc3Rg==" Mar 29 22:42:57 volumio volumio[3037]: info: Spotify volume: 100 Mar 29 22:42:57 volumio volumio[3037]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Mar 29 22:42:57 volumio volumio[3037]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Mar 29 22:42:57 volumio volumio[3037]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Mar 29 22:42:57 volumio volumio[3037]: info: Received Get System Version Mar 29 22:42:57 volumio volumio[3037]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 29 22:42:57 volumio volumio[3037]: info: Received Get System Info Mar 29 22:42:57 volumio volumio[3037]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 29 22:42:57 volumio volumio[3037]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 29 22:42:57 volumio volumio[3037]: info: Discovery: Getting this device information Mar 29 22:42:57 volumio volumio[3037]: info: CoreCommandRouter::volumioGetState Mar 29 22:42:57 volumio volumio[3037]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 29 22:42:57 volumio go-librespot[17803]: time="2026-03-29T22:42:57+05:30" level=debug msg="put connect state because NEW_DEVICE" Mar 29 22:42:57 volumio go-librespot[17803]: time="2026-03-29T22:42:57+05:30" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Mar 29 22:42:57 volumio go-librespot[17803]: time="2026-03-29T22:42:57+05:30" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Mar 29 22:42:57 volumio go-librespot[17803]: time="2026-03-29T22:42:57+05:30" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Mar 29 22:42:57 volumio go-librespot[17803]: time="2026-03-29T22:42:57+05:30" level=trace msg="received accesspoint pong ack" Mar 29 22:42:57 volumio volumio[3037]: info: go-librespot daemon successfully initialized Mar 29 22:42:58 volumio volumio[3037]: info: go-librespot daemon successfully initialized Mar 29 22:42:59 volumio volumio[3037]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 29 22:42:59 volumio volumio[3037]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 29 22:42:59 volumio volumio[3037]: info: Creating Spotify config file Mar 29 22:42:59 volumio volumio[3037]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 29 22:42:59 volumio volumio[3037]: info: Spotify config file written Mar 29 22:42:59 volumio sudo[17834]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 29 22:42:59 volumio sudo[17834]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 29 22:42:59 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 29 22:42:59 volumio systemd[1]: go-librespot-daemon.service: Killing process 17807 (go-librespot) with signal SIGKILL. Mar 29 22:42:59 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 29 22:42:59 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 29 22:42:59 volumio volumio[3037]: info: Connection to go-librespot Websocket closed Mar 29 22:42:59 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 29 22:42:59 volumio go-librespot[17836]: go-librespot daemon starting... Mar 29 22:42:59 volumio sudo[17834]: pam_unix(sudo:session): session closed for user root Mar 29 22:42:59 volumio go-librespot[17837]: time="2026-03-29T22:42:59+05:30" level=info msg="running go-librespot 0.7.1" Mar 29 22:42:59 volumio go-librespot[17837]: time="2026-03-29T22:42:59+05:30" level=debug msg="app state loaded" Mar 29 22:42:59 volumio go-librespot[17837]: time="2026-03-29T22:42:59+05:30" level=info msg="api server listening on 127.0.0.1:9879" Mar 29 22:42:59 volumio go-librespot[17837]: time="2026-03-29T22:42:59+05:30" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Mar 29 22:42:59 volumio go-librespot[17837]: time="2026-03-29T22:42:59+05:30" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Mar 29 22:42:59 volumio go-librespot[17837]: time="2026-03-29T22:42:59+05:30" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Mar 29 22:42:59 volumio go-librespot[17837]: time="2026-03-29T22:42:59+05:30" level=info msg="zeroconf server listening on port 37025" Mar 29 22:42:59 volumio go-librespot[17837]: time="2026-03-29T22:42:59+05:30" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Mar 29 22:42:59 volumio go-librespot[17837]: time="2026-03-29T22:42:59+05:30" level=debug msg="obtained new client token: AAAOGcaiFDHoZ0n9hrx6Y4OtrYvcfdno7wmGdSupZ5HWYYFWo2tk3Ck+9E6ZhPMoSIqUY6A1QAHhn9aSG5UhBvYxJLy3LFoIT5mYneMpqv/IX+wKIfLOHxHV6xEZJk2EfE1m/+6m6BE5QBPDgq52bzB8jTIRgVNV8GMMz+JW1E5GUdt6R9f9rhgqfoPTjZ1aMltcGUinxKhjviiegipwG5Jbh2lYnfNdENzDwdrcvRyOtM1j9IiHQGhdPg==" Mar 29 22:42:59 volumio go-librespot[17837]: time="2026-03-29T22:42:59+05:30" level=debug msg="connected to ap-gae2.spotify.com:4070" Mar 29 22:42:59 volumio volumio[3037]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 29 22:42:59 volumio volumio[3037]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 29 22:42:59 volumio volumio[3037]: info: Creating Spotify config file Mar 29 22:42:59 volumio volumio[3037]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 29 22:42:59 volumio volumio[3037]: info: Spotify config file written Mar 29 22:42:59 volumio sudo[17849]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 29 22:42:59 volumio sudo[17849]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 29 22:42:59 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 29 22:42:59 volumio systemd[1]: go-librespot-daemon.service: Killing process 17842 (go-librespot) with signal SIGKILL. Mar 29 22:42:59 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 29 22:42:59 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 29 22:42:59 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 29 22:43:00 volumio sudo[17849]: pam_unix(sudo:session): session closed for user root Mar 29 22:43:00 volumio go-librespot[17851]: go-librespot daemon starting... Mar 29 22:43:00 volumio go-librespot[17852]: time="2026-03-29T22:43:00+05:30" level=info msg="running go-librespot 0.7.1" Mar 29 22:43:00 volumio go-librespot[17852]: time="2026-03-29T22:43:00+05:30" level=debug msg="app state loaded" Mar 29 22:43:00 volumio go-librespot[17852]: time="2026-03-29T22:43:00+05:30" level=info msg="api server listening on 127.0.0.1:9879" Mar 29 22:43:00 volumio volumio[3037]: info: Getting Spotify volume Mar 29 22:43:00 volumio volumio[3037]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Mar 29 22:43:00 volumio volumio[3037]: info: CoreCommandRouter::volumioGetState Mar 29 22:43:00 volumio volumio[3037]: SPOTIFY: RECEIVED VOLUMIO VOLUME 30 Mar 29 22:43:00 volumio volumio[3037]: SPOTIFY: SPOTIFY VOLUME 100 Mar 29 22:43:00 volumio volumio[3037]: SPOTIFY: VOLUMIO VOLUME 30 Mar 29 22:43:00 volumio volumio[3037]: SPOTIFY: DELTA VOLUME ENOUGH: true Mar 29 22:43:00 volumio volumio[3037]: info: Setting Spotify Volume from Volumio: 30 Mar 29 22:43:00 volumio go-librespot[17852]: time="2026-03-29T22:43:00+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]" Mar 29 22:43:00 volumio go-librespot[17852]: time="2026-03-29T22:43:00+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]" Mar 29 22:43:00 volumio go-librespot[17852]: time="2026-03-29T22:43:00+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]" Mar 29 22:43:00 volumio go-librespot[17852]: time="2026-03-29T22:43:00+05:30" level=info msg="zeroconf server listening on port 35007" Mar 29 22:43:00 volumio go-librespot[17852]: time="2026-03-29T22:43:00+05:30" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Mar 29 22:43:00 volumio volumio[3037]: info: Initializing connection to go-librespot Websocket Mar 29 22:43:00 volumio go-librespot[17852]: time="2026-03-29T22:43:00+05:30" level=debug msg="new websocket client" Mar 29 22:43:00 volumio volumio[3037]: info: Connection to go-librespot Websocket established Mar 29 22:43:00 volumio go-librespot[17852]: time="2026-03-29T22:43:00+05:30" level=debug msg="obtained new client token: AAC2cUJxLBUMP2+ny3wDNW4h2cfRteju7a2r9SA6zzGgRTHrKzR9Y20vF/R+5Slk7cxHfGY3Kw+kiOF68uKNd4V4zQ6FV5w6LFJ0OrpvHw3ahGAPeQ6w/2zS0/a4ODHsURW+9FRrqlSEZDAOgPn3IrA3CJnOGyq6DNGxzAx7ZggG3wF/z+zr9800LHKLBDOM+HSpBF7dCZ91PLexfTkewgTbtKMlxzjlSBwO09pNc7ySjYN+aoqR/K91FA==" Mar 29 22:43:00 volumio go-librespot[17852]: time="2026-03-29T22:43:00+05:30" level=debug msg="connected to ap-gae2.spotify.com:4070" Mar 29 22:43:00 volumio go-librespot[17852]: time="2026-03-29T22:43:00+05:30" level=debug msg="completed keyexchange" Mar 29 22:43:00 volumio go-librespot[17852]: time="2026-03-29T22:43:00+05:30" level=debug msg="completed challenge" Mar 29 22:43:00 volumio go-librespot[17852]: time="2026-03-29T22:43:00+05:30" level=info msg="authenticated AP" username="31************************zu" Mar 29 22:43:00 volumio volumio[3037]: info: Initializing connection to go-librespot Websocket Mar 29 22:43:00 volumio volumio[3037]: info: Connection to go-librespot Websocket established Mar 29 22:43:00 volumio go-librespot[17852]: time="2026-03-29T22:43:00+05:30" level=debug msg="new websocket client" Mar 29 22:43:01 volumio go-librespot[17852]: time="2026-03-29T22:43:01+05:30" level=info msg="authenticated Login5" username="31************************zu" Mar 29 22:43:01 volumio go-librespot[17852]: time="2026-03-29T22:43:01+05:30" level=debug msg="initializing zeroconf session" username="31************************zu" Mar 29 22:43:01 volumio go-librespot[17852]: time="2026-03-29T22:43:01+05:30" level=debug msg="dealer connection opened" Mar 29 22:43:01 volumio go-librespot[17852]: time="2026-03-29T22:43:01+05:30" level=trace msg="starting accesspoint recv loop" Mar 29 22:43:01 volumio go-librespot[17852]: time="2026-03-29T22:43:01+05:30" level=trace msg="starting dealer recv loop" Mar 29 22:43:01 volumio go-librespot[17852]: time="2026-03-29T22:43:01+05:30" level=trace msg="received accesspoint ping" Mar 29 22:43:01 volumio go-librespot[17852]: time="2026-03-29T22:43:01+05:30" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Mar 29 22:43:01 volumio go-librespot[17852]: time="2026-03-29T22:43:01+05:30" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Mar 29 22:43:01 volumio go-librespot[17852]: time="2026-03-29T22:43:01+05:30" level=debug msg="received connection id: NjUzZTY1MzAtZmM1...QjIzM0VBNzdDQw==" Mar 29 22:43:01 volumio volumio[3037]: info: Spotify volume: 100 Mar 29 22:43:01 volumio volumio[3037]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 29 22:43:01 volumio volumio[3037]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 29 22:43:01 volumio volumio[3037]: info: Creating Spotify config file Mar 29 22:43:01 volumio volumio[3037]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 29 22:43:01 volumio volumio[3037]: info: Spotify config file written Mar 29 22:43:01 volumio go-librespot[17852]: time="2026-03-29T22:43:01+05:30" level=debug msg="put connect state because NEW_DEVICE" Mar 29 22:43:01 volumio go-librespot[17852]: time="2026-03-29T22:43:01+05:30" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Mar 29 22:43:01 volumio go-librespot[17852]: time="2026-03-29T22:43:01+05:30" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Mar 29 22:43:01 volumio go-librespot[17852]: time="2026-03-29T22:43:01+05:30" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Mar 29 22:43:01 volumio go-librespot[17852]: time="2026-03-29T22:43:01+05:30" level=trace msg="received accesspoint pong ack" Mar 29 22:43:01 volumio sudo[17864]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 29 22:43:01 volumio sudo[17864]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 29 22:43:01 volumio volumio[3037]: info: Initializing connection to go-librespot Websocket Mar 29 22:43:01 volumio go-librespot[17852]: time="2026-03-29T22:43:01+05:30" level=debug msg="new websocket client" Mar 29 22:43:01 volumio volumio[3037]: info: Connection to go-librespot Websocket established Mar 29 22:43:01 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 29 22:43:01 volumio systemd[1]: go-librespot-daemon.service: Killing process 17860 (go-librespot) with signal SIGKILL. Mar 29 22:43:01 volumio volumio[3037]: info: Connection to go-librespot Websocket closed Mar 29 22:43:01 volumio volumio[3037]: info: Connection to go-librespot Websocket closed Mar 29 22:43:01 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 29 22:43:01 volumio volumio[3037]: info: Connection to go-librespot Websocket closed Mar 29 22:43:01 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 29 22:43:01 volumio systemd[1]: go-librespot-daemon.service: Start request repeated too quickly. Mar 29 22:43:01 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'start-limit-hit'. Mar 29 22:43:01 volumio systemd[1]: Failed to start go-librespot-daemon.service - go-librespot Daemon. Mar 29 22:43:01 volumio sudo[17864]: pam_unix(sudo:session): session closed for user root Mar 29 22:43:01 volumio volumio[3037]: error: Cannot start Go-librespot Daemon: Error: Command failed: /usr/bin/sudo systemctl restart go-librespot-daemon.service Mar 29 22:43:01 volumio volumio[3037]: Job for go-librespot-daemon.service failed because start of the service was attempted too often. Mar 29 22:43:01 volumio volumio[3037]: See "systemctl status go-librespot-daemon.service" and "journalctl -xeu go-librespot-daemon.service" for details. Mar 29 22:43:01 volumio volumio[3037]: To force a start use "systemctl reset-failed go-librespot-daemon.service" Mar 29 22:43:01 volumio volumio[3037]: followed by "systemctl start go-librespot-daemon.service" again. Mar 29 22:43:01 volumio volumio[3037]: error: Error initializing go-librespot daemon: Error: Command failed: /usr/bin/sudo systemctl restart go-librespot-daemon.service Mar 29 22:43:01 volumio volumio[3037]: Job for go-librespot-daemon.service failed because start of the service was attempted too often. Mar 29 22:43:01 volumio volumio[3037]: See "systemctl status go-librespot-daemon.service" and "journalctl -xeu go-librespot-daemon.service" for details. Mar 29 22:43:01 volumio volumio[3037]: To force a start use "systemctl reset-failed go-librespot-daemon.service" Mar 29 22:43:01 volumio volumio[3037]: followed by "systemctl start go-librespot-daemon.service" again. Mar 29 22:43:01 volumio volumio[3037]: SPOTIFY: SETTING SPOTIFY VOLUME 30 Mar 29 22:43:01 volumio volumio[3037]: info: Sending Spotify command with payload to local API: /player/volume Mar 29 22:43:01 volumio volumio[3037]: error: Failed to send command to Spotify local API: /player/volume: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 29 22:43:02 volumio volumio[3037]: info: go-librespot daemon successfully initialized Mar 29 22:43:03 volumio volumio[3037]: info: go-librespot daemon successfully initialized Mar 29 22:43:03 volumio volumio[3037]: info: Getting Spotify volume Mar 29 22:43:03 volumio volumio[3037]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 29 22:43:03 volumio volumio[3037]: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 29 22:43:03 volumio volumio[3037]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Mar 29 22:43:03 volumio volumio[3037]: errno: -111, Mar 29 22:43:03 volumio volumio[3037]: code: 'ECONNREFUSED', Mar 29 22:43:03 volumio volumio[3037]: syscall: 'connect', Mar 29 22:43:03 volumio volumio[3037]: address: '127.0.0.1', Mar 29 22:43:03 volumio volumio[3037]: port: 9879, Mar 29 22:43:03 volumio volumio[3037]: response: undefined Mar 29 22:43:03 volumio volumio[3037]: } Mar 29 22:43:03 volumio volumio[3037]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 29 22:43:03 volumio sudo[17884]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-03-29 22:42' Mar 29 22:43:03 volumio sudo[17884]: 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"