Feb 10 16:44:01 volumio-peter volumio[1109]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Feb 10 16:44:01 volumio-peter volumio[1109]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Feb 10 16:44:01 volumio-peter volumio[1109]: info: Streaming services startup Feb 10 16:44:01 volumio-peter volumio[1109]: info: Starting Streaming Daemon Feb 10 16:44:01 volumio-peter volumio[1109]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Feb 10 16:44:01 volumio-peter sudo[1659]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Feb 10 16:44:01 volumio-peter sudo[1659]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 10 16:44:02 volumio-peter sudo[1659]: pam_unix(sudo:session): session closed for user root Feb 10 16:44:02 volumio-peter go-librespot[1529]: time="2026-02-10T16:44:02+01:00" level=debug msg="new websocket client" Feb 10 16:44:02 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Feb 10 16:44:02 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Feb 10 16:44:02 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Feb 10 16:44:02 volumio-peter volumio[1109]: info: AutoStart - Check #5/60 - VOLUMIO_SYSTEM_STATUS = starting Feb 10 16:44:02 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 10 16:44:02 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 10 16:44:02 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Feb 10 16:44:02 volumio-peter volumio[1109]: info: BOOT COMPLETED Feb 10 16:44:02 volumio-peter volumio[1109]: error: An error occurred while listing Spotify featured playlists Error: Client network socket disconnected before secure TLS connection was established Feb 10 16:44:02 volumio-peter volumio[1109]: info: An error occurred while getting Spotify ROOT Discover Folders: Feb 10 16:44:03 volumio-peter volumio[1109]: error: An error occurred while listing Spotify new albums Error: Client network socket disconnected before secure TLS connection was established Feb 10 16:44:03 volumio-peter volumio[1109]: error: An error occurred while listing Spotify categories Error: Client network socket disconnected before secure TLS connection was established Feb 10 16:44:03 volumio-peter volumio[1109]: info: Connection to go-librespot Websocket established Feb 10 16:44:03 volumio-peter volumio[1109]: error: Cannot start Volumio Streaming Daemon Feb 10 16:44:03 volumio-peter volumio[1109]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Feb 10 16:44:03 volumio-peter volumio[1109]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Feb 10 16:44:03 volumio-peter volumio[1109]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Feb 10 16:44:03 volumio-peter volumio[1109]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Feb 10 16:44:03 volumio-peter volumio[1109]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Feb 10 16:44:03 volumio-peter volumio[1109]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Feb 10 16:44:03 volumio-peter volumio[1109]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Feb 10 16:44:03 volumio-peter volumio[1109]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Feb 10 16:44:03 volumio-peter volumio[1109]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Feb 10 16:44:03 volumio-peter volumio[1109]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Feb 10 16:44:03 volumio-peter volumio[1109]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Feb 10 16:44:03 volumio-peter volumio[1109]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Feb 10 16:44:03 volumio-peter volumio[1109]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Feb 10 16:44:03 volumio-peter volumio[1109]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Feb 10 16:44:03 volumio-peter volumio[1109]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Feb 10 16:44:03 volumio-peter volumio[1109]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Feb 10 16:44:03 volumio-peter volumio[1109]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Feb 10 16:44:03 volumio-peter volumio[1109]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Feb 10 16:44:03 volumio-peter volumio[1109]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Feb 10 16:44:03 volumio-peter volumio[1109]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Feb 10 16:44:03 volumio-peter volumio[1109]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Feb 10 16:44:03 volumio-peter volumio[1109]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Feb 10 16:44:03 volumio-peter volumio[1109]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Feb 10 16:44:03 volumio-peter volumio[1109]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Feb 10 16:44:03 volumio-peter volumio[1109]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Feb 10 16:44:03 volumio-peter volumio[1109]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Feb 10 16:44:03 volumio-peter volumio[1109]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Feb 10 16:44:03 volumio-peter volumio[1109]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Feb 10 16:44:03 volumio-peter volumio[1109]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Feb 10 16:44:03 volumio-peter volumio[1109]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Feb 10 16:44:03 volumio-peter volumio[1109]: info: Adding plugin bluetooth to MyMusic Plugins Feb 10 16:44:03 volumio-peter volumio[1109]: info: Adding plugin multiroom to MyMusic Plugins Feb 10 16:44:03 volumio-peter volumio[1109]: info: Adding plugin metavolumio to MyMusic Plugins Feb 10 16:44:03 volumio-peter volumio[1109]: info: Adding plugin cd_controller to MyMusic Plugins Feb 10 16:44:03 volumio-peter volumio[1109]: info: Adding plugin qobuzconnect to MyMusic Plugins Feb 10 16:44:03 volumio-peter volumio[1109]: info: Adding plugin smart_inputs to MyMusic Plugins Feb 10 16:44:03 volumio-peter volumio[1109]: info: Adding plugin tidalconnect to MyMusic Plugins Feb 10 16:44:03 volumio-peter volumio[1109]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Feb 10 16:44:03 volumio-peter volumio[1109]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Feb 10 16:44:03 volumio-peter volumio[1109]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Feb 10 16:44:03 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 10 16:44:03 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 10 16:44:03 volumio-peter volumio[1109]: info: Starting MyVolumio Remote Streaming Endpoints Feb 10 16:44:04 volumio-peter volumio-remote-updater[626]: Test mode disabled Feb 10 16:44:04 volumio-peter volumio-remote-updater[626]: Alpha mode disabled Feb 10 16:44:04 volumio-peter volumio-remote-updater[626]: Alpha legacy test mode disabled Feb 10 16:44:04 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled Feb 10 16:44:05 volumio-peter wpa_supplicant[1069]: wlan0: WPA: Group rekeying completed with 74:42:7f:52:c5:70 [GTK=CCMP] Feb 10 16:44:05 volumio-peter volumio[1109]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Feb 10 16:44:05 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Feb 10 16:44:05 volumio-peter volumio[1109]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Feb 10 16:44:06 volumio-peter volumio[1109]: info: Getting Spotify volume Feb 10 16:44:06 volumio-peter volumio[1109]: info: Spotify volume: 100 Feb 10 16:44:07 volumio-peter volumio[1109]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 10 Feb 10 16:44:07 volumio-peter volumio[1109]: info: MyVolumio token set successfully Feb 10 16:44:07 volumio-peter volumio[1109]: info: MYVOLUMIO: Adding device Feb 10 16:44:07 volumio-peter volumio[1109]: info: MYVOLUMIO: Evaluating Server Feb 10 16:44:07 volumio-peter volumio[1109]: info: AutoStart - Check #6/60 - VOLUMIO_SYSTEM_STATUS = ready Feb 10 16:44:07 volumio-peter volumio[1109]: info: AutoStart - System ready state CONFIRMED after 6 checks Feb 10 16:44:07 volumio-peter volumio[1109]: info: AutoStart - Applying additional delay of 5000ms before playback Feb 10 16:44:08 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Feb 10 16:44:09 volumio-peter volumio[1109]: info: MyVolumio status changed Feb 10 16:44:09 volumio-peter volumio[1109]: info: Streaming services startup Feb 10 16:44:09 volumio-peter volumio[1109]: info: Starting Streaming Daemon Feb 10 16:44:09 volumio-peter wpa_supplicant[1069]: RRM: Ignoring radio measurement request: Not RRM network Feb 10 16:44:09 volumio-peter volumio[1109]: info: Removing browser output: myVolumio user plan is not superstar Feb 10 16:44:09 volumio-peter volumio[1109]: info: Removing audio output: Feb 10 16:44:09 volumio-peter volumio[1109]: info: Stoppping Tunnel 1 Feb 10 16:44:09 volumio-peter sudo[1707]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Feb 10 16:44:09 volumio-peter sudo[1707]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 10 16:44:09 volumio-peter sudo[1707]: pam_unix(sudo:session): session closed for user root Feb 10 16:44:09 volumio-peter sudo[1710]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Feb 10 16:44:09 volumio-peter sudo[1710]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 10 16:44:09 volumio-peter systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Feb 10 16:44:09 volumio-peter systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Feb 10 16:44:09 volumio-peter systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Feb 10 16:44:09 volumio-peter systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Feb 10 16:44:09 volumio-peter volumio[1109]: info: Setting Geolocation for MyVolumio to eu10 Feb 10 16:44:09 volumio-peter systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Feb 10 16:44:09 volumio-peter systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Feb 10 16:44:09 volumio-peter sudo[1710]: pam_unix(sudo:session): session closed for user root Feb 10 16:44:09 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 10 16:44:09 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 10 16:44:09 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 10 16:44:09 volumio-peter volumio[1109]: info: Remote SSH Stopped Feb 10 16:44:09 volumio-peter volumio[1109]: error: Cannot start Volumio Streaming Daemon Feb 10 16:44:09 volumio-peter volumio[1109]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Feb 10 16:44:09 volumio-peter volumio[1109]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Feb 10 16:44:10 volumio-peter volumio[1109]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 11 Feb 10 16:44:10 volumio-peter volumio[1109]: info: Successfully Added MyVolumio device Feb 10 16:44:10 volumio-peter volumio[1109]: info: CoreCommandRouter::volumioGetState Feb 10 16:44:10 volumio-peter volumio[1109]: info: CorePlayQueue::getTrack 0 Feb 10 16:44:10 volumio-peter volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 63 Feb 10 16:44:10 volumio-peter volumio[1109]: SPOTIFY: SPOTIFY VOLUME 100 Feb 10 16:44:10 volumio-peter volumio[1109]: SPOTIFY: VOLUMIO VOLUME 63 Feb 10 16:44:10 volumio-peter volumio[1109]: SPOTIFY: DELTA VOLUME ENOUGH: true Feb 10 16:44:10 volumio-peter volumio[1109]: info: Setting Spotify Volume from Volumio: 63 Feb 10 16:44:10 volumio-peter volumio[1109]: info: CoreCommandRouter::volumioGetState Feb 10 16:44:10 volumio-peter volumio[1109]: info: CorePlayQueue::getTrack 0 Feb 10 16:44:10 volumio-peter volumio[1109]: info: Updating MyVolumio device info Feb 10 16:44:10 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 10 16:44:10 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 10 16:44:10 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 10 16:44:11 volumio-peter wpa_supplicant[1069]: RRM: Ignoring radio measurement request: Not RRM network Feb 10 16:44:11 volumio-peter volumio[1109]: info: Successfully Updated MyVolumio device Feb 10 16:44:11 volumio-peter volumio[1109]: SPOTIFY: SETTING SPOTIFY VOLUME 63 Feb 10 16:44:11 volumio-peter volumio[1109]: info: Sending Spotify command with payload to local API: /player/volume Feb 10 16:44:11 volumio-peter go-librespot[1529]: time="2026-02-10T16:44:11+01:00" level=debug msg="update volume requested to 41287/65535" Feb 10 16:44:11 volumio-peter go-librespot[1529]: time="2026-02-10T16:44:11+01:00" level=debug msg="put connect state because VOLUME_CHANGED" Feb 10 16:44:11 volumio-peter go-librespot[1529]: time="2026-02-10T16:44:11+01:00" level=trace msg="emitting websocket event: volume" Feb 10 16:44:12 volumio-peter volumio[1109]: SPOTIFY: received: {"type":"volume","data":{"value":63,"max":100}} Feb 10 16:44:12 volumio-peter volumio[1109]: SPOTIFY: RECEIVED SPOTIFY VOLUME 63 Feb 10 16:44:12 volumio-peter volumio[1109]: info: AutoStart - startPlayback called Feb 10 16:44:12 volumio-peter volumio[1109]: info: CoreCommandRouter::volumioGetQueue Feb 10 16:44:12 volumio-peter volumio[1109]: info: CoreStateMachine::getQueue Feb 10 16:44:12 volumio-peter volumio[1109]: info: CorePlayQueue::getQueue Feb 10 16:44:12 volumio-peter volumio[1109]: info: AutoStart - Queue has 6 items Feb 10 16:44:12 volumio-peter volumio[1109]: info: AutoStart - Playing from position 0 Feb 10 16:44:12 volumio-peter volumio[1109]: info: CoreCommandRouter::volumioPlay Feb 10 16:44:12 volumio-peter volumio[1109]: info: CoreStateMachine::play index 0 Feb 10 16:44:12 volumio-peter volumio[1109]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 10 16:44:12 volumio-peter volumio[1109]: info: CoreStateMachine::stop Feb 10 16:44:12 volumio-peter volumio[1109]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 10 16:44:12 volumio-peter volumio[1109]: info: CoreStateMachine::play index undefined Feb 10 16:44:12 volumio-peter volumio[1109]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 10 16:44:12 volumio-peter volumio[1109]: info: CorePlayQueue::getTrack 0 Feb 10 16:44:12 volumio-peter volumio[1109]: info: CoreStateMachine::startPlaybackTimer Feb 10 16:44:12 volumio-peter volumio[1109]: info: CorePlayQueue::getTrack 0 Feb 10 16:44:12 volumio-peter volumio[1109]: info: [1770738252628] ControllerSpotify::clearAddPlayTrack Feb 10 16:44:12 volumio-peter volumio[1109]: info: Sending Spotify command with payload to local API: /player/play Feb 10 16:44:12 volumio-peter go-librespot[1529]: time="2026-02-10T16:44:12+01:00" level=debug msg="resolved context of track" uri="spotify:track:4YRb00HJfBRQ5iflOHMefm" Feb 10 16:44:12 volumio-peter go-librespot[1529]: time="2026-02-10T16:44:12+01:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:4YRb00HJfBRQ5iflOHMefm" Feb 10 16:44:12 volumio-peter go-librespot[1529]: time="2026-02-10T16:44:12+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:4YRb00HJfBRQ5iflOHMefm" Feb 10 16:44:12 volumio-peter go-librespot[1529]: time="2026-02-10T16:44:12+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 10 16:44:12 volumio-peter go-librespot[1529]: time="2026-02-10T16:44:12+01:00" level=trace msg="emitting websocket event: will_play" Feb 10 16:44:12 volumio-peter volumio[1109]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:4YRb00HJfBRQ5iflOHMefm","uri":"spotify:track:4YRb00HJfBRQ5iflOHMefm","play_origin":"go-librespot"}} Feb 10 16:44:12 volumio-peter go-librespot[1529]: time="2026-02-10T16:44:12+01:00" level=debug msg="selected format OGG_VORBIS_320 (66ee23941138359d4ed7b656f3bba5f46855b49c)" uri="spotify:track:4YRb00HJfBRQ5iflOHMefm" Feb 10 16:44:12 volumio-peter go-librespot[1529]: time="2026-02-10T16:44:12+01:00" level=debug msg="requested aes key for file 66ee23941138359d4ed7b656f3bba5f46855b49c, gid: 4YRb00HJfBRQ5iflOHMefm" Feb 10 16:44:12 volumio-peter go-librespot[1529]: time="2026-02-10T16:44:12+01:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:4YRb00HJfBRQ5iflOHMefm: failed retrieving audio key: failed retrieving aes key with code 1" Feb 10 16:44:12 volumio-peter volumio[1109]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Feb 10 16:44:13 volumio-peter wpa_supplicant[1069]: RRM: Ignoring radio measurement request: Not RRM network Feb 10 16:44:13 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 10 16:44:13 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 10 16:44:13 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Feb 10 16:44:13 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Feb 10 16:44:13 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Feb 10 16:44:13 volumio-peter volumio[1109]: info: CoreCommandRouter::volumioGetBrowseSources Feb 10 16:44:13 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 10 16:44:15 volumio-peter wpa_supplicant[1069]: RRM: Ignoring radio measurement request: Not RRM network Feb 10 16:44:17 volumio-peter wpa_supplicant[1069]: RRM: Ignoring radio measurement request: Not RRM network Feb 10 16:44:17 volumio-peter wpa_supplicant[1069]: wlan0: WNM: Preferred List Available Feb 10 16:44:17 volumio-peter wpa_supplicant[1069]: wlan0: Trying to associate with 74:42:7f:52:c5:6f (SSID='FRITZ!Box 7530 AQ - Th' freq=5260 MHz) Feb 10 16:44:17 volumio-peter dhcpcd[686]: wlan0: carrier lost - roaming Feb 10 16:44:17 volumio-peter dhcpcd[686]: wlan0: changing route to 192.168.178.0/24 Feb 10 16:44:17 volumio-peter dhcpcd[686]: wlan0: changing default route via 192.168.178.1 Feb 10 16:44:17 volumio-peter kernel: ieee80211 phy0: brcmf_p2p_send_action_frame: Unknown Frame: category 0xa, action 0x8 Feb 10 16:44:17 volumio-peter wpa_supplicant[1069]: wlan0: Associated with 74:42:7f:52:c5:6f Feb 10 16:44:17 volumio-peter wpa_supplicant[1069]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0 Feb 10 16:44:17 volumio-peter wpa_supplicant[1069]: wlan0: WPA: Key negotiation completed with 74:42:7f:52:c5:6f [PTK=CCMP GTK=CCMP] Feb 10 16:44:17 volumio-peter wpa_supplicant[1069]: wlan0: CTRL-EVENT-CONNECTED - Connection to 74:42:7f:52:c5:6f completed [id=0 id_str=] Feb 10 16:44:17 volumio-peter dhcpcd[686]: wlan0: carrier acquired Feb 10 16:44:17 volumio-peter dhcpcd[686]: wlan0: IAID eb:e6:bf:7d Feb 10 16:44:18 volumio-peter dhcpcd[686]: wlan0: soliciting an IPv6 router Feb 10 16:44:18 volumio-peter volumio[1109]: info: Received Get System Info Feb 10 16:44:18 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 10 16:44:18 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 10 16:44:18 volumio-peter volumio[1109]: info: Discovery: Getting this device information Feb 10 16:44:18 volumio-peter volumio[1109]: info: CoreCommandRouter::volumioGetState Feb 10 16:44:18 volumio-peter volumio[1109]: info: CorePlayQueue::getTrack 0 Feb 10 16:44:18 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 10 16:44:18 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Feb 10 16:44:18 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Feb 10 16:44:18 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Feb 10 16:44:19 volumio-peter volumio[1109]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 12 Feb 10 16:44:19 volumio-peter volumio[1109]: info: CoreCommandRouter::volumioGetState Feb 10 16:44:19 volumio-peter volumio[1109]: info: CorePlayQueue::getTrack 0 Feb 10 16:44:19 volumio-peter dhcpcd[686]: wlan0: rebinding lease of 192.168.178.58 Feb 10 16:44:20 volumio-peter dhcpcd[686]: wlan0: leased 192.168.178.58 for 864000 seconds Feb 10 16:44:20 volumio-peter dhcpcd[686]: wlan0: changing route to 192.168.178.0/24 Feb 10 16:44:20 volumio-peter dhcpcd[686]: wlan0: changing default route via 192.168.178.1 Feb 10 16:44:20 volumio-peter systemd[1]: Stopped target ip-changed@wlan0.target - IP Address changed on wlan0. Feb 10 16:44:20 volumio-peter systemd[1]: Stopping ip-changed@wlan0.target - IP Address changed on wlan0... Feb 10 16:44:20 volumio-peter systemd[1]: welcome.service: Deactivated successfully. Feb 10 16:44:20 volumio-peter systemd[1]: Stopped welcome.service - Show a welcome message on console. Feb 10 16:44:20 volumio-peter systemd[1]: Stopping welcome.service - Show a welcome message on console... Feb 10 16:44:20 volumio-peter systemd[1]: Starting welcome.service - Show a welcome message on console... Feb 10 16:44:20 volumio-peter welcome[1755]: Resolved ip:[1] 192.168.178.58 Feb 10 16:44:20 volumio-peter systemd[1]: Finished welcome.service - Show a welcome message on console. Feb 10 16:44:20 volumio-peter systemd[1]: Reached target ip-changed@wlan0.target - IP Address changed on wlan0. Feb 10 16:44:20 volumio-peter volumio[1109]: info: Received Get System Info Feb 10 16:44:20 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 10 16:44:20 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 10 16:44:20 volumio-peter volumio[1109]: info: Discovery: Getting this device information Feb 10 16:44:20 volumio-peter volumio[1109]: info: CoreCommandRouter::volumioGetState Feb 10 16:44:20 volumio-peter volumio[1109]: info: CorePlayQueue::getTrack 0 Feb 10 16:44:20 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 10 16:44:20 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Feb 10 16:44:20 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Feb 10 16:44:23 volumio-peter go-librespot[1529]: time="2026-02-10T16:44:23+01:00" level=trace msg="sent dealer ping" Feb 10 16:44:23 volumio-peter go-librespot[1529]: time="2026-02-10T16:44:23+01:00" level=trace msg="received dealer pong" Feb 10 16:44:23 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 10 16:44:23 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 10 16:44:23 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Feb 10 16:44:23 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Feb 10 16:44:23 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Feb 10 16:44:23 volumio-peter volumio[1109]: info: CoreCommandRouter::volumioGetBrowseSources Feb 10 16:44:23 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 10 16:44:25 volumio-peter wpa_supplicant[1069]: RRM: Ignoring radio measurement request: Not RRM network Feb 10 16:44:31 volumio-peter upmpdcli[1786]: writing RSA key Feb 10 16:44:53 volumio-peter go-librespot[1529]: time="2026-02-10T16:44:53+01:00" level=trace msg="sent dealer ping" Feb 10 16:44:53 volumio-peter go-librespot[1529]: time="2026-02-10T16:44:53+01:00" level=trace msg="received dealer pong" Feb 10 16:45:03 volumio-peter volumio5-onboarding[1438]: time=2026-02-10T16:45:03.859+01:00 level=INFO msg="established new WebSocket connection" component=conn/ws remoteAddr=192.168.178.53:49720 Feb 10 16:45:04 volumio-peter sudo[1844]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Feb 10 16:45:04 volumio-peter sudo[1844]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 10 16:45:05 volumio-peter sudo[1844]: pam_unix(sudo:session): session closed for user root Feb 10 16:45:05 volumio-peter sudo[1846]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Feb 10 16:45:05 volumio-peter sudo[1846]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 10 16:45:05 volumio-peter sudo[1846]: pam_unix(sudo:session): session closed for user root Feb 10 16:45:05 volumio-peter volumio[1109]: verbose: New Socket.io Connection to 192.168.178.58 from 192.168.178.53 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_7 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 7 Feb 10 16:45:05 volumio-peter sudo[1850]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Feb 10 16:45:05 volumio-peter sudo[1850]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 10 16:45:05 volumio-peter sudo[1850]: pam_unix(sudo:session): session closed for user root Feb 10 16:45:05 volumio-peter sudo[1852]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Feb 10 16:45:05 volumio-peter sudo[1852]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 10 16:45:05 volumio-peter sudo[1852]: pam_unix(sudo:session): session closed for user root Feb 10 16:45:06 volumio-peter volumio[1109]: verbose: New Socket.io Connection to 192.168.178.58 from 192.168.178.53 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 Feb 10 16:45:06 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Feb 10 16:45:06 volumio-peter volumio[1109]: info: CoreCommandRouter::volumioGetVisibleSources Feb 10 16:45:06 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 10 16:45:06 volumio-peter volumio[1109]: info: CoreCommandRouter::volumioGetState Feb 10 16:45:06 volumio-peter volumio[1109]: info: CorePlayQueue::getTrack 0 Feb 10 16:45:06 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Feb 10 16:45:06 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Feb 10 16:45:06 volumio-peter volumio[1109]: info: Received Get System Info Feb 10 16:45:06 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 10 16:45:06 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 10 16:45:06 volumio-peter volumio[1109]: info: Discovery: Getting this device information Feb 10 16:45:06 volumio-peter volumio[1109]: info: CoreCommandRouter::volumioGetState Feb 10 16:45:06 volumio-peter volumio[1109]: info: CorePlayQueue::getTrack 0 Feb 10 16:45:06 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 10 16:45:06 volumio-peter volumio[1109]: info: CoreCommandRouter::volumioGetState Feb 10 16:45:06 volumio-peter volumio[1109]: info: CorePlayQueue::getTrack 0 Feb 10 16:45:06 volumio-peter volumio[1109]: info: Listing playlists Feb 10 16:45:06 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Feb 10 16:45:06 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Feb 10 16:45:06 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Feb 10 16:45:07 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Feb 10 16:45:07 volumio-peter volumio[1109]: info: Received Get System Info Feb 10 16:45:07 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 10 16:45:07 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 10 16:45:07 volumio-peter volumio[1109]: info: Discovery: Getting this device information Feb 10 16:45:07 volumio-peter volumio[1109]: info: CoreCommandRouter::volumioGetState Feb 10 16:45:07 volumio-peter volumio[1109]: info: CorePlayQueue::getTrack 0 Feb 10 16:45:07 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 10 16:45:08 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Feb 10 16:45:08 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Feb 10 16:45:08 volumio-peter volumio[1109]: info: Received Get System Info Feb 10 16:45:08 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 10 16:45:08 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 10 16:45:08 volumio-peter volumio[1109]: info: Discovery: Getting this device information Feb 10 16:45:08 volumio-peter volumio[1109]: info: CoreCommandRouter::volumioGetState Feb 10 16:45:08 volumio-peter volumio[1109]: info: CorePlayQueue::getTrack 0 Feb 10 16:45:08 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 10 16:45:08 volumio-peter volumio[1109]: info: CoreCommandRouter::volumioPlay Feb 10 16:45:08 volumio-peter volumio[1109]: info: CoreStateMachine::play index undefined Feb 10 16:45:08 volumio-peter volumio[1109]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 10 16:45:08 volumio-peter volumio[1109]: info: CorePlayQueue::getTrack 0 Feb 10 16:45:08 volumio-peter volumio[1109]: info: CoreStateMachine::startPlaybackTimer Feb 10 16:45:08 volumio-peter volumio[1109]: info: CorePlayQueue::getTrack 0 Feb 10 16:45:08 volumio-peter volumio[1109]: info: [1770738308691] ControllerSpotify::clearAddPlayTrack Feb 10 16:45:08 volumio-peter volumio[1109]: info: Sending Spotify command with payload to local API: /player/play Feb 10 16:45:08 volumio-peter go-librespot[1529]: time="2026-02-10T16:45:08+01:00" level=debug msg="resolved context of track" uri="spotify:track:4YRb00HJfBRQ5iflOHMefm" Feb 10 16:45:08 volumio-peter go-librespot[1529]: time="2026-02-10T16:45:08+01:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:4YRb00HJfBRQ5iflOHMefm" Feb 10 16:45:08 volumio-peter go-librespot[1529]: time="2026-02-10T16:45:08+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:4YRb00HJfBRQ5iflOHMefm" Feb 10 16:45:08 volumio-peter go-librespot[1529]: time="2026-02-10T16:45:08+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 10 16:45:08 volumio-peter go-librespot[1529]: time="2026-02-10T16:45:08+01:00" level=trace msg="emitting websocket event: will_play" Feb 10 16:45:08 volumio-peter volumio[1109]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:4YRb00HJfBRQ5iflOHMefm","uri":"spotify:track:4YRb00HJfBRQ5iflOHMefm","play_origin":"go-librespot"}} Feb 10 16:45:08 volumio-peter go-librespot[1529]: time="2026-02-10T16:45:08+01:00" level=debug msg="selected format OGG_VORBIS_320 (66ee23941138359d4ed7b656f3bba5f46855b49c)" uri="spotify:track:4YRb00HJfBRQ5iflOHMefm" Feb 10 16:45:08 volumio-peter go-librespot[1529]: time="2026-02-10T16:45:08+01:00" level=debug msg="requested aes key for file 66ee23941138359d4ed7b656f3bba5f46855b49c, gid: 4YRb00HJfBRQ5iflOHMefm" Feb 10 16:45:08 volumio-peter go-librespot[1529]: time="2026-02-10T16:45:08+01:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:4YRb00HJfBRQ5iflOHMefm: failed retrieving audio key: failed retrieving aes key with code 1" Feb 10 16:45:08 volumio-peter volumio[1109]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Feb 10 16:45:11 volumio-peter volumio[1109]: info: CoreCommandRouter::volumioPlay Feb 10 16:45:11 volumio-peter volumio[1109]: info: CoreStateMachine::play index undefined Feb 10 16:45:11 volumio-peter volumio[1109]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 10 16:45:11 volumio-peter volumio[1109]: info: CorePlayQueue::getTrack 0 Feb 10 16:45:11 volumio-peter volumio[1109]: info: CoreStateMachine::startPlaybackTimer Feb 10 16:45:11 volumio-peter volumio[1109]: info: CorePlayQueue::getTrack 0 Feb 10 16:45:11 volumio-peter volumio[1109]: info: [1770738311361] ControllerSpotify::clearAddPlayTrack Feb 10 16:45:11 volumio-peter volumio[1109]: info: Sending Spotify command with payload to local API: /player/play Feb 10 16:45:11 volumio-peter go-librespot[1529]: time="2026-02-10T16:45:11+01:00" level=debug msg="resolved context of track" uri="spotify:track:4YRb00HJfBRQ5iflOHMefm" Feb 10 16:45:11 volumio-peter go-librespot[1529]: time="2026-02-10T16:45:11+01:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:4YRb00HJfBRQ5iflOHMefm" Feb 10 16:45:11 volumio-peter go-librespot[1529]: time="2026-02-10T16:45:11+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:4YRb00HJfBRQ5iflOHMefm" Feb 10 16:45:11 volumio-peter go-librespot[1529]: time="2026-02-10T16:45:11+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 10 16:45:11 volumio-peter go-librespot[1529]: time="2026-02-10T16:45:11+01:00" level=trace msg="emitting websocket event: will_play" Feb 10 16:45:11 volumio-peter volumio[1109]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:4YRb00HJfBRQ5iflOHMefm","uri":"spotify:track:4YRb00HJfBRQ5iflOHMefm","play_origin":"go-librespot"}} Feb 10 16:45:11 volumio-peter go-librespot[1529]: time="2026-02-10T16:45:11+01:00" level=debug msg="selected format OGG_VORBIS_320 (66ee23941138359d4ed7b656f3bba5f46855b49c)" uri="spotify:track:4YRb00HJfBRQ5iflOHMefm" Feb 10 16:45:11 volumio-peter go-librespot[1529]: time="2026-02-10T16:45:11+01:00" level=debug msg="requested aes key for file 66ee23941138359d4ed7b656f3bba5f46855b49c, gid: 4YRb00HJfBRQ5iflOHMefm" Feb 10 16:45:11 volumio-peter go-librespot[1529]: time="2026-02-10T16:45:11+01:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:4YRb00HJfBRQ5iflOHMefm: failed retrieving audio key: failed retrieving aes key with code 1" Feb 10 16:45:11 volumio-peter volumio[1109]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Feb 10 16:45:12 volumio-peter volumio[1109]: info: CoreCommandRouter::volumioGetQueue Feb 10 16:45:12 volumio-peter volumio[1109]: info: CoreStateMachine::getQueue Feb 10 16:45:12 volumio-peter volumio[1109]: info: CorePlayQueue::getQueue Feb 10 16:45:13 volumio-peter volumio[1109]: info: CoreCommandRouter::volumioPlay Feb 10 16:45:13 volumio-peter volumio[1109]: info: CoreStateMachine::play index 5 Feb 10 16:45:13 volumio-peter volumio[1109]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 10 16:45:13 volumio-peter volumio[1109]: info: CoreStateMachine::stop Feb 10 16:45:13 volumio-peter volumio[1109]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 10 16:45:13 volumio-peter volumio[1109]: info: CoreStateMachine::play index undefined Feb 10 16:45:13 volumio-peter volumio[1109]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 10 16:45:13 volumio-peter volumio[1109]: info: CorePlayQueue::getTrack 5 Feb 10 16:45:13 volumio-peter volumio[1109]: info: CoreStateMachine::startPlaybackTimer Feb 10 16:45:13 volumio-peter volumio[1109]: info: CorePlayQueue::getTrack 5 Feb 10 16:45:13 volumio-peter volumio[1109]: info: [1770738313657] ControllerSpotify::clearAddPlayTrack Feb 10 16:45:13 volumio-peter volumio[1109]: info: Sending Spotify command with payload to local API: /player/play Feb 10 16:45:13 volumio-peter go-librespot[1529]: time="2026-02-10T16:45:13+01:00" level=debug msg="resolved context of track" uri="spotify:track:2LNsZbDPc4zermXO0u6xfi" Feb 10 16:45:13 volumio-peter go-librespot[1529]: time="2026-02-10T16:45:13+01:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:2LNsZbDPc4zermXO0u6xfi" Feb 10 16:45:13 volumio-peter go-librespot[1529]: time="2026-02-10T16:45:13+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:2LNsZbDPc4zermXO0u6xfi" Feb 10 16:45:13 volumio-peter go-librespot[1529]: time="2026-02-10T16:45:13+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 10 16:45:13 volumio-peter go-librespot[1529]: time="2026-02-10T16:45:13+01:00" level=trace msg="emitting websocket event: will_play" Feb 10 16:45:13 volumio-peter volumio[1109]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:2LNsZbDPc4zermXO0u6xfi","uri":"spotify:track:2LNsZbDPc4zermXO0u6xfi","play_origin":"go-librespot"}} Feb 10 16:45:13 volumio-peter go-librespot[1529]: time="2026-02-10T16:45:13+01:00" level=debug msg="selected format OGG_VORBIS_320 (83f7d05e1e9134654745f4f4983afc369b5504d2)" uri="spotify:track:2LNsZbDPc4zermXO0u6xfi" Feb 10 16:45:13 volumio-peter go-librespot[1529]: time="2026-02-10T16:45:13+01:00" level=debug msg="requested aes key for file 83f7d05e1e9134654745f4f4983afc369b5504d2, gid: 2LNsZbDPc4zermXO0u6xfi" Feb 10 16:45:13 volumio-peter go-librespot[1529]: time="2026-02-10T16:45:13+01:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:2LNsZbDPc4zermXO0u6xfi: failed retrieving audio key: failed retrieving aes key with code 1" Feb 10 16:45:13 volumio-peter volumio[1109]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Feb 10 16:45:15 volumio-peter volumio[1109]: info: CoreCommandRouter::volumioPlay Feb 10 16:45:15 volumio-peter volumio[1109]: info: CoreStateMachine::play index 5 Feb 10 16:45:15 volumio-peter volumio[1109]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 10 16:45:15 volumio-peter volumio[1109]: info: CoreStateMachine::stop Feb 10 16:45:15 volumio-peter volumio[1109]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 10 16:45:15 volumio-peter volumio[1109]: info: CoreStateMachine::play index undefined Feb 10 16:45:15 volumio-peter volumio[1109]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 10 16:45:15 volumio-peter volumio[1109]: info: CorePlayQueue::getTrack 5 Feb 10 16:45:15 volumio-peter volumio[1109]: info: CoreStateMachine::startPlaybackTimer Feb 10 16:45:15 volumio-peter volumio[1109]: info: CorePlayQueue::getTrack 5 Feb 10 16:45:15 volumio-peter volumio[1109]: info: [1770738315426] ControllerSpotify::clearAddPlayTrack Feb 10 16:45:15 volumio-peter volumio[1109]: info: Sending Spotify command with payload to local API: /player/play Feb 10 16:45:15 volumio-peter go-librespot[1529]: time="2026-02-10T16:45:15+01:00" level=debug msg="resolved context of track" uri="spotify:track:2LNsZbDPc4zermXO0u6xfi" Feb 10 16:45:15 volumio-peter go-librespot[1529]: time="2026-02-10T16:45:15+01:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:2LNsZbDPc4zermXO0u6xfi" Feb 10 16:45:15 volumio-peter go-librespot[1529]: time="2026-02-10T16:45:15+01:00" level=debug msg="loading track (paused: false, position: 1ms)" uri="spotify:track:2LNsZbDPc4zermXO0u6xfi" Feb 10 16:45:15 volumio-peter go-librespot[1529]: time="2026-02-10T16:45:15+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 10 16:45:15 volumio-peter go-librespot[1529]: time="2026-02-10T16:45:15+01:00" level=trace msg="emitting websocket event: will_play" Feb 10 16:45:15 volumio-peter volumio[1109]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:2LNsZbDPc4zermXO0u6xfi","uri":"spotify:track:2LNsZbDPc4zermXO0u6xfi","play_origin":"go-librespot"}} Feb 10 16:45:15 volumio-peter go-librespot[1529]: time="2026-02-10T16:45:15+01:00" level=debug msg="selected format OGG_VORBIS_320 (83f7d05e1e9134654745f4f4983afc369b5504d2)" uri="spotify:track:2LNsZbDPc4zermXO0u6xfi" Feb 10 16:45:15 volumio-peter go-librespot[1529]: time="2026-02-10T16:45:15+01:00" level=debug msg="requested aes key for file 83f7d05e1e9134654745f4f4983afc369b5504d2, gid: 2LNsZbDPc4zermXO0u6xfi" Feb 10 16:45:15 volumio-peter go-librespot[1529]: time="2026-02-10T16:45:15+01:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:2LNsZbDPc4zermXO0u6xfi: failed retrieving audio key: failed retrieving aes key with code 1" Feb 10 16:45:15 volumio-peter volumio[1109]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Feb 10 16:45:15 volumio-peter volumio[1109]: info: CoreCommandRouter::volumioPlay Feb 10 16:45:15 volumio-peter volumio[1109]: info: CoreStateMachine::play index 5 Feb 10 16:45:15 volumio-peter volumio[1109]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 10 16:45:15 volumio-peter volumio[1109]: info: CoreStateMachine::stop Feb 10 16:45:15 volumio-peter volumio[1109]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 10 16:45:15 volumio-peter volumio[1109]: info: CoreStateMachine::play index undefined Feb 10 16:45:15 volumio-peter volumio[1109]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 10 16:45:15 volumio-peter volumio[1109]: info: CorePlayQueue::getTrack 5 Feb 10 16:45:15 volumio-peter volumio[1109]: info: CoreStateMachine::startPlaybackTimer Feb 10 16:45:15 volumio-peter volumio[1109]: info: CorePlayQueue::getTrack 5 Feb 10 16:45:15 volumio-peter volumio[1109]: info: [1770738315914] ControllerSpotify::clearAddPlayTrack Feb 10 16:45:15 volumio-peter volumio[1109]: info: Sending Spotify command with payload to local API: /player/play Feb 10 16:45:15 volumio-peter go-librespot[1529]: time="2026-02-10T16:45:15+01:00" level=debug msg="resolved context of track" uri="spotify:track:2LNsZbDPc4zermXO0u6xfi" Feb 10 16:45:15 volumio-peter go-librespot[1529]: time="2026-02-10T16:45:15+01:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:2LNsZbDPc4zermXO0u6xfi" Feb 10 16:45:15 volumio-peter go-librespot[1529]: time="2026-02-10T16:45:15+01:00" level=debug msg="loading track (paused: false, position: 1ms)" uri="spotify:track:2LNsZbDPc4zermXO0u6xfi" Feb 10 16:45:15 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Feb 10 16:45:16 volumio-peter go-librespot[1529]: time="2026-02-10T16:45:16+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 10 16:45:16 volumio-peter go-librespot[1529]: time="2026-02-10T16:45:16+01:00" level=trace msg="emitting websocket event: will_play" Feb 10 16:45:16 volumio-peter volumio[1109]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:2LNsZbDPc4zermXO0u6xfi","uri":"spotify:track:2LNsZbDPc4zermXO0u6xfi","play_origin":"go-librespot"}} Feb 10 16:45:16 volumio-peter go-librespot[1529]: time="2026-02-10T16:45:16+01:00" level=debug msg="selected format OGG_VORBIS_320 (83f7d05e1e9134654745f4f4983afc369b5504d2)" uri="spotify:track:2LNsZbDPc4zermXO0u6xfi" Feb 10 16:45:16 volumio-peter go-librespot[1529]: time="2026-02-10T16:45:16+01:00" level=debug msg="requested aes key for file 83f7d05e1e9134654745f4f4983afc369b5504d2, gid: 2LNsZbDPc4zermXO0u6xfi" Feb 10 16:45:16 volumio-peter go-librespot[1529]: time="2026-02-10T16:45:16+01:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:2LNsZbDPc4zermXO0u6xfi: failed retrieving audio key: failed retrieving aes key with code 1" Feb 10 16:45:16 volumio-peter volumio[1109]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Feb 10 16:45:20 volumio-peter volumio[1109]: info: CoreCommandRouter::volumioPlay Feb 10 16:45:20 volumio-peter volumio[1109]: info: CoreStateMachine::play index undefined Feb 10 16:45:20 volumio-peter volumio[1109]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 10 16:45:20 volumio-peter volumio[1109]: info: CorePlayQueue::getTrack 5 Feb 10 16:45:20 volumio-peter volumio[1109]: info: CoreStateMachine::startPlaybackTimer Feb 10 16:45:20 volumio-peter volumio[1109]: info: CorePlayQueue::getTrack 5 Feb 10 16:45:20 volumio-peter volumio[1109]: info: [1770738320893] ControllerSpotify::clearAddPlayTrack Feb 10 16:45:20 volumio-peter volumio[1109]: info: Sending Spotify command with payload to local API: /player/play Feb 10 16:45:20 volumio-peter go-librespot[1529]: time="2026-02-10T16:45:20+01:00" level=debug msg="resolved context of track" uri="spotify:track:2LNsZbDPc4zermXO0u6xfi" Feb 10 16:45:20 volumio-peter go-librespot[1529]: time="2026-02-10T16:45:20+01:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:2LNsZbDPc4zermXO0u6xfi" Feb 10 16:45:20 volumio-peter go-librespot[1529]: time="2026-02-10T16:45:20+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:2LNsZbDPc4zermXO0u6xfi" Feb 10 16:45:21 volumio-peter go-librespot[1529]: time="2026-02-10T16:45:21+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 10 16:45:21 volumio-peter go-librespot[1529]: time="2026-02-10T16:45:21+01:00" level=trace msg="emitting websocket event: will_play" Feb 10 16:45:21 volumio-peter volumio[1109]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:2LNsZbDPc4zermXO0u6xfi","uri":"spotify:track:2LNsZbDPc4zermXO0u6xfi","play_origin":"go-librespot"}} Feb 10 16:45:21 volumio-peter go-librespot[1529]: time="2026-02-10T16:45:21+01:00" level=debug msg="selected format OGG_VORBIS_320 (83f7d05e1e9134654745f4f4983afc369b5504d2)" uri="spotify:track:2LNsZbDPc4zermXO0u6xfi" Feb 10 16:45:21 volumio-peter go-librespot[1529]: time="2026-02-10T16:45:21+01:00" level=debug msg="requested aes key for file 83f7d05e1e9134654745f4f4983afc369b5504d2, gid: 2LNsZbDPc4zermXO0u6xfi" Feb 10 16:45:21 volumio-peter go-librespot[1529]: time="2026-02-10T16:45:21+01:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:2LNsZbDPc4zermXO0u6xfi: failed retrieving audio key: failed retrieving aes key with code 1" Feb 10 16:45:21 volumio-peter volumio[1109]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Feb 10 16:45:22 volumio-peter go-librespot[1529]: time="2026-02-10T16:45:22+01:00" level=trace msg="received accesspoint ping" Feb 10 16:45:22 volumio-peter go-librespot[1529]: time="2026-02-10T16:45:22+01:00" level=trace msg="received accesspoint pong ack" Feb 10 16:45:23 volumio-peter go-librespot[1529]: time="2026-02-10T16:45:23+01:00" level=trace msg="sent dealer ping" Feb 10 16:45:23 volumio-peter go-librespot[1529]: time="2026-02-10T16:45:23+01:00" level=trace msg="received dealer pong" Feb 10 16:45:23 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Feb 10 16:45:23 volumio-peter volumio[1109]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Feb 10 16:45:24 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Feb 10 16:45:24 volumio-peter volumio[1109]: info: Received Get System Version Feb 10 16:45:24 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 10 16:45:24 volumio-peter volumio[1109]: info: Received Get System Info Feb 10 16:45:24 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 10 16:45:24 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 10 16:45:24 volumio-peter volumio[1109]: info: Discovery: Getting this device information Feb 10 16:45:24 volumio-peter volumio[1109]: info: CoreCommandRouter::volumioGetState Feb 10 16:45:24 volumio-peter volumio[1109]: info: CorePlayQueue::getTrack 5 Feb 10 16:45:24 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 10 16:45:31 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Feb 10 16:45:31 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Feb 10 16:45:43 volumio-peter volumio[1109]: info: CoreCommandRouter::getUIConfigOnPlugin Feb 10 16:45:43 volumio-peter volumio[1109]: info: CoreCommandRouter::getUIConfigOnPlugin Feb 10 16:45:43 volumio-peter volumio[1109]: info: Retrieving Cloud Streaming UI Feb 10 16:45:43 volumio-peter volumio[1109]: info: Getting Tidal Cloud Configuration Feb 10 16:45:43 volumio-peter volumio[1109]: info: CoreCommandRouter::getUIConfigOnPlugin Feb 10 16:45:43 volumio-peter volumio[1109]: info: Getting Qobuz Cloud Configuration Feb 10 16:45:43 volumio-peter volumio[1109]: info: Asking plugin for UI Config Feb 10 16:45:43 volumio-peter volumio[1109]: info: CoreCommandRouter::getUIConfigOnPlugin Feb 10 16:45:43 volumio-peter volumio[1109]: info: Getting Spotify Cloud Configuration Feb 10 16:45:43 volumio-peter volumio[1109]: info: Asking plugin for UI Config Feb 10 16:45:43 volumio-peter volumio[1109]: info: CoreCommandRouter::getUIConfigOnPlugin Feb 10 16:45:43 volumio-peter volumio[1109]: info: Saving Spotify Acccount Feb 10 16:45:43 volumio-peter volumio[1109]: info: Got Tidal Cloud Configuration Feb 10 16:45:43 volumio-peter volumio[1109]: info: Got it Feb 10 16:45:43 volumio-peter volumio[1109]: info: Got it Feb 10 16:45:43 volumio-peter volumio[1109]: error: Could not retrieve Spotify Config from plugin Spotify: no section found Feb 10 16:45:43 volumio-peter volumio[1109]: info: CoreCommandRouter::getUIConfigOnPlugin Feb 10 16:45:43 volumio-peter volumio[1109]: error: Error retrieving Highresaudio conf: TypeError: Cannot read properties of undefined (reading 'onSave') Feb 10 16:45:44 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Feb 10 16:45:44 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Feb 10 16:45:44 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Feb 10 16:45:44 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Feb 10 16:45:44 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 10 16:45:44 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 10 16:45:44 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 10 16:45:44 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 10 16:45:44 volumio-peter volumio[1109]: info: CoreCommandRouter::volumioGetBrowseSources Feb 10 16:45:44 volumio-peter volumio[1109]: info: CoreCommandRouter::volumioGetBrowseSources Feb 10 16:45:44 volumio-peter volumio[1109]: info: CoreCommandRouter::volumioGetBrowseSources Feb 10 16:45:44 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Feb 10 16:45:44 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: networkfs , listShares Feb 10 16:45:46 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: networkfs , discoverShares Feb 10 16:45:46 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , browseForService Feb 10 16:45:48 volumio-peter volumio[1109]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Feb 10 16:45:51 volumio-peter volumio[1109]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 10 16:45:51 volumio-peter volumio[1109]: Error: dns service error: unknown Feb 10 16:45:51 volumio-peter volumio[1109]: at MDNSService.on_resolver_done (/volumio/node_modules/mdns/lib/resolver_sequence_tasks.js:19:30) Feb 10 16:45:51 volumio-peter volumio[1109]: at MDNSService.self.watcher.callback (/volumio/node_modules/mdns/lib/mdns_service.js:18:40) { Feb 10 16:45:51 volumio-peter volumio[1109]: errorCode: -65537 Feb 10 16:45:51 volumio-peter volumio[1109]: } Feb 10 16:45:51 volumio-peter volumio[1109]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 10 16:45:53 volumio-peter go-librespot[1529]: time="2026-02-10T16:45:53+01:00" level=trace msg="sent dealer ping" Feb 10 16:45:53 volumio-peter go-librespot[1529]: time="2026-02-10T16:45:53+01:00" level=trace msg="received dealer pong" Feb 10 16:45:57 volumio-peter sudo[1950]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-02-10 16:44' Feb 10 16:45:57 volumio-peter sudo[1950]: 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="a78d359cf1dc63ac74e9d151015afd30d31a709a" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="c1ffe93b2136013fc1b5903a4ed7e3f34e0a7bec" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu Feb 5 14:07:07 UTC 2026" VOLUMIO_VERSION="4.096" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="5e37060f9823263a753eb5e84030104f"