Jan 09 18:37:15 volumio kernel: usb 2-1: USB disconnect, device number 2 Jan 09 18:37:16 volumio systemd[1]: Stopped target sound.target - Sound Card. Jan 09 18:37:16 volumio acpid[814]: input device has been disconnected, fd 8 Jan 09 18:37:16 volumio volumio[1004]: info: Jan 09 18:37:16 volumio volumio[1004]: ---------------------------- USB Audio Device Detached Jan 09 18:37:16 volumio volumio[1004]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , usbAudioDetach Jan 09 18:37:16 volumio volumio[1004]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Jan 09 18:37:16 volumio volumio[1004]: aplay: device_list:274: no soundcards found... Jan 09 18:37:16 volumio volumio[1004]: info: CoreCommandRouter::executeOnPlugin: raat , onStop Jan 09 18:37:16 volumio volumio[1004]: info: No valid Plugin REST Endpoint Jan 09 18:37:18 volumio kernel: usb 2-1: new high-speed USB device number 3 using xhci_hcd Jan 09 18:37:18 volumio kernel: usb 2-1: New USB device found, idVendor=3302, idProduct=3365, bcdDevice= 0.01 Jan 09 18:37:18 volumio kernel: usb 2-1: New USB device strings: Mfr=1, Product=2, SerialNumber=0 Jan 09 18:37:18 volumio kernel: usb 2-1: Product: CX31993 384Khz HIFI AUDIO Jan 09 18:37:18 volumio kernel: usb 2-1: Manufacturer: TTGK Technology Co.,Ltd Jan 09 18:37:18 volumio kernel: input: TTGK Technology Co.,Ltd CX31993 384Khz HIFI AUDIO Consumer Control as /devices/pci0000:00/0000:00:1e.0/0000:02:1b.0/usb2/2-1/2-1:1.3/0003:3302:3365.0003/input/input7 Jan 09 18:37:18 volumio kernel: hid-generic 0003:3302:3365.0003: input,hidraw1: USB HID v1.11 Device [TTGK Technology Co.,Ltd CX31993 384Khz HIFI AUDIO] on usb-0000:02:1b.0-1/input3 Jan 09 18:37:18 volumio (udev-worker)[3417]: controlC5: Process '/usr/sbin/alsactl -E HOME=/run/alsa -E XDG_RUNTIME_DIR=/run/alsa/runtime restore 5' failed with exit code 99. Jan 09 18:37:18 volumio systemd[1]: alsa-state.service - Manage Sound Card State (restore and store) was skipped because of an unmet condition check (ConditionPathExists=/etc/alsa/state-daemon.conf). Jan 09 18:37:18 volumio systemd[1]: Reached target sound.target - Sound Card. Jan 09 18:37:18 volumio volumio[1004]: info: Jan 09 18:37:18 volumio volumio[1004]: ---------------------------- USB Audio Device Attached Jan 09 18:37:18 volumio volumio[1004]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , usbAudioAttach Jan 09 18:37:18 volumio volumio[1004]: info: CoreCommandRouter::Close All Modals sent Jan 09 18:37:18 volumio volumio[1004]: info: Preparing to save Alsa Options, stopping services first Jan 09 18:37:18 volumio volumio[1004]: info: CoreCommandRouter::volumioGetState Jan 09 18:37:18 volumio volumio[1004]: info: CorePlayQueue::getTrack 0 Jan 09 18:37:18 volumio volumio[1004]: info: CoreCommandRouter::volumioPause Jan 09 18:37:18 volumio volumio[1004]: info: CoreStateMachine::pause Jan 09 18:37:18 volumio volumio[1004]: info: Saving Audio Output to: {"disallowPush":true,"output_device":{"value":"5","label":"CX31993 384Khz HIFI AUDIO","alsacard":"AUDIO"},"i2s":false} Jan 09 18:37:18 volumio volumio[1004]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Jan 09 18:37:18 volumio volumio[1004]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Jan 09 18:37:18 volumio volumio[1004]: info: Setting mixer Speaker Volume for card CX31993 384Khz HIFI AUDIO Jan 09 18:37:18 volumio volumio[1004]: info: CoreCommandRouter::volumioUpdateVolumeSettings Jan 09 18:37:18 volumio volumio[1004]: info: Updating Volume Controller Parameters: Device: 5 Name: CX31993 384Khz HIFI AUDIO Mixer: Speaker Volume Max Vol: 100 Vol Curve; logarithmic Vol Steps: 1 Jan 09 18:37:18 volumio volumio[1004]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , setExternalVolume Jan 09 18:37:18 volumio volumio[1004]: info: Disabling external Volume Control Jan 09 18:37:18 volumio volumio[1004]: info: CoreCommandRouter::getUIConfigOnPlugin Jan 09 18:37:18 volumio volumio[1004]: info: Preparing to generate the ALSA configuration file Jan 09 18:37:18 volumio volumio[1004]: info: No valid Plugin REST Endpoint Jan 09 18:37:18 volumio volumio[1004]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Jan 09 18:37:18 volumio volumio[1004]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 09 18:37:18 volumio volumio[1004]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Jan 09 18:37:18 volumio volumio[1004]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 09 18:37:18 volumio volumio[1004]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 09 18:37:18 volumio volumio[1004]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 09 18:37:18 volumio volumio[1004]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 09 18:37:18 volumio volumio[1004]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 09 18:37:18 volumio volumio[1004]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 09 18:37:18 volumio volumio[1004]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 09 18:37:18 volumio volumio[1004]: info: CoreCommandRouter::executeOnPlugin: mpd , getPlaybackMode Jan 09 18:37:18 volumio volumio[1004]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Jan 09 18:37:18 volumio volumio[1004]: info: Asound.conf file unchanged, so no further update is needed Jan 09 18:37:18 volumio volumio[1004]: info: Output device has changed, restarting MPD Jan 09 18:37:18 volumio volumio[1004]: info: Output device has changed, restarting Shairport Sync Jan 09 18:37:18 volumio volumio[1004]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 09 18:37:18 volumio volumio[1004]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 09 18:37:18 volumio sudo[3460]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 09 18:37:18 volumio sudo[3460]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 09 18:37:18 volumio sudo[3461]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 09 18:37:18 volumio sudo[3461]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 09 18:37:18 volumio volumio[1004]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 09 18:37:18 volumio volumio[1004]: info: VolumeController:: Volume=100 Mute =false Jan 09 18:37:18 volumio sudo[3461]: pam_unix(sudo:session): session closed for user root Jan 09 18:37:18 volumio volumio[1004]: info: CoreStateMachine::pushState Jan 09 18:37:18 volumio volumio[1004]: info: CorePlayQueue::getTrack 0 Jan 09 18:37:18 volumio volumio[1004]: info: CoreCommandRouter::volumioPushState Jan 09 18:37:19 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Jan 09 18:37:19 volumio volumio[1004]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jan 09 18:37:19 volumio volumio[1004]: info: MPD Permissions set Jan 09 18:37:19 volumio volumio[1004]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 09 18:37:19 volumio volumio[1004]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 09 18:37:19 volumio volumio[1004]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 09 18:37:19 volumio volumio[1004]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 09 18:37:19 volumio volumio[1004]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 09 18:37:19 volumio volumio[1004]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 09 18:37:19 volumio systemd[1]: mpd.service: Deactivated successfully. Jan 09 18:37:19 volumio volumio[1004]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 09 18:37:19 volumio volumio[1004]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 09 18:37:19 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 09 18:37:19 volumio systemd[1]: mpd.socket: Deactivated successfully. Jan 09 18:37:19 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 09 18:37:19 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 09 18:37:19 volumio volumio[1004]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 09 18:37:19 volumio volumio[1004]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber Jan 09 18:37:19 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 09 18:37:19 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Jan 09 18:37:19 volumio volumio[1004]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 09 18:37:19 volumio volumio[1004]: info: Starting Shairport Sync Jan 09 18:37:19 volumio sudo[3477]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 09 18:37:19 volumio sudo[3477]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jan 09 18:37:19 volumio sudo[3477]: pam_unix(sudo:session): session closed for user root Jan 09 18:37:19 volumio sudo[3480]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 09 18:37:19 volumio sudo[3480]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 09 18:37:19 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 09 18:37:19 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Jan 09 18:37:19 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 09 18:37:19 volumio systemd[1]: shairport-sync.service: Consumed 2.460s CPU time. Jan 09 18:37:19 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 09 18:37:19 volumio sudo[3480]: pam_unix(sudo:session): session closed for user root Jan 09 18:37:19 volumio volumio[1004]: info: Shairport-Sync Started Jan 09 18:37:19 volumio volumio[1004]: info: CoreCommandRouter::executeOnPlugin: raat , restartRaat Jan 09 18:37:19 volumio mpd[3482]: 2026-01-09T18:37:19 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jan 09 18:37:19 volumio systemd[1]: Started mpd.service - Music Player Daemon. Jan 09 18:37:19 volumio sudo[3460]: pam_unix(sudo:session): session closed for user root Jan 09 18:37:19 volumio volumio[1004]: error: updateQueue error: null Jan 09 18:37:22 volumio go-librespot[3274]: time="2026-01-09T18:37:22+02:00" level=debug msg="obtained new client token: AAB/K/CEzfM+tWIUlF+pYgJA7/hUJ/giJJUMRQ8NbRVSvAvNBzNJ8eDV2O7wWuVMc88lZUtw7DW+7/iJZGqEf0W0Srh0B4Vz79YeyKe+Im0blRby8vtSUhLU2rzYWRTkFiayWBHfwxib2WvfpJNogbFqyy6HYHNZmKkfPYcW+wZBFShDklyDQ19OIYDAljJoawldNGLKVLMSLbVoerFKTVh5IjUT1CZ67ipldLHTuSNcB2yFetZJyDI=" Jan 09 18:37:22 volumio sudo[3506]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 09 18:37:22 volumio sudo[3506]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 09 18:37:22 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Jan 09 18:37:22 volumio systemd[1]: mpd_monitor.service: Deactivated successfully. Jan 09 18:37:22 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Jan 09 18:37:22 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Jan 09 18:37:22 volumio mpd_monitor.sh[3508]: MPD Monitor Service: Starting MPD Monitor Service Jan 09 18:37:22 volumio sudo[3506]: pam_unix(sudo:session): session closed for user root Jan 09 18:37:22 volumio volumio[1004]: info: Successfully started MPD Monitor Jan 09 18:37:22 volumio go-librespot[3274]: time="2026-01-09T18:37:22+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Jan 09 18:37:22 volumio volumio[1004]: info: CoreCommandRouter::volumioRetrieveVolumeLevels Jan 09 18:37:22 volumio volumio[1004]: info: CoreStateMachine::getcurrentVolume Jan 09 18:37:22 volumio volumio[1004]: info: CoreCommandRouter::volumioRetrievevolume Jan 09 18:37:22 volumio volumio[1004]: info: VolumeController:: Volume=100 Mute =false Jan 09 18:37:22 volumio volumio[1004]: info: CoreStateMachine::pushState Jan 09 18:37:22 volumio volumio[1004]: info: CorePlayQueue::getTrack 0 Jan 09 18:37:22 volumio volumio[1004]: info: CoreCommandRouter::volumioPushState Jan 09 18:37:22 volumio volumio[1004]: info: CoreStateMachine::updateTrackBlock Jan 09 18:37:22 volumio volumio[1004]: info: CorePlayQueue::getTrackBlock Jan 09 18:37:22 volumio volumio[1004]: info: CoreCommandRouter::volumioRetrievevolume Jan 09 18:37:22 volumio volumio[1004]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jan 09 18:37:22 volumio go-librespot[3274]: time="2026-01-09T18:37:22+02:00" level=debug msg="completed keyexchange" Jan 09 18:37:22 volumio go-librespot[3274]: time="2026-01-09T18:37:22+02:00" level=debug msg="completed challenge" Jan 09 18:37:22 volumio volumio[1004]: info: VolumeController:: Volume=100 Mute =false Jan 09 18:37:22 volumio volumio[1004]: info: CoreStateMachine::pushState Jan 09 18:37:22 volumio volumio[1004]: info: CorePlayQueue::getTrack 0 Jan 09 18:37:22 volumio volumio[1004]: info: CoreCommandRouter::volumioPushState Jan 09 18:37:22 volumio volumio[1004]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jan 09 18:37:23 volumio go-librespot[3274]: time="2026-01-09T18:37:23+02:00" level=info msg="authenticated AP" username="31************************pu" Jan 09 18:37:23 volumio go-librespot[3274]: time="2026-01-09T18:37:23+02:00" level=info msg="authenticated Login5" username="31************************pu" Jan 09 18:37:23 volumio go-librespot[3274]: time="2026-01-09T18:37:23+02:00" level=info msg="accepted zeroconf from Dean's S22" username="31************************pu" Jan 09 18:37:23 volumio go-librespot[3274]: time="2026-01-09T18:37:23+02:00" level=debug msg="dealer connection opened" Jan 09 18:37:23 volumio go-librespot[3274]: time="2026-01-09T18:37:23+02:00" level=trace msg="starting accesspoint recv loop" Jan 09 18:37:23 volumio go-librespot[3274]: time="2026-01-09T18:37:23+02:00" level=trace msg="starting dealer recv loop" Jan 09 18:37:23 volumio go-librespot[3274]: time="2026-01-09T18:37:23+02:00" level=trace msg="received accesspoint ping" Jan 09 18:37:23 volumio go-librespot[3274]: time="2026-01-09T18:37:23+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jan 09 18:37:23 volumio go-librespot[3274]: time="2026-01-09T18:37:23+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jan 09 18:37:23 volumio go-librespot[3274]: time="2026-01-09T18:37:23+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jan 09 18:37:23 volumio go-librespot[3274]: time="2026-01-09T18:37:23+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jan 09 18:37:23 volumio go-librespot[3274]: time="2026-01-09T18:37:23+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jan 09 18:37:23 volumio go-librespot[3274]: time="2026-01-09T18:37:23+02:00" level=debug msg="received connection id: MWMxNzhiNzAtOTBi...OTZGNENFNzRBRQ==" Jan 09 18:37:23 volumio go-librespot[3274]: time="2026-01-09T18:37:23+02:00" level=trace msg="received accesspoint pong ack" Jan 09 18:37:23 volumio go-librespot[3274]: time="2026-01-09T18:37:23+02:00" level=debug msg="put connect state because NEW_DEVICE" Jan 09 18:37:24 volumio go-librespot[3274]: time="2026-01-09T18:37:24+02:00" level=debug msg="handling transfer player command from 1c8e78e81e75f29b8a1621e69854678e1b9f9d2f" Jan 09 18:37:24 volumio go-librespot[3274]: time="2026-01-09T18:37:24+02:00" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZF1DX0rCrO4CFRfM" Jan 09 18:37:24 volumio go-librespot[3274]: time="2026-01-09T18:37:24+02:00" level=trace msg="fetched new page 0 with 50 items (list: 50)" uri="spotify:playlist:37i9dQZF1DX0rCrO4CFRfM" Jan 09 18:37:24 volumio go-librespot[3274]: time="2026-01-09T18:37:24+02:00" level=debug msg="loading track (paused: false, position: 2ms)" uri="spotify:track:1CfFF36728zzSOcSLzj74U" Jan 09 18:37:24 volumio go-librespot[3274]: time="2026-01-09T18:37:24+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 09 18:37:24 volumio go-librespot[3274]: time="2026-01-09T18:37:24+02:00" level=trace msg="emitting websocket event: will_play" Jan 09 18:37:24 volumio volumio[1004]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:playlist:37i9dQZF1DX0rCrO4CFRfM","uri":"spotify:track:1CfFF36728zzSOcSLzj74U","play_origin":"playlist"}} Jan 09 18:37:24 volumio go-librespot[3274]: time="2026-01-09T18:37:24+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 411" Jan 09 18:37:24 volumio go-librespot[3274]: time="2026-01-09T18:37:24+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1376" Jan 09 18:37:24 volumio go-librespot[3274]: time="2026-01-09T18:37:24+02:00" level=debug msg="selected format OGG_VORBIS_320 (de32d548d2b3f4bb1b2faf3f6d20a3075d626dcb)" uri="spotify:track:1CfFF36728zzSOcSLzj74U" Jan 09 18:37:24 volumio go-librespot[3274]: time="2026-01-09T18:37:24+02:00" level=debug msg="requested aes key for file de32d548d2b3f4bb1b2faf3f6d20a3075d626dcb, gid: 1CfFF36728zzSOcSLzj74U" Jan 09 18:37:25 volumio go-librespot[3274]: time="2026-01-09T18:37:25+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1132" Jan 09 18:37:25 volumio go-librespot[3274]: time="2026-01-09T18:37:25+02:00" level=warning msg="failed handling dealer request" error="failed loading current track (transfer): failed creating stream for spotify:track:1CfFF36728zzSOcSLzj74U: failed retrieving audio key: failed retrieving aes key with code 1" Jan 09 18:37:25 volumio go-librespot[3274]: time="2026-01-09T18:37:25+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Jan 09 18:37:25 volumio go-librespot[3274]: time="2026-01-09T18:37:25+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Jan 09 18:37:25 volumio go-librespot[3274]: time="2026-01-09T18:37:25+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Jan 09 18:37:34 volumio go-librespot[3274]: time="2026-01-09T18:37:34+02:00" level=debug msg="handling skip_next player command from 1c8e78e81e75f29b8a1621e69854678e1b9f9d2f" Jan 09 18:37:34 volumio go-librespot[3274]: time="2026-01-09T18:37:34+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:2Nz14MtLy82a3togG2EI8l" Jan 09 18:37:34 volumio go-librespot[3274]: time="2026-01-09T18:37:34+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 09 18:37:34 volumio go-librespot[3274]: time="2026-01-09T18:37:34+02:00" level=trace msg="emitting websocket event: will_play" Jan 09 18:37:34 volumio volumio[1004]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:playlist:37i9dQZF1DX0rCrO4CFRfM","uri":"spotify:track:2Nz14MtLy82a3togG2EI8l","play_origin":"playlist"}} Jan 09 18:37:35 volumio go-librespot[3274]: time="2026-01-09T18:37:35+02:00" level=debug msg="selected format OGG_VORBIS_320 (95d005138208da09723a19398c07c8b5222154a5)" uri="spotify:track:2Nz14MtLy82a3togG2EI8l" Jan 09 18:37:35 volumio go-librespot[3274]: time="2026-01-09T18:37:35+02:00" level=debug msg="requested aes key for file 95d005138208da09723a19398c07c8b5222154a5, gid: 2Nz14MtLy82a3togG2EI8l" Jan 09 18:37:35 volumio go-librespot[3274]: time="2026-01-09T18:37:35+02:00" level=warning msg="failed handling dealer request" error="failed skipping to next track: failed loading current track (advance to spotify:track:2Nz14MtLy82a3togG2EI8l): failed creating stream for spotify:track:2Nz14MtLy82a3togG2EI8l: failed retrieving audio key: failed retrieving aes key with code 1" Jan 09 18:37:46 volumio volumio[1004]: info: CoreCommandRouter::volumioGetState Jan 09 18:37:46 volumio volumio[1004]: info: CorePlayQueue::getTrack 0 Jan 09 18:37:53 volumio go-librespot[3274]: time="2026-01-09T18:37:53+02:00" level=trace msg="sent dealer ping" Jan 09 18:37:53 volumio go-librespot[3274]: time="2026-01-09T18:37:53+02:00" level=trace msg="received dealer pong" Jan 09 18:38:08 volumio volumio[1004]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jan 09 18:38:08 volumio volumio[1004]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Jan 09 18:38:20 volumio volumio[1004]: info: CoreCommandRouter::getUIConfigOnPlugin Jan 09 18:38:23 volumio go-librespot[3274]: time="2026-01-09T18:38:23+02:00" level=trace msg="sent dealer ping" Jan 09 18:38:23 volumio go-librespot[3274]: time="2026-01-09T18:38:23+02:00" level=trace msg="received dealer pong" Jan 09 18:38:40 volumio volumio[1004]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Jan 09 18:38:40 volumio volumio[1004]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Jan 09 18:38:40 volumio volumio[1004]: info: Creating Spotify config file Jan 09 18:38:40 volumio volumio[1004]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 09 18:38:40 volumio volumio[1004]: info: Spotify config file written Jan 09 18:38:40 volumio sudo[3730]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 09 18:38:40 volumio sudo[3730]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 09 18:38:40 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jan 09 18:38:40 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jan 09 18:38:40 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 09 18:38:40 volumio volumio[1004]: info: Connection to go-librespot Websocket closed Jan 09 18:38:40 volumio go-librespot[3732]: go-librespot daemon starting... Jan 09 18:38:40 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 09 18:38:40 volumio sudo[3730]: pam_unix(sudo:session): session closed for user root Jan 09 18:38:40 volumio go-librespot[3733]: time="2026-01-09T18:38:40+02:00" level=info msg="running go-librespot 0.6.2" Jan 09 18:38:40 volumio go-librespot[3733]: time="2026-01-09T18:38:40+02:00" level=debug msg="app state loaded" Jan 09 18:38:40 volumio go-librespot[3733]: time="2026-01-09T18:38:40+02:00" level=debug msg="stored credentials not found" Jan 09 18:38:40 volumio go-librespot[3733]: time="2026-01-09T18:38:40+02:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 09 18:38:40 volumio go-librespot[3733]: time="2026-01-09T18:38:40+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Jan 09 18:38:40 volumio go-librespot[3733]: time="2026-01-09T18:38:40+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Jan 09 18:38:40 volumio go-librespot[3733]: time="2026-01-09T18:38:40+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Jan 09 18:38:40 volumio go-librespot[3733]: time="2026-01-09T18:38:40+02:00" level=info msg="zeroconf server listening on port 43687" Jan 09 18:38:41 volumio volumio[1004]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Jan 09 18:38:41 volumio volumio[1004]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Jan 09 18:38:41 volumio volumio[1004]: info: Creating Spotify config file Jan 09 18:38:41 volumio volumio[1004]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 09 18:38:41 volumio volumio[1004]: info: Spotify config file written Jan 09 18:38:41 volumio sudo[3743]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 09 18:38:41 volumio sudo[3743]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 09 18:38:41 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jan 09 18:38:41 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jan 09 18:38:41 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 09 18:38:41 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 09 18:38:41 volumio go-librespot[3745]: go-librespot daemon starting... Jan 09 18:38:41 volumio sudo[3743]: pam_unix(sudo:session): session closed for user root Jan 09 18:38:41 volumio go-librespot[3746]: time="2026-01-09T18:38:41+02:00" level=info msg="running go-librespot 0.6.2" Jan 09 18:38:41 volumio go-librespot[3746]: time="2026-01-09T18:38:41+02:00" level=debug msg="app state loaded" Jan 09 18:38:41 volumio go-librespot[3746]: time="2026-01-09T18:38:41+02:00" level=debug msg="stored credentials not found" Jan 09 18:38:41 volumio go-librespot[3746]: time="2026-01-09T18:38:41+02:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 09 18:38:42 volumio go-librespot[3746]: time="2026-01-09T18:38:42+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 09 18:38:42 volumio go-librespot[3746]: time="2026-01-09T18:38:42+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 09 18:38:42 volumio go-librespot[3746]: time="2026-01-09T18:38:42+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 09 18:38:42 volumio go-librespot[3746]: time="2026-01-09T18:38:42+02:00" level=info msg="zeroconf server listening on port 41621" Jan 09 18:38:42 volumio volumio[1004]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Jan 09 18:38:42 volumio volumio[1004]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Jan 09 18:38:42 volumio volumio[1004]: info: Creating Spotify config file Jan 09 18:38:42 volumio volumio[1004]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 09 18:38:42 volumio volumio[1004]: info: Spotify config file written Jan 09 18:38:42 volumio sudo[3757]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 09 18:38:42 volumio sudo[3757]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 09 18:38:42 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jan 09 18:38:42 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jan 09 18:38:42 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 09 18:38:42 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 09 18:38:42 volumio sudo[3757]: pam_unix(sudo:session): session closed for user root Jan 09 18:38:42 volumio go-librespot[3762]: go-librespot daemon starting... Jan 09 18:38:42 volumio go-librespot[3763]: time="2026-01-09T18:38:42+02:00" level=info msg="running go-librespot 0.6.2" Jan 09 18:38:42 volumio go-librespot[3763]: time="2026-01-09T18:38:42+02:00" level=debug msg="app state loaded" Jan 09 18:38:42 volumio go-librespot[3763]: time="2026-01-09T18:38:42+02:00" level=debug msg="stored credentials not found" Jan 09 18:38:42 volumio go-librespot[3763]: time="2026-01-09T18:38:42+02:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 09 18:38:42 volumio go-librespot[3763]: time="2026-01-09T18:38:42+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 09 18:38:42 volumio go-librespot[3763]: time="2026-01-09T18:38:42+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 09 18:38:42 volumio go-librespot[3763]: time="2026-01-09T18:38:42+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 09 18:38:42 volumio go-librespot[3763]: time="2026-01-09T18:38:42+02:00" level=info msg="zeroconf server listening on port 39527" Jan 09 18:38:43 volumio volumio[1004]: info: Initializing connection to go-librespot Websocket Jan 09 18:38:43 volumio go-librespot[3763]: time="2026-01-09T18:38:43+02:00" level=debug msg="new websocket client" Jan 09 18:38:43 volumio volumio[1004]: info: Connection to go-librespot Websocket established Jan 09 18:38:43 volumio volumio[1004]: info: go-librespot daemon successfully initialized Jan 09 18:38:44 volumio volumio[1004]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Jan 09 18:38:44 volumio volumio[1004]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Jan 09 18:38:44 volumio volumio[1004]: info: Creating Spotify config file Jan 09 18:38:44 volumio volumio[1004]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 09 18:38:44 volumio volumio[1004]: info: Spotify config file written Jan 09 18:38:44 volumio sudo[3788]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 09 18:38:44 volumio sudo[3788]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 09 18:38:44 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jan 09 18:38:44 volumio volumio[1004]: info: Connection to go-librespot Websocket closed Jan 09 18:38:44 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jan 09 18:38:44 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 09 18:38:44 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 09 18:38:44 volumio sudo[3788]: pam_unix(sudo:session): session closed for user root Jan 09 18:38:44 volumio go-librespot[3790]: go-librespot daemon starting... Jan 09 18:38:44 volumio go-librespot[3791]: time="2026-01-09T18:38:44+02:00" level=info msg="running go-librespot 0.6.2" Jan 09 18:38:44 volumio go-librespot[3791]: time="2026-01-09T18:38:44+02:00" level=debug msg="app state loaded" Jan 09 18:38:44 volumio go-librespot[3791]: time="2026-01-09T18:38:44+02:00" level=debug msg="stored credentials not found" Jan 09 18:38:44 volumio go-librespot[3791]: time="2026-01-09T18:38:44+02:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 09 18:38:44 volumio go-librespot[3791]: time="2026-01-09T18:38:44+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Jan 09 18:38:44 volumio go-librespot[3791]: time="2026-01-09T18:38:44+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Jan 09 18:38:44 volumio go-librespot[3791]: time="2026-01-09T18:38:44+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Jan 09 18:38:44 volumio go-librespot[3791]: time="2026-01-09T18:38:44+02:00" level=info msg="zeroconf server listening on port 34761" Jan 09 18:38:44 volumio volumio[1004]: info: go-librespot daemon successfully initialized Jan 09 18:38:45 volumio volumio[1004]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Jan 09 18:38:45 volumio volumio[1004]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Jan 09 18:38:45 volumio volumio[1004]: info: Creating Spotify config file Jan 09 18:38:45 volumio volumio[1004]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 09 18:38:45 volumio volumio[1004]: info: Spotify config file written Jan 09 18:38:45 volumio sudo[3802]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 09 18:38:45 volumio sudo[3802]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 09 18:38:45 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jan 09 18:38:45 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jan 09 18:38:45 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 09 18:38:45 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 09 18:38:45 volumio go-librespot[3804]: go-librespot daemon starting... Jan 09 18:38:45 volumio sudo[3802]: pam_unix(sudo:session): session closed for user root Jan 09 18:38:45 volumio go-librespot[3805]: time="2026-01-09T18:38:45+02:00" level=info msg="running go-librespot 0.6.2" Jan 09 18:38:45 volumio go-librespot[3805]: time="2026-01-09T18:38:45+02:00" level=debug msg="app state loaded" Jan 09 18:38:45 volumio go-librespot[3805]: time="2026-01-09T18:38:45+02:00" level=debug msg="stored credentials not found" Jan 09 18:38:45 volumio go-librespot[3805]: time="2026-01-09T18:38:45+02:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 09 18:38:45 volumio volumio[1004]: info: go-librespot daemon successfully initialized Jan 09 18:38:45 volumio go-librespot[3805]: time="2026-01-09T18:38:45+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 09 18:38:45 volumio go-librespot[3805]: time="2026-01-09T18:38:45+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 09 18:38:45 volumio go-librespot[3805]: time="2026-01-09T18:38:45+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 09 18:38:45 volumio go-librespot[3805]: time="2026-01-09T18:38:45+02:00" level=info msg="zeroconf server listening on port 37891" Jan 09 18:38:45 volumio volumio[1004]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Jan 09 18:38:45 volumio volumio[1004]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Jan 09 18:38:45 volumio volumio[1004]: info: Creating Spotify config file Jan 09 18:38:45 volumio volumio[1004]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 09 18:38:45 volumio volumio[1004]: info: Spotify config file written Jan 09 18:38:45 volumio sudo[3814]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 09 18:38:45 volumio sudo[3814]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 09 18:38:45 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jan 09 18:38:45 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jan 09 18:38:45 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 09 18:38:45 volumio systemd[1]: go-librespot-daemon.service: Start request repeated too quickly. Jan 09 18:38:45 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'start-limit-hit'. Jan 09 18:38:45 volumio systemd[1]: Failed to start go-librespot-daemon.service - go-librespot Daemon. Jan 09 18:38:45 volumio sudo[3814]: pam_unix(sudo:session): session closed for user root Jan 09 18:38:45 volumio volumio[1004]: error: Cannot start Go-librespot Daemon: Error: Command failed: /usr/bin/sudo systemctl restart go-librespot-daemon.service Jan 09 18:38:45 volumio volumio[1004]: Job for go-librespot-daemon.service failed because start of the service was attempted too often. Jan 09 18:38:45 volumio volumio[1004]: See "systemctl status go-librespot-daemon.service" and "journalctl -xeu go-librespot-daemon.service" for details. Jan 09 18:38:45 volumio volumio[1004]: To force a start use "systemctl reset-failed go-librespot-daemon.service" Jan 09 18:38:45 volumio volumio[1004]: followed by "systemctl start go-librespot-daemon.service" again. Jan 09 18:38:45 volumio volumio[1004]: error: Error initializing go-librespot daemon: Error: Command failed: /usr/bin/sudo systemctl restart go-librespot-daemon.service Jan 09 18:38:45 volumio volumio[1004]: Job for go-librespot-daemon.service failed because start of the service was attempted too often. Jan 09 18:38:45 volumio volumio[1004]: See "systemctl status go-librespot-daemon.service" and "journalctl -xeu go-librespot-daemon.service" for details. Jan 09 18:38:45 volumio volumio[1004]: To force a start use "systemctl reset-failed go-librespot-daemon.service" Jan 09 18:38:45 volumio volumio[1004]: followed by "systemctl start go-librespot-daemon.service" again. Jan 09 18:38:46 volumio volumio[1004]: info: Getting Spotify volume Jan 09 18:38:46 volumio volumio[1004]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 09 18:38:46 volumio volumio[1004]: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 09 18:38:46 volumio volumio[1004]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Jan 09 18:38:46 volumio volumio[1004]: errno: -111, Jan 09 18:38:46 volumio volumio[1004]: code: 'ECONNREFUSED', Jan 09 18:38:46 volumio volumio[1004]: syscall: 'connect', Jan 09 18:38:46 volumio volumio[1004]: address: '127.0.0.1', Jan 09 18:38:46 volumio volumio[1004]: port: 9879, Jan 09 18:38:46 volumio volumio[1004]: response: undefined Jan 09 18:38:46 volumio volumio[1004]: } Jan 09 18:38:46 volumio volumio[1004]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 09 18:38:46 volumio sudo[3831]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-09 18:37' Jan 09 18:38:46 volumio sudo[3831]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Debian GNU/Linux 12 (bookworm)" NAME="Debian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="cfdc872d40b979cca36352a7333c940c38dc64b5" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="6cbc2303e10f00c3a01cb7f02c6d12448bd32c62" VOLUMIO_ARCH="x64" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri Dec 5 21:07:15 UTC 2025" VOLUMIO_VERSION="4.073" VOLUMIO_HARDWARE="x86_amd64" VOLUMIO_DEVICENAME="x86_64" VOLUMIO_HASH="4b5c74f40f473b90a542bf010b97924b"