Dec 13 18:49:44 volumiowork volumio[1099]: info: Received OAUTH Data Dec 13 18:49:44 volumiowork volumio[1099]: info: Executing Spotify Oauth Login Dec 13 18:49:44 volumiowork volumio[1099]: info: Saving Spotify Refresh Token Dec 13 18:49:45 volumiowork volumio[1099]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 13 18:49:45 volumiowork volumio[1099]: SPOTIFY: BQD60kJh_yWKw0IGBzOneHy_7uasADLoBg4blSfNQrAFPTkRVZ1ujZK9aupxVB4NFdoHZzrUONeFRWUPeCe2-pgccoHQUCLHugNQ0Cp81pU7uU6SLgSvrjokk_HyotuVZR1rLJX-2TbLFR6mMYWW0G7n34QHShngw0FpgzRQtmyjwycTH519GYMhNMI7jtxTujyT9NsbW9dm2R0maz4IkTU2FidBAjcWiPG6m9qTA2sWE6FHVqEGzktvCkHxBewKFP3SIwDJcssn-_XG18EkEaXsZhxblQ Dec 13 18:49:45 volumiowork volumio[1099]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 13 18:49:45 volumiowork volumio[1099]: info: New Spotify access token = BQD60kJh_yWKw0IGBzOneHy_7uasADLoBg4blSfNQrAFPTkRVZ1ujZK9aupxVB4NFdoHZzrUONeFRWUPeCe2-pgccoHQUCLHugNQ0Cp81pU7uU6SLgSvrjokk_HyotuVZR1rLJX-2TbLFR6mMYWW0G7n34QHShngw0FpgzRQtmyjwycTH519GYMhNMI7jtxTujyT9NsbW9dm2R0maz4IkTU2FidBAjcWiPG6m9qTA2sWE6FHVqEGzktvCkHxBewKFP3SIwDJcssn-_XG18EkEaXsZhxblQ Dec 13 18:49:45 volumiowork volumio[1099]: info: Spotify credentials grant success - running version from March 24, 2019 Dec 13 18:49:45 volumiowork sudo[17262]: volumio : unable to resolve host volumiowork: System error Dec 13 18:49:45 volumiowork sudo[17262]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 13 18:49:45 volumiowork sudo[17262]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 13 18:49:45 volumiowork sudo[17264]: volumio : unable to resolve host volumiowork: System error Dec 13 18:49:45 volumiowork sudo[17264]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 13 18:49:45 volumiowork sudo[17264]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 13 18:49:45 volumiowork sudo[17264]: pam_unix(sudo:session): session closed for user root Dec 13 18:49:45 volumiowork sudo[17262]: pam_unix(sudo:session): session closed for user root Dec 13 18:49:45 volumiowork volumio[1099]: verbose: New Socket.io Connection to 192.168.50.169 from 192.168.50.88 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_7 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 7 Dec 13 18:49:45 volumiowork volumio[1099]: SPOTIFY: User informations: {"country":"NO","display_name":"tendn","email":"synneskenneth@hotmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/tendn"},"followers":{"href":null,"total":1},"href":"https://api.spotify.com/v1/users/tendn","id":"tendn","images":[],"product":"premium","type":"user","uri":"spotify:user:tendn"} Dec 13 18:49:45 volumiowork volumio[1099]: info: Creating Spotify config file Dec 13 18:49:45 volumiowork volumio[1099]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 13 18:49:45 volumiowork volumio[1099]: info: Spotify config file written Dec 13 18:49:45 volumiowork volumio[1099]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 13 18:49:45 volumiowork sudo[17274]: volumio : unable to resolve host volumiowork: System error Dec 13 18:49:45 volumiowork sudo[17274]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 13 18:49:45 volumiowork sudo[17274]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 13 18:49:45 volumiowork volumio[1099]: info: CoreCommandRouter::volumioGetState Dec 13 18:49:45 volumiowork volumio[1099]: info: CorePlayQueue::getTrack 9 Dec 13 18:49:45 volumiowork volumio[1099]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Dec 13 18:49:45 volumiowork volumio[1099]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Dec 13 18:49:45 volumiowork volumio[1099]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Dec 13 18:49:45 volumiowork volumio[1099]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Dec 13 18:49:45 volumiowork systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 13 18:49:45 volumiowork systemd[1]: go-librespot-daemon.service: Killing process 17043 (go-librespot) with signal SIGKILL. Dec 13 18:49:45 volumiowork systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 13 18:49:45 volumiowork systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 13 18:49:45 volumiowork volumio[1099]: info: Connection to go-librespot Websocket closed Dec 13 18:49:45 volumiowork systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 13 18:49:45 volumiowork go-librespot[17279]: go-librespot daemon starting... Dec 13 18:49:45 volumiowork sudo[17274]: pam_unix(sudo:session): session closed for user root Dec 13 18:49:45 volumiowork go-librespot[17280]: time="2025-12-13T18:49:45+01:00" level=info msg="running go-librespot 0.4.0" Dec 13 18:49:45 volumiowork go-librespot[17280]: time="2025-12-13T18:49:45+01:00" level=debug msg="app state loaded" Dec 13 18:49:45 volumiowork go-librespot[17280]: time="2025-12-13T18:49:45+01:00" level=debug msg="stored credentials not found" Dec 13 18:49:45 volumiowork go-librespot[17280]: time="2025-12-13T18:49:45+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 13 18:49:46 volumiowork volumio[1099]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 13 18:49:46 volumiowork volumio[1099]: SPOTIFY: BQDtm4Zsq55hYVqEXeAjxoEZWiJ74_GkcopFZlZ6fBB9ECOBZpfTWp3G4XtE7JVzQWW2camxJ_Gl9S0gWaFQ57UsywDUIhUi2ZYh2MErq-7HA9YbYqXckMltGB_usHL_1-DXldbY8oKx7uM1EV4C888VXjrRp-K-T6DjGSxuhsbF56QUjezmsy630rqeWEVgz5O8ZUWvbdBCqH8DQjWOsfb2396XxNO1NNYTEV_pldgrhXRzIKK2qN3VnlYAtr4DLpB94PipMGxKEuDcDc_jR7ttETsiOA Dec 13 18:49:46 volumiowork volumio[1099]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 13 18:49:46 volumiowork volumio[1099]: info: New Spotify access token = BQDtm4Zsq55hYVqEXeAjxoEZWiJ74_GkcopFZlZ6fBB9ECOBZpfTWp3G4XtE7JVzQWW2camxJ_Gl9S0gWaFQ57UsywDUIhUi2ZYh2MErq-7HA9YbYqXckMltGB_usHL_1-DXldbY8oKx7uM1EV4C888VXjrRp-K-T6DjGSxuhsbF56QUjezmsy630rqeWEVgz5O8ZUWvbdBCqH8DQjWOsfb2396XxNO1NNYTEV_pldgrhXRzIKK2qN3VnlYAtr4DLpB94PipMGxKEuDcDc_jR7ttETsiOA Dec 13 18:49:46 volumiowork volumio[1099]: info: Spotify credentials grant success - running version from March 24, 2019 Dec 13 18:49:46 volumiowork go-librespot[17280]: time="2025-12-13T18:49:46+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Dec 13 18:49:46 volumiowork go-librespot[17280]: time="2025-12-13T18:49:46+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 13 18:49:46 volumiowork go-librespot[17280]: time="2025-12-13T18:49:46+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 13 18:49:46 volumiowork go-librespot[17280]: time="2025-12-13T18:49:46+01:00" level=info msg="zeroconf server listening on port 46283" Dec 13 18:49:46 volumiowork volumio[1099]: SPOTIFY: User informations: {"country":"NO","display_name":"tendn","email":"synneskenneth@hotmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/tendn"},"followers":{"href":null,"total":1},"href":"https://api.spotify.com/v1/users/tendn","id":"tendn","images":[],"product":"premium","type":"user","uri":"spotify:user:tendn"} Dec 13 18:49:46 volumiowork volumio[1099]: info: Spotify Successfully logged in Dec 13 18:49:46 volumiowork volumio[1099]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 13 18:49:46 volumiowork volumio[1099]: info: [1765648186399] CoreMusicLibrary::Adding element Spotify Dec 13 18:49:46 volumiowork volumio[1099]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 13 18:49:46 volumiowork volumio[1099]: Cannot find translation for source Spotify Dec 13 18:49:46 volumiowork go-librespot[17280]: time="2025-12-13T18:49:46+01:00" level=debug msg="obtained new client token: AAA7jqocxtV4fQVTFac4/CVD1fDBOpAW7DIB/Nc+jN2nL7xSuANDWxc2mo6vB4Y8etq4r6CV1GaxfUJmNy6BToKZsKuwJIOrrkLq3C+MxjPWmzt39312hV8OhV7Z119QPfne2s2d98XM7RSQTkUugH7ooxVW3M3QJWy1WpwiLUpioDKK3yCst1o5+pYse6czIVrK3qQHY2UNwjCcDERhwOg7yO0sKLQJnJA8RmNfuPa+OJKaZYbjJGwIZg==" Dec 13 18:49:46 volumiowork go-librespot[17280]: time="2025-12-13T18:49:46+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 13 18:49:46 volumiowork go-librespot[17280]: time="2025-12-13T18:49:46+01:00" level=debug msg="completed keyexchange" Dec 13 18:49:46 volumiowork go-librespot[17280]: time="2025-12-13T18:49:46+01:00" level=debug msg="completed challenge" Dec 13 18:49:46 volumiowork go-librespot[17280]: time="2025-12-13T18:49:46+01:00" level=info msg="authenticated AP" username="te*dn" Dec 13 18:49:47 volumiowork go-librespot[17280]: time="2025-12-13T18:49:47+01:00" level=info msg="authenticated Login5" username="te*dn" Dec 13 18:49:47 volumiowork go-librespot[17280]: time="2025-12-13T18:49:47+01:00" level=debug msg="stored credentials" username="te*dn" Dec 13 18:49:47 volumiowork go-librespot[17280]: time="2025-12-13T18:49:47+01:00" level=debug msg="initializing zeroconf session" username="te*dn" Dec 13 18:49:47 volumiowork volumio[1099]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 13 18:49:47 volumiowork volumio[1099]: info: Received Get System Info Dec 13 18:49:47 volumiowork volumio[1099]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 13 18:49:47 volumiowork volumio[1099]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 13 18:49:47 volumiowork volumio[1099]: info: Discovery: Getting this device information Dec 13 18:49:47 volumiowork volumio[1099]: info: CoreCommandRouter::volumioGetState Dec 13 18:49:47 volumiowork volumio[1099]: info: CorePlayQueue::getTrack 9 Dec 13 18:49:47 volumiowork volumio[1099]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 13 18:49:47 volumiowork go-librespot[17280]: time="2025-12-13T18:49:47+01:00" level=debug msg="dealer connection opened" Dec 13 18:49:47 volumiowork go-librespot[17280]: time="2025-12-13T18:49:47+01:00" level=trace msg="starting accesspoint recv loop" Dec 13 18:49:47 volumiowork go-librespot[17280]: time="2025-12-13T18:49:47+01:00" level=trace msg="starting dealer recv loop" Dec 13 18:49:47 volumiowork go-librespot[17280]: time="2025-12-13T18:49:47+01:00" level=trace msg="received accesspoint ping" Dec 13 18:49:47 volumiowork go-librespot[17280]: time="2025-12-13T18:49:47+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Dec 13 18:49:47 volumiowork go-librespot[17280]: time="2025-12-13T18:49:47+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Dec 13 18:49:47 volumiowork go-librespot[17280]: time="2025-12-13T18:49:47+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Dec 13 18:49:47 volumiowork go-librespot[17280]: time="2025-12-13T18:49:47+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Dec 13 18:49:47 volumiowork go-librespot[17280]: time="2025-12-13T18:49:47+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Dec 13 18:49:47 volumiowork go-librespot[17280]: time="2025-12-13T18:49:47+01:00" level=debug msg="received connection id: OGIzMjg0ZmUtNmJm...MzQ1QTdFMUQ2RA==" Dec 13 18:49:47 volumiowork go-librespot[17280]: time="2025-12-13T18:49:47+01:00" level=trace msg="received accesspoint pong ack" Dec 13 18:49:48 volumiowork volumio[1099]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 13 18:49:48 volumiowork volumio[1099]: info: Received Get System Info Dec 13 18:49:48 volumiowork volumio[1099]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 13 18:49:48 volumiowork volumio[1099]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 13 18:49:48 volumiowork volumio[1099]: info: Discovery: Getting this device information Dec 13 18:49:48 volumiowork volumio[1099]: info: CoreCommandRouter::volumioGetState Dec 13 18:49:48 volumiowork volumio[1099]: info: CorePlayQueue::getTrack 9 Dec 13 18:49:48 volumiowork volumio[1099]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 13 18:49:48 volumiowork volumio[1099]: info: Initializing connection to go-librespot Websocket Dec 13 18:49:48 volumiowork go-librespot[17280]: time="2025-12-13T18:49:48+01:00" level=debug msg="new websocket client" Dec 13 18:49:48 volumiowork volumio[1099]: info: Connection to go-librespot Websocket established Dec 13 18:49:48 volumiowork volumio[1099]: info: go-librespot daemon successfully initialized Dec 13 18:49:50 volumiowork go-librespot[17280]: time="2025-12-13T18:49:50+01:00" level=debug msg="put connect state because NEW_DEVICE" Dec 13 18:49:51 volumiowork volumio[1099]: info: Getting Spotify volume Dec 13 18:49:51 volumiowork volumio[1099]: info: Spotify volume: 100 Dec 13 18:49:51 volumiowork volumio[1099]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Dec 13 18:49:51 volumiowork volumio[1099]: info: CoreCommandRouter::volumioGetState Dec 13 18:49:51 volumiowork volumio[1099]: info: CorePlayQueue::getTrack 9 Dec 13 18:49:51 volumiowork volumio[1099]: info: Initializing connection to go-librespot Websocket Dec 13 18:49:51 volumiowork volumio[1099]: SPOTIFY: RECEIVED VOLUMIO VOLUME 36 Dec 13 18:49:51 volumiowork volumio[1099]: SPOTIFY: SPOTIFY VOLUME 100 Dec 13 18:49:51 volumiowork volumio[1099]: SPOTIFY: VOLUMIO VOLUME 36 Dec 13 18:49:51 volumiowork volumio[1099]: SPOTIFY: DELTA VOLUME ENOUGH: true Dec 13 18:49:51 volumiowork volumio[1099]: info: Setting Spotify Volume from Volumio: 36 Dec 13 18:49:51 volumiowork go-librespot[17280]: time="2025-12-13T18:49:51+01:00" level=debug msg="new websocket client" Dec 13 18:49:51 volumiowork volumio[1099]: info: Connection to go-librespot Websocket established Dec 13 18:49:53 volumiowork volumio[1099]: SPOTIFY: SETTING SPOTIFY VOLUME 36 Dec 13 18:49:53 volumiowork volumio[1099]: info: Sending Spotify command with payload to local API: /player/volume Dec 13 18:49:53 volumiowork go-librespot[17280]: time="2025-12-13T18:49:53+01:00" level=debug msg="update volume requested to 23592/65535" Dec 13 18:49:53 volumiowork go-librespot[17280]: time="2025-12-13T18:49:53+01:00" level=debug msg="put connect state because VOLUME_CHANGED" Dec 13 18:49:53 volumiowork go-librespot[17280]: time="2025-12-13T18:49:53+01:00" level=trace msg="emitting websocket event: volume" Dec 13 18:49:53 volumiowork volumio[1099]: SPOTIFY: received: {"type":"volume","data":{"value":36,"max":100}} Dec 13 18:49:53 volumiowork volumio[1099]: SPOTIFY: RECEIVED SPOTIFY VOLUME 36 Dec 13 18:49:53 volumiowork volumio[1099]: SPOTIFY: received: {"type":"volume","data":{"value":36,"max":100}} Dec 13 18:49:53 volumiowork volumio[1099]: SPOTIFY: RECEIVED SPOTIFY VOLUME 36 Dec 13 18:49:54 volumiowork volumio[1099]: info: Getting Spotify volume Dec 13 18:49:54 volumiowork volumio[1099]: info: Spotify volume: 36 Dec 13 18:49:54 volumiowork volumio[1099]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Dec 13 18:49:54 volumiowork volumio[1099]: info: CoreCommandRouter::volumioGetState Dec 13 18:49:54 volumiowork volumio[1099]: info: CorePlayQueue::getTrack 9 Dec 13 18:49:54 volumiowork volumio[1099]: SPOTIFY: RECEIVED VOLUMIO VOLUME 36 Dec 13 18:49:55 volumiowork volumio[1099]: info: CorePlayQueue::getTrack 9 Dec 13 18:49:55 volumiowork volumio[1099]: info: CorePlayQueue::getTrack 10 Dec 13 18:49:55 volumiowork volumio[1099]: info: Prefetching next song Dec 13 18:49:55 volumiowork volumio[1099]: info: Doing Prefetch in UPNP Dec 13 18:49:55 volumiowork volumio[1099]: verbose: ControllerMpd::sendMpdCommand add "http://192.168.50.146:8200/MediaItems/17253.flac" Dec 13 18:49:55 volumiowork volumio[1099]: info: Dec 13 18:49:55 volumiowork volumio[1099]: ---------------------------- MPD announces system playlist update Dec 13 18:49:55 volumiowork upmpdcli[1321]: :3:../src/mpdcli.cxx:148::MPDCli::startEventLoop: already started Dec 13 18:49:55 volumiowork volumio[1099]: info: Ignoring MPD Status Update Dec 13 18:49:55 volumiowork volumio[1099]: info: sendMpdCommand add "http://192.168.50.146:8200/MediaItems/17253.flac" took 4 milliseconds Dec 13 18:49:55 volumiowork volumio[1099]: verbose: ControllerMpd::sendMpdCommand consume 1 Dec 13 18:49:55 volumiowork volumio[1099]: info: Dec 13 18:49:55 volumiowork volumio[1099]: ---------------------------- MPD announces system playlist update Dec 13 18:49:55 volumiowork volumio[1099]: info: Ignoring MPD Status Update Dec 13 18:49:55 volumiowork volumio[1099]: info: Dec 13 18:49:55 volumiowork volumio[1099]: ---------------------------- MPD announces state update: options Dec 13 18:49:55 volumiowork volumio[1099]: info: ------------------------------ 7ms Dec 13 18:49:55 volumiowork volumio[1099]: info: sendMpdCommand consume 1 took 5 milliseconds Dec 13 18:49:55 volumiowork volumio[1099]: info: ControllerMpd::getState Dec 13 18:49:55 volumiowork volumio[1099]: verbose: ControllerMpd::sendMpdCommand status Dec 13 18:49:55 volumiowork volumio[1099]: info: ------------------------------ 4ms Dec 13 18:49:55 volumiowork volumio[1099]: info: Dec 13 18:49:55 volumiowork volumio[1099]: ---------------------------- MPD announces state update: options Dec 13 18:49:55 volumiowork volumio[1099]: info: ControllerMpd::getState Dec 13 18:49:55 volumiowork volumio[1099]: verbose: ControllerMpd::sendMpdCommand status Dec 13 18:49:55 volumiowork volumio[1099]: info: sendMpdCommand status took 3 milliseconds Dec 13 18:49:55 volumiowork volumio[1099]: info: sendMpdCommand status took 2 milliseconds Dec 13 18:49:55 volumiowork volumio[1099]: verbose: ControllerMpd::parseState Dec 13 18:49:55 volumiowork volumio[1099]: verbose: ControllerMpd::parseState Dec 13 18:49:55 volumiowork volumio[1099]: info: ControllerMpd::pushState Dec 13 18:49:55 volumiowork volumio[1099]: info: CoreCommandRouter::servicePushState Dec 13 18:49:55 volumiowork volumio[1099]: info: CoreStateMachine::pushState Dec 13 18:49:55 volumiowork volumio[1099]: info: CorePlayQueue::getTrack 9 Dec 13 18:49:55 volumiowork volumio[1099]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 13 18:49:55 volumiowork volumio[1099]: info: CoreCommandRouter::volumioPushState Dec 13 18:49:55 volumiowork volumio[1099]: info: CorePlayQueue::getTrack 9 Dec 13 18:49:55 volumiowork volumio[1099]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Dec 13 18:49:55 volumiowork volumio[1099]: verbose: CURRENT POSITION 9 Dec 13 18:49:55 volumiowork volumio[1099]: info: CoreStateMachine::syncState stateService stop Dec 13 18:49:55 volumiowork volumio[1099]: info: CoreStateMachine::syncState currentStatus play Dec 13 18:49:55 volumiowork volumio[1099]: info: CoreStateMachine::pushState Dec 13 18:49:55 volumiowork volumio[1099]: info: CorePlayQueue::getTrack 10 Dec 13 18:49:55 volumiowork volumio[1099]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 13 18:49:55 volumiowork volumio[1099]: info: CoreCommandRouter::volumioPushState Dec 13 18:49:55 volumiowork volumio[1099]: info: CoreStateMachine::pushState Dec 13 18:49:55 volumiowork volumio[1099]: info: CorePlayQueue::getTrack 10 Dec 13 18:49:55 volumiowork volumio[1099]: info: CoreCommandRouter::volumioPushState Dec 13 18:49:55 volumiowork volumio[1099]: info: ControllerMpd::pushState Dec 13 18:49:55 volumiowork volumio[1099]: info: CoreCommandRouter::servicePushState Dec 13 18:49:55 volumiowork volumio[1099]: info: CoreStateMachine::pushState Dec 13 18:49:55 volumiowork volumio[1099]: info: CorePlayQueue::getTrack 10 Dec 13 18:49:55 volumiowork volumio[1099]: info: CoreCommandRouter::volumioPushState Dec 13 18:49:55 volumiowork volumio[1099]: info: CorePlayQueue::getTrack 10 Dec 13 18:49:55 volumiowork volumio[1099]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Dec 13 18:49:55 volumiowork volumio[1099]: verbose: CURRENT POSITION 10 Dec 13 18:49:55 volumiowork volumio[1099]: info: CoreStateMachine::syncState stateService stop Dec 13 18:49:55 volumiowork volumio[1099]: info: CoreStateMachine::syncState currentStatus stop Dec 13 18:49:55 volumiowork volumio[1099]: info: CoreStateMachine::pushState Dec 13 18:49:55 volumiowork volumio[1099]: info: CorePlayQueue::getTrack 10 Dec 13 18:49:55 volumiowork volumio[1099]: info: CoreCommandRouter::volumioPushState Dec 13 18:49:55 volumiowork volumio[1099]: info: No code Dec 13 18:49:55 volumiowork volumio[1099]: info: CoreStateMachine::pushState Dec 13 18:49:55 volumiowork volumio[1099]: info: CorePlayQueue::getTrack 10 Dec 13 18:49:55 volumiowork volumio[1099]: info: CoreCommandRouter::volumioPushState Dec 13 18:49:55 volumiowork volumio[1099]: info: ------------------------------ 52ms Dec 13 18:49:55 volumiowork volumio[1099]: info: ------------------------------ 50ms Dec 13 18:49:55 volumiowork volumio[1099]: info: CoreCommandRouter::volumioGetQueue Dec 13 18:49:55 volumiowork volumio[1099]: info: CoreStateMachine::getQueue Dec 13 18:49:55 volumiowork volumio[1099]: info: CorePlayQueue::getQueue Dec 13 18:49:55 volumiowork volumio[1099]: info: PeppyMeterBasic ---peppymeterbasic status play Dec 13 18:49:55 volumiowork volumio[1099]: info: PeppyMeterBasic ---peppymeterbasic status stop Dec 13 18:49:55 volumiowork volumio[1099]: info: PeppyMeterBasic ---peppymeterbasic status stop Dec 13 18:49:55 volumiowork volumio[1099]: info: PeppyMeterBasic ---peppymeterbasic status stop Dec 13 18:49:55 volumiowork volumio[1099]: info: PeppyMeterBasic ---peppymeterbasic status stop Dec 13 18:49:55 volumiowork volumio[1099]: info: PeppyMeterBasic ---peppymeterbasic status stop Dec 13 18:49:55 volumiowork volumio[1099]: SPOTIFY: RECEIVED VOLUMIO VOLUME 36 Dec 13 18:49:55 volumiowork volumio[1099]: SPOTIFY: RECEIVED VOLUMIO VOLUME 36 Dec 13 18:49:55 volumiowork volumio[1099]: SPOTIFY: RECEIVED VOLUMIO VOLUME 36 Dec 13 18:49:55 volumiowork volumio[1099]: SPOTIFY: RECEIVED VOLUMIO VOLUME 36 Dec 13 18:49:55 volumiowork volumio[1099]: SPOTIFY: RECEIVED VOLUMIO VOLUME 36 Dec 13 18:49:55 volumiowork volumio[1099]: SPOTIFY: RECEIVED VOLUMIO VOLUME 36 Dec 13 18:49:55 volumiowork sudo[17314]: volumio : unable to resolve host volumiowork: System error Dec 13 18:49:55 volumiowork sudo[17316]: volumio : unable to resolve host volumiowork: System error Dec 13 18:49:55 volumiowork sudo[17314]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppymeterbasic.service Dec 13 18:49:55 volumiowork sudo[17316]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop peppymeterbasic.service Dec 13 18:49:55 volumiowork sudo[17322]: volumio : unable to resolve host volumiowork: System error Dec 13 18:49:55 volumiowork sudo[17314]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 13 18:49:55 volumiowork sudo[17316]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 13 18:49:55 volumiowork sudo[17320]: volumio : unable to resolve host volumiowork: System error Dec 13 18:49:55 volumiowork sudo[17318]: volumio : unable to resolve host volumiowork: System error Dec 13 18:49:55 volumiowork sudo[17322]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop peppymeterbasic.service Dec 13 18:49:55 volumiowork sudo[17322]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 13 18:49:55 volumiowork sudo[17320]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop peppymeterbasic.service Dec 13 18:49:55 volumiowork sudo[17320]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 13 18:49:55 volumiowork sudo[17318]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop peppymeterbasic.service Dec 13 18:49:55 volumiowork sudo[17318]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 13 18:49:55 volumiowork sudo[17324]: volumio : unable to resolve host volumiowork: System error Dec 13 18:49:55 volumiowork sudo[17324]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop peppymeterbasic.service Dec 13 18:49:55 volumiowork sudo[17324]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 13 18:49:55 volumiowork sudo[17322]: pam_unix(sudo:session): session closed for user root Dec 13 18:49:55 volumiowork sudo[17316]: pam_unix(sudo:session): session closed for user root Dec 13 18:49:55 volumiowork sudo[17314]: pam_unix(sudo:session): session closed for user root Dec 13 18:49:55 volumiowork volumio[1099]: info: PeppyMeterBasic ---peppymeterbasic failed to stop!! Error: Command failed: /usr/bin/sudo /bin/systemctl stop peppymeterbasic.service Dec 13 18:49:55 volumiowork volumio[1099]: sudo: unable to resolve host volumiowork: System error Dec 13 18:49:55 volumiowork volumio[1099]: Job for peppymeterbasic.service canceled. Dec 13 18:49:55 volumiowork volumio[1099]: info: PeppyMeterBasic ---peppymeterbasic failed to stop!! Error: Command failed: /usr/bin/sudo /bin/systemctl stop peppymeterbasic.service Dec 13 18:49:55 volumiowork volumio[1099]: sudo: unable to resolve host volumiowork: System error Dec 13 18:49:55 volumiowork volumio[1099]: Job for peppymeterbasic.service canceled. Dec 13 18:49:55 volumiowork volumio[1099]: info: PeppyMeterBasic ---peppymeterbasic failed to start. Check your configuration Error: Command failed: /usr/bin/sudo /bin/systemctl start peppymeterbasic.service Dec 13 18:49:55 volumiowork volumio[1099]: sudo: unable to resolve host volumiowork: System error Dec 13 18:49:55 volumiowork volumio[1099]: Job for peppymeterbasic.service canceled. Dec 13 18:49:56 volumiowork sudo[17318]: pam_unix(sudo:session): session closed for user root Dec 13 18:49:56 volumiowork volumio[1099]: info: peppymeterbasic Daemon Stop Dec 13 18:49:56 volumiowork sudo[17320]: pam_unix(sudo:session): session closed for user root Dec 13 18:49:56 volumiowork sudo[17324]: pam_unix(sudo:session): session closed for user root Dec 13 18:49:56 volumiowork volumio[1099]: info: peppymeterbasic Daemon Stop Dec 13 18:49:56 volumiowork volumio[1099]: info: peppymeterbasic Daemon Stop Dec 13 18:49:57 volumiowork volumio[1099]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Dec 13 18:49:57 volumiowork volumio[1099]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Dec 13 18:49:57 volumiowork volumio[1099]: info: Creating Spotify config file Dec 13 18:49:57 volumiowork volumio[1099]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 13 18:49:57 volumiowork volumio[1099]: info: Spotify config file written Dec 13 18:49:57 volumiowork sudo[17333]: volumio : unable to resolve host volumiowork: System error Dec 13 18:49:57 volumiowork sudo[17333]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 13 18:49:57 volumiowork sudo[17333]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 13 18:49:57 volumiowork systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 13 18:49:57 volumiowork systemd[1]: go-librespot-daemon.service: Killing process 17286 (go-librespot) with signal SIGKILL. Dec 13 18:49:57 volumiowork systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 13 18:49:57 volumiowork systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 13 18:49:57 volumiowork volumio[1099]: info: Connection to go-librespot Websocket closed Dec 13 18:49:57 volumiowork volumio[1099]: info: Connection to go-librespot Websocket closed Dec 13 18:49:57 volumiowork systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 13 18:49:57 volumiowork go-librespot[17348]: go-librespot daemon starting... Dec 13 18:49:57 volumiowork sudo[17333]: pam_unix(sudo:session): session closed for user root Dec 13 18:49:57 volumiowork go-librespot[17350]: time="2025-12-13T18:49:57+01:00" level=info msg="running go-librespot 0.4.0" Dec 13 18:49:57 volumiowork go-librespot[17350]: time="2025-12-13T18:49:57+01:00" level=debug msg="app state loaded" Dec 13 18:49:57 volumiowork go-librespot[17350]: time="2025-12-13T18:49:57+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 13 18:49:57 volumiowork go-librespot[17350]: time="2025-12-13T18:49:57+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Dec 13 18:49:57 volumiowork go-librespot[17350]: time="2025-12-13T18:49:57+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Dec 13 18:49:57 volumiowork go-librespot[17350]: time="2025-12-13T18:49:57+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Dec 13 18:49:57 volumiowork go-librespot[17350]: time="2025-12-13T18:49:57+01:00" level=info msg="zeroconf server listening on port 33129" Dec 13 18:49:57 volumiowork go-librespot[17350]: time="2025-12-13T18:49:57+01:00" level=debug msg="obtained new client token: AAA0WcSJ7C7fWNqoX3F+7tINju90hQNXYF+/K5zx/TAHVYj47PX78+aZ9GFHax3McDgF44sC0J7Fddw2MHA5mDLWC35fGK4Il7hW9uGK1/CwxunziyhTP+lbnjGSmhGevQ270Hc+/utTnx/7SZ9D5bB0moF6Z7KoTGnJ2CsKkLqq6yW0ml3cEVxgKy+8RueHkMkPyoQDyLX00kcyPGBeYRCbjLA5LKhoEE+H9NqoYBxu+c4yMy78GgJNYQ==" Dec 13 18:49:57 volumiowork go-librespot[17350]: time="2025-12-13T18:49:57+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 13 18:49:59 volumiowork go-librespot[17350]: time="2025-12-13T18:49:59+01:00" level=debug msg="completed keyexchange" Dec 13 18:49:59 volumiowork go-librespot[17350]: time="2025-12-13T18:49:59+01:00" level=debug msg="completed challenge" Dec 13 18:49:59 volumiowork go-librespot[17350]: time="2025-12-13T18:49:59+01:00" level=info msg="authenticated AP" username="te*dn" Dec 13 18:49:59 volumiowork go-librespot[17350]: time="2025-12-13T18:49:59+01:00" level=info msg="authenticated Login5" username="te*dn" Dec 13 18:49:59 volumiowork go-librespot[17350]: time="2025-12-13T18:49:59+01:00" level=debug msg="initializing zeroconf session" username="te*dn" Dec 13 18:49:59 volumiowork go-librespot[17350]: time="2025-12-13T18:49:59+01:00" level=debug msg="dealer connection opened" Dec 13 18:49:59 volumiowork go-librespot[17350]: time="2025-12-13T18:49:59+01:00" level=trace msg="starting accesspoint recv loop" Dec 13 18:49:59 volumiowork go-librespot[17350]: time="2025-12-13T18:49:59+01:00" level=trace msg="starting dealer recv loop" Dec 13 18:49:59 volumiowork go-librespot[17350]: time="2025-12-13T18:49:59+01:00" level=trace msg="received accesspoint ping" Dec 13 18:49:59 volumiowork go-librespot[17350]: time="2025-12-13T18:49:59+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Dec 13 18:49:59 volumiowork go-librespot[17350]: time="2025-12-13T18:49:59+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Dec 13 18:49:59 volumiowork go-librespot[17350]: time="2025-12-13T18:49:59+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Dec 13 18:49:59 volumiowork go-librespot[17350]: time="2025-12-13T18:49:59+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Dec 13 18:49:59 volumiowork go-librespot[17350]: time="2025-12-13T18:49:59+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Dec 13 18:49:59 volumiowork go-librespot[17350]: time="2025-12-13T18:49:59+01:00" level=debug msg="received connection id: ZjYxNDg5YTUtZTJj...QTU0QTM0OUExMQ==" Dec 13 18:49:59 volumiowork go-librespot[17350]: time="2025-12-13T18:49:59+01:00" level=trace msg="received accesspoint pong ack" Dec 13 18:50:00 volumiowork go-librespot[17350]: time="2025-12-13T18:50:00+01:00" level=debug msg="put connect state because NEW_DEVICE" Dec 13 18:50:00 volumiowork volumio[1099]: info: Initializing connection to go-librespot Websocket Dec 13 18:50:00 volumiowork go-librespot[17350]: time="2025-12-13T18:50:00+01:00" level=debug msg="new websocket client" Dec 13 18:50:00 volumiowork volumio[1099]: info: Connection to go-librespot Websocket established Dec 13 18:50:00 volumiowork volumio[1099]: info: go-librespot daemon successfully initialized Dec 13 18:50:00 volumiowork volumio[1099]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Dec 13 18:50:00 volumiowork volumio[1099]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Dec 13 18:50:00 volumiowork volumio[1099]: info: Creating Spotify config file Dec 13 18:50:00 volumiowork volumio[1099]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 13 18:50:00 volumiowork volumio[1099]: info: Spotify config file written Dec 13 18:50:00 volumiowork sudo[17360]: volumio : unable to resolve host volumiowork: System error Dec 13 18:50:00 volumiowork sudo[17360]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 13 18:50:00 volumiowork sudo[17360]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 13 18:50:00 volumiowork systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 13 18:50:00 volumiowork systemd[1]: go-librespot-daemon.service: Killing process 17357 (go-librespot) with signal SIGKILL. Dec 13 18:50:00 volumiowork systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 13 18:50:00 volumiowork volumio[1099]: info: Connection to go-librespot Websocket closed Dec 13 18:50:00 volumiowork systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 13 18:50:00 volumiowork systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 13 18:50:00 volumiowork go-librespot[17362]: go-librespot daemon starting... Dec 13 18:50:00 volumiowork sudo[17360]: pam_unix(sudo:session): session closed for user root Dec 13 18:50:00 volumiowork go-librespot[17363]: time="2025-12-13T18:50:00+01:00" level=info msg="running go-librespot 0.4.0" Dec 13 18:50:00 volumiowork go-librespot[17363]: time="2025-12-13T18:50:00+01:00" level=debug msg="app state loaded" Dec 13 18:50:00 volumiowork go-librespot[17363]: time="2025-12-13T18:50:00+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 13 18:50:00 volumiowork go-librespot[17363]: time="2025-12-13T18:50:00+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Dec 13 18:50:00 volumiowork go-librespot[17363]: time="2025-12-13T18:50:00+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 13 18:50:00 volumiowork go-librespot[17363]: time="2025-12-13T18:50:00+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 13 18:50:00 volumiowork go-librespot[17363]: time="2025-12-13T18:50:00+01:00" level=info msg="zeroconf server listening on port 45853" Dec 13 18:50:01 volumiowork go-librespot[17363]: time="2025-12-13T18:50:01+01:00" level=debug msg="obtained new client token: AAAfP5iwZxBRkGe0E6t0qEdkksnyWD5wvEPAjLWTrWi8LD2Tn983+KUytbrfOL2eEJp/wXZIbNXdqH3BPJyeD49RSyr4MevlvhCbIcSXBkVQeaA6feZonD9nPCG/4YIcn5fkoZqCVr4irnuiA7qp5ZzWnALFP33qPcXP1hTM6++dVQJysl4bds+Zm3phopDlQR+4oWTNffD/9G6lcXoGgVnvcWRy5PHiphGd/6iwBSSs37sovdbaGB4=" Dec 13 18:50:01 volumiowork go-librespot[17363]: time="2025-12-13T18:50:01+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 13 18:50:01 volumiowork go-librespot[17363]: time="2025-12-13T18:50:01+01:00" 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" Dec 13 18:50:01 volumiowork systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 13 18:50:01 volumiowork systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 13 18:50:03 volumiowork volumio[1099]: info: Getting Spotify volume Dec 13 18:50:03 volumiowork volumio[1099]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 13 18:50:03 volumiowork volumio[1099]: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 13 18:50:03 volumiowork volumio[1099]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Dec 13 18:50:03 volumiowork volumio[1099]: errno: -111, Dec 13 18:50:03 volumiowork volumio[1099]: code: 'ECONNREFUSED', Dec 13 18:50:03 volumiowork volumio[1099]: syscall: 'connect', Dec 13 18:50:03 volumiowork volumio[1099]: address: '127.0.0.1', Dec 13 18:50:03 volumiowork volumio[1099]: port: 9879, Dec 13 18:50:03 volumiowork volumio[1099]: response: undefined Dec 13 18:50:03 volumiowork volumio[1099]: } Dec 13 18:50:03 volumiowork volumio[1099]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 13 18:50:04 volumiowork systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Dec 13 18:50:04 volumiowork systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 13 18:50:04 volumiowork systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 13 18:50:04 volumiowork go-librespot[17384]: go-librespot daemon starting... Dec 13 18:50:04 volumiowork go-librespot[17385]: time="2025-12-13T18:50:04+01:00" level=info msg="running go-librespot 0.4.0" Dec 13 18:50:04 volumiowork go-librespot[17385]: time="2025-12-13T18:50:04+01:00" level=debug msg="app state loaded" Dec 13 18:50:04 volumiowork go-librespot[17385]: time="2025-12-13T18:50:04+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 13 18:50:05 volumiowork go-librespot[17385]: time="2025-12-13T18:50:05+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Dec 13 18:50:05 volumiowork go-librespot[17385]: time="2025-12-13T18:50:05+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Dec 13 18:50:05 volumiowork go-librespot[17385]: time="2025-12-13T18:50:05+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Dec 13 18:50:05 volumiowork go-librespot[17385]: time="2025-12-13T18:50:05+01:00" level=info msg="zeroconf server listening on port 39337" Dec 13 18:50:05 volumiowork go-librespot[17385]: time="2025-12-13T18:50:05+01:00" level=debug msg="obtained new client token: AADGCsPM2Feaj6xb64cHVMrl/JLcysL+OdJ9hyJfLmeDYERbO4d4SuVmebIxiUlJFwwV9cmQUxSuCQ713eAxhyLr/cb79BnZ1b1EBZV3ICB4YJfP9ct7M0V9U5Gbyj+SyuGv0QJCql4yy+aJUirZ1wKQ7b4IpG+ZH5xcidcsmXukP2pqF4otVQRQFFneHlBDyzkWYSHtWJXTWwwxM0FlLgCIRt2WP5Gw4Redw0J6WaLQC1bnOjZFNbs=" Dec 13 18:50:05 volumiowork go-librespot[17385]: time="2025-12-13T18:50:05+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 13 18:50:05 volumiowork go-librespot[17385]: time="2025-12-13T18:50:05+01:00" level=debug msg="completed keyexchange" Dec 13 18:50:05 volumiowork go-librespot[17385]: time="2025-12-13T18:50:05+01:00" level=debug msg="completed challenge" Dec 13 18:50:05 volumiowork go-librespot[17385]: time="2025-12-13T18:50:05+01:00" level=info msg="authenticated AP" username="te*dn" Dec 13 18:50:05 volumiowork sudo[17395]: volumio : unable to resolve host volumiowork: System error Dec 13 18:50:05 volumiowork sudo[17395]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-13 18:49' Dec 13 18:50:05 volumiowork sudo[17395]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 13 18:50:05 volumiowork go-librespot[17385]: time="2025-12-13T18:50:05+01:00" level=info msg="authenticated Login5" username="te*dn" Dec 13 18:50:05 volumiowork go-librespot[17385]: time="2025-12-13T18:50:05+01:00" level=debug msg="initializing zeroconf session" username="te*dn" 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"