-- Logs begin at Thu 2019-02-14 11:11:59 CET, end at Mon 2025-09-08 15:19:17 CEST. -- Sep 08 15:18:01 volumio-room go-librespot[8245]: time="2025-09-08T15:18:01+02:00" level=debug msg="update volume requested to 19004/65535" Sep 08 15:18:01 volumio-room go-librespot[8245]: time="2025-09-08T15:18:01+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 08 15:18:01 volumio-room go-librespot[8245]: time="2025-09-08T15:18:01+02:00" level=trace msg="emitting websocket event: volume" Sep 08 15:18:01 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":29,"max":100}} Sep 08 15:18:01 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 29 Sep 08 15:18:01 volumio-room volumio[846]: info: Setting Volumio Volume from Spotify: 29 Sep 08 15:18:01 volumio-room volumio[846]: info: VolumeController::SetAlsaVolume29 Sep 08 15:18:01 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:18:01 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 08 15:18:01 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:18:01 volumio-room go-librespot[8245]: time="2025-09-08T15:18:01+02:00" level=debug msg="update volume requested to 18349/65535" Sep 08 15:18:01 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:18:01 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:18:02 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:02 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":29,"max":100}} Sep 08 15:18:02 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 29 Sep 08 15:18:02 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 29 Sep 08 15:18:02 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 29 Sep 08 15:18:02 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:18:02 volumio-room volumio[846]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: xcb_connection_has_error() returned true Sep 08 15:18:02 volumio-room volumio[846]: amixer: Unable to find simple control 'SoftMaster',0 Sep 08 15:18:02 volumio-room go-librespot[8245]: time="2025-09-08T15:18:02+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 08 15:18:02 volumio-room go-librespot[8245]: time="2025-09-08T15:18:02+02:00" level=trace msg="emitting websocket event: volume" Sep 08 15:18:02 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":28,"max":100}} Sep 08 15:18:02 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 28 Sep 08 15:18:02 volumio-room volumio[846]: info: Setting Volumio Volume from Spotify: 28 Sep 08 15:18:02 volumio-room volumio[846]: info: VolumeController::SetAlsaVolume28 Sep 08 15:18:02 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:18:02 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 08 15:18:02 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:18:02 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:18:02 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:18:02 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:02 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":28,"max":100}} Sep 08 15:18:02 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 28 Sep 08 15:18:02 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 28 Sep 08 15:18:02 volumio-room go-librespot[8245]: time="2025-09-08T15:18:02+02:00" level=debug msg="update volume requested to 16383/65535" Sep 08 15:18:02 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 28 Sep 08 15:18:02 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:18:02 volumio-room volumio[846]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: xcb_connection_has_error() returned true Sep 08 15:18:02 volumio-room volumio[846]: amixer: Unable to find simple control 'SoftMaster',0 Sep 08 15:18:02 volumio-room go-librespot[8245]: time="2025-09-08T15:18:02+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 08 15:18:02 volumio-room go-librespot[8245]: time="2025-09-08T15:18:02+02:00" level=trace msg="emitting websocket event: volume" Sep 08 15:18:02 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":25,"max":100}} Sep 08 15:18:02 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 25 Sep 08 15:18:02 volumio-room volumio[846]: info: Setting Volumio Volume from Spotify: 25 Sep 08 15:18:02 volumio-room volumio[846]: info: VolumeController::SetAlsaVolume25 Sep 08 15:18:02 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:18:02 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 08 15:18:02 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:18:02 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:18:02 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:18:02 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:02 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":25,"max":100}} Sep 08 15:18:02 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 25 Sep 08 15:18:02 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 25 Sep 08 15:18:02 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 25 Sep 08 15:18:02 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:18:02 volumio-room volumio[846]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: xcb_connection_has_error() returned true Sep 08 15:18:02 volumio-room volumio[846]: amixer: Unable to find simple control 'SoftMaster',0 Sep 08 15:18:02 volumio-room go-librespot[8245]: time="2025-09-08T15:18:02+02:00" level=debug msg="update volume requested to 11796/65535" Sep 08 15:18:02 volumio-room go-librespot[8245]: time="2025-09-08T15:18:02+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 08 15:18:02 volumio-room go-librespot[8245]: time="2025-09-08T15:18:02+02:00" level=trace msg="emitting websocket event: volume" Sep 08 15:18:02 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":18,"max":100}} Sep 08 15:18:02 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 18 Sep 08 15:18:02 volumio-room volumio[846]: info: Setting Volumio Volume from Spotify: 18 Sep 08 15:18:02 volumio-room volumio[846]: info: VolumeController::SetAlsaVolume18 Sep 08 15:18:02 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:18:02 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 08 15:18:02 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:18:02 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:18:02 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:18:02 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:02 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":18,"max":100}} Sep 08 15:18:02 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 18 Sep 08 15:18:02 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 18 Sep 08 15:18:02 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 18 Sep 08 15:18:02 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:18:02 volumio-room volumio[846]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: xcb_connection_has_error() returned true Sep 08 15:18:02 volumio-room volumio[846]: amixer: Unable to find simple control 'SoftMaster',0 Sep 08 15:18:03 volumio-room go-librespot[8245]: time="2025-09-08T15:18:03+02:00" level=debug msg="update volume requested to 11140/65535" Sep 08 15:18:03 volumio-room go-librespot[8245]: time="2025-09-08T15:18:03+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 08 15:18:03 volumio-room go-librespot[8245]: time="2025-09-08T15:18:03+02:00" level=trace msg="emitting websocket event: volume" Sep 08 15:18:03 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":17,"max":100}} Sep 08 15:18:03 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 17 Sep 08 15:18:03 volumio-room volumio[846]: info: Setting Volumio Volume from Spotify: 17 Sep 08 15:18:03 volumio-room volumio[846]: info: VolumeController::SetAlsaVolume17 Sep 08 15:18:03 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:18:03 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 08 15:18:03 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:18:03 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:18:03 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:18:03 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:03 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":17,"max":100}} Sep 08 15:18:03 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 17 Sep 08 15:18:03 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 17 Sep 08 15:18:03 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 17 Sep 08 15:18:03 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:18:03 volumio-room volumio[846]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: xcb_connection_has_error() returned true Sep 08 15:18:03 volumio-room volumio[846]: amixer: Unable to find simple control 'SoftMaster',0 Sep 08 15:18:04 volumio-room go-librespot[8245]: time="2025-09-08T15:18:04+02:00" level=debug msg="update volume requested to 11796/65535" Sep 08 15:18:04 volumio-room go-librespot[8245]: time="2025-09-08T15:18:04+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 08 15:18:04 volumio-room go-librespot[8245]: time="2025-09-08T15:18:04+02:00" level=trace msg="emitting websocket event: volume" Sep 08 15:18:04 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":18,"max":100}} Sep 08 15:18:04 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 18 Sep 08 15:18:04 volumio-room volumio[846]: info: Setting Volumio Volume from Spotify: 18 Sep 08 15:18:04 volumio-room volumio[846]: info: VolumeController::SetAlsaVolume18 Sep 08 15:18:04 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:18:04 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 08 15:18:04 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:18:04 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:18:04 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:18:04 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:04 volumio-room go-librespot[8245]: time="2025-09-08T15:18:04+02:00" level=debug msg="update volume requested to 12451/65535" Sep 08 15:18:04 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":18,"max":100}} Sep 08 15:18:04 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 18 Sep 08 15:18:05 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 18 Sep 08 15:18:05 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 18 Sep 08 15:18:05 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:18:05 volumio-room volumio[846]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: xcb_connection_has_error() returned true Sep 08 15:18:05 volumio-room volumio[846]: amixer: Unable to find simple control 'SoftMaster',0 Sep 08 15:18:05 volumio-room go-librespot[8245]: time="2025-09-08T15:18:05+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 08 15:18:05 volumio-room go-librespot[8245]: time="2025-09-08T15:18:05+02:00" level=trace msg="emitting websocket event: volume" Sep 08 15:18:05 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":19,"max":100}} Sep 08 15:18:05 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 19 Sep 08 15:18:05 volumio-room volumio[846]: info: Setting Volumio Volume from Spotify: 19 Sep 08 15:18:05 volumio-room volumio[846]: info: VolumeController::SetAlsaVolume19 Sep 08 15:18:05 volumio-room go-librespot[8245]: time="2025-09-08T15:18:05+02:00" level=debug msg="update volume requested to 14417/65535" Sep 08 15:18:05 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:18:05 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 08 15:18:05 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:18:05 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:18:05 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:18:05 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:05 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":19,"max":100}} Sep 08 15:18:05 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 19 Sep 08 15:18:05 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 19 Sep 08 15:18:05 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 19 Sep 08 15:18:05 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:18:05 volumio-room volumio[846]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: xcb_connection_has_error() returned true Sep 08 15:18:05 volumio-room volumio[846]: amixer: Unable to find simple control 'SoftMaster',0 Sep 08 15:18:05 volumio-room go-librespot[8245]: time="2025-09-08T15:18:05+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 08 15:18:05 volumio-room go-librespot[8245]: time="2025-09-08T15:18:05+02:00" level=trace msg="emitting websocket event: volume" Sep 08 15:18:05 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":22,"max":100}} Sep 08 15:18:05 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 22 Sep 08 15:18:05 volumio-room volumio[846]: info: Setting Volumio Volume from Spotify: 22 Sep 08 15:18:05 volumio-room volumio[846]: info: VolumeController::SetAlsaVolume22 Sep 08 15:18:05 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:18:05 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 08 15:18:05 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:18:05 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:18:05 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:18:05 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:05 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":22,"max":100}} Sep 08 15:18:05 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 22 Sep 08 15:18:05 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 22 Sep 08 15:18:05 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 22 Sep 08 15:18:05 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:18:05 volumio-room volumio[846]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: xcb_connection_has_error() returned true Sep 08 15:18:05 volumio-room volumio[846]: amixer: Unable to find simple control 'SoftMaster',0 Sep 08 15:18:05 volumio-room go-librespot[8245]: time="2025-09-08T15:18:05+02:00" level=debug msg="update volume requested to 16383/65535" Sep 08 15:18:05 volumio-room go-librespot[8245]: time="2025-09-08T15:18:05+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 08 15:18:05 volumio-room go-librespot[8245]: time="2025-09-08T15:18:05+02:00" level=trace msg="emitting websocket event: volume" Sep 08 15:18:05 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":25,"max":100}} Sep 08 15:18:05 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 25 Sep 08 15:18:05 volumio-room volumio[846]: info: Setting Volumio Volume from Spotify: 25 Sep 08 15:18:05 volumio-room volumio[846]: info: VolumeController::SetAlsaVolume25 Sep 08 15:18:05 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:18:05 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 08 15:18:05 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:18:05 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:18:05 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:18:05 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:05 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":25,"max":100}} Sep 08 15:18:05 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 25 Sep 08 15:18:05 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 25 Sep 08 15:18:05 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 25 Sep 08 15:18:05 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:18:05 volumio-room volumio[846]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: amixer: Unable to find simple control 'SoftMaster',0 Sep 08 15:18:07 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 08 15:18:07 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 08 15:18:07 volumio-room volumio[846]: info: Discovery: Getting this device information Sep 08 15:18:07 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:07 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 08 15:18:07 volumio-room go-librespot[8245]: time="2025-09-08T15:18:07+02:00" level=debug msg="fetched chunk 13/13, size: 166313" uri="spotify:track:3HV2Yu22mmHDme4cxOUeuY" Sep 08 15:18:09 volumio-room go-librespot[8245]: time="2025-09-08T15:18:09+02:00" level=debug msg="update volume requested to 17038/65535" Sep 08 15:18:09 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:09 volumio-room go-librespot[8245]: time="2025-09-08T15:18:09+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 08 15:18:09 volumio-room go-librespot[8245]: time="2025-09-08T15:18:09+02:00" level=trace msg="emitting websocket event: volume" Sep 08 15:18:09 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":26,"max":100}} Sep 08 15:18:09 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 26 Sep 08 15:18:09 volumio-room volumio[846]: info: Setting Volumio Volume from Spotify: 26 Sep 08 15:18:09 volumio-room volumio[846]: info: VolumeController::SetAlsaVolume26 Sep 08 15:18:09 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:18:09 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 08 15:18:09 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:18:09 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:18:09 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:18:09 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:09 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":26,"max":100}} Sep 08 15:18:09 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 26 Sep 08 15:18:09 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 26 Sep 08 15:18:09 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 26 Sep 08 15:18:09 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:18:09 volumio-room volumio[846]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: xcb_connection_has_error() returned true Sep 08 15:18:09 volumio-room volumio[846]: amixer: Unable to find simple control 'SoftMaster',0 Sep 08 15:18:09 volumio-room go-librespot[8245]: time="2025-09-08T15:18:09+02:00" level=debug msg="update volume requested to 17694/65535" Sep 08 15:18:09 volumio-room go-librespot[8245]: time="2025-09-08T15:18:09+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 08 15:18:09 volumio-room go-librespot[8245]: time="2025-09-08T15:18:09+02:00" level=trace msg="emitting websocket event: volume" Sep 08 15:18:09 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":27,"max":100}} Sep 08 15:18:09 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 27 Sep 08 15:18:09 volumio-room volumio[846]: info: Setting Volumio Volume from Spotify: 27 Sep 08 15:18:09 volumio-room volumio[846]: info: VolumeController::SetAlsaVolume27 Sep 08 15:18:09 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:18:09 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 08 15:18:09 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:18:09 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:18:09 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:18:09 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:09 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":27,"max":100}} Sep 08 15:18:09 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 27 Sep 08 15:18:09 volumio-room go-librespot[8245]: time="2025-09-08T15:18:09+02:00" level=debug msg="update volume requested to 18349/65535" Sep 08 15:18:09 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 27 Sep 08 15:18:09 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 27 Sep 08 15:18:09 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:18:09 volumio-room volumio[846]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: xcb_connection_has_error() returned true Sep 08 15:18:09 volumio-room volumio[846]: amixer: Unable to find simple control 'SoftMaster',0 Sep 08 15:18:09 volumio-room go-librespot[8245]: time="2025-09-08T15:18:09+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 08 15:18:09 volumio-room go-librespot[8245]: time="2025-09-08T15:18:09+02:00" level=trace msg="emitting websocket event: volume" Sep 08 15:18:09 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":28,"max":100}} Sep 08 15:18:09 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 28 Sep 08 15:18:09 volumio-room volumio[846]: info: Setting Volumio Volume from Spotify: 28 Sep 08 15:18:09 volumio-room volumio[846]: info: VolumeController::SetAlsaVolume28 Sep 08 15:18:10 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:18:10 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 08 15:18:10 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:18:10 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:18:10 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:18:10 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:10 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":28,"max":100}} Sep 08 15:18:10 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 28 Sep 08 15:18:10 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 28 Sep 08 15:18:10 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 28 Sep 08 15:18:10 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:18:10 volumio-room volumio[846]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: xcb_connection_has_error() returned true Sep 08 15:18:10 volumio-room volumio[846]: amixer: Unable to find simple control 'SoftMaster',0 Sep 08 15:18:19 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:19 volumio-room volumio[846]: info: Listing playlists Sep 08 15:18:19 volumio-room volumio[846]: info: Listing playlists Sep 08 15:18:21 volumio-room go-librespot[8245]: time="2025-09-08T15:18:21+02:00" level=trace msg="sent dealer ping" Sep 08 15:18:21 volumio-room go-librespot[8245]: time="2025-09-08T15:18:21+02:00" level=trace msg="received dealer pong" Sep 08 15:18:21 volumio-room volumio[846]: info: CALLMETHOD: audio_interface alsa_controller saveVolumeOptions [object Object] Sep 08 15:18:21 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , saveVolumeOptions Sep 08 15:18:21 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:21 volumio-room volumio[846]: info: Restoring Previous Volume level: 28 false true Sep 08 15:18:21 volumio-room volumio[846]: info: VolumeController::SetAlsaVolume100 Sep 08 15:18:21 volumio-room volumio[846]: info: Volume configurations have been set Sep 08 15:18:21 volumio-room volumio[846]: info: QobuzConnect: setDeactiveState invoked Sep 08 15:18:21 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:21 volumio-room vtcs[10774]: [2025-09-08 15:18:21.321] [tisoc] [error] [SpkconServer.cpp:375] recv error. socket disconnected Sep 08 15:18:21 volumio-room vtcs[10774]: [2025-09-08 15:18:21.321] [tisoc] [warning] [SessionManagerImpl.cpp:240] Illegal State: IDLE Sep 08 15:18:21 volumio-room volumio[846]: xcb_connection_has_error() returned true Sep 08 15:18:21 volumio-room volumio[846]: info: CoreCommandRouter::volumioUpdateVolumeSettings Sep 08 15:18:21 volumio-room volumio[846]: info: Updating Volume Controller Parameters: Device: 2 Name: softvolume Mixer: SoftMaster Max Vol: 100 Vol Curve; logarithmic Vol Steps: 5 Sep 08 15:18:21 volumio-room sudo[10912]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Sep 08 15:18:21 volumio-room sudo[10912]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 08 15:18:21 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , setExternalVolume Sep 08 15:18:21 volumio-room volumio[846]: info: Disabling external Volume Control Sep 08 15:18:21 volumio-room systemd[1]: Stopping Volumio Tidal Connect Service... Sep 08 15:18:21 volumio-room systemd[1]: vtcs.service: Main process exited, code=killed, status=15/TERM Sep 08 15:18:21 volumio-room systemd[1]: vtcs.service: Succeeded. Sep 08 15:18:21 volumio-room systemd[1]: Stopped Volumio Tidal Connect Service. Sep 08 15:18:21 volumio-room volumio[846]: info: CoreCommandRouter::getUIConfigOnPlugin Sep 08 15:18:21 volumio-room sudo[10912]: pam_unix(sudo:session): session closed for user root Sep 08 15:18:21 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:18:21 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 08 15:18:21 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:18:21 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:18:21 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:18:21 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:21 volumio-room sudo[10925]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Sep 08 15:18:21 volumio-room sudo[10925]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 08 15:18:21 volumio-room sudo[10925]: pam_unix(sudo:session): session closed for user root Sep 08 15:18:21 volumio-room volumio[846]: ------------------------------------ BT MESSAGE: BT STATUS: running Sep 08 15:18:21 volumio-room sudo[10931]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed qobuz-connect.service Sep 08 15:18:21 volumio-room sudo[10931]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 08 15:18:21 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Sep 08 15:18:21 volumio-room volumio[846]: SPOTIFY: SPOTIFY VOLUME 28 Sep 08 15:18:21 volumio-room volumio[846]: SPOTIFY: VOLUMIO VOLUME 100 Sep 08 15:18:21 volumio-room volumio[846]: SPOTIFY: DELTA VOLUME ENOUGH: true Sep 08 15:18:21 volumio-room volumio[846]: info: Setting Spotify Volume from Volumio: 100 Sep 08 15:18:21 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Sep 08 15:18:21 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:18:21 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:18:21 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 08 15:18:21 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:18:21 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:18:21 volumio-room sudo[10931]: pam_unix(sudo:session): session closed for user root Sep 08 15:18:21 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:18:21 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:21 volumio-room volumio[846]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: xcb_connection_has_error() returned true Sep 08 15:18:21 volumio-room volumio[846]: amixer: Unable to find simple control 'SoftMaster',0 Sep 08 15:18:21 volumio-room volumio[846]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: xcb_connection_has_error() returned true Sep 08 15:18:21 volumio-room volumio[846]: amixer: Unable to find simple control 'SoftMaster',0 Sep 08 15:18:21 volumio-room sudo[10934]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart qobuz-connect.service Sep 08 15:18:21 volumio-room sudo[10934]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 08 15:18:21 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:18:21 volumio-room systemd[1]: Stopping Volumio Qobuz Connect Service... Sep 08 15:18:21 volumio-room qobuz-connect[10773]: 20250908 15:18:21.744 [10773.10773] INFO SampleApp: Stopping Local configuration server Sep 08 15:18:21 volumio-room qobuz-connect[10773]: 20250908 15:18:21.755 [10773.10773] INFO SampleApp: shat down connection on UNIX socket Sep 08 15:18:21 volumio-room systemd[1]: qobuz-connect.service: Succeeded. Sep 08 15:18:21 volumio-room systemd[1]: Stopped Volumio Qobuz Connect Service. Sep 08 15:18:21 volumio-room systemd[1]: Started Volumio Qobuz Connect Service. Sep 08 15:18:21 volumio-room sudo[10934]: pam_unix(sudo:session): session closed for user root Sep 08 15:18:21 volumio-room volumio[846]: xcb_connection_has_error() returned true Sep 08 15:18:21 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Sep 08 15:18:21 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 08 15:18:21 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Sep 08 15:18:21 volumio-room volumio[846]: info: Getting Alsa Cards List without I2S DAC Sep 08 15:18:21 volumio-room volumio[846]: xcb_connection_has_error() returned true Sep 08 15:18:21 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2SNumber Sep 08 15:18:21 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 08 15:18:21 volumio-room volumio[846]: xcb_connection_has_error() returned true Sep 08 15:18:22 volumio-room volumio[846]: xcb_connection_has_error() returned true Sep 08 15:18:22 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Sep 08 15:18:22 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Sep 08 15:18:22 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: mpd , getPlaybackMode Sep 08 15:18:22 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Sep 08 15:18:22 volumio-room volumio[846]: ------------------------------------ BT MESSAGE: BT STATUS: running Sep 08 15:18:22 volumio-room volumio[846]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Sep 08 15:18:22 volumio-room volumio[846]: info: QobuzConnect: Qobuz Connect client [object Object] disconnected Sep 08 15:18:22 volumio-room volumio[846]: info: QobuzConnect: setDeactiveState invoked Sep 08 15:18:22 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:22 volumio-room volumio[846]: info: Executing endpoint qc_getconfig Sep 08 15:18:22 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: qobuzconnect , onGetConfig Sep 08 15:18:22 volumio-room qobuz-connect[10937]: 20250908 15:18:22.113 [10937.10937] INFO SampleApp: Started connection to /tmp/qbz-connect.socket UNIX socket Sep 08 15:18:22 volumio-room volumio[846]: info: QobuzConnect: Qobuz Connect socket /tmp/qbz-connect.socket connected to client [object Object] Sep 08 15:18:22 volumio-room volumio[846]: info: QobuzConnect: QOBUZ Connect daemon connected Sep 08 15:18:22 volumio-room qobuz-connect[10937]: 20250908 15:18:22.121 [10937.10937] INFO VolumeManager: [0x80e8b0]: Setting new playback volume: 75 Sep 08 15:18:22 volumio-room qobuz-connect[10937]: 20250908 15:18:22.121 [10937.10937] INFO VolumeManager: [0x80e8b0]: Setting new mute state: 0 Sep 08 15:18:22 volumio-room qobuz-connect[10937]: 20250908 15:18:22.121 [10937.10937] INFO QobuzConnect: [0x80f280]: Client initialized! Sep 08 15:18:22 volumio-room qobuz-connect[10937]: 20250908 15:18:22.121 [10937.10937] INFO SampleApp: Starting Avahi advertising, name: Volumio room, service name: _qobuz-connect._tcp Sep 08 15:18:22 volumio-room qobuz-connect[10937]: 20250908 15:18:22.133 [10937.10937] INFO LocalConfigManager: [0x80e190]: Starting Local Configuration server Sep 08 15:18:22 volumio-room qobuz-connect[10937]: 20250908 15:18:22.133 [10937.10937] INFO SampleApp: Starting Local configuration server Sep 08 15:18:22 volumio-room qobuz-connect[10937]: 20250908 15:18:22.134 [10937.10937] INFO SampleApp: Connected to UNIX socket client 0x803f60 Sep 08 15:18:22 volumio-room volumio[846]: info: VolumeController::SetAlsaVolume0 Sep 08 15:18:22 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:18:22 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 08 15:18:22 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:18:22 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:18:22 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:18:22 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:22 volumio-room volumio[846]: info: VolumeController::SetAlsaVolume0 Sep 08 15:18:22 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:18:22 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:18:22 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:18:22 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:18:22 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:22 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:18:22 volumio-room qobuz-connect[10937]: 20250908 15:18:22.262 [10937.10937] INFO SampleApp: Playback volume changed: 75 Sep 08 15:18:22 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:18:22 volumio-room volumio[846]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: xcb_connection_has_error() returned true Sep 08 15:18:22 volumio-room volumio[846]: amixer: Unable to find simple control 'SoftMaster',0 Sep 08 15:18:22 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:22 volumio-room volumio[846]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: xcb_connection_has_error() returned true Sep 08 15:18:22 volumio-room volumio[846]: amixer: Unable to find simple control 'SoftMaster',0 Sep 08 15:18:22 volumio-room volumio[846]: info: VolumeController::SetAlsaVolume0 Sep 08 15:18:22 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:18:22 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 08 15:18:22 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:18:22 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:18:22 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:18:22 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:22 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:18:22 volumio-room volumio[846]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: xcb_connection_has_error() returned true Sep 08 15:18:22 volumio-room volumio[846]: amixer: Unable to find simple control 'SoftMaster',0 Sep 08 15:18:23 volumio-room volumio[846]: SPOTIFY: SETTING SPOTIFY VOLUME 100 Sep 08 15:18:23 volumio-room volumio[846]: info: Sending Spotify command with payload to local API: /player/volume Sep 08 15:18:23 volumio-room go-librespot[8245]: time="2025-09-08T15:18:23+02:00" level=debug msg="update volume requested to 65535/65535" Sep 08 15:18:23 volumio-room go-librespot[8245]: time="2025-09-08T15:18:23+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 08 15:18:23 volumio-room go-librespot[8245]: time="2025-09-08T15:18:23+02:00" level=trace msg="emitting websocket event: volume" Sep 08 15:18:23 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":100,"max":100}} Sep 08 15:18:23 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 100 Sep 08 15:18:23 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":100,"max":100}} Sep 08 15:18:23 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 100 Sep 08 15:18:23 volumio-room volumio[846]: info: VolumeController::SetAlsaVolume0 Sep 08 15:18:23 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:18:23 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 08 15:18:23 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:18:23 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:18:23 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:18:23 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:23 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:18:23 volumio-room volumio[846]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: xcb_connection_has_error() returned true Sep 08 15:18:23 volumio-room volumio[846]: amixer: Unable to find simple control 'SoftMaster',0 Sep 08 15:18:24 volumio-room volumio[846]: info: TidalConnect service stoped! Sep 08 15:18:24 volumio-room volumio[846]: info: TidalConnect service stoped! Sep 08 15:18:24 volumio-room volumio[846]: info: Updating tc_getconfig REST Endpoint for plugin: music_service/tidalconnect Sep 08 15:18:24 volumio-room volumio[846]: info: Updating tc_connect REST Endpoint for plugin: music_service/tidalconnect Sep 08 15:18:24 volumio-room sudo[10978]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start vtcs.service Sep 08 15:18:24 volumio-room sudo[10978]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 08 15:18:24 volumio-room systemd[1]: Started Volumio Tidal Connect Service. Sep 08 15:18:24 volumio-room sudo[10978]: pam_unix(sudo:session): session closed for user root Sep 08 15:18:25 volumio-room go-librespot[8245]: time="2025-09-08T15:18:25+02:00" level=debug msg="update volume requested to 64880/65535" Sep 08 15:18:25 volumio-room volumio[846]: info: Executing endpoint tc_getconfig Sep 08 15:18:25 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onGetConfig Sep 08 15:18:25 volumio-room vtcs[10980]: STARTING TidalConnect services, version: 1.5.1-beta1 Sep 08 15:18:25 volumio-room vtcs[10980]: [2025-09-08 15:18:25.188] [tisoc] [critical] [DeviceInfo.cpp:52] ioctl error. ret=-1, errno="No such device" Sep 08 15:18:25 volumio-room vtcs[10980]: [2025-09-08 15:18:25.188] [tisoc] [critical] [DeviceInfo.cpp:53] [ASSERT] generateDeviceId(0) Sep 08 15:18:25 volumio-room vtcs[10980]: STARTED TidalConnect services. Sep 08 15:18:25 volumio-room volumio[846]: info: Executing endpoint tc_connect Sep 08 15:18:25 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onConnect Sep 08 15:18:25 volumio-room volumio[846]: info: Connecting to TidalConnect Sep 08 15:18:25 volumio-room volumio[846]: info: CoreCommandRouter::servicePushState Sep 08 15:18:25 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:18:25 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 08 15:18:25 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:18:25 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:18:25 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:18:25 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:25 volumio-room volumio[846]: info: CorePlayQueue::getTrack 0 Sep 08 15:18:25 volumio-room volumio[846]: verbose: STATE SERVICE {"status":"stop","service":"tidalconnect","title":"","artist":"","album":"","albumart":"/albumart","uri":"","icon":"fa fa-spinner","trackType":"tidal","codec":"","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"","channels":2,"random":false,"repeat":false,"repeatSingle":false} Sep 08 15:18:25 volumio-room volumio[846]: verbose: CURRENT POSITION 0 Sep 08 15:18:25 volumio-room volumio[846]: info: CoreStateMachine::syncState stateService stop Sep 08 15:18:25 volumio-room volumio[846]: info: CoreStateMachine::syncState currentStatus play Sep 08 15:18:25 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:18:25 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:18:25 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:18:25 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:25 volumio-room volumio[846]: info: CoreStateMachine::stPlaybackTimer Sep 08 15:18:25 volumio-room volumio[846]: info: CoreCommandRouter::servicePushState Sep 08 15:18:25 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:18:25 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:18:25 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:18:25 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:18:25 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:25 volumio-room volumio[846]: info: CorePlayQueue::getTrack 0 Sep 08 15:18:25 volumio-room volumio[846]: verbose: STATE SERVICE {"status":"stop","service":"tidalconnect","title":"","artist":"","album":"","albumart":"/albumart","uri":"","icon":"fa fa-spinner","trackType":"tidal","codec":"","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"","channels":2,"random":false,"repeat":false,"repeatSingle":false} Sep 08 15:18:25 volumio-room volumio[846]: verbose: CURRENT POSITION 0 Sep 08 15:18:25 volumio-room volumio[846]: info: CoreStateMachine::syncState stateService stop Sep 08 15:18:25 volumio-room volumio[846]: info: CoreStateMachine::syncState currentStatus stop Sep 08 15:18:25 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:18:25 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:18:25 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:18:25 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:18:25 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:25 volumio-room volumio[846]: info: No code Sep 08 15:18:25 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:18:25 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:18:25 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:18:25 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:18:25 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:25 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:18:25 volumio-room volumio[846]: info: [GPIO_Control] Status changed: stop Sep 08 15:18:25 volumio-room volumio[846]: info: [GPIO_Control] Handling event: musicStop Sep 08 15:18:25 volumio-room volumio[846]: info: [GPIO_Control] *** musicStop *** Sep 08 15:18:25 volumio-room volumio[846]: info: [GPIO_Control] Delaying: 6000ms Sep 08 15:18:25 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:18:25 volumio-room volumio[846]: info: [GPIO_Control] Handling event: musicPlay Sep 08 15:18:25 volumio-room volumio[846]: info: [GPIO_Control] *** musicPlay *** Sep 08 15:18:25 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:18:25 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:18:25 volumio-room volumio[846]: info: [GPIO_Control] Turning GPIO 17 On (musicPlay) Sep 08 15:18:25 volumio-room volumio[846]: info: [GPIO_Control] Delaying: 100ms Sep 08 15:18:25 volumio-room go-librespot[8245]: time="2025-09-08T15:18:25+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 08 15:18:25 volumio-room go-librespot[8245]: time="2025-09-08T15:18:25+02:00" level=trace msg="emitting websocket event: volume" Sep 08 15:18:25 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":99,"max":100}} Sep 08 15:18:25 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 99 Sep 08 15:18:25 volumio-room volumio[846]: info: Setting Volumio Volume from Spotify: 99 Sep 08 15:18:25 volumio-room volumio[846]: info: VolumeController::SetAlsaVolume99 Sep 08 15:18:25 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:18:25 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 08 15:18:25 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:18:25 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:18:25 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:18:25 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:25 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":99,"max":100}} Sep 08 15:18:25 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 99 Sep 08 15:18:25 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 99 Sep 08 15:18:25 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 99 Sep 08 15:18:25 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:18:25 volumio-room volumio[846]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: xcb_connection_has_error() returned true Sep 08 15:18:25 volumio-room volumio[846]: amixer: Unable to find simple control 'SoftMaster',0 Sep 08 15:18:25 volumio-room go-librespot[8245]: time="2025-09-08T15:18:25+02:00" level=debug msg="update volume requested to 64224/65535" Sep 08 15:18:25 volumio-room volumio[846]: info: [GPIO_Control] Turning GPIO 17 Off (musicPlay) Sep 08 15:18:25 volumio-room volumio[846]: info: VolumeController::SetAlsaVolume28 Sep 08 15:18:25 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:18:25 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 08 15:18:25 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:18:25 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:18:25 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:18:25 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:25 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 28 Sep 08 15:18:25 volumio-room volumio[846]: SPOTIFY: SPOTIFY VOLUME 99 Sep 08 15:18:25 volumio-room volumio[846]: SPOTIFY: VOLUMIO VOLUME 28 Sep 08 15:18:25 volumio-room volumio[846]: SPOTIFY: DELTA VOLUME ENOUGH: true Sep 08 15:18:25 volumio-room volumio[846]: info: Setting Spotify Volume from Volumio: 28 Sep 08 15:18:25 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 28 Sep 08 15:18:25 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:18:25 volumio-room volumio[846]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: xcb_connection_has_error() returned true Sep 08 15:18:25 volumio-room volumio[846]: amixer: Unable to find simple control 'SoftMaster',0 Sep 08 15:18:25 volumio-room volumio[846]: An internal error occurred while serving an albumart. Details: SyntaxError: Unexpected token ',' Sep 08 15:18:25 volumio-room volumio[846]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) Sep 08 15:18:25 volumio-room volumio[846]: at next (/volumio/node_modules/express/lib/router/route.js:137:13) Sep 08 15:18:25 volumio-room volumio[846]: at Route.dispatch (/volumio/node_modules/express/lib/router/route.js:112:3) Sep 08 15:18:25 volumio-room volumio[846]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) Sep 08 15:18:25 volumio-room volumio[846]: at /volumio/node_modules/express/lib/router/index.js:281:22 Sep 08 15:18:25 volumio-room volumio[846]: at Function.process_params (/volumio/node_modules/express/lib/router/index.js:335:12) Sep 08 15:18:25 volumio-room volumio[846]: at next (/volumio/node_modules/express/lib/router/index.js:275:10) Sep 08 15:18:25 volumio-room volumio[846]: at allowCrossDomain (/volumio/http/index.js:34:5) Sep 08 15:18:25 volumio-room volumio[846]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) Sep 08 15:18:25 volumio-room volumio[846]: at trim_prefix (/volumio/node_modules/express/lib/router/index.js:317:13) Sep 08 15:18:25 volumio-room volumio[846]: at /volumio/node_modules/express/lib/router/index.js:284:7 Sep 08 15:18:25 volumio-room volumio[846]: at Function.process_params (/volumio/node_modules/express/lib/router/index.js:335:12) Sep 08 15:18:25 volumio-room volumio[846]: at next (/volumio/node_modules/express/lib/router/index.js:275:10) Sep 08 15:18:25 volumio-room volumio[846]: at SendStream.error (/volumio/node_modules/serve-static/index.js:121:7) Sep 08 15:18:25 volumio-room volumio[846]: at SendStream.emit (events.js:315:20) Sep 08 15:18:25 volumio-room volumio[846]: at SendStream.error (/volumio/node_modules/send/index.js:270:17) Sep 08 15:18:25 volumio-room go-librespot[8245]: time="2025-09-08T15:18:25+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 08 15:18:25 volumio-room go-librespot[8245]: time="2025-09-08T15:18:25+02:00" level=trace msg="emitting websocket event: volume" Sep 08 15:18:25 volumio-room go-librespot[8245]: time="2025-09-08T15:18:25+02:00" level=debug msg="update volume requested to 62258/65535" Sep 08 15:18:25 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":98,"max":100}} Sep 08 15:18:25 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 98 Sep 08 15:18:25 volumio-room volumio[846]: info: Setting Volumio Volume from Spotify: 98 Sep 08 15:18:25 volumio-room volumio[846]: info: VolumeController::SetAlsaVolume98 Sep 08 15:18:26 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:18:26 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 08 15:18:26 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:18:26 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:18:26 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:18:26 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:26 volumio-room go-librespot[8245]: time="2025-09-08T15:18:26+02:00" level=debug msg="update volume requested to 57015/65535" Sep 08 15:18:26 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":98,"max":100}} Sep 08 15:18:26 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 98 Sep 08 15:18:26 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Sep 08 15:18:26 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Sep 08 15:18:26 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:18:26 volumio-room volumio[846]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: xcb_connection_has_error() returned true Sep 08 15:18:26 volumio-room volumio[846]: amixer: Unable to find simple control 'SoftMaster',0 Sep 08 15:18:26 volumio-room go-librespot[8245]: time="2025-09-08T15:18:26+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 08 15:18:26 volumio-room go-librespot[8245]: time="2025-09-08T15:18:26+02:00" level=trace msg="emitting websocket event: volume" Sep 08 15:18:26 volumio-room go-librespot[8245]: time="2025-09-08T15:18:26+02:00" level=debug msg="update volume requested to 54394/65535" Sep 08 15:18:26 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":87,"max":100}} Sep 08 15:18:26 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 87 Sep 08 15:18:26 volumio-room volumio[846]: info: Setting Volumio Volume from Spotify: 87 Sep 08 15:18:26 volumio-room volumio[846]: info: VolumeController::SetAlsaVolume87 Sep 08 15:18:26 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:18:26 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 08 15:18:26 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:18:26 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:18:26 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:18:26 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:26 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":87,"max":100}} Sep 08 15:18:26 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 87 Sep 08 15:18:26 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 87 Sep 08 15:18:26 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 87 Sep 08 15:18:26 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:18:26 volumio-room volumio[846]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: xcb_connection_has_error() returned true Sep 08 15:18:26 volumio-room volumio[846]: amixer: Unable to find simple control 'SoftMaster',0 Sep 08 15:18:26 volumio-room vtcs[10980]: [2025-09-08 15:18:26.533] [tisoc] [error] [avahiImpl.cpp:202] entryGroupCallback() err_code : AVAHI_ENTRY_GROUP_COLLISION Sep 08 15:18:26 volumio-room volumio[846]: An internal error occurred while serving an albumart. Details: SyntaxError: Unexpected token ',' Sep 08 15:18:26 volumio-room volumio[846]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) Sep 08 15:18:26 volumio-room volumio[846]: at next (/volumio/node_modules/express/lib/router/route.js:137:13) Sep 08 15:18:26 volumio-room volumio[846]: at Route.dispatch (/volumio/node_modules/express/lib/router/route.js:112:3) Sep 08 15:18:26 volumio-room volumio[846]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) Sep 08 15:18:26 volumio-room volumio[846]: at /volumio/node_modules/express/lib/router/index.js:281:22 Sep 08 15:18:26 volumio-room volumio[846]: at Function.process_params (/volumio/node_modules/express/lib/router/index.js:335:12) Sep 08 15:18:26 volumio-room volumio[846]: at next (/volumio/node_modules/express/lib/router/index.js:275:10) Sep 08 15:18:26 volumio-room volumio[846]: at allowCrossDomain (/volumio/http/index.js:34:5) Sep 08 15:18:26 volumio-room volumio[846]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) Sep 08 15:18:26 volumio-room volumio[846]: at trim_prefix (/volumio/node_modules/express/lib/router/index.js:317:13) Sep 08 15:18:26 volumio-room volumio[846]: at /volumio/node_modules/express/lib/router/index.js:284:7 Sep 08 15:18:26 volumio-room volumio[846]: at Function.process_params (/volumio/node_modules/express/lib/router/index.js:335:12) Sep 08 15:18:26 volumio-room volumio[846]: at next (/volumio/node_modules/express/lib/router/index.js:275:10) Sep 08 15:18:26 volumio-room volumio[846]: at SendStream.error (/volumio/node_modules/serve-static/index.js:121:7) Sep 08 15:18:26 volumio-room volumio[846]: at SendStream.emit (events.js:315:20) Sep 08 15:18:26 volumio-room volumio[846]: at SendStream.error (/volumio/node_modules/send/index.js:270:17) Sep 08 15:18:26 volumio-room go-librespot[8245]: time="2025-09-08T15:18:26+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 08 15:18:26 volumio-room go-librespot[8245]: time="2025-09-08T15:18:26+02:00" level=trace msg="emitting websocket event: volume" Sep 08 15:18:26 volumio-room go-librespot[8245]: time="2025-09-08T15:18:26+02:00" level=debug msg="update volume requested to 49151/65535" Sep 08 15:18:26 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":83,"max":100}} Sep 08 15:18:26 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 83 Sep 08 15:18:26 volumio-room volumio[846]: info: Setting Volumio Volume from Spotify: 83 Sep 08 15:18:26 volumio-room volumio[846]: info: VolumeController::SetAlsaVolume83 Sep 08 15:18:26 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:18:26 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 08 15:18:26 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:18:26 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:18:26 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:18:26 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:26 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":83,"max":100}} Sep 08 15:18:26 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 83 Sep 08 15:18:26 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 83 Sep 08 15:18:26 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 83 Sep 08 15:18:26 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:18:26 volumio-room volumio[846]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: xcb_connection_has_error() returned true Sep 08 15:18:26 volumio-room volumio[846]: amixer: Unable to find simple control 'SoftMaster',0 Sep 08 15:18:27 volumio-room go-librespot[8245]: time="2025-09-08T15:18:27+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 08 15:18:27 volumio-room go-librespot[8245]: time="2025-09-08T15:18:27+02:00" level=trace msg="emitting websocket event: volume" Sep 08 15:18:27 volumio-room go-librespot[8245]: time="2025-09-08T15:18:27+02:00" level=debug msg="update volume requested to 43908/65535" Sep 08 15:18:27 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":75,"max":100}} Sep 08 15:18:27 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 75 Sep 08 15:18:27 volumio-room volumio[846]: info: Setting Volumio Volume from Spotify: 75 Sep 08 15:18:27 volumio-room volumio[846]: info: VolumeController::SetAlsaVolume75 Sep 08 15:18:27 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:18:27 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 08 15:18:27 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:18:27 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:18:27 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:18:27 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:27 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":75,"max":100}} Sep 08 15:18:27 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 75 Sep 08 15:18:27 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 75 Sep 08 15:18:27 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 75 Sep 08 15:18:27 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:18:27 volumio-room volumio[846]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: amixer: Unable to find simple control 'SoftMaster',0 Sep 08 15:18:27 volumio-room volumio[846]: SPOTIFY: SETTING SPOTIFY VOLUME 28 Sep 08 15:18:27 volumio-room volumio[846]: info: Sending Spotify command with payload to local API: /player/volume Sep 08 15:18:27 volumio-room go-librespot[8245]: time="2025-09-08T15:18:27+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 08 15:18:27 volumio-room go-librespot[8245]: time="2025-09-08T15:18:27+02:00" level=trace msg="emitting websocket event: volume" Sep 08 15:18:27 volumio-room go-librespot[8245]: time="2025-09-08T15:18:27+02:00" level=debug msg="update volume requested to 18349/65535" Sep 08 15:18:27 volumio-room go-librespot[8245]: time="2025-09-08T15:18:27+02:00" level=debug msg="update volume requested to 38666/65535" Sep 08 15:18:27 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":67,"max":100}} Sep 08 15:18:27 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 67 Sep 08 15:18:27 volumio-room volumio[846]: info: Setting Volumio Volume from Spotify: 67 Sep 08 15:18:27 volumio-room volumio[846]: info: VolumeController::SetAlsaVolume67 Sep 08 15:18:27 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:18:27 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 08 15:18:27 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:18:27 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:18:27 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:18:27 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:27 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":67,"max":100}} Sep 08 15:18:27 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 67 Sep 08 15:18:27 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 67 Sep 08 15:18:27 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 67 Sep 08 15:18:27 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:18:27 volumio-room volumio[846]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: xcb_connection_has_error() returned true Sep 08 15:18:27 volumio-room volumio[846]: amixer: Unable to find simple control 'SoftMaster',0 Sep 08 15:18:27 volumio-room go-librespot[8245]: time="2025-09-08T15:18:27+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 08 15:18:27 volumio-room go-librespot[8245]: time="2025-09-08T15:18:27+02:00" level=trace msg="emitting websocket event: volume" Sep 08 15:18:27 volumio-room go-librespot[8245]: time="2025-09-08T15:18:27+02:00" level=debug msg="update volume requested to 36044/65535" Sep 08 15:18:27 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":59,"max":100}} Sep 08 15:18:27 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 59 Sep 08 15:18:27 volumio-room volumio[846]: info: Setting Volumio Volume from Spotify: 59 Sep 08 15:18:27 volumio-room volumio[846]: info: VolumeController::SetAlsaVolume59 Sep 08 15:18:27 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:18:27 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 08 15:18:27 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:18:27 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:18:27 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:18:27 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:27 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":59,"max":100}} Sep 08 15:18:27 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 59 Sep 08 15:18:27 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 59 Sep 08 15:18:27 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 59 Sep 08 15:18:27 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:18:27 volumio-room volumio[846]: info: TidalConnect service started! Sep 08 15:18:27 volumio-room volumio[846]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: xcb_connection_has_error() returned true Sep 08 15:18:27 volumio-room volumio[846]: amixer: Unable to find simple control 'SoftMaster',0 Sep 08 15:18:28 volumio-room go-librespot[8245]: time="2025-09-08T15:18:28+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 08 15:18:28 volumio-room go-librespot[8245]: time="2025-09-08T15:18:28+02:00" level=trace msg="emitting websocket event: volume" Sep 08 15:18:28 volumio-room go-librespot[8245]: time="2025-09-08T15:18:28+02:00" level=debug msg="update volume requested to 30801/65535" Sep 08 15:18:28 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":55,"max":100}} Sep 08 15:18:28 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 55 Sep 08 15:18:28 volumio-room volumio[846]: info: Setting Volumio Volume from Spotify: 55 Sep 08 15:18:28 volumio-room volumio[846]: info: VolumeController::SetAlsaVolume55 Sep 08 15:18:28 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:18:28 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 08 15:18:28 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:18:28 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:18:28 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:18:28 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:28 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":55,"max":100}} Sep 08 15:18:28 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 55 Sep 08 15:18:28 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 55 Sep 08 15:18:28 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 55 Sep 08 15:18:28 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:18:28 volumio-room volumio[846]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: xcb_connection_has_error() returned true Sep 08 15:18:28 volumio-room volumio[846]: amixer: Unable to find simple control 'SoftMaster',0 Sep 08 15:18:28 volumio-room volumio[846]: info: Executing endpoint metavolumio Sep 08 15:18:28 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Sep 08 15:18:28 volumio-room volumio[846]: info: Executing endpoint metavolumio Sep 08 15:18:28 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Sep 08 15:18:28 volumio-room volumio[846]: info: Executing endpoint metavolumio Sep 08 15:18:28 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Sep 08 15:18:28 volumio-room go-librespot[8245]: time="2025-09-08T15:18:28+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 08 15:18:28 volumio-room go-librespot[8245]: time="2025-09-08T15:18:28+02:00" level=trace msg="emitting websocket event: volume" Sep 08 15:18:28 volumio-room go-librespot[8245]: time="2025-09-08T15:18:28+02:00" level=debug msg="update volume requested to 29491/65535" Sep 08 15:18:28 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":47,"max":100}} Sep 08 15:18:28 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 47 Sep 08 15:18:28 volumio-room volumio[846]: info: Setting Volumio Volume from Spotify: 47 Sep 08 15:18:28 volumio-room volumio[846]: info: VolumeController::SetAlsaVolume47 Sep 08 15:18:28 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:18:28 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 08 15:18:28 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:18:28 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:18:28 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:18:28 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:28 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":47,"max":100}} Sep 08 15:18:28 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 47 Sep 08 15:18:28 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Sep 08 15:18:28 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Sep 08 15:18:28 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:18:28 volumio-room volumio[846]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: xcb_connection_has_error() returned true Sep 08 15:18:28 volumio-room volumio[846]: amixer: Unable to find simple control 'SoftMaster',0 Sep 08 15:18:29 volumio-room go-librespot[8245]: time="2025-09-08T15:18:29+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 08 15:18:29 volumio-room go-librespot[8245]: time="2025-09-08T15:18:29+02:00" level=trace msg="emitting websocket event: volume" Sep 08 15:18:29 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":45,"max":100}} Sep 08 15:18:29 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 45 Sep 08 15:18:29 volumio-room volumio[846]: info: Setting Volumio Volume from Spotify: 45 Sep 08 15:18:29 volumio-room volumio[846]: info: VolumeController::SetAlsaVolume45 Sep 08 15:18:29 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:18:29 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 08 15:18:29 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:18:29 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:18:29 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:18:29 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:29 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":45,"max":100}} Sep 08 15:18:29 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 45 Sep 08 15:18:29 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 45 Sep 08 15:18:29 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 45 Sep 08 15:18:29 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:18:29 volumio-room volumio[846]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: xcb_connection_has_error() returned true Sep 08 15:18:29 volumio-room volumio[846]: amixer: Unable to find simple control 'SoftMaster',0 Sep 08 15:18:29 volumio-room go-librespot[8245]: time="2025-09-08T15:18:29+02:00" level=debug msg="update volume requested to 30146/65535" Sep 08 15:18:29 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:29 volumio-room go-librespot[8245]: time="2025-09-08T15:18:29+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 08 15:18:29 volumio-room go-librespot[8245]: time="2025-09-08T15:18:29+02:00" level=trace msg="emitting websocket event: volume" Sep 08 15:18:29 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":46,"max":100}} Sep 08 15:18:29 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 46 Sep 08 15:18:29 volumio-room volumio[846]: info: Setting Volumio Volume from Spotify: 46 Sep 08 15:18:29 volumio-room volumio[846]: info: VolumeController::SetAlsaVolume46 Sep 08 15:18:29 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:18:29 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 08 15:18:29 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:18:29 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:18:29 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:18:29 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:29 volumio-room go-librespot[8245]: time="2025-09-08T15:18:29+02:00" level=debug msg="update volume requested to 29490/65535" Sep 08 15:18:29 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":46,"max":100}} Sep 08 15:18:29 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 46 Sep 08 15:18:29 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Sep 08 15:18:29 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Sep 08 15:18:29 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:18:29 volumio-room volumio[846]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: xcb_connection_has_error() returned true Sep 08 15:18:29 volumio-room volumio[846]: amixer: Unable to find simple control 'SoftMaster',0 Sep 08 15:18:29 volumio-room volumio[846]: info: Executing endpoint metavolumio Sep 08 15:18:29 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Sep 08 15:18:29 volumio-room volumio[846]: info: Executing endpoint metavolumio Sep 08 15:18:29 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Sep 08 15:18:29 volumio-room volumio[846]: info: Executing endpoint metavolumio Sep 08 15:18:29 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Sep 08 15:18:30 volumio-room go-librespot[8245]: time="2025-09-08T15:18:30+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 08 15:18:30 volumio-room go-librespot[8245]: time="2025-09-08T15:18:30+02:00" level=trace msg="emitting websocket event: volume" Sep 08 15:18:30 volumio-room go-librespot[8245]: time="2025-09-08T15:18:30+02:00" level=debug msg="update volume requested to 26869/65535" Sep 08 15:18:30 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":45,"max":100}} Sep 08 15:18:30 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 45 Sep 08 15:18:30 volumio-room volumio[846]: info: Setting Volumio Volume from Spotify: 45 Sep 08 15:18:30 volumio-room volumio[846]: info: VolumeController::SetAlsaVolume45 Sep 08 15:18:30 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:18:30 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 08 15:18:30 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:18:30 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:18:30 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:18:30 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:30 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":45,"max":100}} Sep 08 15:18:30 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 45 Sep 08 15:18:30 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 45 Sep 08 15:18:30 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 45 Sep 08 15:18:30 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:18:30 volumio-room volumio[846]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: xcb_connection_has_error() returned true Sep 08 15:18:30 volumio-room volumio[846]: amixer: Unable to find simple control 'SoftMaster',0 Sep 08 15:18:30 volumio-room go-librespot[8245]: time="2025-09-08T15:18:30+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 08 15:18:30 volumio-room go-librespot[8245]: time="2025-09-08T15:18:30+02:00" level=trace msg="emitting websocket event: volume" Sep 08 15:18:30 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":41,"max":100}} Sep 08 15:18:30 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 41 Sep 08 15:18:30 volumio-room volumio[846]: info: Setting Volumio Volume from Spotify: 41 Sep 08 15:18:30 volumio-room volumio[846]: info: VolumeController::SetAlsaVolume41 Sep 08 15:18:30 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:18:30 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 08 15:18:30 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:18:30 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:18:30 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:18:30 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:30 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":41,"max":100}} Sep 08 15:18:30 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 41 Sep 08 15:18:30 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 41 Sep 08 15:18:30 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 41 Sep 08 15:18:30 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:18:30 volumio-room volumio[846]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: xcb_connection_has_error() returned true Sep 08 15:18:30 volumio-room volumio[846]: amixer: Unable to find simple control 'SoftMaster',0 Sep 08 15:18:32 volumio-room go-librespot[8245]: time="2025-09-08T15:18:32+02:00" level=debug msg="update volume requested to 26214/65535" Sep 08 15:18:32 volumio-room go-librespot[8245]: time="2025-09-08T15:18:32+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 08 15:18:32 volumio-room go-librespot[8245]: time="2025-09-08T15:18:32+02:00" level=trace msg="emitting websocket event: volume" Sep 08 15:18:32 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":40,"max":100}} Sep 08 15:18:32 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 40 Sep 08 15:18:32 volumio-room volumio[846]: info: Setting Volumio Volume from Spotify: 40 Sep 08 15:18:32 volumio-room volumio[846]: info: VolumeController::SetAlsaVolume40 Sep 08 15:18:32 volumio-room go-librespot[8245]: time="2025-09-08T15:18:32+02:00" level=debug msg="update volume requested to 25558/65535" Sep 08 15:18:32 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:18:32 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 08 15:18:32 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:18:33 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:18:33 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:18:33 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:33 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":40,"max":100}} Sep 08 15:18:33 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 40 Sep 08 15:18:33 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 40 Sep 08 15:18:33 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:18:33 volumio-room volumio[846]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: xcb_connection_has_error() returned true Sep 08 15:18:33 volumio-room volumio[846]: amixer: Unable to find simple control 'SoftMaster',0 Sep 08 15:18:33 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":39,"max":100}} Sep 08 15:18:33 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 39 Sep 08 15:18:33 volumio-room volumio[846]: info: Setting Volumio Volume from Spotify: 39 Sep 08 15:18:33 volumio-room volumio[846]: info: VolumeController::SetAlsaVolume39 Sep 08 15:18:33 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:18:33 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 08 15:18:33 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:18:33 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:18:33 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:18:33 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:33 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":39,"max":100}} Sep 08 15:18:33 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 39 Sep 08 15:18:33 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 39 Sep 08 15:18:33 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:18:33 volumio-room volumio[846]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: xcb_connection_has_error() returned true Sep 08 15:18:33 volumio-room volumio[846]: amixer: Unable to find simple control 'SoftMaster',0 Sep 08 15:18:33 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":38,"max":100}} Sep 08 15:18:33 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 38 Sep 08 15:18:33 volumio-room volumio[846]: info: Setting Volumio Volume from Spotify: 38 Sep 08 15:18:33 volumio-room volumio[846]: info: VolumeController::SetAlsaVolume38 Sep 08 15:18:33 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:18:33 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 08 15:18:33 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:18:33 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:18:33 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:18:33 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:33 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":38,"max":100}} Sep 08 15:18:33 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 38 Sep 08 15:18:33 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 38 Sep 08 15:18:33 volumio-room go-librespot[8245]: time="2025-09-08T15:18:32+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 08 15:18:33 volumio-room go-librespot[8245]: time="2025-09-08T15:18:32+02:00" level=trace msg="emitting websocket event: volume" Sep 08 15:18:33 volumio-room go-librespot[8245]: time="2025-09-08T15:18:32+02:00" level=debug msg="update volume requested to 24903/65535" Sep 08 15:18:33 volumio-room go-librespot[8245]: time="2025-09-08T15:18:32+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 08 15:18:33 volumio-room go-librespot[8245]: time="2025-09-08T15:18:32+02:00" level=trace msg="emitting websocket event: volume" Sep 08 15:18:33 volumio-room go-librespot[8245]: time="2025-09-08T15:18:32+02:00" level=debug msg="update volume requested to 24247/65535" Sep 08 15:18:33 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:18:33 volumio-room volumio[846]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: xcb_connection_has_error() returned true Sep 08 15:18:33 volumio-room volumio[846]: amixer: Unable to find simple control 'SoftMaster',0 Sep 08 15:18:33 volumio-room go-librespot[8245]: time="2025-09-08T15:18:33+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 08 15:18:33 volumio-room go-librespot[8245]: time="2025-09-08T15:18:33+02:00" level=trace msg="emitting websocket event: volume" Sep 08 15:18:33 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":37,"max":100}} Sep 08 15:18:33 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 37 Sep 08 15:18:33 volumio-room volumio[846]: info: Setting Volumio Volume from Spotify: 37 Sep 08 15:18:33 volumio-room volumio[846]: info: VolumeController::SetAlsaVolume37 Sep 08 15:18:33 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:18:33 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 08 15:18:33 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:18:33 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:18:33 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:18:33 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:33 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":37,"max":100}} Sep 08 15:18:33 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 37 Sep 08 15:18:33 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 37 Sep 08 15:18:33 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 37 Sep 08 15:18:33 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:18:33 volumio-room volumio[846]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: xcb_connection_has_error() returned true Sep 08 15:18:33 volumio-room volumio[846]: amixer: Unable to find simple control 'SoftMaster',0 Sep 08 15:18:34 volumio-room volumiologrotate[487]: ls: cannot access '/var/log/samba/log.wb-VOLUMIO': No such file or directory Sep 08 15:18:34 volumio-room volumiologrotate[487]: ls: cannot access 'ROOM': No such file or directory Sep 08 15:18:35 volumio-room go-librespot[8245]: time="2025-09-08T15:18:35+02:00" level=debug msg="update volume requested to 23592/65535" Sep 08 15:18:36 volumio-room go-librespot[8245]: time="2025-09-08T15:18:36+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 08 15:18:36 volumio-room go-librespot[8245]: time="2025-09-08T15:18:36+02:00" level=trace msg="emitting websocket event: volume" Sep 08 15:18:36 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":36,"max":100}} Sep 08 15:18:36 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 36 Sep 08 15:18:36 volumio-room volumio[846]: info: Setting Volumio Volume from Spotify: 36 Sep 08 15:18:36 volumio-room volumio[846]: info: VolumeController::SetAlsaVolume36 Sep 08 15:18:36 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:18:36 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 08 15:18:36 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:18:36 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:18:36 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:18:36 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:36 volumio-room go-librespot[8245]: time="2025-09-08T15:18:36+02:00" level=debug msg="update volume requested to 22937/65535" Sep 08 15:18:36 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":36,"max":100}} Sep 08 15:18:36 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 36 Sep 08 15:18:36 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 36 Sep 08 15:18:36 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 36 Sep 08 15:18:36 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:18:36 volumio-room volumio[846]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: xcb_connection_has_error() returned true Sep 08 15:18:36 volumio-room volumio[846]: amixer: Unable to find simple control 'SoftMaster',0 Sep 08 15:18:36 volumio-room go-librespot[8245]: time="2025-09-08T15:18:36+02:00" level=debug msg="prefetching next track" uri="spotify:track:14LXUuHHmuce69WPXXwTA5" Sep 08 15:18:36 volumio-room go-librespot[8245]: time="2025-09-08T15:18:36+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 08 15:18:36 volumio-room go-librespot[8245]: time="2025-09-08T15:18:36+02:00" level=trace msg="emitting websocket event: volume" Sep 08 15:18:36 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":35,"max":100}} Sep 08 15:18:36 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 35 Sep 08 15:18:36 volumio-room volumio[846]: info: Setting Volumio Volume from Spotify: 35 Sep 08 15:18:36 volumio-room volumio[846]: info: VolumeController::SetAlsaVolume35 Sep 08 15:18:36 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:18:36 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 08 15:18:36 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:18:36 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:18:36 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:18:36 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:36 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":35,"max":100}} Sep 08 15:18:36 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 35 Sep 08 15:18:36 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 35 Sep 08 15:18:36 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 35 Sep 08 15:18:36 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:18:36 volumio-room volumio[846]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: xcb_connection_has_error() returned true Sep 08 15:18:36 volumio-room volumio[846]: amixer: Unable to find simple control 'SoftMaster',0 Sep 08 15:18:36 volumio-room go-librespot[8245]: time="2025-09-08T15:18:36+02:00" level=debug msg="update volume requested to 21626/65535" Sep 08 15:18:36 volumio-room go-librespot[8245]: time="2025-09-08T15:18:36+02:00" level=debug msg="selected format OGG_VORBIS_320 (ef89be829411ac4784a263869d3771ffa3124906)" uri="spotify:track:14LXUuHHmuce69WPXXwTA5" Sep 08 15:18:36 volumio-room go-librespot[8245]: time="2025-09-08T15:18:36+02:00" level=debug msg="requested aes key for file ef89be829411ac4784a263869d3771ffa3124906, gid: 14LXUuHHmuce69WPXXwTA5" Sep 08 15:18:36 volumio-room go-librespot[8245]: time="2025-09-08T15:18:36+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 08 15:18:36 volumio-room go-librespot[8245]: time="2025-09-08T15:18:36+02:00" level=trace msg="emitting websocket event: volume" Sep 08 15:18:36 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":33,"max":100}} Sep 08 15:18:36 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 33 Sep 08 15:18:36 volumio-room volumio[846]: info: Setting Volumio Volume from Spotify: 33 Sep 08 15:18:36 volumio-room volumio[846]: info: VolumeController::SetAlsaVolume33 Sep 08 15:18:36 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:18:36 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 08 15:18:36 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:18:36 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:18:36 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:18:36 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:36 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":33,"max":100}} Sep 08 15:18:36 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 33 Sep 08 15:18:36 volumio-room go-librespot[8245]: time="2025-09-08T15:18:36+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:14LXUuHHmuce69WPXXwTA5" Sep 08 15:18:36 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 33 Sep 08 15:18:36 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 33 Sep 08 15:18:36 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:18:36 volumio-room volumio[846]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: xcb_connection_has_error() returned true Sep 08 15:18:36 volumio-room volumio[846]: amixer: Unable to find simple control 'SoftMaster',0 Sep 08 15:18:37 volumio-room go-librespot[8245]: time="2025-09-08T15:18:37+02:00" level=debug msg="fetched first chunk of 15, total size is 7506544 bytes" uri="spotify:track:14LXUuHHmuce69WPXXwTA5" Sep 08 15:18:37 volumio-room go-librespot[8245]: time="2025-09-08T15:18:37+02:00" level=info msg="prefetched track \"Les Barricades Mystérieuses - Arr. Fred Thomas\" (duration: 208870ms)" uri="spotify:track:14LXUuHHmuce69WPXXwTA5" Sep 08 15:18:37 volumio-room go-librespot[8245]: time="2025-09-08T15:18:37+02:00" level=debug msg="fetched chunk 1/14, size: 524288" uri="spotify:track:14LXUuHHmuce69WPXXwTA5" Sep 08 15:18:38 volumio-room go-librespot[8245]: time="2025-09-08T15:18:38+02:00" level=debug msg="fetched chunk 3/14, size: 524288" uri="spotify:track:14LXUuHHmuce69WPXXwTA5" Sep 08 15:18:38 volumio-room go-librespot[8245]: time="2025-09-08T15:18:38+02:00" level=debug msg="handling pause player command from 5213bca5ab914ee6fbdd972dab095ac4c7941856" Sep 08 15:18:38 volumio-room go-librespot[8245]: time="2025-09-08T15:18:38+02:00" level=debug msg="pause track at 198026ms" Sep 08 15:18:38 volumio-room go-librespot[8245]: time="2025-09-08T15:18:38+02:00" level=debug msg="fetched chunk 2/14, size: 524288" uri="spotify:track:14LXUuHHmuce69WPXXwTA5" Sep 08 15:18:38 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 08 15:18:38 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 08 15:18:38 volumio-room volumio[846]: info: Discovery: Getting this device information Sep 08 15:18:38 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:38 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 08 15:18:38 volumio-room go-librespot[8245]: time="2025-09-08T15:18:38+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 08 15:18:38 volumio-room go-librespot[8245]: time="2025-09-08T15:18:38+02:00" level=debug msg="sending successful reply for dealer request" Sep 08 15:18:38 volumio-room go-librespot[8245]: time="2025-09-08T15:18:38+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 08 15:18:38 volumio-room go-librespot[8245]: time="2025-09-08T15:18:38+02:00" level=trace msg="emitting websocket event: paused" Sep 08 15:18:38 volumio-room volumio[846]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:3HV2Yu22mmHDme4cxOUeuY","play_origin":""}} Sep 08 15:18:38 volumio-room volumio[846]: SPOTIFY: PUSH STATE SPOTIFY Sep 08 15:18:38 volumio-room volumio[846]: SPOTIFY: {"status":"pause","service":"spop","title":"Nana para Coco y Luna","artist":"Juan Medina, Fran Ramos","album":"Fugaz","albumart":"https://i.scdn.co/image/ab67616d00001e02467efdee6a8562cb1086a12d","uri":"spotify:track:3HV2Yu22mmHDme4cxOUeuY","trackType":"spotify","seek":198000,"duration":226,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Sep 08 15:18:38 volumio-room volumio[846]: info: CoreCommandRouter::servicePushState Sep 08 15:18:38 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:18:38 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 08 15:18:38 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:18:38 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:18:38 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:18:38 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:38 volumio-room volumio[846]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:3HV2Yu22mmHDme4cxOUeuY","play_origin":""}} Sep 08 15:18:38 volumio-room volumio[846]: SPOTIFY: PUSH STATE SPOTIFY Sep 08 15:18:38 volumio-room volumio[846]: SPOTIFY: {"status":"pause","service":"spop","title":"Nana para Coco y Luna","artist":"Juan Medina, Fran Ramos","album":"Fugaz","albumart":"https://i.scdn.co/image/ab67616d00001e02467efdee6a8562cb1086a12d","uri":"spotify:track:3HV2Yu22mmHDme4cxOUeuY","trackType":"spotify","seek":198000,"duration":226,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Sep 08 15:18:38 volumio-room volumio[846]: info: CoreCommandRouter::servicePushState Sep 08 15:18:38 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:18:38 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:18:38 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:18:38 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:18:38 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:38 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 33 Sep 08 15:18:38 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 33 Sep 08 15:18:38 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 33 Sep 08 15:18:38 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 33 Sep 08 15:18:38 volumio-room volumio[846]: info: [GPIO_Control] Status changed: pause Sep 08 15:18:38 volumio-room volumio[846]: info: [GPIO_Control] Handling event: musicPause Sep 08 15:18:38 volumio-room volumio[846]: info: [GPIO_Control] *** musicPause *** Sep 08 15:18:38 volumio-room volumio[846]: info: [GPIO_Control] Delaying: 6000ms Sep 08 15:18:38 volumio-room volumio[846]: info: [GPIO_Control] Status changed: pause Sep 08 15:18:38 volumio-room go-librespot[8245]: time="2025-09-08T15:18:38+02:00" level=debug msg="handling resume player command from 5213bca5ab914ee6fbdd972dab095ac4c7941856" Sep 08 15:18:38 volumio-room go-librespot[8245]: time="2025-09-08T15:18:38+02:00" level=trace msg="seek to 198026ms (diff: 287ms, samples: 8732946, bytes: 6170000)" uri="spotify:track:3HV2Yu22mmHDme4cxOUeuY" Sep 08 15:18:38 volumio-room go-librespot[8245]: time="2025-09-08T15:18:38+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames" Sep 08 15:18:38 volumio-room go-librespot[8245]: time="2025-09-08T15:18:38+02:00" level=debug msg="resume track at 197739ms" Sep 08 15:18:38 volumio-room go-librespot[8245]: time="2025-09-08T15:18:38+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 08 15:18:38 volumio-room go-librespot[8245]: time="2025-09-08T15:18:38+02:00" level=debug msg="sending successful reply for dealer request" Sep 08 15:18:38 volumio-room go-librespot[8245]: time="2025-09-08T15:18:38+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 08 15:18:38 volumio-room go-librespot[8245]: time="2025-09-08T15:18:38+02:00" level=trace msg="emitting websocket event: playing" Sep 08 15:18:38 volumio-room volumio[846]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:3HV2Yu22mmHDme4cxOUeuY","resume":true,"play_origin":""}} Sep 08 15:18:38 volumio-room volumio[846]: SPOTIFY: PUSH STATE SPOTIFY Sep 08 15:18:38 volumio-room volumio[846]: SPOTIFY: {"status":"play","service":"spop","title":"Nana para Coco y Luna","artist":"Juan Medina, Fran Ramos","album":"Fugaz","albumart":"https://i.scdn.co/image/ab67616d00001e02467efdee6a8562cb1086a12d","uri":"spotify:track:3HV2Yu22mmHDme4cxOUeuY","trackType":"spotify","seek":198000,"duration":226,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Sep 08 15:18:38 volumio-room volumio[846]: info: CoreCommandRouter::servicePushState Sep 08 15:18:38 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:18:38 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 08 15:18:38 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:18:38 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:18:38 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:18:38 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:38 volumio-room volumio[846]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:3HV2Yu22mmHDme4cxOUeuY","resume":true,"play_origin":""}} Sep 08 15:18:38 volumio-room volumio[846]: SPOTIFY: PUSH STATE SPOTIFY Sep 08 15:18:38 volumio-room volumio[846]: SPOTIFY: {"status":"play","service":"spop","title":"Nana para Coco y Luna","artist":"Juan Medina, Fran Ramos","album":"Fugaz","albumart":"https://i.scdn.co/image/ab67616d00001e02467efdee6a8562cb1086a12d","uri":"spotify:track:3HV2Yu22mmHDme4cxOUeuY","trackType":"spotify","seek":198000,"duration":226,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Sep 08 15:18:38 volumio-room volumio[846]: info: CoreCommandRouter::servicePushState Sep 08 15:18:38 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:18:38 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:18:38 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:18:38 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:18:38 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:38 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 33 Sep 08 15:18:38 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 33 Sep 08 15:18:38 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 33 Sep 08 15:18:38 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 33 Sep 08 15:18:38 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:18:38 volumio-room volumio[846]: info: [GPIO_Control] Handling event: musicPlay Sep 08 15:18:38 volumio-room volumio[846]: info: [GPIO_Control] *** musicPlay *** Sep 08 15:18:38 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:18:38 volumio-room volumio[846]: info: [GPIO_Control] Turning GPIO 17 On (musicPlay) Sep 08 15:18:38 volumio-room volumio[846]: info: [GPIO_Control] Delaying: 100ms Sep 08 15:18:38 volumio-room volumio[846]: info: [GPIO_Control] Turning GPIO 17 Off (musicPlay) Sep 08 15:18:39 volumio-room volumio[846]: SPOTIFY: PUSH STATE SPOTIFY Sep 08 15:18:39 volumio-room volumio[846]: SPOTIFY: {"status":"play","service":"spop","title":"Nana para Coco y Luna","artist":"Juan Medina, Fran Ramos","album":"Fugaz","albumart":"https://i.scdn.co/image/ab67616d00001e02467efdee6a8562cb1086a12d","uri":"spotify:track:3HV2Yu22mmHDme4cxOUeuY","trackType":"spotify","seek":198000,"duration":226,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Sep 08 15:18:39 volumio-room volumio[846]: info: CoreCommandRouter::servicePushState Sep 08 15:18:39 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:18:39 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:18:39 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:18:39 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:18:39 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:39 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 33 Sep 08 15:18:39 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 33 Sep 08 15:18:39 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:18:39 volumio-room volumio[846]: SPOTIFY: PUSH STATE SPOTIFY Sep 08 15:18:39 volumio-room volumio[846]: SPOTIFY: {"status":"play","service":"spop","title":"Nana para Coco y Luna","artist":"Juan Medina, Fran Ramos","album":"Fugaz","albumart":"https://i.scdn.co/image/ab67616d00001e02467efdee6a8562cb1086a12d","uri":"spotify:track:3HV2Yu22mmHDme4cxOUeuY","trackType":"spotify","seek":198000,"duration":226,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Sep 08 15:18:39 volumio-room volumio[846]: info: CoreCommandRouter::servicePushState Sep 08 15:18:39 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:18:39 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:18:39 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:18:39 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:18:39 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:39 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 33 Sep 08 15:18:39 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 33 Sep 08 15:18:39 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:18:39 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:39 volumio-room volumio[846]: info: Listing playlists Sep 08 15:18:39 volumio-room volumio[846]: info: Listing playlists Sep 08 15:18:42 volumio-room volumio[846]: info: VolumeController::SetAlsaVolume- Sep 08 15:18:42 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:18:42 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 08 15:18:42 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:18:42 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:18:42 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:18:42 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:42 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 28 Sep 08 15:18:42 volumio-room volumio[846]: SPOTIFY: SPOTIFY VOLUME 33 Sep 08 15:18:42 volumio-room volumio[846]: SPOTIFY: VOLUMIO VOLUME 28 Sep 08 15:18:42 volumio-room volumio[846]: SPOTIFY: DELTA VOLUME ENOUGH: true Sep 08 15:18:42 volumio-room volumio[846]: info: Setting Spotify Volume from Volumio: 28 Sep 08 15:18:42 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 28 Sep 08 15:18:42 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:18:42 volumio-room volumio[846]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: xcb_connection_has_error() returned true Sep 08 15:18:42 volumio-room volumio[846]: amixer: Unable to find simple control 'SoftMaster',0 Sep 08 15:18:43 volumio-room volumio[846]: SPOTIFY: SETTING SPOTIFY VOLUME 28 Sep 08 15:18:43 volumio-room volumio[846]: info: Sending Spotify command with payload to local API: /player/volume Sep 08 15:18:43 volumio-room go-librespot[8245]: time="2025-09-08T15:18:43+02:00" level=debug msg="update volume requested to 18349/65535" Sep 08 15:18:43 volumio-room go-librespot[8245]: time="2025-09-08T15:18:43+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 08 15:18:43 volumio-room go-librespot[8245]: time="2025-09-08T15:18:43+02:00" level=trace msg="emitting websocket event: volume" Sep 08 15:18:43 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":28,"max":100}} Sep 08 15:18:43 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 28 Sep 08 15:18:43 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":28,"max":100}} Sep 08 15:18:43 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 28 Sep 08 15:18:44 volumio-room volumio[846]: info: VolumeController::SetAlsaVolume- Sep 08 15:18:44 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:18:44 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 08 15:18:44 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:18:44 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:18:44 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:18:44 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:44 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 23 Sep 08 15:18:44 volumio-room volumio[846]: SPOTIFY: SPOTIFY VOLUME 28 Sep 08 15:18:44 volumio-room volumio[846]: SPOTIFY: VOLUMIO VOLUME 23 Sep 08 15:18:44 volumio-room volumio[846]: SPOTIFY: DELTA VOLUME ENOUGH: true Sep 08 15:18:44 volumio-room volumio[846]: info: Setting Spotify Volume from Volumio: 23 Sep 08 15:18:44 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 23 Sep 08 15:18:44 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:18:44 volumio-room volumio[846]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: xcb_connection_has_error() returned true Sep 08 15:18:44 volumio-room volumio[846]: amixer: Unable to find simple control 'SoftMaster',0 Sep 08 15:18:45 volumio-room volumio[846]: SPOTIFY: SETTING SPOTIFY VOLUME 23 Sep 08 15:18:45 volumio-room volumio[846]: info: Sending Spotify command with payload to local API: /player/volume Sep 08 15:18:45 volumio-room go-librespot[8245]: time="2025-09-08T15:18:45+02:00" level=debug msg="update volume requested to 15073/65535" Sep 08 15:18:46 volumio-room go-librespot[8245]: time="2025-09-08T15:18:46+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 08 15:18:46 volumio-room go-librespot[8245]: time="2025-09-08T15:18:46+02:00" level=trace msg="emitting websocket event: volume" Sep 08 15:18:46 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":23,"max":100}} Sep 08 15:18:46 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 23 Sep 08 15:18:46 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":23,"max":100}} Sep 08 15:18:46 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 23 Sep 08 15:18:46 volumio-room volumio[846]: info: VolumeController::SetAlsaVolume+ Sep 08 15:18:46 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:18:46 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 08 15:18:46 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:18:46 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:18:46 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:18:46 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:46 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 28 Sep 08 15:18:46 volumio-room volumio[846]: SPOTIFY: SPOTIFY VOLUME 23 Sep 08 15:18:46 volumio-room volumio[846]: SPOTIFY: VOLUMIO VOLUME 28 Sep 08 15:18:46 volumio-room volumio[846]: SPOTIFY: DELTA VOLUME ENOUGH: true Sep 08 15:18:46 volumio-room volumio[846]: info: Setting Spotify Volume from Volumio: 28 Sep 08 15:18:46 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 28 Sep 08 15:18:46 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:18:46 volumio-room volumio[846]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: xcb_connection_has_error() returned true Sep 08 15:18:46 volumio-room volumio[846]: amixer: Unable to find simple control 'SoftMaster',0 Sep 08 15:18:47 volumio-room go-librespot[8245]: time="2025-09-08T15:18:47+02:00" level=debug msg="update volume requested to 15728/65535" Sep 08 15:18:47 volumio-room go-librespot[8245]: time="2025-09-08T15:18:47+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 08 15:18:47 volumio-room go-librespot[8245]: time="2025-09-08T15:18:47+02:00" level=trace msg="emitting websocket event: volume" Sep 08 15:18:47 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":24,"max":100}} Sep 08 15:18:47 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 24 Sep 08 15:18:47 volumio-room volumio[846]: info: Setting Volumio Volume from Spotify: 24 Sep 08 15:18:47 volumio-room volumio[846]: info: VolumeController::SetAlsaVolume24 Sep 08 15:18:47 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:18:47 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 08 15:18:47 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:18:47 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:18:47 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:18:47 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:47 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":24,"max":100}} Sep 08 15:18:47 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 24 Sep 08 15:18:47 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 24 Sep 08 15:18:47 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 24 Sep 08 15:18:47 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:18:47 volumio-room volumio[846]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: xcb_connection_has_error() returned true Sep 08 15:18:47 volumio-room volumio[846]: amixer: Unable to find simple control 'SoftMaster',0 Sep 08 15:18:48 volumio-room volumio[846]: SPOTIFY: SETTING SPOTIFY VOLUME 28 Sep 08 15:18:48 volumio-room volumio[846]: info: Sending Spotify command with payload to local API: /player/volume Sep 08 15:18:48 volumio-room go-librespot[8245]: time="2025-09-08T15:18:48+02:00" level=debug msg="update volume requested to 18349/65535" Sep 08 15:18:48 volumio-room go-librespot[8245]: time="2025-09-08T15:18:48+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 08 15:18:48 volumio-room go-librespot[8245]: time="2025-09-08T15:18:48+02:00" level=trace msg="emitting websocket event: volume" Sep 08 15:18:48 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":28,"max":100}} Sep 08 15:18:48 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 28 Sep 08 15:18:48 volumio-room volumio[846]: info: Setting Volumio Volume from Spotify: 28 Sep 08 15:18:48 volumio-room volumio[846]: info: VolumeController::SetAlsaVolume28 Sep 08 15:18:48 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:18:48 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 08 15:18:48 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:18:48 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:18:48 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:18:48 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:48 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":28,"max":100}} Sep 08 15:18:48 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 28 Sep 08 15:18:48 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 28 Sep 08 15:18:48 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 28 Sep 08 15:18:48 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:18:48 volumio-room volumio[846]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: xcb_connection_has_error() returned true Sep 08 15:18:48 volumio-room volumio[846]: amixer: Unable to find simple control 'SoftMaster',0 Sep 08 15:18:48 volumio-room go-librespot[8245]: time="2025-09-08T15:18:48+02:00" level=debug msg="update volume requested to 19004/65535" Sep 08 15:18:48 volumio-room go-librespot[8245]: time="2025-09-08T15:18:48+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 08 15:18:48 volumio-room go-librespot[8245]: time="2025-09-08T15:18:48+02:00" level=trace msg="emitting websocket event: volume" Sep 08 15:18:48 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":29,"max":100}} Sep 08 15:18:48 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 29 Sep 08 15:18:48 volumio-room volumio[846]: info: Setting Volumio Volume from Spotify: 29 Sep 08 15:18:48 volumio-room volumio[846]: info: VolumeController::SetAlsaVolume29 Sep 08 15:18:49 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:18:49 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 08 15:18:49 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:18:49 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:18:49 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:18:49 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:49 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":29,"max":100}} Sep 08 15:18:49 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 29 Sep 08 15:18:49 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 29 Sep 08 15:18:49 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 29 Sep 08 15:18:49 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:18:49 volumio-room volumio[846]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: xcb_connection_has_error() returned true Sep 08 15:18:49 volumio-room volumio[846]: amixer: Unable to find simple control 'SoftMaster',0 Sep 08 15:18:49 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:50 volumio-room go-librespot[8245]: time="2025-09-08T15:18:50+02:00" level=debug msg="update volume requested to 19660/65535" Sep 08 15:18:50 volumio-room go-librespot[8245]: time="2025-09-08T15:18:50+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 08 15:18:50 volumio-room go-librespot[8245]: time="2025-09-08T15:18:50+02:00" level=trace msg="emitting websocket event: volume" Sep 08 15:18:50 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":30,"max":100}} Sep 08 15:18:50 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 30 Sep 08 15:18:50 volumio-room volumio[846]: info: Setting Volumio Volume from Spotify: 30 Sep 08 15:18:50 volumio-room volumio[846]: info: VolumeController::SetAlsaVolume30 Sep 08 15:18:50 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:18:50 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 08 15:18:50 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:18:50 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:18:50 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:18:50 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:50 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":30,"max":100}} Sep 08 15:18:50 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 30 Sep 08 15:18:50 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 30 Sep 08 15:18:50 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 30 Sep 08 15:18:50 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:18:50 volumio-room volumio[846]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: xcb_connection_has_error() returned true Sep 08 15:18:50 volumio-room volumio[846]: amixer: Unable to find simple control 'SoftMaster',0 Sep 08 15:18:51 volumio-room go-librespot[8245]: time="2025-09-08T15:18:51+02:00" level=trace msg="sent dealer ping" Sep 08 15:18:51 volumio-room go-librespot[8245]: time="2025-09-08T15:18:51+02:00" level=trace msg="received dealer pong" Sep 08 15:18:53 volumio-room go-librespot[8245]: time="2025-09-08T15:18:53+02:00" level=debug msg="update volume requested to 19004/65535" Sep 08 15:18:53 volumio-room go-librespot[8245]: time="2025-09-08T15:18:53+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 08 15:18:53 volumio-room go-librespot[8245]: time="2025-09-08T15:18:53+02:00" level=trace msg="emitting websocket event: volume" Sep 08 15:18:53 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":29,"max":100}} Sep 08 15:18:53 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 29 Sep 08 15:18:53 volumio-room volumio[846]: info: Setting Volumio Volume from Spotify: 29 Sep 08 15:18:53 volumio-room volumio[846]: info: VolumeController::SetAlsaVolume29 Sep 08 15:18:53 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:18:53 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 08 15:18:53 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:18:53 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:18:53 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:18:53 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:53 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":29,"max":100}} Sep 08 15:18:53 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 29 Sep 08 15:18:53 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 29 Sep 08 15:18:53 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 29 Sep 08 15:18:53 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:18:53 volumio-room volumio[846]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: xcb_connection_has_error() returned true Sep 08 15:18:53 volumio-room volumio[846]: amixer: Unable to find simple control 'SoftMaster',0 Sep 08 15:18:54 volumio-room go-librespot[8245]: time="2025-09-08T15:18:54+02:00" level=debug msg="update volume requested to 18349/65535" Sep 08 15:18:54 volumio-room go-librespot[8245]: time="2025-09-08T15:18:54+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 08 15:18:54 volumio-room go-librespot[8245]: time="2025-09-08T15:18:54+02:00" level=trace msg="emitting websocket event: volume" Sep 08 15:18:54 volumio-room go-librespot[8245]: time="2025-09-08T15:18:54+02:00" level=debug msg="update volume requested to 17694/65535" Sep 08 15:18:54 volumio-room go-librespot[8245]: time="2025-09-08T15:18:54+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 08 15:18:54 volumio-room go-librespot[8245]: time="2025-09-08T15:18:54+02:00" level=trace msg="emitting websocket event: volume" Sep 08 15:18:54 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":28,"max":100}} Sep 08 15:18:54 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 28 Sep 08 15:18:54 volumio-room volumio[846]: info: Setting Volumio Volume from Spotify: 28 Sep 08 15:18:54 volumio-room volumio[846]: info: VolumeController::SetAlsaVolume28 Sep 08 15:18:54 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:18:54 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 08 15:18:54 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:18:54 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:18:54 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:18:54 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:54 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":28,"max":100}} Sep 08 15:18:54 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 28 Sep 08 15:18:54 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 28 Sep 08 15:18:54 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:18:54 volumio-room volumio[846]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: xcb_connection_has_error() returned true Sep 08 15:18:54 volumio-room volumio[846]: amixer: Unable to find simple control 'SoftMaster',0 Sep 08 15:18:54 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":27,"max":100}} Sep 08 15:18:54 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 27 Sep 08 15:18:54 volumio-room volumio[846]: info: Setting Volumio Volume from Spotify: 27 Sep 08 15:18:54 volumio-room volumio[846]: info: VolumeController::SetAlsaVolume27 Sep 08 15:18:54 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:18:54 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 08 15:18:54 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:18:54 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:18:54 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:18:54 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:54 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":27,"max":100}} Sep 08 15:18:54 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 27 Sep 08 15:18:54 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 27 Sep 08 15:18:54 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:18:54 volumio-room volumio[846]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: xcb_connection_has_error() returned true Sep 08 15:18:54 volumio-room volumio[846]: amixer: Unable to find simple control 'SoftMaster',0 Sep 08 15:18:55 volumio-room go-librespot[8245]: time="2025-09-08T15:18:55+02:00" level=debug msg="update volume requested to 17038/65535" Sep 08 15:18:55 volumio-room go-librespot[8245]: time="2025-09-08T15:18:55+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 08 15:18:55 volumio-room go-librespot[8245]: time="2025-09-08T15:18:55+02:00" level=trace msg="emitting websocket event: volume" Sep 08 15:18:55 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":26,"max":100}} Sep 08 15:18:55 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 26 Sep 08 15:18:55 volumio-room volumio[846]: info: Setting Volumio Volume from Spotify: 26 Sep 08 15:18:55 volumio-room volumio[846]: info: VolumeController::SetAlsaVolume26 Sep 08 15:18:55 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:18:55 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 08 15:18:55 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:18:55 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:18:55 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:18:55 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:55 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":26,"max":100}} Sep 08 15:18:55 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 26 Sep 08 15:18:55 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 26 Sep 08 15:18:55 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 26 Sep 08 15:18:55 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:18:55 volumio-room volumio[846]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: xcb_connection_has_error() returned true Sep 08 15:18:55 volumio-room volumio[846]: amixer: Unable to find simple control 'SoftMaster',0 Sep 08 15:18:57 volumio-room go-librespot[8245]: time="2025-09-08T15:18:57+02:00" level=debug msg="update volume requested to 16383/65535" Sep 08 15:18:57 volumio-room go-librespot[8245]: time="2025-09-08T15:18:57+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 08 15:18:57 volumio-room go-librespot[8245]: time="2025-09-08T15:18:57+02:00" level=trace msg="emitting websocket event: volume" Sep 08 15:18:57 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":25,"max":100}} Sep 08 15:18:57 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 25 Sep 08 15:18:57 volumio-room volumio[846]: info: Setting Volumio Volume from Spotify: 25 Sep 08 15:18:57 volumio-room volumio[846]: info: VolumeController::SetAlsaVolume25 Sep 08 15:18:57 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:18:57 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 08 15:18:57 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:18:57 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:18:57 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:18:57 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:57 volumio-room go-librespot[8245]: time="2025-09-08T15:18:57+02:00" level=debug msg="update volume requested to 15728/65535" Sep 08 15:18:57 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":25,"max":100}} Sep 08 15:18:57 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 25 Sep 08 15:18:57 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 25 Sep 08 15:18:57 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 25 Sep 08 15:18:57 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:18:57 volumio-room volumio[846]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: xcb_connection_has_error() returned true Sep 08 15:18:57 volumio-room volumio[846]: amixer: Unable to find simple control 'SoftMaster',0 Sep 08 15:18:58 volumio-room go-librespot[8245]: time="2025-09-08T15:18:58+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 08 15:18:58 volumio-room go-librespot[8245]: time="2025-09-08T15:18:58+02:00" level=trace msg="emitting websocket event: volume" Sep 08 15:18:58 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":24,"max":100}} Sep 08 15:18:58 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 24 Sep 08 15:18:58 volumio-room volumio[846]: info: Setting Volumio Volume from Spotify: 24 Sep 08 15:18:58 volumio-room volumio[846]: info: VolumeController::SetAlsaVolume24 Sep 08 15:18:58 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:18:58 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 08 15:18:58 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:18:58 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:18:58 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:18:58 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:58 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":24,"max":100}} Sep 08 15:18:58 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 24 Sep 08 15:18:58 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 24 Sep 08 15:18:58 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 24 Sep 08 15:18:58 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:18:58 volumio-room volumio[846]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: xcb_connection_has_error() returned true Sep 08 15:18:58 volumio-room volumio[846]: amixer: Unable to find simple control 'SoftMaster',0 Sep 08 15:18:58 volumio-room go-librespot[8245]: time="2025-09-08T15:18:58+02:00" level=debug msg="update volume requested to 10485/65535" Sep 08 15:18:58 volumio-room go-librespot[8245]: time="2025-09-08T15:18:58+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 08 15:18:58 volumio-room go-librespot[8245]: time="2025-09-08T15:18:58+02:00" level=trace msg="emitting websocket event: volume" Sep 08 15:18:58 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":16,"max":100}} Sep 08 15:18:58 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 16 Sep 08 15:18:58 volumio-room volumio[846]: info: Setting Volumio Volume from Spotify: 16 Sep 08 15:18:58 volumio-room volumio[846]: info: VolumeController::SetAlsaVolume16 Sep 08 15:18:58 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:18:58 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 08 15:18:58 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:18:58 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:18:58 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:18:58 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:58 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":16,"max":100}} Sep 08 15:18:58 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 16 Sep 08 15:18:58 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 16 Sep 08 15:18:58 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 16 Sep 08 15:18:58 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:18:58 volumio-room volumio[846]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: xcb_connection_has_error() returned true Sep 08 15:18:58 volumio-room volumio[846]: amixer: Unable to find simple control 'SoftMaster',0 Sep 08 15:18:59 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:18:59 volumio-room volumio[846]: info: Listing playlists Sep 08 15:19:00 volumio-room go-librespot[8245]: time="2025-09-08T15:19:00+02:00" level=debug msg="update volume requested to 11140/65535" Sep 08 15:19:00 volumio-room go-librespot[8245]: time="2025-09-08T15:19:00+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 08 15:19:00 volumio-room go-librespot[8245]: time="2025-09-08T15:19:00+02:00" level=trace msg="emitting websocket event: volume" Sep 08 15:19:00 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":17,"max":100}} Sep 08 15:19:00 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 17 Sep 08 15:19:00 volumio-room volumio[846]: info: Setting Volumio Volume from Spotify: 17 Sep 08 15:19:00 volumio-room volumio[846]: info: VolumeController::SetAlsaVolume17 Sep 08 15:19:00 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:19:00 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 08 15:19:00 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:19:00 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:19:00 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:19:00 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:19:00 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":17,"max":100}} Sep 08 15:19:00 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 17 Sep 08 15:19:00 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 17 Sep 08 15:19:00 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 17 Sep 08 15:19:00 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:19:00 volumio-room go-librespot[8245]: time="2025-09-08T15:19:00+02:00" level=debug msg="update volume requested to 11795/65535" Sep 08 15:19:00 volumio-room volumio[846]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: xcb_connection_has_error() returned true Sep 08 15:19:00 volumio-room volumio[846]: amixer: Unable to find simple control 'SoftMaster',0 Sep 08 15:19:00 volumio-room go-librespot[8245]: time="2025-09-08T15:19:00+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 08 15:19:00 volumio-room go-librespot[8245]: time="2025-09-08T15:19:00+02:00" level=trace msg="emitting websocket event: volume" Sep 08 15:19:00 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":18,"max":100}} Sep 08 15:19:00 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 18 Sep 08 15:19:00 volumio-room volumio[846]: info: Setting Volumio Volume from Spotify: 18 Sep 08 15:19:00 volumio-room volumio[846]: info: VolumeController::SetAlsaVolume18 Sep 08 15:19:00 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:19:00 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 08 15:19:00 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:19:00 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:19:00 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:19:00 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:19:00 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":18,"max":100}} Sep 08 15:19:00 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 18 Sep 08 15:19:00 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 18 Sep 08 15:19:00 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 18 Sep 08 15:19:00 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:19:00 volumio-room volumio[846]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: xcb_connection_has_error() returned true Sep 08 15:19:00 volumio-room volumio[846]: amixer: Unable to find simple control 'SoftMaster',0 Sep 08 15:19:00 volumio-room go-librespot[8245]: time="2025-09-08T15:19:00+02:00" level=debug msg="update volume requested to 16383/65535" Sep 08 15:19:00 volumio-room go-librespot[8245]: time="2025-09-08T15:19:00+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 08 15:19:00 volumio-room go-librespot[8245]: time="2025-09-08T15:19:00+02:00" level=trace msg="emitting websocket event: volume" Sep 08 15:19:00 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":25,"max":100}} Sep 08 15:19:00 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 25 Sep 08 15:19:00 volumio-room volumio[846]: info: Setting Volumio Volume from Spotify: 25 Sep 08 15:19:00 volumio-room volumio[846]: info: VolumeController::SetAlsaVolume25 Sep 08 15:19:00 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:19:00 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 08 15:19:00 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:19:00 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:19:00 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:19:00 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:19:00 volumio-room volumio[846]: SPOTIFY: received: {"type":"volume","data":{"value":25,"max":100}} Sep 08 15:19:00 volumio-room volumio[846]: SPOTIFY: RECEIVED SPOTIFY VOLUME 25 Sep 08 15:19:00 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 25 Sep 08 15:19:00 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 25 Sep 08 15:19:00 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:19:00 volumio-room volumio[846]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: xcb_connection_has_error() returned true Sep 08 15:19:00 volumio-room volumio[846]: amixer: Unable to find simple control 'SoftMaster',0 Sep 08 15:19:05 volumio-room go-librespot[8245]: time="2025-09-08T15:19:05+02:00" level=trace msg="emitting websocket event: not_playing" Sep 08 15:19:05 volumio-room go-librespot[8245]: time="2025-09-08T15:19:05+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:14LXUuHHmuce69WPXXwTA5" Sep 08 15:19:05 volumio-room volumio[846]: SPOTIFY: received: {"type":"not_playing","data":{"uri":"spotify:track:3HV2Yu22mmHDme4cxOUeuY","play_origin":""}} Sep 08 15:19:05 volumio-room volumio[846]: error: Failed to decode event: not_playing Sep 08 15:19:05 volumio-room volumio[846]: SPOTIFY: received: {"type":"not_playing","data":{"uri":"spotify:track:3HV2Yu22mmHDme4cxOUeuY","play_origin":""}} Sep 08 15:19:05 volumio-room volumio[846]: error: Failed to decode event: not_playing Sep 08 15:19:05 volumio-room go-librespot[8245]: time="2025-09-08T15:19:05+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 08 15:19:05 volumio-room go-librespot[8245]: time="2025-09-08T15:19:05+02:00" level=trace msg="emitting websocket event: will_play" Sep 08 15:19:05 volumio-room volumio[846]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:14LXUuHHmuce69WPXXwTA5","play_origin":""}} Sep 08 15:19:05 volumio-room go-librespot[8245]: time="2025-09-08T15:19:05+02:00" level=info msg="loaded track \"Les Barricades Mystérieuses - Arr. Fred Thomas\" (paused: false, position: 0ms, duration: 208870ms, prefetched: true)" uri="spotify:track:14LXUuHHmuce69WPXXwTA5" Sep 08 15:19:05 volumio-room volumio[846]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:14LXUuHHmuce69WPXXwTA5","play_origin":""}} Sep 08 15:19:05 volumio-room go-librespot[8245]: time="2025-09-08T15:19:05+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 08 15:19:05 volumio-room go-librespot[8245]: time="2025-09-08T15:19:05+02:00" level=trace msg="scheduling prefetch in 179s" Sep 08 15:19:05 volumio-room go-librespot[8245]: time="2025-09-08T15:19:05+02:00" level=trace msg="emitting websocket event: metadata" Sep 08 15:19:05 volumio-room volumio[846]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:14LXUuHHmuce69WPXXwTA5","name":"Les Barricades Mystérieuses - Arr. Fred Thomas","artist_names":["Fernando Egozcue","Fred Thomas"],"album_name":"Entre Nosotros","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0287f1c6f71fd61eb4319d6172","position":0,"duration":208870,"release_date":"year:2021 month:2 day:19","track_number":4,"disc_number":1}} Sep 08 15:19:05 volumio-room volumio[846]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:14LXUuHHmuce69WPXXwTA5","name":"Les Barricades Mystérieuses - Arr. Fred Thomas","artist_names":["Fernando Egozcue","Fred Thomas"],"album_name":"Entre Nosotros","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0287f1c6f71fd61eb4319d6172","position":0,"duration":208870,"release_date":"year:2021 month:2 day:19","track_number":4,"disc_number":1}} Sep 08 15:19:05 volumio-room go-librespot[8245]: time="2025-09-08T15:19:05+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 08 15:19:05 volumio-room go-librespot[8245]: time="2025-09-08T15:19:05+02:00" level=trace msg="emitting websocket event: playing" Sep 08 15:19:05 volumio-room volumio[846]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:14LXUuHHmuce69WPXXwTA5","resume":false,"play_origin":""}} Sep 08 15:19:05 volumio-room volumio[846]: SPOTIFY: PUSH STATE SPOTIFY Sep 08 15:19:05 volumio-room volumio[846]: SPOTIFY: {"status":"play","service":"spop","title":"Les Barricades Mystérieuses - Arr. Fred Thomas","artist":"Fernando Egozcue, Fred Thomas","album":"Entre Nosotros","albumart":"https://i.scdn.co/image/ab67616d00001e0287f1c6f71fd61eb4319d6172","uri":"spotify:track:14LXUuHHmuce69WPXXwTA5","trackType":"spotify","seek":0,"duration":208,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Sep 08 15:19:05 volumio-room volumio[846]: info: CoreCommandRouter::servicePushState Sep 08 15:19:05 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:19:05 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 08 15:19:05 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:19:05 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:19:05 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:19:05 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:19:05 volumio-room volumio[846]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:14LXUuHHmuce69WPXXwTA5","resume":false,"play_origin":""}} Sep 08 15:19:05 volumio-room volumio[846]: SPOTIFY: PUSH STATE SPOTIFY Sep 08 15:19:05 volumio-room volumio[846]: SPOTIFY: {"status":"play","service":"spop","title":"Les Barricades Mystérieuses - Arr. Fred Thomas","artist":"Fernando Egozcue, Fred Thomas","album":"Entre Nosotros","albumart":"https://i.scdn.co/image/ab67616d00001e0287f1c6f71fd61eb4319d6172","uri":"spotify:track:14LXUuHHmuce69WPXXwTA5","trackType":"spotify","seek":0,"duration":208,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Sep 08 15:19:05 volumio-room volumio[846]: info: CoreCommandRouter::servicePushState Sep 08 15:19:05 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:19:05 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:19:05 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:19:05 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:19:05 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:19:05 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 25 Sep 08 15:19:05 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 25 Sep 08 15:19:05 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 25 Sep 08 15:19:05 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 25 Sep 08 15:19:05 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:19:05 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:19:05 volumio-room volumio[846]: SPOTIFY: PUSH STATE SPOTIFY Sep 08 15:19:05 volumio-room volumio[846]: SPOTIFY: {"status":"play","service":"spop","title":"Les Barricades Mystérieuses - Arr. Fred Thomas","artist":"Fernando Egozcue, Fred Thomas","album":"Entre Nosotros","albumart":"https://i.scdn.co/image/ab67616d00001e0287f1c6f71fd61eb4319d6172","uri":"spotify:track:14LXUuHHmuce69WPXXwTA5","trackType":"spotify","seek":1000,"duration":208,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Sep 08 15:19:05 volumio-room volumio[846]: info: CoreCommandRouter::servicePushState Sep 08 15:19:05 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:19:05 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 08 15:19:05 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:19:05 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:19:05 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:19:05 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:19:05 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 25 Sep 08 15:19:05 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 25 Sep 08 15:19:05 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:19:05 volumio-room volumio[846]: SPOTIFY: PUSH STATE SPOTIFY Sep 08 15:19:05 volumio-room volumio[846]: SPOTIFY: {"status":"play","service":"spop","title":"Les Barricades Mystérieuses - Arr. Fred Thomas","artist":"Fernando Egozcue, Fred Thomas","album":"Entre Nosotros","albumart":"https://i.scdn.co/image/ab67616d00001e0287f1c6f71fd61eb4319d6172","uri":"spotify:track:14LXUuHHmuce69WPXXwTA5","trackType":"spotify","seek":1000,"duration":208,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Sep 08 15:19:05 volumio-room volumio[846]: info: CoreCommandRouter::servicePushState Sep 08 15:19:05 volumio-room volumio[846]: info: CoreStateMachine::pushState Sep 08 15:19:05 volumio-room volumio[846]: info: CoreCommandRouter::volumioPushState Sep 08 15:19:05 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output update for this device Sep 08 15:19:05 volumio-room volumio[846]: info: MRS: Pushing multiroomSync output Sep 08 15:19:05 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:19:05 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 25 Sep 08 15:19:05 volumio-room volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 25 Sep 08 15:19:05 volumio-room volumio[846]: info: [GPIO_Control] Status changed: play Sep 08 15:19:07 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 08 15:19:07 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 08 15:19:07 volumio-room volumio[846]: info: Discovery: Getting this device information Sep 08 15:19:07 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:19:07 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 08 15:19:07 volumio-room volumio[846]: info: Executing endpoint metavolumio Sep 08 15:19:07 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Sep 08 15:19:07 volumio-room volumio[846]: info: Executing endpoint metavolumio Sep 08 15:19:07 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Sep 08 15:19:07 volumio-room volumio[846]: info: Executing endpoint metavolumio Sep 08 15:19:07 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Sep 08 15:19:08 volumio-room volumio[846]: info: Executing endpoint metavolumio Sep 08 15:19:08 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Sep 08 15:19:08 volumio-room volumio[846]: info: Executing endpoint metavolumio Sep 08 15:19:08 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Sep 08 15:19:08 volumio-room volumio[846]: info: Executing endpoint metavolumio Sep 08 15:19:08 volumio-room volumio[846]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Sep 08 15:19:09 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:19:12 volumio-room volumio[846]: error: Failed request for metavolumio API Sep 08 15:19:13 volumio-room volumio[846]: info: CoreCommandRouter::volumioGetState Sep 08 15:19:15 volumio-room volumio[846]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 08 15:19:15 volumio-room volumio[846]: SyntaxError: Invalid or unexpected token Sep 08 15:19:15 volumio-room volumio[846]: at Object.onceWrapper (events.js:421:28) Sep 08 15:19:15 volumio-room volumio[846]: at ClientRequest.emit (events.js:315:20) Sep 08 15:19:15 volumio-room volumio[846]: at TLSSocket.emitRequestTimeout (_http_client.js:784:9) Sep 08 15:19:15 volumio-room volumio[846]: at Object.onceWrapper (events.js:421:28) Sep 08 15:19:15 volumio-room volumio[846]: at TLSSocket.emit (events.js:327:22) Sep 08 15:19:15 volumio-room volumio[846]: at TLSSocket.Socket._onTimeout (net.js:483:8) Sep 08 15:19:15 volumio-room volumio[846]: at listOnTimeout (internal/timers.js:554:17) Sep 08 15:19:15 volumio-room volumio[846]: at processTimers (internal/timers.js:497:7) Sep 08 15:19:15 volumio-room volumio[846]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 08 15:19:17 volumio-room sudo[11166]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-09-08 15:18 Sep 08 15:19:17 volumio-room sudo[11166]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster 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="95d9088e5dcb3a55aabfe7f209b9ae00946f3ec5" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="9a3927796ae9ab3a5a247866bf574288cd09ee64" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu 04 Sep 2025 04:11:35 PM CEST" VOLUMIO_VERSION="3.845" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="d8c10ad904a299b47c7499a1cf239286"