Dec 16 18:57:29 volumio go-librespot[4412]: time="2025-12-16T18:57:29+02:00" level=trace msg="sent dealer ping" Dec 16 18:57:29 volumio go-librespot[4412]: time="2025-12-16T18:57:29+02:00" level=trace msg="received dealer pong" Dec 16 18:57:32 volumio volumio[4090]: info: CALLMETHOD: audio_interface alsa_controller saveVolumeOptions [object Object] Dec 16 18:57:32 volumio volumio[4090]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , saveVolumeOptions Dec 16 18:57:32 volumio volumio[4090]: info: CoreCommandRouter::volumioGetState Dec 16 18:57:32 volumio volumio[4090]: info: CoreCommandRouter::executeOnPlugin: mpd , saveResampleOptions Dec 16 18:57:32 volumio volumio[4090]: info: Restoring Previous Volume level: 58 false false Dec 16 18:57:32 volumio volumio[4090]: info: Volume configurations have been set Dec 16 18:57:32 volumio volumio[4090]: info: QobuzConnect: setDeactiveState invoked Dec 16 18:57:32 volumio volumio[4090]: info: CoreCommandRouter::volumioGetState Dec 16 18:57:32 volumio vtcs[4709]: [2025-12-16 18:57:32.734] [tisoc] [warning] [SessionManagerImpl.cpp:240] Illegal State: IDLE Dec 16 18:57:32 volumio vtcs[4709]: [2025-12-16 18:57:32.734] [tisoc] [error] [SpkconServer.cpp:375] recv error. socket disconnected Dec 16 18:57:32 volumio sudo[4870]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 16 18:57:32 volumio sudo[4870]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 16 18:57:32 volumio sudo[4870]: pam_unix(sudo:session): session closed for user root Dec 16 18:57:32 volumio sudo[4872]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 16 18:57:32 volumio sudo[4872]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 16 18:57:32 volumio sudo[4875]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Dec 16 18:57:32 volumio sudo[4875]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 16 18:57:32 volumio volumio[4090]: info: CoreCommandRouter::volumioUpdateVolumeSettings Dec 16 18:57:32 volumio volumio[4090]: info: Updating Volume Controller Parameters: Device: 1 Name: Headphones Mixer: PCM Max Vol: 100 Vol Curve; logarithmic Vol Steps: 1 Dec 16 18:57:32 volumio volumio[4090]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , setExternalVolume Dec 16 18:57:32 volumio volumio[4090]: info: Disabling external Volume Control Dec 16 18:57:32 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Dec 16 18:57:32 volumio systemd[1]: Stopping vtcs.service - Volumio Tidal Connect Service... Dec 16 18:57:32 volumio systemd[1]: vtcs.service: Killing process 4720 (vtcs) with signal SIGKILL. Dec 16 18:57:32 volumio systemd[1]: vtcs.service: Deactivated successfully. Dec 16 18:57:32 volumio systemd[1]: Stopped vtcs.service - Volumio Tidal Connect Service. Dec 16 18:57:32 volumio volumio[4090]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 16 18:57:32 volumio sudo[4875]: pam_unix(sudo:session): session closed for user root Dec 16 18:57:32 volumio systemd[1]: mpd.service: Deactivated successfully. Dec 16 18:57:32 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 16 18:57:32 volumio systemd[1]: mpd.service: Consumed 1.365s CPU time. Dec 16 18:57:32 volumio systemd[1]: mpd.socket: Deactivated successfully. Dec 16 18:57:32 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 16 18:57:32 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 16 18:57:32 volumio sudo[4885]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Dec 16 18:57:32 volumio sudo[4885]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 16 18:57:32 volumio sudo[4892]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed qobuz-connect.service Dec 16 18:57:32 volumio sudo[4892]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 16 18:57:32 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 16 18:57:32 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Dec 16 18:57:32 volumio volumio[4090]: info: MPD Permissions set Dec 16 18:57:32 volumio volumio[4090]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 16 18:57:32 volumio volumio[4090]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 16 18:57:32 volumio volumio[4090]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 16 18:57:32 volumio volumio[4090]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 16 18:57:32 volumio volumio[4090]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 16 18:57:32 volumio volumio[4090]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 16 18:57:32 volumio volumio[4090]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 16 18:57:32 volumio volumio[4090]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 16 18:57:32 volumio volumio[4090]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 16 18:57:32 volumio volumio[4090]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 16 18:57:32 volumio sudo[4892]: pam_unix(sudo:session): session closed for user root Dec 16 18:57:32 volumio sudo[4885]: pam_unix(sudo:session): session closed for user root Dec 16 18:57:32 volumio volumio[4090]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Dec 16 18:57:32 volumio sudo[4904]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart qobuz-connect.service Dec 16 18:57:32 volumio sudo[4904]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 16 18:57:32 volumio volumio[4090]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 16 18:57:32 volumio volumio[4090]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Dec 16 18:57:32 volumio systemd[1]: Stopping qobuz-connect.service - Volumio Qobuz Connect Service... Dec 16 18:57:33 volumio qobuz-connect[4688]: 20251216 18:57:33.008 [4688.4688] INFO SampleApp: Stopping Local configuration server Dec 16 18:57:33 volumio volumio[4090]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 16 18:57:33 volumio volumio[4090]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 16 18:57:33 volumio volumio[4090]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 16 18:57:33 volumio volumio[4090]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 16 18:57:33 volumio volumio[4090]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 16 18:57:33 volumio volumio[4090]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 16 18:57:33 volumio volumio[4090]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 16 18:57:33 volumio volumio[4090]: info: CoreCommandRouter::executeOnPlugin: mpd , getPlaybackMode Dec 16 18:57:33 volumio volumio[4090]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Dec 16 18:57:33 volumio volumio[4090]: info: VolumeController:: Volume=58 Mute =false Dec 16 18:57:33 volumio volumio[4090]: info: CoreStateMachine::pushState Dec 16 18:57:33 volumio volumio[4090]: info: CoreCommandRouter::volumioPushState Dec 16 18:57:33 volumio volumio[4090]: info: MRS: Pushing multiroomSync output update for this device Dec 16 18:57:33 volumio volumio[4090]: info: MRS: Pushing multiroomSync output Dec 16 18:57:33 volumio volumio[4090]: info: CoreCommandRouter::volumioGetState Dec 16 18:57:33 volumio sudo[4895]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 16 18:57:33 volumio sudo[4895]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 16 18:57:33 volumio sudo[4895]: pam_unix(sudo:session): session closed for user root Dec 16 18:57:33 volumio volumio[4090]: info: PeppyMeterBasic ---peppymeterbasic status undefined Dec 16 18:57:33 volumio volumio[4090]: SPOTIFY: RECEIVED VOLUMIO VOLUME 58 Dec 16 18:57:33 volumio volumio[4090]: error: Cannot update RT Device info: Error: Reference.set failed: First argument contains undefined in property 'user_devices.pkJP7uJihOgVhJuOFVJOQdFKb2I3.11b52ce8763ae86cf0948604e236adac.state.status' Dec 16 18:57:34 volumio qobuz-connect[4688]: 20251216 18:57:34.196 [4688.4688] INFO SampleApp: shat down connection on UNIX socket Dec 16 18:57:34 volumio volumio[4090]: info: QobuzConnect: Qobuz Connect client [object Object] disconnected Dec 16 18:57:34 volumio volumio[4090]: info: QobuzConnect: setDeactiveState invoked Dec 16 18:57:34 volumio volumio[4090]: info: CoreCommandRouter::volumioGetState Dec 16 18:57:34 volumio systemd[1]: qobuz-connect.service: Deactivated successfully. Dec 16 18:57:34 volumio systemd[1]: Stopped qobuz-connect.service - Volumio Qobuz Connect Service. Dec 16 18:57:34 volumio systemd[1]: Started qobuz-connect.service - Volumio Qobuz Connect Service. Dec 16 18:57:34 volumio sudo[4904]: pam_unix(sudo:session): session closed for user root Dec 16 18:57:34 volumio volumio[4090]: info: Executing endpoint qc_getconfig Dec 16 18:57:34 volumio volumio[4090]: info: CoreCommandRouter::executeOnPlugin: qobuzconnect , onGetConfig Dec 16 18:57:34 volumio qobuz-connect[4912]: 20251216 18:57:34.312 [4912.4912] INFO SampleApp: Started connection to /tmp/qbz-connect.socket UNIX socket Dec 16 18:57:34 volumio volumio[4090]: info: QobuzConnect: Qobuz Connect socket /tmp/qbz-connect.socket connected to client [object Object] Dec 16 18:57:34 volumio volumio[4090]: info: QobuzConnect: QOBUZ Connect daemon connected Dec 16 18:57:34 volumio qobuz-connect[4912]: 20251216 18:57:34.318 [4912.4912] INFO VolumeManager: [0x6f8258]: Setting new playback volume: 75 Dec 16 18:57:34 volumio qobuz-connect[4912]: 20251216 18:57:34.318 [4912.4912] INFO VolumeManager: [0x6f8258]: Setting new mute state: 0 Dec 16 18:57:34 volumio qobuz-connect[4912]: 20251216 18:57:34.318 [4912.4912] INFO QobuzConnect: [0x6f8c28]: Client initialized! Dec 16 18:57:34 volumio qobuz-connect[4912]: 20251216 18:57:34.318 [4912.4912] INFO SampleApp: Starting Avahi advertising, name: Volumio, service name: _qobuz-connect._tcp Dec 16 18:57:34 volumio mpd[4911]: 2025-12-16T18:57:34 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 16 18:57:34 volumio qobuz-connect[4912]: 20251216 18:57:34.327 [4912.4912] INFO LocalConfigManager: [0x6f7b38]: Starting Local Configuration server Dec 16 18:57:34 volumio qobuz-connect[4912]: 20251216 18:57:34.327 [4912.4912] INFO SampleApp: Starting Local configuration server Dec 16 18:57:34 volumio qobuz-connect[4912]: 20251216 18:57:34.328 [4912.4912] INFO SampleApp: Connected to UNIX socket client 0x6e2818 Dec 16 18:57:34 volumio systemd[1]: Started mpd.service - Music Player Daemon. Dec 16 18:57:34 volumio sudo[4872]: pam_unix(sudo:session): session closed for user root Dec 16 18:57:34 volumio volumio[4090]: error: updateQueue error: null Dec 16 18:57:34 volumio qobuz-connect[4912]: 20251216 18:57:34.462 [4912.4912] INFO SampleApp: Playback volume changed: 75 Dec 16 18:57:34 volumio volumio[4090]: info: CoreCommandRouter::volumioGetState Dec 16 18:57:35 volumio volumio[4090]: info: Executing endpoint metavolumio Dec 16 18:57:35 volumio volumio[4090]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Dec 16 18:57:35 volumio volumio[4090]: info: TidalConnect service stoped! Dec 16 18:57:35 volumio volumio[4090]: info: TidalConnect service stoped! Dec 16 18:57:35 volumio volumio[4090]: info: Updating tc_getconfig REST Endpoint for plugin: music_service/tidalconnect Dec 16 18:57:35 volumio volumio[4090]: info: Updating tc_connect REST Endpoint for plugin: music_service/tidalconnect Dec 16 18:57:36 volumio sudo[4929]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start vtcs.service Dec 16 18:57:36 volumio sudo[4929]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 16 18:57:36 volumio systemd[1]: Started vtcs.service - Volumio Tidal Connect Service. Dec 16 18:57:36 volumio sudo[4929]: pam_unix(sudo:session): session closed for user root Dec 16 18:57:36 volumio volumio[4090]: info: Executing endpoint tc_getconfig Dec 16 18:57:36 volumio volumio[4090]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onGetConfig Dec 16 18:57:36 volumio vtcs[4932]: STARTING TidalConnect services, version: 1.5.2.56 Dec 16 18:57:36 volumio vtcs[4932]: STARTED TidalConnect services. Dec 16 18:57:36 volumio volumio[4090]: info: Executing endpoint tc_connect Dec 16 18:57:36 volumio volumio[4090]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onConnect Dec 16 18:57:36 volumio volumio[4090]: info: Connecting to TidalConnect Dec 16 18:57:36 volumio volumio[4090]: info: CoreCommandRouter::servicePushState Dec 16 18:57:36 volumio volumio[4090]: info: CoreStateMachine::pushState Dec 16 18:57:36 volumio volumio[4090]: info: CoreCommandRouter::volumioPushState Dec 16 18:57:36 volumio volumio[4090]: info: MRS: Pushing multiroomSync output update for this device Dec 16 18:57:36 volumio volumio[4090]: info: MRS: Pushing multiroomSync output Dec 16 18:57:36 volumio volumio[4090]: info: CoreCommandRouter::volumioGetState Dec 16 18:57:36 volumio volumio[4090]: info: CorePlayQueue::getTrack 0 Dec 16 18:57:36 volumio volumio[4090]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current spop Received tidalconnect Dec 16 18:57:36 volumio volumio[4090]: info: CoreCommandRouter::servicePushState Dec 16 18:57:36 volumio volumio[4090]: info: CoreStateMachine::pushState Dec 16 18:57:36 volumio volumio[4090]: info: CoreCommandRouter::volumioPushState Dec 16 18:57:36 volumio volumio[4090]: info: MRS: Pushing multiroomSync output update for this device Dec 16 18:57:36 volumio volumio[4090]: info: MRS: Pushing multiroomSync output Dec 16 18:57:36 volumio volumio[4090]: info: CoreCommandRouter::volumioGetState Dec 16 18:57:36 volumio volumio[4090]: info: CorePlayQueue::getTrack 0 Dec 16 18:57:36 volumio volumio[4090]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current spop Received tidalconnect Dec 16 18:57:36 volumio volumio[4090]: info: PeppyMeterBasic ---peppymeterbasic status undefined Dec 16 18:57:36 volumio volumio[4090]: info: PeppyMeterBasic ---peppymeterbasic status undefined Dec 16 18:57:36 volumio volumio[4090]: SPOTIFY: RECEIVED VOLUMIO VOLUME 58 Dec 16 18:57:36 volumio volumio[4090]: SPOTIFY: RECEIVED VOLUMIO VOLUME 58 Dec 16 18:57:36 volumio volumio[4090]: error: Cannot update RT Device info: Error: Reference.set failed: First argument contains undefined in property 'user_devices.pkJP7uJihOgVhJuOFVJOQdFKb2I3.11b52ce8763ae86cf0948604e236adac.state.status' Dec 16 18:57:36 volumio volumio[4090]: error: Cannot update RT Device info: Error: Reference.set failed: First argument contains undefined in property 'user_devices.pkJP7uJihOgVhJuOFVJOQdFKb2I3.11b52ce8763ae86cf0948604e236adac.state.status' Dec 16 18:57:37 volumio volumio[4090]: info: VolumeController::SetAlsaVolume58 Dec 16 18:57:37 volumio volumio[4090]: info: CoreStateMachine::pushState Dec 16 18:57:37 volumio volumio[4090]: info: CoreCommandRouter::volumioPushState Dec 16 18:57:37 volumio volumio[4090]: info: MRS: Pushing multiroomSync output update for this device Dec 16 18:57:37 volumio volumio[4090]: info: MRS: Pushing multiroomSync output Dec 16 18:57:37 volumio volumio[4090]: info: CoreCommandRouter::volumioGetState Dec 16 18:57:37 volumio volumio[4090]: info: PeppyMeterBasic ---peppymeterbasic status undefined Dec 16 18:57:37 volumio volumio[4090]: SPOTIFY: RECEIVED VOLUMIO VOLUME 58 Dec 16 18:57:37 volumio volumio[4090]: error: Cannot update RT Device info: Error: Reference.set failed: First argument contains undefined in property 'user_devices.pkJP7uJihOgVhJuOFVJOQdFKb2I3.11b52ce8763ae86cf0948604e236adac.state.status' Dec 16 18:57:37 volumio sudo[4950]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 16 18:57:37 volumio sudo[4950]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 16 18:57:37 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 16 18:57:37 volumio systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 16 18:57:37 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 16 18:57:37 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 16 18:57:37 volumio sudo[4950]: pam_unix(sudo:session): session closed for user root Dec 16 18:57:37 volumio mpd_monitor.sh[4952]: MPD Monitor Service: Starting MPD Monitor Service Dec 16 18:57:37 volumio volumio[4090]: info: Successfully started MPD Monitor Dec 16 18:57:37 volumio volumio[4090]: info: CoreCommandRouter::volumioVolatilePlay Dec 16 18:57:37 volumio volumio[4090]: ------------------------------------ BT MESSAGE: [FUNC] play Dec 16 18:57:37 volumio volumio[4090]: ------------------------------------ BT MESSAGE: sendPlay skipped: activePlayer not bound or invalid Dec 16 18:57:38 volumio volumio[4090]: info: CoreCommandRouter::volumioVolatilePlay Dec 16 18:57:38 volumio volumio[4090]: ------------------------------------ BT MESSAGE: [FUNC] play Dec 16 18:57:38 volumio volumio[4090]: ------------------------------------ BT MESSAGE: sendPlay skipped: activePlayer not bound or invalid Dec 16 18:57:39 volumio volumio[4090]: info: TidalConnect service started! Dec 16 18:57:39 volumio volumio[4090]: info: Executing endpoint metavolumio Dec 16 18:57:39 volumio volumio[4090]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Dec 16 18:57:39 volumio volumio[4090]: info: CoreCommandRouter::volumioVolatilePlay Dec 16 18:57:39 volumio volumio[4090]: ------------------------------------ BT MESSAGE: [FUNC] play Dec 16 18:57:39 volumio volumio[4090]: ------------------------------------ BT MESSAGE: sendPlay skipped: activePlayer not bound or invalid Dec 16 18:57:44 volumio volumio[4090]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 16 18:57:44 volumio volumio[4090]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Dec 16 18:57:58 volumio go-librespot[4412]: time="2025-12-16T18:57:58+02:00" level=trace msg="received accesspoint ping" Dec 16 18:57:58 volumio go-librespot[4412]: time="2025-12-16T18:57:58+02:00" level=trace msg="received accesspoint pong ack" Dec 16 18:57:59 volumio go-librespot[4412]: time="2025-12-16T18:57:59+02:00" level=trace msg="sent dealer ping" Dec 16 18:57:59 volumio go-librespot[4412]: time="2025-12-16T18:57:59+02:00" level=trace msg="received dealer pong" Dec 16 18:58:03 volumio volumio[4090]: info: Downloading plugin at https://plugins.volumio.workers.dev/pluginsv2/downloadLatestStable/mpdoutput/volumio/bookworm/armhf Dec 16 18:58:05 volumio volumio[4090]: info: END DOWNLOAD: https://plugins.volumio.workers.dev/pluginsv2/downloadLatestStable/mpdoutput/volumio/bookworm/armhf Dec 16 18:58:05 volumio volumio[4090]: info: Folder /tmp/plugins removed Dec 16 18:58:05 volumio volumio[4090]: info: Check plugin dependencies Dec 16 18:58:05 volumio volumio[4090]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 16 18:58:05 volumio volumio[4090]: info: Checking if plugin already exists Dec 16 18:58:05 volumio volumio[4090]: info: Rename folder Dec 16 18:58:05 volumio volumio[4090]: info: Folder /tmp/downloaded_plugin.zip removed Dec 16 18:58:05 volumio volumio[4090]: info: Move to category Dec 16 18:58:05 volumio volumio[4090]: info: Checking if install.sh is present Dec 16 18:58:05 volumio volumio[4090]: info: Executing install.sh Dec 16 18:58:05 volumio sudo[5021]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/sh /data/plugins/audio_interface/mpdoutput/install.sh Dec 16 18:58:05 volumio sudo[5021]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 16 18:58:05 volumio sudo[5021]: pam_unix(sudo:session): session closed for user root Dec 16 18:58:05 volumio volumio[4090]: info: Installing mpd http output Dec 16 18:58:05 volumio volumio[4090]: info: Install script completed Dec 16 18:58:05 volumio volumio[4090]: info: Adding reference to registry Dec 16 18:58:05 volumio volumio[4090]: info: Done installing plugin. Dec 16 18:58:05 volumio volumio[4090]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 16 18:58:05 volumio volumio[4090]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Dec 16 18:58:05 volumio volumio[4090]: Plugin install end detected on script Dec 16 18:58:05 volumio volumio[4090]: info: Folder /tmp/plugins removed Dec 16 18:58:05 volumio volumio[4090]: info: Folder /tmp/downloaded_plugin.zip removed Dec 16 18:58:05 volumio volumio[4090]: info: Folder /data/temp removed Dec 16 18:58:08 volumio volumio[4090]: info: Enabling plugin mpdoutput Dec 16 18:58:08 volumio volumio[4090]: info: Loading plugin "mpdoutput"... Dec 16 18:58:08 volumio volumio[4090]: info: PLUGIN START: mpdoutput Dec 16 18:58:08 volumio volumio[4090]: info: Done. Dec 16 18:58:17 volumio volumio[4090]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 16 18:58:17 volumio volumio[4090]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Dec 16 18:58:22 volumio volumio[4090]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 16 18:58:25 volumio ntpd[1028]: PROTO: 62.1.105.163 unlink local addr 192.168.1.4 -> Dec 16 18:58:29 volumio go-librespot[4412]: time="2025-12-16T18:58:29+02:00" level=trace msg="sent dealer ping" Dec 16 18:58:29 volumio go-librespot[4412]: time="2025-12-16T18:58:29+02:00" level=trace msg="received dealer pong" Dec 16 18:58:31 volumio volumio[4090]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Dec 16 18:58:31 volumio volumio[4090]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Dec 16 18:58:31 volumio volumio[4090]: info: Creating Spotify config file Dec 16 18:58:31 volumio volumio[4090]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 16 18:58:31 volumio volumio[4090]: info: Spotify config file written Dec 16 18:58:31 volumio sudo[5060]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 16 18:58:31 volumio sudo[5060]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 16 18:58:31 volumio systemd[1]: Starting setdatetime-helper.service - Time Synchronization Helper Service... Dec 16 18:58:31 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 16 18:58:31 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 16 18:58:31 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 16 18:58:31 volumio volumio[4090]: info: Connection to go-librespot Websocket closed Dec 16 18:58:31 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 16 18:58:31 volumio sudo[5060]: pam_unix(sudo:session): session closed for user root Dec 16 18:58:31 volumio go-librespot[5065]: go-librespot daemon starting... Dec 16 18:58:31 volumio go-librespot[5068]: time="2025-12-16T18:58:31+02:00" level=info msg="running go-librespot 0.4.0" Dec 16 18:58:31 volumio go-librespot[5068]: time="2025-12-16T18:58:31+02:00" level=debug msg="app state loaded" Dec 16 18:58:31 volumio go-librespot[5068]: time="2025-12-16T18:58:31+02:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 16 18:58:31 volumio go-librespot[5068]: time="2025-12-16T18:58:31+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]" Dec 16 18:58:31 volumio go-librespot[5068]: time="2025-12-16T18:58:31+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]" Dec 16 18:58:31 volumio go-librespot[5068]: time="2025-12-16T18:58:31+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]" Dec 16 18:58:31 volumio go-librespot[5068]: time="2025-12-16T18:58:31+02:00" level=info msg="zeroconf server listening on port 33811" Dec 16 18:58:31 volumio go-librespot[5068]: time="2025-12-16T18:58:31+02:00" level=debug msg="obtained new client token: AABy1WE6dwqK8uUEto/iMmax2Sd9cVVO/eQt5qj3Hrl9aHJO1sh/KXlP4qh0AyNedVjAF/yDMsgTsUqtZeCnaN7X6S3YCqtvY/kxtplKQXR2jSvobNKN8bLeFDV0pHUrQaA7cjnJ2j/4mtd8lHjmflHocuscwkp627lfZFWDXqCX1oD0Y3majUvvr4yXDQsgIwPNEh/YnodicHcTNE+3q4MZx+VUD1VqqoCN4wcp3W/IMt46Bj1/r/eUWA==" Dec 16 18:58:31 volumio go-librespot[5068]: time="2025-12-16T18:58:31+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Dec 16 18:58:31 volumio go-librespot[5068]: time="2025-12-16T18:58:31+02:00" level=debug msg="completed keyexchange" Dec 16 18:58:31 volumio go-librespot[5068]: time="2025-12-16T18:58:31+02:00" level=debug msg="completed challenge" Dec 16 18:58:31 volumio systemd[1]: setdatetime-helper.service: Deactivated successfully. Dec 16 18:58:31 volumio systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service. Dec 16 18:58:31 volumio go-librespot[5068]: time="2025-12-16T18:58:31+02:00" level=info msg="authenticated AP" username="fi*****sg" Dec 16 18:58:32 volumio go-librespot[5068]: time="2025-12-16T18:58:32+02:00" level=info msg="authenticated Login5" username="fi*****sg" Dec 16 18:58:32 volumio go-librespot[5068]: time="2025-12-16T18:58:32+02:00" level=debug msg="initializing zeroconf session" username="fi*****sg" Dec 16 18:58:32 volumio go-librespot[5068]: time="2025-12-16T18:58:32+02:00" level=debug msg="dealer connection opened" Dec 16 18:58:32 volumio go-librespot[5068]: time="2025-12-16T18:58:32+02:00" level=trace msg="starting accesspoint recv loop" Dec 16 18:58:32 volumio go-librespot[5068]: time="2025-12-16T18:58:32+02:00" level=trace msg="starting dealer recv loop" Dec 16 18:58:32 volumio go-librespot[5068]: time="2025-12-16T18:58:32+02:00" level=trace msg="received accesspoint ping" Dec 16 18:58:32 volumio go-librespot[5068]: time="2025-12-16T18:58:32+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Dec 16 18:58:32 volumio go-librespot[5068]: time="2025-12-16T18:58:32+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Dec 16 18:58:32 volumio go-librespot[5068]: time="2025-12-16T18:58:32+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Dec 16 18:58:32 volumio go-librespot[5068]: time="2025-12-16T18:58:32+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Dec 16 18:58:32 volumio go-librespot[5068]: time="2025-12-16T18:58:32+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Dec 16 18:58:32 volumio go-librespot[5068]: time="2025-12-16T18:58:32+02:00" level=debug msg="received connection id: NjlmMTNjYmQtZjMz...MDAwNTMxMkNERA==" Dec 16 18:58:32 volumio go-librespot[5068]: time="2025-12-16T18:58:32+02:00" level=trace msg="received accesspoint pong ack" Dec 16 18:58:32 volumio volumio[4090]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Dec 16 18:58:32 volumio volumio[4090]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Dec 16 18:58:32 volumio volumio[4090]: info: Creating Spotify config file Dec 16 18:58:32 volumio volumio[4090]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 16 18:58:32 volumio volumio[4090]: info: Spotify config file written Dec 16 18:58:32 volumio go-librespot[5068]: time="2025-12-16T18:58:32+02:00" level=debug msg="put connect state because NEW_DEVICE" Dec 16 18:58:32 volumio sudo[5110]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 16 18:58:32 volumio sudo[5110]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 16 18:58:32 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 16 18:58:32 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 16 18:58:32 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 16 18:58:32 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 16 18:58:32 volumio go-librespot[5112]: go-librespot daemon starting... Dec 16 18:58:32 volumio sudo[5110]: pam_unix(sudo:session): session closed for user root Dec 16 18:58:32 volumio go-librespot[5113]: time="2025-12-16T18:58:32+02:00" level=info msg="running go-librespot 0.4.0" Dec 16 18:58:32 volumio go-librespot[5113]: time="2025-12-16T18:58:32+02:00" level=debug msg="app state loaded" Dec 16 18:58:32 volumio go-librespot[5113]: time="2025-12-16T18:58:32+02:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 16 18:58:32 volumio go-librespot[5113]: time="2025-12-16T18:58:32+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Dec 16 18:58:32 volumio go-librespot[5113]: time="2025-12-16T18:58:32+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]" Dec 16 18:58:32 volumio go-librespot[5113]: time="2025-12-16T18:58:32+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]" Dec 16 18:58:32 volumio go-librespot[5113]: time="2025-12-16T18:58:32+02:00" level=info msg="zeroconf server listening on port 32865" Dec 16 18:58:33 volumio go-librespot[5113]: time="2025-12-16T18:58:33+02:00" level=debug msg="obtained new client token: AAA7kTmY87zmd/A2hgWLJzcjsqfX1E6BwoFSlOPbA9gOZiJQrEnc6gaW7aax8JG5eAv76jzWBUZJWrjVWOr2J06XL0fbkLH7tDRim3jaJ/0lXYwq/tpdBnet2Nme5VmxTfHyHGF1+ayCPlVU7X9sqy/guKgfkL2ibDR/8Xv+2MV9YRWfFNjAipb2BhavaW3+qDV5f8Ks39uIun5D2DTjsPpGA1n7E/WHuC5M3qUl1UjB5Kjf6mhTUDlmRA==" Dec 16 18:58:33 volumio go-librespot[5113]: time="2025-12-16T18:58:33+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Dec 16 18:58:33 volumio go-librespot[5113]: time="2025-12-16T18:58:33+02:00" level=debug msg="completed keyexchange" Dec 16 18:58:33 volumio go-librespot[5113]: time="2025-12-16T18:58:33+02:00" level=debug msg="completed challenge" Dec 16 18:58:33 volumio go-librespot[5113]: time="2025-12-16T18:58:33+02:00" level=info msg="authenticated AP" username="fi*****sg" Dec 16 18:58:33 volumio volumio[4090]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Dec 16 18:58:33 volumio volumio[4090]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Dec 16 18:58:33 volumio volumio[4090]: info: Creating Spotify config file Dec 16 18:58:33 volumio volumio[4090]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 16 18:58:33 volumio volumio[4090]: info: Spotify config file written Dec 16 18:58:33 volumio sudo[5121]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 16 18:58:33 volumio sudo[5121]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 16 18:58:33 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 16 18:58:33 volumio systemd[1]: go-librespot-daemon.service: Killing process 5117 (go-librespot) with signal SIGKILL. Dec 16 18:58:33 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 16 18:58:33 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 16 18:58:33 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 16 18:58:33 volumio go-librespot[5123]: go-librespot daemon starting... Dec 16 18:58:33 volumio sudo[5121]: pam_unix(sudo:session): session closed for user root Dec 16 18:58:33 volumio go-librespot[5124]: time="2025-12-16T18:58:33+02:00" level=info msg="running go-librespot 0.4.0" Dec 16 18:58:33 volumio go-librespot[5124]: time="2025-12-16T18:58:33+02:00" level=debug msg="app state loaded" Dec 16 18:58:33 volumio go-librespot[5124]: time="2025-12-16T18:58:33+02:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 16 18:58:33 volumio go-librespot[5124]: time="2025-12-16T18:58:33+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]" Dec 16 18:58:33 volumio go-librespot[5124]: time="2025-12-16T18:58:33+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]" Dec 16 18:58:33 volumio go-librespot[5124]: time="2025-12-16T18:58:33+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]" Dec 16 18:58:33 volumio go-librespot[5124]: time="2025-12-16T18:58:33+02:00" level=info msg="zeroconf server listening on port 39035" Dec 16 18:58:33 volumio go-librespot[5124]: time="2025-12-16T18:58:33+02:00" level=debug msg="obtained new client token: AACA/yAd7YH8Lxu9jfQ88mleyOvfZDcEUkx6z3sLvfag8Uq+dmFJHMYbjEXdBa8VxnvC6Trqox+2AH6oLEsazv9ZkzRyiAKQXLLiZIp14bHATyHuQyO6lJ3Xn1vmFYbVbOVZWT9p8QCj8Xr9+YvUa8vWIIBF9T9FI7Ms7wSos2WaAQqp11yXwAbumKi3GiObL6Xf256/74QooaJABAM6aTR2MdsbeGOVN34H2/MjIDN8rSsPCR7zxuY9Tg==" Dec 16 18:58:33 volumio go-librespot[5124]: time="2025-12-16T18:58:33+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Dec 16 18:58:33 volumio go-librespot[5124]: time="2025-12-16T18:58:33+02:00" level=debug msg="completed keyexchange" Dec 16 18:58:33 volumio go-librespot[5124]: time="2025-12-16T18:58:33+02:00" level=debug msg="completed challenge" Dec 16 18:58:34 volumio volumio[4090]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Dec 16 18:58:34 volumio volumio[4090]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Dec 16 18:58:34 volumio volumio[4090]: info: Creating Spotify config file Dec 16 18:58:34 volumio volumio[4090]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 16 18:58:34 volumio volumio[4090]: info: Spotify config file written Dec 16 18:58:34 volumio sudo[5132]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 16 18:58:34 volumio sudo[5132]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 16 18:58:34 volumio go-librespot[5124]: time="2025-12-16T18:58:34+02:00" level=info msg="authenticated AP" username="fi*****sg" Dec 16 18:58:34 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 16 18:58:34 volumio systemd[1]: go-librespot-daemon.service: Killing process 5128 (go-librespot) with signal SIGKILL. Dec 16 18:58:34 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 16 18:58:34 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 16 18:58:34 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 16 18:58:34 volumio go-librespot[5134]: go-librespot daemon starting... Dec 16 18:58:34 volumio sudo[5132]: pam_unix(sudo:session): session closed for user root Dec 16 18:58:34 volumio go-librespot[5135]: time="2025-12-16T18:58:34+02:00" level=info msg="running go-librespot 0.4.0" Dec 16 18:58:34 volumio go-librespot[5135]: time="2025-12-16T18:58:34+02:00" level=debug msg="app state loaded" Dec 16 18:58:34 volumio go-librespot[5135]: time="2025-12-16T18:58:34+02:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 16 18:58:34 volumio volumio[4090]: info: Initializing connection to go-librespot Websocket Dec 16 18:58:34 volumio go-librespot[5135]: time="2025-12-16T18:58:34+02:00" level=debug msg="new websocket client" Dec 16 18:58:34 volumio volumio[4090]: info: Connection to go-librespot Websocket established Dec 16 18:58:34 volumio volumio[4090]: info: go-librespot daemon successfully initialized Dec 16 18:58:34 volumio go-librespot[5135]: time="2025-12-16T18:58:34+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 16 18:58:34 volumio go-librespot[5135]: time="2025-12-16T18:58:34+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 16 18:58:34 volumio go-librespot[5135]: time="2025-12-16T18:58:34+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 16 18:58:34 volumio go-librespot[5135]: time="2025-12-16T18:58:34+02:00" level=info msg="zeroconf server listening on port 36667" Dec 16 18:58:34 volumio go-librespot[5135]: time="2025-12-16T18:58:34+02:00" level=debug msg="obtained new client token: AACnDTQA30jbtcVIlaEJk8pmCYz0wAvccU0oL4Qs31th3n2uVreiObSCKHO20cTzd6qcuw2Rls6NR5SVLVysz7e9jCfRSQb0y37gE2fvzivzspAKJbIJ4Fn9taAbTSozlrqTzZdpRIAIP2bDbjgDaCsT9fSbapwO+9zgTAmj4iFe2Ja/l3I7zCBbr/P87uo0m4AKrXAldKOkFlJV12gCoVp/bSHeExTkCZMCsuVStMnkgHuxbPuI+cHRPQ==" Dec 16 18:58:34 volumio go-librespot[5135]: time="2025-12-16T18:58:34+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Dec 16 18:58:34 volumio go-librespot[5135]: time="2025-12-16T18:58:34+02:00" level=debug msg="completed keyexchange" Dec 16 18:58:34 volumio go-librespot[5135]: time="2025-12-16T18:58:34+02:00" level=debug msg="completed challenge" Dec 16 18:58:34 volumio go-librespot[5135]: time="2025-12-16T18:58:34+02:00" level=info msg="authenticated AP" username="fi*****sg" Dec 16 18:58:34 volumio volumio[4090]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Dec 16 18:58:34 volumio volumio[4090]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Dec 16 18:58:34 volumio volumio[4090]: info: Creating Spotify config file Dec 16 18:58:34 volumio volumio[4090]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 16 18:58:34 volumio volumio[4090]: info: Spotify config file written Dec 16 18:58:34 volumio sudo[5144]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 16 18:58:34 volumio sudo[5144]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 16 18:58:34 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 16 18:58:34 volumio systemd[1]: go-librespot-daemon.service: Killing process 5140 (go-librespot) with signal SIGKILL. Dec 16 18:58:34 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 16 18:58:34 volumio volumio[4090]: info: Connection to go-librespot Websocket closed Dec 16 18:58:34 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 16 18:58:34 volumio sudo[5144]: pam_unix(sudo:session): session closed for user root Dec 16 18:58:34 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 16 18:58:34 volumio go-librespot[5146]: go-librespot daemon starting... Dec 16 18:58:34 volumio go-librespot[5147]: time="2025-12-16T18:58:34+02:00" level=info msg="running go-librespot 0.4.0" Dec 16 18:58:34 volumio go-librespot[5147]: time="2025-12-16T18:58:34+02:00" level=debug msg="app state loaded" Dec 16 18:58:34 volumio go-librespot[5147]: time="2025-12-16T18:58:34+02:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 16 18:58:35 volumio go-librespot[5147]: time="2025-12-16T18:58:35+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]" Dec 16 18:58:35 volumio go-librespot[5147]: time="2025-12-16T18:58:35+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]" Dec 16 18:58:35 volumio go-librespot[5147]: time="2025-12-16T18:58:35+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]" Dec 16 18:58:35 volumio go-librespot[5147]: time="2025-12-16T18:58:35+02:00" level=info msg="zeroconf server listening on port 42789" Dec 16 18:58:35 volumio go-librespot[5147]: time="2025-12-16T18:58:35+02:00" level=debug msg="obtained new client token: AAC+PB/MSBwFiDE6dFY8qL4al2ZRsa1WZUfwVPJ6rbqQV8vqaEjljd3hEDmUfZNllMw9o19C5a7fEpIgWVnAIot6cfafMpDhhdEOC8jkRnXFWaTzjr3nApznuPwovxKYKcjuzTpZdPmTwoelzad+1dm6yAvP4LqEGYsJoQGjrhMhbJaH4C30gQq8WG9T0KHTCgNgEaS7nvuk5GTzOBGwqjsU6Az/wxV96JgW4hXd+dcp6S6cCRoh5nBm6A==" Dec 16 18:58:35 volumio go-librespot[5147]: time="2025-12-16T18:58:35+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Dec 16 18:58:35 volumio go-librespot[5147]: time="2025-12-16T18:58:35+02:00" level=debug msg="completed keyexchange" Dec 16 18:58:35 volumio go-librespot[5147]: time="2025-12-16T18:58:35+02:00" level=debug msg="completed challenge" Dec 16 18:58:35 volumio volumio[4090]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Dec 16 18:58:35 volumio volumio[4090]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Dec 16 18:58:35 volumio volumio[4090]: info: Creating Spotify config file Dec 16 18:58:35 volumio volumio[4090]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 16 18:58:35 volumio volumio[4090]: info: Spotify config file written Dec 16 18:58:35 volumio sudo[5155]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 16 18:58:35 volumio sudo[5155]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 16 18:58:35 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 16 18:58:35 volumio systemd[1]: go-librespot-daemon.service: Killing process 5149 (go-librespot) with signal SIGKILL. Dec 16 18:58:35 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 16 18:58:35 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 16 18:58:35 volumio systemd[1]: go-librespot-daemon.service: Start request repeated too quickly. Dec 16 18:58:35 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'start-limit-hit'. Dec 16 18:58:35 volumio systemd[1]: Failed to start go-librespot-daemon.service - go-librespot Daemon. Dec 16 18:58:35 volumio sudo[5155]: pam_unix(sudo:session): session closed for user root Dec 16 18:58:35 volumio volumio[4090]: error: Cannot start Go-librespot Daemon: Error: Command failed: /usr/bin/sudo systemctl restart go-librespot-daemon.service Dec 16 18:58:35 volumio volumio[4090]: Job for go-librespot-daemon.service failed because start of the service was attempted too often. Dec 16 18:58:35 volumio volumio[4090]: See "systemctl status go-librespot-daemon.service" and "journalctl -xeu go-librespot-daemon.service" for details. Dec 16 18:58:35 volumio volumio[4090]: To force a start use "systemctl reset-failed go-librespot-daemon.service" Dec 16 18:58:35 volumio volumio[4090]: followed by "systemctl start go-librespot-daemon.service" again. Dec 16 18:58:35 volumio volumio[4090]: error: Error initializing go-librespot daemon: Error: Command failed: /usr/bin/sudo systemctl restart go-librespot-daemon.service Dec 16 18:58:35 volumio volumio[4090]: Job for go-librespot-daemon.service failed because start of the service was attempted too often. Dec 16 18:58:35 volumio volumio[4090]: See "systemctl status go-librespot-daemon.service" and "journalctl -xeu go-librespot-daemon.service" for details. Dec 16 18:58:35 volumio volumio[4090]: To force a start use "systemctl reset-failed go-librespot-daemon.service" Dec 16 18:58:35 volumio volumio[4090]: followed by "systemctl start go-librespot-daemon.service" again. Dec 16 18:58:35 volumio volumio[4090]: info: go-librespot daemon successfully initialized Dec 16 18:58:36 volumio volumio[4090]: info: go-librespot daemon successfully initialized Dec 16 18:58:37 volumio volumio[4090]: info: go-librespot daemon successfully initialized Dec 16 18:58:37 volumio volumio[4090]: info: Getting Spotify volume Dec 16 18:58:37 volumio volumio[4090]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 16 18:58:37 volumio volumio[4090]: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 16 18:58:37 volumio volumio[4090]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Dec 16 18:58:37 volumio volumio[4090]: errno: -111, Dec 16 18:58:37 volumio volumio[4090]: code: 'ECONNREFUSED', Dec 16 18:58:37 volumio volumio[4090]: syscall: 'connect', Dec 16 18:58:37 volumio volumio[4090]: address: '127.0.0.1', Dec 16 18:58:37 volumio volumio[4090]: port: 9879, Dec 16 18:58:37 volumio volumio[4090]: response: undefined Dec 16 18:58:37 volumio volumio[4090]: } Dec 16 18:58:37 volumio volumio[4090]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 16 18:58:37 volumio sudo[5174]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-16 18:57' Dec 16 18:58:37 volumio sudo[5174]: 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"