Dec 23 18:49:15 volumio-c2 go-librespot[1591]: time="2025-12-23T18:49:15+01:00" level=trace msg="sent dealer ping" Dec 23 18:49:15 volumio-c2 go-librespot[1591]: time="2025-12-23T18:49:15+01:00" level=trace msg="received dealer pong" Dec 23 18:49:21 volumio-c2 volumio[1271]: verbose: New Socket.io Connection to 192.168.1.39 from 192.168.1.37 UA: Mozilla/5.0 (Linux; Android 16; A024 Build/BQ2A.250721.001-BP2A.250605.031.A3; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/143.0.7499.116 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 8 Dec 23 18:49:21 volumio-c2 volumio[1271]: info: CoreCommandRouter::volumioGetState Dec 23 18:49:21 volumio-c2 volumio[1271]: info: CorePlayQueue::getTrack 0 Dec 23 18:49:21 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Dec 23 18:49:21 volumio-c2 volumio[1271]: info: Listing playlists Dec 23 18:49:21 volumio-c2 volumio[1271]: info: CoreCommandRouter::volumioGetQueue Dec 23 18:49:21 volumio-c2 volumio[1271]: info: CoreStateMachine::getQueue Dec 23 18:49:21 volumio-c2 volumio[1271]: info: CorePlayQueue::getQueue Dec 23 18:49:21 volumio-c2 volumio[1271]: info: CoreCommandRouter::volumioGetVisibleSources Dec 23 18:49:21 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 23 18:49:24 volumio-c2 volumio[1271]: info: CoreCommandRouter::volumioPlay Dec 23 18:49:24 volumio-c2 volumio[1271]: info: CoreStateMachine::play index undefined Dec 23 18:49:24 volumio-c2 volumio[1271]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 23 18:49:24 volumio-c2 volumio[1271]: info: CorePlayQueue::getTrack 0 Dec 23 18:49:24 volumio-c2 volumio[1271]: info: CoreStateMachine::startPlaybackTimer Dec 23 18:49:24 volumio-c2 volumio[1271]: info: CorePlayQueue::getTrack 0 Dec 23 18:49:24 volumio-c2 volumio[1271]: info: [1766512164184] ControllerSpotify::clearAddPlayTrack Dec 23 18:49:24 volumio-c2 volumio[1271]: info: Sending Spotify command with payload to local API: /player/play Dec 23 18:49:24 volumio-c2 go-librespot[1591]: time="2025-12-23T18:49:24+01:00" level=debug msg="resolved context of track" uri="spotify:track:2FRnf9qhLbvw8fu4IBXx78" Dec 23 18:49:24 volumio-c2 go-librespot[1591]: time="2025-12-23T18:49:24+01:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:2FRnf9qhLbvw8fu4IBXx78" Dec 23 18:49:24 volumio-c2 go-librespot[1591]: time="2025-12-23T18:49:24+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:2FRnf9qhLbvw8fu4IBXx78" Dec 23 18:49:24 volumio-c2 go-librespot[1591]: time="2025-12-23T18:49:24+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 23 18:49:24 volumio-c2 go-librespot[1591]: time="2025-12-23T18:49:24+01:00" level=trace msg="emitting websocket event: will_play" Dec 23 18:49:24 volumio-c2 volumio[1271]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:2FRnf9qhLbvw8fu4IBXx78","uri":"spotify:track:2FRnf9qhLbvw8fu4IBXx78","play_origin":"go-librespot"}} Dec 23 18:49:24 volumio-c2 go-librespot[1591]: time="2025-12-23T18:49:24+01:00" level=debug msg="selected format OGG_VORBIS_320 (bc4c46dec7eb7cf1e695a0c81c7c37331dd5b1df)" uri="spotify:track:2FRnf9qhLbvw8fu4IBXx78" Dec 23 18:49:24 volumio-c2 go-librespot[1591]: time="2025-12-23T18:49:24+01:00" level=debug msg="requested aes key for file bc4c46dec7eb7cf1e695a0c81c7c37331dd5b1df, gid: 2FRnf9qhLbvw8fu4IBXx78" Dec 23 18:49:24 volumio-c2 go-librespot[1591]: time="2025-12-23T18:49:24+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:2FRnf9qhLbvw8fu4IBXx78: failed retrieving audio key: failed retrieving aes key with code 1" Dec 23 18:49:24 volumio-c2 volumio[1271]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Dec 23 18:49:28 volumio-c2 volumio[1271]: info: CoreCommandRouter::volumioPlay Dec 23 18:49:28 volumio-c2 volumio[1271]: info: CoreStateMachine::play index undefined Dec 23 18:49:28 volumio-c2 volumio[1271]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 23 18:49:28 volumio-c2 volumio[1271]: info: CorePlayQueue::getTrack 0 Dec 23 18:49:28 volumio-c2 volumio[1271]: info: CoreStateMachine::startPlaybackTimer Dec 23 18:49:28 volumio-c2 volumio[1271]: info: CorePlayQueue::getTrack 0 Dec 23 18:49:28 volumio-c2 volumio[1271]: info: [1766512168772] ControllerSpotify::clearAddPlayTrack Dec 23 18:49:28 volumio-c2 volumio[1271]: info: Sending Spotify command with payload to local API: /player/play Dec 23 18:49:28 volumio-c2 go-librespot[1591]: time="2025-12-23T18:49:28+01:00" level=debug msg="resolved context of track" uri="spotify:track:2FRnf9qhLbvw8fu4IBXx78" Dec 23 18:49:28 volumio-c2 go-librespot[1591]: time="2025-12-23T18:49:28+01:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:2FRnf9qhLbvw8fu4IBXx78" Dec 23 18:49:28 volumio-c2 go-librespot[1591]: time="2025-12-23T18:49:28+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:2FRnf9qhLbvw8fu4IBXx78" Dec 23 18:49:29 volumio-c2 go-librespot[1591]: time="2025-12-23T18:49:29+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 23 18:49:29 volumio-c2 go-librespot[1591]: time="2025-12-23T18:49:29+01:00" level=trace msg="emitting websocket event: will_play" Dec 23 18:49:29 volumio-c2 volumio[1271]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:2FRnf9qhLbvw8fu4IBXx78","uri":"spotify:track:2FRnf9qhLbvw8fu4IBXx78","play_origin":"go-librespot"}} Dec 23 18:49:29 volumio-c2 go-librespot[1591]: time="2025-12-23T18:49:29+01:00" level=debug msg="selected format OGG_VORBIS_320 (bc4c46dec7eb7cf1e695a0c81c7c37331dd5b1df)" uri="spotify:track:2FRnf9qhLbvw8fu4IBXx78" Dec 23 18:49:29 volumio-c2 go-librespot[1591]: time="2025-12-23T18:49:29+01:00" level=debug msg="requested aes key for file bc4c46dec7eb7cf1e695a0c81c7c37331dd5b1df, gid: 2FRnf9qhLbvw8fu4IBXx78" Dec 23 18:49:29 volumio-c2 go-librespot[1591]: time="2025-12-23T18:49:29+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:2FRnf9qhLbvw8fu4IBXx78: failed retrieving audio key: failed retrieving aes key with code 1" Dec 23 18:49:29 volumio-c2 volumio[1271]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Dec 23 18:49:31 volumio-c2 volumio[1271]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 23 18:49:31 volumio-c2 volumio[1271]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 23 18:49:31 volumio-c2 volumio[1271]: info: Retrieving Cloud Streaming UI Dec 23 18:49:31 volumio-c2 volumio[1271]: info: Getting Tidal Cloud Configuration Dec 23 18:49:31 volumio-c2 volumio[1271]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 23 18:49:31 volumio-c2 volumio[1271]: info: Getting Qobuz Cloud Configuration Dec 23 18:49:31 volumio-c2 volumio[1271]: info: Asking plugin for UI Config Dec 23 18:49:31 volumio-c2 volumio[1271]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 23 18:49:31 volumio-c2 volumio[1271]: info: Getting Spotify Cloud Configuration Dec 23 18:49:31 volumio-c2 volumio[1271]: info: Asking plugin for UI Config Dec 23 18:49:31 volumio-c2 volumio[1271]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 23 18:49:31 volumio-c2 volumio[1271]: info: Saving Spotify Acccount Dec 23 18:49:31 volumio-c2 volumio[1271]: info: Got Tidal Cloud Configuration Dec 23 18:49:31 volumio-c2 volumio[1271]: info: Got it Dec 23 18:49:31 volumio-c2 volumio[1271]: info: Got it Dec 23 18:49:31 volumio-c2 volumio[1271]: error: Could not retrieve Spotify Config from plugin Spotify: no section found Dec 23 18:49:31 volumio-c2 volumio[1271]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 23 18:49:31 volumio-c2 volumio[1271]: error: Error retrieving Highresaudio conf: TypeError: Cannot read properties of undefined (reading 'onSave') Dec 23 18:49:31 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Dec 23 18:49:31 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Dec 23 18:49:31 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Dec 23 18:49:31 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Dec 23 18:49:31 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 23 18:49:31 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 23 18:49:31 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 23 18:49:31 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 23 18:49:31 volumio-c2 volumio[1271]: info: CoreCommandRouter::volumioGetBrowseSources Dec 23 18:49:31 volumio-c2 volumio[1271]: info: CoreCommandRouter::volumioGetBrowseSources Dec 23 18:49:31 volumio-c2 volumio[1271]: info: CoreCommandRouter::volumioGetBrowseSources Dec 23 18:49:31 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Dec 23 18:49:31 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: networkfs , listShares Dec 23 18:49:34 volumio-c2 volumio[1271]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 23 18:49:34 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Dec 23 18:49:34 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 23 18:49:34 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Dec 23 18:49:34 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 23 18:49:34 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 23 18:49:34 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 23 18:49:34 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 23 18:49:34 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 23 18:49:34 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 23 18:49:34 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 23 18:49:34 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: mpd , getPlaybackMode Dec 23 18:49:34 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Dec 23 18:49:37 volumio-c2 volumio[1271]: info: CALLMETHOD: audio_interface alsa_controller saveAlsaOptions [object Object] Dec 23 18:49:37 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , saveAlsaOptions Dec 23 18:49:37 volumio-c2 volumio[1271]: info: Preparing to save Alsa Options, stopping services first Dec 23 18:49:37 volumio-c2 volumio[1271]: info: CoreCommandRouter::volumioGetState Dec 23 18:49:37 volumio-c2 volumio[1271]: info: CorePlayQueue::getTrack 0 Dec 23 18:49:37 volumio-c2 volumio[1271]: info: CoreCommandRouter::volumioPause Dec 23 18:49:37 volumio-c2 volumio[1271]: info: CoreStateMachine::pause Dec 23 18:49:37 volumio-c2 volumio[1271]: info: Saving Audio Output to: {"output_device":{"value":"0","label":"HDMI Out"},"i2s":false,"i2sid":{"value":"adafruit-max98357","label":"Adafruit MAX98357"}} Dec 23 18:49:37 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Dec 23 18:49:37 volumio-c2 volumio[1271]: info: Enabling PI HDMI Output Dec 23 18:49:37 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Dec 23 18:49:37 volumio-c2 volumio[1271]: info: Found match in Cards Database: setting mixer PCM for card HDMI Out Dec 23 18:49:38 volumio-c2 volumio[1271]: info: CoreCommandRouter::volumioUpdateVolumeSettings Dec 23 18:49:38 volumio-c2 volumio[1271]: info: Updating Volume Controller Parameters: Device: 0 Name: HDMI Out Mixer: PCM Max Vol: 100 Vol Curve; logarithmic Vol Steps: 1 Dec 23 18:49:38 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , setExternalVolume Dec 23 18:49:38 volumio-c2 volumio[1271]: info: Disabling external Volume Control Dec 23 18:49:38 volumio-c2 volumio[1271]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 23 18:49:38 volumio-c2 volumio[1271]: info: Preparing to generate the ALSA configuration file Dec 23 18:49:38 volumio-c2 volumio[1271]: info: Raspberry PI HDMI Output Enabled Dec 23 18:49:38 volumio-c2 sudo[2570]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/sbin/alsactl store Dec 23 18:49:38 volumio-c2 sudo[2570]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 23 18:49:38 volumio-c2 sudo[2570]: pam_unix(sudo:session): session closed for user root Dec 23 18:49:38 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Dec 23 18:49:38 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 23 18:49:38 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Dec 23 18:49:38 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 23 18:49:38 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 23 18:49:38 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 23 18:49:38 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 23 18:49:38 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 23 18:49:38 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 23 18:49:38 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 23 18:49:38 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: mpd , getPlaybackMode Dec 23 18:49:38 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Dec 23 18:49:38 volumio-c2 volumio[1271]: info: VolumeController:: Volume=100 Mute =false Dec 23 18:49:38 volumio-c2 volumio[1271]: info: CoreStateMachine::pushState Dec 23 18:49:38 volumio-c2 volumio[1271]: info: CorePlayQueue::getTrack 0 Dec 23 18:49:38 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 23 18:49:38 volumio-c2 volumio[1271]: info: CoreCommandRouter::volumioPushState Dec 23 18:49:38 volumio-c2 volumio[1271]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Dec 23 18:49:38 volumio-c2 volumio[1271]: SPOTIFY: SPOTIFY VOLUME 99 Dec 23 18:49:38 volumio-c2 volumio[1271]: SPOTIFY: VOLUMIO VOLUME 100 Dec 23 18:49:38 volumio-c2 volumio[1271]: SPOTIFY: DELTA VOLUME ENOUGH: false Dec 23 18:49:38 volumio-c2 volumio[1271]: info: Alsa Settings successfully stored Dec 23 18:49:38 volumio-c2 volumio[1271]: info: Asound.conf file written Dec 23 18:49:38 volumio-c2 sudo[2584]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf Dec 23 18:49:38 volumio-c2 sudo[2584]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 23 18:49:38 volumio-c2 sudo[2584]: pam_unix(sudo:session): session closed for user root Dec 23 18:49:38 volumio-c2 volumio[1271]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:0 use case configuration -2 Dec 23 18:49:38 volumio-c2 volumio[1271]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:1 use case configuration -2 Dec 23 18:49:38 volumio-c2 volumio[1271]: info: Output device has changed, restarting MPD Dec 23 18:49:38 volumio-c2 volumio[1271]: info: Output device has changed, restarting Shairport Sync Dec 23 18:49:38 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 23 18:49:38 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 23 18:49:38 volumio-c2 sudo[2590]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 23 18:49:38 volumio-c2 sudo[2590]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 23 18:49:38 volumio-c2 sudo[2590]: pam_unix(sudo:session): session closed for user root Dec 23 18:49:38 volumio-c2 sudo[2593]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 23 18:49:38 volumio-c2 sudo[2593]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 23 18:49:38 volumio-c2 volumio[1271]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 23 18:49:38 volumio-c2 volumio[1271]: info: Output device has changed, restarting MPD Dec 23 18:49:38 volumio-c2 volumio[1271]: info: Output device has changed, restarting Shairport Sync Dec 23 18:49:38 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 23 18:49:38 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 23 18:49:38 volumio-c2 sudo[2600]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 23 18:49:38 volumio-c2 sudo[2600]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 23 18:49:38 volumio-c2 systemd[1]: Stopping mpd.service - Music Player Daemon... Dec 23 18:49:38 volumio-c2 sudo[2600]: pam_unix(sudo:session): session closed for user root Dec 23 18:49:38 volumio-c2 sudo[2602]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 23 18:49:38 volumio-c2 sudo[2602]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 23 18:49:38 volumio-c2 volumio[1271]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 23 18:49:38 volumio-c2 volumio[1271]: info: MPD Permissions set Dec 23 18:49:38 volumio-c2 volumio[1271]: info: MPD Permissions set Dec 23 18:49:38 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 23 18:49:38 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 23 18:49:38 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 23 18:49:38 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 23 18:49:38 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 23 18:49:38 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 23 18:49:38 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 23 18:49:38 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 23 18:49:38 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 23 18:49:38 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 23 18:49:38 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 23 18:49:38 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 23 18:49:38 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 23 18:49:38 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 23 18:49:38 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 23 18:49:38 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 23 18:49:38 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 23 18:49:38 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 23 18:49:38 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 23 18:49:38 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 23 18:49:38 volumio-c2 volumio[1271]: info: Starting Shairport Sync Dec 23 18:49:38 volumio-c2 volumio[1271]: info: Starting Shairport Sync Dec 23 18:49:38 volumio-c2 sudo[2622]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 23 18:49:38 volumio-c2 sudo[2623]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 23 18:49:38 volumio-c2 sudo[2622]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 23 18:49:38 volumio-c2 sudo[2623]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 23 18:49:38 volumio-c2 systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 23 18:49:38 volumio-c2 systemd[1]: shairport-sync.service: Deactivated successfully. Dec 23 18:49:38 volumio-c2 systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 23 18:49:38 volumio-c2 systemd[1]: shairport-sync.service: Consumed 2.879s CPU time. Dec 23 18:49:38 volumio-c2 systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 23 18:49:38 volumio-c2 sudo[2622]: pam_unix(sudo:session): session closed for user root Dec 23 18:49:38 volumio-c2 sudo[2623]: pam_unix(sudo:session): session closed for user root Dec 23 18:49:38 volumio-c2 volumio[1271]: info: Shairport-Sync Started Dec 23 18:49:38 volumio-c2 volumio[1271]: info: Shairport-Sync Started Dec 23 18:49:39 volumio-c2 volumio[1271]: info: CALLMETHOD: audio_interface alsa_controller saveAlsaOptions [object Object] Dec 23 18:49:39 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , saveAlsaOptions Dec 23 18:49:39 volumio-c2 volumio[1271]: info: Preparing to save Alsa Options, stopping services first Dec 23 18:49:39 volumio-c2 volumio[1271]: info: CoreCommandRouter::volumioGetState Dec 23 18:49:39 volumio-c2 volumio[1271]: info: CorePlayQueue::getTrack 0 Dec 23 18:49:39 volumio-c2 volumio[1271]: info: CoreCommandRouter::volumioPause Dec 23 18:49:39 volumio-c2 volumio[1271]: info: CoreStateMachine::pause Dec 23 18:49:39 volumio-c2 volumio[1271]: info: Saving Audio Output to: {"output_device":{"value":"0","label":"HDMI Out"},"i2s":false,"i2sid":{"value":"adafruit-max98357","label":"Adafruit MAX98357"}} Dec 23 18:49:39 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Dec 23 18:49:39 volumio-c2 volumio[1271]: info: Enabling PI HDMI Output Dec 23 18:49:39 volumio-c2 systemd[1]: mpd.service: Deactivated successfully. Dec 23 18:49:39 volumio-c2 systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 23 18:49:39 volumio-c2 systemd[1]: mpd.service: Consumed 5.889s CPU time. Dec 23 18:49:39 volumio-c2 systemd[1]: mpd.socket: Deactivated successfully. Dec 23 18:49:39 volumio-c2 systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 23 18:49:39 volumio-c2 systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 23 18:49:39 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Dec 23 18:49:39 volumio-c2 volumio[1271]: info: Found match in Cards Database: setting mixer PCM for card HDMI Out Dec 23 18:49:39 volumio-c2 systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 23 18:49:39 volumio-c2 systemd[1]: Starting mpd.service - Music Player Daemon... Dec 23 18:49:39 volumio-c2 volumio[1271]: info: CoreCommandRouter::volumioUpdateVolumeSettings Dec 23 18:49:39 volumio-c2 volumio[1271]: info: Updating Volume Controller Parameters: Device: 0 Name: HDMI Out Mixer: PCM Max Vol: 100 Vol Curve; logarithmic Vol Steps: 1 Dec 23 18:49:39 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , setExternalVolume Dec 23 18:49:39 volumio-c2 volumio[1271]: info: Disabling external Volume Control Dec 23 18:49:39 volumio-c2 volumio[1271]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 23 18:49:39 volumio-c2 volumio[1271]: info: Preparing to generate the ALSA configuration file Dec 23 18:49:39 volumio-c2 volumio[1271]: info: Raspberry PI HDMI Output Enabled Dec 23 18:49:39 volumio-c2 volumio[1271]: info: VolumeController:: Volume=100 Mute =false Dec 23 18:49:39 volumio-c2 volumio[1271]: info: CoreStateMachine::pushState Dec 23 18:49:39 volumio-c2 volumio[1271]: info: CorePlayQueue::getTrack 0 Dec 23 18:49:39 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 23 18:49:39 volumio-c2 volumio[1271]: info: CoreCommandRouter::volumioPushState Dec 23 18:49:39 volumio-c2 sudo[2660]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/sbin/alsactl store Dec 23 18:49:39 volumio-c2 sudo[2660]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 23 18:49:39 volumio-c2 sudo[2660]: pam_unix(sudo:session): session closed for user root Dec 23 18:49:39 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Dec 23 18:49:39 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 23 18:49:39 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Dec 23 18:49:39 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 23 18:49:39 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 23 18:49:39 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 23 18:49:39 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 23 18:49:39 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 23 18:49:39 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 23 18:49:39 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 23 18:49:39 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: mpd , getPlaybackMode Dec 23 18:49:39 volumio-c2 sudo[2656]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 23 18:49:39 volumio-c2 sudo[2656]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 23 18:49:39 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Dec 23 18:49:39 volumio-c2 volumio[1271]: info: Asound.conf file unchanged, so no further update is needed Dec 23 18:49:39 volumio-c2 volumio[1271]: info: Output device has changed, restarting MPD Dec 23 18:49:39 volumio-c2 sudo[2656]: pam_unix(sudo:session): session closed for user root Dec 23 18:49:39 volumio-c2 volumio[1271]: info: Output device has changed, restarting Shairport Sync Dec 23 18:49:39 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 23 18:49:39 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 23 18:49:39 volumio-c2 sudo[2676]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 23 18:49:39 volumio-c2 sudo[2675]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 23 18:49:39 volumio-c2 sudo[2675]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 23 18:49:39 volumio-c2 sudo[2676]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 23 18:49:39 volumio-c2 sudo[2675]: pam_unix(sudo:session): session closed for user root Dec 23 18:49:39 volumio-c2 volumio[1271]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 23 18:49:39 volumio-c2 volumio[1271]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Dec 23 18:49:39 volumio-c2 volumio[1271]: SPOTIFY: SPOTIFY VOLUME 99 Dec 23 18:49:39 volumio-c2 volumio[1271]: SPOTIFY: VOLUMIO VOLUME 100 Dec 23 18:49:39 volumio-c2 volumio[1271]: SPOTIFY: DELTA VOLUME ENOUGH: false Dec 23 18:49:39 volumio-c2 volumio[1271]: info: MPD Permissions set Dec 23 18:49:39 volumio-c2 volumio[1271]: info: Alsa Settings successfully stored Dec 23 18:49:39 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 23 18:49:39 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 23 18:49:39 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 23 18:49:39 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 23 18:49:39 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 23 18:49:39 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 23 18:49:39 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 23 18:49:39 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 23 18:49:39 volumio-c2 systemd[1]: mpd.service: Deactivated successfully. Dec 23 18:49:39 volumio-c2 systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 23 18:49:39 volumio-c2 systemd[1]: mpd.socket: Deactivated successfully. Dec 23 18:49:39 volumio-c2 systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 23 18:49:39 volumio-c2 systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 23 18:49:39 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 23 18:49:39 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 23 18:49:39 volumio-c2 volumio[1271]: info: Starting Shairport Sync Dec 23 18:49:39 volumio-c2 sudo[2690]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 23 18:49:39 volumio-c2 systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 23 18:49:39 volumio-c2 sudo[2690]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 23 18:49:39 volumio-c2 systemd[1]: Starting mpd.service - Music Player Daemon... Dec 23 18:49:39 volumio-c2 systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 23 18:49:39 volumio-c2 systemd[1]: shairport-sync.service: Deactivated successfully. Dec 23 18:49:39 volumio-c2 systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 23 18:49:39 volumio-c2 systemd[1]: shairport-sync.service: Consumed 1.244s CPU time. Dec 23 18:49:39 volumio-c2 systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 23 18:49:39 volumio-c2 sudo[2690]: pam_unix(sudo:session): session closed for user root Dec 23 18:49:39 volumio-c2 volumio[1271]: info: Shairport-Sync Started Dec 23 18:49:40 volumio-c2 sudo[2692]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 23 18:49:40 volumio-c2 sudo[2692]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 23 18:49:40 volumio-c2 sudo[2692]: pam_unix(sudo:session): session closed for user root Dec 23 18:49:41 volumio-c2 volumio[1271]: info: CoreCommandRouter::volumioPlay Dec 23 18:49:41 volumio-c2 volumio[1271]: info: CoreStateMachine::play index undefined Dec 23 18:49:41 volumio-c2 volumio[1271]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 23 18:49:41 volumio-c2 volumio[1271]: info: CorePlayQueue::getTrack 0 Dec 23 18:49:41 volumio-c2 volumio[1271]: info: CoreStateMachine::startPlaybackTimer Dec 23 18:49:41 volumio-c2 volumio[1271]: info: CorePlayQueue::getTrack 0 Dec 23 18:49:41 volumio-c2 volumio[1271]: info: [1766512181188] ControllerSpotify::clearAddPlayTrack Dec 23 18:49:41 volumio-c2 volumio[1271]: info: Sending Spotify command with payload to local API: /player/play Dec 23 18:49:41 volumio-c2 go-librespot[1591]: time="2025-12-23T18:49:41+01:00" level=debug msg="resolved context of track" uri="spotify:track:2FRnf9qhLbvw8fu4IBXx78" Dec 23 18:49:41 volumio-c2 go-librespot[1591]: time="2025-12-23T18:49:41+01:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:2FRnf9qhLbvw8fu4IBXx78" Dec 23 18:49:41 volumio-c2 go-librespot[1591]: time="2025-12-23T18:49:41+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:2FRnf9qhLbvw8fu4IBXx78" Dec 23 18:49:41 volumio-c2 go-librespot[1591]: time="2025-12-23T18:49:41+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 23 18:49:41 volumio-c2 go-librespot[1591]: time="2025-12-23T18:49:41+01:00" level=trace msg="emitting websocket event: will_play" Dec 23 18:49:41 volumio-c2 volumio[1271]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:2FRnf9qhLbvw8fu4IBXx78","uri":"spotify:track:2FRnf9qhLbvw8fu4IBXx78","play_origin":"go-librespot"}} Dec 23 18:49:41 volumio-c2 go-librespot[1591]: time="2025-12-23T18:49:41+01:00" level=debug msg="selected format OGG_VORBIS_320 (bc4c46dec7eb7cf1e695a0c81c7c37331dd5b1df)" uri="spotify:track:2FRnf9qhLbvw8fu4IBXx78" Dec 23 18:49:41 volumio-c2 go-librespot[1591]: time="2025-12-23T18:49:41+01:00" level=debug msg="requested aes key for file bc4c46dec7eb7cf1e695a0c81c7c37331dd5b1df, gid: 2FRnf9qhLbvw8fu4IBXx78" Dec 23 18:49:41 volumio-c2 go-librespot[1591]: time="2025-12-23T18:49:41+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:2FRnf9qhLbvw8fu4IBXx78: failed retrieving audio key: failed retrieving aes key with code 1" Dec 23 18:49:41 volumio-c2 volumio[1271]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Dec 23 18:49:42 volumio-c2 volumio[1271]: info: CoreCommandRouter::volumioRetrieveVolumeLevels Dec 23 18:49:42 volumio-c2 volumio[1271]: info: CoreStateMachine::getcurrentVolume Dec 23 18:49:42 volumio-c2 volumio[1271]: info: CoreCommandRouter::volumioRetrievevolume Dec 23 18:49:42 volumio-c2 volumio[1271]: info: VolumeController:: Volume=100 Mute =false Dec 23 18:49:42 volumio-c2 volumio[1271]: info: CoreStateMachine::pushState Dec 23 18:49:42 volumio-c2 volumio[1271]: info: CorePlayQueue::getTrack 0 Dec 23 18:49:42 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 23 18:49:42 volumio-c2 volumio[1271]: info: CoreCommandRouter::volumioPushState Dec 23 18:49:42 volumio-c2 volumio[1271]: info: CoreStateMachine::updateTrackBlock Dec 23 18:49:42 volumio-c2 volumio[1271]: info: CorePlayQueue::getTrackBlock Dec 23 18:49:42 volumio-c2 volumio[1271]: info: CoreCommandRouter::volumioRetrievevolume Dec 23 18:49:42 volumio-c2 volumio[1271]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Dec 23 18:49:42 volumio-c2 volumio[1271]: SPOTIFY: SPOTIFY VOLUME 99 Dec 23 18:49:42 volumio-c2 volumio[1271]: SPOTIFY: VOLUMIO VOLUME 100 Dec 23 18:49:42 volumio-c2 volumio[1271]: SPOTIFY: DELTA VOLUME ENOUGH: false Dec 23 18:49:42 volumio-c2 volumio[1271]: info: VolumeController:: Volume=100 Mute =false Dec 23 18:49:42 volumio-c2 volumio[1271]: info: CoreStateMachine::pushState Dec 23 18:49:42 volumio-c2 volumio[1271]: info: CorePlayQueue::getTrack 0 Dec 23 18:49:42 volumio-c2 volumio[1271]: info: CoreCommandRouter::volumioPushState Dec 23 18:49:42 volumio-c2 volumio[1271]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Dec 23 18:49:42 volumio-c2 volumio[1271]: SPOTIFY: SPOTIFY VOLUME 99 Dec 23 18:49:42 volumio-c2 volumio[1271]: SPOTIFY: VOLUMIO VOLUME 100 Dec 23 18:49:42 volumio-c2 volumio[1271]: SPOTIFY: DELTA VOLUME ENOUGH: false Dec 23 18:49:43 volumio-c2 mpd[2710]: 2025-12-23T18:49:43 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 23 18:49:43 volumio-c2 systemd[1]: Started mpd.service - Music Player Daemon. Dec 23 18:49:43 volumio-c2 sudo[2676]: pam_unix(sudo:session): session closed for user root Dec 23 18:49:43 volumio-c2 sudo[2602]: pam_unix(sudo:session): session closed for user root Dec 23 18:49:43 volumio-c2 sudo[2593]: pam_unix(sudo:session): session closed for user root Dec 23 18:49:43 volumio-c2 volumio[1271]: error: MPD error: The expression evaluated to a falsy value: Dec 23 18:49:43 volumio-c2 volumio[1271]: assert.ok(self.idling) Dec 23 18:49:43 volumio-c2 volumio[1271]: error: The expression evaluated to a falsy value: Dec 23 18:49:43 volumio-c2 volumio[1271]: assert.ok(self.idling) Dec 23 18:49:43 volumio-c2 volumio[1271]: error: MPD error: The expression evaluated to a falsy value: Dec 23 18:49:43 volumio-c2 volumio[1271]: assert.ok(self.idling) Dec 23 18:49:43 volumio-c2 volumio[1271]: error: The expression evaluated to a falsy value: Dec 23 18:49:43 volumio-c2 volumio[1271]: assert.ok(self.idling) Dec 23 18:49:43 volumio-c2 volumio[1271]: error: updateQueue error: null Dec 23 18:49:43 volumio-c2 volumio[1271]: info: CoreCommandRouter::volumioRetrieveVolumeLevels Dec 23 18:49:43 volumio-c2 volumio[1271]: info: CoreStateMachine::getcurrentVolume Dec 23 18:49:43 volumio-c2 volumio[1271]: info: CoreCommandRouter::volumioRetrievevolume Dec 23 18:49:43 volumio-c2 volumio[1271]: info: VolumeController:: Volume=100 Mute =false Dec 23 18:49:43 volumio-c2 volumio[1271]: info: CoreStateMachine::pushState Dec 23 18:49:43 volumio-c2 volumio[1271]: info: CorePlayQueue::getTrack 0 Dec 23 18:49:43 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 23 18:49:43 volumio-c2 volumio[1271]: info: CoreCommandRouter::volumioPushState Dec 23 18:49:43 volumio-c2 volumio[1271]: info: CoreStateMachine::updateTrackBlock Dec 23 18:49:43 volumio-c2 volumio[1271]: info: CorePlayQueue::getTrackBlock Dec 23 18:49:43 volumio-c2 volumio[1271]: info: CoreCommandRouter::volumioRetrievevolume Dec 23 18:49:43 volumio-c2 volumio[1271]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Dec 23 18:49:43 volumio-c2 volumio[1271]: SPOTIFY: SPOTIFY VOLUME 99 Dec 23 18:49:43 volumio-c2 volumio[1271]: SPOTIFY: VOLUMIO VOLUME 100 Dec 23 18:49:43 volumio-c2 volumio[1271]: SPOTIFY: DELTA VOLUME ENOUGH: false Dec 23 18:49:43 volumio-c2 volumio[1271]: info: VolumeController:: Volume=100 Mute =false Dec 23 18:49:43 volumio-c2 volumio[1271]: info: CoreStateMachine::pushState Dec 23 18:49:43 volumio-c2 volumio[1271]: info: CorePlayQueue::getTrack 0 Dec 23 18:49:43 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 23 18:49:43 volumio-c2 volumio[1271]: info: CoreCommandRouter::volumioPushState Dec 23 18:49:43 volumio-c2 volumio[1271]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Dec 23 18:49:43 volumio-c2 volumio[1271]: SPOTIFY: SPOTIFY VOLUME 99 Dec 23 18:49:43 volumio-c2 volumio[1271]: SPOTIFY: VOLUMIO VOLUME 100 Dec 23 18:49:43 volumio-c2 volumio[1271]: SPOTIFY: DELTA VOLUME ENOUGH: false Dec 23 18:49:45 volumio-c2 volumio[1271]: info: CoreCommandRouter::volumioPlay Dec 23 18:49:45 volumio-c2 volumio[1271]: info: CoreStateMachine::play index undefined Dec 23 18:49:45 volumio-c2 volumio[1271]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 23 18:49:45 volumio-c2 volumio[1271]: info: CorePlayQueue::getTrack 0 Dec 23 18:49:45 volumio-c2 volumio[1271]: info: CoreStateMachine::startPlaybackTimer Dec 23 18:49:45 volumio-c2 volumio[1271]: info: CorePlayQueue::getTrack 0 Dec 23 18:49:45 volumio-c2 volumio[1271]: info: [1766512185138] ControllerSpotify::clearAddPlayTrack Dec 23 18:49:45 volumio-c2 volumio[1271]: info: Sending Spotify command with payload to local API: /player/play Dec 23 18:49:45 volumio-c2 go-librespot[1591]: time="2025-12-23T18:49:45+01:00" level=debug msg="resolved context of track" uri="spotify:track:2FRnf9qhLbvw8fu4IBXx78" Dec 23 18:49:45 volumio-c2 go-librespot[1591]: time="2025-12-23T18:49:45+01:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:2FRnf9qhLbvw8fu4IBXx78" Dec 23 18:49:45 volumio-c2 go-librespot[1591]: time="2025-12-23T18:49:45+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:2FRnf9qhLbvw8fu4IBXx78" Dec 23 18:49:45 volumio-c2 go-librespot[1591]: time="2025-12-23T18:49:45+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 23 18:49:45 volumio-c2 go-librespot[1591]: time="2025-12-23T18:49:45+01:00" level=trace msg="emitting websocket event: will_play" Dec 23 18:49:45 volumio-c2 volumio[1271]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:2FRnf9qhLbvw8fu4IBXx78","uri":"spotify:track:2FRnf9qhLbvw8fu4IBXx78","play_origin":"go-librespot"}} Dec 23 18:49:45 volumio-c2 go-librespot[1591]: time="2025-12-23T18:49:45+01:00" level=debug msg="selected format OGG_VORBIS_320 (bc4c46dec7eb7cf1e695a0c81c7c37331dd5b1df)" uri="spotify:track:2FRnf9qhLbvw8fu4IBXx78" Dec 23 18:49:45 volumio-c2 go-librespot[1591]: time="2025-12-23T18:49:45+01:00" level=debug msg="requested aes key for file bc4c46dec7eb7cf1e695a0c81c7c37331dd5b1df, gid: 2FRnf9qhLbvw8fu4IBXx78" Dec 23 18:49:45 volumio-c2 go-librespot[1591]: time="2025-12-23T18:49:45+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:2FRnf9qhLbvw8fu4IBXx78: failed retrieving audio key: failed retrieving aes key with code 1" Dec 23 18:49:45 volumio-c2 volumio[1271]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Dec 23 18:49:45 volumio-c2 go-librespot[1591]: time="2025-12-23T18:49:45+01:00" level=trace msg="received accesspoint ping" Dec 23 18:49:45 volumio-c2 go-librespot[1591]: time="2025-12-23T18:49:45+01:00" level=trace msg="received accesspoint pong ack" Dec 23 18:49:45 volumio-c2 go-librespot[1591]: time="2025-12-23T18:49:45+01:00" level=trace msg="sent dealer ping" Dec 23 18:49:45 volumio-c2 go-librespot[1591]: time="2025-12-23T18:49:45+01:00" level=trace msg="received dealer pong" Dec 23 18:49:46 volumio-c2 sudo[2737]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 23 18:49:46 volumio-c2 sudo[2737]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 23 18:49:46 volumio-c2 sudo[2739]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 23 18:49:46 volumio-c2 sudo[2739]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 23 18:49:46 volumio-c2 sudo[2742]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 23 18:49:46 volumio-c2 sudo[2742]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 23 18:49:46 volumio-c2 systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 23 18:49:46 volumio-c2 systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 23 18:49:46 volumio-c2 systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 23 18:49:46 volumio-c2 systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 23 18:49:46 volumio-c2 sudo[2737]: pam_unix(sudo:session): session closed for user root Dec 23 18:49:46 volumio-c2 mpd_monitor.sh[2745]: MPD Monitor Service: Starting MPD Monitor Service Dec 23 18:49:46 volumio-c2 sudo[2739]: pam_unix(sudo:session): session closed for user root Dec 23 18:49:46 volumio-c2 sudo[2742]: pam_unix(sudo:session): session closed for user root Dec 23 18:49:46 volumio-c2 volumio[1271]: info: Successfully started MPD Monitor Dec 23 18:49:46 volumio-c2 volumio[1271]: info: Successfully started MPD Monitor Dec 23 18:49:46 volumio-c2 volumio[1271]: info: Successfully started MPD Monitor Dec 23 18:49:46 volumio-c2 sudo[2751]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 23 18:49:46 volumio-c2 sudo[2751]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 23 18:49:46 volumio-c2 sudo[2747]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 23 18:49:46 volumio-c2 sudo[2747]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 23 18:49:46 volumio-c2 sudo[2751]: pam_unix(sudo:session): session closed for user root Dec 23 18:49:46 volumio-c2 sudo[2747]: pam_unix(sudo:session): session closed for user root Dec 23 18:49:46 volumio-c2 volumio[1271]: verbose: New Socket.io Connection to 192.168.1.39 from 192.168.1.254 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/143.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 8 Dec 23 18:49:46 volumio-c2 sudo[2756]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 23 18:49:46 volumio-c2 sudo[2756]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 23 18:49:46 volumio-c2 sudo[2756]: pam_unix(sudo:session): session closed for user root Dec 23 18:49:46 volumio-c2 sudo[2758]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 23 18:49:46 volumio-c2 sudo[2758]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 23 18:49:46 volumio-c2 sudo[2758]: pam_unix(sudo:session): session closed for user root Dec 23 18:49:46 volumio-c2 volumio[1271]: verbose: New Socket.io Connection to 192.168.1.39 from 192.168.1.254 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/143.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 8 Dec 23 18:49:46 volumio-c2 volumio[1271]: info: CoreCommandRouter::volumioGetState Dec 23 18:49:46 volumio-c2 volumio[1271]: info: CorePlayQueue::getTrack 0 Dec 23 18:49:46 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Dec 23 18:49:46 volumio-c2 volumio[1271]: info: Listing playlists Dec 23 18:49:46 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Dec 23 18:49:46 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Dec 23 18:49:46 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Dec 23 18:49:46 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Dec 23 18:49:48 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 23 18:49:48 volumio-c2 volumio[1271]: info: Received Get System Info Dec 23 18:49:48 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 23 18:49:48 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 23 18:49:48 volumio-c2 volumio[1271]: info: Discovery: Getting this device information Dec 23 18:49:48 volumio-c2 volumio[1271]: info: CoreCommandRouter::volumioGetState Dec 23 18:49:48 volumio-c2 volumio[1271]: info: CorePlayQueue::getTrack 0 Dec 23 18:49:48 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 23 18:49:49 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 23 18:49:49 volumio-c2 volumio[1271]: info: Received Get System Info Dec 23 18:49:49 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 23 18:49:49 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 23 18:49:49 volumio-c2 volumio[1271]: info: Discovery: Getting this device information Dec 23 18:49:49 volumio-c2 volumio[1271]: info: CoreCommandRouter::volumioGetState Dec 23 18:49:49 volumio-c2 volumio[1271]: info: CorePlayQueue::getTrack 0 Dec 23 18:49:49 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 23 18:49:55 volumio-c2 volumio[1271]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 23 18:49:55 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Dec 23 18:49:55 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Dec 23 18:49:55 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Dec 23 18:49:55 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: appearance , getAvailableUIs Dec 23 18:49:55 volumio-c2 volumio[1271]: info: Received Get System Version Dec 23 18:49:55 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 23 18:49:55 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: appearance , getBackgrounds Dec 23 18:50:04 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Dec 23 18:50:04 volumio-c2 volumio[1271]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Dec 23 18:50:04 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Dec 23 18:50:04 volumio-c2 volumio[1271]: info: Received Get System Version Dec 23 18:50:04 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 23 18:50:04 volumio-c2 volumio[1271]: info: Received Get System Info Dec 23 18:50:04 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 23 18:50:04 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 23 18:50:04 volumio-c2 volumio[1271]: info: Discovery: Getting this device information Dec 23 18:50:04 volumio-c2 volumio[1271]: info: CoreCommandRouter::volumioGetState Dec 23 18:50:04 volumio-c2 volumio[1271]: info: CorePlayQueue::getTrack 0 Dec 23 18:50:04 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 23 18:50:11 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: appearance , setBackgrounds Dec 23 18:50:11 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: appearance , getBackgrounds Dec 23 18:50:11 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Dec 23 18:50:12 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: appearance , setBackgrounds Dec 23 18:50:12 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: appearance , getBackgrounds Dec 23 18:50:12 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Dec 23 18:50:15 volumio-c2 sudo[2813]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 23 18:50:15 volumio-c2 sudo[2813]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 23 18:50:15 volumio-c2 sudo[2813]: pam_unix(sudo:session): session closed for user root Dec 23 18:50:15 volumio-c2 sudo[2815]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 23 18:50:15 volumio-c2 sudo[2815]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 23 18:50:15 volumio-c2 sudo[2815]: pam_unix(sudo:session): session closed for user root Dec 23 18:50:15 volumio-c2 volumio[1271]: verbose: New Socket.io Connection to 192.168.1.39 from 192.168.1.254 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/143.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 7 Dec 23 18:50:15 volumio-c2 sudo[2819]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 23 18:50:15 volumio-c2 sudo[2819]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 23 18:50:15 volumio-c2 sudo[2819]: pam_unix(sudo:session): session closed for user root Dec 23 18:50:15 volumio-c2 sudo[2821]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 23 18:50:15 volumio-c2 sudo[2821]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 23 18:50:15 volumio-c2 sudo[2821]: pam_unix(sudo:session): session closed for user root Dec 23 18:50:15 volumio-c2 volumio[1271]: verbose: New Socket.io Connection to 192.168.1.39 from 192.168.1.254 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/143.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 7 Dec 23 18:50:15 volumio-c2 volumio[1271]: info: CoreCommandRouter::volumioGetState Dec 23 18:50:15 volumio-c2 volumio[1271]: info: CorePlayQueue::getTrack 0 Dec 23 18:50:15 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Dec 23 18:50:15 volumio-c2 volumio[1271]: info: Listing playlists Dec 23 18:50:15 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Dec 23 18:50:15 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Dec 23 18:50:15 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Dec 23 18:50:15 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Dec 23 18:50:15 volumio-c2 go-librespot[1591]: time="2025-12-23T18:50:15+01:00" level=trace msg="sent dealer ping" Dec 23 18:50:15 volumio-c2 go-librespot[1591]: time="2025-12-23T18:50:15+01:00" level=trace msg="received dealer pong" Dec 23 18:50:17 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 23 18:50:17 volumio-c2 volumio[1271]: info: Received Get System Info Dec 23 18:50:17 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 23 18:50:17 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 23 18:50:17 volumio-c2 volumio[1271]: info: Discovery: Getting this device information Dec 23 18:50:17 volumio-c2 volumio[1271]: info: CoreCommandRouter::volumioGetState Dec 23 18:50:17 volumio-c2 volumio[1271]: info: CorePlayQueue::getTrack 0 Dec 23 18:50:17 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 23 18:50:18 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 23 18:50:18 volumio-c2 volumio[1271]: info: Received Get System Info Dec 23 18:50:18 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 23 18:50:18 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 23 18:50:18 volumio-c2 volumio[1271]: info: Discovery: Getting this device information Dec 23 18:50:18 volumio-c2 volumio[1271]: info: CoreCommandRouter::volumioGetState Dec 23 18:50:18 volumio-c2 volumio[1271]: info: CorePlayQueue::getTrack 0 Dec 23 18:50:18 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 23 18:50:19 volumio-c2 volumio[1271]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 23 18:50:25 volumio-c2 volumio[1271]: info: CALLMETHOD: miscellanea appearance setLanguage [object Object] Dec 23 18:50:25 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: appearance , setLanguage Dec 23 18:50:25 volumio-c2 volumio[1271]: info: Loading i18n strings for locale es Dec 23 18:50:25 volumio-c2 volumio[1271]: Updating browse sources language Dec 23 18:50:25 volumio-c2 volumio[1271]: Cannot find translation for source Spotify Dec 23 18:50:25 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 23 18:50:25 volumio-c2 volumio[1271]: Cannot find translation for source Spotify Dec 23 18:50:25 volumio-c2 volumio[1271]: info: Fetching Streaming Services browse cache Dec 23 18:50:32 volumio-c2 volumio[1271]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 23 18:50:32 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Dec 23 18:50:32 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Dec 23 18:50:32 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Dec 23 18:50:32 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: appearance , getAvailableUIs Dec 23 18:50:32 volumio-c2 volumio[1271]: info: Received Get System Version Dec 23 18:50:32 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 23 18:50:32 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: appearance , getBackgrounds Dec 23 18:50:33 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Dec 23 18:50:33 volumio-c2 volumio[1271]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Dec 23 18:50:33 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Dec 23 18:50:33 volumio-c2 volumio[1271]: info: Received Get System Version Dec 23 18:50:33 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 23 18:50:33 volumio-c2 volumio[1271]: info: Received Get System Info Dec 23 18:50:33 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 23 18:50:33 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 23 18:50:33 volumio-c2 volumio[1271]: info: Discovery: Getting this device information Dec 23 18:50:33 volumio-c2 volumio[1271]: info: CoreCommandRouter::volumioGetState Dec 23 18:50:33 volumio-c2 volumio[1271]: info: CorePlayQueue::getTrack 0 Dec 23 18:50:33 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 23 18:50:34 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: appearance , setBackgrounds Dec 23 18:50:34 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: appearance , getBackgrounds Dec 23 18:50:34 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Dec 23 18:50:36 volumio-c2 volumio[1271]: info: CoreCommandRouter::volumioPlay Dec 23 18:50:36 volumio-c2 volumio[1271]: info: CoreStateMachine::play index undefined Dec 23 18:50:36 volumio-c2 volumio[1271]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 23 18:50:36 volumio-c2 volumio[1271]: info: CorePlayQueue::getTrack 0 Dec 23 18:50:36 volumio-c2 volumio[1271]: info: CoreStateMachine::startPlaybackTimer Dec 23 18:50:36 volumio-c2 volumio[1271]: info: CorePlayQueue::getTrack 0 Dec 23 18:50:36 volumio-c2 volumio[1271]: info: [1766512236437] ControllerSpotify::clearAddPlayTrack Dec 23 18:50:36 volumio-c2 volumio[1271]: info: Sending Spotify command with payload to local API: /player/play Dec 23 18:50:36 volumio-c2 go-librespot[1591]: time="2025-12-23T18:50:36+01:00" level=debug msg="resolved context of track" uri="spotify:track:2FRnf9qhLbvw8fu4IBXx78" Dec 23 18:50:36 volumio-c2 go-librespot[1591]: time="2025-12-23T18:50:36+01:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:2FRnf9qhLbvw8fu4IBXx78" Dec 23 18:50:36 volumio-c2 go-librespot[1591]: time="2025-12-23T18:50:36+01:00" level=debug msg="loading track (paused: false, position: 1ms)" uri="spotify:track:2FRnf9qhLbvw8fu4IBXx78" Dec 23 18:50:36 volumio-c2 go-librespot[1591]: time="2025-12-23T18:50:36+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 23 18:50:36 volumio-c2 go-librespot[1591]: time="2025-12-23T18:50:36+01:00" level=trace msg="emitting websocket event: will_play" Dec 23 18:50:36 volumio-c2 volumio[1271]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:2FRnf9qhLbvw8fu4IBXx78","uri":"spotify:track:2FRnf9qhLbvw8fu4IBXx78","play_origin":"go-librespot"}} Dec 23 18:50:36 volumio-c2 go-librespot[1591]: time="2025-12-23T18:50:36+01:00" level=debug msg="selected format OGG_VORBIS_320 (bc4c46dec7eb7cf1e695a0c81c7c37331dd5b1df)" uri="spotify:track:2FRnf9qhLbvw8fu4IBXx78" Dec 23 18:50:36 volumio-c2 go-librespot[1591]: time="2025-12-23T18:50:36+01:00" level=debug msg="requested aes key for file bc4c46dec7eb7cf1e695a0c81c7c37331dd5b1df, gid: 2FRnf9qhLbvw8fu4IBXx78" Dec 23 18:50:36 volumio-c2 go-librespot[1591]: time="2025-12-23T18:50:36+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:2FRnf9qhLbvw8fu4IBXx78: failed retrieving audio key: failed retrieving aes key with code 1" Dec 23 18:50:36 volumio-c2 volumio[1271]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Dec 23 18:50:41 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 23 18:50:41 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Dec 23 18:50:44 volumio-c2 volumio[1271]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 23 18:50:45 volumio-c2 go-librespot[1591]: time="2025-12-23T18:50:45+01:00" level=trace msg="sent dealer ping" Dec 23 18:50:45 volumio-c2 go-librespot[1591]: time="2025-12-23T18:50:45+01:00" level=trace msg="received dealer pong" Dec 23 18:50:52 volumio-c2 volumio[1271]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Dec 23 18:50:52 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Dec 23 18:50:52 volumio-c2 volumio[1271]: info: Creating Spotify config file Dec 23 18:50:52 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 23 18:50:52 volumio-c2 volumio[1271]: info: Spotify config file written Dec 23 18:50:52 volumio-c2 sudo[2919]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 23 18:50:52 volumio-c2 sudo[2919]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 23 18:50:52 volumio-c2 systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 23 18:50:52 volumio-c2 systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 23 18:50:52 volumio-c2 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 23 18:50:52 volumio-c2 systemd[1]: go-librespot-daemon.service: Consumed 1.162s CPU time. Dec 23 18:50:52 volumio-c2 volumio[1271]: info: Connection to go-librespot Websocket closed Dec 23 18:50:52 volumio-c2 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 23 18:50:52 volumio-c2 go-librespot[2921]: go-librespot daemon starting... Dec 23 18:50:52 volumio-c2 sudo[2919]: pam_unix(sudo:session): session closed for user root Dec 23 18:50:52 volumio-c2 go-librespot[2922]: time="2025-12-23T18:50:52+01:00" level=info msg="running go-librespot 0.4.0" Dec 23 18:50:52 volumio-c2 go-librespot[2922]: time="2025-12-23T18:50:52+01:00" level=debug msg="app state loaded" Dec 23 18:50:52 volumio-c2 go-librespot[2922]: time="2025-12-23T18:50:52+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 23 18:50:52 volumio-c2 go-librespot[2922]: time="2025-12-23T18:50:52+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Dec 23 18:50:52 volumio-c2 go-librespot[2922]: time="2025-12-23T18:50:52+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 23 18:50:52 volumio-c2 go-librespot[2922]: time="2025-12-23T18:50:52+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 23 18:50:52 volumio-c2 go-librespot[2922]: time="2025-12-23T18:50:52+01:00" level=info msg="zeroconf server listening on port 43517" Dec 23 18:50:52 volumio-c2 go-librespot[2922]: time="2025-12-23T18:50:52+01:00" level=debug msg="obtained new client token: AACXv1XzHfxcua+hSi0nYCjlZnOXZnLBhSvcdXThZbxZSNRKuCxfQGm2OwM27n7twiVVcgJWvL/0ivx1Ef4z3k99kwMOhcEWjP+NLu2O0/cWTMp6cTKGMggVoxkIy+5F7GkfCw4D9xq33LFRCaKv2vi43yv597lIloBa125NYeZR8pGNFcDk+GlCunoZXxdsoUuC9chkN02QXQMi6yEFbuMVlEeNYmZFJwgYn5ob0b+WZVE0myBPwbpm" Dec 23 18:50:53 volumio-c2 go-librespot[2922]: time="2025-12-23T18:50:53+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Dec 23 18:50:53 volumio-c2 go-librespot[2922]: time="2025-12-23T18:50:53+01:00" level=debug msg="completed keyexchange" Dec 23 18:50:53 volumio-c2 go-librespot[2922]: time="2025-12-23T18:50:53+01:00" level=debug msg="completed challenge" Dec 23 18:50:53 volumio-c2 go-librespot[2922]: time="2025-12-23T18:50:53+01:00" level=info msg="authenticated AP" username="31************************3y" Dec 23 18:50:53 volumio-c2 go-librespot[2922]: time="2025-12-23T18:50:53+01:00" level=info msg="authenticated Login5" username="31************************3y" Dec 23 18:50:53 volumio-c2 go-librespot[2922]: time="2025-12-23T18:50:53+01:00" level=debug msg="initializing zeroconf session" username="31************************3y" Dec 23 18:50:53 volumio-c2 go-librespot[2922]: time="2025-12-23T18:50:53+01:00" level=debug msg="dealer connection opened" Dec 23 18:50:53 volumio-c2 go-librespot[2922]: time="2025-12-23T18:50:53+01:00" level=trace msg="starting accesspoint recv loop" Dec 23 18:50:53 volumio-c2 go-librespot[2922]: time="2025-12-23T18:50:53+01:00" level=trace msg="starting dealer recv loop" Dec 23 18:50:53 volumio-c2 go-librespot[2922]: time="2025-12-23T18:50:53+01:00" level=trace msg="received accesspoint ping" Dec 23 18:50:53 volumio-c2 go-librespot[2922]: time="2025-12-23T18:50:53+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Dec 23 18:50:53 volumio-c2 go-librespot[2922]: time="2025-12-23T18:50:53+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Dec 23 18:50:53 volumio-c2 go-librespot[2922]: time="2025-12-23T18:50:53+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Dec 23 18:50:53 volumio-c2 go-librespot[2922]: time="2025-12-23T18:50:53+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Dec 23 18:50:53 volumio-c2 go-librespot[2922]: time="2025-12-23T18:50:53+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Dec 23 18:50:53 volumio-c2 go-librespot[2922]: time="2025-12-23T18:50:53+01:00" level=debug msg="received connection id: YjFlNDQ0OGUtNWJm...NEQxOTE2NkFGMw==" Dec 23 18:50:53 volumio-c2 go-librespot[2922]: time="2025-12-23T18:50:53+01:00" level=trace msg="received accesspoint pong ack" Dec 23 18:50:53 volumio-c2 go-librespot[2922]: time="2025-12-23T18:50:53+01:00" level=debug msg="put connect state because NEW_DEVICE" Dec 23 18:50:55 volumio-c2 volumio[1271]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Dec 23 18:50:55 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Dec 23 18:50:55 volumio-c2 volumio[1271]: info: Creating Spotify config file Dec 23 18:50:55 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 23 18:50:55 volumio-c2 volumio[1271]: info: Spotify config file written Dec 23 18:50:55 volumio-c2 sudo[2931]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 23 18:50:55 volumio-c2 sudo[2931]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 23 18:50:55 volumio-c2 systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 23 18:50:55 volumio-c2 systemd[1]: go-librespot-daemon.service: Killing process 2929 (go-librespot) with signal SIGKILL. Dec 23 18:50:55 volumio-c2 systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 23 18:50:55 volumio-c2 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 23 18:50:55 volumio-c2 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 23 18:50:55 volumio-c2 go-librespot[2933]: go-librespot daemon starting... Dec 23 18:50:55 volumio-c2 sudo[2931]: pam_unix(sudo:session): session closed for user root Dec 23 18:50:55 volumio-c2 go-librespot[2934]: time="2025-12-23T18:50:55+01:00" level=info msg="running go-librespot 0.4.0" Dec 23 18:50:55 volumio-c2 go-librespot[2934]: time="2025-12-23T18:50:55+01:00" level=debug msg="app state loaded" Dec 23 18:50:55 volumio-c2 go-librespot[2934]: time="2025-12-23T18:50:55+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 23 18:50:55 volumio-c2 go-librespot[2934]: time="2025-12-23T18:50:55+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 23 18:50:55 volumio-c2 go-librespot[2934]: time="2025-12-23T18:50:55+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 23 18:50:55 volumio-c2 go-librespot[2934]: time="2025-12-23T18:50:55+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 23 18:50:55 volumio-c2 go-librespot[2934]: time="2025-12-23T18:50:55+01:00" level=info msg="zeroconf server listening on port 38301" Dec 23 18:50:55 volumio-c2 volumio[1271]: info: Initializing connection to go-librespot Websocket Dec 23 18:50:55 volumio-c2 go-librespot[2934]: time="2025-12-23T18:50:55+01:00" level=debug msg="new websocket client" Dec 23 18:50:55 volumio-c2 volumio[1271]: info: Connection to go-librespot Websocket established Dec 23 18:50:55 volumio-c2 volumio[1271]: info: go-librespot daemon successfully initialized Dec 23 18:50:55 volumio-c2 go-librespot[2934]: time="2025-12-23T18:50:55+01:00" level=debug msg="obtained new client token: AAD0/JdCivNBQCdnC5+YT3KwXEEjZN3ismROE0y2NxzFxSriiPH8xEA/DYU56JWB7SgU38E3WK1iTyWOYSsAsDQ9gaWttMYUhM6FkYkK0vrmV9lC8no/yZ4oBOz3SXDxLPr7JI3chdRC5784zZabl46Y6op5uIiPzqoQ647Mm3HAae1Nw8n2X01hahwfPiVgoQ992PsQH/xrrvhsjPzszYrpnHBIAgosl8nAPvhdoSPZ40uuYwsk1Bsc" Dec 23 18:50:55 volumio-c2 go-librespot[2934]: time="2025-12-23T18:50:55+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Dec 23 18:50:55 volumio-c2 go-librespot[2934]: time="2025-12-23T18:50:55+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: read tcp 192.168.1.39:35184->104.199.65.9:4070: read: connection reset by peer" Dec 23 18:50:55 volumio-c2 volumio[1271]: info: Connection to go-librespot Websocket closed Dec 23 18:50:55 volumio-c2 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 23 18:50:55 volumio-c2 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 23 18:50:58 volumio-c2 volumio[1271]: info: go-librespot daemon successfully initialized Dec 23 18:50:58 volumio-c2 volumio[1271]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Dec 23 18:50:58 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Dec 23 18:50:58 volumio-c2 volumio[1271]: info: Creating Spotify config file Dec 23 18:50:58 volumio-c2 volumio[1271]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 23 18:50:58 volumio-c2 volumio[1271]: info: Spotify config file written Dec 23 18:50:58 volumio-c2 sudo[2956]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 23 18:50:58 volumio-c2 sudo[2956]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 23 18:50:58 volumio-c2 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 23 18:50:58 volumio-c2 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 23 18:50:58 volumio-c2 go-librespot[2958]: go-librespot daemon starting... Dec 23 18:50:58 volumio-c2 sudo[2956]: pam_unix(sudo:session): session closed for user root Dec 23 18:50:58 volumio-c2 go-librespot[2959]: time="2025-12-23T18:50:58+01:00" level=info msg="running go-librespot 0.4.0" Dec 23 18:50:58 volumio-c2 go-librespot[2959]: time="2025-12-23T18:50:58+01:00" level=debug msg="app state loaded" Dec 23 18:50:58 volumio-c2 go-librespot[2959]: time="2025-12-23T18:50:58+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 23 18:50:58 volumio-c2 volumio[1271]: info: Getting Spotify volume Dec 23 18:50:58 volumio-c2 volumio[1271]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Dec 23 18:50:58 volumio-c2 volumio[1271]: info: Initializing connection to go-librespot Websocket Dec 23 18:50:58 volumio-c2 go-librespot[2959]: time="2025-12-23T18:50:58+01:00" level=debug msg="new websocket client" Dec 23 18:50:58 volumio-c2 volumio[1271]: info: Connection to go-librespot Websocket established Dec 23 18:50:58 volumio-c2 volumio[1271]: info: CoreCommandRouter::volumioGetState Dec 23 18:50:58 volumio-c2 volumio[1271]: info: CorePlayQueue::getTrack 0 Dec 23 18:50:58 volumio-c2 volumio[1271]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Dec 23 18:50:58 volumio-c2 volumio[1271]: SPOTIFY: SPOTIFY VOLUME 99 Dec 23 18:50:58 volumio-c2 volumio[1271]: SPOTIFY: VOLUMIO VOLUME 100 Dec 23 18:50:58 volumio-c2 volumio[1271]: SPOTIFY: DELTA VOLUME ENOUGH: false Dec 23 18:50:58 volumio-c2 volumio[1271]: info: Initializing connection to go-librespot Websocket Dec 23 18:50:58 volumio-c2 go-librespot[2959]: time="2025-12-23T18:50:58+01:00" level=debug msg="new websocket client" Dec 23 18:50:58 volumio-c2 volumio[1271]: info: Connection to go-librespot Websocket established Dec 23 18:50:58 volumio-c2 go-librespot[2959]: time="2025-12-23T18:50:58+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Dec 23 18:50:58 volumio-c2 go-librespot[2959]: time="2025-12-23T18:50:58+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 23 18:50:58 volumio-c2 go-librespot[2959]: time="2025-12-23T18:50:58+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 23 18:50:58 volumio-c2 go-librespot[2959]: time="2025-12-23T18:50:58+01:00" level=info msg="zeroconf server listening on port 35909" Dec 23 18:50:58 volumio-c2 go-librespot[2959]: time="2025-12-23T18:50:58+01:00" level=debug msg="obtained new client token: AAATRbVbhN0ELTHL6AtyoW265P6n8gZGIfdBCCnRaYBW7WHBV9ZLoYAJY4zBueMSmz40r7G1FRY3AY+1EOl9agVz8wcOn7r7FOa6DJuYUiHQcgi2+8g+5GHY1HT7QQaspCTnfPRC6+J+byoPww9jZGVHnh6l6+rVjMpgVhtcq75Lsi6txX9/5qTtSyOiX9q4wJs39TFhVpfpAyfxQQ/rG7R81KxeEtp4sT67KPm47au7gM+fo7zBKW7r" Dec 23 18:50:58 volumio-c2 go-librespot[2959]: time="2025-12-23T18:50:58+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Dec 23 18:50:59 volumio-c2 go-librespot[2959]: time="2025-12-23T18:50:59+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Dec 23 18:50:59 volumio-c2 volumio[1271]: info: Connection to go-librespot Websocket closed Dec 23 18:50:59 volumio-c2 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 23 18:50:59 volumio-c2 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 23 18:50:59 volumio-c2 volumio[1271]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 23 18:50:59 volumio-c2 volumio[1271]: Error: socket hang up Dec 23 18:50:59 volumio-c2 volumio[1271]: at connResetException (node:internal/errors:720:14) Dec 23 18:50:59 volumio-c2 volumio[1271]: at Socket.socketOnEnd (node:_http_client:519:23) Dec 23 18:50:59 volumio-c2 volumio[1271]: at Socket.emit (node:events:526:35) Dec 23 18:50:59 volumio-c2 volumio[1271]: at endReadableNT (node:internal/streams/readable:1376:12) Dec 23 18:50:59 volumio-c2 volumio[1271]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Dec 23 18:50:59 volumio-c2 volumio[1271]: code: 'ECONNRESET', Dec 23 18:50:59 volumio-c2 volumio[1271]: response: undefined Dec 23 18:50:59 volumio-c2 volumio[1271]: } Dec 23 18:50:59 volumio-c2 volumio[1271]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 23 18:50:59 volumio-c2 sudo[2981]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-23 18:49' Dec 23 18:50:59 volumio-c2 sudo[2981]: 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="cfdc872d40b979cca36352a7333c940c38dc64b5" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="6cbc2303e10f00c3a01cb7f02c6d12448bd32c62" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri Dec 5 20:42:14 UTC 2025" VOLUMIO_VERSION="4.073" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="67fdc5f60f00b7a328ccd8c4ad441086"