Jan 28 11:14:06 volumiodan go-librespot[2434]: time="2026-01-28T11:14:06Z" level=trace msg="received accesspoint ping" Jan 28 11:14:06 volumiodan go-librespot[2434]: time="2026-01-28T11:14:06Z" level=trace msg="received accesspoint pong ack" Jan 28 11:14:06 volumiodan go-librespot[2434]: time="2026-01-28T11:14:06Z" level=trace msg="sent dealer ping" Jan 28 11:14:06 volumiodan go-librespot[2434]: time="2026-01-28T11:14:06Z" level=trace msg="received dealer pong" Jan 28 11:14:16 volumiodan volumio[1191]: info: Jan 28 11:14:16 volumiodan volumio[1191]: ---------------------------- MPD announces system playlist update Jan 28 11:14:16 volumiodan volumio[1191]: info: Ignoring MPD Status Update Jan 28 11:14:16 volumiodan volumio[1191]: info: Jan 28 11:14:16 volumiodan volumio[1191]: ---------------------------- MPD announces state update: player Jan 28 11:14:16 volumiodan volumio[1191]: info: ControllerMpd::getState Jan 28 11:14:16 volumiodan volumio[1191]: verbose: ControllerMpd::sendMpdCommand status Jan 28 11:14:16 volumiodan volumio[1191]: info: ------------------------------ 2ms Jan 28 11:14:16 volumiodan volumio[1191]: info: sendMpdCommand status took 1 milliseconds Jan 28 11:14:16 volumiodan volumio[1191]: verbose: ControllerMpd::parseState Jan 28 11:14:16 volumiodan volumio[1191]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 28 11:14:16 volumiodan volumio[1191]: info: sendMpdCommand playlistinfo took 1 milliseconds Jan 28 11:14:16 volumiodan volumio[1191]: verbose: ControllerMpd::parseTrackInfo Jan 28 11:14:16 volumiodan volumio[1191]: info: ControllerMpd::pushState Jan 28 11:14:16 volumiodan volumio[1191]: info: CoreCommandRouter::servicePushState Jan 28 11:14:16 volumiodan volumio[1191]: info: CorePlayQueue::getTrack 0 Jan 28 11:14:16 volumiodan volumio[1191]: verbose: STATE SERVICE {"status":"play","position":0,"seek":307682,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Only You (And You Alone) - Platters","artist":"RMF GOLD","album":null,"uri":"http://www.rmfon.pl/tunein/tunein.php?host=rs203-krk-cyfronet.rmfstream.pl&mount=rmf_gold&secure=0","trackType":""} Jan 28 11:14:16 volumiodan volumio[1191]: verbose: CURRENT POSITION 0 Jan 28 11:14:16 volumiodan volumio[1191]: info: CoreStateMachine::syncState stateService play Jan 28 11:14:16 volumiodan volumio[1191]: info: CoreStateMachine::syncState currentStatus play Jan 28 11:14:16 volumiodan volumio[1191]: info: Received an update from plugin. extracting info from payload Jan 28 11:14:16 volumiodan volumio[1191]: info: CoreStateMachine::pushState Jan 28 11:14:16 volumiodan volumio[1191]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 28 11:14:16 volumiodan volumio[1191]: info: CoreCommandRouter::volumioPushState Jan 28 11:14:16 volumiodan volumio[1191]: info: CoreStateMachine::pushState Jan 28 11:14:16 volumiodan volumio[1191]: info: CoreCommandRouter::volumioPushState Jan 28 11:14:16 volumiodan volumio[1191]: info: ------------------------------ 47ms Jan 28 11:14:16 volumiodan volumio[1191]: info: PeppyMeterBasic ---peppymeterbasic status play Jan 28 11:14:16 volumiodan volumio[1191]: info: PeppyMeterBasic ---peppymeterbasic status play Jan 28 11:14:16 volumiodan sudo[4112]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppymeterbasic.service Jan 28 11:14:16 volumiodan sudo[4112]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 11:14:16 volumiodan volumio[1191]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Jan 28 11:14:16 volumiodan sudo[4116]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppymeterbasic.service Jan 28 11:14:16 volumiodan sudo[4116]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 11:14:16 volumiodan volumio[1191]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Jan 28 11:14:16 volumiodan sudo[4116]: pam_unix(sudo:session): session closed for user root Jan 28 11:14:16 volumiodan sudo[4112]: pam_unix(sudo:session): session closed for user root Jan 28 11:14:16 volumiodan volumio[1191]: info: peppymeterbasic Daemon Started Jan 28 11:14:16 volumiodan volumio[1191]: info: peppymeterbasic Daemon Started Jan 28 11:14:36 volumiodan go-librespot[2434]: time="2026-01-28T11:14:36Z" level=trace msg="sent dealer ping" Jan 28 11:14:36 volumiodan go-librespot[2434]: time="2026-01-28T11:14:36Z" level=trace msg="received dealer pong" Jan 28 11:14:54 volumiodan volumio[1191]: info: Received OAUTH Data Jan 28 11:14:54 volumiodan volumio[1191]: info: Executing Spotify Oauth Login Jan 28 11:14:54 volumiodan volumio[1191]: info: Saving Spotify Refresh Token Jan 28 11:14:54 volumiodan systemd[1]: Starting fstrim.service - Discard unused blocks on filesystems from /etc/fstab... Jan 28 11:14:54 volumiodan volumio[1191]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jan 28 11:14:54 volumiodan volumio[1191]: SPOTIFY: BQAPe90gy_mVhK412h4-zFWfL7NerXc5eBllVAjMs-jtxRxXJWiBrLVS2o46C7RDhO8DJwFfhWykU0Pupxo6_Prc8zUJ7R5WfclQ7mjSjVY0niqy9v-nbWgQWBQ4JNXyzTiB7xWNw8JEcoOxGid9npEhDqgRrplP-ESGugu5URlA6fkLwTk77jNv05r0mHmNKjCzIy6lXnVdolOoO-kLY6fsViyAj6U5jXlnCkiNsALTlREhbovdtaEJMVzoTAsIKp_VGLviZ3yHWxiLYxON4sx-E-_ktXe7C7OhV2LPdhkKMwnUeCn4-O2ef-RX Jan 28 11:14:54 volumiodan volumio[1191]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jan 28 11:14:54 volumiodan volumio[1191]: info: New Spotify access token = BQAPe90gy_mVhK412h4-zFWfL7NerXc5eBllVAjMs-jtxRxXJWiBrLVS2o46C7RDhO8DJwFfhWykU0Pupxo6_Prc8zUJ7R5WfclQ7mjSjVY0niqy9v-nbWgQWBQ4JNXyzTiB7xWNw8JEcoOxGid9npEhDqgRrplP-ESGugu5URlA6fkLwTk77jNv05r0mHmNKjCzIy6lXnVdolOoO-kLY6fsViyAj6U5jXlnCkiNsALTlREhbovdtaEJMVzoTAsIKp_VGLviZ3yHWxiLYxON4sx-E-_ktXe7C7OhV2LPdhkKMwnUeCn4-O2ef-RX Jan 28 11:14:54 volumiodan volumio[1191]: info: Spotify credentials grant success - running version from March 24, 2019 Jan 28 11:14:54 volumiodan fstrim[4267]: /boot: 208.3 MiB (218456064 bytes) trimmed on /dev/mmcblk0p1 Jan 28 11:14:54 volumiodan systemd[1]: fstrim.service: Deactivated successfully. Jan 28 11:14:54 volumiodan systemd[1]: Finished fstrim.service - Discard unused blocks on filesystems from /etc/fstab. Jan 28 11:14:54 volumiodan volumio[1191]: SPOTIFY: User informations: {"country":"PL","display_name":"danste77","email":"danste77@protonmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/31jl23ruj5jjjlijwtw4v4m5smoi"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/31jl23ruj5jjjlijwtw4v4m5smoi","id":"31jl23ruj5jjjlijwtw4v4m5smoi","images":[],"product":"premium","type":"user","uri":"spotify:user:31jl23ruj5jjjlijwtw4v4m5smoi"} Jan 28 11:14:54 volumiodan volumio[1191]: info: Creating Spotify config file Jan 28 11:14:54 volumiodan volumio[1191]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 11:14:54 volumiodan volumio[1191]: info: Spotify config file written Jan 28 11:14:54 volumiodan sudo[4273]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 28 11:14:54 volumiodan sudo[4273]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 11:14:54 volumiodan systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jan 28 11:14:54 volumiodan systemd[1]: go-librespot-daemon.service: Killing process 2435 (go-librespot) with signal SIGKILL. Jan 28 11:14:54 volumiodan systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jan 28 11:14:54 volumiodan systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 28 11:14:54 volumiodan volumio[1191]: info: Connection to go-librespot Websocket closed Jan 28 11:14:54 volumiodan systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 28 11:14:54 volumiodan go-librespot[4276]: go-librespot daemon starting... Jan 28 11:14:54 volumiodan sudo[4273]: pam_unix(sudo:session): session closed for user root Jan 28 11:14:54 volumiodan go-librespot[4277]: time="2026-01-28T11:14:54Z" level=info msg="running go-librespot 0.4.0" Jan 28 11:14:54 volumiodan go-librespot[4277]: time="2026-01-28T11:14:54Z" level=debug msg="app state loaded" Jan 28 11:14:54 volumiodan go-librespot[4277]: time="2026-01-28T11:14:54Z" level=info msg="api server listening on 127.0.0.1:9879" Jan 28 11:14:54 volumiodan volumio[1191]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jan 28 11:14:54 volumiodan volumio[1191]: SPOTIFY: BQBiXXWvPXY07GGjbg87lO6Gt06CX5FSLb2PQzyAG-KbUIsPmZhGSseez-78cRyei2GoSgtEKG8tS5r7uo8H9OifKapSzYaF-Yed4sl3BkL6oJEbgmyIlRWDLTFM2HbHCbjPXlOsbva-58OjjKYiIEd1nvQP1JpFSyGEsYzIKbF34lDPrWrPs4cqVxUOJWRGqZTLab6_JSj0miik3Bgmu5LbQ1aacFTLscH08A0P4EC4P4oQ8pYzFl2_lfnJ2lo2LEfMak5VX2sxwdgsKhRsArGe9eO8nihbUW1890KgllF2Lu-gvgEGOmaovYqY Jan 28 11:14:54 volumiodan volumio[1191]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jan 28 11:14:54 volumiodan volumio[1191]: info: New Spotify access token = BQBiXXWvPXY07GGjbg87lO6Gt06CX5FSLb2PQzyAG-KbUIsPmZhGSseez-78cRyei2GoSgtEKG8tS5r7uo8H9OifKapSzYaF-Yed4sl3BkL6oJEbgmyIlRWDLTFM2HbHCbjPXlOsbva-58OjjKYiIEd1nvQP1JpFSyGEsYzIKbF34lDPrWrPs4cqVxUOJWRGqZTLab6_JSj0miik3Bgmu5LbQ1aacFTLscH08A0P4EC4P4oQ8pYzFl2_lfnJ2lo2LEfMak5VX2sxwdgsKhRsArGe9eO8nihbUW1890KgllF2Lu-gvgEGOmaovYqY Jan 28 11:14:54 volumiodan volumio[1191]: info: Spotify credentials grant success - running version from March 24, 2019 Jan 28 11:14:55 volumiodan volumio[1191]: SPOTIFY: User informations: {"country":"PL","display_name":"danste77","email":"danste77@protonmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/31jl23ruj5jjjlijwtw4v4m5smoi"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/31jl23ruj5jjjlijwtw4v4m5smoi","id":"31jl23ruj5jjjlijwtw4v4m5smoi","images":[],"product":"premium","type":"user","uri":"spotify:user:31jl23ruj5jjjlijwtw4v4m5smoi"} Jan 28 11:14:55 volumiodan volumio[1191]: info: Spotify Successfully logged in Jan 28 11:14:55 volumiodan volumio[1191]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 28 11:14:55 volumiodan volumio[1191]: info: [1769598895023] CoreMusicLibrary::Adding element Spotify Jan 28 11:14:55 volumiodan volumio[1191]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 28 11:14:55 volumiodan volumio[1191]: Cannot find translation for source Spotify Jan 28 11:14:55 volumiodan go-librespot[4277]: time="2026-01-28T11:14:55Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Jan 28 11:14:55 volumiodan go-librespot[4277]: time="2026-01-28T11:14:55Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Jan 28 11:14:55 volumiodan go-librespot[4277]: time="2026-01-28T11:14:55Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Jan 28 11:14:55 volumiodan go-librespot[4277]: time="2026-01-28T11:14:55Z" level=info msg="zeroconf server listening on port 43345" Jan 28 11:14:55 volumiodan go-librespot[4277]: time="2026-01-28T11:14:55Z" level=debug msg="obtained new client token: AADgMPWV9bANqMUmF9W21OWMNAbGWc6zL2g4NVatngManAZVSlH/UnrpaAonOB6OilTFAdR7uuHqb24swaIpL0SamQ411sfu4qodGnZgedu9Rs/TdEsNz0zuxNTHhv9C8Kq1XcBFg3YenElfgUaf7G5PuDJH5ZnKAbItg+iAOdYmjcng40N/76NvceYPMbfkOz6M+DcqjH+wNLXYYuSSInKdVESClsTZTeqAdv+zCLxV0ewpHqsq2ww=" Jan 28 11:14:55 volumiodan go-librespot[4277]: time="2026-01-28T11:14:55Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Jan 28 11:14:55 volumiodan go-librespot[4277]: time="2026-01-28T11:14:55Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Jan 28 11:14:55 volumiodan systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 28 11:14:55 volumiodan systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 28 11:14:57 volumiodan sudo[4310]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 28 11:14:57 volumiodan sudo[4310]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 11:14:57 volumiodan sudo[4310]: pam_unix(sudo:session): session closed for user root Jan 28 11:14:57 volumiodan sudo[4312]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 28 11:14:57 volumiodan sudo[4312]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 11:14:57 volumiodan sudo[4312]: pam_unix(sudo:session): session closed for user root Jan 28 11:14:57 volumiodan volumio[1191]: info: Initializing connection to go-librespot Websocket Jan 28 11:14:57 volumiodan volumio[1191]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 28 11:14:57 volumiodan volumio[1191]: verbose: New Socket.io Connection to 192.168.1.5 from 192.168.1.2 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/144.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 8 Jan 28 11:14:57 volumiodan volumio[1191]: info: go-librespot daemon successfully initialized Jan 28 11:14:57 volumiodan volumio[1191]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Jan 28 11:14:57 volumiodan volumio[1191]: info: CoreCommandRouter::volumioGetVisibleSources Jan 28 11:14:57 volumiodan volumio[1191]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 28 11:14:57 volumiodan volumio[1191]: info: CoreCommandRouter::volumioGetState Jan 28 11:14:57 volumiodan volumio[1191]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Jan 28 11:14:57 volumiodan volumio[1191]: info: CoreCommandRouter::getUIConfigOnPlugin Jan 28 11:14:57 volumiodan volumio[1191]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Jan 28 11:14:57 volumiodan volumio[1191]: info: Received Get System Info Jan 28 11:14:57 volumiodan volumio[1191]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jan 28 11:14:57 volumiodan volumio[1191]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jan 28 11:14:57 volumiodan volumio[1191]: info: Discovery: Getting this device information Jan 28 11:14:57 volumiodan volumio[1191]: info: CoreCommandRouter::volumioGetState Jan 28 11:14:57 volumiodan volumio[1191]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jan 28 11:14:57 volumiodan volumio[1191]: info: CoreCommandRouter::volumioGetState Jan 28 11:14:57 volumiodan volumio[1191]: info: Listing playlists Jan 28 11:14:57 volumiodan volumio[1191]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Jan 28 11:14:57 volumiodan volumio[1191]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Jan 28 11:14:58 volumiodan volumio[1191]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Jan 28 11:14:58 volumiodan systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Jan 28 11:14:58 volumiodan systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 28 11:14:58 volumiodan systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 28 11:14:58 volumiodan go-librespot[4315]: go-librespot daemon starting... Jan 28 11:14:58 volumiodan go-librespot[4316]: time="2026-01-28T11:14:58Z" level=info msg="running go-librespot 0.4.0" Jan 28 11:14:58 volumiodan go-librespot[4316]: time="2026-01-28T11:14:58Z" level=debug msg="app state loaded" Jan 28 11:14:58 volumiodan go-librespot[4316]: time="2026-01-28T11:14:58Z" level=info msg="api server listening on 127.0.0.1:9879" Jan 28 11:14:58 volumiodan go-librespot[4316]: time="2026-01-28T11:14:58Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 28 11:14:58 volumiodan go-librespot[4316]: time="2026-01-28T11:14:58Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 28 11:14:58 volumiodan go-librespot[4316]: time="2026-01-28T11:14:58Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 28 11:14:58 volumiodan go-librespot[4316]: time="2026-01-28T11:14:58Z" level=info msg="zeroconf server listening on port 32979" Jan 28 11:14:58 volumiodan go-librespot[4316]: time="2026-01-28T11:14:58Z" level=debug msg="obtained new client token: AADgPZ5o5bQveVejezx758De2ww6x57B/OmurY4gb3rkZz9aspV1urSOV6fXIVc9pXYkQxVfpScS4xnAyP7JimCGW0l0FZgibXjMfKhCeDHi00scW4rrO7s2BuTDR8JPPkuCoMhfnMDczYhaoDA8xs9aeP5FjMam21qFw1FqM29BqOUxgp3W/BS9Cn9NnMSh39JwHBEy/kcMyqyfzVSmwXgyJo30db+KtB1bTdPUj6jE8UQrbqze1d2BZw==" Jan 28 11:14:58 volumiodan go-librespot[4316]: time="2026-01-28T11:14:58Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Jan 28 11:14:58 volumiodan go-librespot[4316]: time="2026-01-28T11:14:58Z" level=debug msg="completed keyexchange" Jan 28 11:14:58 volumiodan go-librespot[4316]: time="2026-01-28T11:14:58Z" level=debug msg="completed challenge" Jan 28 11:14:58 volumiodan go-librespot[4316]: time="2026-01-28T11:14:58Z" level=info msg="authenticated AP" username="31************************oi" Jan 28 11:14:58 volumiodan go-librespot[4316]: time="2026-01-28T11:14:58Z" level=info msg="authenticated Login5" username="31************************oi" Jan 28 11:14:58 volumiodan go-librespot[4316]: time="2026-01-28T11:14:58Z" level=debug msg="initializing zeroconf session" username="31************************oi" Jan 28 11:14:59 volumiodan go-librespot[4316]: time="2026-01-28T11:14:59Z" level=debug msg="dealer connection opened" Jan 28 11:14:59 volumiodan go-librespot[4316]: time="2026-01-28T11:14:59Z" level=trace msg="starting accesspoint recv loop" Jan 28 11:14:59 volumiodan go-librespot[4316]: time="2026-01-28T11:14:59Z" level=trace msg="starting dealer recv loop" Jan 28 11:14:59 volumiodan go-librespot[4316]: time="2026-01-28T11:14:59Z" level=trace msg="received accesspoint ping" Jan 28 11:14:59 volumiodan go-librespot[4316]: time="2026-01-28T11:14:59Z" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jan 28 11:14:59 volumiodan go-librespot[4316]: time="2026-01-28T11:14:59Z" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jan 28 11:14:59 volumiodan go-librespot[4316]: time="2026-01-28T11:14:59Z" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jan 28 11:14:59 volumiodan go-librespot[4316]: time="2026-01-28T11:14:59Z" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jan 28 11:14:59 volumiodan go-librespot[4316]: time="2026-01-28T11:14:59Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jan 28 11:14:59 volumiodan go-librespot[4316]: time="2026-01-28T11:14:59Z" level=debug msg="received connection id: MDA5YzgwZGUtYzM2...RjZEODAwQTVBRQ==" Jan 28 11:14:59 volumiodan go-librespot[4316]: time="2026-01-28T11:14:59Z" level=trace msg="received accesspoint pong ack" Jan 28 11:14:59 volumiodan go-librespot[4316]: time="2026-01-28T11:14:59Z" level=debug msg="put connect state because NEW_DEVICE" Jan 28 11:14:59 volumiodan volumio[1191]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Jan 28 11:14:59 volumiodan volumio[1191]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jan 28 11:14:59 volumiodan volumio[1191]: info: Received Get System Info Jan 28 11:14:59 volumiodan volumio[1191]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jan 28 11:14:59 volumiodan volumio[1191]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jan 28 11:14:59 volumiodan volumio[1191]: info: Discovery: Getting this device information Jan 28 11:14:59 volumiodan volumio[1191]: info: CoreCommandRouter::volumioGetState Jan 28 11:14:59 volumiodan volumio[1191]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jan 28 11:15:00 volumiodan volumio[1191]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jan 28 11:15:00 volumiodan volumio[1191]: info: Received Get System Info Jan 28 11:15:00 volumiodan volumio[1191]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jan 28 11:15:00 volumiodan volumio[1191]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jan 28 11:15:00 volumiodan volumio[1191]: info: Discovery: Getting this device information Jan 28 11:15:00 volumiodan volumio[1191]: info: CoreCommandRouter::volumioGetState Jan 28 11:15:00 volumiodan volumio[1191]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jan 28 11:15:00 volumiodan volumio[1191]: info: Initializing connection to go-librespot Websocket Jan 28 11:15:00 volumiodan go-librespot[4316]: time="2026-01-28T11:15:00Z" level=debug msg="new websocket client" Jan 28 11:15:00 volumiodan volumio[1191]: info: Connection to go-librespot Websocket established Jan 28 11:15:00 volumiodan volumio[1191]: info: Initializing connection to go-librespot Websocket Jan 28 11:15:00 volumiodan go-librespot[4316]: time="2026-01-28T11:15:00Z" level=debug msg="new websocket client" Jan 28 11:15:00 volumiodan volumio[1191]: info: Connection to go-librespot Websocket established Jan 28 11:15:02 volumiodan volumio[1191]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Jan 28 11:15:02 volumiodan volumio[1191]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Jan 28 11:15:02 volumiodan volumio[1191]: info: Creating Spotify config file Jan 28 11:15:02 volumiodan volumio[1191]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 11:15:02 volumiodan volumio[1191]: info: Spotify config file written Jan 28 11:15:02 volumiodan sudo[4332]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 28 11:15:02 volumiodan sudo[4332]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 11:15:02 volumiodan systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jan 28 11:15:02 volumiodan systemd[1]: go-librespot-daemon.service: Killing process 4321 (go-librespot) with signal SIGKILL. Jan 28 11:15:02 volumiodan systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jan 28 11:15:02 volumiodan systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 28 11:15:02 volumiodan volumio[1191]: info: Connection to go-librespot Websocket closed Jan 28 11:15:02 volumiodan volumio[1191]: info: Connection to go-librespot Websocket closed Jan 28 11:15:02 volumiodan systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 28 11:15:02 volumiodan go-librespot[4334]: go-librespot daemon starting... Jan 28 11:15:02 volumiodan sudo[4332]: pam_unix(sudo:session): session closed for user root Jan 28 11:15:02 volumiodan go-librespot[4335]: time="2026-01-28T11:15:02Z" level=info msg="running go-librespot 0.4.0" Jan 28 11:15:02 volumiodan go-librespot[4335]: time="2026-01-28T11:15:02Z" level=debug msg="app state loaded" Jan 28 11:15:02 volumiodan go-librespot[4335]: time="2026-01-28T11:15:02Z" level=info msg="api server listening on 127.0.0.1:9879" Jan 28 11:15:02 volumiodan go-librespot[4335]: time="2026-01-28T11:15:02Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Jan 28 11:15:02 volumiodan go-librespot[4335]: time="2026-01-28T11:15:02Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Jan 28 11:15:02 volumiodan go-librespot[4335]: time="2026-01-28T11:15:02Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Jan 28 11:15:02 volumiodan go-librespot[4335]: time="2026-01-28T11:15:02Z" level=info msg="zeroconf server listening on port 35917" Jan 28 11:15:02 volumiodan go-librespot[4335]: time="2026-01-28T11:15:02Z" level=debug msg="obtained new client token: AAD5J30VKnU1DDPV1ho9isG7JbwQXLG4bXvATqLPYp956xaMyIp0277n32eSZ/2l7Redk5b73NoFMWDFECJFgXXghufa4QjKEDjvRlqBKKc2Fjgf9WxwqWYN+Rxjd1/F/ROarQDqerpQ5lVh+vnrtRwedA1PGH0zj6qWkag3C+53nDQr/tE87mOnRskVDBvo/e18dd5kBmpDWDSaRDQCKvZpkVl82dIgWd0phMhMVHqmOoEeOWSEjnrcYg==" Jan 28 11:15:02 volumiodan go-librespot[4335]: time="2026-01-28T11:15:02Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Jan 28 11:15:02 volumiodan go-librespot[4335]: time="2026-01-28T11:15:02Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: read tcp 192.168.1.5:38716->104.199.65.9:4070: read: connection reset by peer" Jan 28 11:15:02 volumiodan systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 28 11:15:02 volumiodan systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 28 11:15:03 volumiodan volumio[1191]: info: Getting Spotify volume Jan 28 11:15:03 volumiodan volumio[1191]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 28 11:15:03 volumiodan volumio[1191]: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 28 11:15:03 volumiodan volumio[1191]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Jan 28 11:15:03 volumiodan volumio[1191]: errno: -111, Jan 28 11:15:03 volumiodan volumio[1191]: code: 'ECONNREFUSED', Jan 28 11:15:03 volumiodan volumio[1191]: syscall: 'connect', Jan 28 11:15:03 volumiodan volumio[1191]: address: '127.0.0.1', Jan 28 11:15:03 volumiodan volumio[1191]: port: 9879, Jan 28 11:15:03 volumiodan volumio[1191]: response: undefined Jan 28 11:15:03 volumiodan volumio[1191]: } Jan 28 11:15:03 volumiodan volumio[1191]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 28 11:15:04 volumiodan sudo[4358]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-28 11:14' Jan 28 11:15:04 volumiodan sudo[4358]: 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="cfdc872d40b979cca36352a7333c940c38dc64b5" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="6cbc2303e10f00c3a01cb7f02c6d12448bd32c62" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri Dec 5 20:42:14 UTC 2025" VOLUMIO_VERSION="4.073" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="67fdc5f60f00b7a328ccd8c4ad441086"