May 31 20:11:02 volumio volumio5-onboarding[1496]: time=2026-05-31T20:11:02.769+02:00 level=INFO msg="established new WebSocket connection" component=conn/ws remoteAddr=192.168.31.187:33046 May 31 20:11:03 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 31 20:11:03 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 31 20:11:03 volumio volumio[1158]: info: Discovery: Getting this device information May 31 20:11:03 volumio volumio[1158]: info: CoreCommandRouter::volumioGetState May 31 20:11:03 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 31 20:11:03 volumio volumio5-onboarding[1496]: time=2026-05-31T20:11:03.032+02:00 level=INFO msg="app ready event" component=server event=CLIENT_EVENT_TYPE_APP_READY peer="192.168.31.187:33046 @ 0x2800210" latency=-1.950800429s platform=PLATFORM_ANDROID version=5.260413.0 May 31 20:11:03 volumio volumio5-onboarding[1496]: time=2026-05-31T20:11:03.032+02:00 level=INFO msg="device data request" component=server type=REQUEST_TYPE_DEVICE_DATA peer="192.168.31.187:33046 @ 0x2800210" latency=-1.951799961s timeout=10s May 31 20:11:03 volumio volumio5-onboarding[1496]: time=2026-05-31T20:11:03.032+02:00 level=INFO msg="emitting device capabilities changed event" component=server peer="192.168.31.187:33046 @ 0x2800210" May 31 20:11:03 volumio volumio[1158]: info: Received Get System Info May 31 20:11:03 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 31 20:11:03 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 31 20:11:03 volumio volumio[1158]: info: Discovery: Getting this device information May 31 20:11:03 volumio volumio[1158]: info: CoreCommandRouter::volumioGetState May 31 20:11:03 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 31 20:11:03 volumio volumio5-onboarding[1496]: time=2026-05-31T20:11:03.038+02:00 level=INFO msg="emitting device name changed event" component=server peer="192.168.31.187:33046 @ 0x2800210" name=Volumio May 31 20:11:03 volumio volumio5-onboarding[1496]: time=2026-05-31T20:11:03.040+02:00 level=INFO msg="emitting device language changed event" component=server peer="192.168.31.187:33046 @ 0x2800210" language=en May 31 20:11:03 volumio volumio[1158]: verbose: New Socket.io Connection to 192.168.31.20:3000 from 192.168.31.187 UA: Dart/3.10 (dart:io) Engine version: 3 Transport: websocket Total Clients: 7 May 31 20:11:03 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: system , getCurrentTimezone May 31 20:11:03 volumio volumio5-onboarding[1496]: time=2026-05-31T20:11:03.051+02:00 level=INFO msg="emitting device timezone changed event" component=server peer="192.168.31.187:33046 @ 0x2800210" timezone=Europe/Paris May 31 20:11:03 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard May 31 20:11:03 volumio volumio5-onboarding[1496]: time=2026-05-31T20:11:03.053+02:00 level=INFO msg="emitting ethernet info changed event" component=server peer="192.168.31.187:33046 @ 0x2800210" available=true connected=false macAddress= ip4Address= ip6Address= May 31 20:11:03 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard May 31 20:11:03 volumio volumio5-onboarding[1496]: time=2026-05-31T20:11:03.059+02:00 level=INFO msg="emitting wifi info changed event" component=server peer="192.168.31.187:33046 @ 0x2800210" available=true connected=true macAddress=b8:27:eb:75:6a:4d ip4Address=192.168.31.20/24 ip6Address= ssid=SFR_0FD8 May 31 20:11:03 volumio volumio5-onboarding[1496]: time=2026-05-31T20:11:03.059+02:00 level=INFO msg="emitting device setup status changed event" component=server peer="192.168.31.187:33046 @ 0x2800210" setupComplete=true May 31 20:11:03 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getExtendedOutputDevices May 31 20:11:03 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions May 31 20:11:03 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 31 20:11:03 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus May 31 20:11:03 volumio volumio[1158]: amixer -c 0 info | grep "bcm2835 ALSA" May 31 20:11:03 volumio volumio[1158]: amixer -c 1 info | grep "bcm2835 Headphones" May 31 20:11:03 volumio volumio[1158]: Card sysdefault:1 'Headphones'/'bcm2835 Headphones' May 31 20:11:03 volumio volumio[1158]: error: Cannot read Audio Device Capabilities Command failed: /usr/local/bin/alsacap -C 2 May 31 20:11:03 volumio volumio[1158]: /bin/sh: 1: /usr/local/bin/alsacap: not found May 31 20:11:03 volumio volumio[1158]: {"cmd":"/usr/local/bin/alsacap -C 2","code":127,"killed":false,"signal":null,"stack":"Error: Command failed: /usr/local/bin/alsacap -C 2\n/bin/sh: 1: /usr/local/bin/alsacap: not found\n\n at ChildProcess.exithandler (node:child_process:421:12)\n at ChildProcess.emit (node:events:514:28)\n at maybeClose (node:internal/child_process:1105:16)\n at Socket. (node:internal/child_process:457:11)\n at Socket.emit (node:events:514:28)\n at Pipe. (node:net:337:12)"} May 31 20:11:03 volumio volumio[1158]: amixer -c 2 info | grep "vc4-hdmi" May 31 20:11:03 volumio volumio[1158]: Card sysdefault:2 'vc4hdmi'/'vc4-hdmi' May 31 20:11:03 volumio volumio[1158]: error: Cannot read Audio Device Capabilities Command failed: /usr/local/bin/alsacap -C 5 May 31 20:11:03 volumio volumio[1158]: /bin/sh: 1: /usr/local/bin/alsacap: not found May 31 20:11:03 volumio volumio[1158]: {"cmd":"/usr/local/bin/alsacap -C 5","code":127,"killed":false,"signal":null,"stack":"Error: Command failed: /usr/local/bin/alsacap -C 5\n/bin/sh: 1: /usr/local/bin/alsacap: not found\n\n at ChildProcess.exithandler (node:child_process:421:12)\n at ChildProcess.emit (node:events:514:28)\n at maybeClose (node:internal/child_process:1105:16)\n at Socket. (node:internal/child_process:457:11)\n at Socket.emit (node:events:514:28)\n at Pipe. (node:net:337:12)"} May 31 20:11:03 volumio volumio[1158]: amixer -c 5 info | grep "C-Media USB Headphone Set" May 31 20:11:03 volumio volumio[1158]: Card sysdefault:5 'Set'/'C-Media USB Headphone Set at usb-3f980000.usb-1.5, full speed' May 31 20:11:03 volumio volumio[1158]: error: Cannot read Audio Device Capabilities Command failed: /usr/local/bin/alsacap -C 5 May 31 20:11:03 volumio volumio[1158]: /bin/sh: 1: /usr/local/bin/alsacap: not found May 31 20:11:03 volumio volumio[1158]: {"cmd":"/usr/local/bin/alsacap -C 5","code":127,"killed":false,"signal":null,"stack":"Error: Command failed: /usr/local/bin/alsacap -C 5\n/bin/sh: 1: /usr/local/bin/alsacap: not found\n\n at ChildProcess.exithandler (node:child_process:421:12)\n at ChildProcess.emit (node:events:514:28)\n at maybeClose (node:internal/child_process:1105:16)\n at Socket. (node:internal/child_process:457:11)\n at Socket.emit (node:events:514:28)\n at Pipe. (node:net:337:12)"} May 31 20:11:03 volumio volumio[1158]: amixer -c 5 info | grep "C-Media USB Headphone Set" May 31 20:11:03 volumio volumio[1158]: Card sysdefault:5 'Set'/'C-Media USB Headphone Set at usb-3f980000.usb-1.5, full speed' May 31 20:11:03 volumio volumio5-onboarding[1496]: time=2026-05-31T20:11:03.289+02:00 level=INFO msg="emitting audio outputs changed event" component=server peer="192.168.31.187:33046 @ 0x2800210" selectedOutputId=5 May 31 20:11:03 volumio volumio[1158]: info: Received Get System Info May 31 20:11:03 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 31 20:11:03 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 31 20:11:03 volumio volumio[1158]: info: Discovery: Getting this device information May 31 20:11:03 volumio volumio[1158]: info: CoreCommandRouter::volumioGetState May 31 20:11:03 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 31 20:11:03 volumio volumio5-onboarding[1496]: time=2026-05-31T20:11:03.326+02:00 level=INFO msg="emitting software info changed event" component=server peer="192.168.31.187:33046 @ 0x2800210" currentVersion=4.119 latestVersion=4.119 May 31 20:11:03 volumio volumio5-onboarding[1496]: time=2026-05-31T20:11:03.326+02:00 level=INFO msg="emitting software update progress event" component=server peer="192.168.31.187:33046 @ 0x2800210" status=UPDATE_STATUS_NONE progress=0 May 31 20:11:03 volumio volumio5-onboarding[1496]: time=2026-05-31T20:11:03.326+02:00 level=INFO msg="emitting user changed event" component=server peer="192.168.31.187:33046 @ 0x2800210" userId= May 31 20:11:03 volumio volumio5-onboarding[1496]: time=2026-05-31T20:11:03.327+02:00 level=INFO msg="emitting music providers changed event" component=server peer="192.168.31.187:33046 @ 0x2800210" providers=3 May 31 20:11:03 volumio volumio5-onboarding[1496]: time=2026-05-31T20:11:03.327+02:00 level=INFO msg="emitting plugins changed event" component=server peer="192.168.31.187:33046 @ 0x2800210" plugins=67 May 31 20:11:03 volumio volumio[1158]: info: CoreCommandRouter::volumioGetState May 31 20:11:03 volumio volumio5-onboarding[1496]: time=2026-05-31T20:11:03.333+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.31.187:33046 @ 0x2800210" state=STATUS_PLAYING positionMs=241566 volume=62 May 31 20:11:03 volumio volumio5-onboarding[1496]: time=2026-05-31T20:11:03.334+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.31.187:33046 @ 0x2800210" id=spotify:episode:5atN5Qn9j5GxG28Iiab2iG title="Whispers from the lost library book Chapter 10: Heidi Heckelbeck - Book Return" May 31 20:11:04 volumio volumio5-onboarding[1496]: time=2026-05-31T20:11:04.279+02:00 level=INFO msg="navigate to next page" component=server type=REQUEST_TYPE_CONTINUE_NAVIGATION peer="192.168.31.187:33046 @ 0x2800210" latency=-1.954229796s timeout=10s from=APP_PAGE_ROOT to=APP_PAGE_LEGACY_DEVICE May 31 20:11:04 volumio volumio[1158]: verbose: New Socket.io Connection to 192.168.31.20 from 192.168.31.187 UA: Mozilla/5.0 (Linux; Android 16; Pixel 8 Build/CP1A.260505.005; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/148.0.7778.178 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 7 May 31 20:11:04 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings May 31 20:11:04 volumio volumio[1158]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined May 31 20:11:04 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates May 31 20:11:04 volumio volumio[1158]: info: Received Get System Version May 31 20:11:04 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 31 20:11:04 volumio volumio[1158]: info: Received Get System Info May 31 20:11:04 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 31 20:11:04 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 31 20:11:04 volumio volumio[1158]: info: Discovery: Getting this device information May 31 20:11:04 volumio volumio[1158]: info: CoreCommandRouter::volumioGetState May 31 20:11:04 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 31 20:11:04 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled May 31 20:11:04 volumio volumio[1158]: info: CoreCommandRouter::volumioGetVisibleSources May 31 20:11:04 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 31 20:11:04 volumio volumio[1158]: info: CoreCommandRouter::volumioGetState May 31 20:11:04 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback May 31 20:11:04 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom May 31 20:11:04 volumio volumio[1158]: info: Received Get System Info May 31 20:11:04 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 31 20:11:04 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 31 20:11:04 volumio volumio[1158]: info: Discovery: Getting this device information May 31 20:11:04 volumio volumio[1158]: info: CoreCommandRouter::volumioGetState May 31 20:11:04 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 31 20:11:04 volumio volumio[1158]: info: CoreCommandRouter::volumioGetState May 31 20:11:04 volumio volumio[1158]: info: Listing playlists May 31 20:11:04 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache May 31 20:11:05 volumio sudo[3048]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 May 31 20:11:05 volumio sudo[3048]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 31 20:11:05 volumio sudo[3048]: pam_unix(sudo:session): session closed for user root May 31 20:11:05 volumio sudo[3050]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 May 31 20:11:05 volumio sudo[3050]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 31 20:11:05 volumio sudo[3050]: pam_unix(sudo:session): session closed for user root May 31 20:11:05 volumio volumio[1158]: verbose: New Socket.io Connection to 192.168.31.20 from 192.168.31.187 UA: Mozilla/5.0 (Linux; Android 16; Pixel 8 Build/CP1A.260505.005; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/148.0.7778.178 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 8 May 31 20:11:06 volumio go-librespot[1572]: time="2026-05-31T20:11:06+02:00" level=debug msg="fetched chunk 5/14, size: 524288" uri="spotify:track:6L89mwZXSOwYl76YXfX13s" May 31 20:11:06 volumio sudo[3054]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 May 31 20:11:06 volumio sudo[3054]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 31 20:11:06 volumio sudo[3054]: pam_unix(sudo:session): session closed for user root May 31 20:11:06 volumio sudo[3056]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 May 31 20:11:06 volumio sudo[3056]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 31 20:11:06 volumio sudo[3056]: pam_unix(sudo:session): session closed for user root May 31 20:11:06 volumio volumio[1158]: verbose: New Socket.io Connection to 192.168.31.20 from 192.168.31.187 UA: Mozilla/5.0 (Linux; Android 16; Pixel 8 Build/CP1A.260505.005; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/148.0.7778.178 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 9 May 31 20:11:07 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled May 31 20:11:07 volumio volumio[1158]: info: CoreCommandRouter::volumioGetVisibleSources May 31 20:11:07 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 31 20:11:07 volumio volumio[1158]: info: CoreCommandRouter::volumioGetState May 31 20:11:07 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback May 31 20:11:07 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom May 31 20:11:07 volumio volumio[1158]: info: Received Get System Info May 31 20:11:07 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 31 20:11:07 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 31 20:11:07 volumio volumio[1158]: info: Discovery: Getting this device information May 31 20:11:07 volumio volumio[1158]: info: CoreCommandRouter::volumioGetState May 31 20:11:07 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 31 20:11:07 volumio volumio[1158]: info: CoreCommandRouter::volumioGetState May 31 20:11:07 volumio volumio[1158]: info: Listing playlists May 31 20:11:07 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache May 31 20:11:07 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings May 31 20:11:07 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings May 31 20:11:08 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 31 20:11:08 volumio volumio[1158]: info: Received Get System Info May 31 20:11:08 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 31 20:11:08 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 31 20:11:08 volumio volumio[1158]: info: Discovery: Getting this device information May 31 20:11:08 volumio volumio[1158]: info: CoreCommandRouter::volumioGetState May 31 20:11:08 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 31 20:11:08 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard May 31 20:11:08 volumio go-librespot[1572]: time="2026-05-31T20:11:08+02:00" level=trace msg="sent dealer ping" May 31 20:11:08 volumio go-librespot[1572]: time="2026-05-31T20:11:08+02:00" level=trace msg="received dealer pong" May 31 20:11:09 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 31 20:11:09 volumio volumio[1158]: info: Received Get System Info May 31 20:11:09 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 31 20:11:09 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 31 20:11:09 volumio volumio[1158]: info: Discovery: Getting this device information May 31 20:11:09 volumio volumio[1158]: info: CoreCommandRouter::volumioGetState May 31 20:11:09 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 31 20:11:14 volumio volumio[1158]: info: CoreCommandRouter::getUIConfigOnPlugin May 31 20:11:14 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam May 31 20:11:14 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam May 31 20:11:14 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam May 31 20:11:14 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: appearance , getAvailableUIs May 31 20:11:15 volumio volumio[1158]: info: Received Get System Version May 31 20:11:15 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 31 20:11:16 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted May 31 20:11:18 volumio go-librespot[1572]: time="2026-05-31T20:11:18+02:00" level=debug msg="fetched chunk 6/14, size: 524288" uri="spotify:track:6L89mwZXSOwYl76YXfX13s" May 31 20:11:24 volumio volumio[1158]: info: CoreCommandRouter::getUIConfigOnPlugin May 31 20:11:24 volumio volumio[1158]: info: CoreCommandRouter::getUIConfigOnPlugin May 31 20:11:24 volumio volumio[1158]: info: Retrieving Cloud Streaming UI May 31 20:11:24 volumio volumio[1158]: info: Getting Tidal Cloud Configuration May 31 20:11:24 volumio volumio[1158]: info: CoreCommandRouter::getUIConfigOnPlugin May 31 20:11:24 volumio volumio[1158]: info: Getting Qobuz Cloud Configuration May 31 20:11:24 volumio volumio[1158]: info: Asking plugin for UI Config May 31 20:11:24 volumio volumio[1158]: info: CoreCommandRouter::getUIConfigOnPlugin May 31 20:11:24 volumio volumio[1158]: info: Getting Spotify Cloud Configuration May 31 20:11:24 volumio volumio[1158]: info: Asking plugin for UI Config May 31 20:11:24 volumio volumio[1158]: info: CoreCommandRouter::getUIConfigOnPlugin May 31 20:11:24 volumio volumio[1158]: info: Saving Spotify Acccount May 31 20:11:24 volumio volumio[1158]: info: Got Tidal Cloud Configuration May 31 20:11:24 volumio volumio[1158]: info: Got it May 31 20:11:24 volumio volumio[1158]: info: Got it May 31 20:11:24 volumio volumio[1158]: error: Could not retrieve Spotify Config from plugin Spotify: no section found May 31 20:11:24 volumio volumio[1158]: info: CoreCommandRouter::getUIConfigOnPlugin May 31 20:11:24 volumio volumio[1158]: error: Error retrieving Highresaudio conf: TypeError: Cannot read properties of undefined (reading 'onSave') May 31 20:11:24 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus May 31 20:11:24 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam May 31 20:11:24 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam May 31 20:11:24 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam May 31 20:11:24 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 31 20:11:24 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 31 20:11:24 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 31 20:11:24 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 31 20:11:24 volumio volumio[1158]: info: CoreCommandRouter::volumioGetBrowseSources May 31 20:11:24 volumio volumio[1158]: info: CoreCommandRouter::volumioGetBrowseSources May 31 20:11:24 volumio volumio[1158]: info: CoreCommandRouter::volumioGetBrowseSources May 31 20:11:24 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats May 31 20:11:24 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: networkfs , listShares May 31 20:11:25 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings May 31 20:11:25 volumio volumio[1158]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined May 31 20:11:25 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates May 31 20:11:25 volumio volumio[1158]: info: Received Get System Version May 31 20:11:25 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 31 20:11:25 volumio volumio[1158]: info: Received Get System Info May 31 20:11:25 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 31 20:11:25 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 31 20:11:25 volumio volumio[1158]: info: Discovery: Getting this device information May 31 20:11:25 volumio volumio[1158]: info: CoreCommandRouter::volumioGetState May 31 20:11:25 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 31 20:11:28 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats May 31 20:11:31 volumio go-librespot[1572]: time="2026-05-31T20:11:31+02:00" level=debug msg="fetched chunk 7/14, size: 524288" uri="spotify:track:6L89mwZXSOwYl76YXfX13s" May 31 20:11:32 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats May 31 20:11:34 volumio volumio5-onboarding[1496]: time=2026-05-31T20:11:34.030+02:00 level=INFO msg="new address was allocated" component=ble/conn old=7 new=8 May 31 20:11:36 volumio volumio5-onboarding[1496]: time=2026-05-31T20:11:36.280+02:00 level=INFO msg="new address was allocated" component=ble/conn old=8 new=9 May 31 20:11:36 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats May 31 20:11:38 volumio go-librespot[1572]: time="2026-05-31T20:11:38+02:00" level=trace msg="sent dealer ping" May 31 20:11:38 volumio go-librespot[1572]: time="2026-05-31T20:11:38+02:00" level=trace msg="received dealer pong" May 31 20:11:39 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 31 20:11:39 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken May 31 20:11:43 volumio go-librespot[1572]: time="2026-05-31T20:11:43+02:00" level=debug msg="fetched chunk 8/14, size: 524288" uri="spotify:track:6L89mwZXSOwYl76YXfX13s" May 31 20:11:44 volumio volumio[1158]: info: CoreCommandRouter::getUIConfigOnPlugin May 31 20:11:55 volumio go-librespot[1572]: time="2026-05-31T20:11:55+02:00" level=debug msg="fetched chunk 9/14, size: 524288" uri="spotify:track:6L89mwZXSOwYl76YXfX13s" May 31 20:12:06 volumio go-librespot[1572]: time="2026-05-31T20:12:06+02:00" level=debug msg="fetched chunk 10/14, size: 524288" uri="spotify:track:6L89mwZXSOwYl76YXfX13s" May 31 20:12:08 volumio go-librespot[1572]: time="2026-05-31T20:12:08+02:00" level=trace msg="sent dealer ping" May 31 20:12:09 volumio go-librespot[1572]: time="2026-05-31T20:12:09+02:00" level=trace msg="received dealer pong" May 31 20:12:18 volumio go-librespot[1572]: time="2026-05-31T20:12:18+02:00" level=debug msg="fetched chunk 11/14, size: 524288" uri="spotify:track:6L89mwZXSOwYl76YXfX13s" May 31 20:12:22 volumio volumio[1158]: info: Received OAUTH Data May 31 20:12:22 volumio volumio[1158]: info: Executing Spotify Oauth Login May 31 20:12:22 volumio volumio[1158]: info: Saving Spotify Refresh Token May 31 20:12:22 volumio volumio[1158]: info: New Spotify access tokenBQB8ZXwysS... May 31 20:12:22 volumio volumio[1158]: info: Spotify credentials grant success - running version from March 24, 2019 May 31 20:12:22 volumio sudo[3182]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 May 31 20:12:22 volumio sudo[3184]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 May 31 20:12:22 volumio sudo[3182]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 31 20:12:22 volumio sudo[3184]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 31 20:12:22 volumio volumio[1158]: SPOTIFY: User informations: {"account_id":"JhyoFiEuop","country":"FR","display_name":"ematli","email":"emanuele.matli@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/ematli"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/ematli","id":"ematli","images":[],"product":"premium","type":"user","uri":"spotify:user:ematli"} May 31 20:12:22 volumio volumio[1158]: info: Creating Spotify config file May 31 20:12:22 volumio sudo[3182]: pam_unix(sudo:session): session closed for user root May 31 20:12:22 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 31 20:12:22 volumio sudo[3184]: pam_unix(sudo:session): session closed for user root May 31 20:12:22 volumio volumio[1158]: info: Spotify config file written May 31 20:12:22 volumio sudo[3189]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service May 31 20:12:22 volumio sudo[3189]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 31 20:12:22 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... May 31 20:12:22 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. May 31 20:12:22 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 31 20:12:22 volumio systemd[1]: go-librespot-daemon.service: Consumed 9.700s CPU time. May 31 20:12:22 volumio volumio[1158]: info: Connection to go-librespot Websocket closed May 31 20:12:22 volumio volumio[1158]: verbose: New Socket.io Connection to 192.168.31.20 from 192.168.31.187 UA: Mozilla/5.0 (Linux; Android 16; Pixel 8 Build/CP1A.260505.005; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/148.0.7778.178 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 8 May 31 20:12:22 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 31 20:12:22 volumio go-librespot[3191]: go-librespot daemon starting... May 31 20:12:22 volumio sudo[3189]: pam_unix(sudo:session): session closed for user root May 31 20:12:22 volumio go-librespot[3192]: time="2026-05-31T20:12:22+02:00" level=info msg="running go-librespot 0.7.1" May 31 20:12:22 volumio go-librespot[3192]: time="2026-05-31T20:12:22+02:00" level=debug msg="app state loaded" May 31 20:12:22 volumio go-librespot[3192]: time="2026-05-31T20:12:22+02:00" level=debug msg="stored credentials not found" May 31 20:12:22 volumio volumio[1158]: info: New Spotify access tokenBQBNWxfDMl... May 31 20:12:22 volumio volumio[1158]: info: Spotify credentials grant success - running version from March 24, 2019 May 31 20:12:22 volumio go-librespot[3192]: time="2026-05-31T20:12:22+02:00" level=info msg="api server listening on 127.0.0.1:9879" May 31 20:12:23 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled May 31 20:12:23 volumio volumio[1158]: SPOTIFY: User informations: {"account_id":"JhyoFiEuop","country":"FR","display_name":"ematli","email":"emanuele.matli@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/ematli"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/ematli","id":"ematli","images":[],"product":"premium","type":"user","uri":"spotify:user:ematli"} May 31 20:12:23 volumio volumio[1158]: info: Spotify Successfully logged in May 31 20:12:23 volumio volumio[1158]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 31 20:12:23 volumio volumio[1158]: info: [1780251143190] CoreMusicLibrary::Adding element Spotify May 31 20:12:23 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 31 20:12:23 volumio volumio[1158]: Cannot find translation for source Radio Browser May 31 20:12:23 volumio volumio[1158]: Cannot find translation for source Spotify May 31 20:12:23 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache May 31 20:12:23 volumio volumio[1158]: info: CoreCommandRouter::volumioGetVisibleSources May 31 20:12:23 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 31 20:12:23 volumio volumio[1158]: info: CoreCommandRouter::volumioGetState May 31 20:12:23 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback May 31 20:12:23 volumio volumio[1158]: info: CoreCommandRouter::getUIConfigOnPlugin May 31 20:12:23 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom May 31 20:12:23 volumio go-librespot[3192]: time="2026-05-31T20:12:23+02: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]" May 31 20:12:23 volumio go-librespot[3192]: time="2026-05-31T20:12:23+02: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]" May 31 20:12:23 volumio go-librespot[3192]: time="2026-05-31T20:12:23+02: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]" May 31 20:12:23 volumio go-librespot[3192]: time="2026-05-31T20:12:23+02:00" level=info msg="zeroconf server listening on port 41869" May 31 20:12:23 volumio go-librespot[3192]: time="2026-05-31T20:12:23+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" May 31 20:12:23 volumio volumio[1158]: info: Received Get System Info May 31 20:12:23 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 31 20:12:23 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 31 20:12:23 volumio volumio[1158]: info: Discovery: Getting this device information May 31 20:12:23 volumio volumio[1158]: info: CoreCommandRouter::volumioGetState May 31 20:12:23 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 31 20:12:23 volumio volumio[1158]: info: CoreCommandRouter::volumioGetState May 31 20:12:23 volumio volumio[1158]: info: Listing playlists May 31 20:12:23 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings May 31 20:12:23 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings May 31 20:12:23 volumio go-librespot[3192]: time="2026-05-31T20:12:23+02:00" level=debug msg="obtained new client token: AABtjLksrmwdYy9iuu7JakBHFHnjW5BRH8fQLObJOAe+si8KIsJG4RrClJQzrfmjgZqoDlR39hoC7lsO22qyUU6cRYZp5DYC40lPTzCv6uS/rRK4mE+RaFADYaQRALlTzA54md0g138Z8xy6rmLC9iF2zmUT90FqnAy6cQ3HX8zbDhhu4BTsYi/1iBawnC9bJOpAu/tLptjUArnAakCBKTb/C/KIw4rVC08N+yv3uz5Qw1BcOJ3Ab01+" May 31 20:12:23 volumio go-librespot[3192]: time="2026-05-31T20:12:23+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" May 31 20:12:23 volumio go-librespot[3192]: time="2026-05-31T20:12:23+02:00" level=debug msg="completed keyexchange" May 31 20:12:23 volumio go-librespot[3192]: time="2026-05-31T20:12:23+02:00" level=debug msg="completed challenge" May 31 20:12:23 volumio go-librespot[3192]: time="2026-05-31T20:12:23+02:00" level=info msg="authenticated AP" username="em**li" May 31 20:12:23 volumio go-librespot[3192]: time="2026-05-31T20:12:23+02:00" level=info msg="authenticated Login5" username="em**li" May 31 20:12:23 volumio go-librespot[3192]: time="2026-05-31T20:12:23+02:00" level=debug msg="stored credentials" username="em**li" May 31 20:12:23 volumio go-librespot[3192]: time="2026-05-31T20:12:23+02:00" level=debug msg="initializing zeroconf session" username="em**li" May 31 20:12:23 volumio go-librespot[3192]: time="2026-05-31T20:12:23+02:00" level=debug msg="dealer connection opened" May 31 20:12:23 volumio go-librespot[3192]: time="2026-05-31T20:12:23+02:00" level=trace msg="starting accesspoint recv loop" May 31 20:12:23 volumio go-librespot[3192]: time="2026-05-31T20:12:23+02:00" level=trace msg="starting dealer recv loop" May 31 20:12:23 volumio go-librespot[3192]: time="2026-05-31T20:12:23+02:00" level=trace msg="received accesspoint ping" May 31 20:12:23 volumio go-librespot[3192]: time="2026-05-31T20:12:23+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" May 31 20:12:23 volumio go-librespot[3192]: time="2026-05-31T20:12:23+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" May 31 20:12:23 volumio go-librespot[3192]: time="2026-05-31T20:12:23+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" May 31 20:12:23 volumio go-librespot[3192]: time="2026-05-31T20:12:23+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" May 31 20:12:23 volumio go-librespot[3192]: time="2026-05-31T20:12:23+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" May 31 20:12:23 volumio go-librespot[3192]: time="2026-05-31T20:12:23+02:00" level=debug msg="received connection id: MWE0Y2RkNjYtMWIy...NDVEODcwM0U5RQ==" May 31 20:12:23 volumio go-librespot[3192]: time="2026-05-31T20:12:23+02:00" level=trace msg="received accesspoint pong ack" May 31 20:12:24 volumio go-librespot[3192]: time="2026-05-31T20:12:24+02:00" level=debug msg="put connect state because NEW_DEVICE" May 31 20:12:24 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 31 20:12:24 volumio volumio[1158]: info: Received Get System Info May 31 20:12:24 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 31 20:12:24 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 31 20:12:24 volumio volumio[1158]: info: Discovery: Getting this device information May 31 20:12:24 volumio volumio[1158]: info: CoreCommandRouter::volumioGetState May 31 20:12:24 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 31 20:12:24 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard May 31 20:12:25 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 31 20:12:25 volumio volumio[1158]: info: Received Get System Info May 31 20:12:25 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 31 20:12:25 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 31 20:12:25 volumio volumio[1158]: info: Discovery: Getting this device information May 31 20:12:25 volumio volumio[1158]: info: CoreCommandRouter::volumioGetState May 31 20:12:25 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 31 20:12:25 volumio volumio[1158]: info: Initializing connection to go-librespot Websocket May 31 20:12:25 volumio go-librespot[3192]: time="2026-05-31T20:12:25+02:00" level=debug msg="new websocket client" May 31 20:12:25 volumio volumio[1158]: info: Connection to go-librespot Websocket established May 31 20:12:25 volumio volumio[1158]: info: go-librespot daemon successfully initialized May 31 20:12:28 volumio volumio[1158]: info: Getting Spotify volume May 31 20:12:28 volumio volumio[1158]: info: Initializing connection to go-librespot Websocket May 31 20:12:28 volumio volumio[1158]: info: Spotify volume: 100 May 31 20:12:28 volumio go-librespot[3192]: time="2026-05-31T20:12:28+02:00" level=debug msg="new websocket client" May 31 20:12:28 volumio volumio[1158]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 May 31 20:12:28 volumio volumio[1158]: info: Connection to go-librespot Websocket established May 31 20:12:28 volumio volumio[1158]: info: CoreCommandRouter::volumioGetState May 31 20:12:28 volumio volumio[1158]: SPOTIFY: RECEIVED VOLUMIO VOLUME 62 May 31 20:12:28 volumio volumio[1158]: SPOTIFY: SPOTIFY VOLUME 100 May 31 20:12:28 volumio volumio[1158]: SPOTIFY: VOLUMIO VOLUME 62 May 31 20:12:28 volumio volumio[1158]: SPOTIFY: DELTA VOLUME ENOUGH: true May 31 20:12:28 volumio volumio[1158]: info: Setting Spotify Volume from Volumio: 62 May 31 20:12:30 volumio volumio[1158]: SPOTIFY: SETTING SPOTIFY VOLUME 62 May 31 20:12:30 volumio volumio[1158]: info: Sending Spotify command with payload to local API: /player/volume May 31 20:12:30 volumio go-librespot[3192]: time="2026-05-31T20:12:30+02:00" level=debug msg="update volume requested to 40631/65535" May 31 20:12:30 volumio go-librespot[3192]: time="2026-05-31T20:12:30+02:00" level=debug msg="put connect state because VOLUME_CHANGED" May 31 20:12:30 volumio go-librespot[3192]: time="2026-05-31T20:12:30+02:00" level=trace msg="emitting websocket event: volume" May 31 20:12:30 volumio volumio[1158]: SPOTIFY: received: {"type":"volume","data":{"value":62,"max":100}} May 31 20:12:30 volumio volumio[1158]: SPOTIFY: RECEIVED SPOTIFY VOLUME 62 May 31 20:12:30 volumio volumio[1158]: SPOTIFY: received: {"type":"volume","data":{"value":62,"max":100}} May 31 20:12:30 volumio volumio[1158]: SPOTIFY: RECEIVED SPOTIFY VOLUME 62 May 31 20:12:31 volumio volumio[1158]: info: Getting Spotify volume May 31 20:12:31 volumio volumio[1158]: info: Spotify volume: 62 May 31 20:12:31 volumio volumio[1158]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 May 31 20:12:31 volumio volumio[1158]: info: CoreCommandRouter::volumioGetState May 31 20:12:31 volumio volumio[1158]: SPOTIFY: RECEIVED VOLUMIO VOLUME 62 May 31 20:12:32 volumio volumio[1158]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] May 31 20:12:32 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings May 31 20:12:32 volumio volumio[1158]: info: Creating Spotify config file May 31 20:12:32 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 31 20:12:32 volumio volumio[1158]: info: Spotify config file written May 31 20:12:32 volumio sudo[3216]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service May 31 20:12:32 volumio sudo[3216]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 31 20:12:32 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... May 31 20:12:32 volumio systemd[1]: go-librespot-daemon.service: Killing process 3196 (go-librespot) with signal SIGKILL. May 31 20:12:32 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. May 31 20:12:32 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 31 20:12:32 volumio volumio[1158]: info: Connection to go-librespot Websocket closed May 31 20:12:32 volumio volumio[1158]: info: Connection to go-librespot Websocket closed May 31 20:12:32 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 31 20:12:32 volumio go-librespot[3219]: go-librespot daemon starting... May 31 20:12:32 volumio sudo[3216]: pam_unix(sudo:session): session closed for user root May 31 20:12:32 volumio go-librespot[3220]: time="2026-05-31T20:12:32+02:00" level=info msg="running go-librespot 0.7.1" May 31 20:12:32 volumio go-librespot[3220]: time="2026-05-31T20:12:32+02:00" level=debug msg="app state loaded" May 31 20:12:32 volumio go-librespot[3220]: time="2026-05-31T20:12:32+02:00" level=info msg="api server listening on 127.0.0.1:9879" May 31 20:12:32 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted May 31 20:12:32 volumio go-librespot[3220]: time="2026-05-31T20:12:32+02: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]" May 31 20:12:32 volumio go-librespot[3220]: time="2026-05-31T20:12:32+02: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]" May 31 20:12:32 volumio go-librespot[3220]: time="2026-05-31T20:12:32+02: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]" May 31 20:12:32 volumio go-librespot[3220]: time="2026-05-31T20:12:32+02:00" level=info msg="zeroconf server listening on port 40385" May 31 20:12:32 volumio go-librespot[3220]: time="2026-05-31T20:12:32+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" May 31 20:12:33 volumio go-librespot[3220]: time="2026-05-31T20:12:33+02:00" level=debug msg="obtained new client token: AABYhZzQ8ec22anYlwZt1qli8XYMmo6tiI5VU0R6RvOjg8M/cWIz+5WNinu2ptYFUHcnWzophTFX1ec0EFBVqqNTiD2uQho1q9tJqcL+vzW8dmnP9FF7yliQp4DZlE7KZoXhGMYUstYZQrs/TfF0DG+bJ8P5OxNR//afmPdNBTAfc9xI6yE/mPPj9/TiJQNF/xuP7EW2j9QLVh6W0Bi+ktEeUNsCZVK9Tf2O2g7MVrKaT6YogTfCFw==" May 31 20:12:33 volumio go-librespot[3220]: time="2026-05-31T20:12:33+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" May 31 20:12:33 volumio go-librespot[3220]: time="2026-05-31T20:12:33+02:00" level=debug msg="completed keyexchange" May 31 20:12:33 volumio go-librespot[3220]: time="2026-05-31T20:12:33+02:00" level=debug msg="completed challenge" May 31 20:12:33 volumio go-librespot[3220]: time="2026-05-31T20:12:33+02:00" level=info msg="authenticated AP" username="em**li" May 31 20:12:33 volumio go-librespot[3220]: time="2026-05-31T20:12:33+02:00" level=info msg="authenticated Login5" username="em**li" May 31 20:12:33 volumio go-librespot[3220]: time="2026-05-31T20:12:33+02:00" level=debug msg="initializing zeroconf session" username="em**li" May 31 20:12:33 volumio go-librespot[3220]: time="2026-05-31T20:12:33+02:00" level=debug msg="dealer connection opened" May 31 20:12:33 volumio go-librespot[3220]: time="2026-05-31T20:12:33+02:00" level=trace msg="starting accesspoint recv loop" May 31 20:12:33 volumio go-librespot[3220]: time="2026-05-31T20:12:33+02:00" level=trace msg="starting dealer recv loop" May 31 20:12:33 volumio go-librespot[3220]: time="2026-05-31T20:12:33+02:00" level=trace msg="received accesspoint ping" May 31 20:12:33 volumio go-librespot[3220]: time="2026-05-31T20:12:33+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" May 31 20:12:33 volumio go-librespot[3220]: time="2026-05-31T20:12:33+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" May 31 20:12:33 volumio go-librespot[3220]: time="2026-05-31T20:12:33+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" May 31 20:12:33 volumio go-librespot[3220]: time="2026-05-31T20:12:33+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" May 31 20:12:33 volumio go-librespot[3220]: time="2026-05-31T20:12:33+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" May 31 20:12:33 volumio go-librespot[3220]: time="2026-05-31T20:12:33+02:00" level=debug msg="received connection id: ZDQyNzRkMmEtY2Ew...RDczOTVEMUU4NA==" May 31 20:12:33 volumio go-librespot[3220]: time="2026-05-31T20:12:33+02:00" level=trace msg="received accesspoint pong ack" May 31 20:12:33 volumio go-librespot[3220]: time="2026-05-31T20:12:33+02:00" level=debug msg="put connect state because NEW_DEVICE" May 31 20:12:34 volumio volumio[1158]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] May 31 20:12:34 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings May 31 20:12:34 volumio volumio[1158]: info: Creating Spotify config file May 31 20:12:34 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 31 20:12:34 volumio volumio[1158]: info: Spotify config file written May 31 20:12:34 volumio sudo[3230]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service May 31 20:12:34 volumio sudo[3230]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 31 20:12:34 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... May 31 20:12:34 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. May 31 20:12:34 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 31 20:12:34 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 31 20:12:34 volumio go-librespot[3232]: go-librespot daemon starting... May 31 20:12:34 volumio sudo[3230]: pam_unix(sudo:session): session closed for user root May 31 20:12:34 volumio go-librespot[3233]: time="2026-05-31T20:12:34+02:00" level=info msg="running go-librespot 0.7.1" May 31 20:12:34 volumio go-librespot[3233]: time="2026-05-31T20:12:34+02:00" level=debug msg="app state loaded" May 31 20:12:34 volumio go-librespot[3233]: time="2026-05-31T20:12:34+02:00" level=info msg="api server listening on 127.0.0.1:9879" May 31 20:12:34 volumio go-librespot[3233]: time="2026-05-31T20:12:34+02: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]" May 31 20:12:34 volumio go-librespot[3233]: time="2026-05-31T20:12:34+02: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]" May 31 20:12:34 volumio go-librespot[3233]: time="2026-05-31T20:12:34+02: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]" May 31 20:12:34 volumio go-librespot[3233]: time="2026-05-31T20:12:34+02:00" level=info msg="zeroconf server listening on port 35631" May 31 20:12:34 volumio go-librespot[3233]: time="2026-05-31T20:12:34+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" May 31 20:12:35 volumio go-librespot[3233]: time="2026-05-31T20:12:35+02:00" level=debug msg="obtained new client token: AADyRNx4wPWsbjnx1KLZJZWj/CPQWzbAOXkeIpSF7S+dGjD8NwjhuoeOFxqGZIAHmqwZaONqjPu3DEikaelG17MH6ddgC5oBZNe+8H0Gb4ZyV+P8+0GHfpA3cVRp+qNTPxRqadvJXHdbpcTvsEkVAdmQeVYg+wKeWqOvnEWZvVSIRDlmqBH66PQoolCtR1z0C1X8BqoMdn3g7h0NQxQRJjziHHQvl1tSOSrOcWDPJVQ1IhdmBEUuEnFO" May 31 20:12:35 volumio go-librespot[3233]: time="2026-05-31T20:12:35+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" May 31 20:12:35 volumio go-librespot[3233]: time="2026-05-31T20:12:35+02:00" level=debug msg="completed keyexchange" May 31 20:12:35 volumio go-librespot[3233]: time="2026-05-31T20:12:35+02:00" level=debug msg="completed challenge" May 31 20:12:35 volumio go-librespot[3233]: time="2026-05-31T20:12:35+02:00" level=info msg="authenticated AP" username="em**li" May 31 20:12:35 volumio go-librespot[3233]: time="2026-05-31T20:12:35+02:00" level=info msg="authenticated Login5" username="em**li" May 31 20:12:35 volumio go-librespot[3233]: time="2026-05-31T20:12:35+02:00" level=debug msg="initializing zeroconf session" username="em**li" May 31 20:12:35 volumio go-librespot[3233]: time="2026-05-31T20:12:35+02:00" level=debug msg="dealer connection opened" May 31 20:12:35 volumio go-librespot[3233]: time="2026-05-31T20:12:35+02:00" level=trace msg="starting accesspoint recv loop" May 31 20:12:35 volumio go-librespot[3233]: time="2026-05-31T20:12:35+02:00" level=trace msg="starting dealer recv loop" May 31 20:12:35 volumio go-librespot[3233]: time="2026-05-31T20:12:35+02:00" level=trace msg="received accesspoint ping" May 31 20:12:35 volumio go-librespot[3233]: time="2026-05-31T20:12:35+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" May 31 20:12:35 volumio go-librespot[3233]: time="2026-05-31T20:12:35+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" May 31 20:12:35 volumio go-librespot[3233]: time="2026-05-31T20:12:35+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" May 31 20:12:35 volumio go-librespot[3233]: time="2026-05-31T20:12:35+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" May 31 20:12:35 volumio go-librespot[3233]: time="2026-05-31T20:12:35+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" May 31 20:12:35 volumio go-librespot[3233]: time="2026-05-31T20:12:35+02:00" level=debug msg="received connection id: NTlmYmQ4OWItNzcy...NDI2Q0Q1QkJENA==" May 31 20:12:35 volumio go-librespot[3233]: time="2026-05-31T20:12:35+02:00" level=trace msg="received accesspoint pong ack" May 31 20:12:35 volumio volumio[1158]: info: Initializing connection to go-librespot Websocket May 31 20:12:35 volumio go-librespot[3233]: time="2026-05-31T20:12:35+02:00" level=debug msg="new websocket client" May 31 20:12:35 volumio volumio[1158]: info: Connection to go-librespot Websocket established May 31 20:12:35 volumio volumio[1158]: info: go-librespot daemon successfully initialized May 31 20:12:35 volumio go-librespot[3233]: time="2026-05-31T20:12:35+02:00" level=debug msg="put connect state because NEW_DEVICE" May 31 20:12:37 volumio volumio[1158]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] May 31 20:12:37 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings May 31 20:12:37 volumio volumio[1158]: info: Creating Spotify config file May 31 20:12:37 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 31 20:12:37 volumio volumio[1158]: info: Spotify config file written May 31 20:12:37 volumio sudo[3259]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service May 31 20:12:37 volumio sudo[3259]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 31 20:12:37 volumio systemd[1]: Starting setdatetime-helper.service - Time Synchronization Helper Service... May 31 20:12:37 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... May 31 20:12:37 volumio volumio[1158]: info: Connection to go-librespot Websocket closed May 31 20:12:37 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. May 31 20:12:37 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 31 20:12:37 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 31 20:12:37 volumio go-librespot[3264]: go-librespot daemon starting... May 31 20:12:37 volumio sudo[3259]: pam_unix(sudo:session): session closed for user root May 31 20:12:37 volumio go-librespot[3265]: time="2026-05-31T20:12:37+02:00" level=info msg="running go-librespot 0.7.1" May 31 20:12:37 volumio go-librespot[3265]: time="2026-05-31T20:12:37+02:00" level=debug msg="app state loaded" May 31 20:12:37 volumio go-librespot[3265]: time="2026-05-31T20:12:37+02:00" level=info msg="api server listening on 127.0.0.1:9879" May 31 20:12:37 volumio volumio[1158]: info: go-librespot daemon successfully initialized May 31 20:12:37 volumio go-librespot[3265]: time="2026-05-31T20:12:37+02: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]" May 31 20:12:37 volumio go-librespot[3265]: time="2026-05-31T20:12:37+02: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]" May 31 20:12:37 volumio go-librespot[3265]: time="2026-05-31T20:12:37+02: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]" May 31 20:12:37 volumio go-librespot[3265]: time="2026-05-31T20:12:37+02:00" level=info msg="zeroconf server listening on port 36107" May 31 20:12:37 volumio go-librespot[3265]: time="2026-05-31T20:12:37+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" May 31 20:12:37 volumio go-librespot[3265]: time="2026-05-31T20:12:37+02:00" level=debug msg="obtained new client token: AACggGWQqmrAwLvBoAC7gXFw7nPxBy+IzxSlDc4kXceaeYTIv598i1QuEVYBK8/fwoT1jo/fPus+vd/ez8CDZbCs/dmzTY5qNLMCx5cjQT78M3vEAVmLhi/q6MUPtQ+TFBfZ+jEDVIQ3YYigA3hMi99T/UVfqeGFzxvBkAX1dHskjg+XCUaCZPWO3o1y40OP4NNsCFgRF4iHQEPaPKSnI4+0vFnVXYVQKu60SQ/mXtw2kdEnygxX+dPP" May 31 20:12:37 volumio go-librespot[3265]: time="2026-05-31T20:12:37+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" May 31 20:12:38 volumio go-librespot[3265]: time="2026-05-31T20:12:38+02:00" level=debug msg="completed keyexchange" May 31 20:12:38 volumio go-librespot[3265]: time="2026-05-31T20:12:38+02:00" level=debug msg="completed challenge" May 31 20:12:38 volumio go-librespot[3265]: time="2026-05-31T20:12:38+02:00" level=info msg="authenticated AP" username="em**li" May 31 20:12:38 volumio go-librespot[3265]: time="2026-05-31T20:12:38+02:00" level=info msg="authenticated Login5" username="em**li" May 31 20:12:38 volumio go-librespot[3265]: time="2026-05-31T20:12:38+02:00" level=debug msg="initializing zeroconf session" username="em**li" May 31 20:12:38 volumio go-librespot[3265]: time="2026-05-31T20:12:38+02:00" level=debug msg="dealer connection opened" May 31 20:12:38 volumio go-librespot[3265]: time="2026-05-31T20:12:38+02:00" level=trace msg="starting accesspoint recv loop" May 31 20:12:38 volumio go-librespot[3265]: time="2026-05-31T20:12:38+02:00" level=trace msg="starting dealer recv loop" May 31 20:12:38 volumio go-librespot[3265]: time="2026-05-31T20:12:38+02:00" level=trace msg="received accesspoint ping" May 31 20:12:38 volumio go-librespot[3265]: time="2026-05-31T20:12:38+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" May 31 20:12:38 volumio go-librespot[3265]: time="2026-05-31T20:12:38+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" May 31 20:12:38 volumio go-librespot[3265]: time="2026-05-31T20:12:38+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" May 31 20:12:38 volumio go-librespot[3265]: time="2026-05-31T20:12:38+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" May 31 20:12:38 volumio go-librespot[3265]: time="2026-05-31T20:12:38+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" May 31 20:12:38 volumio go-librespot[3265]: time="2026-05-31T20:12:38+02:00" level=debug msg="received connection id: NTljMTJhYTQtNTEz...QTQ4ODFCNzRGRg==" May 31 20:12:38 volumio go-librespot[3265]: time="2026-05-31T20:12:38+02:00" level=trace msg="received accesspoint pong ack" May 31 20:12:38 volumio volumio[1158]: info: Getting Spotify volume May 31 20:12:38 volumio volumio[1158]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 May 31 20:12:38 volumio volumio[1158]: info: Initializing connection to go-librespot Websocket May 31 20:12:38 volumio go-librespot[3265]: time="2026-05-31T20:12:38+02:00" level=debug msg="new websocket client" May 31 20:12:38 volumio volumio[1158]: info: CoreCommandRouter::volumioGetState May 31 20:12:38 volumio volumio[1158]: info: Connection to go-librespot Websocket established May 31 20:12:38 volumio volumio[1158]: SPOTIFY: RECEIVED VOLUMIO VOLUME 62 May 31 20:12:38 volumio systemd[1]: setdatetime-helper.service: Deactivated successfully. May 31 20:12:38 volumio systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service. May 31 20:12:38 volumio systemd[1]: setdatetime-helper.service: Consumed 1.101s CPU time. May 31 20:12:38 volumio go-librespot[3265]: time="2026-05-31T20:12:38+02:00" level=debug msg="put connect state because NEW_DEVICE" May 31 20:12:38 volumio volumio[1158]: info: Spotify volume: 100 May 31 20:12:39 volumio volumio[1158]: info: CoreCommandRouter::volumioPause May 31 20:12:39 volumio volumio[1158]: info: CoreStateMachine::pause May 31 20:12:39 volumio volumio[1158]: info: CoreStateMachine::stPlaybackTimer May 31 20:12:39 volumio volumio[1158]: info: CoreStateMachine::servicePause May 31 20:12:39 volumio volumio[1158]: info: CoreCommandRouter::servicePause May 31 20:12:39 volumio volumio[1158]: info: Spotify Received pause May 31 20:12:39 volumio volumio[1158]: SPOTIFY: SPOTIFY PAUSE May 31 20:12:39 volumio volumio[1158]: SPOTIFY: {"status":"play","title":"Whispers from the lost library book Chapter 10: Heidi Heckelbeck - Book Return","artist":"Latest Peppa pig Stories","album":"Latest Peppa pig Stories","albumart":"https://i.scdn.co/image/ab67656300005f1f65afd38c02a50745f0360bc3","uri":"spotify:episode:5atN5Qn9j5GxG28Iiab2iG","trackType":"spotify","codec":"ogg","seek":326566,"duration":349,"samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2,"random":null,"repeat":null,"repeatSingle":null,"consume":false,"volume":62,"dbVolume":null,"mute":false,"disableVolumeControl":false,"stream":false,"updatedb":false,"volatile":true,"service":"spop"} May 31 20:12:39 volumio volumio[1158]: info: Sending Spotify command to local API: /player/pause May 31 20:12:40 volumio volumio[1158]: info: Initializing connection to go-librespot Websocket May 31 20:12:40 volumio go-librespot[3265]: time="2026-05-31T20:12:40+02:00" level=debug msg="new websocket client" May 31 20:12:40 volumio volumio[1158]: info: Connection to go-librespot Websocket established May 31 20:12:40 volumio volumio[1158]: info: go-librespot daemon successfully initialized May 31 20:12:40 volumio volumio[1158]: info: Initializing connection to go-librespot Websocket May 31 20:12:40 volumio go-librespot[3265]: time="2026-05-31T20:12:40+02:00" level=debug msg="new websocket client" May 31 20:12:40 volumio volumio[1158]: info: Connection to go-librespot Websocket established May 31 20:12:40 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings May 31 20:12:40 volumio volumio[1158]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined May 31 20:12:40 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates May 31 20:12:40 volumio volumio[1158]: info: Received Get System Version May 31 20:12:40 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 31 20:12:40 volumio volumio[1158]: info: Received Get System Info May 31 20:12:40 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 31 20:12:40 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 31 20:12:40 volumio volumio[1158]: info: Discovery: Getting this device information May 31 20:12:40 volumio volumio[1158]: info: CoreCommandRouter::volumioGetState May 31 20:12:40 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 31 20:12:41 volumio volumio[1158]: info: Getting Spotify volume May 31 20:12:41 volumio volumio[1158]: info: Spotify volume: 100 May 31 20:12:41 volumio volumio[1158]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 May 31 20:12:41 volumio volumio[1158]: info: CoreCommandRouter::volumioGetState May 31 20:12:41 volumio volumio[1158]: SPOTIFY: RECEIVED VOLUMIO VOLUME 62 May 31 20:12:41 volumio volumio[1158]: SPOTIFY: SPOTIFY VOLUME 100 May 31 20:12:41 volumio volumio[1158]: SPOTIFY: VOLUMIO VOLUME 62 May 31 20:12:41 volumio volumio[1158]: SPOTIFY: DELTA VOLUME ENOUGH: true May 31 20:12:41 volumio volumio[1158]: info: Setting Spotify Volume from Volumio: 62 May 31 20:12:41 volumio volumio[1158]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] May 31 20:12:41 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings May 31 20:12:41 volumio volumio[1158]: info: Creating Spotify config file May 31 20:12:41 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 31 20:12:41 volumio volumio[1158]: info: Spotify config file written May 31 20:12:41 volumio sudo[3299]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service May 31 20:12:41 volumio sudo[3299]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 31 20:12:41 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... May 31 20:12:41 volumio volumio[1158]: info: Connection to go-librespot Websocket closed May 31 20:12:41 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. May 31 20:12:41 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 31 20:12:41 volumio volumio[1158]: info: Connection to go-librespot Websocket closed May 31 20:12:41 volumio volumio[1158]: info: Connection to go-librespot Websocket closed May 31 20:12:42 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 31 20:12:42 volumio go-librespot[3301]: go-librespot daemon starting... May 31 20:12:42 volumio sudo[3299]: pam_unix(sudo:session): session closed for user root May 31 20:12:42 volumio go-librespot[3302]: time="2026-05-31T20:12:42+02:00" level=info msg="running go-librespot 0.7.1" May 31 20:12:42 volumio go-librespot[3302]: time="2026-05-31T20:12:42+02:00" level=debug msg="app state loaded" May 31 20:12:42 volumio go-librespot[3302]: time="2026-05-31T20:12:42+02:00" level=info msg="api server listening on 127.0.0.1:9879" May 31 20:12:42 volumio go-librespot[3302]: time="2026-05-31T20:12:42+02: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]" May 31 20:12:42 volumio go-librespot[3302]: time="2026-05-31T20:12:42+02: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]" May 31 20:12:42 volumio go-librespot[3302]: time="2026-05-31T20:12:42+02: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]" May 31 20:12:42 volumio go-librespot[3302]: time="2026-05-31T20:12:42+02:00" level=info msg="zeroconf server listening on port 45041" May 31 20:12:42 volumio volumio[1158]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] May 31 20:12:42 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings May 31 20:12:42 volumio volumio[1158]: info: Creating Spotify config file May 31 20:12:42 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 31 20:12:42 volumio volumio[1158]: info: Spotify config file written May 31 20:12:42 volumio go-librespot[3302]: time="2026-05-31T20:12:42+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" May 31 20:12:42 volumio sudo[3312]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service May 31 20:12:42 volumio sudo[3312]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 31 20:12:42 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... May 31 20:12:42 volumio systemd[1]: go-librespot-daemon.service: Killing process 3305 (go-librespot) with signal SIGKILL. May 31 20:12:42 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. May 31 20:12:42 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 31 20:12:42 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 31 20:12:42 volumio go-librespot[3314]: go-librespot daemon starting... May 31 20:12:42 volumio sudo[3312]: pam_unix(sudo:session): session closed for user root May 31 20:12:42 volumio go-librespot[3315]: time="2026-05-31T20:12:42+02:00" level=info msg="running go-librespot 0.7.1" May 31 20:12:42 volumio go-librespot[3315]: time="2026-05-31T20:12:42+02:00" level=debug msg="app state loaded" May 31 20:12:42 volumio volumio[1158]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] May 31 20:12:42 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings May 31 20:12:42 volumio go-librespot[3315]: time="2026-05-31T20:12:42+02:00" level=info msg="api server listening on 127.0.0.1:9879" May 31 20:12:42 volumio volumio[1158]: info: Creating Spotify config file May 31 20:12:42 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 31 20:12:42 volumio volumio[1158]: info: Spotify config file written May 31 20:12:42 volumio sudo[3325]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service May 31 20:12:42 volumio sudo[3325]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 31 20:12:42 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... May 31 20:12:42 volumio systemd[1]: go-librespot-daemon.service: Killing process 3318 (go-librespot) with signal SIGKILL. May 31 20:12:42 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. May 31 20:12:42 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 31 20:12:42 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 31 20:12:42 volumio go-librespot[3327]: go-librespot daemon starting... May 31 20:12:42 volumio sudo[3325]: pam_unix(sudo:session): session closed for user root May 31 20:12:42 volumio volumio[1158]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] May 31 20:12:42 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings May 31 20:12:42 volumio volumio[1158]: info: Creating Spotify config file May 31 20:12:42 volumio volumio[1158]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 31 20:12:42 volumio volumio[1158]: info: Spotify config file written May 31 20:12:42 volumio go-librespot[3329]: time="2026-05-31T20:12:42+02:00" level=info msg="running go-librespot 0.7.1" May 31 20:12:42 volumio go-librespot[3329]: time="2026-05-31T20:12:42+02:00" level=debug msg="app state loaded" May 31 20:12:42 volumio sudo[3336]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service May 31 20:12:42 volumio sudo[3336]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 31 20:12:42 volumio go-librespot[3329]: time="2026-05-31T20:12:42+02:00" level=info msg="api server listening on 127.0.0.1:9879" May 31 20:12:42 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... May 31 20:12:42 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. May 31 20:12:42 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 31 20:12:42 volumio systemd[1]: go-librespot-daemon.service: Start request repeated too quickly. May 31 20:12:42 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'start-limit-hit'. May 31 20:12:42 volumio systemd[1]: Failed to start go-librespot-daemon.service - go-librespot Daemon. May 31 20:12:42 volumio sudo[3336]: pam_unix(sudo:session): session closed for user root May 31 20:12:42 volumio volumio[1158]: error: Cannot start Go-librespot Daemon: Error: Command failed: /usr/bin/sudo systemctl restart go-librespot-daemon.service May 31 20:12:42 volumio volumio[1158]: Job for go-librespot-daemon.service failed because start of the service was attempted too often. May 31 20:12:42 volumio volumio[1158]: See "systemctl status go-librespot-daemon.service" and "journalctl -xeu go-librespot-daemon.service" for details. May 31 20:12:42 volumio volumio[1158]: To force a start use "systemctl reset-failed go-librespot-daemon.service" May 31 20:12:42 volumio volumio[1158]: followed by "systemctl start go-librespot-daemon.service" again. May 31 20:12:42 volumio volumio[1158]: error: Error initializing go-librespot daemon: Error: Command failed: /usr/bin/sudo systemctl restart go-librespot-daemon.service May 31 20:12:42 volumio volumio[1158]: Job for go-librespot-daemon.service failed because start of the service was attempted too often. May 31 20:12:42 volumio volumio[1158]: See "systemctl status go-librespot-daemon.service" and "journalctl -xeu go-librespot-daemon.service" for details. May 31 20:12:42 volumio volumio[1158]: To force a start use "systemctl reset-failed go-librespot-daemon.service" May 31 20:12:42 volumio volumio[1158]: followed by "systemctl start go-librespot-daemon.service" again. May 31 20:12:43 volumio volumio[1158]: SPOTIFY: SETTING SPOTIFY VOLUME 62 May 31 20:12:43 volumio volumio[1158]: info: Sending Spotify command with payload to local API: /player/volume May 31 20:12:43 volumio volumio[1158]: error: Failed to send command to Spotify local API: /player/volume: Error: connect ECONNREFUSED 127.0.0.1:9879 May 31 20:12:43 volumio volumio[1158]: info: Getting Spotify volume May 31 20:12:43 volumio volumio[1158]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 31 20:12:43 volumio volumio[1158]: Error: connect ECONNREFUSED 127.0.0.1:9879 May 31 20:12:43 volumio volumio[1158]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { May 31 20:12:43 volumio volumio[1158]: errno: -111, May 31 20:12:43 volumio volumio[1158]: code: 'ECONNREFUSED', May 31 20:12:43 volumio volumio[1158]: syscall: 'connect', May 31 20:12:43 volumio volumio[1158]: address: '127.0.0.1', May 31 20:12:43 volumio volumio[1158]: port: 9879, May 31 20:12:43 volumio volumio[1158]: response: undefined May 31 20:12:43 volumio volumio[1158]: } May 31 20:12:43 volumio volumio[1158]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 31 20:12:44 volumio sudo[3354]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-05-31 20:11' May 31 20:12:44 volumio sudo[3354]: 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"