Aug 25 20:19:00 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:00 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:00 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:00 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:00 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:00 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:00 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:00 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:01 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:01 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:01 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:01 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:01 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:01 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:02 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:02 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:02 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:02 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:02 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:02 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:03 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:03 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:03 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:03 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:03 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:03.390+01:00 level=INFO msg="check connectivity" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" latency=-1.332046ms timeout=10s Aug 25 20:19:03 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:03.428+01:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" latency=-1.332046ms timeout=10s endpoint=https://radio-directory.firebaseapp.com duration=36.12563ms Aug 25 20:19:03 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:03.435+01:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" latency=-1.332046ms timeout=10s endpoint=https://oauth-performer.dfs.volumio.org duration=42.906532ms Aug 25 20:19:03 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:03.438+01:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" latency=-1.332046ms timeout=10s endpoint=https://browsing-performer.dfs.volumio.org duration=45.989187ms Aug 25 20:19:03 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:03.484+01:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" latency=-1.332046ms timeout=10s endpoint=http://pushupdates.volumio.org duration=91.312582ms Aug 25 20:19:03 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:03.491+01:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" latency=-1.332046ms timeout=10s endpoint=https://google.com duration=98.78437ms Aug 25 20:19:03 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:03.530+01:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" latency=-1.332046ms timeout=10s endpoint=https://myvolumio.firebaseio.com duration=137.892137ms Aug 25 20:19:03 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:03.531+01:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" latency=-1.332046ms timeout=10s endpoint=https://www.googleapis.com duration=138.774153ms Aug 25 20:19:03 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:03.547+01:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" latency=-1.332046ms timeout=10s endpoint=https://securetoken.googleapis.com duration=154.446245ms Aug 25 20:19:03 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:03.548+01:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" latency=-1.332046ms timeout=10s endpoint=https://functions.volumio.cloud duration=155.602278ms Aug 25 20:19:03 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:03.549+01:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" latency=-1.332046ms timeout=10s endpoint=https://functions.volumio.cloud duration=156.135368ms Aug 25 20:19:03 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:03.564+01:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" latency=-1.332046ms timeout=10s endpoint=https://database.volumio.cloud duration=169.953837ms Aug 25 20:19:03 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:03 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:03 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:03.777+01:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" latency=-1.332046ms timeout=10s endpoint=http://cddb.volumio.org duration=384.853941ms Aug 25 20:19:03 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:03.895+01:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" latency=-1.332046ms timeout=10s endpoint=http://plugins.volumio.org duration=501.743412ms Aug 25 20:19:04 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:04 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:04 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:04 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:04 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:04 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:04 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:04 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:05 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:05 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:05 volumio volumio[28410]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 25 20:19:05 volumio volumio[28410]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 25 20:19:05 volumio volumio[28410]: info: Discovery: Getting this device information Aug 25 20:19:05 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:05 volumio volumio[28410]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 25 20:19:05 volumio volumio[28410]: verbose: New Socket.io Connection to 192.168.8.130:3000 from 192.168.8.147 UA: Dart/3.12 (dart:io) Engine version: 3 Transport: websocket Total Clients: 8 Aug 25 20:19:05 volumio volumio[28410]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 25 20:19:05 volumio volumio[28410]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 25 20:19:05 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:05 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:05 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:05 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:06 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:06 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:06 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:06 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:06 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:06 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:07 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:07 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:07 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:07 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:07 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:07 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:08 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:08 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:08 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:08 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:08 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:08 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:08 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:08 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:09 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:09 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:09 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:09 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:09 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:09 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:10 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:10 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:10 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:10 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:10 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:10 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:11 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:11 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:11 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:11 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:11 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:11 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:12 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:12 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:12 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:12 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:12 volumio volumio[28410]: info: Received OAUTH Data Aug 25 20:19:12 volumio volumio[28410]: info: Executing Spotify Oauth Login Aug 25 20:19:12 volumio volumio[28410]: info: Saving Spotify Refresh Token Aug 25 20:19:12 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:12 volumio sudo[26075]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 25 20:19:12 volumio sudo[26075]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 20:19:12 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:12 volumio sudo[26075]: pam_unix(sudo:session): session closed for user root Aug 25 20:19:12 volumio sudo[26077]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 25 20:19:12 volumio sudo[26077]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 20:19:12 volumio sudo[26077]: pam_unix(sudo:session): session closed for user root Aug 25 20:19:12 volumio volumio[28410]: verbose: New Socket.io Connection to 192.168.8.130 from 192.168.8.147 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_7 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 8 Aug 25 20:19:12 volumio volumio[28410]: info: New Spotify access tokenBQCbVpnShi... Aug 25 20:19:12 volumio volumio[28410]: info: Spotify credentials grant success - running version from March 24, 2019 Aug 25 20:19:12 volumio volumio[28410]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Aug 25 20:19:12 volumio volumio[28410]: info: CoreCommandRouter::volumioGetVisibleSources Aug 25 20:19:12 volumio volumio[28410]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 25 20:19:12 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:12 volumio volumio[28410]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Aug 25 20:19:12 volumio volumio[28410]: info: CoreCommandRouter::getUIConfigOnPlugin Aug 25 20:19:12 volumio volumio[28410]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Aug 25 20:19:12 volumio volumio[28410]: info: Received Get System Info Aug 25 20:19:12 volumio volumio[28410]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 25 20:19:12 volumio volumio[28410]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 25 20:19:12 volumio volumio[28410]: info: Discovery: Getting this device information Aug 25 20:19:12 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:12 volumio volumio[28410]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 25 20:19:12 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:12 volumio volumio[28410]: info: Listing playlists Aug 25 20:19:12 volumio volumio[28410]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Aug 25 20:19:12 volumio volumio[28410]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Aug 25 20:19:12 volumio volumio[28410]: info: CoreCommandRouter::getUIConfigOnPlugin Aug 25 20:19:12 volumio volumio[28410]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Aug 25 20:19:13 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:13 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:13 volumio volumio[28410]: SPOTIFY: User informations: {"account_id":"t82GVaIOx8","country":"GB","display_name":"Paul Goodwin","email":"pgoodwin22@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/31tiq3wne3n6pqa4l5txzjibxj5e"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/31tiq3wne3n6pqa4l5txzjibxj5e","id":"31tiq3wne3n6pqa4l5txzjibxj5e","images":[],"product":"premium","type":"user","uri":"spotify:user:31tiq3wne3n6pqa4l5txzjibxj5e"} Aug 25 20:19:13 volumio volumio[28410]: info: Creating Spotify config file Aug 25 20:19:13 volumio volumio[28410]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 20:19:13 volumio volumio[28410]: info: Spotify config file written Aug 25 20:19:13 volumio sudo[26082]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Aug 25 20:19:13 volumio sudo[26082]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 20:19:13 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Aug 25 20:19:13 volumio volumio[28410]: info: Connection to go-librespot Websocket closed Aug 25 20:19:13 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Aug 25 20:19:13 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 20:19:13 volumio systemd[1]: go-librespot-daemon.service: Consumed 20.456s CPU time. Aug 25 20:19:13 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 20:19:13 volumio go-librespot[26084]: go-librespot daemon starting... Aug 25 20:19:13 volumio sudo[26082]: pam_unix(sudo:session): session closed for user root Aug 25 20:19:13 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:13 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:13 volumio go-librespot[26085]: time="2026-08-25T20:19:13+01:00" level=info msg="running go-librespot 0.7.1" Aug 25 20:19:13 volumio go-librespot[26085]: time="2026-08-25T20:19:13+01:00" level=debug msg="app state loaded" Aug 25 20:19:13 volumio go-librespot[26085]: time="2026-08-25T20:19:13+01:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 20:19:13 volumio volumio[28410]: info: New Spotify access tokenBQBLm4Lkmd... Aug 25 20:19:13 volumio volumio[28410]: info: Spotify credentials grant success - running version from March 24, 2019 Aug 25 20:19:13 volumio volumio[28410]: SPOTIFY: User informations: {"account_id":"t82GVaIOx8","country":"GB","display_name":"Paul Goodwin","email":"pgoodwin22@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/31tiq3wne3n6pqa4l5txzjibxj5e"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/31tiq3wne3n6pqa4l5txzjibxj5e","id":"31tiq3wne3n6pqa4l5txzjibxj5e","images":[],"product":"premium","type":"user","uri":"spotify:user:31tiq3wne3n6pqa4l5txzjibxj5e"} Aug 25 20:19:13 volumio volumio[28410]: info: Spotify Successfully logged in Aug 25 20:19:13 volumio volumio[28410]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 25 20:19:13 volumio volumio[28410]: info: [1787685553521] CoreMusicLibrary::Adding element Spotify Aug 25 20:19:13 volumio volumio[28410]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 25 20:19:13 volumio volumio[28410]: Cannot find translation for source Mother Earth Radio Aug 25 20:19:13 volumio volumio[28410]: Cannot find translation for source Spotify Aug 25 20:19:13 volumio go-librespot[26085]: time="2026-08-25T20:19:13+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Aug 25 20:19:13 volumio go-librespot[26085]: time="2026-08-25T20:19:13+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 25 20:19:13 volumio go-librespot[26085]: time="2026-08-25T20:19:13+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 25 20:19:13 volumio go-librespot[26085]: time="2026-08-25T20:19:13+01:00" level=info msg="zeroconf server listening on port 33913" Aug 25 20:19:13 volumio go-librespot[26085]: time="2026-08-25T20:19:13+01:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 20:19:13 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:13 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:13 volumio go-librespot[26085]: time="2026-08-25T20:19:13+01:00" level=debug msg="obtained new client token: AAEyht3m9p74hEJnI5nSM14771n+4j8wY/T+0J97T9PmEnIXN7SpS7oJjdPlz6dCBKD8AXbZ3LsSeE0wJwifaN3ZU3W5cuo2PgbSI8rEwlbSEeSksBwhIYEgXjk8arNJsVhXGt06W4ewoLVMZoJmg+B8OkSLdT/7aJ8xCTrxGVGUPNvZcgNMdZji/aJNRIrS1jcGu6mjqXr8KoMmMG1Ie2rBTqDSGb0AoeYQyCjLg6Yd/3RVtIUsOOSQ" Aug 25 20:19:13 volumio go-librespot[26085]: time="2026-08-25T20:19:13+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 25 20:19:13 volumio go-librespot[26085]: time="2026-08-25T20:19:13+01:00" level=debug msg="completed keyexchange" Aug 25 20:19:13 volumio go-librespot[26085]: time="2026-08-25T20:19:13+01:00" level=debug msg="completed challenge" Aug 25 20:19:13 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:13 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:13 volumio go-librespot[26085]: time="2026-08-25T20:19:13+01:00" level=info msg="authenticated AP" username="31************************5e" Aug 25 20:19:14 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:14 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:14 volumio go-librespot[26085]: time="2026-08-25T20:19:14+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 25 20:19:14 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 20:19:14 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 20:19:14 volumio volumio[28410]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Aug 25 20:19:14 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:14 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:14 volumio volumio[28410]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 25 20:19:14 volumio volumio[28410]: info: Received Get System Info Aug 25 20:19:14 volumio volumio[28410]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 25 20:19:14 volumio volumio[28410]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 25 20:19:14 volumio volumio[28410]: info: Discovery: Getting this device information Aug 25 20:19:14 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:14 volumio volumio[28410]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 25 20:19:14 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:14 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:15 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:15 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:15 volumio volumio[28410]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 25 20:19:15 volumio volumio[28410]: info: Received Get System Info Aug 25 20:19:15 volumio volumio[28410]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 25 20:19:15 volumio volumio[28410]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 25 20:19:15 volumio volumio[28410]: info: Discovery: Getting this device information Aug 25 20:19:15 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:15 volumio volumio[28410]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 25 20:19:15 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:15 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:15 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:15 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:16 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:16 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:16 volumio volumio[28410]: info: Initializing connection to go-librespot Websocket Aug 25 20:19:16 volumio volumio[28410]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 20:19:16 volumio volumio[28410]: info: go-librespot daemon successfully initialized Aug 25 20:19:16 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:16 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:16 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:16 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:17 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:17 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:17 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:17 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:17 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Aug 25 20:19:17 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 20:19:17 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 20:19:17 volumio go-librespot[26109]: go-librespot daemon starting... Aug 25 20:19:17 volumio go-librespot[26110]: time="2026-08-25T20:19:17+01:00" level=info msg="running go-librespot 0.7.1" Aug 25 20:19:17 volumio go-librespot[26110]: time="2026-08-25T20:19:17+01:00" level=debug msg="app state loaded" Aug 25 20:19:17 volumio go-librespot[26110]: time="2026-08-25T20:19:17+01:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 20:19:17 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:17 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:17 volumio go-librespot[26110]: time="2026-08-25T20:19:17+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Aug 25 20:19:17 volumio go-librespot[26110]: time="2026-08-25T20:19:17+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 25 20:19:17 volumio go-librespot[26110]: time="2026-08-25T20:19:17+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 25 20:19:17 volumio go-librespot[26110]: time="2026-08-25T20:19:17+01:00" level=info msg="zeroconf server listening on port 33513" Aug 25 20:19:17 volumio go-librespot[26110]: time="2026-08-25T20:19:17+01:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 20:19:17 volumio go-librespot[26110]: time="2026-08-25T20:19:17+01:00" level=debug msg="obtained new client token: AAEUcBO5FeWQRb1V7Vd6MjWfyRZ1/Z48wMHC6BNJN4sLLZvbPGu/b9e/Xs7f7BlsIjHS7WFg7o14ovJ6u/vvOH8sNlDBIA0GyGkqbCCgk9woWTkoFCa+2BHZcxXIfPdV2w2yMYUwD513YEPKyTC6d4PgH7369P3o+Rfs4iJE+ApQf6XsGd11uAj95d1PQfuNQeylOCr5s1jKRpDfGgq4/+n2y1MUJMmuVSanEB5pBm3rKK5giQNkVgLg" Aug 25 20:19:17 volumio go-librespot[26110]: time="2026-08-25T20:19:17+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 25 20:19:17 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:17 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:18 volumio go-librespot[26110]: time="2026-08-25T20:19:18+01:00" level=debug msg="completed keyexchange" Aug 25 20:19:18 volumio go-librespot[26110]: time="2026-08-25T20:19:18+01:00" level=debug msg="completed challenge" Aug 25 20:19:18 volumio go-librespot[26110]: time="2026-08-25T20:19:18+01:00" level=info msg="authenticated AP" username="31************************5e" Aug 25 20:19:18 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:18 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:18 volumio go-librespot[26110]: time="2026-08-25T20:19:18+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 25 20:19:18 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 20:19:18 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 20:19:18 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:18 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:18 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:18 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:19 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:19 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:19 volumio volumio[28410]: info: Initializing connection to go-librespot Websocket Aug 25 20:19:19 volumio volumio[28410]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 20:19:19 volumio volumio[28410]: info: Initializing connection to go-librespot Websocket Aug 25 20:19:19 volumio volumio[28410]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 20:19:19 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:19 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:19 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:19 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:19 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:19.841+01:00 level=INFO msg="navigate to next page" component=server type=REQUEST_TYPE_CONTINUE_NAVIGATION peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" latency=-15.507298ms timeout=10s from=APP_PAGE_ROOT to=APP_PAGE_LEGACY_DEVICE Aug 25 20:19:19 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:19.858+01:00 level=INFO msg="check connectivity" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" latency=-15.994603ms timeout=10s Aug 25 20:19:19 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:19.897+01:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" latency=-15.994603ms timeout=10s endpoint=https://radio-directory.firebaseapp.com duration=39.394045ms Aug 25 20:19:19 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:19.906+01:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" latency=-15.994603ms timeout=10s endpoint=https://browsing-performer.dfs.volumio.org duration=48.301735ms Aug 25 20:19:19 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:19.907+01:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" latency=-15.994603ms timeout=10s endpoint=http://pushupdates.volumio.org duration=47.895885ms Aug 25 20:19:19 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:19.908+01:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" latency=-15.994603ms timeout=10s endpoint=https://oauth-performer.dfs.volumio.org duration=49.770414ms Aug 25 20:19:19 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:19.954+01:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" latency=-15.994603ms timeout=10s endpoint=https://google.com duration=96.448915ms Aug 25 20:19:19 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:19.991+01:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" latency=-15.994603ms timeout=10s endpoint=https://myvolumio.firebaseio.com duration=133.040914ms Aug 25 20:19:19 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:19.991+01:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" latency=-15.994603ms timeout=10s endpoint=https://www.googleapis.com duration=133.364913ms Aug 25 20:19:20 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:20.003+01:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" latency=-15.994603ms timeout=10s endpoint=https://database.volumio.cloud duration=144.817428ms Aug 25 20:19:20 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:20.012+01:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" latency=-15.994603ms timeout=10s endpoint=https://functions.volumio.cloud duration=154.023172ms Aug 25 20:19:20 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:20.012+01:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" latency=-15.994603ms timeout=10s endpoint=https://functions.volumio.cloud duration=154.428337ms Aug 25 20:19:20 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:20.023+01:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" latency=-15.994603ms timeout=10s endpoint=https://securetoken.googleapis.com duration=164.797968ms Aug 25 20:19:20 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:20 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:20 volumio sudo[26120]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 25 20:19:20 volumio sudo[26120]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 20:19:20 volumio sudo[26120]: pam_unix(sudo:session): session closed for user root Aug 25 20:19:20 volumio sudo[26122]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 25 20:19:20 volumio sudo[26122]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 20:19:20 volumio sudo[26122]: pam_unix(sudo:session): session closed for user root Aug 25 20:19:20 volumio volumio[28410]: verbose: New Socket.io Connection to 192.168.8.130 from 192.168.8.147 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_7 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 9 Aug 25 20:19:20 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:20.209+01:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" latency=-15.994603ms timeout=10s endpoint=http://cddb.volumio.org duration=350.828211ms Aug 25 20:19:20 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:20.316+01:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" latency=-15.994603ms timeout=10s endpoint=http://plugins.volumio.org duration=458.209198ms Aug 25 20:19:20 volumio sudo[26126]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 25 20:19:20 volumio sudo[26126]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 20:19:20 volumio sudo[26126]: pam_unix(sudo:session): session closed for user root Aug 25 20:19:20 volumio sudo[26128]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 25 20:19:20 volumio sudo[26128]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 20:19:20 volumio sudo[26128]: pam_unix(sudo:session): session closed for user root Aug 25 20:19:20 volumio volumio[28410]: verbose: New Socket.io Connection to 192.168.8.130 from 192.168.8.147 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_7 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 9 Aug 25 20:19:20 volumio volumio[28410]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Aug 25 20:19:20 volumio volumio[28410]: info: CoreCommandRouter::volumioGetVisibleSources Aug 25 20:19:20 volumio volumio[28410]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 25 20:19:20 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:20 volumio volumio[28410]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Aug 25 20:19:20 volumio volumio[28410]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Aug 25 20:19:20 volumio volumio[28410]: info: Received Get System Info Aug 25 20:19:20 volumio volumio[28410]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 25 20:19:20 volumio volumio[28410]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 25 20:19:20 volumio volumio[28410]: info: Discovery: Getting this device information Aug 25 20:19:20 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:20 volumio volumio[28410]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 25 20:19:20 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:20 volumio volumio[28410]: info: Listing playlists Aug 25 20:19:20 volumio volumio[28410]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Aug 25 20:19:20 volumio volumio[28410]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Aug 25 20:19:20 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:20 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:20 volumio volumio[28410]: info: CoreCommandRouter::getUIConfigOnPlugin Aug 25 20:19:20 volumio volumio[28410]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Aug 25 20:19:20 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:20 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:21 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:21 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:21 volumio volumio[28410]: info: CoreCommandRouter::volumioStop Aug 25 20:19:21 volumio volumio[28410]: info: CoreStateMachine::stop Aug 25 20:19:21 volumio volumio[28410]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 25 20:19:21 volumio volumio[28410]: info: CoreStateMachine::stPlaybackTimer Aug 25 20:19:21 volumio volumio[28410]: info: CoreStateMachine::updateTrackBlock Aug 25 20:19:21 volumio volumio[28410]: info: CorePlayQueue::getTrackBlock Aug 25 20:19:21 volumio volumio[28410]: info: CoreStateMachine::pushState Aug 25 20:19:21 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:21 volumio volumio[28410]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 25 20:19:21 volumio volumio[28410]: info: CoreCommandRouter::volumioPushState Aug 25 20:19:21 volumio volumio[28410]: info: CoreStateMachine::serviceStop Aug 25 20:19:21 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:21 volumio volumio[28410]: info: CoreCommandRouter::serviceStop Aug 25 20:19:21 volumio volumio[28410]: info: [1787685561275] ControllerWebradio::stop Aug 25 20:19:21 volumio volumio[28410]: verbose: ControllerMpd::sendMpdCommand stop Aug 25 20:19:21 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:21.276+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" state=STATUS_STOPPED positionMs=0 volume=71 Aug 25 20:19:21 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:21.276+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" id=http://direct.fipradio.fr/live/fip-midfi.mp3 title=FIP Aug 25 20:19:21 volumio volumio[28410]: info: FusionDsp - Volumio is not playing Aug 25 20:19:21 volumio volumio[28410]: info: FusionDsp - Clipped samples monitor stopped Aug 25 20:19:21 volumio volumio[28410]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Aug 25 20:19:21 volumio volumio[28410]: info: Aug 25 20:19:21 volumio volumio[28410]: ---------------------------- MPD announces state update: player Aug 25 20:19:21 volumio volumio[28410]: info: sendMpdCommand stop took 9 milliseconds Aug 25 20:19:21 volumio volumio[28410]: info: ControllerMpd::getState Aug 25 20:19:21 volumio volumio[28410]: verbose: ControllerMpd::sendMpdCommand status Aug 25 20:19:21 volumio volumio[28410]: info: sendMpdCommand status took 1 milliseconds Aug 25 20:19:21 volumio volumio[28410]: verbose: ControllerMpd::parseState Aug 25 20:19:21 volumio volumio[28410]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 25 20:19:21 volumio volumio[28410]: info: Aug 25 20:19:21 volumio volumio[28410]: ---------------------------- MPD announces state update: player Aug 25 20:19:21 volumio volumio[28410]: info: ControllerMpd::getState Aug 25 20:19:21 volumio volumio[28410]: verbose: ControllerMpd::sendMpdCommand status Aug 25 20:19:21 volumio volumio[28410]: info: Aug 25 20:19:21 volumio volumio[28410]: ---------------------------- MPD announces state update: player Aug 25 20:19:21 volumio volumio[28410]: info: ControllerMpd::getState Aug 25 20:19:21 volumio volumio[28410]: verbose: ControllerMpd::sendMpdCommand status Aug 25 20:19:21 volumio volumio[28410]: info: Aug 25 20:19:21 volumio volumio[28410]: ---------------------------- MPD announces state update: player Aug 25 20:19:21 volumio volumio[28410]: info: ControllerMpd::getState Aug 25 20:19:21 volumio volumio[28410]: verbose: ControllerMpd::sendMpdCommand status Aug 25 20:19:21 volumio volumio[28410]: info: Aug 25 20:19:21 volumio volumio[28410]: ---------------------------- MPD announces state update: player Aug 25 20:19:21 volumio volumio[28410]: info: ControllerMpd::getState Aug 25 20:19:21 volumio volumio[28410]: verbose: ControllerMpd::sendMpdCommand status Aug 25 20:19:21 volumio volumio[28410]: info: sendMpdCommand playlistinfo took 5 milliseconds Aug 25 20:19:21 volumio volumio[28410]: info: sendMpdCommand status took 4 milliseconds Aug 25 20:19:21 volumio volumio[28410]: info: sendMpdCommand status took 3 milliseconds Aug 25 20:19:21 volumio volumio[28410]: info: sendMpdCommand status took 3 milliseconds Aug 25 20:19:21 volumio volumio[28410]: info: sendMpdCommand status took 2 milliseconds Aug 25 20:19:21 volumio volumio[28410]: verbose: ControllerMpd::parseTrackInfo Aug 25 20:19:21 volumio volumio[28410]: verbose: ControllerMpd::parseState Aug 25 20:19:21 volumio volumio[28410]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 25 20:19:21 volumio volumio[28410]: verbose: ControllerMpd::parseState Aug 25 20:19:21 volumio volumio[28410]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 25 20:19:21 volumio volumio[28410]: verbose: ControllerMpd::parseState Aug 25 20:19:21 volumio volumio[28410]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 25 20:19:21 volumio volumio[28410]: verbose: ControllerMpd::parseState Aug 25 20:19:21 volumio volumio[28410]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 25 20:19:21 volumio volumio[28410]: info: ControllerMpd::pushState Aug 25 20:19:21 volumio volumio[28410]: info: CoreCommandRouter::servicePushState Aug 25 20:19:21 volumio volumio[28410]: info: CoreStateMachine::pushState Aug 25 20:19:21 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:21 volumio volumio[28410]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 25 20:19:21 volumio volumio[28410]: info: CoreCommandRouter::volumioPushState Aug 25 20:19:21 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:21 volumio volumio[28410]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current webradio Received mpd Aug 25 20:19:21 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:21.295+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" state=STATUS_STOPPED positionMs=251 volume=71 Aug 25 20:19:21 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:21.296+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" id=http://direct.fipradio.fr/live/fip-midfi.mp3 title=FIP Aug 25 20:19:21 volumio volumio[28410]: info: ------------------------------ 14ms Aug 25 20:19:21 volumio volumio[28410]: info: sendMpdCommand playlistinfo took 6 milliseconds Aug 25 20:19:21 volumio volumio[28410]: info: sendMpdCommand playlistinfo took 7 milliseconds Aug 25 20:19:21 volumio volumio[28410]: info: sendMpdCommand playlistinfo took 7 milliseconds Aug 25 20:19:21 volumio volumio[28410]: info: sendMpdCommand playlistinfo took 7 milliseconds Aug 25 20:19:21 volumio volumio[28410]: verbose: ControllerMpd::parseTrackInfo Aug 25 20:19:21 volumio volumio[28410]: verbose: ControllerMpd::parseTrackInfo Aug 25 20:19:21 volumio volumio[28410]: verbose: ControllerMpd::parseTrackInfo Aug 25 20:19:21 volumio volumio[28410]: verbose: ControllerMpd::parseTrackInfo Aug 25 20:19:21 volumio volumio[28410]: info: ControllerMpd::pushState Aug 25 20:19:21 volumio volumio[28410]: info: CoreCommandRouter::servicePushState Aug 25 20:19:21 volumio volumio[28410]: info: CoreStateMachine::pushState Aug 25 20:19:21 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:21 volumio volumio[28410]: info: CoreCommandRouter::volumioPushState Aug 25 20:19:21 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:21 volumio volumio[28410]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current webradio Received mpd Aug 25 20:19:21 volumio volumio[28410]: info: ControllerMpd::pushState Aug 25 20:19:21 volumio volumio[28410]: info: CoreCommandRouter::servicePushState Aug 25 20:19:21 volumio volumio[28410]: info: CoreStateMachine::pushState Aug 25 20:19:21 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:21 volumio volumio[28410]: info: CoreCommandRouter::volumioPushState Aug 25 20:19:21 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:21 volumio volumio[28410]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current webradio Received mpd Aug 25 20:19:21 volumio volumio[28410]: info: ControllerMpd::pushState Aug 25 20:19:21 volumio volumio[28410]: info: CoreCommandRouter::servicePushState Aug 25 20:19:21 volumio volumio[28410]: info: CoreStateMachine::pushState Aug 25 20:19:21 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:21 volumio volumio[28410]: info: CoreCommandRouter::volumioPushState Aug 25 20:19:21 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:21 volumio volumio[28410]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current webradio Received mpd Aug 25 20:19:21 volumio volumio[28410]: info: ControllerMpd::pushState Aug 25 20:19:21 volumio volumio[28410]: info: CoreCommandRouter::servicePushState Aug 25 20:19:21 volumio volumio[28410]: info: CoreStateMachine::pushState Aug 25 20:19:21 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:21 volumio volumio[28410]: info: CoreCommandRouter::volumioPushState Aug 25 20:19:21 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:21 volumio volumio[28410]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current webradio Received mpd Aug 25 20:19:21 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:21.305+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" state=STATUS_STOPPED positionMs=251 volume=71 Aug 25 20:19:21 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:21.305+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" id=http://direct.fipradio.fr/live/fip-midfi.mp3 title=FIP Aug 25 20:19:21 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:21.306+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" state=STATUS_STOPPED positionMs=251 volume=71 Aug 25 20:19:21 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:21.306+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" state=STATUS_STOPPED positionMs=251 volume=71 Aug 25 20:19:21 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:21.306+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" id=http://direct.fipradio.fr/live/fip-midfi.mp3 title=FIP Aug 25 20:19:21 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:21.306+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" id=http://direct.fipradio.fr/live/fip-midfi.mp3 title=FIP Aug 25 20:19:21 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:21.306+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" state=STATUS_STOPPED positionMs=251 volume=71 Aug 25 20:19:21 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:21.306+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" id=http://direct.fipradio.fr/live/fip-midfi.mp3 title=FIP Aug 25 20:19:21 volumio volumio[28410]: info: ------------------------------ 25ms Aug 25 20:19:21 volumio volumio[28410]: info: ------------------------------ 25ms Aug 25 20:19:21 volumio volumio[28410]: info: ------------------------------ 25ms Aug 25 20:19:21 volumio volumio[28410]: info: ------------------------------ 24ms Aug 25 20:19:21 volumio volumio[28410]: info: FusionDsp - Volumio is not playing Aug 25 20:19:21 volumio volumio[28410]: info: FusionDsp - Clipped samples monitor stopped Aug 25 20:19:21 volumio volumio[28410]: info: FusionDsp - Volumio is not playing Aug 25 20:19:21 volumio volumio[28410]: info: FusionDsp - Clipped samples monitor stopped Aug 25 20:19:21 volumio volumio[28410]: info: FusionDsp - Volumio is not playing Aug 25 20:19:21 volumio volumio[28410]: info: FusionDsp - Clipped samples monitor stopped Aug 25 20:19:21 volumio volumio[28410]: info: FusionDsp - Volumio is not playing Aug 25 20:19:21 volumio volumio[28410]: info: FusionDsp - Clipped samples monitor stopped Aug 25 20:19:21 volumio volumio[28410]: info: FusionDsp - Volumio is not playing Aug 25 20:19:21 volumio volumio[28410]: info: FusionDsp - Clipped samples monitor stopped Aug 25 20:19:21 volumio volumio[28410]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Aug 25 20:19:21 volumio volumio[28410]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Aug 25 20:19:21 volumio volumio[28410]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Aug 25 20:19:21 volumio volumio[28410]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Aug 25 20:19:21 volumio volumio[28410]: SPOTIFY: RECEIVED VOLUMIO VOLUME 71 Aug 25 20:19:21 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:21 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:21 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:21 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:21 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Aug 25 20:19:21 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 20:19:21 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 20:19:21 volumio go-librespot[26132]: go-librespot daemon starting... Aug 25 20:19:21 volumio go-librespot[26133]: time="2026-08-25T20:19:21+01:00" level=info msg="running go-librespot 0.7.1" Aug 25 20:19:21 volumio go-librespot[26133]: time="2026-08-25T20:19:21+01:00" level=debug msg="app state loaded" Aug 25 20:19:21 volumio go-librespot[26133]: time="2026-08-25T20:19:21+01:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 20:19:21 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:21 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:21 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:21 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:21 volumio go-librespot[26133]: time="2026-08-25T20:19:21+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Aug 25 20:19:21 volumio go-librespot[26133]: time="2026-08-25T20:19:21+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 25 20:19:21 volumio go-librespot[26133]: time="2026-08-25T20:19:21+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 25 20:19:21 volumio go-librespot[26133]: time="2026-08-25T20:19:21+01:00" level=info msg="zeroconf server listening on port 37909" Aug 25 20:19:21 volumio go-librespot[26133]: time="2026-08-25T20:19:21+01:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 20:19:21 volumio go-librespot[26133]: time="2026-08-25T20:19:21+01:00" level=debug msg="obtained new client token: AAGM3tZqV3tsuqtzltPTUREaht+Af6jZhE91b0njlpkS4aDy8iO8N5rGuI5wkkx4CGFKPhKFgjFYgCMecBGfAATuUi8rFTvQME5y/wJZAlxcgkz11iLCYxI77c1xVPzUGYiyraSTgDg6p1Mq8F1htujRnk0ytd38eiSuE6AU+M4O157o7fB4gda3LdO5SA95wzTTWQmi60Fx2x8y/u4pJEouLwtsKxJJ+ZroqkdVL3kAlJraWqSf618+" Aug 25 20:19:21 volumio go-librespot[26133]: time="2026-08-25T20:19:21+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 25 20:19:21 volumio volumio[28410]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Aug 25 20:19:21 volumio go-librespot[26133]: time="2026-08-25T20:19:21+01:00" level=debug msg="completed keyexchange" Aug 25 20:19:21 volumio go-librespot[26133]: time="2026-08-25T20:19:21+01:00" level=debug msg="completed challenge" Aug 25 20:19:21 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:21 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:21 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:21 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:22 volumio go-librespot[26133]: time="2026-08-25T20:19:22+01:00" level=info msg="authenticated AP" username="31************************5e" Aug 25 20:19:22 volumio volumio[28410]: info: camilladsp respawn in 100 ms (attempt 1/10) Aug 25 20:19:22 volumio go-librespot[26133]: time="2026-08-25T20:19:22+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 25 20:19:22 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 20:19:22 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 20:19:22 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:22 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:22 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:22 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:22 volumio volumio[28410]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 25 20:19:22 volumio volumio[28410]: info: Received Get System Info Aug 25 20:19:22 volumio volumio[28410]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 25 20:19:22 volumio volumio[28410]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 25 20:19:22 volumio volumio[28410]: info: Discovery: Getting this device information Aug 25 20:19:22 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:22 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:22 volumio volumio[28410]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 25 20:19:22 volumio volumio[28410]: info: Initializing connection to go-librespot Websocket Aug 25 20:19:22 volumio volumio[28410]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 20:19:22 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:22 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:22 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:22 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:22 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:22 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:22 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:22 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:23 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:23 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:23 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:23 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:23 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:23 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:23 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:23 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:23 volumio volumio[28410]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 25 20:19:23 volumio volumio[28410]: info: Received Get System Info Aug 25 20:19:23 volumio volumio[28410]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 25 20:19:23 volumio volumio[28410]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 25 20:19:23 volumio volumio[28410]: info: Discovery: Getting this device information Aug 25 20:19:23 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:23 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:23 volumio volumio[28410]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 25 20:19:23 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:23 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:23 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:23 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:24 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:24 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:24 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:24 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:24 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:24 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:24 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:24 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:24 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:24 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:24 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:24 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:25 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:25 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:25 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:25 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:25 volumio volumio[28410]: info: Initializing connection to go-librespot Websocket Aug 25 20:19:25 volumio volumio[28410]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 20:19:25 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:25 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:25 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:25 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:25 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Aug 25 20:19:25 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 20:19:25 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 20:19:25 volumio go-librespot[26159]: go-librespot daemon starting... Aug 25 20:19:25 volumio go-librespot[26160]: time="2026-08-25T20:19:25+01:00" level=info msg="running go-librespot 0.7.1" Aug 25 20:19:25 volumio go-librespot[26160]: time="2026-08-25T20:19:25+01:00" level=debug msg="app state loaded" Aug 25 20:19:25 volumio go-librespot[26160]: time="2026-08-25T20:19:25+01:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 20:19:25 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:25 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:25 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:25 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:25 volumio go-librespot[26160]: time="2026-08-25T20:19:25+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Aug 25 20:19:25 volumio go-librespot[26160]: time="2026-08-25T20:19:25+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 25 20:19:25 volumio go-librespot[26160]: time="2026-08-25T20:19:25+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 25 20:19:25 volumio go-librespot[26160]: time="2026-08-25T20:19:25+01:00" level=info msg="zeroconf server listening on port 42803" Aug 25 20:19:25 volumio go-librespot[26160]: time="2026-08-25T20:19:25+01:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 20:19:25 volumio go-librespot[26160]: time="2026-08-25T20:19:25+01:00" level=debug msg="obtained new client token: AAErt4OXguoE8zXqk4pXbroNI8dmtMHOnkZ/k0sqWdQX9j21kiJbnrc9YSOrSQlo+I+N4nysbSInTiyFXJvvwyQmTJJGbflJJDWO/KEArsEzKiAWXujS2DnHiEJjtrcdpy8XEs3Ka4HN4xsSxfr84Nbde/nAVHGulQOhxslSNhKnH6HgD+QDmmG0r2YYUEDY66y3EgkO5P1rkXphLv2n2DeG8PnMGZXR4x1VFuX9GQY2QeYSkCa1mmJc" Aug 25 20:19:25 volumio go-librespot[26160]: time="2026-08-25T20:19:25+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 25 20:19:25 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:25 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:25 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:25 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:25 volumio go-librespot[26160]: time="2026-08-25T20:19:25+01:00" level=debug msg="completed keyexchange" Aug 25 20:19:25 volumio go-librespot[26160]: time="2026-08-25T20:19:25+01:00" level=debug msg="completed challenge" Aug 25 20:19:26 volumio go-librespot[26160]: time="2026-08-25T20:19:26+01:00" level=info msg="authenticated AP" username="31************************5e" Aug 25 20:19:26 volumio go-librespot[26160]: time="2026-08-25T20:19:26+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 25 20:19:26 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 20:19:26 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 20:19:26 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:26 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:26 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:26 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:26 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:26 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:26 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:26 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:26 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:26 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:26 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:26 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:27 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:27 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:27 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:27 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:27 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:27 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:27 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:27 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:27 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:27 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:27 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:27 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:28 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:28 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:28 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:28 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:28 volumio volumio[28410]: info: Initializing connection to go-librespot Websocket Aug 25 20:19:28 volumio volumio[28410]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 20:19:28 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:28 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:28 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:28 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:28 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:28 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:28 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:28 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:29 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:29 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:29 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:29 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:29 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Aug 25 20:19:29 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 20:19:29 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:29 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:29 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:29 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:29 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 20:19:29 volumio go-librespot[26170]: go-librespot daemon starting... Aug 25 20:19:29 volumio go-librespot[26171]: time="2026-08-25T20:19:29+01:00" level=info msg="running go-librespot 0.7.1" Aug 25 20:19:29 volumio go-librespot[26171]: time="2026-08-25T20:19:29+01:00" level=debug msg="app state loaded" Aug 25 20:19:29 volumio go-librespot[26171]: time="2026-08-25T20:19:29+01:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 20:19:29 volumio go-librespot[26171]: time="2026-08-25T20:19:29+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Aug 25 20:19:29 volumio go-librespot[26171]: time="2026-08-25T20:19:29+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 25 20:19:29 volumio go-librespot[26171]: time="2026-08-25T20:19:29+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 25 20:19:29 volumio go-librespot[26171]: time="2026-08-25T20:19:29+01:00" level=info msg="zeroconf server listening on port 37227" Aug 25 20:19:29 volumio go-librespot[26171]: time="2026-08-25T20:19:29+01:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 20:19:29 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:29 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:29 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:29 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:29 volumio go-librespot[26171]: time="2026-08-25T20:19:29+01:00" level=debug msg="obtained new client token: AAGH08RLLUDB0dLFRzQ1XnlMLdnMy5BX2zxH/OCdmg4I/gh/NEbichetaTWS45bp9b+y39Rct15PXA7HSv2uYEt8d3h/M+54Yb/V1sG/13Y1UyN+2BK6LNG9JYa8h4aT8dSYoQVUIC2IAcmvLbNcyLfWLrjguXTup1bZEjwDO/Y7FBKfGXPhtUGyHEUcQdhyNfJH4aBGxafl1VxG/+CLaeznoe2CbogZ6sh/JCPRCCG2FIfucjt5/ngf" Aug 25 20:19:29 volumio go-librespot[26171]: time="2026-08-25T20:19:29+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 25 20:19:29 volumio go-librespot[26171]: time="2026-08-25T20:19:29+01:00" level=debug msg="completed keyexchange" Aug 25 20:19:29 volumio go-librespot[26171]: time="2026-08-25T20:19:29+01:00" level=debug msg="completed challenge" Aug 25 20:19:29 volumio go-librespot[26171]: time="2026-08-25T20:19:29+01:00" level=info msg="authenticated AP" username="31************************5e" Aug 25 20:19:30 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:30 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:30 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:30 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:30 volumio go-librespot[26171]: time="2026-08-25T20:19:30+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 25 20:19:30 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 20:19:30 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 20:19:30 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:30 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:30 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:30 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:30 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:30 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:30 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:30 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:30 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:30 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:30 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:30 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:31 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:31 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:31 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:31 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:31 volumio volumio[28410]: info: Initializing connection to go-librespot Websocket Aug 25 20:19:31 volumio volumio[28410]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 20:19:31 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:31 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:31 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:31 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:31 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:31 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:31 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:31 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:32 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:32 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:32 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:32 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:32 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:32 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:32 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:32 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:32 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:32 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:32 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:32 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:33 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:33 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:33 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:33 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:33 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Aug 25 20:19:33 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 20:19:33 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 20:19:33 volumio go-librespot[26181]: go-librespot daemon starting... Aug 25 20:19:33 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:33 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:33 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:33 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:33 volumio go-librespot[26182]: time="2026-08-25T20:19:33+01:00" level=info msg="running go-librespot 0.7.1" Aug 25 20:19:33 volumio go-librespot[26182]: time="2026-08-25T20:19:33+01:00" level=debug msg="app state loaded" Aug 25 20:19:33 volumio go-librespot[26182]: time="2026-08-25T20:19:33+01:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 20:19:33 volumio go-librespot[26182]: time="2026-08-25T20:19:33+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Aug 25 20:19:33 volumio go-librespot[26182]: time="2026-08-25T20:19:33+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 25 20:19:33 volumio go-librespot[26182]: time="2026-08-25T20:19:33+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 25 20:19:33 volumio go-librespot[26182]: time="2026-08-25T20:19:33+01:00" level=info msg="zeroconf server listening on port 36443" Aug 25 20:19:33 volumio go-librespot[26182]: time="2026-08-25T20:19:33+01:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 20:19:33 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:33 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:33 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:33 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:33 volumio go-librespot[26182]: time="2026-08-25T20:19:33+01:00" level=debug msg="obtained new client token: AAHAe+R5yO0zTJ7o0Z9UPP+hRg7lkO4uMK3owDgLa8vzQ5l+pJvhb4K2yVJZX2+bXuklmdAwkwvrwUFJ0RWA9JWYSZUp1jqbyAewXVYWKIDLMHjvMbdUtUr/LGgQA0GE4wersypO7BkzIUhb3gMpgj5Q6CKQbp7LNX0PuVzBkidxCLCa83AdklmUKgpIlkOsFymgVIQcFp1vFrZw6kq51K3L5UVuFD+QSpaRAN8Uaz9RO/oUTIJ1fdyl" Aug 25 20:19:33 volumio go-librespot[26182]: time="2026-08-25T20:19:33+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 25 20:19:33 volumio go-librespot[26182]: time="2026-08-25T20:19:33+01:00" level=debug msg="completed keyexchange" Aug 25 20:19:33 volumio go-librespot[26182]: time="2026-08-25T20:19:33+01:00" level=debug msg="completed challenge" Aug 25 20:19:34 volumio go-librespot[26182]: time="2026-08-25T20:19:34+01:00" level=info msg="authenticated AP" username="31************************5e" Aug 25 20:19:34 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:34 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:34 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:34 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:34 volumio go-librespot[26182]: time="2026-08-25T20:19:34+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 25 20:19:34 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 20:19:34 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 20:19:34 volumio volumio[28410]: info: Initializing connection to go-librespot Websocket Aug 25 20:19:34 volumio volumio[28410]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 20:19:34 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:34 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:34 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:34 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:34 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:34 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:34 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:34 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:34 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:34 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:34 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:34 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:35 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:35 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:35 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:35 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:35 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:35 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:35 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:35 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:35 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:35 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:35 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:35 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:36 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:36 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:36 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:36 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:36 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:36 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:36 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:36 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:36 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:36 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:36 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:36 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:37 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:37 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:37 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:37 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:37 volumio volumio[28410]: info: Initializing connection to go-librespot Websocket Aug 25 20:19:37 volumio volumio[28410]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 20:19:37 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. Aug 25 20:19:37 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 20:19:37 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 20:19:37 volumio go-librespot[26206]: go-librespot daemon starting... Aug 25 20:19:37 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:37 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:37 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:37 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:37 volumio go-librespot[26207]: time="2026-08-25T20:19:37+01:00" level=info msg="running go-librespot 0.7.1" Aug 25 20:19:37 volumio go-librespot[26207]: time="2026-08-25T20:19:37+01:00" level=debug msg="app state loaded" Aug 25 20:19:37 volumio go-librespot[26207]: time="2026-08-25T20:19:37+01:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 20:19:37 volumio go-librespot[26207]: time="2026-08-25T20:19:37+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Aug 25 20:19:37 volumio go-librespot[26207]: time="2026-08-25T20:19:37+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 25 20:19:37 volumio go-librespot[26207]: time="2026-08-25T20:19:37+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 25 20:19:37 volumio go-librespot[26207]: time="2026-08-25T20:19:37+01:00" level=info msg="zeroconf server listening on port 36893" Aug 25 20:19:37 volumio go-librespot[26207]: time="2026-08-25T20:19:37+01:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 20:19:37 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:37 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:37 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:37 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:37 volumio go-librespot[26207]: time="2026-08-25T20:19:37+01:00" level=debug msg="obtained new client token: AAH84N5U2c+6MjiwwexjwUUIGa4LJE5ppCPjtgQkeioUsjM77QSbpzY2aW0uET4C8eTXjQdzdCOVSt5fr+RlfadGrYhH9US+tA13Cuo19lI8OCCa3u0Y5c9AwKbgE7F7MLzWbN+pFUe37Pc5q3NuCWpgJ9+K7hgCCW8A0KtNdagboL7VPcPIybH3/N5wnithP+QvBQN2lEZRBwXmdw4oLQZbDm76ZYTqy6Z7jRDvgqlvClUgIxqRGY+J" Aug 25 20:19:37 volumio go-librespot[26207]: time="2026-08-25T20:19:37+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 25 20:19:38 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:38 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:38 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:38 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:38 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:38 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:38 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:38 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:38 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:38 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:38 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:38 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:38 volumio go-librespot[26207]: time="2026-08-25T20:19:38+01:00" level=debug msg="completed keyexchange" Aug 25 20:19:38 volumio go-librespot[26207]: time="2026-08-25T20:19:38+01:00" level=debug msg="completed challenge" Aug 25 20:19:38 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:38 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:38 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:38 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:39 volumio go-librespot[26207]: time="2026-08-25T20:19:39+01:00" level=info msg="authenticated AP" username="31************************5e" Aug 25 20:19:39 volumio go-librespot[26207]: time="2026-08-25T20:19:39+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 25 20:19:39 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 20:19:39 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 20:19:39 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:39 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:39 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:39 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:39 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:39 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:39 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:39 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:39 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:39 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:39 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:39 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:40 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:40 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:40 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:40 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:40 volumio volumio[28410]: info: Initializing connection to go-librespot Websocket Aug 25 20:19:40 volumio volumio[28410]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 20:19:40 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:40 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:40 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:40 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:40 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:40 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:40 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:40 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:41 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:41 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:41 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:41 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:41 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:41 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:41 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:41 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:41 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:41 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:41 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:41 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:42 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:42 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:42 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:42 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:42 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7. Aug 25 20:19:42 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 20:19:42 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:42 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:42 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:42 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:42 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 20:19:42 volumio go-librespot[26216]: go-librespot daemon starting... Aug 25 20:19:42 volumio go-librespot[26217]: time="2026-08-25T20:19:42+01:00" level=info msg="running go-librespot 0.7.1" Aug 25 20:19:42 volumio go-librespot[26217]: time="2026-08-25T20:19:42+01:00" level=debug msg="app state loaded" Aug 25 20:19:42 volumio go-librespot[26217]: time="2026-08-25T20:19:42+01:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 20:19:42 volumio go-librespot[26217]: time="2026-08-25T20:19:42+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Aug 25 20:19:42 volumio go-librespot[26217]: time="2026-08-25T20:19:42+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 25 20:19:42 volumio go-librespot[26217]: time="2026-08-25T20:19:42+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 25 20:19:42 volumio go-librespot[26217]: time="2026-08-25T20:19:42+01:00" level=info msg="zeroconf server listening on port 46303" Aug 25 20:19:42 volumio go-librespot[26217]: time="2026-08-25T20:19:42+01:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 20:19:42 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:42 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:42 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:42 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:42 volumio go-librespot[26217]: time="2026-08-25T20:19:42+01:00" level=debug msg="obtained new client token: AAHmK3k6sjZRIqO+H7uiKX5+z6E2ibPJ1dgtgmIXdABWHd+UkLcQVu69aFwktqXx8a3EVX4TH/J47sMn78uqSAAPDjIukJN6vFFrfS6DB0mWhbmE2R6vlzmpel6ewQ4iLcZZkzYN/qQSqxXKQ9GfDjcO4UknLl5FFXVv49CrgES9NfRbxgmIyEnrUlWnzosu1g9+qY92GVfam3QkCM4s4pFMyzh4fJJ1Fhu7BRGUgvoeHjRgvtW1ldds" Aug 25 20:19:42 volumio go-librespot[26217]: time="2026-08-25T20:19:42+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 25 20:19:42 volumio go-librespot[26217]: time="2026-08-25T20:19:42+01:00" level=debug msg="completed keyexchange" Aug 25 20:19:42 volumio go-librespot[26217]: time="2026-08-25T20:19:42+01:00" level=debug msg="completed challenge" Aug 25 20:19:42 volumio go-librespot[26217]: time="2026-08-25T20:19:42+01:00" level=info msg="authenticated AP" username="31************************5e" Aug 25 20:19:42 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:42 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:43 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:43 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:43 volumio go-librespot[26217]: time="2026-08-25T20:19:43+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 25 20:19:43 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 20:19:43 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 20:19:43 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:43 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:43 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:43 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:43 volumio volumio[28410]: info: Initializing connection to go-librespot Websocket Aug 25 20:19:43 volumio volumio[28410]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 20:19:43 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:43 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:43 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:43 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:43 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:43 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:43 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:43 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:44 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:44 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:44 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:44 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:44 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:44 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:44 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:44 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:44 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:44 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:44 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:44 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:45 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:45 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:45 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:45 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:45 volumio volumio[28410]: info: Airplay started streaming, receiving metadatas Aug 25 20:19:45 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:45 volumio volumio[28410]: info: CoreCommandRouter::volumioStop Aug 25 20:19:45 volumio volumio[28410]: info: CoreStateMachine::stop Aug 25 20:19:45 volumio volumio[28410]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 25 20:19:45 volumio volumio[28410]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 25 20:19:45 volumio volumio[28410]: info: Airplay started streaming, receiving metadatas Aug 25 20:19:45 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:45 volumio volumio[28410]: info: CoreCommandRouter::volumioStop Aug 25 20:19:45 volumio volumio[28410]: info: CoreStateMachine::stop Aug 25 20:19:45 volumio volumio[28410]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 25 20:19:45 volumio volumio[28410]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 25 20:19:45 volumio volumio[28410]: info: Airplay started streaming, receiving metadatas Aug 25 20:19:45 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:45 volumio volumio[28410]: info: CoreCommandRouter::volumioStop Aug 25 20:19:45 volumio volumio[28410]: info: CoreStateMachine::stop Aug 25 20:19:45 volumio volumio[28410]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 25 20:19:45 volumio volumio[28410]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 25 20:19:45 volumio volumio[28410]: info: Airplay started streaming, receiving metadatas Aug 25 20:19:45 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:45 volumio volumio[28410]: info: CoreCommandRouter::volumioStop Aug 25 20:19:45 volumio volumio[28410]: info: CoreStateMachine::stop Aug 25 20:19:45 volumio volumio[28410]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 25 20:19:45 volumio volumio[28410]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 25 20:19:45 volumio volumio[28410]: info: Airplay started streaming, receiving metadatas Aug 25 20:19:45 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:45 volumio volumio[28410]: info: CoreCommandRouter::volumioStop Aug 25 20:19:45 volumio volumio[28410]: info: CoreStateMachine::stop Aug 25 20:19:45 volumio volumio[28410]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 25 20:19:45 volumio volumio[28410]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 25 20:19:45 volumio shairport-sync[26238]: % Total % Received % Xferd Average Speed Time Time Time Current Aug 25 20:19:45 volumio shairport-sync[26238]: Dload Upload Total Spent Left Speed Aug 25 20:19:45 volumio volumio[28410]: info: Aug 25 20:19:45 volumio volumio[28410]: ---------------------------- Client requests AirplayActive Aug 25 20:19:45 volumio volumio[28410]: info: CoreCommandRouter::executeOnPlugin: airplay_emulation , setAirplayActive Aug 25 20:19:45 volumio shairport-sync[26238]: [158B blob data] Aug 25 20:19:45 volumio shairport-sync[26238]: {"time":1787685585359,"response":"airplayActive Success"} Aug 25 20:19:45 volumio shairport-sync[26249]: % Total % Received % Xferd Average Speed Time Time Time Current Aug 25 20:19:45 volumio shairport-sync[26249]: Dload Upload Total Spent Left Speed Aug 25 20:19:45 volumio volumio[28410]: info: Aug 25 20:19:45 volumio volumio[28410]: ---------------------------- Client requests Start Airplay PlaybackRoutine Aug 25 20:19:45 volumio volumio[28410]: info: CoreCommandRouter::executeOnPlugin: airplay_emulation , startAirplayPlayback Aug 25 20:19:45 volumio volumio[28410]: info: Airplay playback start Aug 25 20:19:45 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:45 volumio volumio[28410]: info: CoreCommandRouter::volumioStop Aug 25 20:19:45 volumio volumio[28410]: info: CoreStateMachine::stop Aug 25 20:19:45 volumio volumio[28410]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 25 20:19:45 volumio volumio[28410]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 25 20:19:45 volumio shairport-sync[26249]: [158B blob data] Aug 25 20:19:45 volumio volumio[28410]: info: camilladsp respawn in 200 ms (attempt 2/10) Aug 25 20:19:45 volumio volumio[28410]: info: Updating volume from AirPlay: -20; 33% Aug 25 20:19:45 volumio volumio[28410]: info: VolumeController::SetAlsaVolume33 Aug 25 20:19:45 volumio volumio[28410]: info: CoreStateMachine::pushState Aug 25 20:19:45 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:45 volumio volumio[28410]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 25 20:19:45 volumio volumio[28410]: info: CoreCommandRouter::volumioPushState Aug 25 20:19:45 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:45.414+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" state=STATUS_STOPPED positionMs=251 volume=33 Aug 25 20:19:45 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:45.415+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" id=http://direct.fipradio.fr/live/fip-midfi.mp3 title=FIP Aug 25 20:19:45 volumio volumio[28410]: info: FusionDsp - Volumio is not playing Aug 25 20:19:45 volumio volumio[28410]: info: FusionDsp - Clipped samples monitor stopped Aug 25 20:19:45 volumio volumio[28410]: SPOTIFY: RECEIVED VOLUMIO VOLUME 33 Aug 25 20:19:45 volumio volumio[28410]: SPOTIFY: SPOTIFY VOLUME 71 Aug 25 20:19:45 volumio volumio[28410]: SPOTIFY: VOLUMIO VOLUME 33 Aug 25 20:19:45 volumio volumio[28410]: SPOTIFY: DELTA VOLUME ENOUGH: true Aug 25 20:19:45 volumio volumio[28410]: info: Setting Spotify Volume from Volumio: 33 Aug 25 20:19:45 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:45 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:45 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:45 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:45 volumio volumio[28410]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Aug 25 20:19:45 volumio volumio[28410]: info: FusionDsp - ---- read samplerate from file: 44100 Aug 25 20:19:45 volumio volumio[28410]: info: camilladsp service terminated, instance 1 Aug 25 20:19:45 volumio volumio[28410]: info: FusionDsp - If filter freq >samplerate/2 then disable it Aug 25 20:19:45 volumio volumio[28410]: info: FusionDsp - Nulleq applied Aug 25 20:19:45 volumio volumio[28410]: info: camilladsp service started and running in background, instance 1 Aug 25 20:19:45 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:45 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:45 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:45 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:46 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:46 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:46 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:46 volumio volumio[28410]: info: CorePlayQueue::getTrack 0 Aug 25 20:19:46 volumio volumio[28410]: info: Initializing connection to go-librespot Websocket Aug 25 20:19:46 volumio volumio[28410]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 20:19:46 volumio volumio[28410]: info: CoreCommandRouter::servicePushState Aug 25 20:19:46 volumio volumio[28410]: info: CoreStateMachine::pushState Aug 25 20:19:46 volumio volumio[28410]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 25 20:19:46 volumio volumio[28410]: info: CoreCommandRouter::volumioPushState Aug 25 20:19:46 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:46.339+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" state=STATUS_PLAYING positionMs=0 volume=33 Aug 25 20:19:46 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:46.340+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" id= title= Aug 25 20:19:46 volumio volumio[28410]: info: CoreCommandRouter::servicePushState Aug 25 20:19:46 volumio volumio[28410]: info: CoreStateMachine::pushState Aug 25 20:19:46 volumio volumio[28410]: info: CoreCommandRouter::volumioPushState Aug 25 20:19:46 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:46.345+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" state=STATUS_PLAYING positionMs=0 volume=33 Aug 25 20:19:46 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:46.345+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" id= title= Aug 25 20:19:46 volumio volumio[28410]: info: FusionDsp - Volumio is playing Aug 25 20:19:46 volumio volumio[28410]: warn: FusionDsp - Monitor WebSocket not open, skipping commands Aug 25 20:19:46 volumio volumio[28410]: info: FusionDsp - Volumio is playing Aug 25 20:19:46 volumio volumio[28410]: SPOTIFY: RECEIVED VOLUMIO VOLUME 33 Aug 25 20:19:46 volumio volumio[28410]: SPOTIFY: RECEIVED VOLUMIO VOLUME 33 Aug 25 20:19:46 volumio volumio[28410]: info: CoreCommandRouter::servicePushState Aug 25 20:19:46 volumio volumio[28410]: info: CoreStateMachine::pushState Aug 25 20:19:46 volumio volumio[28410]: info: CoreCommandRouter::volumioPushState Aug 25 20:19:46 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:46.359+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" state=STATUS_PLAYING positionMs=0 volume=33 Aug 25 20:19:46 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:46.360+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" id= title= Aug 25 20:19:46 volumio volumio[28410]: info: CoreCommandRouter::servicePushState Aug 25 20:19:46 volumio volumio[28410]: info: CoreStateMachine::pushState Aug 25 20:19:46 volumio volumio[28410]: info: CoreCommandRouter::volumioPushState Aug 25 20:19:46 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:46.366+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" state=STATUS_PLAYING positionMs=0 volume=33 Aug 25 20:19:46 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:46.366+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" id= title= Aug 25 20:19:46 volumio volumio[28410]: info: CoreCommandRouter::servicePushState Aug 25 20:19:46 volumio volumio[28410]: info: CoreStateMachine::pushState Aug 25 20:19:46 volumio volumio[28410]: info: CoreCommandRouter::volumioPushState Aug 25 20:19:46 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:46.372+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" state=STATUS_PLAYING positionMs=0 volume=33 Aug 25 20:19:46 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:46.372+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" id= title= Aug 25 20:19:46 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8. Aug 25 20:19:46 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 20:19:46 volumio volumio[28410]: info: FusionDsp - Volumio is playing Aug 25 20:19:46 volumio volumio[28410]: info: FusionDsp - Volumio is playing Aug 25 20:19:46 volumio volumio[28410]: info: FusionDsp - Volumio is playing Aug 25 20:19:46 volumio volumio[28410]: SPOTIFY: RECEIVED VOLUMIO VOLUME 33 Aug 25 20:19:46 volumio volumio[28410]: SPOTIFY: RECEIVED VOLUMIO VOLUME 33 Aug 25 20:19:46 volumio volumio[28410]: SPOTIFY: RECEIVED VOLUMIO VOLUME 33 Aug 25 20:19:46 volumio volumio[28410]: info: CoreCommandRouter::servicePushState Aug 25 20:19:46 volumio volumio[28410]: info: CoreStateMachine::pushState Aug 25 20:19:46 volumio volumio[28410]: info: CoreCommandRouter::volumioPushState Aug 25 20:19:46 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:46.390+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" state=STATUS_PLAYING positionMs=0 volume=33 Aug 25 20:19:46 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:46.391+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" id= title= Aug 25 20:19:46 volumio volumio[28410]: info: FusionDsp - Volumio is playing Aug 25 20:19:46 volumio volumio[28410]: SPOTIFY: RECEIVED VOLUMIO VOLUME 33 Aug 25 20:19:46 volumio volumio[28410]: error: FusionDsp - Monitor WebSocket error: [object Object] Aug 25 20:19:46 volumio volumio[28410]: info: FusionDsp - Clipping Monitor reconnecting in 2000ms Aug 25 20:19:46 volumio volumio[28410]: error: FusionDsp - Monitor WebSocket error: [object Object] Aug 25 20:19:46 volumio volumio[28410]: info: FusionDsp - Clipping Monitor reconnecting in 4000ms Aug 25 20:19:46 volumio volumio[28410]: error: FusionDsp - Monitor WebSocket error: [object Object] Aug 25 20:19:46 volumio volumio[28410]: info: FusionDsp - Clipping Monitor reconnecting in 8000ms Aug 25 20:19:46 volumio volumio[28410]: error: FusionDsp - Monitor WebSocket error: [object Object] Aug 25 20:19:46 volumio volumio[28410]: info: FusionDsp - Clipping Monitor reconnecting in 16000ms Aug 25 20:19:46 volumio volumio[28410]: error: FusionDsp - Monitor WebSocket error: [object Object] Aug 25 20:19:46 volumio volumio[28410]: info: FusionDsp - Clipping Monitor reconnecting in 30000ms Aug 25 20:19:46 volumio volumio[28410]: error: FusionDsp - Monitor WebSocket error: [object Object] Aug 25 20:19:46 volumio volumio[28410]: info: FusionDsp - Clipping Monitor reconnecting in 30000ms Aug 25 20:19:46 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:46 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 20:19:46 volumio go-librespot[26261]: go-librespot daemon starting... Aug 25 20:19:46 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:46 volumio go-librespot[26262]: time="2026-08-25T20:19:46+01:00" level=info msg="running go-librespot 0.7.1" Aug 25 20:19:46 volumio go-librespot[26262]: time="2026-08-25T20:19:46+01:00" level=debug msg="app state loaded" Aug 25 20:19:46 volumio go-librespot[26262]: time="2026-08-25T20:19:46+01:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 20:19:46 volumio go-librespot[26262]: time="2026-08-25T20:19:46+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Aug 25 20:19:46 volumio go-librespot[26262]: time="2026-08-25T20:19:46+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 25 20:19:46 volumio go-librespot[26262]: time="2026-08-25T20:19:46+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 25 20:19:46 volumio go-librespot[26262]: time="2026-08-25T20:19:46+01:00" level=info msg="zeroconf server listening on port 42725" Aug 25 20:19:46 volumio volumio[28410]: info: CoreCommandRouter::servicePushState Aug 25 20:19:46 volumio volumio[28410]: info: CoreStateMachine::pushState Aug 25 20:19:46 volumio volumio[28410]: info: CoreCommandRouter::volumioPushState Aug 25 20:19:46 volumio go-librespot[26262]: time="2026-08-25T20:19:46+01:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 20:19:46 volumio volumio[28410]: info: CoreCommandRouter::servicePushState Aug 25 20:19:46 volumio volumio[28410]: info: CoreStateMachine::pushState Aug 25 20:19:46 volumio volumio[28410]: info: CoreCommandRouter::volumioPushState Aug 25 20:19:46 volumio volumio[28410]: info: CoreCommandRouter::servicePushState Aug 25 20:19:46 volumio volumio[28410]: info: CoreStateMachine::pushState Aug 25 20:19:46 volumio volumio[28410]: info: CoreCommandRouter::volumioPushState Aug 25 20:19:46 volumio volumio[28410]: info: CoreCommandRouter::servicePushState Aug 25 20:19:46 volumio volumio[28410]: info: CoreStateMachine::pushState Aug 25 20:19:46 volumio volumio[28410]: info: CoreCommandRouter::volumioPushState Aug 25 20:19:46 volumio volumio[28410]: info: CoreCommandRouter::servicePushState Aug 25 20:19:46 volumio volumio[28410]: info: CoreStateMachine::pushState Aug 25 20:19:46 volumio volumio[28410]: info: CoreCommandRouter::volumioPushState Aug 25 20:19:46 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:46.681+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" state=STATUS_PLAYING positionMs=0 volume=33 Aug 25 20:19:46 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:46.681+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" state=STATUS_PLAYING positionMs=0 volume=33 Aug 25 20:19:46 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:46.681+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" state=STATUS_PLAYING positionMs=0 volume=33 Aug 25 20:19:46 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:46.682+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" state=STATUS_PLAYING positionMs=0 volume=33 Aug 25 20:19:46 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:46.682+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" id= title= Aug 25 20:19:46 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:46.682+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" id= title= Aug 25 20:19:46 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:46.682+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" state=STATUS_PLAYING positionMs=0 volume=33 Aug 25 20:19:46 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:46.682+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" id= title= Aug 25 20:19:46 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:46.683+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" id= title= Aug 25 20:19:46 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:46.683+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" id= title= Aug 25 20:19:46 volumio volumio[28410]: info: FusionDsp - Volumio is playing Aug 25 20:19:46 volumio volumio[28410]: info: FusionDsp - Volumio is playing Aug 25 20:19:46 volumio volumio[28410]: info: FusionDsp - Volumio is playing Aug 25 20:19:46 volumio volumio[28410]: info: FusionDsp - Volumio is playing Aug 25 20:19:46 volumio volumio[28410]: info: FusionDsp - Volumio is playing Aug 25 20:19:46 volumio volumio[28410]: SPOTIFY: RECEIVED VOLUMIO VOLUME 33 Aug 25 20:19:46 volumio volumio[28410]: SPOTIFY: RECEIVED VOLUMIO VOLUME 33 Aug 25 20:19:46 volumio volumio[28410]: SPOTIFY: RECEIVED VOLUMIO VOLUME 33 Aug 25 20:19:46 volumio volumio[28410]: SPOTIFY: RECEIVED VOLUMIO VOLUME 33 Aug 25 20:19:46 volumio volumio[28410]: SPOTIFY: RECEIVED VOLUMIO VOLUME 33 Aug 25 20:19:46 volumio volumio[28410]: error: FusionDsp - Monitor WebSocket error: [object Object] Aug 25 20:19:46 volumio volumio[28410]: info: FusionDsp - Clipping Monitor reconnecting in 30000ms Aug 25 20:19:46 volumio volumio[28410]: error: FusionDsp - Monitor WebSocket error: [object Object] Aug 25 20:19:46 volumio volumio[28410]: info: FusionDsp - Clipping Monitor reconnecting in 30000ms Aug 25 20:19:46 volumio shairport-sync[26249]: {"time":1787685585373,"response":"startAirplayPlayback Success"} Aug 25 20:19:46 volumio volumio[28410]: error: FusionDsp - Monitor WebSocket error: [object Object] Aug 25 20:19:46 volumio volumio[28410]: info: FusionDsp - Clipping Monitor reconnecting in 30000ms Aug 25 20:19:46 volumio shairport-sync[26272]: % Total % Received % Xferd Average Speed Time Time Time Current Aug 25 20:19:46 volumio shairport-sync[26272]: Dload Upload Total Spent Left Speed Aug 25 20:19:46 volumio volumio[28410]: error: FusionDsp - Monitor WebSocket error: [object Object] Aug 25 20:19:46 volumio volumio[28410]: info: FusionDsp - Clipping Monitor reconnecting in 30000ms Aug 25 20:19:46 volumio volumio[28410]: error: FusionDsp - Monitor WebSocket error: [object Object] Aug 25 20:19:46 volumio volumio[28410]: info: FusionDsp - Clipping Monitor reconnecting in 30000ms Aug 25 20:19:46 volumio volumio[28410]: info: Aug 25 20:19:46 volumio volumio[28410]: ---------------------------- Client requests Stop Airplay Playback Aug 25 20:19:46 volumio volumio[28410]: info: CoreCommandRouter::executeOnPlugin: airplay_emulation , stopAirplayPlayback Aug 25 20:19:46 volumio volumio[28410]: info: Airplay playback stop Aug 25 20:19:46 volumio volumio[28410]: info: Airplay Playback Stopped, clearing state Aug 25 20:19:46 volumio volumio[28410]: info: CoreStateMachine::resetVolumioState Aug 25 20:19:46 volumio volumio[28410]: info: CoreStateMachine::getcurrentVolume Aug 25 20:19:46 volumio volumio[28410]: info: CoreCommandRouter::volumioRetrievevolume Aug 25 20:19:46 volumio shairport-sync[26272]: [158B blob data] Aug 25 20:19:46 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:46 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:46 volumio volumio[28410]: info: VolumeController:: Volume=33 Mute =false Aug 25 20:19:46 volumio volumio[28410]: info: CoreStateMachine::pushState Aug 25 20:19:46 volumio volumio[28410]: info: CoreCommandRouter::volumioPushState Aug 25 20:19:46 volumio volumio[28410]: info: CoreStateMachine::updateTrackBlock Aug 25 20:19:46 volumio volumio[28410]: info: CorePlayQueue::getTrackBlock Aug 25 20:19:46 volumio volumio[28410]: info: CoreCommandRouter::volumioRetrievevolume Aug 25 20:19:46 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:46.775+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" state=STATUS_PLAYING positionMs=0 volume=33 Aug 25 20:19:46 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:46.776+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" id= title= Aug 25 20:19:46 volumio volumio[28410]: info: FusionDsp - Volumio is playing Aug 25 20:19:46 volumio volumio[28410]: SPOTIFY: RECEIVED VOLUMIO VOLUME 33 Aug 25 20:19:46 volumio volumio[28410]: error: FusionDsp - Monitor WebSocket error: [object Object] Aug 25 20:19:46 volumio volumio[28410]: info: FusionDsp - Clipping Monitor reconnecting in 30000ms Aug 25 20:19:46 volumio volumio[28410]: info: VolumeController:: Volume=33 Mute =false Aug 25 20:19:46 volumio volumio[28410]: info: CoreStateMachine::pushState Aug 25 20:19:46 volumio volumio[28410]: info: CoreCommandRouter::volumioPushState Aug 25 20:19:46 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:46.804+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" state=STATUS_PLAYING positionMs=0 volume=33 Aug 25 20:19:46 volumio volumio5-onboarding[27133]: time=2026-08-25T20:19:46.804+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" id= title= Aug 25 20:19:46 volumio volumio[28410]: info: FusionDsp - Volumio is playing Aug 25 20:19:46 volumio volumio[28410]: SPOTIFY: RECEIVED VOLUMIO VOLUME 33 Aug 25 20:19:46 volumio volumio[28410]: error: FusionDsp - Monitor WebSocket error: [object Object] Aug 25 20:19:46 volumio volumio[28410]: info: FusionDsp - Clipping Monitor reconnecting in 30000ms Aug 25 20:19:46 volumio go-librespot[26262]: time="2026-08-25T20:19:46+01:00" level=debug msg="obtained new client token: AAEtPupickdy6Uib9Qdi/FoZDawWpAMRm9USiQYG090i0CB24ETQaJo2n+van89iCPCQYUwKg/kdXTklfWzGLD/0Zk/d0hsmwHkTUa/Dut8N+YWR71MaVpJjSAX1I/OLFmpkmuf0QcThMcR7vDxnmT/IQxJDCHzrsx7tJr7mpYy23HgbtFqR8L0hsixtc0jtATxr7pvEUJV6H5bXgX7g4kr/keGGtZfJ6PLEcdJSJD6LEjSgKSslupmG" Aug 25 20:19:46 volumio go-librespot[26262]: time="2026-08-25T20:19:46+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 25 20:19:46 volumio go-librespot[26262]: time="2026-08-25T20:19:46+01:00" level=debug msg="completed keyexchange" Aug 25 20:19:46 volumio go-librespot[26262]: time="2026-08-25T20:19:46+01:00" level=debug msg="completed challenge" Aug 25 20:19:46 volumio volumio[28410]: SPOTIFY: SETTING SPOTIFY VOLUME 33 Aug 25 20:19:46 volumio volumio[28410]: info: Sending Spotify command with payload to local API: /player/volume Aug 25 20:19:46 volumio go-librespot[26262]: time="2026-08-25T20:19:46+01:00" level=info msg="authenticated AP" username="31************************5e" Aug 25 20:19:47 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:47 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:47 volumio go-librespot[26262]: time="2026-08-25T20:19:47+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 25 20:19:47 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 20:19:47 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 20:19:47 volumio volumio[28410]: error: Failed to send command to Spotify local API: /player/volume: Error: socket hang up Aug 25 20:19:47 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:47 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:47 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:47 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:47 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:47 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:48 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:48 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:48 volumio volumio[28410]: error: FusionDsp - Monitor WebSocket error: [object Object] Aug 25 20:19:48 volumio volumio[28410]: info: FusionDsp - Clipping Monitor reconnecting in 30000ms Aug 25 20:19:48 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:48 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:48 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:48 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:49 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:49 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:49 volumio volumio[28410]: info: Initializing connection to go-librespot Websocket Aug 25 20:19:49 volumio volumio[28410]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 20:19:49 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:49 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:49 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:49 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:50 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 9. Aug 25 20:19:50 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 20:19:50 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:50 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:50 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 20:19:50 volumio go-librespot[26277]: go-librespot daemon starting... Aug 25 20:19:50 volumio go-librespot[26278]: time="2026-08-25T20:19:50+01:00" level=info msg="running go-librespot 0.7.1" Aug 25 20:19:50 volumio go-librespot[26278]: time="2026-08-25T20:19:50+01:00" level=debug msg="app state loaded" Aug 25 20:19:50 volumio go-librespot[26278]: time="2026-08-25T20:19:50+01:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 20:19:50 volumio go-librespot[26278]: time="2026-08-25T20:19:50+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 25 20:19:50 volumio go-librespot[26278]: time="2026-08-25T20:19:50+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 25 20:19:50 volumio go-librespot[26278]: time="2026-08-25T20:19:50+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 25 20:19:50 volumio go-librespot[26278]: time="2026-08-25T20:19:50+01:00" level=info msg="zeroconf server listening on port 36357" Aug 25 20:19:50 volumio go-librespot[26278]: time="2026-08-25T20:19:50+01:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 20:19:50 volumio volumio[28410]: error: FusionDsp - Monitor WebSocket error: [object Object] Aug 25 20:19:50 volumio volumio[28410]: info: FusionDsp - Clipping Monitor reconnecting in 30000ms Aug 25 20:19:50 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:50 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:50 volumio go-librespot[26278]: time="2026-08-25T20:19:50+01:00" level=debug msg="obtained new client token: AAHeUp/RKN/ipeuUOrNFuleHQH7CCSGH9Muyg2fOdMZgZ+0a2q1dzEdzjYdp8Lv0fNGSiw/+RUdo2X5Gs3RNpZ6CFlmarv4VfI27s6g8s5m6mFtBRQNc2J6JIv2dHerd2JPqgTj0M3Ao2jV5l6u33jW1vL6x5bva6Ek9LRj2BcUgtrX0pbGyLTRQTXv1+fIGawtI9Ie+qXuyBVYOU9vKaFNuz4pKO/+/wSNyBicVfzjxJnyBhHved/qi" Aug 25 20:19:50 volumio go-librespot[26278]: time="2026-08-25T20:19:50+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 25 20:19:50 volumio go-librespot[26278]: time="2026-08-25T20:19:50+01:00" level=debug msg="completed keyexchange" Aug 25 20:19:50 volumio go-librespot[26278]: time="2026-08-25T20:19:50+01:00" level=debug msg="completed challenge" Aug 25 20:19:50 volumio go-librespot[26278]: time="2026-08-25T20:19:50+01:00" level=info msg="authenticated AP" username="31************************5e" Aug 25 20:19:50 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:50 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:50 volumio go-librespot[26278]: time="2026-08-25T20:19:50+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 25 20:19:50 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 20:19:50 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 20:19:51 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:51 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:51 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:51 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:51 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:51 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:52 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:52 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:52 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:52 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:52 volumio volumio[28410]: info: Initializing connection to go-librespot Websocket Aug 25 20:19:52 volumio volumio[28410]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 20:19:52 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:52 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:52 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:52 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:53 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:53 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:53 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:53 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:53 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:53 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:53 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 10. Aug 25 20:19:53 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 20:19:53 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 20:19:53 volumio go-librespot[26288]: go-librespot daemon starting... Aug 25 20:19:53 volumio go-librespot[26289]: time="2026-08-25T20:19:53+01:00" level=info msg="running go-librespot 0.7.1" Aug 25 20:19:53 volumio go-librespot[26289]: time="2026-08-25T20:19:53+01:00" level=debug msg="app state loaded" Aug 25 20:19:53 volumio go-librespot[26289]: time="2026-08-25T20:19:53+01:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 20:19:54 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:54 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:54 volumio go-librespot[26289]: time="2026-08-25T20:19:54+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Aug 25 20:19:54 volumio go-librespot[26289]: time="2026-08-25T20:19:54+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 25 20:19:54 volumio go-librespot[26289]: time="2026-08-25T20:19:54+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 25 20:19:54 volumio go-librespot[26289]: time="2026-08-25T20:19:54+01:00" level=info msg="zeroconf server listening on port 41833" Aug 25 20:19:54 volumio go-librespot[26289]: time="2026-08-25T20:19:54+01:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 20:19:54 volumio go-librespot[26289]: time="2026-08-25T20:19:54+01:00" level=debug msg="obtained new client token: AAGjMP2AFR5sn9awvUGO4hE4xORswrU4gYqYEpIzljNo9nZW4Gi1LtZYCmfNsSop1GRs2Mj4Pnd7AgUaIoTFX/cT+uGG1X1Pc0wzPl5UYPMpEQUPWH46Mu+vUQuCrOe9VXDwo7RxWevIjlJQHpr5oidH3HQvIQieeB6lg/Sy+lPetYX3FE0K+Su9+qm04BqY4GCB0IfGke7bpsLss+TtYBGqNbiQDJWOFLPN3K2hS8/Qfrk1Xo5mG+Ip" Aug 25 20:19:54 volumio go-librespot[26289]: time="2026-08-25T20:19:54+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 25 20:19:54 volumio volumio[28410]: error: FusionDsp - Monitor WebSocket error: [object Object] Aug 25 20:19:54 volumio volumio[28410]: info: FusionDsp - Clipping Monitor reconnecting in 30000ms Aug 25 20:19:54 volumio go-librespot[26289]: time="2026-08-25T20:19:54+01:00" level=debug msg="completed keyexchange" Aug 25 20:19:54 volumio go-librespot[26289]: time="2026-08-25T20:19:54+01:00" level=debug msg="completed challenge" Aug 25 20:19:54 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:54 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:54 volumio go-librespot[26289]: time="2026-08-25T20:19:54+01:00" level=info msg="authenticated AP" username="31************************5e" Aug 25 20:19:54 volumio go-librespot[26289]: time="2026-08-25T20:19:54+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 25 20:19:54 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 20:19:54 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 20:19:54 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:54 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:55 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:55 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:55 volumio volumio[28410]: info: Initializing connection to go-librespot Websocket Aug 25 20:19:55 volumio volumio[28410]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 20:19:55 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:55 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:55 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:55 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:56 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:56 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:56 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:56 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:56 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:56 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:56 volumio shairport-sync[26272]: {"time":1787685586724,"response":"stopAirplayPlayback Success"} Aug 25 20:19:56 volumio shairport-sync[26313]: % Total % Received % Xferd Average Speed Time Time Time Current Aug 25 20:19:56 volumio shairport-sync[26313]: Dload Upload Total Spent Left Speed Aug 25 20:19:56 volumio volumio[28410]: info: Aug 25 20:19:56 volumio volumio[28410]: ---------------------------- Client requests AirplayInactive Aug 25 20:19:56 volumio volumio[28410]: info: CoreCommandRouter::executeOnPlugin: airplay_emulation , setAirplayInctive Aug 25 20:19:56 volumio shairport-sync[26313]: [158B blob data] Aug 25 20:19:56 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:56 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:57 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:57 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:57 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:57 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:57 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:57 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:57 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 11. Aug 25 20:19:57 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 20:19:57 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 20:19:57 volumio go-librespot[26314]: go-librespot daemon starting... Aug 25 20:19:57 volumio go-librespot[26315]: time="2026-08-25T20:19:57+01:00" level=info msg="running go-librespot 0.7.1" Aug 25 20:19:57 volumio go-librespot[26315]: time="2026-08-25T20:19:57+01:00" level=debug msg="app state loaded" Aug 25 20:19:57 volumio go-librespot[26315]: time="2026-08-25T20:19:57+01:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 20:19:58 volumio go-librespot[26315]: time="2026-08-25T20:19:58+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Aug 25 20:19:58 volumio go-librespot[26315]: time="2026-08-25T20:19:58+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 25 20:19:58 volumio go-librespot[26315]: time="2026-08-25T20:19:58+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 25 20:19:58 volumio go-librespot[26315]: time="2026-08-25T20:19:58+01:00" level=info msg="zeroconf server listening on port 43857" Aug 25 20:19:58 volumio go-librespot[26315]: time="2026-08-25T20:19:58+01:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 20:19:58 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:58 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:58 volumio volumio[28410]: info: Initializing connection to go-librespot Websocket Aug 25 20:19:58 volumio volumio[28410]: info: Connection to go-librespot Websocket established Aug 25 20:19:58 volumio go-librespot[26315]: time="2026-08-25T20:19:58+01:00" level=debug msg="new websocket client" Aug 25 20:19:58 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:58 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:58 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:58 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:59 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:59 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:59 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:59 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:59 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:19:59 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:00 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:00 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:00 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:00 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:00 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:00 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:00 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:00 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:01 volumio volumio[28410]: info: Airplay started streaming, receiving metadatas Aug 25 20:20:01 volumio volumio[28410]: info: Airplay started streaming, receiving metadatas Aug 25 20:20:01 volumio volumio[28410]: info: Airplay started streaming, receiving metadatas Aug 25 20:20:01 volumio volumio[28410]: info: Airplay started streaming, receiving metadatas Aug 25 20:20:01 volumio volumio[28410]: info: Airplay started streaming, receiving metadatas Aug 25 20:20:01 volumio shairport-sync[26313]: {"time":1787685596704,"response":"airplayInactive Success"} Aug 25 20:20:01 volumio shairport-sync[26335]: % Total % Received % Xferd Average Speed Time Time Time Current Aug 25 20:20:01 volumio shairport-sync[26335]: Dload Upload Total Spent Left Speed Aug 25 20:20:01 volumio shairport-sync[26335]: [50B blob data] Aug 25 20:20:01 volumio shairport-sync[26339]: % Total % Received % Xferd Average Speed Time Time Time Current Aug 25 20:20:01 volumio shairport-sync[26339]: Dload Upload Total Spent Left Speed Aug 25 20:20:01 volumio shairport-sync[26339]: [79B blob data] Aug 25 20:20:01 volumio volumio[28410]: info: Aug 25 20:20:01 volumio volumio[28410]: ---------------------------- Client requests Start Airplay PlaybackRoutine Aug 25 20:20:01 volumio volumio[28410]: info: CoreCommandRouter::executeOnPlugin: airplay_emulation , startAirplayPlayback Aug 25 20:20:01 volumio volumio[28410]: info: Airplay playback start Aug 25 20:20:01 volumio shairport-sync[26335]: --:-- --:--:-- --:--:-- 0 Aug 25 20:20:01 volumio shairport-sync[26339]: [79B blob data] Aug 25 20:20:01 volumio volumio[28410]: info: Aug 25 20:20:01 volumio volumio[28410]: ---------------------------- Client requests AirplayActive Aug 25 20:20:01 volumio volumio[28410]: info: CoreCommandRouter::executeOnPlugin: airplay_emulation , setAirplayActive Aug 25 20:20:01 volumio shairport-sync[26339]: {"time":1787685601199,"response":"startAirplayPlayback Success"} Aug 25 20:20:01 volumio shairport-sync[26335]: [79B blob data] Aug 25 20:20:01 volumio volumio[28410]: info: camilladsp respawn in 100 ms (attempt 1/10) Aug 25 20:20:01 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:01 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:01 volumio volumio[28410]: info: Getting Spotify volume Aug 25 20:20:01 volumio volumio[28410]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Aug 25 20:20:01 volumio volumio[28410]: info: FusionDsp - ---- read samplerate from file: 44100 Aug 25 20:20:01 volumio volumio[28410]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Aug 25 20:20:01 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:01 volumio volumio[28410]: SPOTIFY: RECEIVED VOLUMIO VOLUME 33 Aug 25 20:20:01 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:01 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:01 volumio volumio[28410]: info: FusionDsp - If filter freq >samplerate/2 then disable it Aug 25 20:20:01 volumio volumio[28410]: info: FusionDsp - Nulleq applied Aug 25 20:20:01 volumio volumio[28410]: error: FusionDsp - Reload WebSocket error: [object Object] Aug 25 20:20:01 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:01 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:02 volumio volumio[28410]: info: CoreCommandRouter::servicePushState Aug 25 20:20:02 volumio volumio[28410]: info: CoreStateMachine::pushState Aug 25 20:20:02 volumio volumio[28410]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 25 20:20:02 volumio volumio[28410]: info: CoreCommandRouter::volumioPushState Aug 25 20:20:02 volumio volumio5-onboarding[27133]: time=2026-08-25T20:20:02.165+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" state=STATUS_PLAYING positionMs=1000 volume=33 Aug 25 20:20:02 volumio volumio5-onboarding[27133]: time=2026-08-25T20:20:02.166+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" id= title= Aug 25 20:20:02 volumio volumio[28410]: info: FusionDsp - Volumio is playing Aug 25 20:20:02 volumio volumio[28410]: SPOTIFY: RECEIVED VOLUMIO VOLUME 33 Aug 25 20:20:02 volumio volumio[28410]: info: CoreCommandRouter::servicePushState Aug 25 20:20:02 volumio volumio[28410]: info: CoreStateMachine::pushState Aug 25 20:20:02 volumio volumio[28410]: info: CoreCommandRouter::volumioPushState Aug 25 20:20:02 volumio volumio5-onboarding[27133]: time=2026-08-25T20:20:02.174+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" state=STATUS_PLAYING positionMs=1000 volume=33 Aug 25 20:20:02 volumio volumio5-onboarding[27133]: time=2026-08-25T20:20:02.174+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" id= title= Aug 25 20:20:02 volumio volumio[28410]: info: CoreCommandRouter::servicePushState Aug 25 20:20:02 volumio volumio[28410]: info: CoreStateMachine::pushState Aug 25 20:20:02 volumio volumio[28410]: info: CoreCommandRouter::volumioPushState Aug 25 20:20:02 volumio volumio5-onboarding[27133]: time=2026-08-25T20:20:02.178+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" state=STATUS_PLAYING positionMs=1000 volume=33 Aug 25 20:20:02 volumio volumio5-onboarding[27133]: time=2026-08-25T20:20:02.178+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" id= title= Aug 25 20:20:02 volumio volumio[28410]: info: CoreCommandRouter::servicePushState Aug 25 20:20:02 volumio volumio[28410]: info: CoreStateMachine::pushState Aug 25 20:20:02 volumio volumio[28410]: info: CoreCommandRouter::volumioPushState Aug 25 20:20:02 volumio volumio5-onboarding[27133]: time=2026-08-25T20:20:02.182+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" state=STATUS_PLAYING positionMs=1000 volume=33 Aug 25 20:20:02 volumio volumio5-onboarding[27133]: time=2026-08-25T20:20:02.182+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" id= title= Aug 25 20:20:02 volumio volumio[28410]: info: CoreCommandRouter::servicePushState Aug 25 20:20:02 volumio volumio[28410]: info: CoreStateMachine::pushState Aug 25 20:20:02 volumio volumio[28410]: info: CoreCommandRouter::volumioPushState Aug 25 20:20:02 volumio volumio5-onboarding[27133]: time=2026-08-25T20:20:02.186+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" state=STATUS_PLAYING positionMs=1000 volume=33 Aug 25 20:20:02 volumio volumio5-onboarding[27133]: time=2026-08-25T20:20:02.187+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" id= title= Aug 25 20:20:02 volumio volumio[28410]: info: FusionDsp - Volumio is playing Aug 25 20:20:02 volumio volumio[28410]: info: FusionDsp - Volumio is playing Aug 25 20:20:02 volumio volumio[28410]: info: FusionDsp - Volumio is playing Aug 25 20:20:02 volumio volumio[28410]: info: FusionDsp - Volumio is playing Aug 25 20:20:02 volumio volumio[28410]: SPOTIFY: RECEIVED VOLUMIO VOLUME 33 Aug 25 20:20:02 volumio volumio[28410]: SPOTIFY: RECEIVED VOLUMIO VOLUME 33 Aug 25 20:20:02 volumio volumio[28410]: SPOTIFY: RECEIVED VOLUMIO VOLUME 33 Aug 25 20:20:02 volumio volumio[28410]: SPOTIFY: RECEIVED VOLUMIO VOLUME 33 Aug 25 20:20:02 volumio volumio[28410]: info: CoreCommandRouter::servicePushState Aug 25 20:20:02 volumio volumio[28410]: info: CoreStateMachine::pushState Aug 25 20:20:02 volumio volumio[28410]: info: CoreCommandRouter::volumioPushState Aug 25 20:20:02 volumio volumio5-onboarding[27133]: time=2026-08-25T20:20:02.207+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" state=STATUS_PLAYING positionMs=1000 volume=33 Aug 25 20:20:02 volumio volumio5-onboarding[27133]: time=2026-08-25T20:20:02.208+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" id= title= Aug 25 20:20:02 volumio volumio[28410]: info: FusionDsp - Volumio is playing Aug 25 20:20:02 volumio volumio[28410]: SPOTIFY: RECEIVED VOLUMIO VOLUME 33 Aug 25 20:20:02 volumio volumio[28410]: error: FusionDsp - Monitor WebSocket error: [object Object] Aug 25 20:20:02 volumio volumio[28410]: info: FusionDsp - Clipping Monitor reconnecting in 30000ms Aug 25 20:20:02 volumio volumio[28410]: error: FusionDsp - Monitor WebSocket error: [object Object] Aug 25 20:20:02 volumio volumio[28410]: info: FusionDsp - Clipping Monitor reconnecting in 30000ms Aug 25 20:20:02 volumio volumio[28410]: error: FusionDsp - Monitor WebSocket error: [object Object] Aug 25 20:20:02 volumio volumio[28410]: info: FusionDsp - Clipping Monitor reconnecting in 30000ms Aug 25 20:20:02 volumio volumio[28410]: error: FusionDsp - Monitor WebSocket error: [object Object] Aug 25 20:20:02 volumio volumio[28410]: info: FusionDsp - Clipping Monitor reconnecting in 30000ms Aug 25 20:20:02 volumio volumio[28410]: error: FusionDsp - Monitor WebSocket error: [object Object] Aug 25 20:20:02 volumio volumio[28410]: info: FusionDsp - Clipping Monitor reconnecting in 30000ms Aug 25 20:20:02 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:02 volumio volumio[28410]: error: FusionDsp - Monitor WebSocket error: [object Object] Aug 25 20:20:02 volumio volumio[28410]: info: FusionDsp - Clipping Monitor reconnecting in 30000ms Aug 25 20:20:02 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:02 volumio volumio[28410]: error: FusionDsp - Monitor WebSocket error: [object Object] Aug 25 20:20:02 volumio volumio[28410]: info: FusionDsp - Clipping Monitor reconnecting in 30000ms Aug 25 20:20:02 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:02 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:02 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:02 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:03 volumio volumio[28410]: info: CoreCommandRouter::servicePushState Aug 25 20:20:03 volumio volumio[28410]: info: CoreStateMachine::pushState Aug 25 20:20:03 volumio volumio[28410]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 25 20:20:03 volumio volumio[28410]: info: CoreCommandRouter::volumioPushState Aug 25 20:20:03 volumio volumio[28410]: info: CoreCommandRouter::servicePushState Aug 25 20:20:03 volumio volumio[28410]: info: CoreStateMachine::pushState Aug 25 20:20:03 volumio volumio[28410]: info: CoreCommandRouter::volumioPushState Aug 25 20:20:03 volumio shairport-sync[26335]: {"time":1787685601202,"response":"airplayActive Success"} Aug 25 20:20:03 volumio shairport-sync[25842]: ALSA lib /home/pi/volumio-hook-plugin/src/pcm_volumiohook.c:101:(_snd_pcm_volumiohook_execute) The PCM fusiondsphook failed to run command echo '44100,S32_LE,2,32' >/tmp/fusiondsp_stream_params.log Aug 25 20:20:03 volumio volumio[28410]: info: CoreCommandRouter::servicePushState Aug 25 20:20:03 volumio volumio[28410]: info: CoreStateMachine::pushState Aug 25 20:20:03 volumio volumio[28410]: info: CoreCommandRouter::volumioPushState Aug 25 20:20:03 volumio volumio[28410]: info: CoreCommandRouter::servicePushState Aug 25 20:20:03 volumio volumio[28410]: info: CoreStateMachine::pushState Aug 25 20:20:03 volumio volumio[28410]: info: CoreCommandRouter::volumioPushState Aug 25 20:20:03 volumio volumio[28410]: info: CoreCommandRouter::servicePushState Aug 25 20:20:03 volumio volumio[28410]: info: CoreStateMachine::pushState Aug 25 20:20:03 volumio volumio[28410]: info: CoreCommandRouter::volumioPushState Aug 25 20:20:03 volumio volumio5-onboarding[27133]: time=2026-08-25T20:20:03.155+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" state=STATUS_PLAYING positionMs= volume=33 Aug 25 20:20:03 volumio volumio5-onboarding[27133]: time=2026-08-25T20:20:03.155+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" id= title= Aug 25 20:20:03 volumio volumio5-onboarding[27133]: time=2026-08-25T20:20:03.157+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" state=STATUS_PLAYING positionMs= volume=33 Aug 25 20:20:03 volumio volumio5-onboarding[27133]: time=2026-08-25T20:20:03.158+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" id= title= Aug 25 20:20:03 volumio volumio5-onboarding[27133]: time=2026-08-25T20:20:03.159+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" state=STATUS_PLAYING positionMs= volume=33 Aug 25 20:20:03 volumio volumio5-onboarding[27133]: time=2026-08-25T20:20:03.160+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" state=STATUS_PLAYING positionMs= volume=33 Aug 25 20:20:03 volumio volumio5-onboarding[27133]: time=2026-08-25T20:20:03.160+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" id= title= Aug 25 20:20:03 volumio volumio5-onboarding[27133]: time=2026-08-25T20:20:03.159+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" state=STATUS_PLAYING positionMs= volume=33 Aug 25 20:20:03 volumio volumio5-onboarding[27133]: time=2026-08-25T20:20:03.160+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" id= title= Aug 25 20:20:03 volumio volumio5-onboarding[27133]: time=2026-08-25T20:20:03.160+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" id= title= Aug 25 20:20:03 volumio volumio[28410]: info: CoreCommandRouter::servicePushState Aug 25 20:20:03 volumio volumio[28410]: info: CoreStateMachine::pushState Aug 25 20:20:03 volumio volumio[28410]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 25 20:20:03 volumio volumio[28410]: info: CoreCommandRouter::volumioPushState Aug 25 20:20:03 volumio volumio[28410]: info: CoreCommandRouter::servicePushState Aug 25 20:20:03 volumio volumio[28410]: info: CoreStateMachine::pushState Aug 25 20:20:03 volumio volumio[28410]: info: CoreCommandRouter::volumioPushState Aug 25 20:20:03 volumio volumio[28410]: info: CoreCommandRouter::servicePushState Aug 25 20:20:03 volumio volumio[28410]: info: CoreStateMachine::pushState Aug 25 20:20:03 volumio volumio[28410]: info: CoreCommandRouter::volumioPushState Aug 25 20:20:03 volumio volumio[28410]: info: CoreCommandRouter::servicePushState Aug 25 20:20:03 volumio volumio[28410]: info: CoreStateMachine::pushState Aug 25 20:20:03 volumio volumio[28410]: info: CoreCommandRouter::volumioPushState Aug 25 20:20:03 volumio volumio[28410]: info: CoreCommandRouter::servicePushState Aug 25 20:20:03 volumio volumio[28410]: info: CoreStateMachine::pushState Aug 25 20:20:03 volumio volumio[28410]: info: CoreCommandRouter::volumioPushState Aug 25 20:20:03 volumio volumio5-onboarding[27133]: time=2026-08-25T20:20:03.183+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" state=STATUS_PLAYING positionMs= volume=33 Aug 25 20:20:03 volumio volumio5-onboarding[27133]: time=2026-08-25T20:20:03.184+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" id= title="Make Me Feel" Aug 25 20:20:03 volumio volumio5-onboarding[27133]: time=2026-08-25T20:20:03.185+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" state=STATUS_PLAYING positionMs= volume=33 Aug 25 20:20:03 volumio volumio5-onboarding[27133]: time=2026-08-25T20:20:03.185+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" state=STATUS_PLAYING positionMs= volume=33 Aug 25 20:20:03 volumio volumio5-onboarding[27133]: time=2026-08-25T20:20:03.185+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" id= title="Make Me Feel" Aug 25 20:20:03 volumio volumio5-onboarding[27133]: time=2026-08-25T20:20:03.186+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" state=STATUS_PLAYING positionMs= volume=33 Aug 25 20:20:03 volumio volumio5-onboarding[27133]: time=2026-08-25T20:20:03.186+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" id= title="Make Me Feel" Aug 25 20:20:03 volumio volumio5-onboarding[27133]: time=2026-08-25T20:20:03.187+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" state=STATUS_PLAYING positionMs= volume=33 Aug 25 20:20:03 volumio volumio5-onboarding[27133]: time=2026-08-25T20:20:03.187+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" id= title="Make Me Feel" Aug 25 20:20:03 volumio volumio5-onboarding[27133]: time=2026-08-25T20:20:03.187+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" id= title="Make Me Feel" Aug 25 20:20:03 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:03 volumio volumio[28410]: info: FusionDsp - Volumio is playing Aug 25 20:20:03 volumio volumio[28410]: info: FusionDsp - Volumio is playing Aug 25 20:20:03 volumio volumio[28410]: info: FusionDsp - Volumio is playing Aug 25 20:20:03 volumio volumio[28410]: info: FusionDsp - Volumio is playing Aug 25 20:20:03 volumio volumio[28410]: info: FusionDsp - Volumio is playing Aug 25 20:20:03 volumio volumio[28410]: info: FusionDsp - Volumio is playing Aug 25 20:20:03 volumio volumio[28410]: info: FusionDsp - Volumio is playing Aug 25 20:20:03 volumio volumio[28410]: info: FusionDsp - Volumio is playing Aug 25 20:20:03 volumio volumio[28410]: info: FusionDsp - Volumio is playing Aug 25 20:20:03 volumio volumio[28410]: info: FusionDsp - Volumio is playing Aug 25 20:20:03 volumio volumio[28410]: SPOTIFY: RECEIVED VOLUMIO VOLUME 33 Aug 25 20:20:03 volumio volumio[28410]: SPOTIFY: RECEIVED VOLUMIO VOLUME 33 Aug 25 20:20:03 volumio volumio[28410]: SPOTIFY: RECEIVED VOLUMIO VOLUME 33 Aug 25 20:20:03 volumio volumio[28410]: SPOTIFY: RECEIVED VOLUMIO VOLUME 33 Aug 25 20:20:03 volumio volumio[28410]: SPOTIFY: RECEIVED VOLUMIO VOLUME 33 Aug 25 20:20:03 volumio volumio[28410]: SPOTIFY: RECEIVED VOLUMIO VOLUME 33 Aug 25 20:20:03 volumio volumio[28410]: SPOTIFY: RECEIVED VOLUMIO VOLUME 33 Aug 25 20:20:03 volumio volumio[28410]: SPOTIFY: RECEIVED VOLUMIO VOLUME 33 Aug 25 20:20:03 volumio volumio[28410]: SPOTIFY: RECEIVED VOLUMIO VOLUME 33 Aug 25 20:20:03 volumio volumio[28410]: SPOTIFY: RECEIVED VOLUMIO VOLUME 33 Aug 25 20:20:03 volumio volumio[28410]: info: FusionDsp - Clipping Monitor started Aug 25 20:20:03 volumio volumio[28410]: info: FusionDsp - Clipping Monitor started Aug 25 20:20:03 volumio volumio[28410]: info: FusionDsp - Clipping Monitor started Aug 25 20:20:03 volumio volumio[28410]: info: FusionDsp - Clipping Monitor started Aug 25 20:20:03 volumio volumio[28410]: info: FusionDsp - Clipping Monitor started Aug 25 20:20:03 volumio volumio[28410]: info: FusionDsp - Clipping Monitor started Aug 25 20:20:03 volumio volumio[28410]: info: FusionDsp - Clipping Monitor started Aug 25 20:20:03 volumio volumio[28410]: info: FusionDsp - Clipping Monitor started Aug 25 20:20:03 volumio volumio[28410]: info: FusionDsp - Clipping Monitor started Aug 25 20:20:03 volumio volumio[28410]: info: FusionDsp - Clipping Monitor started Aug 25 20:20:03 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:03 volumio volumio[28410]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Aug 25 20:20:03 volumio volumio[28410]: info: FusionDsp - ---- read samplerate from file: 44100 Aug 25 20:20:03 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:03 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:03 volumio volumio[28410]: info: FusionDsp - If filter freq >samplerate/2 then disable it Aug 25 20:20:03 volumio volumio[28410]: info: FusionDsp - Nulleq applied Aug 25 20:20:03 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:03 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:04 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:04 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:04 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:04 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:04 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:04 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:05 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:05 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:05 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:05 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:05 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:05 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:06 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:06 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:06 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:06 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:06 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:06 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:06 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:06 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:07 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:07 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:07 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:07 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:07 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:07 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:08 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:08 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:08 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:08 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:08 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:08 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:09 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:09 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:09 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:09 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:09 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:09 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:10 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:10 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:10 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:10 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:10 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:10 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:10 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:10 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:11 volumio volumio[28410]: info: CoreCommandRouter::servicePushState Aug 25 20:20:11 volumio volumio[28410]: info: CoreStateMachine::pushState Aug 25 20:20:11 volumio volumio[28410]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 25 20:20:11 volumio volumio[28410]: info: CoreCommandRouter::volumioPushState Aug 25 20:20:11 volumio volumio[28410]: info: CoreCommandRouter::servicePushState Aug 25 20:20:11 volumio volumio[28410]: info: CoreStateMachine::pushState Aug 25 20:20:11 volumio volumio[28410]: info: CoreCommandRouter::volumioPushState Aug 25 20:20:11 volumio volumio[28410]: info: CoreCommandRouter::servicePushState Aug 25 20:20:11 volumio volumio[28410]: info: CoreStateMachine::pushState Aug 25 20:20:11 volumio volumio[28410]: info: CoreCommandRouter::volumioPushState Aug 25 20:20:11 volumio volumio[28410]: info: CoreCommandRouter::servicePushState Aug 25 20:20:11 volumio volumio[28410]: info: CoreStateMachine::pushState Aug 25 20:20:11 volumio volumio[28410]: info: CoreCommandRouter::volumioPushState Aug 25 20:20:11 volumio volumio[28410]: info: CoreCommandRouter::servicePushState Aug 25 20:20:11 volumio volumio[28410]: info: CoreStateMachine::pushState Aug 25 20:20:11 volumio volumio[28410]: info: CoreCommandRouter::volumioPushState Aug 25 20:20:11 volumio volumio5-onboarding[27133]: time=2026-08-25T20:20:11.212+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" state=STATUS_PLAYING positionMs=0 volume=33 Aug 25 20:20:11 volumio volumio5-onboarding[27133]: time=2026-08-25T20:20:11.212+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" state=STATUS_PLAYING positionMs=0 volume=33 Aug 25 20:20:11 volumio volumio5-onboarding[27133]: time=2026-08-25T20:20:11.212+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" id= title= Aug 25 20:20:11 volumio volumio5-onboarding[27133]: time=2026-08-25T20:20:11.212+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" id= title= Aug 25 20:20:11 volumio volumio5-onboarding[27133]: time=2026-08-25T20:20:11.214+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" state=STATUS_PLAYING positionMs=0 volume=33 Aug 25 20:20:11 volumio volumio5-onboarding[27133]: time=2026-08-25T20:20:11.214+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" state=STATUS_PLAYING positionMs=0 volume=33 Aug 25 20:20:11 volumio volumio5-onboarding[27133]: time=2026-08-25T20:20:11.217+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" id= title= Aug 25 20:20:11 volumio volumio5-onboarding[27133]: time=2026-08-25T20:20:11.214+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" state=STATUS_PLAYING positionMs=0 volume=33 Aug 25 20:20:11 volumio volumio5-onboarding[27133]: time=2026-08-25T20:20:11.219+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" id= title= Aug 25 20:20:11 volumio volumio5-onboarding[27133]: time=2026-08-25T20:20:11.219+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" id= title= Aug 25 20:20:11 volumio volumio[28410]: info: FusionDsp - Volumio is playing Aug 25 20:20:11 volumio volumio[28410]: info: FusionDsp - Volumio is playing Aug 25 20:20:11 volumio volumio[28410]: info: FusionDsp - Volumio is playing Aug 25 20:20:11 volumio volumio[28410]: info: FusionDsp - Volumio is playing Aug 25 20:20:11 volumio volumio[28410]: info: FusionDsp - Volumio is playing Aug 25 20:20:11 volumio volumio[28410]: SPOTIFY: RECEIVED VOLUMIO VOLUME 33 Aug 25 20:20:11 volumio volumio[28410]: SPOTIFY: RECEIVED VOLUMIO VOLUME 33 Aug 25 20:20:11 volumio volumio[28410]: SPOTIFY: RECEIVED VOLUMIO VOLUME 33 Aug 25 20:20:11 volumio volumio[28410]: SPOTIFY: RECEIVED VOLUMIO VOLUME 33 Aug 25 20:20:11 volumio volumio[28410]: SPOTIFY: RECEIVED VOLUMIO VOLUME 33 Aug 25 20:20:11 volumio shairport-sync[26377]: % Total % Received % Xferd Average Speed Time Time Time Current Aug 25 20:20:11 volumio shairport-sync[26377]: Dload Upload Total Spent Left Speed Aug 25 20:20:11 volumio volumio[28410]: info: Aug 25 20:20:11 volumio volumio[28410]: ---------------------------- Client requests Stop Airplay Playback Aug 25 20:20:11 volumio volumio[28410]: info: CoreCommandRouter::executeOnPlugin: airplay_emulation , stopAirplayPlayback Aug 25 20:20:11 volumio volumio[28410]: info: Airplay playback stop Aug 25 20:20:11 volumio volumio[28410]: info: Airplay Playback Stopped, clearing state Aug 25 20:20:11 volumio volumio[28410]: info: CoreStateMachine::resetVolumioState Aug 25 20:20:11 volumio volumio[28410]: info: CoreStateMachine::getcurrentVolume Aug 25 20:20:11 volumio volumio[28410]: info: CoreCommandRouter::volumioRetrievevolume Aug 25 20:20:11 volumio shairport-sync[26377]: [158B blob data] Aug 25 20:20:11 volumio volumio[28410]: info: VolumeController:: Volume=33 Mute =false Aug 25 20:20:11 volumio volumio[28410]: info: CoreStateMachine::pushState Aug 25 20:20:11 volumio volumio[28410]: info: CoreCommandRouter::volumioPushState Aug 25 20:20:11 volumio volumio[28410]: info: CoreStateMachine::updateTrackBlock Aug 25 20:20:11 volumio volumio[28410]: info: CorePlayQueue::getTrackBlock Aug 25 20:20:11 volumio volumio[28410]: info: CoreCommandRouter::volumioRetrievevolume Aug 25 20:20:11 volumio volumio5-onboarding[27133]: time=2026-08-25T20:20:11.297+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" state=STATUS_PLAYING positionMs=0 volume=33 Aug 25 20:20:11 volumio volumio5-onboarding[27133]: time=2026-08-25T20:20:11.297+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" id= title= Aug 25 20:20:11 volumio volumio[28410]: info: FusionDsp - Volumio is playing Aug 25 20:20:11 volumio volumio[28410]: SPOTIFY: RECEIVED VOLUMIO VOLUME 33 Aug 25 20:20:11 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:11 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:11 volumio volumio[28410]: info: VolumeController:: Volume=33 Mute =false Aug 25 20:20:11 volumio volumio[28410]: info: CoreStateMachine::pushState Aug 25 20:20:11 volumio volumio[28410]: info: CoreCommandRouter::volumioPushState Aug 25 20:20:11 volumio volumio5-onboarding[27133]: time=2026-08-25T20:20:11.325+01:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" state=STATUS_PLAYING positionMs=0 volume=33 Aug 25 20:20:11 volumio volumio5-onboarding[27133]: time=2026-08-25T20:20:11.325+01:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.8.147:53511,00:00:00:00:00:00%01 @ 0x19277d0" id= title= Aug 25 20:20:11 volumio volumio[28410]: info: FusionDsp - Volumio is playing Aug 25 20:20:11 volumio volumio[28410]: SPOTIFY: RECEIVED VOLUMIO VOLUME 33 Aug 25 20:20:11 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:11 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:11 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:11 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:12 volumio volumio[28410]: info: FusionDsp - Clipping Monitor reconnecting in 30000ms Aug 25 20:20:12 volumio volumio[28410]: info: FusionDsp - Clipping Monitor reconnecting in 30000ms Aug 25 20:20:12 volumio volumio[28410]: info: FusionDsp - Clipping Monitor reconnecting in 30000ms Aug 25 20:20:12 volumio volumio[28410]: info: FusionDsp - Clipping Monitor reconnecting in 30000ms Aug 25 20:20:12 volumio volumio[28410]: info: FusionDsp - Clipping Monitor reconnecting in 30000ms Aug 25 20:20:12 volumio volumio[28410]: info: FusionDsp - Clipping Monitor reconnecting in 30000ms Aug 25 20:20:12 volumio volumio[28410]: info: FusionDsp - Clipping Monitor reconnecting in 30000ms Aug 25 20:20:12 volumio volumio[28410]: info: FusionDsp - Clipping Monitor reconnecting in 30000ms Aug 25 20:20:12 volumio volumio[28410]: info: FusionDsp - Clipping Monitor reconnecting in 30000ms Aug 25 20:20:12 volumio volumio[28410]: info: FusionDsp - Clipping Monitor reconnecting in 30000ms Aug 25 20:20:12 volumio volumio[28410]: info: camilladsp respawn in 200 ms (attempt 2/10) Aug 25 20:20:12 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:12 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:12 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:12 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:12 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:12 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:13 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:13 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:13 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:13 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:13 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:13 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:14 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:14 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:14 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:14 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:14 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:14 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:15 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:15 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:15 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:15 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:15 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:15 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:15 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:15 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:16 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:16 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:16 volumio volumio[28410]: error: FusionDsp - Monitor WebSocket error: [object Object] Aug 25 20:20:16 volumio volumio[28410]: info: FusionDsp - Clipping Monitor reconnecting in 30000ms Aug 25 20:20:16 volumio volumio[28410]: error: FusionDsp - Monitor WebSocket error: [object Object] Aug 25 20:20:16 volumio volumio[28410]: info: FusionDsp - Clipping Monitor reconnecting in 30000ms Aug 25 20:20:16 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:16 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:16 volumio volumio[28410]: error: FusionDsp - Monitor WebSocket error: [object Object] Aug 25 20:20:16 volumio volumio[28410]: info: FusionDsp - Clipping Monitor reconnecting in 30000ms Aug 25 20:20:16 volumio volumio[28410]: error: FusionDsp - Monitor WebSocket error: [object Object] Aug 25 20:20:16 volumio volumio[28410]: info: FusionDsp - Clipping Monitor reconnecting in 30000ms Aug 25 20:20:16 volumio volumio[28410]: error: FusionDsp - Monitor WebSocket error: [object Object] Aug 25 20:20:16 volumio volumio[28410]: info: FusionDsp - Clipping Monitor reconnecting in 30000ms Aug 25 20:20:16 volumio volumio[28410]: error: FusionDsp - Monitor WebSocket error: [object Object] Aug 25 20:20:16 volumio volumio[28410]: info: FusionDsp - Clipping Monitor reconnecting in 30000ms Aug 25 20:20:16 volumio volumio[28410]: error: FusionDsp - Monitor WebSocket error: [object Object] Aug 25 20:20:16 volumio volumio[28410]: info: FusionDsp - Clipping Monitor reconnecting in 30000ms Aug 25 20:20:16 volumio volumio[28410]: error: FusionDsp - Monitor WebSocket error: [object Object] Aug 25 20:20:16 volumio volumio[28410]: info: FusionDsp - Clipping Monitor reconnecting in 30000ms Aug 25 20:20:16 volumio volumio[28410]: error: FusionDsp - Monitor WebSocket error: [object Object] Aug 25 20:20:16 volumio volumio[28410]: info: FusionDsp - Clipping Monitor reconnecting in 30000ms Aug 25 20:20:16 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:16 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:17 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:17 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:17 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:17 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:17 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:17 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:18 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:18 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:18 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:18 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:18 volumio volumio[28410]: error: FusionDsp - Monitor WebSocket error: [object Object] Aug 25 20:20:18 volumio volumio[28410]: info: FusionDsp - Clipping Monitor reconnecting in 30000ms Aug 25 20:20:18 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:18 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:19 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:19 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:19 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:19 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:19 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:19 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:19 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:19 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:20 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:20 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:20 volumio volumio[28410]: error: FusionDsp - Monitor WebSocket error: [object Object] Aug 25 20:20:20 volumio volumio[28410]: info: FusionDsp - Clipping Monitor reconnecting in 30000ms Aug 25 20:20:20 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:20 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:20 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:20 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:21 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:21 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:21 volumio shairport-sync[26377]: {"time":1787685611250,"response":"stopAirplayPlayback Success"} Aug 25 20:20:21 volumio shairport-sync[26400]: % Total % Received % Xferd Average Speed Time Time Time Current Aug 25 20:20:21 volumio shairport-sync[26400]: Dload Upload Total Spent Left Speed Aug 25 20:20:21 volumio volumio[28410]: info: Aug 25 20:20:21 volumio volumio[28410]: ---------------------------- Client requests AirplayInactive Aug 25 20:20:21 volumio volumio[28410]: info: CoreCommandRouter::executeOnPlugin: airplay_emulation , setAirplayInctive Aug 25 20:20:21 volumio shairport-sync[26400]: [158B blob data] Aug 25 20:20:21 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:21 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:21 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:21 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:22 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:22 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:22 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:22 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:22 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:22 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:23 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:23 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:23 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:23 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:23 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:23 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:23 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:23 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:24 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:24 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:24 volumio volumio[28410]: error: FusionDsp - Monitor WebSocket error: [object Object] Aug 25 20:20:24 volumio volumio[28410]: info: FusionDsp - Clipping Monitor reconnecting in 30000ms Aug 25 20:20:24 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:24 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:24 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:24 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:25 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:25 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:25 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:25 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:25 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:25 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:26 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:26 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:26 volumio volumio[28410]: warn: FusionDsp - Monitor WebSocket not open, skipping commands Aug 25 20:20:26 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:26 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:26 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:26 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:27 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:27 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:27 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:27 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:27 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:27 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:27 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:27 volumio volumio[28410]: info: CoreCommandRouter::volumioGetState Aug 25 20:20:28 volumio go-librespot[26315]: time="2026-08-25T20:20:28+01:00" level=fatal msg="failed running with username and spotify token" error="failed obtaining client token: failed requesting clienttoken: Post \"https://clienttoken.spotify.com/v1/clienttoken\": context deadline exceeded (Client.Timeout exceeded while awaiting headers)" Aug 25 20:20:28 volumio volumio[28410]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 25 20:20:28 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 20:20:28 volumio volumio[28410]: Error: socket hang up Aug 25 20:20:28 volumio volumio[28410]: at connResetException (node:internal/errors:720:14) Aug 25 20:20:28 volumio volumio[28410]: at Socket.socketOnEnd (node:_http_client:519:23) Aug 25 20:20:28 volumio volumio[28410]: at Socket.emit (node:events:526:35) Aug 25 20:20:28 volumio volumio[28410]: at endReadableNT (node:internal/streams/readable:1376:12) Aug 25 20:20:28 volumio volumio[28410]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Aug 25 20:20:28 volumio volumio[28410]: code: 'ECONNRESET', Aug 25 20:20:28 volumio volumio[28410]: response: undefined Aug 25 20:20:28 volumio volumio[28410]: } Aug 25 20:20:28 volumio volumio[28410]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 25 20:20:28 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 20:20:28 volumio sudo[26429]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-08-25 20:19' Aug 25 20:20:28 volumio sudo[26429]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="18952480e8d8c63f22208e9007a0f47a9563eae6" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="0e58f1861fa88e02087981b8d91f7511f0e7011b" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue Mar 24 17:20:52 UTC 2026" VOLUMIO_VERSION="4.119" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="d0c2fd9dbc5e70e58c32413c12353563"