Jan 27 17:00:00 cx100 sudo[1728]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 17:00:00 cx100 systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 27 17:00:00 cx100 volumio-remote-updater[722]: [2026-01-27 17:00:00] [connect] Successful connection Jan 27 17:00:00 cx100 sudo[1731]: pam_unix(sudo:session): session closed for user root Jan 27 17:00:00 cx100 systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 27 17:00:00 cx100 systemd[1]: shairport-sync.service: Deactivated successfully. Jan 27 17:00:00 cx100 systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 27 17:00:00 cx100 systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 27 17:00:00 cx100 sudo[1726]: pam_unix(sudo:session): session closed for user root Jan 27 17:00:00 cx100 systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 27 17:00:00 cx100 systemd[1]: shairport-sync.service: Deactivated successfully. Jan 27 17:00:00 cx100 systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 27 17:00:00 cx100 systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 27 17:00:00 cx100 sudo[1728]: pam_unix(sudo:session): session closed for user root Jan 27 17:00:00 cx100 volumio[1175]: info: Discovery: Browse raised the following error Error: getaddrinfo -3007 Jan 27 17:00:00 cx100 volumio[1175]: info: Discovery: Restarting Browsing Jan 27 17:00:00 cx100 volumio[1175]: info: Discovery: Browse raised the following error Error: getaddrinfo -3007 Jan 27 17:00:00 cx100 volumio[1175]: info: Discovery: Restarting Browsing Jan 27 17:00:00 cx100 volumio[1175]: info: Discovery: Restart already pending, ignoring duplicate call Jan 27 17:00:00 cx100 volumio[1175]: error: updateQueue error: null Jan 27 17:00:00 cx100 volumio[1175]: info: Shairport-Sync Started Jan 27 17:00:00 cx100 volumio[1175]: Error adding Membership: Error: addMembership EINVAL Jan 27 17:00:00 cx100 volumio[1175]: info: Shairport-Sync Started Jan 27 17:00:00 cx100 volumio[1175]: info: Shairport-Sync Started Jan 27 17:00:00 cx100 volumio[1175]: info: Asound.conf file unchanged, so no further update is needed Jan 27 17:00:00 cx100 volumio[1175]: info: Output device has changed, restarting MPD Jan 27 17:00:00 cx100 sudo[1766]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 27 17:00:00 cx100 sudo[1766]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 17:00:00 cx100 sudo[1766]: pam_unix(sudo:session): session closed for user root Jan 27 17:00:00 cx100 volumio[1175]: info: Output device has changed, restarting Shairport Sync Jan 27 17:00:00 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:00:00 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 17:00:01 cx100 sudo[1769]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 27 17:00:01 cx100 sudo[1769]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 17:00:01 cx100 systemd[1]: Stopping mpd.service - Music Player Daemon... Jan 27 17:00:01 cx100 upmpdcli[1527]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 17:00:01 cx100 volumio[1175]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 27 17:00:01 cx100 volumio[1175]: info: go-librespot daemon successfully initialized Jan 27 17:00:01 cx100 systemd[1]: mpd.service: Deactivated successfully. Jan 27 17:00:01 cx100 systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 27 17:00:01 cx100 systemd[1]: mpd.service: Consumed 6.641s CPU time. Jan 27 17:00:01 cx100 systemd[1]: mpd.socket: Deactivated successfully. Jan 27 17:00:01 cx100 systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 27 17:00:01 cx100 systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 27 17:00:01 cx100 volumio[1175]: info: Discovery: Browse raised the following error Error: getaddrinfo -3007 Jan 27 17:00:01 cx100 volumio[1175]: info: Discovery: Restarting Browsing Jan 27 17:00:01 cx100 volumio[1175]: info: Discovery: Restart already pending, ignoring duplicate call Jan 27 17:00:01 cx100 systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 27 17:00:01 cx100 systemd[1]: Starting mpd.service - Music Player Daemon... Jan 27 17:00:02 cx100 volumio[1175]: info: MPD Permissions set Jan 27 17:00:02 cx100 sudo[1776]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 27 17:00:02 cx100 sudo[1776]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jan 27 17:00:02 cx100 sudo[1776]: pam_unix(sudo:session): session closed for user root Jan 27 17:00:02 cx100 volumio-remote-updater[722]: [2026-01-27 17:00:02] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1769529600 101 Jan 27 17:00:02 cx100 volumio[1175]: 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: 10 Jan 27 17:00:02 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:00:02 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:00:02 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:00:02 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:00:02 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:00:02 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:00:02 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:00:02 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:00:03 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 17:00:03 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:00:04 cx100 volumio[1175]: info: Starting Shairport Sync Jan 27 17:00:04 cx100 sudo[1785]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 27 17:00:04 cx100 sudo[1785]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 17:00:04 cx100 volumio[1175]: info: CoreCommandRouter::volumioGetState Jan 27 17:00:04 cx100 volumio[1175]: info: CorePlayQueue::getTrack 0 Jan 27 17:00:04 cx100 systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 27 17:00:04 cx100 systemd[1]: shairport-sync.service: Deactivated successfully. Jan 27 17:00:04 cx100 systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 27 17:00:04 cx100 systemd[1]: shairport-sync.service: Consumed 1.343s CPU time. Jan 27 17:00:04 cx100 volumio[1175]: info: Initializing connection to go-librespot Websocket Jan 27 17:00:04 cx100 systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 27 17:00:04 cx100 sudo[1785]: pam_unix(sudo:session): session closed for user root Jan 27 17:00:05 cx100 volumio[1175]: info: Shairport-Sync Started Jan 27 17:00:05 cx100 go-librespot[1677]: time="2026-01-27T17:00:05+01:00" level=debug msg="new websocket client" Jan 27 17:00:05 cx100 volumio[1175]: info: Connection to go-librespot Websocket established Jan 27 17:00:06 cx100 mpd[1778]: 2026-01-27T17:00:06 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jan 27 17:00:06 cx100 volumio[1175]: info: Discovery: Browse raised the following error Error: getaddrinfo -3007 Jan 27 17:00:06 cx100 volumio[1175]: info: Discovery: Restarting Browsing Jan 27 17:00:06 cx100 upmpdcli[1527]: :3:../src/mpdcli.cxx:148::MPDCli::startEventLoop: already started Jan 27 17:00:06 cx100 systemd[1]: Started mpd.service - Music Player Daemon. Jan 27 17:00:06 cx100 sudo[1769]: pam_unix(sudo:session): session closed for user root Jan 27 17:00:06 cx100 upmpdcli[1527]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 17:00:06 cx100 volumio[1175]: SPOTIFY: User informations: {"country":"DK","display_name":"Rosenkrands","email":"rosenkrands@live.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/31idj4o4qpj2jz3qgyhtzwat7uyq"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/31idj4o4qpj2jz3qgyhtzwat7uyq","id":"31idj4o4qpj2jz3qgyhtzwat7uyq","images":[],"product":"premium","type":"user","uri":"spotify:user:31idj4o4qpj2jz3qgyhtzwat7uyq"} Jan 27 17:00:06 cx100 volumio[1175]: info: Spotify Successfully logged in Jan 27 17:00:06 cx100 volumio[1175]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 27 17:00:06 cx100 volumio[1175]: info: [1769529606282] CoreMusicLibrary::Adding element Spotify Jan 27 17:00:06 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 27 17:00:06 cx100 volumio[1175]: Cannot find translation for source Spotify Jan 27 17:00:06 cx100 volumio[1175]: info: Discovery: Browse raised the following error Error: getaddrinfo -3007 Jan 27 17:00:06 cx100 volumio[1175]: info: Discovery: Restarting Browsing Jan 27 17:00:06 cx100 volumio[1175]: info: Discovery: Restart already pending, ignoring duplicate call Jan 27 17:00:06 cx100 volumio[1175]: info: Discovery: Browse raised the following error Error: getaddrinfo -3007 Jan 27 17:00:06 cx100 volumio[1175]: info: Discovery: Restarting Browsing Jan 27 17:00:06 cx100 volumio[1175]: info: Discovery: Restart already pending, ignoring duplicate call Jan 27 17:00:07 cx100 volumio[1175]: error: updateQueue error: null Jan 27 17:00:08 cx100 volumio[1175]: info: [yt-cast-receiver] DIAL server listening on port 8098 Jan 27 17:00:08 cx100 volumio[1175]: info: CoreCommandRouter::volumioRetrievevolume Jan 27 17:00:08 cx100 volumio[1175]: info: Getting Spotify volume Jan 27 17:00:08 cx100 volumio[1175]: Unable to parse: Jan 27 17:00:08 cx100 volumio[1175]: Simple mixer control 'Master',0 Jan 27 17:00:08 cx100 volumio[1175]: Capabilities: volume volume-joined Jan 27 17:00:08 cx100 volumio[1175]: Playback channels: Mono Jan 27 17:00:08 cx100 volumio[1175]: Capture channels: Mono Jan 27 17:00:08 cx100 volumio[1175]: Limits: 0 - 248 Jan 27 17:00:08 cx100 volumio[1175]: Mono: 159 [64%] Jan 27 17:00:08 cx100 volumio[1175]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: failed to parse output Jan 27 17:00:08 cx100 volumio[1175]: info: Spotify volume: 100 Jan 27 17:00:09 cx100 volumio[1175]: Unable to parse: Jan 27 17:00:09 cx100 volumio[1175]: Simple mixer control 'Master',0 Jan 27 17:00:09 cx100 volumio[1175]: Capabilities: volume volume-joined Jan 27 17:00:09 cx100 volumio[1175]: Playback channels: Mono Jan 27 17:00:09 cx100 volumio[1175]: Capture channels: Mono Jan 27 17:00:09 cx100 volumio[1175]: Limits: 0 - 248 Jan 27 17:00:09 cx100 volumio[1175]: Mono: 159 [64%] Jan 27 17:00:09 cx100 volumio[1175]: info: VolumeController:: Volume=undefined Mute =false Jan 27 17:00:09 cx100 volumio[1175]: info: CoreCommandRouter::volumioGetState Jan 27 17:00:09 cx100 volumio[1175]: info: CorePlayQueue::getTrack 0 Jan 27 17:00:09 cx100 volumio[1175]: info: CoreStateMachine::pushState Jan 27 17:00:09 cx100 volumio[1175]: info: CorePlayQueue::getTrack 0 Jan 27 17:00:09 cx100 volumio[1175]: info: CoreCommandRouter::volumioPushState Jan 27 17:00:09 cx100 volumio[1175]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 11 Jan 27 17:00:10 cx100 volumio[1175]: info: Completed starting Core Plugins Jan 27 17:00:10 cx100 volumio[1175]: info: ------------------------------------------- Jan 27 17:00:10 cx100 volumio[1175]: info: ----- MyVolumio plugins startup ---- Jan 27 17:00:10 cx100 volumio[1175]: info: ------------------------------------------- Jan 27 17:00:10 cx100 volumio[1175]: info: [MyVolumio PluginManager] Fetching plans data.... Jan 27 17:00:12 cx100 volumio[1175]: info: CoreCommandRouter::volumioGetState Jan 27 17:00:12 cx100 volumio[1175]: info: CorePlayQueue::getTrack 0 Jan 27 17:00:12 cx100 volumio[1175]: info: Discovery: Browse raised the following error Error: getaddrinfo -3007 Jan 27 17:00:12 cx100 volumio[1175]: info: Discovery: Restarting Browsing Jan 27 17:00:12 cx100 volumio[1175]: info: Discovery: Browse raised the following error Error: getaddrinfo -3007 Jan 27 17:00:12 cx100 volumio[1175]: info: Discovery: Restarting Browsing Jan 27 17:00:12 cx100 volumio[1175]: info: Discovery: Restart already pending, ignoring duplicate call Jan 27 17:00:12 cx100 volumio[1175]: info: Discovery: Browse raised the following error Error: getaddrinfo -3007 Jan 27 17:00:12 cx100 volumio[1175]: info: Discovery: Restarting Browsing Jan 27 17:00:12 cx100 volumio[1175]: info: Discovery: Restart already pending, ignoring duplicate call Jan 27 17:00:18 cx100 volumio[1175]: info: Discovery: Browse raised the following error Error: getaddrinfo -3007 Jan 27 17:00:18 cx100 volumio[1175]: info: Discovery: Restarting Browsing Jan 27 17:00:18 cx100 volumio[1175]: verbose: New Socket.io Connection to 192.168.10.89 from 192.168.10.226 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/143.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 12 Jan 27 17:00:18 cx100 volumio[1175]: info: Discovery: Browse raised the following error Error: getaddrinfo -3007 Jan 27 17:00:18 cx100 volumio[1175]: info: Discovery: Restarting Browsing Jan 27 17:00:18 cx100 volumio[1175]: info: Discovery: Restart already pending, ignoring duplicate call Jan 27 17:00:18 cx100 volumio[1175]: info: Discovery: Browse raised the following error Error: getaddrinfo -3007 Jan 27 17:00:18 cx100 volumio[1175]: info: Discovery: Restarting Browsing Jan 27 17:00:18 cx100 volumio[1175]: info: Discovery: Restart already pending, ignoring duplicate call Jan 27 17:00:18 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Jan 27 17:00:19 cx100 volumio[1175]: info: CoreCommandRouter::volumioGetVisibleSources Jan 27 17:00:19 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 27 17:00:19 cx100 volumio[1175]: info: CoreCommandRouter::volumioGetState Jan 27 17:00:19 cx100 volumio[1175]: info: CorePlayQueue::getTrack 0 Jan 27 17:00:19 cx100 volumio[1175]: info: CoreCommandRouter::volumioGetState Jan 27 17:00:19 cx100 volumio[1175]: info: CorePlayQueue::getTrack 0 Jan 27 17:00:19 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Jan 27 17:00:19 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Jan 27 17:00:19 cx100 volumio[1175]: info: Received Get System Info Jan 27 17:00:19 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jan 27 17:00:19 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jan 27 17:00:19 cx100 volumio[1175]: info: Discovery: Getting this device information Jan 27 17:00:19 cx100 volumio[1175]: info: CoreCommandRouter::volumioGetState Jan 27 17:00:19 cx100 volumio[1175]: info: CorePlayQueue::getTrack 0 Jan 27 17:00:19 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jan 27 17:00:19 cx100 volumio[1175]: info: CoreCommandRouter::volumioGetState Jan 27 17:00:19 cx100 volumio[1175]: info: CorePlayQueue::getTrack 0 Jan 27 17:00:19 cx100 volumio[1175]: info: Listing playlists Jan 27 17:00:19 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 27 17:00:19 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 17:00:19 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Jan 27 17:00:20 cx100 volumio[1175]: info: CoreCommandRouter::getUIConfigOnPlugin Jan 27 17:00:20 cx100 volumio[1175]: info: CoreCommandRouter::getUIConfigOnPlugin Jan 27 17:00:25 cx100 volumio[1175]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Jan 27 17:00:25 cx100 volumio[1175]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Jan 27 17:00:25 cx100 volumio[1175]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Jan 27 17:00:25 cx100 volumio[1175]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Jan 27 17:00:25 cx100 volumio[1175]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Jan 27 17:00:25 cx100 volumio[1175]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Jan 27 17:00:25 cx100 volumio[1175]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Jan 27 17:00:25 cx100 volumio[1175]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Jan 27 17:00:25 cx100 volumio[1175]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Jan 27 17:00:25 cx100 volumio[1175]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Jan 27 17:00:25 cx100 volumio[1175]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Jan 27 17:00:25 cx100 volumio[1175]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Jan 27 17:00:25 cx100 volumio[1175]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Jan 27 17:00:25 cx100 volumio[1175]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Jan 27 17:00:25 cx100 volumio[1175]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Jan 27 17:00:25 cx100 volumio[1175]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Jan 27 17:00:25 cx100 volumio[1175]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Jan 27 17:00:25 cx100 volumio[1175]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Jan 27 17:00:25 cx100 volumio[1175]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Jan 27 17:00:25 cx100 volumio[1175]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Jan 27 17:00:25 cx100 volumio[1175]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Jan 27 17:00:25 cx100 volumio[1175]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Jan 27 17:00:25 cx100 volumio[1175]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Jan 27 17:00:25 cx100 volumio[1175]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Jan 27 17:00:25 cx100 volumio[1175]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Jan 27 17:00:25 cx100 volumio[1175]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Jan 27 17:00:25 cx100 volumio[1175]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Jan 27 17:00:25 cx100 volumio[1175]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Jan 27 17:00:25 cx100 volumio[1175]: info: Adding plugin bluetooth to MyMusic Plugins Jan 27 17:00:25 cx100 volumio[1175]: info: Adding plugin multiroom to MyMusic Plugins Jan 27 17:00:25 cx100 volumio[1175]: info: Adding plugin metavolumio to MyMusic Plugins Jan 27 17:00:25 cx100 volumio[1175]: info: Adding plugin cd_controller to MyMusic Plugins Jan 27 17:00:25 cx100 volumio[1175]: info: Adding plugin qobuzconnect to MyMusic Plugins Jan 27 17:00:25 cx100 volumio[1175]: info: Adding plugin smart_inputs to MyMusic Plugins Jan 27 17:00:25 cx100 volumio[1175]: info: Adding plugin tidalconnect to MyMusic Plugins Jan 27 17:00:25 cx100 volumio[1175]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Jan 27 17:00:25 cx100 volumio5-onboarding[1578]: failed to bootstrap state: failed to check for software update: could not check for updates: context deadline exceeded Jan 27 17:00:25 cx100 systemd[1]: volumio5-onboarding.service: Main process exited, code=exited, status=1/FAILURE Jan 27 17:00:25 cx100 systemd[1]: volumio5-onboarding.service: Failed with result 'exit-code'. Jan 27 17:00:26 cx100 systemd[1]: volumio5-onboarding.service: Scheduled restart job, restart counter is at 1. Jan 27 17:00:26 cx100 systemd[1]: Stopped volumio5-onboarding.service - Volumio5 Onboarding Server. Jan 27 17:00:26 cx100 systemd[1]: Started volumio5-onboarding.service - Volumio5 Onboarding Server. Jan 27 17:00:26 cx100 volumio5-onboarding[1855]: time=2026-01-27T17:00:26.245+01:00 level=INFO msg="running volumio5-device-gateway" version=9838fecf+CHANGES buildDate=2026-01-16T16:06:14Z Jan 27 17:00:26 cx100 go-librespot[1677]: time="2026-01-27T17:00:26+01:00" level=trace msg="sent dealer ping" Jan 27 17:00:26 cx100 go-librespot[1677]: time="2026-01-27T17:00:26+01:00" level=trace msg="received dealer pong" Jan 27 17:00:32 cx100 volumio[1175]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Jan 27 17:00:32 cx100 volumio[1175]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Jan 27 17:00:32 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 17:00:32 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 17:00:32 cx100 volumio[1175]: info: Starting MyVolumio Remote Streaming Endpoints Jan 27 17:00:32 cx100 volumio[1175]: info: MyVolumio login type: Token Jan 27 17:00:33 cx100 volumio[1175]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Jan 27 17:00:33 cx100 volumio[1175]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Jan 27 17:00:36 cx100 volumio5-onboarding[1855]: failed to create app: failed to initialize host: failed to create socket connection: could not connect to socket.io server: read tcp 127.0.0.1:37602->127.0.0.1:3000: i/o timeout Jan 27 17:00:36 cx100 systemd[1]: volumio5-onboarding.service: Main process exited, code=exited, status=1/FAILURE Jan 27 17:00:36 cx100 systemd[1]: volumio5-onboarding.service: Failed with result 'exit-code'. Jan 27 17:00:36 cx100 systemd[1]: volumio5-onboarding.service: Scheduled restart job, restart counter is at 2. Jan 27 17:00:36 cx100 systemd[1]: Stopped volumio5-onboarding.service - Volumio5 Onboarding Server. Jan 27 17:00:36 cx100 systemd[1]: Started volumio5-onboarding.service - Volumio5 Onboarding Server. Jan 27 17:00:36 cx100 volumio5-onboarding[1876]: time=2026-01-27T17:00:36.866+01:00 level=INFO msg="running volumio5-device-gateway" version=9838fecf+CHANGES buildDate=2026-01-16T16:06:14Z Jan 27 17:00:38 cx100 volumio[1175]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Jan 27 17:00:38 cx100 volumio[1175]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Jan 27 17:00:38 cx100 volumio[1175]: info: Streaming services startup Jan 27 17:00:38 cx100 volumio[1175]: info: Starting Streaming Daemon Jan 27 17:00:38 cx100 sudo[1883]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Jan 27 17:00:38 cx100 sudo[1883]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 17:00:38 cx100 volumio[1175]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Jan 27 17:00:38 cx100 sudo[1883]: pam_unix(sudo:session): session closed for user root Jan 27 17:00:39 cx100 volumio[1175]: error: Cannot start Volumio Streaming Daemon Jan 27 17:00:39 cx100 volumio[1175]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Jan 27 17:00:39 cx100 volumio[1175]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Jan 27 17:00:40 cx100 volumio-remote-updater[722]: Test mode enabled Jan 27 17:00:40 cx100 volumio-remote-updater[722]: Alpha mode disabled Jan 27 17:00:40 cx100 volumio-remote-updater[722]: Alpha legacy test mode disabled Jan 27 17:00:40 cx100 volumio[1175]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Jan 27 17:00:40 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Jan 27 17:00:41 cx100 volumio5-onboarding[1876]: time=2026-01-27T17:00:41.048+01:00 level=INFO msg="listening for BLE messages" address=B8:27:EB:C2:63:17%00 Jan 27 17:00:41 cx100 volumio[1175]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 12 Jan 27 17:00:41 cx100 volumio5-onboarding[1876]: time=2026-01-27T17:00:41.092+01:00 level=INFO msg="listening for WebSocket messages" address=[::]:7331 Jan 27 17:00:41 cx100 volumio[1175]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 12 Jan 27 17:00:41 cx100 volumio[1175]: info: Received Get System Info Jan 27 17:00:41 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jan 27 17:00:41 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jan 27 17:00:41 cx100 volumio[1175]: info: Discovery: Getting this device information Jan 27 17:00:41 cx100 volumio[1175]: info: CoreCommandRouter::volumioGetState Jan 27 17:00:41 cx100 volumio[1175]: info: CorePlayQueue::getTrack 0 Jan 27 17:00:41 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jan 27 17:00:42 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Jan 27 17:00:42 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Jan 27 17:00:42 cx100 volumio5-onboarding[1876]: time=2026-01-27T17:00:42.473+01:00 level=INFO msg="BLE descriptor updated" deviceId=8ca65ad786e3d7a5aed0eb9f46cc2b08 deviceName=CX100 deviceModel= Jan 27 17:00:42 cx100 volumio5-onboarding[1876]: time=2026-01-27T17:00:42.473+01:00 level=INFO msg="mDNS descriptor updated" deviceId=8ca65ad786e3d7a5aed0eb9f46cc2b08 deviceName=CX100 deviceModel= Jan 27 17:00:42 cx100 volumio5-onboarding[1876]: time=2026-01-27T17:00:42.488+01:00 level=INFO msg="bootstrapping state" hasInternet=true Jan 27 17:00:42 cx100 volumio[1175]: info: Received Get System Info Jan 27 17:00:42 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jan 27 17:00:42 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jan 27 17:00:42 cx100 volumio[1175]: info: Discovery: Getting this device information Jan 27 17:00:42 cx100 volumio[1175]: info: CoreCommandRouter::volumioGetState Jan 27 17:00:42 cx100 volumio[1175]: info: CorePlayQueue::getTrack 0 Jan 27 17:00:42 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jan 27 17:00:42 cx100 volumio[1175]: info: Discovery: Browse raised the following error Error: getaddrinfo -3007 Jan 27 17:00:42 cx100 volumio[1175]: info: Discovery: Restarting Browsing Jan 27 17:00:42 cx100 volumio-remote-updater[722]: Test mode enabled Jan 27 17:00:42 cx100 volumio-remote-updater[722]: Alpha mode disabled Jan 27 17:00:42 cx100 volumio-remote-updater[722]: Alpha legacy test mode disabled Jan 27 17:00:42 cx100 volumio[1175]: info: Discovery: Browse raised the following error Error: getaddrinfo -3007 Jan 27 17:00:42 cx100 volumio[1175]: info: Discovery: Restarting Browsing Jan 27 17:00:42 cx100 volumio[1175]: info: Discovery: Restart already pending, ignoring duplicate call Jan 27 17:00:43 cx100 volumio[1175]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Jan 27 17:00:43 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Jan 27 17:00:43 cx100 volumio[1175]: info: Discovery: Browse raised the following error Error: getaddrinfo -3007 Jan 27 17:00:43 cx100 volumio[1175]: info: Discovery: Restarting Browsing Jan 27 17:00:43 cx100 volumio[1175]: info: Discovery: Restart already pending, ignoring duplicate call Jan 27 17:00:43 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jan 27 17:00:43 cx100 volumio5-onboarding[1876]: time=2026-01-27T17:00:43.734+01:00 level=WARN msg="could not read OAuth data for music provider" component=volumio provider=tidal error="could not open plugin config file for \"tidal\": open /data/configuration/music_service/tidal/config.json: no such file or directory" Jan 27 17:00:43 cx100 volumio5-onboarding[1876]: time=2026-01-27T17:00:43.736+01:00 level=WARN msg="could not read OAuth data for music provider" component=volumio provider=qobuz error="could not open plugin config file for \"qobuz\": open /data/configuration/music_service/qobuz/config.json: no such file or directory" Jan 27 17:00:43 cx100 volumio5-onboarding[1876]: time=2026-01-27T17:00:43.736+01:00 level=WARN msg="could not read username/password data for music provider" component=volumio provider=hi_res_audio error="could not open plugin config file for \"hi_res_audio\": open /data/configuration/music_service/hi_res_audio/config.json: no such file or directory" Jan 27 17:00:44 cx100 volumio[1175]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Jan 27 17:00:44 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jan 27 17:00:44 cx100 volumio[1175]: info: CoreCommandRouter::Close All Modals sent Jan 27 17:00:44 cx100 volumio[1175]: info: CoreCommandRouter::Close All Modals sent Jan 27 17:00:44 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jan 27 17:00:44 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Jan 27 17:00:47 cx100 volumio[1175]: info: CoreCommandRouter::volumioGetState Jan 27 17:00:47 cx100 volumio[1175]: info: CorePlayQueue::getTrack 0 Jan 27 17:00:47 cx100 volumio[1175]: info: MyVolumio token set successfully Jan 27 17:00:47 cx100 volumio[1175]: info: MYVOLUMIO: Adding device Jan 27 17:00:47 cx100 volumio[1175]: info: MYVOLUMIO: Evaluating Server Jan 27 17:00:48 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Jan 27 17:00:48 cx100 volumio[1175]: info: MyVolumio status changed Jan 27 17:00:48 cx100 volumio[1175]: info: Streaming services startup Jan 27 17:00:48 cx100 volumio[1175]: info: Starting Streaming Daemon Jan 27 17:00:48 cx100 volumio[1175]: info: Removing browser output: myVolumio user plan is not superstar Jan 27 17:00:48 cx100 volumio[1175]: info: Removing audio output: Jan 27 17:00:48 cx100 volumio[1175]: info: Stoppping Tunnel 1 Jan 27 17:00:48 cx100 sudo[1939]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Jan 27 17:00:48 cx100 sudo[1937]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Jan 27 17:00:49 cx100 sudo[1939]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 17:00:49 cx100 sudo[1937]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 17:00:49 cx100 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. Jan 27 17:00:49 cx100 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. Jan 27 17:00:49 cx100 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. Jan 27 17:00:49 cx100 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. Jan 27 17:00:49 cx100 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. Jan 27 17:00:49 cx100 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. Jan 27 17:00:49 cx100 sudo[1937]: pam_unix(sudo:session): session closed for user root Jan 27 17:00:49 cx100 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. Jan 27 17:00:49 cx100 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. Jan 27 17:00:49 cx100 sudo[1939]: pam_unix(sudo:session): session closed for user root Jan 27 17:00:49 cx100 volumio[1175]: info: Setting Geolocation for MyVolumio to eu12 Jan 27 17:00:49 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 17:00:49 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 17:00:49 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 17:00:50 cx100 volumio[1175]: info: Remote SSH Stopped Jan 27 17:00:50 cx100 volumio[1175]: error: Cannot start Volumio Streaming Daemon Jan 27 17:00:50 cx100 volumio[1175]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Jan 27 17:00:50 cx100 volumio[1175]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Jan 27 17:00:50 cx100 volumio[1175]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 13 Jan 27 17:00:50 cx100 volumio[1175]: info: Updating MyVolumio device info Jan 27 17:00:50 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 17:00:50 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 17:00:50 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 17:00:50 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jan 27 17:00:50 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Jan 27 17:00:50 cx100 volumio[1175]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Jan 27 17:00:51 cx100 volumio[1175]: info: CoreCommandRouter::getUIConfigOnPlugin Jan 27 17:00:51 cx100 volumio[1175]: info: CoreCommandRouter::getUIConfigOnPlugin Jan 27 17:00:51 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jan 27 17:00:51 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Jan 27 17:00:51 cx100 volumio[1175]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Jan 27 17:00:51 cx100 volumio[1175]: info: Discovery: Browse raised the following error Error: getaddrinfo -3007 Jan 27 17:00:51 cx100 volumio[1175]: info: Discovery: Restarting Browsing Jan 27 17:00:51 cx100 volumio[1175]: info: Discovery: Browse raised the following error Error: getaddrinfo -3007 Jan 27 17:00:51 cx100 volumio[1175]: info: Discovery: Restarting Browsing Jan 27 17:00:51 cx100 volumio[1175]: info: Discovery: Restart already pending, ignoring duplicate call Jan 27 17:00:53 cx100 volumio[1175]: info: Discovery: Browse raised the following error Error: getaddrinfo -3007 Jan 27 17:00:53 cx100 volumio[1175]: info: Discovery: Restarting Browsing Jan 27 17:00:53 cx100 volumio[1175]: info: Discovery: Restart already pending, ignoring duplicate call Jan 27 17:00:53 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:00:53 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:00:53 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Jan 27 17:00:53 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Jan 27 17:00:53 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Jan 27 17:00:53 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Jan 27 17:00:53 cx100 volumio[1175]: info: CoreCommandRouter::volumioGetBrowseSources Jan 27 17:00:53 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 27 17:00:54 cx100 volumio[1175]: info: MYVOLUMIO: Adding device Jan 27 17:00:55 cx100 volumio[1175]: info: MYVOLUMIO: Evaluating Server Jan 27 17:00:55 cx100 volumio5-onboarding[1876]: time=2026-01-27T17:00:55.534+01:00 level=INFO msg="authenticated Firebase client" component=volumio/firebase userId=0ns9I0xoI1OrIjZa1mi60MO7Pi92 tokenExpiry=2026-01-27T18:00:55.534+01:00 Jan 27 17:00:56 cx100 go-librespot[1677]: time="2026-01-27T17:00:56+01:00" level=trace msg="sent dealer ping" Jan 27 17:00:56 cx100 volumio[1175]: info: CoreCommandRouter::volumioGetState Jan 27 17:00:56 cx100 volumio[1175]: info: CorePlayQueue::getTrack 0 Jan 27 17:00:56 cx100 go-librespot[1677]: time="2026-01-27T17:00:56+01:00" level=trace msg="received dealer pong" Jan 27 17:00:57 cx100 volumio[1175]: info: Setting Geolocation for MyVolumio to eu5 Jan 27 17:00:57 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 17:00:57 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 17:00:57 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 17:00:57 cx100 volumio[1175]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Jan 27 17:00:57 cx100 volumio[1175]: info: Discovery: Browse raised the following error Error: getaddrinfo -3007 Jan 27 17:00:57 cx100 volumio[1175]: info: Discovery: Restarting Browsing Jan 27 17:00:57 cx100 volumio[1175]: info: Discovery: Browse raised the following error Error: getaddrinfo -3007 Jan 27 17:00:57 cx100 volumio[1175]: info: Discovery: Restarting Browsing Jan 27 17:00:57 cx100 volumio[1175]: info: Discovery: Restart already pending, ignoring duplicate call Jan 27 17:00:57 cx100 volumio[1175]: info: Discovery: Browse raised the following error Error: getaddrinfo -3007 Jan 27 17:00:57 cx100 volumio[1175]: info: Discovery: Restarting Browsing Jan 27 17:00:57 cx100 volumio[1175]: info: Discovery: Restart already pending, ignoring duplicate call Jan 27 17:00:58 cx100 volumio[1175]: info: Updating MyVolumio device info Jan 27 17:00:58 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 17:00:58 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 17:00:58 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 17:00:58 cx100 volumio[1175]: error: MyVolumio Plugin failed to authenticate in a timely fashion Jan 27 17:00:58 cx100 volumio[1175]: info: Completed starting MyVolumio Plugin Jan 27 17:00:58 cx100 volumio[1175]: [Metrics] CommandRouter: 105s 210.22ms Jan 27 17:00:58 cx100 volumio[1175]: info: CoreCommandRouter::volumiosetStartupVolume Jan 27 17:00:58 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:00:58 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 17:00:58 cx100 volumio[1175]: info: CoreCommandRouter::Close All Modals sent Jan 27 17:00:58 cx100 volumio[1175]: info: CoreCommandRouter::Close All Modals sent Jan 27 17:00:58 cx100 volumio[1175]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Jan 27 17:00:58 cx100 volumio[1175]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Jan 27 17:00:58 cx100 volumio[1175]: info: FusionDsp - ---- read samplerate from file: 44100 Jan 27 17:00:58 cx100 volumio[1175]: info: camilladsp stopping service pid 1660... Jan 27 17:00:59 cx100 volumio[1175]: grep: /proc/1660/cmdline: binary file matches Jan 27 17:00:59 cx100 volumio[1175]: info: camilladsp service terminated, instance 1 Jan 27 17:00:59 cx100 volumio[1175]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jan 27 17:00:59 cx100 volumio[1175]: info: camilladsp service started and running in background, instance 1 Jan 27 17:00:59 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Jan 27 17:00:59 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Jan 27 17:00:59 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Jan 27 17:00:59 cx100 volumio[1175]: info: Version has changed, forcing UI Reload Jan 27 17:00:59 cx100 volumio[1175]: info: CoreCommandRouter::Reload Ui Jan 27 17:01:03 cx100 volumio[1175]: info: Discovery: Browse raised the following error Error: getaddrinfo -3007 Jan 27 17:01:03 cx100 volumio[1175]: info: Discovery: Restarting Browsing Jan 27 17:01:03 cx100 volumio[1175]: info: Discovery: Browse raised the following error Error: getaddrinfo -3007 Jan 27 17:01:03 cx100 volumio[1175]: info: Discovery: Restarting Browsing Jan 27 17:01:03 cx100 volumio[1175]: info: Discovery: Restart already pending, ignoring duplicate call Jan 27 17:01:03 cx100 volumio[1175]: info: Discovery: Browse raised the following error Error: getaddrinfo -3007 Jan 27 17:01:03 cx100 volumio[1175]: info: Discovery: Restarting Browsing Jan 27 17:01:03 cx100 volumio[1175]: info: Discovery: Restart already pending, ignoring duplicate call Jan 27 17:01:04 cx100 sudo[2027]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 27 17:01:04 cx100 sudo[2027]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 17:01:04 cx100 sudo[2029]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 27 17:01:04 cx100 sudo[2029]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 17:01:04 cx100 sudo[2027]: pam_unix(sudo:session): session closed for user root Jan 27 17:01:04 cx100 sudo[2029]: pam_unix(sudo:session): session closed for user root Jan 27 17:01:04 cx100 volumio[1175]: verbose: New Socket.io Connection to 192.168.10.89 from 192.168.10.226 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/143.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 11 Jan 27 17:01:04 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Jan 27 17:01:04 cx100 volumio[1175]: info: CoreCommandRouter::volumioGetVisibleSources Jan 27 17:01:04 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 27 17:01:05 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jan 27 17:01:05 cx100 volumio[1175]: info: CoreCommandRouter::volumioGetState Jan 27 17:01:05 cx100 volumio[1175]: info: CorePlayQueue::getTrack 0 Jan 27 17:01:05 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Jan 27 17:01:05 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Jan 27 17:01:05 cx100 volumio[1175]: info: Received Get System Info Jan 27 17:01:05 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jan 27 17:01:05 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jan 27 17:01:05 cx100 volumio[1175]: info: Discovery: Getting this device information Jan 27 17:01:05 cx100 volumio[1175]: info: CoreCommandRouter::volumioGetState Jan 27 17:01:05 cx100 volumio[1175]: info: CorePlayQueue::getTrack 0 Jan 27 17:01:05 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jan 27 17:01:05 cx100 volumio[1175]: info: CoreCommandRouter::volumioGetState Jan 27 17:01:05 cx100 volumio[1175]: info: CorePlayQueue::getTrack 0 Jan 27 17:01:05 cx100 volumio[1175]: info: Listing playlists Jan 27 17:01:05 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Jan 27 17:01:05 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Jan 27 17:01:05 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Jan 27 17:01:05 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Jan 27 17:01:05 cx100 volumio[1175]: info: CoreCommandRouter::getUIConfigOnPlugin Jan 27 17:01:05 cx100 volumio[1175]: info: CoreCommandRouter::getUIConfigOnPlugin Jan 27 17:01:05 cx100 volumio[1175]: info: BOOT COMPLETED Jan 27 17:01:07 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jan 27 17:01:07 cx100 volumio[1175]: info: Received Get System Info Jan 27 17:01:07 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jan 27 17:01:07 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jan 27 17:01:07 cx100 volumio[1175]: info: Discovery: Getting this device information Jan 27 17:01:07 cx100 volumio[1175]: info: CoreCommandRouter::volumioGetState Jan 27 17:01:07 cx100 volumio[1175]: info: CorePlayQueue::getTrack 0 Jan 27 17:01:07 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jan 27 17:01:08 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jan 27 17:01:08 cx100 volumio[1175]: info: Received Get System Info Jan 27 17:01:08 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jan 27 17:01:08 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jan 27 17:01:08 cx100 volumio[1175]: info: Discovery: Getting this device information Jan 27 17:01:08 cx100 volumio[1175]: info: CoreCommandRouter::volumioGetState Jan 27 17:01:08 cx100 volumio[1175]: info: CorePlayQueue::getTrack 0 Jan 27 17:01:08 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jan 27 17:01:08 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Jan 27 17:01:09 cx100 volumio[1175]: info: Discovery: Browse raised the following error Error: getaddrinfo -3007 Jan 27 17:01:09 cx100 volumio[1175]: info: Discovery: Restarting Browsing Jan 27 17:01:09 cx100 volumio[1175]: info: Discovery: Browse raised the following error Error: getaddrinfo -3007 Jan 27 17:01:09 cx100 volumio[1175]: info: Discovery: Restarting Browsing Jan 27 17:01:09 cx100 volumio[1175]: info: Discovery: Restart already pending, ignoring duplicate call Jan 27 17:01:10 cx100 volumio[1175]: info: Discovery: Browse raised the following error Error: getaddrinfo -3007 Jan 27 17:01:10 cx100 volumio[1175]: info: Discovery: Restarting Browsing Jan 27 17:01:10 cx100 volumio[1175]: info: Discovery: Restart already pending, ignoring duplicate call Jan 27 17:01:11 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Jan 27 17:01:13 cx100 volumio[1175]: info: CoreCommandRouter::getUIConfigOnPlugin Jan 27 17:01:13 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Jan 27 17:01:14 cx100 volumio[1175]: info: CALLMETHOD: music_service spop logout Jan 27 17:01:14 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: spop , logout Jan 27 17:01:14 cx100 volumio[1175]: info: Deleting Spotify credentials File Jan 27 17:01:14 cx100 volumio[1175]: info: CoreCommandRouter::volumioRemoveToBrowseSourcesSpotify Jan 27 17:01:14 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 27 17:01:14 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Jan 27 17:01:15 cx100 volumio[1175]: info: Creating Spotify config file Jan 27 17:01:15 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:01:15 cx100 volumio[1175]: info: Discovery: Browse raised the following error Error: getaddrinfo -3007 Jan 27 17:01:15 cx100 volumio[1175]: info: Discovery: Restarting Browsing Jan 27 17:01:15 cx100 volumio[1175]: info: Discovery: Browse raised the following error Error: getaddrinfo -3007 Jan 27 17:01:15 cx100 volumio[1175]: info: Discovery: Restarting Browsing Jan 27 17:01:15 cx100 volumio[1175]: info: Discovery: Restart already pending, ignoring duplicate call Jan 27 17:01:15 cx100 volumio[1175]: info: Discovery: Browse raised the following error Error: getaddrinfo -3007 Jan 27 17:01:15 cx100 volumio[1175]: info: Discovery: Restarting Browsing Jan 27 17:01:15 cx100 volumio[1175]: info: Discovery: Restart already pending, ignoring duplicate call Jan 27 17:01:15 cx100 volumio[1175]: info: Spotify config file written Jan 27 17:01:15 cx100 sudo[2064]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 27 17:01:15 cx100 sudo[2064]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 17:01:15 cx100 systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jan 27 17:01:15 cx100 systemd[1]: go-librespot-daemon.service: Killing process 1679 (go-librespot) with signal SIGKILL. Jan 27 17:01:15 cx100 systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jan 27 17:01:15 cx100 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 17:01:15 cx100 volumio[1175]: info: Connection to go-librespot Websocket closed Jan 27 17:01:15 cx100 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 17:01:15 cx100 go-librespot[2066]: go-librespot daemon starting... Jan 27 17:01:15 cx100 sudo[2064]: pam_unix(sudo:session): session closed for user root Jan 27 17:01:15 cx100 go-librespot[2067]: time="2026-01-27T17:01:15+01:00" level=info msg="running go-librespot 0.6.2" Jan 27 17:01:15 cx100 go-librespot[2067]: time="2026-01-27T17:01:15+01:00" level=debug msg="no app state found" Jan 27 17:01:15 cx100 go-librespot[2067]: time="2026-01-27T17:01:15+01:00" level=debug msg="stored credentials not found" Jan 27 17:01:15 cx100 go-librespot[2067]: time="2026-01-27T17:01:15+01:00" level=info msg="generated new device id: ee9731d208de1f04722d3b32584f589bfabc5eec" Jan 27 17:01:15 cx100 go-librespot[2067]: time="2026-01-27T17:01:15+01:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 17:01:16 cx100 go-librespot[2067]: time="2026-01-27T17:01:16+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Jan 27 17:01:16 cx100 go-librespot[2067]: time="2026-01-27T17:01:16+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Jan 27 17:01:16 cx100 go-librespot[2067]: time="2026-01-27T17:01:16+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Jan 27 17:01:16 cx100 go-librespot[2067]: time="2026-01-27T17:01:16+01:00" level=info msg="zeroconf server listening on port 42711" Jan 27 17:01:18 cx100 volumio[1175]: info: Initializing connection to go-librespot Websocket Jan 27 17:01:18 cx100 go-librespot[2067]: time="2026-01-27T17:01:18+01:00" level=debug msg="new websocket client" Jan 27 17:01:18 cx100 volumio[1175]: info: Connection to go-librespot Websocket established Jan 27 17:01:18 cx100 volumio[1175]: info: go-librespot daemon successfully initialized Jan 27 17:01:19 cx100 volumio[1175]: info: Received OAUTH Data Jan 27 17:01:19 cx100 volumio[1175]: info: Executing Spotify Oauth Login Jan 27 17:01:19 cx100 volumio[1175]: info: Saving Spotify Refresh Token Jan 27 17:01:20 cx100 volumio[1175]: info: New Spotify access tokenBQBlN4ZEIN... Jan 27 17:01:20 cx100 volumio[1175]: info: Spotify credentials grant success - running version from March 24, 2019 Jan 27 17:01:21 cx100 volumio[1175]: info: Discovery: Browse raised the following error Error: getaddrinfo -3007 Jan 27 17:01:21 cx100 volumio[1175]: info: Discovery: Restarting Browsing Jan 27 17:01:21 cx100 sudo[2097]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 27 17:01:21 cx100 sudo[2097]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 17:01:21 cx100 volumio[1175]: info: Discovery: Browse raised the following error Error: getaddrinfo -3007 Jan 27 17:01:21 cx100 volumio[1175]: info: Discovery: Restarting Browsing Jan 27 17:01:21 cx100 volumio[1175]: info: Discovery: Restart already pending, ignoring duplicate call Jan 27 17:01:21 cx100 volumio[1175]: info: Discovery: Browse raised the following error Error: getaddrinfo -3007 Jan 27 17:01:21 cx100 volumio[1175]: info: Discovery: Restarting Browsing Jan 27 17:01:21 cx100 volumio[1175]: info: Discovery: Restart already pending, ignoring duplicate call Jan 27 17:01:21 cx100 sudo[2097]: pam_unix(sudo:session): session closed for user root Jan 27 17:01:21 cx100 sudo[2095]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 27 17:01:21 cx100 sudo[2095]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 17:01:21 cx100 sudo[2095]: pam_unix(sudo:session): session closed for user root Jan 27 17:01:21 cx100 volumio[1175]: info: Getting Spotify volume Jan 27 17:01:21 cx100 volumio[1175]: verbose: New Socket.io Connection to 192.168.10.89 from 192.168.10.226 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/143.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 8 Jan 27 17:01:21 cx100 volumio[1175]: info: Initializing connection to go-librespot Websocket Jan 27 17:01:21 cx100 volumio[1175]: SPOTIFY: User informations: {"country":"DK","display_name":"Rosenkrands","email":"rosenkrands@live.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/31idj4o4qpj2jz3qgyhtzwat7uyq"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/31idj4o4qpj2jz3qgyhtzwat7uyq","id":"31idj4o4qpj2jz3qgyhtzwat7uyq","images":[],"product":"premium","type":"user","uri":"spotify:user:31idj4o4qpj2jz3qgyhtzwat7uyq"} Jan 27 17:01:21 cx100 volumio[1175]: info: Creating Spotify config file Jan 27 17:01:21 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:01:21 cx100 go-librespot[2067]: time="2026-01-27T17:01:21+01:00" level=debug msg="new websocket client" Jan 27 17:01:22 cx100 volumio[1175]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Jan 27 17:01:22 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Jan 27 17:01:22 cx100 volumio[1175]: info: Connection to go-librespot Websocket established Jan 27 17:01:22 cx100 volumio[1175]: info: Spotify config file written Jan 27 17:01:22 cx100 volumio[1175]: info: CoreCommandRouter::volumioGetVisibleSources Jan 27 17:01:22 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 27 17:01:22 cx100 sudo[2101]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 27 17:01:22 cx100 volumio[1175]: info: CoreCommandRouter::volumioGetState Jan 27 17:01:22 cx100 volumio[1175]: info: CorePlayQueue::getTrack 0 Jan 27 17:01:22 cx100 sudo[2101]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 17:01:22 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Jan 27 17:01:22 cx100 volumio[1175]: info: CoreCommandRouter::getUIConfigOnPlugin Jan 27 17:01:22 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Jan 27 17:01:22 cx100 volumio[1175]: info: Received Get System Info Jan 27 17:01:22 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jan 27 17:01:22 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jan 27 17:01:22 cx100 volumio[1175]: info: Discovery: Getting this device information Jan 27 17:01:22 cx100 volumio[1175]: info: CoreCommandRouter::volumioGetState Jan 27 17:01:22 cx100 volumio[1175]: info: CorePlayQueue::getTrack 0 Jan 27 17:01:22 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jan 27 17:01:22 cx100 volumio[1175]: info: CoreCommandRouter::volumioGetState Jan 27 17:01:22 cx100 volumio[1175]: info: CorePlayQueue::getTrack 0 Jan 27 17:01:22 cx100 volumio[1175]: info: Listing playlists Jan 27 17:01:22 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Jan 27 17:01:22 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Jan 27 17:01:22 cx100 systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jan 27 17:01:22 cx100 systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jan 27 17:01:22 cx100 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 17:01:22 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Jan 27 17:01:22 cx100 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 17:01:22 cx100 go-librespot[2103]: go-librespot daemon starting... Jan 27 17:01:22 cx100 sudo[2101]: pam_unix(sudo:session): session closed for user root Jan 27 17:01:22 cx100 volumio[1175]: info: Connection to go-librespot Websocket closed Jan 27 17:01:22 cx100 volumio[1175]: info: Connection to go-librespot Websocket closed Jan 27 17:01:22 cx100 go-librespot[2104]: time="2026-01-27T17:01:22+01:00" level=info msg="running go-librespot 0.6.2" Jan 27 17:01:22 cx100 go-librespot[2104]: time="2026-01-27T17:01:22+01:00" level=debug msg="app state loaded" Jan 27 17:01:22 cx100 go-librespot[2104]: time="2026-01-27T17:01:22+01:00" level=debug msg="stored credentials not found" Jan 27 17:01:22 cx100 go-librespot[2104]: time="2026-01-27T17:01:22+01:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 17:01:23 cx100 go-librespot[2104]: time="2026-01-27T17:01:23+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Jan 27 17:01:23 cx100 go-librespot[2104]: time="2026-01-27T17:01:23+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Jan 27 17:01:23 cx100 go-librespot[2104]: time="2026-01-27T17:01:23+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Jan 27 17:01:23 cx100 go-librespot[2104]: time="2026-01-27T17:01:23+01:00" level=info msg="zeroconf server listening on port 45767" Jan 27 17:01:23 cx100 go-librespot[2104]: time="2026-01-27T17:01:23+01:00" level=debug msg="obtained new client token: AACbxctR0RmpgZ6rT0ka8CyM+QB105ve4CzPk2hYdn4ngxodauSCMBciyWFogDUcULhREw5MmVIbLKnOOlnyeW+7jVuoT0NHE2H3LnySTTrSkw2DydWYo8k0ZkSKmjDGwPXe9mEdRBl4S20DbWK0YhJ7dDXhZ0TRfOqsUVW2K9GWsEwC8gLvExmKx9pdKgq/SPkV207UdeO2HlL12u2/gi9NEk9AIURftWk5GPlh6t2c6HdkVH+BvrEt" Jan 27 17:01:23 cx100 go-librespot[2104]: time="2026-01-27T17:01:23+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Jan 27 17:01:23 cx100 go-librespot[2104]: time="2026-01-27T17:01:23+01:00" level=debug msg="completed keyexchange" Jan 27 17:01:23 cx100 go-librespot[2104]: time="2026-01-27T17:01:23+01:00" level=debug msg="completed challenge" Jan 27 17:01:23 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jan 27 17:01:23 cx100 volumio[1175]: info: Received Get System Info Jan 27 17:01:23 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jan 27 17:01:23 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jan 27 17:01:23 cx100 volumio[1175]: info: Discovery: Getting this device information Jan 27 17:01:23 cx100 volumio[1175]: info: CoreCommandRouter::volumioGetState Jan 27 17:01:23 cx100 volumio[1175]: info: CorePlayQueue::getTrack 0 Jan 27 17:01:23 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jan 27 17:01:23 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jan 27 17:01:23 cx100 go-librespot[2104]: time="2026-01-27T17:01:23+01:00" level=info msg="authenticated AP" username="31************************yq" Jan 27 17:01:23 cx100 volumio[1175]: info: Received Get System Info Jan 27 17:01:23 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jan 27 17:01:23 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jan 27 17:01:23 cx100 volumio[1175]: info: Discovery: Getting this device information Jan 27 17:01:23 cx100 volumio[1175]: info: CoreCommandRouter::volumioGetState Jan 27 17:01:23 cx100 volumio[1175]: info: CorePlayQueue::getTrack 0 Jan 27 17:01:23 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jan 27 17:01:23 cx100 go-librespot[2104]: time="2026-01-27T17:01:23+01:00" level=info msg="authenticated Login5" username="31************************yq" Jan 27 17:01:23 cx100 go-librespot[2104]: time="2026-01-27T17:01:23+01:00" level=debug msg="stored credentials" username="31************************yq" Jan 27 17:01:23 cx100 go-librespot[2104]: time="2026-01-27T17:01:23+01:00" level=debug msg="initializing zeroconf session" username="31************************yq" Jan 27 17:01:24 cx100 go-librespot[2104]: time="2026-01-27T17:01:24+01:00" level=debug msg="dealer connection opened" Jan 27 17:01:24 cx100 go-librespot[2104]: time="2026-01-27T17:01:24+01:00" level=trace msg="starting accesspoint recv loop" Jan 27 17:01:24 cx100 go-librespot[2104]: time="2026-01-27T17:01:24+01:00" level=trace msg="starting dealer recv loop" Jan 27 17:01:24 cx100 go-librespot[2104]: time="2026-01-27T17:01:24+01:00" level=trace msg="received accesspoint ping" Jan 27 17:01:24 cx100 go-librespot[2104]: time="2026-01-27T17:01:24+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jan 27 17:01:24 cx100 go-librespot[2104]: time="2026-01-27T17:01:24+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jan 27 17:01:24 cx100 go-librespot[2104]: time="2026-01-27T17:01:24+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jan 27 17:01:24 cx100 go-librespot[2104]: time="2026-01-27T17:01:24+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jan 27 17:01:24 cx100 go-librespot[2104]: time="2026-01-27T17:01:24+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jan 27 17:01:24 cx100 go-librespot[2104]: time="2026-01-27T17:01:24+01:00" level=debug msg="received connection id: OWI1MGIzNWYtMDlm...NDE0MTNBM0UzRA==" Jan 27 17:01:24 cx100 volumio[1175]: info: CoreCommandRouter::getUIConfigOnPlugin Jan 27 17:01:24 cx100 go-librespot[2104]: time="2026-01-27T17:01:24+01:00" level=trace msg="received accesspoint pong ack" Jan 27 17:01:24 cx100 go-librespot[2104]: time="2026-01-27T17:01:24+01:00" level=debug msg="put connect state because NEW_DEVICE" Jan 27 17:01:24 cx100 volumio[1175]: info: New Spotify access tokenBQAB_c8p4n... Jan 27 17:01:24 cx100 volumio[1175]: info: Spotify credentials grant success - running version from March 24, 2019 Jan 27 17:01:24 cx100 volumio[1175]: info: CoreCommandRouter::volumioGetState Jan 27 17:01:24 cx100 volumio[1175]: info: CorePlayQueue::getTrack 0 Jan 27 17:01:25 cx100 volumio[1175]: info: Getting Spotify volume Jan 27 17:01:25 cx100 volumio[1175]: info: Initializing connection to go-librespot Websocket Jan 27 17:01:26 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Jan 27 17:01:26 cx100 volumio[1175]: info: Spotify volume: 100 Jan 27 17:01:26 cx100 go-librespot[2104]: time="2026-01-27T17:01:26+01:00" level=debug msg="new websocket client" Jan 27 17:01:26 cx100 volumio[1175]: info: Connection to go-librespot Websocket established Jan 27 17:01:26 cx100 volumio[1175]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Jan 27 17:01:26 cx100 volumio[1175]: info: go-librespot daemon successfully initialized Jan 27 17:01:26 cx100 volumio[1175]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Jan 27 17:01:26 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Jan 27 17:01:26 cx100 volumio[1175]: info: Creating Spotify config file Jan 27 17:01:26 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:01:27 cx100 volumio[1175]: info: Spotify config file written Jan 27 17:01:27 cx100 volumio[1175]: info: Discovery: Browse raised the following error Error: getaddrinfo -3007 Jan 27 17:01:27 cx100 volumio[1175]: info: Discovery: Restarting Browsing Jan 27 17:01:27 cx100 volumio[1175]: SPOTIFY: User informations: {"country":"DK","display_name":"Rosenkrands","email":"rosenkrands@live.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/31idj4o4qpj2jz3qgyhtzwat7uyq"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/31idj4o4qpj2jz3qgyhtzwat7uyq","id":"31idj4o4qpj2jz3qgyhtzwat7uyq","images":[],"product":"premium","type":"user","uri":"spotify:user:31idj4o4qpj2jz3qgyhtzwat7uyq"} Jan 27 17:01:27 cx100 volumio[1175]: info: Spotify Successfully logged in Jan 27 17:01:27 cx100 volumio[1175]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 27 17:01:27 cx100 volumio[1175]: info: [1769529687407] CoreMusicLibrary::Adding element Spotify Jan 27 17:01:27 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 27 17:01:27 cx100 volumio[1175]: Cannot find translation for source Spotify Jan 27 17:01:27 cx100 sudo[2119]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 27 17:01:27 cx100 sudo[2119]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 17:01:27 cx100 systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jan 27 17:01:27 cx100 systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jan 27 17:01:27 cx100 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 17:01:27 cx100 volumio[1175]: info: Discovery: Browse raised the following error Error: getaddrinfo -3007 Jan 27 17:01:27 cx100 volumio[1175]: info: Discovery: Restarting Browsing Jan 27 17:01:27 cx100 volumio[1175]: info: Discovery: Restart already pending, ignoring duplicate call Jan 27 17:01:27 cx100 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 17:01:27 cx100 go-librespot[2121]: go-librespot daemon starting... Jan 27 17:01:27 cx100 sudo[2119]: pam_unix(sudo:session): session closed for user root Jan 27 17:01:27 cx100 go-librespot[2122]: time="2026-01-27T17:01:27+01:00" level=info msg="running go-librespot 0.6.2" Jan 27 17:01:27 cx100 go-librespot[2122]: time="2026-01-27T17:01:27+01:00" level=debug msg="app state loaded" Jan 27 17:01:27 cx100 go-librespot[2122]: time="2026-01-27T17:01:27+01:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 17:01:27 cx100 volumio[1175]: info: Discovery: Browse raised the following error Error: getaddrinfo -3007 Jan 27 17:01:27 cx100 volumio[1175]: info: Discovery: Restarting Browsing Jan 27 17:01:27 cx100 volumio[1175]: info: Discovery: Restart already pending, ignoring duplicate call Jan 27 17:01:27 cx100 volumio[1175]: info: Connection to go-librespot Websocket closed Jan 27 17:01:28 cx100 volumio[1175]: info: CoreCommandRouter::volumioGetState Jan 27 17:01:28 cx100 volumio[1175]: info: CorePlayQueue::getTrack 0 Jan 27 17:01:28 cx100 go-librespot[2122]: time="2026-01-27T17:01:28+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Jan 27 17:01:28 cx100 go-librespot[2122]: time="2026-01-27T17:01:28+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Jan 27 17:01:28 cx100 go-librespot[2122]: time="2026-01-27T17:01:28+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Jan 27 17:01:28 cx100 go-librespot[2122]: time="2026-01-27T17:01:28+01:00" level=info msg="zeroconf server listening on port 37025" Jan 27 17:01:28 cx100 go-librespot[2122]: time="2026-01-27T17:01:28+01:00" level=debug msg="obtained new client token: AACyHGR/WuydpKEyaAu4k+nvZ8Cs9LA9Z9kdaC9nC3Apzl8DyEj1vq8fWXVBoeFCv+iW2ZS5FvNHw8LKiYtLHtV9y+Xomj9T6slo60tVEZyHGOs57len1istbC6FR5dJwyXv231h0eSQ1f7aiQJ6YacMaeMN6PKozRZaPZgxjUbKMZaTaK4xxrdq1/d1/6cqfpbpWlWYWv1OqbDFXJ/k2j7O4wVJRtt3W0XmrLmv6N2ew+dFvqHmOZSb" Jan 27 17:01:28 cx100 go-librespot[2122]: time="2026-01-27T17:01:28+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Jan 27 17:01:28 cx100 go-librespot[2122]: time="2026-01-27T17:01:28+01:00" level=debug msg="completed keyexchange" Jan 27 17:01:28 cx100 go-librespot[2122]: time="2026-01-27T17:01:28+01:00" level=debug msg="completed challenge" Jan 27 17:01:28 cx100 go-librespot[2122]: time="2026-01-27T17:01:28+01:00" level=info msg="authenticated AP" username="31************************yq" Jan 27 17:01:28 cx100 go-librespot[2122]: time="2026-01-27T17:01:28+01:00" level=info msg="authenticated Login5" username="31************************yq" Jan 27 17:01:28 cx100 go-librespot[2122]: time="2026-01-27T17:01:28+01:00" level=debug msg="initializing zeroconf session" username="31************************yq" Jan 27 17:01:28 cx100 go-librespot[2122]: time="2026-01-27T17:01:28+01:00" level=debug msg="dealer connection opened" Jan 27 17:01:28 cx100 go-librespot[2122]: time="2026-01-27T17:01:28+01:00" level=trace msg="starting accesspoint recv loop" Jan 27 17:01:28 cx100 go-librespot[2122]: time="2026-01-27T17:01:28+01:00" level=trace msg="starting dealer recv loop" Jan 27 17:01:28 cx100 go-librespot[2122]: time="2026-01-27T17:01:28+01:00" level=trace msg="received accesspoint ping" Jan 27 17:01:28 cx100 go-librespot[2122]: time="2026-01-27T17:01:28+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jan 27 17:01:28 cx100 go-librespot[2122]: time="2026-01-27T17:01:28+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jan 27 17:01:28 cx100 go-librespot[2122]: time="2026-01-27T17:01:28+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jan 27 17:01:28 cx100 go-librespot[2122]: time="2026-01-27T17:01:28+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jan 27 17:01:28 cx100 go-librespot[2122]: time="2026-01-27T17:01:28+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jan 27 17:01:29 cx100 go-librespot[2122]: time="2026-01-27T17:01:29+01:00" level=debug msg="received connection id: ZGY2MGJiMDItNTM1...RjEwQzMwMDZFMA==" Jan 27 17:01:29 cx100 go-librespot[2122]: time="2026-01-27T17:01:29+01:00" level=trace msg="received accesspoint pong ack" Jan 27 17:01:29 cx100 go-librespot[2122]: time="2026-01-27T17:01:29+01:00" level=debug msg="put connect state because NEW_DEVICE" Jan 27 17:01:29 cx100 volumio[1175]: info: Getting Spotify volume Jan 27 17:01:29 cx100 volumio[1175]: info: Spotify volume: 100 Jan 27 17:01:29 cx100 volumio[1175]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Jan 27 17:01:29 cx100 volumio[1175]: info: Initializing connection to go-librespot Websocket Jan 27 17:01:29 cx100 go-librespot[2122]: time="2026-01-27T17:01:29+01:00" level=debug msg="new websocket client" Jan 27 17:01:29 cx100 volumio[1175]: info: Connection to go-librespot Websocket established Jan 27 17:01:29 cx100 volumio[1175]: info: CoreCommandRouter::volumioGetState Jan 27 17:01:29 cx100 volumio[1175]: info: CorePlayQueue::getTrack 0 Jan 27 17:01:30 cx100 volumio[1175]: info: Initializing connection to go-librespot Websocket Jan 27 17:01:30 cx100 volumio[1175]: info: go-librespot daemon successfully initialized Jan 27 17:01:30 cx100 go-librespot[2122]: time="2026-01-27T17:01:30+01:00" level=debug msg="new websocket client" Jan 27 17:01:31 cx100 volumio[1175]: info: Connection to go-librespot Websocket established Jan 27 17:01:31 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Jan 27 17:01:32 cx100 volumio[1175]: info: Discovery: Browse raised the following error Error: getaddrinfo -3007 Jan 27 17:01:32 cx100 volumio[1175]: info: Discovery: Restarting Browsing Jan 27 17:01:32 cx100 volumio[1175]: info: Discovery: Browse raised the following error Error: getaddrinfo -3007 Jan 27 17:01:32 cx100 volumio[1175]: info: Discovery: Restarting Browsing Jan 27 17:01:32 cx100 volumio[1175]: info: Discovery: Restart already pending, ignoring duplicate call Jan 27 17:01:32 cx100 volumio[1175]: info: Discovery: Browse raised the following error Error: getaddrinfo -3007 Jan 27 17:01:32 cx100 volumio[1175]: info: Discovery: Restarting Browsing Jan 27 17:01:32 cx100 volumio[1175]: info: Discovery: Restart already pending, ignoring duplicate call Jan 27 17:01:32 cx100 volumio[1175]: info: Getting Spotify volume Jan 27 17:01:32 cx100 volumio[1175]: info: Spotify volume: 100 Jan 27 17:01:32 cx100 volumio[1175]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Jan 27 17:01:32 cx100 volumio[1175]: info: CoreCommandRouter::volumioGetState Jan 27 17:01:32 cx100 volumio[1175]: info: CorePlayQueue::getTrack 0 Jan 27 17:01:33 cx100 volumio[1175]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Jan 27 17:01:33 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Jan 27 17:01:33 cx100 volumio[1175]: info: Creating Spotify config file Jan 27 17:01:33 cx100 volumio[1175]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:01:33 cx100 volumio[1175]: info: Spotify config file written Jan 27 17:01:33 cx100 sudo[2151]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 27 17:01:33 cx100 sudo[2151]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 17:01:34 cx100 volumio[1175]: info: Initializing connection to go-librespot Websocket Jan 27 17:01:34 cx100 systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jan 27 17:01:34 cx100 systemd[1]: go-librespot-daemon.service: Killing process 2127 (go-librespot) with signal SIGKILL. Jan 27 17:01:34 cx100 systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jan 27 17:01:34 cx100 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 17:01:34 cx100 volumio[1175]: info: Connection to go-librespot Websocket closed Jan 27 17:01:34 cx100 volumio[1175]: info: Connection to go-librespot Websocket closed Jan 27 17:01:34 cx100 volumio[1175]: info: Getting Spotify volume Jan 27 17:01:34 cx100 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 17:01:34 cx100 go-librespot[2153]: go-librespot daemon starting... Jan 27 17:01:34 cx100 sudo[2151]: pam_unix(sudo:session): session closed for user root Jan 27 17:01:34 cx100 volumio[1175]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 27 17:01:34 cx100 go-librespot[2154]: time="2026-01-27T17:01:34+01:00" level=info msg="running go-librespot 0.6.2" Jan 27 17:01:34 cx100 go-librespot[2154]: time="2026-01-27T17:01:34+01:00" level=debug msg="app state loaded" Jan 27 17:01:34 cx100 go-librespot[2154]: time="2026-01-27T17:01:34+01:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 17:01:34 cx100 volumio[1175]: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 27 17:01:34 cx100 volumio[1175]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Jan 27 17:01:34 cx100 volumio[1175]: errno: -111, Jan 27 17:01:34 cx100 volumio[1175]: code: 'ECONNREFUSED', Jan 27 17:01:34 cx100 volumio[1175]: syscall: 'connect', Jan 27 17:01:34 cx100 volumio[1175]: address: '127.0.0.1', Jan 27 17:01:34 cx100 volumio[1175]: port: 9879, Jan 27 17:01:34 cx100 volumio[1175]: response: undefined Jan 27 17:01:34 cx100 volumio[1175]: } Jan 27 17:01:34 cx100 volumio[1175]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 27 17:01:34 cx100 go-librespot[2154]: time="2026-01-27T17:01:34+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jan 27 17:01:34 cx100 go-librespot[2154]: time="2026-01-27T17:01:34+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jan 27 17:01:34 cx100 go-librespot[2154]: time="2026-01-27T17:01:34+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jan 27 17:01:34 cx100 go-librespot[2154]: time="2026-01-27T17:01:34+01:00" level=info msg="zeroconf server listening on port 40287" Jan 27 17:01:34 cx100 go-librespot[2154]: time="2026-01-27T17:01:34+01:00" level=debug msg="obtained new client token: AAAu9eyQwHz3s+J7j95M6ZD/7TYdprqY7EsI2ECvxWfD0sEn2Vis2yHjoBj1SEmWfa00ZU6u5tTc3732a9QAfGaE0EwCnascHz689y2K9bpUyS6KQqeJ+H1xMwGkBlLi8j57FNNzDuYsIXkLBZkaUYfeVIVrPtZkt/+HPBJgdZPnnxgqROHP0OhTwnS0UlyNfhdPmo2RgyYrNIm1hZcdEBU2Jih1VorLwXRboEl4ZDuUDcAYCb4ZUvNF" Jan 27 17:01:34 cx100 go-librespot[2154]: time="2026-01-27T17:01:34+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Jan 27 17:01:34 cx100 go-librespot[2154]: time="2026-01-27T17:01:34+01:00" level=debug msg="completed keyexchange" Jan 27 17:01:34 cx100 go-librespot[2154]: time="2026-01-27T17:01:34+01:00" level=debug msg="completed challenge" Jan 27 17:01:35 cx100 go-librespot[2154]: time="2026-01-27T17:01:35+01:00" level=info msg="authenticated AP" username="31************************yq" Jan 27 17:01:35 cx100 go-librespot[2154]: time="2026-01-27T17:01:35+01:00" level=info msg="authenticated Login5" username="31************************yq" Jan 27 17:01:35 cx100 go-librespot[2154]: time="2026-01-27T17:01:35+01:00" level=debug msg="initializing zeroconf session" username="31************************yq" Jan 27 17:01:35 cx100 go-librespot[2154]: time="2026-01-27T17:01:35+01:00" level=debug msg="dealer connection opened" Jan 27 17:01:35 cx100 go-librespot[2154]: time="2026-01-27T17:01:35+01:00" level=trace msg="starting accesspoint recv loop" Jan 27 17:01:35 cx100 go-librespot[2154]: time="2026-01-27T17:01:35+01:00" level=trace msg="starting dealer recv loop" Jan 27 17:01:35 cx100 go-librespot[2154]: time="2026-01-27T17:01:35+01:00" level=trace msg="received accesspoint ping" Jan 27 17:01:35 cx100 go-librespot[2154]: time="2026-01-27T17:01:35+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jan 27 17:01:35 cx100 go-librespot[2154]: time="2026-01-27T17:01:35+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jan 27 17:01:35 cx100 go-librespot[2154]: time="2026-01-27T17:01:35+01:00" level=debug msg="received connection id: ZmVkMzkyMmUtOGIz...NjY2RkY3NTAyQg==" Jan 27 17:01:35 cx100 go-librespot[2154]: time="2026-01-27T17:01:35+01:00" level=debug msg="put connect state because NEW_DEVICE" Jan 27 17:01:35 cx100 go-librespot[2154]: time="2026-01-27T17:01:35+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jan 27 17:01:35 cx100 go-librespot[2154]: time="2026-01-27T17:01:35+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jan 27 17:01:35 cx100 go-librespot[2154]: time="2026-01-27T17:01:35+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jan 27 17:01:35 cx100 go-librespot[2154]: time="2026-01-27T17:01:35+01:00" level=trace msg="received accesspoint pong ack" Jan 27 17:01:42 cx100 sudo[2194]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-27 17:00' Jan 27 17:01:42 cx100 sudo[2194]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="2d08ec68ade0b018167f2db96c3e58a38ca68229" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="4ad85e2147d972f0b838d33c21382d2d813b2ae8" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue Jan 20 18:01:18 UTC 2026" VOLUMIO_VERSION="4.089" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="9885f1e3a558c3ea9d61decc103defba"