Dec 26 14:12:00 paulin systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 26 14:12:00 paulin go-librespot[2640]: go-librespot daemon starting...
Dec 26 14:12:00 paulin go-librespot[2641]: time="2025-12-26T14:12:00-03:00" level=info msg="running go-librespot 0.4.0"
Dec 26 14:12:00 paulin go-librespot[2641]: time="2025-12-26T14:12:00-03:00" level=debug msg="app state loaded"
Dec 26 14:12:00 paulin go-librespot[2641]: time="2025-12-26T14:12:00-03:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 26 14:12:00 paulin go-librespot[2641]: time="2025-12-26T14:12:00-03:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 26 14:12:00 paulin go-librespot[2641]: time="2025-12-26T14:12:00-03:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 26 14:12:00 paulin go-librespot[2641]: time="2025-12-26T14:12:00-03:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 26 14:12:00 paulin go-librespot[2641]: time="2025-12-26T14:12:00-03:00" level=info msg="zeroconf server listening on port 42167"
Dec 26 14:12:00 paulin go-librespot[2641]: time="2025-12-26T14:12:00-03:00" level=debug msg="obtained new client token: AAAhuM7XIb812F2ZUzRAuqQHBisDf3oJhcqpICcFo1pYrf54oV33f5k6pB7tVSt31PqX3lze6jQg2VBK7TQTp93RuFdzV4c1I3KOoYbcYNo6Ca0D//AhkXxKRY0rGUqR2Eow8wAI4blLs2jJ+nMCWVhV6XVk8nOZEbEf8WolVSpKwK0xmCpRS7BFxQUB+Ecu4Eu7OigiIG8ifRHqdtDRR5hYHSZLgWxz4h73mHR41evkCsVC4y/SOS9ZHtI="
Dec 26 14:12:00 paulin go-librespot[2641]: time="2025-12-26T14:12:00-03:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 26 14:12:01 paulin go-librespot[2641]: time="2025-12-26T14:12:01-03:00" level=debug msg="completed keyexchange"
Dec 26 14:12:01 paulin go-librespot[2641]: time="2025-12-26T14:12:01-03:00" level=debug msg="completed challenge"
Dec 26 14:12:01 paulin go-librespot[2641]: time="2025-12-26T14:12:01-03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials "
Dec 26 14:12:01 paulin systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 26 14:12:01 paulin systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 26 14:12:01 paulin volumio[2248]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded
Dec 26 14:12:01 paulin volumio[2248]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services
Dec 26 14:12:01 paulin volumio[2248]: info: Streaming services startup
Dec 26 14:12:01 paulin volumio[2248]: info: Starting Streaming Daemon
Dec 26 14:12:01 paulin volumio[2248]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started
Dec 26 14:12:01 paulin sudo[2649]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service
Dec 26 14:12:01 paulin sudo[2649]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 26 14:12:01 paulin sudo[2649]: pam_unix(sudo:session): session closed for user root
Dec 26 14:12:01 paulin volumio[2248]: info: Initializing connection to go-librespot Websocket
Dec 26 14:12:02 paulin volumio[2248]: error: Cannot start Volumio Streaming Daemon
Dec 26 14:12:02 paulin volumio[2248]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service
Dec 26 14:12:02 paulin volumio[2248]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found.
Dec 26 14:12:02 paulin volumio[2248]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 26 14:12:02 paulin volumio[2248]: verbose: New Socket.io Connection to 192.168.10.8 from 192.168.10.11 UA: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/143.0.0.0 Safari/537.36 Edg/143.0.0.0 Engine version: 3 Transport: polling Total Clients: 3
Dec 26 14:12:02 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled
Dec 26 14:12:03 paulin volumio[2248]: info: CoreCommandRouter::volumioGetVisibleSources
Dec 26 14:12:03 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 26 14:12:03 paulin volumio[2248]: info: CoreCommandRouter::volumioGetState
Dec 26 14:12:03 paulin volumio[2248]: info: CorePlayQueue::getTrack 0
Dec 26 14:12:03 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback
Dec 26 14:12:03 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom
Dec 26 14:12:03 paulin volumio[2248]: info: Received Get System Info
Dec 26 14:12:03 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo
Dec 26 14:12:03 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice
Dec 26 14:12:03 paulin volumio[2248]: info: Discovery: Getting this device information
Dec 26 14:12:03 paulin volumio[2248]: info: CoreCommandRouter::volumioGetState
Dec 26 14:12:03 paulin volumio[2248]: info: CorePlayQueue::getTrack 0
Dec 26 14:12:03 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses
Dec 26 14:12:03 paulin volumio[2248]: info: CoreCommandRouter::volumioGetState
Dec 26 14:12:03 paulin volumio[2248]: info: CorePlayQueue::getTrack 0
Dec 26 14:12:03 paulin volumio[2248]: info: Listing playlists
Dec 26 14:12:03 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings
Dec 26 14:12:03 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings
Dec 26 14:12:03 paulin volumio[2248]: error: MyVolumio Custom Token format not valid, refreshing it
Dec 26 14:12:04 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache
Dec 26 14:12:04 paulin systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5.
Dec 26 14:12:04 paulin systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 26 14:12:04 paulin systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 26 14:12:04 paulin go-librespot[2655]: go-librespot daemon starting...
Dec 26 14:12:04 paulin go-librespot[2656]: time="2025-12-26T14:12:04-03:00" level=info msg="running go-librespot 0.4.0"
Dec 26 14:12:04 paulin go-librespot[2656]: time="2025-12-26T14:12:04-03:00" level=debug msg="app state loaded"
Dec 26 14:12:04 paulin go-librespot[2656]: time="2025-12-26T14:12:04-03:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 26 14:12:05 paulin go-librespot[2656]: time="2025-12-26T14:12:05-03:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 26 14:12:05 paulin go-librespot[2656]: time="2025-12-26T14:12:05-03:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 26 14:12:05 paulin go-librespot[2656]: time="2025-12-26T14:12:05-03:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 26 14:12:05 paulin go-librespot[2656]: time="2025-12-26T14:12:05-03:00" level=info msg="zeroconf server listening on port 36269"
Dec 26 14:12:05 paulin go-librespot[2656]: time="2025-12-26T14:12:05-03:00" level=debug msg="obtained new client token: AAD7XDOVFkHOGvqgFKnyQgn1O1WAQ7xF7oTLRUfmm+tO8oX3SGUU5LAJhfDZ5y1sJEw/RhZImQrrM1yzZHmmJqNtHT15ivIN2XDOk0kd18n/m1gii/EnNhKZhhnhqe3JZKGxQGIB30BsJ06KSCzroxacD4Eux8h/3oq1BrLWcEKYbUpMEjPbxWI/+7m0LaknhhNcVLJbPYa1iqDud9/O1hj16Mx+AyOxhwDqypW09bWZGs/gqEsDKP6M"
Dec 26 14:12:05 paulin sudo[2684]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
Dec 26 14:12:05 paulin sudo[2682]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0
Dec 26 14:12:05 paulin sudo[2682]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 26 14:12:05 paulin sudo[2684]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 26 14:12:05 paulin go-librespot[2656]: time="2025-12-26T14:12:05-03:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 26 14:12:05 paulin sudo[2684]: pam_unix(sudo:session): session closed for user root
Dec 26 14:12:05 paulin sudo[2682]: pam_unix(sudo:session): session closed for user root
Dec 26 14:12:05 paulin volumio[2248]: info: Initializing connection to go-librespot Websocket
Dec 26 14:12:05 paulin go-librespot[2656]: time="2025-12-26T14:12:05-03:00" level=debug msg="completed keyexchange"
Dec 26 14:12:05 paulin go-librespot[2656]: time="2025-12-26T14:12:05-03:00" level=debug msg="completed challenge"
Dec 26 14:12:05 paulin volumio[2248]: verbose: New Socket.io Connection to 192.168.10.8 from 192.168.10.11 UA: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/143.0.0.0 Safari/537.36 Edg/143.0.0.0 Engine version: 3 Transport: polling Total Clients: 4
Dec 26 14:12:05 paulin go-librespot[2656]: time="2025-12-26T14:12:05-03:00" level=debug msg="new websocket client"
Dec 26 14:12:05 paulin go-librespot[2656]: time="2025-12-26T14:12:05-03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials "
Dec 26 14:12:05 paulin systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 26 14:12:05 paulin systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 26 14:12:05 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled
Dec 26 14:12:05 paulin volumio[2248]: info: Connection to go-librespot Websocket established
Dec 26 14:12:05 paulin volumio[2248]: info: CoreCommandRouter::volumioGetVisibleSources
Dec 26 14:12:05 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 26 14:12:05 paulin volumio[2248]: info: CoreCommandRouter::volumioGetState
Dec 26 14:12:05 paulin volumio[2248]: info: CorePlayQueue::getTrack 0
Dec 26 14:12:05 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback
Dec 26 14:12:05 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom
Dec 26 14:12:05 paulin volumio[2248]: info: Received Get System Info
Dec 26 14:12:05 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo
Dec 26 14:12:05 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice
Dec 26 14:12:05 paulin volumio[2248]: info: Discovery: Getting this device information
Dec 26 14:12:06 paulin volumio[2248]: info: CoreCommandRouter::volumioGetState
Dec 26 14:12:06 paulin volumio[2248]: info: CorePlayQueue::getTrack 0
Dec 26 14:12:06 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses
Dec 26 14:12:06 paulin volumio[2248]: info: CoreCommandRouter::volumioGetState
Dec 26 14:12:06 paulin volumio[2248]: info: CorePlayQueue::getTrack 0
Dec 26 14:12:06 paulin volumio[2248]: info: Listing playlists
Dec 26 14:12:06 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings
Dec 26 14:12:06 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings
Dec 26 14:12:06 paulin volumio[2248]: info: Connection to go-librespot Websocket closed
Dec 26 14:12:06 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache
Dec 26 14:12:06 paulin volumio[2248]: info: MyVolumio login type: Token
Dec 26 14:12:06 paulin volumio[2248]: info: CoreCommandRouter::volumioGetState
Dec 26 14:12:06 paulin volumio[2248]: info: CorePlayQueue::getTrack 0
Dec 26 14:12:06 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus
Dec 26 14:12:06 paulin volumio[2248]: info: Received Get System Info
Dec 26 14:12:06 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo
Dec 26 14:12:06 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice
Dec 26 14:12:06 paulin volumio[2248]: info: Discovery: Getting this device information
Dec 26 14:12:06 paulin volumio[2248]: info: CoreCommandRouter::volumioGetState
Dec 26 14:12:06 paulin volumio[2248]: info: CorePlayQueue::getTrack 0
Dec 26 14:12:06 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses
Dec 26 14:12:08 paulin volumio[2248]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN
Dec 26 14:12:08 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard
Dec 26 14:12:08 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Dec 26 14:12:08 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 26 14:12:08 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled
Dec 26 14:12:08 paulin systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6.
Dec 26 14:12:08 paulin systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 26 14:12:09 paulin systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 26 14:12:09 paulin go-librespot[2691]: go-librespot daemon starting...
Dec 26 14:12:09 paulin go-librespot[2692]: time="2025-12-26T14:12:09-03:00" level=info msg="running go-librespot 0.4.0"
Dec 26 14:12:09 paulin go-librespot[2692]: time="2025-12-26T14:12:09-03:00" level=debug msg="app state loaded"
Dec 26 14:12:09 paulin go-librespot[2692]: time="2025-12-26T14:12:09-03:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 26 14:12:09 paulin volumio[2248]: info: Getting Spotify volume
Dec 26 14:12:09 paulin volumio-remote-updater[657]: Test mode disabled
Dec 26 14:12:09 paulin volumio-remote-updater[657]: Alpha mode disabled
Dec 26 14:12:09 paulin volumio-remote-updater[657]: Alpha legacy test mode disabled
Dec 26 14:12:09 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled
Dec 26 14:12:09 paulin volumio[2248]: info: Initializing connection to go-librespot Websocket
Dec 26 14:12:09 paulin go-librespot[2692]: time="2025-12-26T14:12:09-03:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 26 14:12:09 paulin go-librespot[2692]: time="2025-12-26T14:12:09-03:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 26 14:12:09 paulin go-librespot[2692]: time="2025-12-26T14:12:09-03:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 26 14:12:09 paulin go-librespot[2692]: time="2025-12-26T14:12:09-03:00" level=info msg="zeroconf server listening on port 38585"
Dec 26 14:12:09 paulin go-librespot[2692]: time="2025-12-26T14:12:09-03:00" level=debug msg="obtained new client token: AAADcO/wGc8rNKs1ssLEBADXECItRtPVGSVNsvMiXxGizcaUKVp0EjC6uqM4bnU1f8jtdrl9z4mUFHYe2IjRSCVUzyICvMpjHLzXkPxkRsMuBCMwl2lsZKcStUd6jcyZonk+exjnPD0W4dwh5IyKrCfCyRGbBylKMTQKK7/dD7FiTkQcbRf1HBCI44jthgRkRgoT+R/+9Eb5WXaKOHlAb2WZJB1dJT98dUvar4hNuRRT0O/iuOUpgfTh4NY="
Dec 26 14:12:09 paulin volumio[2248]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5
Dec 26 14:12:09 paulin go-librespot[2692]: time="2025-12-26T14:12:09-03:00" level=debug msg="new websocket client"
Dec 26 14:12:09 paulin go-librespot[2692]: time="2025-12-26T14:12:09-03:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 26 14:12:09 paulin volumio[2248]: info: MyVolumio token set successfully
Dec 26 14:12:09 paulin volumio[2248]: info: MYVOLUMIO: Adding device
Dec 26 14:12:09 paulin volumio[2248]: info: MYVOLUMIO: Evaluating Server
Dec 26 14:12:10 paulin go-librespot[2692]: time="2025-12-26T14:12:10-03:00" level=debug msg="completed keyexchange"
Dec 26 14:12:10 paulin go-librespot[2692]: time="2025-12-26T14:12:10-03:00" level=debug msg="completed challenge"
Dec 26 14:12:10 paulin volumio[2248]: info: Connection to go-librespot Websocket established
Dec 26 14:12:10 paulin volumio[2248]: info: Update Ready: {"changeLogLink":"http://volumio.org","description":"ANNOUNCEMENT
\n\n- Production line
\n
\nFIX
\n\n- Nodejs 20.5.1 version pinning with static package fallback
\n
\n","title":"Update v4.073","updateavailable":true}
Dec 26 14:12:10 paulin go-librespot[2692]: time="2025-12-26T14:12:10-03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials "
Dec 26 14:12:10 paulin systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 26 14:12:10 paulin systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 26 14:12:10 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache
Dec 26 14:12:11 paulin volumio[2248]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings
Dec 26 14:12:11 paulin volumio[2248]: |||||||||||||||||||||||| WARNING: FATAL ERROR |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Dec 26 14:12:11 paulin volumio[2248]: Error: socket hang up
Dec 26 14:12:11 paulin volumio[2248]: at connResetException (node:internal/errors:720:14)
Dec 26 14:12:11 paulin volumio[2248]: at Socket.socketOnEnd (node:_http_client:519:23)
Dec 26 14:12:11 paulin volumio[2248]: at Socket.emit (node:events:526:35)
Dec 26 14:12:11 paulin volumio[2248]: at endReadableNT (node:internal/streams/readable:1376:12)
Dec 26 14:12:11 paulin volumio[2248]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) {
Dec 26 14:12:11 paulin volumio[2248]: code: 'ECONNRESET',
Dec 26 14:12:11 paulin volumio[2248]: response: undefined
Dec 26 14:12:11 paulin volumio[2248]: }
Dec 26 14:12:11 paulin volumio[2248]: |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Dec 26 14:12:13 paulin systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7.
Dec 26 14:12:13 paulin systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 26 14:12:13 paulin systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 26 14:12:13 paulin go-librespot[2738]: go-librespot daemon starting...
Dec 26 14:12:13 paulin go-librespot[2739]: time="2025-12-26T14:12:13-03:00" level=info msg="running go-librespot 0.4.0"
Dec 26 14:12:13 paulin go-librespot[2739]: time="2025-12-26T14:12:13-03:00" level=debug msg="app state loaded"
Dec 26 14:12:13 paulin go-librespot[2739]: time="2025-12-26T14:12:13-03:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 26 14:12:13 paulin go-librespot[2739]: time="2025-12-26T14:12:13-03:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 26 14:12:13 paulin go-librespot[2739]: time="2025-12-26T14:12:13-03:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 26 14:12:13 paulin go-librespot[2739]: time="2025-12-26T14:12:13-03:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 26 14:12:13 paulin go-librespot[2739]: time="2025-12-26T14:12:13-03:00" level=info msg="zeroconf server listening on port 35331"
Dec 26 14:12:14 paulin go-librespot[2739]: time="2025-12-26T14:12:14-03:00" level=debug msg="obtained new client token: AABOEMb/Ob2TBAd0PXO5zuQQoVOEvChSblCWQJPkxT85GBKsBIZoIsXbSX/n4O+JvK1POZ2WCbP/Or1flCUlRzfKRSrtAPoOhW7BsI3pxJ+dhQyo4EBrBmvD1HRnHe6YAl93Swc+l/6EebwdAc8w5+htJhsXjwCcHZ2EKpvyKPF3K8sI4Jr1m9Jd4R3BtJfmNvm7GnQTthf9H/rUkWK6W6wCCs/lcuQep43iHonXI6jImpagLUe1K+Pn"
Dec 26 14:12:14 paulin go-librespot[2739]: time="2025-12-26T14:12:14-03:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 26 14:12:14 paulin go-librespot[2739]: time="2025-12-26T14:12:14-03:00" level=debug msg="completed keyexchange"
Dec 26 14:12:14 paulin go-librespot[2739]: time="2025-12-26T14:12:14-03:00" level=debug msg="completed challenge"
Dec 26 14:12:14 paulin go-librespot[2739]: time="2025-12-26T14:12:14-03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials "
Dec 26 14:12:14 paulin systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 26 14:12:14 paulin systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 26 14:12:17 paulin sudo[2763]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-26 14:11'
Dec 26 14:12:17 paulin sudo[2763]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 26 14:12:17 paulin systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8.
Dec 26 14:12:17 paulin systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 26 14:12:17 paulin sudo[2763]: pam_unix(sudo:session): session closed for user root
Dec 26 14:12:18 paulin systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 26 14:12:18 paulin go-librespot[2765]: go-librespot daemon starting...
Dec 26 14:12:18 paulin go-librespot[2766]: time="2025-12-26T14:12:18-03:00" level=info msg="running go-librespot 0.4.0"
Dec 26 14:12:18 paulin go-librespot[2766]: time="2025-12-26T14:12:18-03:00" level=debug msg="app state loaded"
Dec 26 14:12:18 paulin go-librespot[2766]: time="2025-12-26T14:12:18-03:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 26 14:12:18 paulin go-librespot[2766]: time="2025-12-26T14:12:18-03:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 26 14:12:18 paulin go-librespot[2766]: time="2025-12-26T14:12:18-03:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 26 14:12:18 paulin go-librespot[2766]: time="2025-12-26T14:12:18-03:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 26 14:12:18 paulin go-librespot[2766]: time="2025-12-26T14:12:18-03:00" level=info msg="zeroconf server listening on port 46081"
Dec 26 14:12:18 paulin go-librespot[2766]: time="2025-12-26T14:12:18-03:00" level=debug msg="obtained new client token: AABukWksv18gOdxDI10P4Kxnu1hnd7CK1yTi4ZjD1KXmEsaelYA11AH2+jH5pki52wDWaKKvOXd2M1evniLWK5Evihvm8/EO8KQtJTIshk1k+kmZLBBOwx1aODBKLy6tREAhfPIJoTmF05Th6oYsBwsZ2DqyRH+iqFueyk/R3EJ71jo8/MwWbELp+nu3naisqz7BaN5QSVHcWdr0gb/kWGftz25N8F7tvVWL/rzYAOJWEG2GJCrHFS8kbXc="
Dec 26 14:12:18 paulin go-librespot[2766]: time="2025-12-26T14:12:18-03:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 26 14:12:19 paulin go-librespot[2766]: time="2025-12-26T14:12:19-03:00" level=debug msg="completed keyexchange"
Dec 26 14:12:19 paulin go-librespot[2766]: time="2025-12-26T14:12:19-03:00" level=debug msg="completed challenge"
Dec 26 14:12:19 paulin go-librespot[2766]: time="2025-12-26T14:12:19-03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials "
Dec 26 14:12:19 paulin systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 26 14:12:19 paulin systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 26 14:12:20 paulin volumio-remote-updater[657]: [2025-12-26 14:12:20] [error] handle_read_frame error: asio.system:104 (Connection reset by peer)
Dec 26 14:12:20 paulin volumio-remote-updater[657]: [2025-12-26 14:12:20] [disconnect] Disconnect close local:[1006,Connection reset by peer] remote:[1006]
Dec 26 14:12:20 paulin systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE
Dec 26 14:12:20 paulin systemd[1]: volumio.service: Failed with result 'exit-code'.
Dec 26 14:12:20 paulin systemd[1]: volumio.service: Consumed 2min 3.331s CPU time.
Dec 26 14:12:20 paulin systemd[1]: Started dynamicswap.service - dynamicswap service.
Dec 26 14:12:20 paulin systemd[1]: dynamicswap.service: Deactivated successfully.
Dec 26 14:12:20 paulin systemd[1]: volumio.service: Scheduled restart job, restart counter is at 3.
Dec 26 14:12:20 paulin systemd[1]: Started dynamicswap.service - dynamicswap service.
Dec 26 14:12:20 paulin systemd[1]: Stopped volumio.service - Volumio Backend Module.
Dec 26 14:12:20 paulin systemd[1]: volumio.service: Consumed 2min 3.331s CPU time.
Dec 26 14:12:20 paulin systemd[1]: Started volumio.service - Volumio Backend Module.
Dec 26 14:12:20 paulin systemd[1]: dynamicswap.service: Deactivated successfully.
Dec 26 14:12:22 paulin systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 9.
Dec 26 14:12:22 paulin systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 26 14:12:22 paulin systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 26 14:12:22 paulin go-librespot[2817]: go-librespot daemon starting...
Dec 26 14:12:22 paulin go-librespot[2824]: time="2025-12-26T14:12:22-03:00" level=info msg="running go-librespot 0.4.0"
Dec 26 14:12:22 paulin go-librespot[2824]: time="2025-12-26T14:12:22-03:00" level=debug msg="app state loaded"
Dec 26 14:12:22 paulin go-librespot[2824]: time="2025-12-26T14:12:22-03:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 26 14:12:22 paulin volumio[2802]: info: -------------------------------------------
Dec 26 14:12:22 paulin volumio[2802]: info: ----- Volumio3 ----
Dec 26 14:12:22 paulin volumio[2802]: info: -------------------------------------------
Dec 26 14:12:22 paulin volumio[2802]: info: ----- System startup ----
Dec 26 14:12:22 paulin volumio[2802]: info: -------------------------------------------
Dec 26 14:12:22 paulin go-librespot[2824]: time="2025-12-26T14:12:22-03:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 26 14:12:22 paulin go-librespot[2824]: time="2025-12-26T14:12:22-03:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 26 14:12:22 paulin go-librespot[2824]: time="2025-12-26T14:12:22-03:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 26 14:12:22 paulin go-librespot[2824]: time="2025-12-26T14:12:22-03:00" level=info msg="zeroconf server listening on port 46369"
Dec 26 14:12:23 paulin go-librespot[2824]: time="2025-12-26T14:12:23-03:00" level=debug msg="obtained new client token: AAAnRd7aVV5uDImvcR/HzXea/ildJeIy9bpkd+fkWyczfaydcacAzXrr87zRY0Lkzswy77jADwPPm49oKHj1azDFhjlitOi9A6n7QVz5R3TWqWL1XGA4J4Wb4vq0HTQyN3s7ud2cz6K297emsJZMdc+oh42NcZ7/8QlrP+LsHvqbc+QQhqHlW1aJYdcflDYPVcPYso+OJi0TQImQRkjXUbuIWeSMtkKUnZeuN8fq59al2mBUn5EgWIgA"
Dec 26 14:12:23 paulin go-librespot[2824]: time="2025-12-26T14:12:23-03:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 26 14:12:23 paulin volumio[2802]: info: MYVOLUMIO Environment detected
Dec 26 14:12:23 paulin volumio[2802]: info: Plugin folders cleanup
Dec 26 14:12:23 paulin volumio[2802]: info: Scanning into folder /volumio/app/plugins/
Dec 26 14:12:23 paulin volumio[2802]: info: Scanning category audio_interface
Dec 26 14:12:23 paulin volumio[2802]: info: Scanning category miscellanea
Dec 26 14:12:23 paulin volumio[2802]: info: Scanning category music_service
Dec 26 14:12:23 paulin volumio[2802]: info: Scanning category plugins.json
Dec 26 14:12:23 paulin volumio[2802]: info: Scanning category system_controller
Dec 26 14:12:23 paulin volumio[2802]: info: Scanning category user_interface
Dec 26 14:12:23 paulin volumio[2802]: info: Scanning into folder /data/plugins/
Dec 26 14:12:23 paulin volumio[2802]: info: Scanning category music_service
Dec 26 14:12:23 paulin volumio[2802]: info: Plugin folders cleanup completed
Dec 26 14:12:23 paulin volumio[2802]: info: -------------------------------------------
Dec 26 14:12:23 paulin go-librespot[2824]: time="2025-12-26T14:12:23-03:00" level=debug msg="completed keyexchange"
Dec 26 14:12:23 paulin volumio[2802]: info: ----- Core plugins startup ----
Dec 26 14:12:23 paulin go-librespot[2824]: time="2025-12-26T14:12:23-03:00" level=debug msg="completed challenge"
Dec 26 14:12:23 paulin volumio[2802]: info: -------------------------------------------
Dec 26 14:12:23 paulin volumio[2802]: info: Loading plugins from folder /volumio/app/plugins/
Dec 26 14:12:23 paulin volumio[2802]: info: Adding plugin upnp to MyMusic Plugins
Dec 26 14:12:23 paulin volumio[2802]: info: Adding plugin airplay_emulation to MyMusic Plugins
Dec 26 14:12:23 paulin volumio[2802]: info: Adding plugin upnp_browser to MyMusic Plugins
Dec 26 14:12:23 paulin volumio[2802]: info: Loading plugins from folder /data/plugins/
Dec 26 14:12:23 paulin volumio[2802]: info: Loading plugin "system"...
Dec 26 14:12:23 paulin volumio[2802]: info: Loading plugin "appearance"...
Dec 26 14:12:23 paulin go-librespot[2824]: time="2025-12-26T14:12:23-03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials "
Dec 26 14:12:23 paulin systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 26 14:12:23 paulin systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 26 14:12:24 paulin volumio[2802]: info: Loading plugin "network"...
Dec 26 14:12:24 paulin volumio[2802]: info: Refreshing Cached IP Addresses
Dec 26 14:12:24 paulin sudo[2838]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0
Dec 26 14:12:24 paulin sudo[2838]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 26 14:12:24 paulin sudo[2840]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
Dec 26 14:12:24 paulin sudo[2840]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 26 14:12:24 paulin sudo[2838]: pam_unix(sudo:session): session closed for user root
Dec 26 14:12:24 paulin sudo[2840]: pam_unix(sudo:session): session closed for user root
Dec 26 14:12:24 paulin volumio[2802]: info: Loading plugin "services"...
Dec 26 14:12:24 paulin volumio[2802]: info: Loading plugin "alsa_controller"...
Dec 26 14:12:24 paulin sudo[2849]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan
Dec 26 14:12:24 paulin sudo[2849]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 26 14:12:24 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Dec 26 14:12:24 paulin volumio[2802]: info: Loading plugin "wizard"...
Dec 26 14:12:24 paulin volumio[2802]: info: Loading plugin "networkfs"...
Dec 26 14:12:24 paulin volumio[2802]: info: Starting Udev Watcher for removable devices
Dec 26 14:12:24 paulin volumio[2802]: info: Ignoring mount for partition: boot
Dec 26 14:12:24 paulin volumio[2802]: info: Ignoring mount for partition: volumio
Dec 26 14:12:24 paulin volumio[2802]: info: Ignoring mount for partition: volumio_data
Dec 26 14:12:24 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback
Dec 26 14:12:24 paulin volumio[2802]: info: Loading plugin "volumio_command_line_client"...
Dec 26 14:12:24 paulin volumio[2802]: info: Loading plugin "upnp"...
Dec 26 14:12:24 paulin volumio[2802]: info: [1766769144610] Starting Upmpd Daemon
Dec 26 14:12:24 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback
Dec 26 14:12:24 paulin volumio[2802]: info: Loading plugin "my_music"...
Dec 26 14:12:24 paulin volumio[2802]: info: Loading plugin "mpd"...
Dec 26 14:12:25 paulin volumio-remote-updater[657]: [2025-12-26 14:12:25] [connect] Successful connection
Dec 26 14:12:25 paulin volumio[2802]: info: Loading plugin "upnp_browser"...
Dec 26 14:12:26 paulin kernel: hwmon hwmon1: Undervoltage detected!
Dec 26 14:12:26 paulin systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 10.
Dec 26 14:12:26 paulin systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 26 14:12:26 paulin systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 26 14:12:26 paulin go-librespot[2876]: go-librespot daemon starting...
Dec 26 14:12:26 paulin go-librespot[2877]: time="2025-12-26T14:12:26-03:00" level=info msg="running go-librespot 0.4.0"
Dec 26 14:12:26 paulin go-librespot[2877]: time="2025-12-26T14:12:26-03:00" level=debug msg="app state loaded"
Dec 26 14:12:26 paulin go-librespot[2877]: time="2025-12-26T14:12:26-03:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 26 14:12:26 paulin sudo[2849]: pam_unix(sudo:session): session closed for user root
Dec 26 14:12:27 paulin go-librespot[2877]: time="2025-12-26T14:12:27-03:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 26 14:12:27 paulin go-librespot[2877]: time="2025-12-26T14:12:27-03:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 26 14:12:27 paulin go-librespot[2877]: time="2025-12-26T14:12:27-03:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 26 14:12:27 paulin go-librespot[2877]: time="2025-12-26T14:12:27-03:00" level=info msg="zeroconf server listening on port 35465"
Dec 26 14:12:27 paulin go-librespot[2877]: time="2025-12-26T14:12:27-03:00" level=debug msg="obtained new client token: AADOp3ald3NyIf1wbEacBtnidnoUAacRmuwGOcIv60d/RDyeBtGp4S23Az4wKXe+wZoRSiT5Dz9a+InD/HKb+FrBbm5lYHCwsn/tn0GgeZux/8n37orZ88ve95BWFQgw3Px1DADZMbS+6eJB8m3HDyVVN9b6xdcsAdfKAXdkIbaLNWu7Qjpgboo+UPE8Ltn6yJYGar+pf8VyHzy3FBTtYnbgQLsQa0PnzIMvqFfjIX0Z6F3iYGSeecc5Me8="
Dec 26 14:12:27 paulin go-librespot[2877]: time="2025-12-26T14:12:27-03:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 26 14:12:27 paulin go-librespot[2877]: time="2025-12-26T14:12:27-03:00" level=debug msg="completed keyexchange"
Dec 26 14:12:27 paulin go-librespot[2877]: time="2025-12-26T14:12:27-03:00" level=debug msg="completed challenge"
Dec 26 14:12:27 paulin volumio[2802]: info: Loading plugin "alarm-clock"...
Dec 26 14:12:28 paulin go-librespot[2877]: time="2025-12-26T14:12:28-03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials "
Dec 26 14:12:28 paulin systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 26 14:12:28 paulin systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 26 14:12:28 paulin volumio[2802]: info: Loading plugin "airplay_emulation"...
Dec 26 14:12:28 paulin volumio[2802]: info: Starting Shairport Sync
Dec 26 14:12:28 paulin volumio[2802]: info: Loading plugin "last_100"...
Dec 26 14:12:28 paulin volumio[2802]: info: Loading plugin "webradio"...
Dec 26 14:12:28 paulin volumio[2802]: info: Loading plugin "i2s_dacs"...
Dec 26 14:12:28 paulin volumio[2802]: info: I2S DAC not set, start Auto-detection
Dec 26 14:12:28 paulin volumio[2802]: info: Loading plugin "volumiodiscovery"...
Dec 26 14:12:28 paulin volumio[2802]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi.
Dec 26 14:12:28 paulin volumio[2802]: *** WARNING *** Please fix your application to use the native API of Avahi!
Dec 26 14:12:28 paulin volumio[2802]: *** WARNING *** For more information see
Dec 26 14:12:28 paulin volumio[2802]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi.
Dec 26 14:12:28 paulin volumio[2802]: *** WARNING *** Please fix your application to use the native API of Avahi!
Dec 26 14:12:28 paulin volumio[2802]: *** WARNING *** For more information see
Dec 26 14:12:28 paulin node[2802]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi.
Dec 26 14:12:28 paulin node[2802]: *** WARNING *** Please fix your application to use the native API of Avahi!
Dec 26 14:12:28 paulin node[2802]: *** WARNING *** For more information see
Dec 26 14:12:28 paulin node[2802]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi.
Dec 26 14:12:28 paulin node[2802]: *** WARNING *** Please fix your application to use the native API of Avahi!
Dec 26 14:12:28 paulin node[2802]: *** WARNING *** For more information see
Dec 26 14:12:28 paulin volumio[2802]: info: Applying required configuration parameters for plugin volumiodiscovery
Dec 26 14:12:28 paulin volumio[2802]: info: Discovery: Started advertising with name: Paulin
Dec 26 14:12:28 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback
Dec 26 14:12:28 paulin volumio[2802]: info: Loading plugin "spop"...
Dec 26 14:12:29 paulin volumio[2802]: info: Loading plugin "outputs"...
Dec 26 14:12:29 paulin volumio[2802]: info: Loading plugin "albumart"...
Dec 26 14:12:29 paulin volumio[2802]: info: Plugin example_plugin is not enabled
Dec 26 14:12:29 paulin volumio[2802]: info: Loading plugin "inputs"...
Dec 26 14:12:29 paulin volumio[2802]: info: Loading plugin "updater_comm"...
Dec 26 14:12:29 paulin volumio[2802]: info: Plugin mpdemulation is not enabled
Dec 26 14:12:29 paulin volumio[2802]: info: Loading plugin "rest_api"...
Dec 26 14:12:29 paulin volumio[2802]: info: Loading plugin "websocket"...
Dec 26 14:12:29 paulin volumio[2802]: info: Starting Socket.io Server version 1.7.4
Dec 26 14:12:29 paulin volumio[2802]: info: Loading i18n strings for locale es
Dec 26 14:12:29 paulin volumio[2802]: Updating browse sources language
Dec 26 14:12:29 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 26 14:12:29 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 26 14:12:29 paulin volumio[2802]: info: CoreCommandRouter::initPlayerControls
Dec 26 14:12:29 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 26 14:12:29 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 26 14:12:29 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 26 14:12:29 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 26 14:12:29 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 26 14:12:29 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 26 14:12:29 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 26 14:12:29 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 26 14:12:29 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 26 14:12:29 paulin volumio[2802]: Express server listening on port 3000
Dec 26 14:12:29 paulin volumio[2802]: [Metrics] WebUI: 7s 495.09ms
Dec 26 14:12:29 paulin volumio[2802]: info: CoreStateMachine::resetVolumioState
Dec 26 14:12:29 paulin volumio[2802]: info: CoreStateMachine::getcurrentVolume
Dec 26 14:12:29 paulin volumio[2802]: info: CoreCommandRouter::volumioRetrievevolume
Dec 26 14:12:29 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 26 14:12:29 paulin volumio[2802]: info: Volumio Network Manager: Network status updated: 1
Dec 26 14:12:29 paulin volumio[2887]: Forking 3 albumart workers
Dec 26 14:12:29 paulin volumio[2802]: verbose: New Socket.io Connection to 192.168.10.8 from 192.168.10.11 UA: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/143.0.0.0 Safari/537.36 Edg/143.0.0.0 Engine version: 3 Transport: polling Total Clients: 1
Dec 26 14:12:29 paulin volumio[2802]: info: VolumeController:: Volume=66 Mute =false
Dec 26 14:12:29 paulin volumio[2802]: info: CoreStateMachine::pushState
Dec 26 14:12:29 paulin volumio[2802]: info: CorePlayQueue::getTrack 0
Dec 26 14:12:29 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Dec 26 14:12:29 paulin volumio[2802]: info: CoreCommandRouter::volumioPushState
Dec 26 14:12:29 paulin volumio[2802]: info: CoreStateMachine::updateTrackBlock
Dec 26 14:12:29 paulin volumio[2802]: info: CorePlayQueue::getTrackBlock
Dec 26 14:12:29 paulin volumio[2802]: info: CoreCommandRouter::volumioRetrievevolume
Dec 26 14:12:29 paulin volumio-remote-updater[657]: [2025-12-26 14:12:29] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1766769145 101
Dec 26 14:12:29 paulin volumio[2802]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 2
Dec 26 14:12:29 paulin volumio[2802]: info: Reloading queue from file
Dec 26 14:12:29 paulin volumio[2802]: verbose: New Socket.io Connection to 192.168.10.8 from 192.168.10.11 UA: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/143.0.0.0 Safari/537.36 Edg/143.0.0.0 Engine version: 3 Transport: polling Total Clients: 3
Dec 26 14:12:29 paulin volumio[2802]: info: CoreStateMachine::setRepeat true single undefined
Dec 26 14:12:29 paulin volumio[2802]: info: CoreStateMachine::pushState
Dec 26 14:12:29 paulin volumio[2802]: info: CorePlayQueue::getTrack 0
Dec 26 14:12:29 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Dec 26 14:12:29 paulin volumio[2802]: info: CoreCommandRouter::volumioPushState
Dec 26 14:12:29 paulin volumio[2802]: info: CoreStateMachine::setRandom null
Dec 26 14:12:29 paulin volumio[2802]: info: CoreStateMachine::pushState
Dec 26 14:12:29 paulin volumio[2802]: info: CorePlayQueue::getTrack 0
Dec 26 14:12:29 paulin volumio[2802]: info: CoreCommandRouter::volumioPushState
Dec 26 14:12:30 paulin volumio[2802]: info: Setting Device type: Raspberry PI
Dec 26 14:12:30 paulin volumio[2802]: info: VolumeController:: Volume=66 Mute =false
Dec 26 14:12:30 paulin volumio[2802]: info: CoreStateMachine::pushState
Dec 26 14:12:30 paulin volumio[2802]: info: CorePlayQueue::getTrack 0
Dec 26 14:12:30 paulin volumio[2802]: info: CoreCommandRouter::volumioPushState
Dec 26 14:12:30 paulin volumio[2802]: info: Completed loading Core Plugins
Dec 26 14:12:30 paulin volumio[2802]: info: Preparing to generate the ALSA configuration file
Dec 26 14:12:30 paulin volumio[2802]: info: Discovery: adding 2faea66e-cdcc-4cb2-b575-db76a09e79cb
Dec 26 14:12:30 paulin volumio[2802]: info: Discovery: Found device Paulin
Dec 26 14:12:30 paulin volumio[2802]: info: CoreCommandRouter::volumioGetState
Dec 26 14:12:30 paulin volumio[2802]: info: CorePlayQueue::getTrack 0
Dec 26 14:12:30 paulin volumio[2802]: info: Discovery: this is already registered, 2faea66e-cdcc-4cb2-b575-db76a09e79cb
Dec 26 14:12:30 paulin volumio[2802]: info: Discovery: Found device Paulin
Dec 26 14:12:30 paulin volumio[2802]: info: CoreCommandRouter::volumioGetState
Dec 26 14:12:30 paulin volumio[2802]: info: CorePlayQueue::getTrack 0
Dec 26 14:12:30 paulin volumio[2802]: info: Asound.conf file unchanged, so no further update is needed
Dec 26 14:12:30 paulin volumio[2802]: info: Output device has changed, restarting MPD
Dec 26 14:12:30 paulin volumio[2802]: info: Output device has changed, restarting Shairport Sync
Dec 26 14:12:30 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 26 14:12:30 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 26 14:12:30 paulin sudo[2943]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf
Dec 26 14:12:30 paulin sudo[2943]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 26 14:12:30 paulin sudo[2943]: pam_unix(sudo:session): session closed for user root
Dec 26 14:12:30 paulin sudo[2944]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service
Dec 26 14:12:30 paulin volumio[2802]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
Dec 26 14:12:30 paulin volumio[2802]: info: ___________ START PLUGINS ___________
Dec 26 14:12:30 paulin sudo[2944]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 26 14:12:30 paulin volumio[2802]: info: ControllerMpd::onStart: Initializing MPD
Dec 26 14:12:30 paulin volumio[2802]: info: Creating MPD Configuration file
Dec 26 14:12:30 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 26 14:12:30 paulin volumio[2802]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 26 14:12:30 paulin volumio[2802]: info: [1766769150290] CoreMusicLibrary::Adding element Media Servers
Dec 26 14:12:30 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 26 14:12:30 paulin sudo[2952]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf
Dec 26 14:12:30 paulin sudo[2952]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 26 14:12:30 paulin sudo[2952]: pam_unix(sudo:session): session closed for user root
Dec 26 14:12:30 paulin systemd[1]: Stopping mpd.service - Music Player Daemon...
Dec 26 14:12:30 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 26 14:12:30 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 26 14:12:30 paulin sudo[2954]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service
Dec 26 14:12:30 paulin sudo[2954]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 26 14:12:30 paulin systemd[1]: mpd.service: Deactivated successfully.
Dec 26 14:12:30 paulin systemd[1]: Stopped mpd.service - Music Player Daemon.
Dec 26 14:12:30 paulin systemd[1]: mpd.service: Consumed 2.814s CPU time.
Dec 26 14:12:30 paulin systemd[1]: mpd.socket: Deactivated successfully.
Dec 26 14:12:30 paulin systemd[1]: Closed mpd.socket - Music Player Daemon Socket.
Dec 26 14:12:30 paulin systemd[1]: Stopping mpd.socket - Music Player Daemon Socket...
Dec 26 14:12:30 paulin volumio[2802]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
Dec 26 14:12:30 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 26 14:12:30 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 26 14:12:30 paulin systemd[1]: Listening on mpd.socket - Music Player Daemon Socket.
Dec 26 14:12:30 paulin systemd[1]: Starting mpd.service - Music Player Daemon...
Dec 26 14:12:30 paulin volumio[2802]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
Dec 26 14:12:30 paulin volumio[2802]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 26 14:12:30 paulin volumio[2802]: info: [1766769150508] CoreMusicLibrary::Adding element Last_100
Dec 26 14:12:30 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 26 14:12:30 paulin volumio[2802]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 26 14:12:30 paulin volumio[2802]: info: [1766769150513] CoreMusicLibrary::Adding element Webradio
Dec 26 14:12:30 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 26 14:12:30 paulin systemd[1]: mpd.service: Deactivated successfully.
Dec 26 14:12:30 paulin systemd[1]: Stopped mpd.service - Music Player Daemon.
Dec 26 14:12:30 paulin systemd[1]: mpd.socket: Deactivated successfully.
Dec 26 14:12:30 paulin systemd[1]: Closed mpd.socket - Music Player Daemon Socket.
Dec 26 14:12:30 paulin systemd[1]: Stopping mpd.socket - Music Player Daemon Socket...
Dec 26 14:12:30 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Dec 26 14:12:30 paulin volumio[2802]: info: Initializing BBC Radios
Dec 26 14:12:30 paulin systemd[1]: Listening on mpd.socket - Music Player Daemon Socket.
Dec 26 14:12:30 paulin systemd[1]: Starting mpd.service - Music Player Daemon...
Dec 26 14:12:30 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Dec 26 14:12:30 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 26 14:12:30 paulin volumio[2802]: info: Creating Spotify config file
Dec 26 14:12:30 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 26 14:12:30 paulin kernel: hwmon hwmon1: Voltage normalised
Dec 26 14:12:30 paulin sudo[2971]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log
Dec 26 14:12:30 paulin sudo[2971]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0)
Dec 26 14:12:30 paulin sudo[2971]: pam_unix(sudo:session): session closed for user root
Dec 26 14:12:31 paulin systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 11.
Dec 26 14:12:31 paulin systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 26 14:12:31 paulin volumio[2905]: Starting albumart workers
Dec 26 14:12:31 paulin systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 26 14:12:31 paulin go-librespot[2985]: go-librespot daemon starting...
Dec 26 14:12:31 paulin go-librespot[2986]: time="2025-12-26T14:12:31-03:00" level=info msg="running go-librespot 0.4.0"
Dec 26 14:12:31 paulin volumio[2802]: info: Volumio Calling Home
Dec 26 14:12:31 paulin volumio[2903]: Starting albumart workers
Dec 26 14:12:31 paulin volumio[2904]: Starting albumart workers
Dec 26 14:12:31 paulin go-librespot[2986]: time="2025-12-26T14:12:31-03:00" level=info msg="zeroconf server listening on port 38517"
Dec 26 14:12:31 paulin volumio[2802]: info: MPD Permissions set
Dec 26 14:12:31 paulin volumio[2802]: info: MPD Permissions set
Dec 26 14:12:31 paulin volumio[2802]: info: Spotify config file written
Dec 26 14:12:32 paulin sudo[2998]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service
Dec 26 14:12:32 paulin sudo[2998]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 26 14:12:32 paulin volumio[2802]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4
Dec 26 14:12:32 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 26 14:12:32 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 26 14:12:32 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 26 14:12:32 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 26 14:12:32 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 26 14:12:32 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 26 14:12:32 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 26 14:12:32 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 26 14:12:32 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 26 14:12:32 paulin systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon...
Dec 26 14:12:32 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 26 14:12:32 paulin systemd[1]: go-librespot-daemon.service: Deactivated successfully.
Dec 26 14:12:32 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 26 14:12:32 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 26 14:12:32 paulin systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 26 14:12:32 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 26 14:12:32 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 26 14:12:32 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 26 14:12:32 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 26 14:12:32 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 26 14:12:32 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 26 14:12:32 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 26 14:12:32 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 26 14:12:32 paulin volumio[2802]: info: No need to fix Spotify hosts
Dec 26 14:12:32 paulin systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 26 14:12:32 paulin go-librespot[3011]: go-librespot daemon starting...
Dec 26 14:12:32 paulin sudo[2998]: pam_unix(sudo:session): session closed for user root
Dec 26 14:12:32 paulin go-librespot[3017]: time="2025-12-26T14:12:32-03:00" level=info msg="running go-librespot 0.4.0"
Dec 26 14:12:32 paulin go-librespot[3017]: time="2025-12-26T14:12:32-03:00" level=debug msg="app state loaded"
Dec 26 14:12:32 paulin go-librespot[3017]: time="2025-12-26T14:12:32-03:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 26 14:12:32 paulin volumio[2802]: info: Volumio called home
Dec 26 14:12:32 paulin volumio[2802]: info: Starting Shairport Sync
Dec 26 14:12:32 paulin volumio[2802]: info: Starting Shairport Sync
Dec 26 14:12:32 paulin volumio[2802]: info: Starting Shairport Sync
Dec 26 14:12:32 paulin sudo[3027]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
Dec 26 14:12:32 paulin sudo[3027]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 26 14:12:32 paulin sudo[3029]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
Dec 26 14:12:32 paulin sudo[3029]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 26 14:12:32 paulin sudo[3031]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
Dec 26 14:12:32 paulin sudo[3031]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 26 14:12:32 paulin go-librespot[3017]: time="2025-12-26T14:12:32-03:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 26 14:12:32 paulin go-librespot[3017]: time="2025-12-26T14:12:32-03:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 26 14:12:32 paulin go-librespot[3017]: time="2025-12-26T14:12:32-03:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 26 14:12:32 paulin systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver...
Dec 26 14:12:32 paulin go-librespot[3017]: time="2025-12-26T14:12:32-03:00" level=info msg="zeroconf server listening on port 46883"
Dec 26 14:12:32 paulin systemd[1]: shairport-sync.service: Deactivated successfully.
Dec 26 14:12:32 paulin systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 26 14:12:32 paulin systemd[1]: shairport-sync.service: Consumed 1.733s CPU time.
Dec 26 14:12:32 paulin volumio[2802]: info: An error occurred while refreshing Spotify Token Error: Bad Request
Dec 26 14:12:32 paulin systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 26 14:12:32 paulin sudo[3029]: pam_unix(sudo:session): session closed for user root
Dec 26 14:12:32 paulin sudo[3027]: pam_unix(sudo:session): session closed for user root
Dec 26 14:12:32 paulin sudo[3031]: pam_unix(sudo:session): session closed for user root
Dec 26 14:12:32 paulin volumio[2802]: info: CoreCommandRouter::volumioGetState
Dec 26 14:12:32 paulin volumio[2802]: info: CorePlayQueue::getTrack 0
Dec 26 14:12:32 paulin volumio[2802]: info: Shairport-Sync Started
Dec 26 14:12:32 paulin volumio[2802]: Error adding Membership: Error: addMembership EINVAL
Dec 26 14:12:32 paulin volumio[2802]: info: Shairport-Sync Started
Dec 26 14:12:32 paulin volumio[2802]: info: Shairport-Sync Started
Dec 26 14:12:32 paulin go-librespot[3017]: time="2025-12-26T14:12:32-03:00" level=debug msg="obtained new client token: AACvBEXySkxUyLLDpguqsnin9ASus3ZsJj7+eUpvy58CPUGad9cgd1itvRp+wJSQIbjxzDhYiKMA80dzR5YEChl8d1EPESHqR7jBMpm7kPzAu3yiFee13uNnOxgEimABETipljlQiixIDNNrUH+hUUqmQNBo6cDEPgSB3+xiaLxffR/zYwGljWcmEEsz0E2Za4BWrZhoXus0c+CuppTsTUV3mvRlBMnEo5s9KGXn4UaDngH4aiw2RvugtIE="
Dec 26 14:12:33 paulin go-librespot[3017]: time="2025-12-26T14:12:33-03:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 26 14:12:33 paulin go-librespot[3017]: time="2025-12-26T14:12:33-03:00" level=debug msg="completed keyexchange"
Dec 26 14:12:33 paulin go-librespot[3017]: time="2025-12-26T14:12:33-03:00" level=debug msg="completed challenge"
Dec 26 14:12:33 paulin go-librespot[3017]: time="2025-12-26T14:12:33-03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials "
Dec 26 14:12:33 paulin systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 26 14:12:33 paulin systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 26 14:12:33 paulin volumio[2802]: verbose: New Socket.io Connection to 192.168.10.8 from 192.168.10.11 UA: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/143.0.0.0 Safari/537.36 Edg/143.0.0.0 Engine version: 3 Transport: polling Total Clients: 5
Dec 26 14:12:33 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings
Dec 26 14:12:33 paulin volumio[2802]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined
Dec 26 14:12:33 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates
Dec 26 14:12:33 paulin volumio[2802]: info: Received Get System Version
Dec 26 14:12:33 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Dec 26 14:12:33 paulin volumio[2802]: info: Received Get System Info
Dec 26 14:12:33 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo
Dec 26 14:12:33 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice
Dec 26 14:12:33 paulin volumio[2802]: info: Discovery: Getting this device information
Dec 26 14:12:33 paulin volumio[2802]: info: CoreCommandRouter::volumioGetState
Dec 26 14:12:33 paulin volumio[2802]: info: CorePlayQueue::getTrack 0
Dec 26 14:12:33 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses
Dec 26 14:12:33 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled
Dec 26 14:12:33 paulin volumio[2802]: info: CoreCommandRouter::volumioGetVisibleSources
Dec 26 14:12:33 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 26 14:12:33 paulin volumio[2802]: info: CoreCommandRouter::volumioGetState
Dec 26 14:12:33 paulin volumio[2802]: info: CorePlayQueue::getTrack 0
Dec 26 14:12:33 paulin volumio[2802]: info: CoreCommandRouter::volumioGetState
Dec 26 14:12:33 paulin volumio[2802]: info: CorePlayQueue::getTrack 0
Dec 26 14:12:33 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback
Dec 26 14:12:33 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom
Dec 26 14:12:33 paulin volumio[2802]: info: Received Get System Info
Dec 26 14:12:33 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo
Dec 26 14:12:33 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice
Dec 26 14:12:33 paulin volumio[2802]: info: Discovery: Getting this device information
Dec 26 14:12:33 paulin volumio[2802]: info: CoreCommandRouter::volumioGetState
Dec 26 14:12:33 paulin volumio[2802]: info: CorePlayQueue::getTrack 0
Dec 26 14:12:33 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses
Dec 26 14:12:33 paulin volumio[2802]: info: CoreCommandRouter::volumioGetState
Dec 26 14:12:33 paulin volumio[2802]: info: CorePlayQueue::getTrack 0
Dec 26 14:12:33 paulin volumio[2802]: info: Listing playlists
Dec 26 14:12:34 paulin mpd[2984]: 2025-12-26T14:12:34 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg
Dec 26 14:12:34 paulin systemd[1]: Started mpd.service - Music Player Daemon.
Dec 26 14:12:34 paulin sudo[2944]: pam_unix(sudo:session): session closed for user root
Dec 26 14:12:34 paulin sudo[2954]: pam_unix(sudo:session): session closed for user root
Dec 26 14:12:34 paulin volumio[2802]: info: Completed starting Core Plugins
Dec 26 14:12:34 paulin volumio[2802]: info: -------------------------------------------
Dec 26 14:12:34 paulin volumio[2802]: info: ----- MyVolumio plugins startup ----
Dec 26 14:12:34 paulin volumio[2802]: info: -------------------------------------------
Dec 26 14:12:34 paulin volumio[2802]: info: [MyVolumio PluginManager] Fetching plans data....
Dec 26 14:12:34 paulin volumio[2802]: error: MPD error: The expression evaluated to a falsy value:
Dec 26 14:12:34 paulin volumio[2802]: assert.ok(self.idling)
Dec 26 14:12:34 paulin volumio[2802]: error: The expression evaluated to a falsy value:
Dec 26 14:12:34 paulin volumio[2802]: assert.ok(self.idling)
Dec 26 14:12:34 paulin volumio[2802]: error: updateQueue error: null
Dec 26 14:12:34 paulin volumio[2802]: info: MPD running with PID2984
Dec 26 14:12:34 paulin volumio[2802]: ,establishing connection
Dec 26 14:12:34 paulin sudo[3082]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0
Dec 26 14:12:34 paulin sudo[3082]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 26 14:12:34 paulin sudo[3084]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
Dec 26 14:12:34 paulin sudo[3084]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 26 14:12:34 paulin sudo[3082]: pam_unix(sudo:session): session closed for user root
Dec 26 14:12:34 paulin sudo[3084]: pam_unix(sudo:session): session closed for user root
Dec 26 14:12:34 paulin volumio[2802]: error: updateQueue error: null
Dec 26 14:12:34 paulin sudo[3088]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service
Dec 26 14:12:34 paulin sudo[3088]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 26 14:12:34 paulin sudo[3088]: pam_unix(sudo:session): session closed for user root
Dec 26 14:12:34 paulin volumio[2802]: info: Upmpdcli Daemon Started
Dec 26 14:12:35 paulin volumio[2802]: info: go-librespot daemon successfully initialized
Dec 26 14:12:36 paulin systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1.
Dec 26 14:12:36 paulin systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 26 14:12:36 paulin systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 26 14:12:36 paulin go-librespot[3090]: go-librespot daemon starting...
Dec 26 14:12:36 paulin go-librespot[3091]: time="2025-12-26T14:12:36-03:00" level=info msg="running go-librespot 0.4.0"
Dec 26 14:12:36 paulin go-librespot[3091]: time="2025-12-26T14:12:36-03:00" level=debug msg="app state loaded"
Dec 26 14:12:36 paulin go-librespot[3091]: time="2025-12-26T14:12:36-03:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 26 14:12:36 paulin kernel: hwmon hwmon1: Undervoltage detected!
Dec 26 14:12:37 paulin go-librespot[3091]: time="2025-12-26T14:12:37-03:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 26 14:12:37 paulin go-librespot[3091]: time="2025-12-26T14:12:37-03:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 26 14:12:37 paulin go-librespot[3091]: time="2025-12-26T14:12:37-03:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 26 14:12:37 paulin go-librespot[3091]: time="2025-12-26T14:12:37-03:00" level=info msg="zeroconf server listening on port 33543"
Dec 26 14:12:37 paulin go-librespot[3091]: time="2025-12-26T14:12:37-03:00" level=debug msg="obtained new client token: AADWFT8cXN9xv1HRICr8pNQEpsgw5ejIPBlrIbVAtVzbNvbnTAvxy1ae/UCOJh9knnWXp7t05c5weYStfcIa3BXpsD5EDk9m5aK57cUFgyaQRUdPefdMv74U+NRW0m4dWDUZMtsvQhoo/Be+0Un4GPL+wH3ePwx0JjIIZIF5U1lfF8GC9ZBfHgxB5aP3KsUQV6AHIfcT4++OGdGD43FX/74XHYVhfAzhRYmRKiZIOVkydkFwIYHvtAXZ8q4="
Dec 26 14:12:37 paulin sudo[3100]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service
Dec 26 14:12:37 paulin sudo[3100]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 26 14:12:37 paulin sudo[3102]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service
Dec 26 14:12:37 paulin sudo[3102]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 26 14:12:37 paulin go-librespot[3091]: time="2025-12-26T14:12:37-03:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 26 14:12:37 paulin systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service...
Dec 26 14:12:37 paulin systemd[1]: mpd_monitor.service: Deactivated successfully.
Dec 26 14:12:37 paulin systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service.
Dec 26 14:12:37 paulin systemd[1]: Started mpd_monitor.service - MPD Monitor Service.
Dec 26 14:12:37 paulin sudo[3102]: pam_unix(sudo:session): session closed for user root
Dec 26 14:12:37 paulin sudo[3100]: pam_unix(sudo:session): session closed for user root
Dec 26 14:12:37 paulin mpd_monitor.sh[3105]: MPD Monitor Service: Starting MPD Monitor Service
Dec 26 14:12:37 paulin volumio[2802]: info: Successfully started MPD Monitor
Dec 26 14:12:37 paulin volumio[2802]: info: Successfully started MPD Monitor
Dec 26 14:12:37 paulin go-librespot[3091]: time="2025-12-26T14:12:37-03:00" level=debug msg="completed keyexchange"
Dec 26 14:12:37 paulin go-librespot[3091]: time="2025-12-26T14:12:37-03:00" level=debug msg="completed challenge"
Dec 26 14:12:38 paulin go-librespot[3091]: time="2025-12-26T14:12:38-03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials "
Dec 26 14:12:38 paulin systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 26 14:12:38 paulin systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 26 14:12:38 paulin volumio[2802]: info: Initializing connection to go-librespot Websocket
Dec 26 14:12:38 paulin volumio[2802]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 26 14:12:39 paulin volumio[2802]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory
Dec 26 14:12:41 paulin systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2.
Dec 26 14:12:41 paulin systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 26 14:12:41 paulin systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 26 14:12:41 paulin go-librespot[3109]: go-librespot daemon starting...
Dec 26 14:12:41 paulin go-librespot[3110]: time="2025-12-26T14:12:41-03:00" level=info msg="running go-librespot 0.4.0"
Dec 26 14:12:41 paulin go-librespot[3110]: time="2025-12-26T14:12:41-03:00" level=debug msg="app state loaded"
Dec 26 14:12:41 paulin go-librespot[3110]: time="2025-12-26T14:12:41-03:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 26 14:12:41 paulin volumio[2802]: info: Initializing connection to go-librespot Websocket
Dec 26 14:12:41 paulin go-librespot[3110]: time="2025-12-26T14:12:41-03:00" level=debug msg="new websocket client"
Dec 26 14:12:41 paulin volumio[2802]: info: Connection to go-librespot Websocket established
Dec 26 14:12:41 paulin go-librespot[3110]: time="2025-12-26T14:12:41-03:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 26 14:12:41 paulin go-librespot[3110]: time="2025-12-26T14:12:41-03:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 26 14:12:41 paulin go-librespot[3110]: time="2025-12-26T14:12:41-03:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 26 14:12:41 paulin go-librespot[3110]: time="2025-12-26T14:12:41-03:00" level=info msg="zeroconf server listening on port 39531"
Dec 26 14:12:42 paulin go-librespot[3110]: time="2025-12-26T14:12:42-03:00" level=debug msg="obtained new client token: AAACCfvDvDSb5leVqZ09OvFFER2d7NdpARJD96FKjXbkfFCTqGoBAIJqqcxyQlcBU6c5nGd6DC9t697AuNBppTz2Z//nTuRsZuyH/tNVduD1BF2zXXmS93mDSOgomMR8Lf9ltwdtBh3Vzx+0eZIyGHDpDA1oCWM6b0GL210+DNB65Da5pebrLMgExWlJ8DW5WlL6LrPMwpq8TxTnvmrIYimuCe8VH+aQgLHIVU40ajj5dLMP3zXhMXq+oFw="
Dec 26 14:12:42 paulin go-librespot[3110]: time="2025-12-26T14:12:42-03:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 26 14:12:42 paulin go-librespot[3110]: time="2025-12-26T14:12:42-03:00" level=debug msg="completed keyexchange"
Dec 26 14:12:42 paulin go-librespot[3110]: time="2025-12-26T14:12:42-03:00" level=debug msg="completed challenge"
Dec 26 14:12:42 paulin go-librespot[3110]: time="2025-12-26T14:12:42-03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials "
Dec 26 14:12:42 paulin systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 26 14:12:42 paulin systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 26 14:12:42 paulin volumio[2802]: info: Connection to go-librespot Websocket closed
Dec 26 14:12:43 paulin volumio[2802]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium
Dec 26 14:12:43 paulin volumio[2802]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium
Dec 26 14:12:43 paulin volumio[2802]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium
Dec 26 14:12:43 paulin volumio[2802]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium
Dec 26 14:12:43 paulin volumio[2802]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium
Dec 26 14:12:43 paulin volumio[2802]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium
Dec 26 14:12:43 paulin volumio[2802]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium
Dec 26 14:12:43 paulin volumio[2802]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium
Dec 26 14:12:43 paulin volumio[2802]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium
Dec 26 14:12:43 paulin volumio[2802]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium
Dec 26 14:12:43 paulin volumio[2802]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium
Dec 26 14:12:43 paulin volumio[2802]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar
Dec 26 14:12:43 paulin volumio[2802]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar
Dec 26 14:12:43 paulin volumio[2802]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar
Dec 26 14:12:43 paulin volumio[2802]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar
Dec 26 14:12:43 paulin volumio[2802]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar
Dec 26 14:12:43 paulin volumio[2802]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar
Dec 26 14:12:43 paulin volumio[2802]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar
Dec 26 14:12:43 paulin volumio[2802]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar
Dec 26 14:12:43 paulin volumio[2802]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar
Dec 26 14:12:43 paulin volumio[2802]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar
Dec 26 14:12:43 paulin volumio[2802]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar
Dec 26 14:12:43 paulin volumio[2802]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso
Dec 26 14:12:43 paulin volumio[2802]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso
Dec 26 14:12:43 paulin volumio[2802]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso
Dec 26 14:12:43 paulin volumio[2802]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso
Dec 26 14:12:43 paulin volumio[2802]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso
Dec 26 14:12:43 paulin volumio[2802]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso
Dec 26 14:12:43 paulin volumio[2802]: info: Adding plugin bluetooth to MyMusic Plugins
Dec 26 14:12:43 paulin volumio[2802]: info: Adding plugin multiroom to MyMusic Plugins
Dec 26 14:12:43 paulin volumio[2802]: info: Adding plugin metavolumio to MyMusic Plugins
Dec 26 14:12:43 paulin volumio[2802]: info: Adding plugin cd_controller to MyMusic Plugins
Dec 26 14:12:43 paulin volumio[2802]: info: Adding plugin qobuzconnect to MyMusic Plugins
Dec 26 14:12:43 paulin volumio[2802]: info: Adding plugin smart_inputs to MyMusic Plugins
Dec 26 14:12:43 paulin volumio[2802]: info: Adding plugin tidalconnect to MyMusic Plugins
Dec 26 14:12:43 paulin volumio[2802]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"...
Dec 26 14:12:44 paulin volumio[2802]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded
Dec 26 14:12:44 paulin volumio[2802]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio
Dec 26 14:12:44 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 26 14:12:44 paulin volumio[2802]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 26 14:12:44 paulin volumio[2802]: info: Starting MyVolumio Remote Streaming Endpoints
Dec 26 14:12:44 paulin volumio[2802]: info: MyVolumio login type: Token
Dec 26 14:12:45 paulin volumio[2802]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started
Dec 26 14:12:45 paulin volumio[2802]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"...
Dec 26 14:12:45 paulin systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3.
Dec 26 14:12:45 paulin systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 26 14:12:45 paulin systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 26 14:12:45 paulin go-librespot[3131]: go-librespot daemon starting...
Dec 26 14:12:45 paulin go-librespot[3132]: time="2025-12-26T14:12:45-03:00" level=info msg="running go-librespot 0.4.0"
Dec 26 14:12:45 paulin go-librespot[3132]: time="2025-12-26T14:12:45-03:00" level=debug msg="app state loaded"
Dec 26 14:12:45 paulin go-librespot[3132]: time="2025-12-26T14:12:45-03:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 26 14:12:46 paulin go-librespot[3132]: time="2025-12-26T14:12:46-03:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 26 14:12:46 paulin go-librespot[3132]: time="2025-12-26T14:12:46-03:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 26 14:12:46 paulin go-librespot[3132]: time="2025-12-26T14:12:46-03:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 26 14:12:46 paulin go-librespot[3132]: time="2025-12-26T14:12:46-03:00" level=info msg="zeroconf server listening on port 37951"
Dec 26 14:12:46 paulin go-librespot[3132]: time="2025-12-26T14:12:46-03:00" level=debug msg="obtained new client token: AADaK2eX80qSEryEENU7aaYVcHXcxo/vdaGGoJBbBfrCxomHQDNoW+E91Wn4YgRREslN5ymy9/KnwaK7n0hW66qoWXGbSlJF5U9maIgrWGkLn1PhReKZaFeHUial98cvy/bEFpTTveMjGycVWqSNsLtgVMyws+ySkSeDhcPl+Sd+08IHPeoCpZcPonCtz0iQtkqVSHUU4z/XDFfAeL2FU//U3ZeBdT5Bk3+CPBZ0TqSfcn/P2Q1g9gQC1Dg="
Dec 26 14:12:46 paulin volumio[2802]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded
Dec 26 14:12:46 paulin volumio[2802]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services
Dec 26 14:12:46 paulin volumio[2802]: info: Streaming services startup
Dec 26 14:12:46 paulin volumio[2802]: info: Starting Streaming Daemon
Dec 26 14:12:46 paulin sudo[3142]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service
Dec 26 14:12:46 paulin volumio[2802]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started
Dec 26 14:12:46 paulin sudo[3142]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 26 14:12:46 paulin sudo[3142]: pam_unix(sudo:session): session closed for user root
Dec 26 14:12:46 paulin go-librespot[3132]: time="2025-12-26T14:12:46-03:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 26 14:12:46 paulin volumio[2802]: info: Getting Spotify volume
Dec 26 14:12:46 paulin volumio[2802]: info: Initializing connection to go-librespot Websocket
Dec 26 14:12:46 paulin volumio[2802]: info: CoreCommandRouter::volumioGetState
Dec 26 14:12:46 paulin volumio[2802]: info: CorePlayQueue::getTrack 0
Dec 26 14:12:46 paulin volumio[2802]: error: Cannot start Volumio Streaming Daemon
Dec 26 14:12:46 paulin volumio[2802]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service
Dec 26 14:12:46 paulin volumio[2802]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found.
Dec 26 14:12:46 paulin go-librespot[3132]: time="2025-12-26T14:12:46-03:00" level=debug msg="new websocket client"
Dec 26 14:12:46 paulin volumio[2802]: info: Connection to go-librespot Websocket established
Dec 26 14:12:46 paulin volumio[2802]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6
Dec 26 14:12:47 paulin volumio[2802]: info: CoreCommandRouter::volumioGetState
Dec 26 14:12:47 paulin volumio[2802]: info: CorePlayQueue::getTrack 0
Dec 26 14:12:47 paulin volumio[2802]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66
Dec 26 14:12:47 paulin volumio[2802]: SPOTIFY: SPOTIFY VOLUME undefined
Dec 26 14:12:47 paulin volumio[2802]: SPOTIFY: VOLUMIO VOLUME 66
Dec 26 14:12:47 paulin volumio[2802]: info: Aligning Spotify Volume to Volumio Volume
Dec 26 14:12:47 paulin volumio[2802]: info: CoreCommandRouter::volumioGetState
Dec 26 14:12:47 paulin volumio[2802]: info: CorePlayQueue::getTrack 0
Dec 26 14:12:47 paulin volumio[2802]: info: Setting Spotify Volume from Volumio: 66
Dec 26 14:12:47 paulin volumio[2802]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN
Dec 26 14:12:48 paulin volumio[2802]: info: MyVolumio token set successfully
Dec 26 14:12:48 paulin volumio[2802]: info: MYVOLUMIO: Adding device
Dec 26 14:12:48 paulin volumio[2802]: info: MYVOLUMIO: Evaluating Server
Dec 26 14:12:48 paulin go-librespot[3132]: time="2025-12-26T14:12:48-03:00" level=debug msg="completed keyexchange"
Dec 26 14:12:48 paulin go-librespot[3132]: time="2025-12-26T14:12:48-03:00" level=debug msg="completed challenge"
Dec 26 14:12:48 paulin volumio[2802]: SPOTIFY: SETTING SPOTIFY VOLUME 66
Dec 26 14:12:48 paulin volumio[2802]: info: Sending Spotify command with payload to local API: /player/volume
Dec 26 14:12:49 paulin go-librespot[3132]: time="2025-12-26T14:12:49-03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials "
Dec 26 14:12:49 paulin volumio[2802]: info: MyVolumio status changed
Dec 26 14:12:49 paulin systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 26 14:12:49 paulin systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 26 14:12:49 paulin volumio[2802]: info: Streaming services startup
Dec 26 14:12:49 paulin volumio[2802]: info: Starting Streaming Daemon
Dec 26 14:12:49 paulin volumio[2802]: info: Removing browser output: myVolumio user plan is not superstar
Dec 26 14:12:49 paulin volumio[2802]: info: Removing audio output:
Dec 26 14:12:49 paulin volumio[2802]: info: Stoppping Tunnel 1
Dec 26 14:12:49 paulin sudo[3169]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service
Dec 26 14:12:49 paulin sudo[3169]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 26 14:12:49 paulin sudo[3169]: pam_unix(sudo:session): session closed for user root
Dec 26 14:12:49 paulin volumio[2802]: error: Failed to send command to Spotify local API: /player/volume: Error: socket hang up
Dec 26 14:12:49 paulin volumio[2802]: |||||||||||||||||||||||| WARNING: FATAL ERROR |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Dec 26 14:12:49 paulin sudo[3172]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service
Dec 26 14:12:49 paulin sudo[3172]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 26 14:12:49 paulin volumio[2802]: Error: socket hang up
Dec 26 14:12:49 paulin volumio[2802]: at connResetException (node:internal/errors:720:14)
Dec 26 14:12:49 paulin volumio[2802]: at Socket.socketOnEnd (node:_http_client:519:23)
Dec 26 14:12:49 paulin volumio[2802]: at Socket.emit (node:events:526:35)
Dec 26 14:12:49 paulin volumio[2802]: at endReadableNT (node:internal/streams/readable:1376:12)
Dec 26 14:12:49 paulin volumio[2802]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) {
Dec 26 14:12:49 paulin volumio[2802]: code: 'ECONNRESET',
Dec 26 14:12:49 paulin volumio[2802]: response: undefined
Dec 26 14:12:49 paulin volumio[2802]: }
Dec 26 14:12:49 paulin volumio[2802]: |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Dec 26 14:12:49 paulin systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Dec 26 14:12:49 paulin systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Dec 26 14:12:49 paulin systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Dec 26 14:12:49 paulin systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Dec 26 14:12:49 paulin systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Dec 26 14:12:49 paulin systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Dec 26 14:12:49 paulin systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Dec 26 14:12:49 paulin systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Dec 26 14:12:49 paulin sudo[3172]: pam_unix(sudo:session): session closed for user root
Dec 26 14:12:50 paulin sudo[3188]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-26 14:11'
Dec 26 14:12:50 paulin sudo[3188]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 26 14:12:51 paulin sudo[3188]: pam_unix(sudo:session): session closed for user root
Dec 26 14:12:51 paulin volumio-remote-updater[657]: [2025-12-26 14:12:51] [error] handle_read_frame error: websocketpp.transport:7 (End of File)
Dec 26 14:12:51 paulin volumio-remote-updater[657]: [2025-12-26 14:12:51] [disconnect] Disconnect close local:[1006,End of File] remote:[1006]
Dec 26 14:12:51 paulin systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE
Dec 26 14:12:51 paulin systemd[1]: volumio.service: Failed with result 'exit-code'.
Dec 26 14:12:51 paulin systemd[1]: volumio.service: Consumed 32.285s CPU time.
Dec 26 14:12:51 paulin systemd[1]: Started dynamicswap.service - dynamicswap service.
Dec 26 14:12:51 paulin systemd[1]: volumio.service: Scheduled restart job, restart counter is at 4.
Dec 26 14:12:51 paulin systemd[1]: Stopped volumio.service - Volumio Backend Module.
Dec 26 14:12:51 paulin systemd[1]: volumio.service: Consumed 32.285s CPU time.
Dec 26 14:12:51 paulin systemd[1]: Started volumio.service - Volumio Backend Module.
Dec 26 14:12:51 paulin systemd[1]: dynamicswap.service: Deactivated successfully.
Dec 26 14:12:52 paulin systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4.
Dec 26 14:12:52 paulin systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 26 14:12:52 paulin systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 26 14:12:52 paulin go-librespot[3213]: go-librespot daemon starting...
Dec 26 14:12:52 paulin go-librespot[3214]: time="2025-12-26T14:12:52-03:00" level=info msg="running go-librespot 0.4.0"
Dec 26 14:12:52 paulin go-librespot[3214]: time="2025-12-26T14:12:52-03:00" level=debug msg="app state loaded"
Dec 26 14:12:52 paulin go-librespot[3214]: time="2025-12-26T14:12:52-03:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 26 14:12:52 paulin go-librespot[3214]: time="2025-12-26T14:12:52-03:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]"
Dec 26 14:12:52 paulin go-librespot[3214]: time="2025-12-26T14:12:52-03:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]"
Dec 26 14:12:52 paulin go-librespot[3214]: time="2025-12-26T14:12:52-03:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]"
Dec 26 14:12:52 paulin go-librespot[3214]: time="2025-12-26T14:12:52-03:00" level=info msg="zeroconf server listening on port 42347"
Dec 26 14:12:53 paulin go-librespot[3214]: time="2025-12-26T14:12:53-03:00" level=debug msg="obtained new client token: AABRZnhPxiJB0G2JbnvMgr9srtxPRqQtltc6gk98SPAeU7iIkOTThb1mkE/eB7URNktokXn0ZEs3JS3sIh6Fl9oN7zFRD3eQBkk5JqleRlXRnsWUhwN4ejr9PkfgGIp7t/WpFGVzeITctjvSoX0JKuGfQ0HZ/Ss4UkWkxlN8eSPnjmfKaIkGQxY2IW8tWfi+CnotRFxV8WDaCvFJXXGiOqPoonBcOtlN9TiMnGyQG5KUqAkQuFc6PTcY"
Dec 26 14:12:53 paulin go-librespot[3214]: time="2025-12-26T14:12:53-03:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 26 14:12:53 paulin go-librespot[3214]: time="2025-12-26T14:12:53-03:00" level=debug msg="completed keyexchange"
Dec 26 14:12:53 paulin go-librespot[3214]: time="2025-12-26T14:12:53-03:00" level=debug msg="completed challenge"
Dec 26 14:12:53 paulin go-librespot[3214]: time="2025-12-26T14:12:53-03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials "
Dec 26 14:12:53 paulin systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 26 14:12:53 paulin systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 26 14:12:54 paulin volumio[3200]: info: -------------------------------------------
Dec 26 14:12:54 paulin volumio[3200]: info: ----- Volumio3 ----
Dec 26 14:12:54 paulin volumio[3200]: info: -------------------------------------------
Dec 26 14:12:54 paulin volumio[3200]: info: ----- System startup ----
Dec 26 14:12:54 paulin volumio[3200]: info: -------------------------------------------
Dec 26 14:12:55 paulin volumio[3200]: info: MYVOLUMIO Environment detected
Dec 26 14:12:55 paulin volumio[3200]: info: Plugin folders cleanup
Dec 26 14:12:55 paulin volumio[3200]: info: Scanning into folder /volumio/app/plugins/
Dec 26 14:12:55 paulin volumio[3200]: info: Scanning category audio_interface
Dec 26 14:12:55 paulin volumio[3200]: info: Scanning category miscellanea
Dec 26 14:12:55 paulin volumio[3200]: info: Scanning category music_service
Dec 26 14:12:55 paulin volumio[3200]: info: Scanning category plugins.json
Dec 26 14:12:55 paulin volumio[3200]: info: Scanning category system_controller
Dec 26 14:12:55 paulin volumio[3200]: info: Scanning category user_interface
Dec 26 14:12:55 paulin volumio[3200]: info: Scanning into folder /data/plugins/
Dec 26 14:12:55 paulin volumio[3200]: info: Scanning category music_service
Dec 26 14:12:55 paulin volumio[3200]: info: Plugin folders cleanup completed
Dec 26 14:12:55 paulin volumio[3200]: info: -------------------------------------------
Dec 26 14:12:55 paulin volumio[3200]: info: ----- Core plugins startup ----
Dec 26 14:12:55 paulin volumio[3200]: info: -------------------------------------------
Dec 26 14:12:55 paulin volumio[3200]: info: Loading plugins from folder /volumio/app/plugins/
Dec 26 14:12:55 paulin volumio[3200]: info: Adding plugin upnp to MyMusic Plugins
Dec 26 14:12:55 paulin volumio[3200]: info: Adding plugin airplay_emulation to MyMusic Plugins
Dec 26 14:12:55 paulin volumio[3200]: info: Adding plugin upnp_browser to MyMusic Plugins
Dec 26 14:12:55 paulin volumio[3200]: info: Loading plugins from folder /data/plugins/
Dec 26 14:12:55 paulin volumio[3200]: info: Loading plugin "system"...
Dec 26 14:12:55 paulin volumio[3200]: info: Loading plugin "appearance"...
Dec 26 14:12:56 paulin volumio-remote-updater[657]: [2025-12-26 14:12:56] [connect] Successful connection
Dec 26 14:12:56 paulin systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5.
Dec 26 14:12:56 paulin systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 26 14:12:56 paulin systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 26 14:12:56 paulin go-librespot[3233]: go-librespot daemon starting...
Dec 26 14:12:56 paulin go-librespot[3234]: time="2025-12-26T14:12:56-03:00" level=info msg="running go-librespot 0.4.0"
Dec 26 14:12:56 paulin go-librespot[3234]: time="2025-12-26T14:12:56-03:00" level=debug msg="app state loaded"
Dec 26 14:12:56 paulin go-librespot[3234]: time="2025-12-26T14:12:56-03:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 26 14:12:57 paulin go-librespot[3234]: time="2025-12-26T14:12:57-03:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 26 14:12:57 paulin go-librespot[3234]: time="2025-12-26T14:12:57-03:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 26 14:12:57 paulin go-librespot[3234]: time="2025-12-26T14:12:57-03:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 26 14:12:57 paulin go-librespot[3234]: time="2025-12-26T14:12:57-03:00" level=info msg="zeroconf server listening on port 40357"
Dec 26 14:12:57 paulin volumio[3200]: info: Loading plugin "network"...
Dec 26 14:12:57 paulin go-librespot[3234]: time="2025-12-26T14:12:57-03:00" level=debug msg="obtained new client token: AAA83MNYnzrMH28doIDBuB1UP81flMaN6PT8UzftKuBkI9+rOcD8exd3PBsUMbwmCIcqeGjpVjyCeAVjv+ItC5qwFVDtGSuJVZri4fYJ9zYgyszXZ9pLo5Fs+Bg9qBEjXy54LY2Nlgeee4PPo1nmBTOpEum7DAZOdPUds+9dxoU0w6DR2CmKp4pix8EDVm0FkzezUzZiJqvJUxv6LfvXTlYv00PrGRl/DOiBwo+jXebtRnMbpH8XTlxh8eY="
Dec 26 14:12:57 paulin volumio[3200]: info: Refreshing Cached IP Addresses
Dec 26 14:12:57 paulin sudo[3243]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0
Dec 26 14:12:57 paulin sudo[3243]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 26 14:12:57 paulin sudo[3245]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
Dec 26 14:12:57 paulin sudo[3245]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 26 14:12:57 paulin sudo[3243]: pam_unix(sudo:session): session closed for user root
Dec 26 14:12:57 paulin volumio[3200]: info: Loading plugin "services"...
Dec 26 14:12:57 paulin sudo[3245]: pam_unix(sudo:session): session closed for user root
Dec 26 14:12:57 paulin volumio[3200]: info: Loading plugin "alsa_controller"...
Dec 26 14:12:57 paulin sudo[3252]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan
Dec 26 14:12:57 paulin sudo[3252]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 26 14:12:57 paulin go-librespot[3234]: time="2025-12-26T14:12:57-03:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 26 14:12:57 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Dec 26 14:12:57 paulin volumio[3200]: info: Loading plugin "wizard"...
Dec 26 14:12:57 paulin volumio[3200]: info: Loading plugin "networkfs"...
Dec 26 14:12:57 paulin volumio[3200]: info: Starting Udev Watcher for removable devices
Dec 26 14:12:57 paulin volumio[3200]: info: Ignoring mount for partition: boot
Dec 26 14:12:57 paulin volumio[3200]: info: Ignoring mount for partition: volumio
Dec 26 14:12:57 paulin volumio[3200]: info: Ignoring mount for partition: volumio_data
Dec 26 14:12:57 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback
Dec 26 14:12:57 paulin volumio[3200]: info: Loading plugin "volumio_command_line_client"...
Dec 26 14:12:57 paulin go-librespot[3234]: time="2025-12-26T14:12:57-03:00" level=debug msg="completed keyexchange"
Dec 26 14:12:57 paulin go-librespot[3234]: time="2025-12-26T14:12:57-03:00" level=debug msg="completed challenge"
Dec 26 14:12:57 paulin volumio[3200]: info: Loading plugin "upnp"...
Dec 26 14:12:57 paulin volumio[3200]: info: [1766769177991] Starting Upmpd Daemon
Dec 26 14:12:57 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback
Dec 26 14:12:57 paulin volumio[3200]: info: Loading plugin "my_music"...
Dec 26 14:12:58 paulin volumio[3200]: info: Loading plugin "mpd"...
Dec 26 14:12:58 paulin go-librespot[3234]: time="2025-12-26T14:12:58-03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials "
Dec 26 14:12:58 paulin systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 26 14:12:58 paulin systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 26 14:12:58 paulin volumio[3200]: info: Loading plugin "upnp_browser"...
Dec 26 14:13:00 paulin sudo[3252]: pam_unix(sudo:session): session closed for user root
Dec 26 14:13:01 paulin systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6.
Dec 26 14:13:01 paulin systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 26 14:13:01 paulin volumio[3200]: info: Loading plugin "alarm-clock"...
Dec 26 14:13:01 paulin systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 26 14:13:01 paulin go-librespot[3279]: go-librespot daemon starting...
Dec 26 14:13:01 paulin go-librespot[3280]: time="2025-12-26T14:13:01-03:00" level=info msg="running go-librespot 0.4.0"
Dec 26 14:13:01 paulin go-librespot[3280]: time="2025-12-26T14:13:01-03:00" level=debug msg="app state loaded"
Dec 26 14:13:01 paulin go-librespot[3280]: time="2025-12-26T14:13:01-03:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 26 14:13:01 paulin volumio[3200]: info: Loading plugin "airplay_emulation"...
Dec 26 14:13:01 paulin volumio[3200]: info: Starting Shairport Sync
Dec 26 14:13:01 paulin volumio[3200]: info: Loading plugin "last_100"...
Dec 26 14:13:01 paulin volumio[3200]: info: Loading plugin "webradio"...
Dec 26 14:13:01 paulin volumio[3200]: info: Loading plugin "i2s_dacs"...
Dec 26 14:13:01 paulin volumio[3200]: info: I2S DAC not set, start Auto-detection
Dec 26 14:13:01 paulin volumio[3200]: info: Loading plugin "volumiodiscovery"...
Dec 26 14:13:01 paulin volumio[3200]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi.
Dec 26 14:13:01 paulin volumio[3200]: *** WARNING *** Please fix your application to use the native API of Avahi!
Dec 26 14:13:01 paulin volumio[3200]: *** WARNING *** For more information see
Dec 26 14:13:01 paulin volumio[3200]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi.
Dec 26 14:13:01 paulin volumio[3200]: *** WARNING *** Please fix your application to use the native API of Avahi!
Dec 26 14:13:01 paulin volumio[3200]: *** WARNING *** For more information see
Dec 26 14:13:01 paulin node[3200]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi.
Dec 26 14:13:01 paulin node[3200]: *** WARNING *** Please fix your application to use the native API of Avahi!
Dec 26 14:13:01 paulin node[3200]: *** WARNING *** For more information see
Dec 26 14:13:01 paulin node[3200]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi.
Dec 26 14:13:01 paulin node[3200]: *** WARNING *** Please fix your application to use the native API of Avahi!
Dec 26 14:13:01 paulin node[3200]: *** WARNING *** For more information see
Dec 26 14:13:01 paulin volumio[3200]: info: Applying required configuration parameters for plugin volumiodiscovery
Dec 26 14:13:01 paulin volumio[3200]: info: Discovery: Started advertising with name: Paulin
Dec 26 14:13:01 paulin go-librespot[3280]: time="2025-12-26T14:13:01-03:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]"
Dec 26 14:13:01 paulin go-librespot[3280]: time="2025-12-26T14:13:01-03:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]"
Dec 26 14:13:01 paulin go-librespot[3280]: time="2025-12-26T14:13:01-03:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]"
Dec 26 14:13:01 paulin go-librespot[3280]: time="2025-12-26T14:13:01-03:00" level=info msg="zeroconf server listening on port 38809"
Dec 26 14:13:01 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback
Dec 26 14:13:01 paulin volumio[3200]: info: Loading plugin "spop"...
Dec 26 14:13:02 paulin go-librespot[3280]: time="2025-12-26T14:13:02-03:00" level=debug msg="obtained new client token: AACGsvBEVlz416nI86lOFk25Q+V/x4u68IoUiO75CmR+dLPStwEfRPyr18w3JIZvPmc7fhjbbgfE+B5wN7lk0IDu4Y+rDINdOiPICXLG0qKeXuZfxzD0mSyuR0MCcQDTtVGiwn9MHThBpr6hNMz005aZ6fGZyVUCvZ18hT/IxdYojc06E+yFNVCCn367cnBYno/mq/7HecvXgJKUjC/u9d765krm82SG4HIAydILTS1OU/twyiaLalLV"
Dec 26 14:13:02 paulin go-librespot[3280]: time="2025-12-26T14:13:02-03:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 26 14:13:02 paulin go-librespot[3280]: time="2025-12-26T14:13:02-03:00" level=debug msg="completed keyexchange"
Dec 26 14:13:02 paulin go-librespot[3280]: time="2025-12-26T14:13:02-03:00" level=debug msg="completed challenge"
Dec 26 14:13:02 paulin go-librespot[3280]: time="2025-12-26T14:13:02-03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials "
Dec 26 14:13:02 paulin systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 26 14:13:02 paulin systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 26 14:13:03 paulin volumio[3200]: info: Loading plugin "outputs"...
Dec 26 14:13:03 paulin volumio[3200]: info: Loading plugin "albumart"...
Dec 26 14:13:03 paulin volumio[3200]: info: Plugin example_plugin is not enabled
Dec 26 14:13:03 paulin volumio[3200]: info: Loading plugin "inputs"...
Dec 26 14:13:03 paulin volumio[3200]: info: Loading plugin "updater_comm"...
Dec 26 14:13:03 paulin volumio[3200]: info: Plugin mpdemulation is not enabled
Dec 26 14:13:03 paulin volumio[3200]: info: Loading plugin "rest_api"...
Dec 26 14:13:03 paulin volumio[3200]: info: Loading plugin "websocket"...
Dec 26 14:13:03 paulin volumio[3200]: info: Starting Socket.io Server version 1.7.4
Dec 26 14:13:04 paulin volumio[3200]: info: Loading i18n strings for locale es
Dec 26 14:13:04 paulin volumio[3200]: Updating browse sources language
Dec 26 14:13:04 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 26 14:13:04 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 26 14:13:04 paulin volumio[3200]: info: CoreCommandRouter::initPlayerControls
Dec 26 14:13:04 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 26 14:13:04 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 26 14:13:04 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 26 14:13:04 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 26 14:13:04 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 26 14:13:04 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 26 14:13:04 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 26 14:13:04 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 26 14:13:04 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 26 14:13:04 paulin volumio[3200]: Express server listening on port 3000
Dec 26 14:13:04 paulin volumio[3200]: [Metrics] WebUI: 10s 953.72ms
Dec 26 14:13:04 paulin volumio[3200]: info: CoreStateMachine::resetVolumioState
Dec 26 14:13:04 paulin volumio[3200]: info: CoreStateMachine::getcurrentVolume
Dec 26 14:13:04 paulin volumio[3200]: info: CoreCommandRouter::volumioRetrievevolume
Dec 26 14:13:04 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 26 14:13:04 paulin volumio[3200]: info: Volumio Network Manager: Network status updated: 1
Dec 26 14:13:04 paulin volumio[3200]: verbose: New Socket.io Connection to 192.168.10.8 from 192.168.10.11 UA: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/143.0.0.0 Safari/537.36 Edg/143.0.0.0 Engine version: 3 Transport: polling Total Clients: 1
Dec 26 14:13:04 paulin volumio[3200]: info: VolumeController:: Volume=66 Mute =false
Dec 26 14:13:04 paulin volumio[3200]: info: CoreStateMachine::pushState
Dec 26 14:13:04 paulin volumio[3200]: info: CorePlayQueue::getTrack 0
Dec 26 14:13:04 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Dec 26 14:13:04 paulin volumio[3200]: info: CoreCommandRouter::volumioPushState
Dec 26 14:13:04 paulin volumio[3290]: Forking 3 albumart workers
Dec 26 14:13:04 paulin volumio[3200]: info: CoreStateMachine::updateTrackBlock
Dec 26 14:13:04 paulin volumio[3200]: info: CorePlayQueue::getTrackBlock
Dec 26 14:13:04 paulin volumio[3200]: info: CoreCommandRouter::volumioRetrievevolume
Dec 26 14:13:04 paulin volumio[3200]: info: Reloading queue from file
Dec 26 14:13:04 paulin volumio[3200]: info: CoreStateMachine::setRepeat true single undefined
Dec 26 14:13:04 paulin volumio[3200]: info: CoreStateMachine::pushState
Dec 26 14:13:04 paulin volumio[3200]: info: CorePlayQueue::getTrack 0
Dec 26 14:13:04 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Dec 26 14:13:04 paulin volumio[3200]: info: CoreCommandRouter::volumioPushState
Dec 26 14:13:04 paulin volumio[3200]: info: CoreStateMachine::setRandom null
Dec 26 14:13:04 paulin volumio[3200]: info: CoreStateMachine::pushState
Dec 26 14:13:04 paulin volumio[3200]: info: CorePlayQueue::getTrack 0
Dec 26 14:13:04 paulin volumio[3200]: info: CoreCommandRouter::volumioPushState
Dec 26 14:13:04 paulin volumio[3200]: info: Setting Device type: Raspberry PI
Dec 26 14:13:05 paulin volumio[3200]: info: VolumeController:: Volume=66 Mute =false
Dec 26 14:13:05 paulin volumio[3200]: info: CoreStateMachine::pushState
Dec 26 14:13:05 paulin volumio[3200]: info: CorePlayQueue::getTrack 0
Dec 26 14:13:05 paulin volumio[3200]: info: CoreCommandRouter::volumioPushState
Dec 26 14:13:05 paulin volumio[3200]: info: Completed loading Core Plugins
Dec 26 14:13:05 paulin volumio[3200]: info: Preparing to generate the ALSA configuration file
Dec 26 14:13:05 paulin volumio[3200]: info: Discovery: adding 2faea66e-cdcc-4cb2-b575-db76a09e79cb
Dec 26 14:13:05 paulin volumio[3200]: info: Discovery: Found device Paulin
Dec 26 14:13:05 paulin volumio[3200]: info: CoreCommandRouter::volumioGetState
Dec 26 14:13:05 paulin volumio[3200]: info: CorePlayQueue::getTrack 0
Dec 26 14:13:05 paulin volumio[3200]: info: Discovery: this is already registered, 2faea66e-cdcc-4cb2-b575-db76a09e79cb
Dec 26 14:13:05 paulin volumio[3200]: info: Discovery: Found device Paulin
Dec 26 14:13:05 paulin volumio[3200]: info: CoreCommandRouter::volumioGetState
Dec 26 14:13:05 paulin volumio[3200]: info: CorePlayQueue::getTrack 0
Dec 26 14:13:05 paulin volumio[3200]: info: Asound.conf file unchanged, so no further update is needed
Dec 26 14:13:05 paulin volumio[3200]: info: Output device has changed, restarting MPD
Dec 26 14:13:05 paulin volumio[3200]: info: Output device has changed, restarting Shairport Sync
Dec 26 14:13:05 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 26 14:13:05 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 26 14:13:05 paulin sudo[3346]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf
Dec 26 14:13:05 paulin sudo[3346]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 26 14:13:05 paulin sudo[3346]: pam_unix(sudo:session): session closed for user root
Dec 26 14:13:05 paulin sudo[3347]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service
Dec 26 14:13:05 paulin sudo[3347]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 26 14:13:05 paulin volumio[3200]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
Dec 26 14:13:05 paulin volumio[3200]: info: ___________ START PLUGINS ___________
Dec 26 14:13:05 paulin volumio[3200]: info: ControllerMpd::onStart: Initializing MPD
Dec 26 14:13:05 paulin volumio[3200]: info: Creating MPD Configuration file
Dec 26 14:13:05 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 26 14:13:05 paulin volumio[3200]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 26 14:13:05 paulin volumio[3200]: info: [1766769185370] CoreMusicLibrary::Adding element Media Servers
Dec 26 14:13:05 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 26 14:13:05 paulin systemd[1]: Stopping mpd.service - Music Player Daemon...
Dec 26 14:13:05 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 26 14:13:05 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 26 14:13:05 paulin sudo[3357]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service
Dec 26 14:13:05 paulin sudo[3357]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 26 14:13:05 paulin sudo[3355]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf
Dec 26 14:13:05 paulin sudo[3355]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 26 14:13:05 paulin sudo[3355]: pam_unix(sudo:session): session closed for user root
Dec 26 14:13:05 paulin volumio[3200]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
Dec 26 14:13:05 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 26 14:13:05 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 26 14:13:05 paulin systemd[1]: mpd.service: Deactivated successfully.
Dec 26 14:13:05 paulin volumio[3200]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
Dec 26 14:13:05 paulin systemd[1]: Stopped mpd.service - Music Player Daemon.
Dec 26 14:13:05 paulin systemd[1]: mpd.service: Consumed 3.707s CPU time.
Dec 26 14:13:05 paulin volumio[3200]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 26 14:13:05 paulin volumio[3200]: info: [1766769185614] CoreMusicLibrary::Adding element Last_100
Dec 26 14:13:05 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 26 14:13:05 paulin systemd[1]: mpd.socket: Deactivated successfully.
Dec 26 14:13:05 paulin systemd[1]: Closed mpd.socket - Music Player Daemon Socket.
Dec 26 14:13:05 paulin systemd[1]: Stopping mpd.socket - Music Player Daemon Socket...
Dec 26 14:13:05 paulin volumio[3200]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 26 14:13:05 paulin volumio[3200]: info: [1766769185635] CoreMusicLibrary::Adding element Webradio
Dec 26 14:13:05 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 26 14:13:05 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Dec 26 14:13:05 paulin volumio[3200]: info: Initializing BBC Radios
Dec 26 14:13:05 paulin systemd[1]: Listening on mpd.socket - Music Player Daemon Socket.
Dec 26 14:13:05 paulin systemd[1]: Starting mpd.service - Music Player Daemon...
Dec 26 14:13:05 paulin systemd[1]: mpd.service: Deactivated successfully.
Dec 26 14:13:05 paulin systemd[1]: Stopped mpd.service - Music Player Daemon.
Dec 26 14:13:05 paulin systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7.
Dec 26 14:13:05 paulin systemd[1]: mpd.socket: Deactivated successfully.
Dec 26 14:13:05 paulin systemd[1]: Closed mpd.socket - Music Player Daemon Socket.
Dec 26 14:13:05 paulin systemd[1]: Stopping mpd.socket - Music Player Daemon Socket...
Dec 26 14:13:05 paulin systemd[1]: Listening on mpd.socket - Music Player Daemon Socket.
Dec 26 14:13:05 paulin systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 26 14:13:05 paulin systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 26 14:13:05 paulin go-librespot[3381]: go-librespot daemon starting...
Dec 26 14:13:05 paulin systemd[1]: Starting mpd.service - Music Player Daemon...
Dec 26 14:13:05 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Dec 26 14:13:05 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 26 14:13:05 paulin go-librespot[3386]: time="2025-12-26T14:13:05-03:00" level=info msg="running go-librespot 0.4.0"
Dec 26 14:13:05 paulin go-librespot[3386]: time="2025-12-26T14:13:05-03:00" level=debug msg="app state loaded"
Dec 26 14:13:05 paulin go-librespot[3386]: time="2025-12-26T14:13:05-03:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 26 14:13:05 paulin volumio[3200]: info: Creating Spotify config file
Dec 26 14:13:05 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 26 14:13:06 paulin sudo[3385]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log
Dec 26 14:13:06 paulin sudo[3385]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0)
Dec 26 14:13:06 paulin sudo[3385]: pam_unix(sudo:session): session closed for user root
Dec 26 14:13:06 paulin go-librespot[3386]: time="2025-12-26T14:13:06-03:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]"
Dec 26 14:13:06 paulin go-librespot[3386]: time="2025-12-26T14:13:06-03:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]"
Dec 26 14:13:06 paulin go-librespot[3386]: time="2025-12-26T14:13:06-03:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]"
Dec 26 14:13:06 paulin go-librespot[3386]: time="2025-12-26T14:13:06-03:00" level=info msg="zeroconf server listening on port 33935"
Dec 26 14:13:06 paulin go-librespot[3386]: time="2025-12-26T14:13:06-03:00" level=debug msg="obtained new client token: AAC4K59rpRtkTMbLCiZAmzhhS9tuzjZ14CAD0D9BFYLnO52S9FXckc4sayUaR2LgMI8Cujd8E1QR3RaZYFGJH9fwPIE7FySXwi2er+X4h5q4hixNcpkgCn5qnWDzo2Mmxe/UHFEyOFmW7f/lHaTTBkUstQ8gwNWHX0Ds/tZnwbcShaYSP70VhfZG1m/8b15EZX0AbZ0oht5zBLaiksjcnimVjZpAht1Dmq2CMi7Pg0MGxtpiOhmLJX3KbKI="
Dec 26 14:13:06 paulin go-librespot[3386]: time="2025-12-26T14:13:06-03:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 26 14:13:07 paulin go-librespot[3386]: time="2025-12-26T14:13:07-03:00" level=debug msg="completed keyexchange"
Dec 26 14:13:07 paulin go-librespot[3386]: time="2025-12-26T14:13:07-03:00" level=debug msg="completed challenge"
Dec 26 14:13:07 paulin volumio[3200]: info: Volumio Calling Home
Dec 26 14:13:07 paulin go-librespot[3386]: time="2025-12-26T14:13:07-03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials "
Dec 26 14:13:07 paulin systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 26 14:13:07 paulin systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 26 14:13:07 paulin volumio[3309]: Starting albumart workers
Dec 26 14:13:07 paulin volumio[3308]: Starting albumart workers
Dec 26 14:13:08 paulin sudo[3415]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0
Dec 26 14:13:08 paulin sudo[3415]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 26 14:13:08 paulin sudo[3415]: pam_unix(sudo:session): session closed for user root
Dec 26 14:13:08 paulin volumio[3200]: info: MPD Permissions set
Dec 26 14:13:08 paulin volumio[3200]: info: MPD Permissions set
Dec 26 14:13:08 paulin volumio[3307]: Starting albumart workers
Dec 26 14:13:08 paulin sudo[3417]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
Dec 26 14:13:08 paulin volumio[3200]: info: Volumio called home
Dec 26 14:13:08 paulin volumio[3200]: info: Spotify config file written
Dec 26 14:13:08 paulin sudo[3417]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 26 14:13:08 paulin sudo[3417]: pam_unix(sudo:session): session closed for user root
Dec 26 14:13:08 paulin sudo[3421]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service
Dec 26 14:13:08 paulin volumio-remote-updater[657]: [2025-12-26 14:13:08] [connect] Successful connection
Dec 26 14:13:08 paulin sudo[3421]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 26 14:13:08 paulin volumio[3200]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2
Dec 26 14:13:08 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 26 14:13:08 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 26 14:13:08 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 26 14:13:08 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 26 14:13:08 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 26 14:13:08 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 26 14:13:08 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 26 14:13:08 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 26 14:13:08 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 26 14:13:08 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 26 14:13:08 paulin systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 26 14:13:08 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 26 14:13:08 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 26 14:13:08 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 26 14:13:08 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 26 14:13:08 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 26 14:13:08 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 26 14:13:08 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 26 14:13:08 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 26 14:13:08 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 26 14:13:08 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 26 14:13:08 paulin volumio[3200]: info: No need to fix Spotify hosts
Dec 26 14:13:08 paulin systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 26 14:13:08 paulin go-librespot[3428]: go-librespot daemon starting...
Dec 26 14:13:08 paulin sudo[3421]: pam_unix(sudo:session): session closed for user root
Dec 26 14:13:09 paulin go-librespot[3434]: time="2025-12-26T14:13:09-03:00" level=info msg="running go-librespot 0.4.0"
Dec 26 14:13:09 paulin go-librespot[3434]: time="2025-12-26T14:13:09-03:00" level=debug msg="app state loaded"
Dec 26 14:13:09 paulin go-librespot[3434]: time="2025-12-26T14:13:09-03:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 26 14:13:09 paulin volumio-remote-updater[657]: [2025-12-26 14:13:09] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1766769188 101
Dec 26 14:13:09 paulin volumio[3200]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 3
Dec 26 14:13:09 paulin volumio[3200]: info: Starting Shairport Sync
Dec 26 14:13:09 paulin volumio[3200]: info: Starting Shairport Sync
Dec 26 14:13:09 paulin go-librespot[3434]: time="2025-12-26T14:13:09-03:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 26 14:13:09 paulin go-librespot[3434]: time="2025-12-26T14:13:09-03:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 26 14:13:09 paulin go-librespot[3434]: time="2025-12-26T14:13:09-03:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 26 14:13:09 paulin go-librespot[3434]: time="2025-12-26T14:13:09-03:00" level=info msg="zeroconf server listening on port 36193"
Dec 26 14:13:09 paulin volumio[3200]: info: Starting Shairport Sync
Dec 26 14:13:09 paulin sudo[3453]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
Dec 26 14:13:09 paulin sudo[3453]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 26 14:13:09 paulin volumio[3200]: info: An error occurred while refreshing Spotify Token Error: Bad Request
Dec 26 14:13:09 paulin sudo[3445]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
Dec 26 14:13:09 paulin sudo[3460]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service
Dec 26 14:13:09 paulin sudo[3445]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 26 14:13:09 paulin sudo[3460]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 26 14:13:09 paulin sudo[3451]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
Dec 26 14:13:09 paulin sudo[3451]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 26 14:13:09 paulin systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver...
Dec 26 14:13:09 paulin systemd[1]: shairport-sync.service: Deactivated successfully.
Dec 26 14:13:09 paulin systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 26 14:13:09 paulin systemd[1]: shairport-sync.service: Consumed 2.102s CPU time.
Dec 26 14:13:09 paulin go-librespot[3434]: time="2025-12-26T14:13:09-03:00" level=debug msg="obtained new client token: AABRTvatJmwMP6pd6ugSYkKK449tFRKyfVx16tI4lJzTDP0kmFJbhRYhnyczppxLe1G0YA5yfVLXxyYSDuovo0nVk3mE369gmCCgzj4TQKkZi+lAzXkSXB/NEQQFxA2yoaeROHpz3vAjXU2ukqqJ6hzxCocz/wL5uYPI3cvacVVKd8HT+dw8lUkulGi1dh7NO26WTkfTTarmBGa7+4hhMQ8h+cxnXZuZV2E23Uo8oPFMlnW/35ebiEC+nzY="
Dec 26 14:13:09 paulin systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 26 14:13:09 paulin sudo[3453]: pam_unix(sudo:session): session closed for user root
Dec 26 14:13:09 paulin systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver...
Dec 26 14:13:09 paulin sudo[3460]: pam_unix(sudo:session): session closed for user root
Dec 26 14:13:09 paulin systemd[1]: shairport-sync.service: Deactivated successfully.
Dec 26 14:13:09 paulin systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 26 14:13:09 paulin go-librespot[3434]: time="2025-12-26T14:13:09-03:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 26 14:13:09 paulin volumio[3200]: info: Upmpdcli Daemon Started
Dec 26 14:13:09 paulin volumio[3200]: info: Shairport-Sync Started
Dec 26 14:13:09 paulin volumio[3200]: Error adding Membership: Error: addMembership EINVAL
Dec 26 14:13:09 paulin systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 26 14:13:09 paulin sudo[3451]: pam_unix(sudo:session): session closed for user root
Dec 26 14:13:09 paulin sudo[3445]: pam_unix(sudo:session): session closed for user root
Dec 26 14:13:10 paulin volumio[3200]: info: CoreCommandRouter::volumioGetState
Dec 26 14:13:10 paulin volumio[3200]: info: CorePlayQueue::getTrack 0
Dec 26 14:13:10 paulin volumio[3200]: info: Shairport-Sync Started
Dec 26 14:13:10 paulin go-librespot[3434]: time="2025-12-26T14:13:10-03:00" level=debug msg="completed keyexchange"
Dec 26 14:13:10 paulin go-librespot[3434]: time="2025-12-26T14:13:10-03:00" level=debug msg="completed challenge"
Dec 26 14:13:10 paulin volumio[3200]: info: Shairport-Sync Started
Dec 26 14:13:10 paulin go-librespot[3434]: time="2025-12-26T14:13:10-03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials "
Dec 26 14:13:10 paulin systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 26 14:13:10 paulin systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 26 14:13:11 paulin sudo[3499]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0
Dec 26 14:13:11 paulin sudo[3499]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 26 14:13:11 paulin sudo[3499]: pam_unix(sudo:session): session closed for user root
Dec 26 14:13:11 paulin sudo[3501]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
Dec 26 14:13:11 paulin sudo[3501]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 26 14:13:11 paulin sudo[3501]: pam_unix(sudo:session): session closed for user root
Dec 26 14:13:11 paulin volumio[3200]: verbose: New Socket.io Connection to 192.168.10.8 from 192.168.10.17 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/143.0.0.0 Safari/537.36 Edg/143.0.0.0 Engine version: 3 Transport: polling Total Clients: 4
Dec 26 14:13:11 paulin mpd[3396]: 2025-12-26T14:13:11 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg
Dec 26 14:13:11 paulin systemd[1]: Started mpd.service - Music Player Daemon.
Dec 26 14:13:11 paulin sudo[3347]: pam_unix(sudo:session): session closed for user root
Dec 26 14:13:11 paulin sudo[3357]: pam_unix(sudo:session): session closed for user root
Dec 26 14:13:11 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled
Dec 26 14:13:11 paulin volumio[3200]: info: Completed starting Core Plugins
Dec 26 14:13:11 paulin volumio[3200]: info: -------------------------------------------
Dec 26 14:13:11 paulin volumio[3200]: info: ----- MyVolumio plugins startup ----
Dec 26 14:13:11 paulin volumio[3200]: info: -------------------------------------------
Dec 26 14:13:11 paulin volumio[3200]: info: [MyVolumio PluginManager] Fetching plans data....
Dec 26 14:13:11 paulin volumio[3200]: error: MPD error: The expression evaluated to a falsy value:
Dec 26 14:13:11 paulin volumio[3200]: assert.ok(self.idling)
Dec 26 14:13:11 paulin volumio[3200]: error: The expression evaluated to a falsy value:
Dec 26 14:13:11 paulin volumio[3200]: assert.ok(self.idling)
Dec 26 14:13:11 paulin volumio[3200]: error: updateQueue error: null
Dec 26 14:13:11 paulin volumio[3200]: info: CoreCommandRouter::volumioGetVisibleSources
Dec 26 14:13:11 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 26 14:13:11 paulin volumio[3200]: info: CoreCommandRouter::volumioGetState
Dec 26 14:13:11 paulin volumio[3200]: info: CorePlayQueue::getTrack 0
Dec 26 14:13:11 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback
Dec 26 14:13:11 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom
Dec 26 14:13:11 paulin volumio[3200]: info: Received Get System Info
Dec 26 14:13:11 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo
Dec 26 14:13:11 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice
Dec 26 14:13:11 paulin volumio[3200]: info: Discovery: Getting this device information
Dec 26 14:13:11 paulin volumio[3200]: info: CoreCommandRouter::volumioGetState
Dec 26 14:13:11 paulin volumio[3200]: info: CorePlayQueue::getTrack 0
Dec 26 14:13:11 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses
Dec 26 14:13:11 paulin volumio[3200]: info: CoreCommandRouter::volumioGetState
Dec 26 14:13:11 paulin volumio[3200]: info: CorePlayQueue::getTrack 0
Dec 26 14:13:11 paulin volumio[3200]: info: Listing playlists
Dec 26 14:13:11 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings
Dec 26 14:13:11 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings
Dec 26 14:13:11 paulin volumio[3200]: info: MPD running with PID3396
Dec 26 14:13:11 paulin volumio[3200]: ,establishing connection
Dec 26 14:13:11 paulin volumio[3200]: error: updateQueue error: null
Dec 26 14:13:11 paulin sudo[3509]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0
Dec 26 14:13:11 paulin sudo[3509]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 26 14:13:11 paulin sudo[3509]: pam_unix(sudo:session): session closed for user root
Dec 26 14:13:11 paulin sudo[3511]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
Dec 26 14:13:11 paulin sudo[3511]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 26 14:13:11 paulin sudo[3511]: pam_unix(sudo:session): session closed for user root
Dec 26 14:13:11 paulin volumio[3200]: verbose: New Socket.io Connection to 192.168.10.8 from 192.168.10.17 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/143.0.0.0 Safari/537.36 Edg/143.0.0.0 Engine version: 3 Transport: polling Total Clients: 4
Dec 26 14:13:11 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled
Dec 26 14:13:11 paulin volumio[3200]: info: CoreCommandRouter::volumioGetVisibleSources
Dec 26 14:13:11 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 26 14:13:11 paulin volumio[3200]: info: CoreCommandRouter::volumioGetState
Dec 26 14:13:11 paulin volumio[3200]: info: CorePlayQueue::getTrack 0
Dec 26 14:13:11 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback
Dec 26 14:13:11 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom
Dec 26 14:13:11 paulin volumio[3200]: info: Received Get System Info
Dec 26 14:13:11 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo
Dec 26 14:13:11 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice
Dec 26 14:13:11 paulin volumio[3200]: info: Discovery: Getting this device information
Dec 26 14:13:11 paulin volumio[3200]: info: CoreCommandRouter::volumioGetState
Dec 26 14:13:11 paulin volumio[3200]: info: CorePlayQueue::getTrack 0
Dec 26 14:13:11 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses
Dec 26 14:13:11 paulin volumio[3200]: info: CoreCommandRouter::volumioGetState
Dec 26 14:13:11 paulin volumio[3200]: info: CorePlayQueue::getTrack 0
Dec 26 14:13:12 paulin volumio[3200]: info: Listing playlists
Dec 26 14:13:12 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings
Dec 26 14:13:12 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings
Dec 26 14:13:12 paulin kernel: hwmon hwmon1: Voltage normalised
Dec 26 14:13:12 paulin volumio[3200]: info: go-librespot daemon successfully initialized
Dec 26 14:13:12 paulin volumio[3200]: info: CoreCommandRouter::volumioGetState
Dec 26 14:13:12 paulin volumio[3200]: info: CorePlayQueue::getTrack 0
Dec 26 14:13:13 paulin systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8.
Dec 26 14:13:13 paulin systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 26 14:13:13 paulin systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 26 14:13:13 paulin go-librespot[3515]: go-librespot daemon starting...
Dec 26 14:13:13 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard
Dec 26 14:13:13 paulin go-librespot[3516]: time="2025-12-26T14:13:13-03:00" level=info msg="running go-librespot 0.4.0"
Dec 26 14:13:13 paulin go-librespot[3516]: time="2025-12-26T14:13:13-03:00" level=debug msg="app state loaded"
Dec 26 14:13:13 paulin go-librespot[3516]: time="2025-12-26T14:13:13-03:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 26 14:13:13 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus
Dec 26 14:13:13 paulin volumio[3200]: info: Received Get System Info
Dec 26 14:13:13 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo
Dec 26 14:13:13 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice
Dec 26 14:13:13 paulin volumio[3200]: info: Discovery: Getting this device information
Dec 26 14:13:13 paulin volumio[3200]: info: CoreCommandRouter::volumioGetState
Dec 26 14:13:13 paulin volumio[3200]: info: CorePlayQueue::getTrack 0
Dec 26 14:13:13 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses
Dec 26 14:13:14 paulin go-librespot[3516]: time="2025-12-26T14:13:14-03:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 26 14:13:14 paulin go-librespot[3516]: time="2025-12-26T14:13:14-03:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 26 14:13:14 paulin go-librespot[3516]: time="2025-12-26T14:13:14-03:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 26 14:13:14 paulin go-librespot[3516]: time="2025-12-26T14:13:14-03:00" level=info msg="zeroconf server listening on port 38573"
Dec 26 14:13:14 paulin go-librespot[3516]: time="2025-12-26T14:13:14-03:00" level=debug msg="obtained new client token: AAC4B0Z+d5dbXIAXHwMNIL/1UmnwEm/7XZKON7x43nbnTLhcpeHaiNPu4c3Ms4ZMXhvYbedWUCJzMQUEKSqMuxEb2QK83jwLigY6WWyiIrDXGggBFEeRomMLD0bZCV5202Cy0sx+tVkZqHzRXZq/nXx6OX8BrpDnXNNbgK7dPrBFQe/v09UlYegErNNG5S4Tu63CPpFrSo1qf1WtoB7h16RNDX/k42D8jhgJuATPVbBAd20cpOLOC3SR"
Dec 26 14:13:14 paulin kernel: hwmon hwmon1: Undervoltage detected!
Dec 26 14:13:14 paulin go-librespot[3516]: time="2025-12-26T14:13:14-03:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 26 14:13:14 paulin sudo[3524]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service
Dec 26 14:13:14 paulin sudo[3524]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 26 14:13:14 paulin sudo[3526]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service
Dec 26 14:13:14 paulin sudo[3526]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 26 14:13:14 paulin systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service...
Dec 26 14:13:14 paulin systemd[1]: mpd_monitor.service: Deactivated successfully.
Dec 26 14:13:14 paulin systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service.
Dec 26 14:13:14 paulin go-librespot[3516]: time="2025-12-26T14:13:14-03:00" level=debug msg="completed keyexchange"
Dec 26 14:13:14 paulin go-librespot[3516]: time="2025-12-26T14:13:14-03:00" level=debug msg="completed challenge"
Dec 26 14:13:14 paulin systemd[1]: Started mpd_monitor.service - MPD Monitor Service.
Dec 26 14:13:14 paulin sudo[3524]: pam_unix(sudo:session): session closed for user root
Dec 26 14:13:14 paulin sudo[3526]: pam_unix(sudo:session): session closed for user root
Dec 26 14:13:14 paulin mpd_monitor.sh[3529]: MPD Monitor Service: Starting MPD Monitor Service
Dec 26 14:13:14 paulin volumio[3200]: info: Successfully started MPD Monitor
Dec 26 14:13:14 paulin volumio[3200]: info: Successfully started MPD Monitor
Dec 26 14:13:14 paulin go-librespot[3516]: time="2025-12-26T14:13:14-03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials "
Dec 26 14:13:14 paulin systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 26 14:13:14 paulin systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 26 14:13:15 paulin volumio[3200]: info: Initializing connection to go-librespot Websocket
Dec 26 14:13:15 paulin volumio[3200]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 26 14:13:16 paulin volumio[3200]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory
Dec 26 14:13:16 paulin volumio[3200]: info: CoreCommandRouter::getUIConfigOnPlugin
Dec 26 14:13:16 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam
Dec 26 14:13:16 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam
Dec 26 14:13:16 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam
Dec 26 14:13:16 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: appearance , getAvailableUIs
Dec 26 14:13:16 paulin volumio[3200]: info: Received Get System Version
Dec 26 14:13:16 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Dec 26 14:13:17 paulin systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 9.
Dec 26 14:13:17 paulin systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 26 14:13:18 paulin systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 26 14:13:18 paulin go-librespot[3550]: go-librespot daemon starting...
Dec 26 14:13:18 paulin go-librespot[3565]: time="2025-12-26T14:13:18-03:00" level=info msg="running go-librespot 0.4.0"
Dec 26 14:13:18 paulin go-librespot[3565]: time="2025-12-26T14:13:18-03:00" level=debug msg="app state loaded"
Dec 26 14:13:18 paulin go-librespot[3565]: time="2025-12-26T14:13:18-03:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 26 14:13:18 paulin volumio[3200]: info: Initializing connection to go-librespot Websocket
Dec 26 14:13:18 paulin go-librespot[3565]: time="2025-12-26T14:13:18-03:00" level=debug msg="new websocket client"
Dec 26 14:13:18 paulin volumio[3200]: info: Connection to go-librespot Websocket established
Dec 26 14:13:18 paulin go-librespot[3565]: time="2025-12-26T14:13:18-03:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 26 14:13:18 paulin go-librespot[3565]: time="2025-12-26T14:13:18-03:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 26 14:13:18 paulin go-librespot[3565]: time="2025-12-26T14:13:18-03:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 26 14:13:18 paulin go-librespot[3565]: time="2025-12-26T14:13:18-03:00" level=info msg="zeroconf server listening on port 39213"
Dec 26 14:13:18 paulin go-librespot[3565]: time="2025-12-26T14:13:18-03:00" level=debug msg="obtained new client token: AABiqg/8GChJIMd0f+KYQlpaSR/tySOY2ELriE7xbCpu6HdN1gVElHr2+OUIrZD6oXgI3pL+fAa8H/APHO30L1lHAMbgO6q8iQ+Ak+Iz3FjHZWO3J4RnKevrMib+ytD5Cbd/r5qzRVL1rbn775i4HUaalQJNLmY9LdmoRQoNdv5w0jifrsRI9XCstrYHBk2IU1xfGRgZTe68LWhcJIjREDMGWTOaMOqlPCQtzPB1DettI5PG24RTyI+TpTg="
Dec 26 14:13:18 paulin go-librespot[3565]: time="2025-12-26T14:13:18-03:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 26 14:13:19 paulin volumio[3200]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium
Dec 26 14:13:19 paulin volumio[3200]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium
Dec 26 14:13:19 paulin volumio[3200]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium
Dec 26 14:13:19 paulin volumio[3200]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium
Dec 26 14:13:19 paulin volumio[3200]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium
Dec 26 14:13:19 paulin volumio[3200]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium
Dec 26 14:13:19 paulin volumio[3200]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium
Dec 26 14:13:19 paulin volumio[3200]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium
Dec 26 14:13:19 paulin volumio[3200]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium
Dec 26 14:13:19 paulin volumio[3200]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium
Dec 26 14:13:19 paulin volumio[3200]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium
Dec 26 14:13:19 paulin volumio[3200]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar
Dec 26 14:13:19 paulin volumio[3200]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar
Dec 26 14:13:19 paulin volumio[3200]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar
Dec 26 14:13:19 paulin volumio[3200]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar
Dec 26 14:13:19 paulin volumio[3200]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar
Dec 26 14:13:19 paulin volumio[3200]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar
Dec 26 14:13:19 paulin volumio[3200]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar
Dec 26 14:13:19 paulin volumio[3200]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar
Dec 26 14:13:19 paulin volumio[3200]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar
Dec 26 14:13:19 paulin volumio[3200]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar
Dec 26 14:13:19 paulin volumio[3200]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar
Dec 26 14:13:19 paulin volumio[3200]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso
Dec 26 14:13:19 paulin volumio[3200]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso
Dec 26 14:13:19 paulin volumio[3200]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso
Dec 26 14:13:19 paulin volumio[3200]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso
Dec 26 14:13:19 paulin volumio[3200]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso
Dec 26 14:13:19 paulin volumio[3200]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso
Dec 26 14:13:19 paulin volumio[3200]: info: Adding plugin bluetooth to MyMusic Plugins
Dec 26 14:13:19 paulin volumio[3200]: info: Adding plugin multiroom to MyMusic Plugins
Dec 26 14:13:19 paulin volumio[3200]: info: Adding plugin metavolumio to MyMusic Plugins
Dec 26 14:13:19 paulin volumio[3200]: info: Adding plugin cd_controller to MyMusic Plugins
Dec 26 14:13:19 paulin volumio[3200]: info: Adding plugin qobuzconnect to MyMusic Plugins
Dec 26 14:13:19 paulin volumio[3200]: info: Adding plugin smart_inputs to MyMusic Plugins
Dec 26 14:13:19 paulin volumio[3200]: info: Adding plugin tidalconnect to MyMusic Plugins
Dec 26 14:13:19 paulin volumio[3200]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"...
Dec 26 14:13:20 paulin go-librespot[3565]: time="2025-12-26T14:13:20-03:00" level=debug msg="completed keyexchange"
Dec 26 14:13:20 paulin go-librespot[3565]: time="2025-12-26T14:13:20-03:00" level=debug msg="completed challenge"
Dec 26 14:13:20 paulin go-librespot[3565]: time="2025-12-26T14:13:20-03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials "
Dec 26 14:13:20 paulin systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 26 14:13:20 paulin systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 26 14:13:21 paulin volumio[3200]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded
Dec 26 14:13:21 paulin volumio[3200]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio
Dec 26 14:13:21 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 26 14:13:21 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 26 14:13:21 paulin volumio[3200]: info: Starting MyVolumio Remote Streaming Endpoints
Dec 26 14:13:21 paulin volumio[3200]: info: MyVolumio login type: Token
Dec 26 14:13:21 paulin volumio[3200]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started
Dec 26 14:13:21 paulin volumio[3200]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"...
Dec 26 14:13:23 paulin volumio[3200]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded
Dec 26 14:13:23 paulin volumio[3200]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services
Dec 26 14:13:23 paulin volumio[3200]: info: Streaming services startup
Dec 26 14:13:23 paulin volumio[3200]: info: Starting Streaming Daemon
Dec 26 14:13:23 paulin sudo[3573]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service
Dec 26 14:13:23 paulin sudo[3573]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 26 14:13:23 paulin volumio[3200]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started
Dec 26 14:13:23 paulin sudo[3573]: pam_unix(sudo:session): session closed for user root
Dec 26 14:13:23 paulin volumio[3200]: info: Getting Spotify volume
Dec 26 14:13:23 paulin volumio[3200]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted
Dec 26 14:13:23 paulin volumio[3200]: |||||||||||||||||||||||| WARNING: FATAL ERROR |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Dec 26 14:13:23 paulin volumio[3200]: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 26 14:13:23 paulin volumio[3200]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) {
Dec 26 14:13:23 paulin volumio[3200]: errno: -111,
Dec 26 14:13:23 paulin volumio[3200]: code: 'ECONNREFUSED',
Dec 26 14:13:23 paulin volumio[3200]: syscall: 'connect',
Dec 26 14:13:23 paulin volumio[3200]: address: '127.0.0.1',
Dec 26 14:13:23 paulin volumio[3200]: port: 9879,
Dec 26 14:13:23 paulin volumio[3200]: response: undefined
Dec 26 14:13:23 paulin volumio[3200]: }
Dec 26 14:13:23 paulin volumio[3200]: |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Dec 26 14:13:23 paulin systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 10.
Dec 26 14:13:23 paulin systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 26 14:13:24 paulin systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 26 14:13:24 paulin go-librespot[3591]: go-librespot daemon starting...
Dec 26 14:13:24 paulin go-librespot[3592]: time="2025-12-26T14:13:24-03:00" level=info msg="running go-librespot 0.4.0"
Dec 26 14:13:24 paulin go-librespot[3592]: time="2025-12-26T14:13:24-03:00" level=debug msg="app state loaded"
Dec 26 14:13:24 paulin go-librespot[3592]: time="2025-12-26T14:13:24-03:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 26 14:13:24 paulin go-librespot[3592]: time="2025-12-26T14:13:24-03:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]"
Dec 26 14:13:24 paulin go-librespot[3592]: time="2025-12-26T14:13:24-03:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]"
Dec 26 14:13:24 paulin go-librespot[3592]: time="2025-12-26T14:13:24-03:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]"
Dec 26 14:13:24 paulin go-librespot[3592]: time="2025-12-26T14:13:24-03:00" level=info msg="zeroconf server listening on port 46391"
Dec 26 14:13:24 paulin go-librespot[3592]: time="2025-12-26T14:13:24-03:00" level=debug msg="obtained new client token: AAAvRZHQXLYGI7MOjFu6iOdn4JimovccJSVuc0PLfGAkecDafyUtaGJ9Bj9FVYAGPI0MtPLeSz3BaicnAUuy55WC84rFq75df/1RYn2zfCJoiHRiCOp/1deWPheWeqG1ov+USKCxp9TQQDnaTUOvtlwLk5mfQRUB2XdiaYV8Vrf/Si5vm4GA5pDTY/M1IzkFqVOlkSSaoL886XVqSCBYMlF8uBCalgyMBKk3J51EkTUCb+wExtEcdo0zZ4g="
Dec 26 14:13:24 paulin sudo[3601]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-26 14:12'
Dec 26 14:13:24 paulin sudo[3601]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 26 14:13:24 paulin go-librespot[3592]: time="2025-12-26T14:13:24-03:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
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="ec1ce6b3390e13e82b9cc0453f957c4f5298419e"
VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd"
VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2"
VOLUMIO_BE_VERSION="8bcc10c3dbcbcb349e9887dc0527d54876b32688"
VOLUMIO_ARCH="arm"
VOLUMIO_VARIANT="volumio"
VOLUMIO_TEST="FALSE"
VOLUMIO_BUILD_DATE="Mon Nov 17 16:31:40 UTC 2025"
VOLUMIO_VERSION="4.071"
VOLUMIO_HARDWARE="pi"
VOLUMIO_DEVICENAME="Raspberry Pi"
VOLUMIO_HASH="5fbe1bcf6936184712979c0bfaf061f2"