-- Logs begin at Thu 2019-02-14 11:11:59 CET, end at Mon 2025-11-03 22:09:29 CET. -- Nov 03 22:08:03 volumio go-librespot[5733]: time="2025-11-03T22:08:03+01:00" level=debug msg="fetched chunk 8/17, size: 524288" uri="spotify:track:2Ektwgee5sBRDqVToA9J0u" Nov 03 22:08:08 volumio volumio[992]: info: CALLMETHOD: audio_interface fusiondsp usethispreset [object Object] Nov 03 22:08:08 volumio volumio[992]: info: CoreCommandRouter::executeOnPlugin: fusiondsp , usethispreset Nov 03 22:08:08 volumio volumio[992]: info: FusionDsp - Value for usedpreset: Nov 03 22:08:08 volumio volumio[992]: error: FusionDsp - Value reading JSON file: {"geq15":"-0.5,1,1.5,1,0.5,1.5,1,0.5,-0.5,-1,-1,1,2,2,1.5","x2geq15":"-0.5,1,1.5,1,0.5,1.5,1,0.5,-0.5,-1,-1,1,2,2,1.5","state4preset":["None",false,false,50,0,0,0,"None",true,false,false,0,0,false]} Nov 03 22:08:08 volumio volumio[992]: info: FusionDsp - geq15 -0.5,1,1.5,1,0.5,1.5,1,0.5,-0.5,-1,-1,1,2,2,1.5 Nov 03 22:08:08 volumio volumio[992]: info: FusionDsp - value state4preset None,false,false,50,0,0,0,None,true,false,false,0,0,false Nov 03 22:08:09 volumio volumio[992]: info: FusionDsp - If filter freq >samplerate/2 then disable it Nov 03 22:08:09 volumio volumio[992]: error: FusionDsp - WebSocket error: [object Object] Nov 03 22:08:09 volumio volumio[992]: info: CoreCommandRouter::getUIConfigOnPlugin Nov 03 22:08:09 volumio volumio[992]: info: CoreCommandRouter::Close All Modals sent Nov 03 22:08:09 volumio volumio[992]: info: FusionDsp - Rock-FusionDsp Nov 03 22:08:09 volumio volumio[992]: info: FusionDsp - .Bass-FusionDsp.json,.Classic-FusionDsp.json,.Rock-FusionDsp.json,.Soundtrack-FusionDsp.json,.Voice-FusionDsp.json Nov 03 22:08:15 volumio go-librespot[5733]: time="2025-11-03T22:08:15+01:00" level=debug msg="fetched chunk 9/17, size: 524288" uri="spotify:track:2Ektwgee5sBRDqVToA9J0u" Nov 03 22:08:25 volumio go-librespot[5733]: time="2025-11-03T22:08:25+01:00" level=trace msg="sent dealer ping" Nov 03 22:08:25 volumio go-librespot[5733]: time="2025-11-03T22:08:25+01:00" level=trace msg="received dealer pong" Nov 03 22:08:27 volumio go-librespot[5733]: time="2025-11-03T22:08:27+01:00" level=debug msg="fetched chunk 10/17, size: 524288" uri="spotify:track:2Ektwgee5sBRDqVToA9J0u" Nov 03 22:08:28 volumio volumio[992]: info: CALLMETHOD: audio_interface fusiondsp usethispreset [object Object] Nov 03 22:08:28 volumio volumio[992]: info: CoreCommandRouter::executeOnPlugin: fusiondsp , usethispreset Nov 03 22:08:28 volumio volumio[992]: info: FusionDsp - Value for usedpreset: Nov 03 22:08:28 volumio volumio[992]: error: FusionDsp - Value reading JSON file: {"geq15":"-6,-5,-4,-3.5,-2.5,-2,-0.5,1,2.5,4,5,4,2.5,1,-1","x2geq15":"-6,-5,-4,-3.5,-2.5,-2,-0.5,1,2.5,4,5,4,2.5,1,-1","state4preset":["None",false,false,50,0,0,0,"None",true,false,false,0,0,false]} Nov 03 22:08:28 volumio volumio[992]: info: FusionDsp - geq15 -6,-5,-4,-3.5,-2.5,-2,-0.5,1,2.5,4,5,4,2.5,1,-1 Nov 03 22:08:28 volumio volumio[992]: info: FusionDsp - value state4preset None,false,false,50,0,0,0,None,true,false,false,0,0,false Nov 03 22:08:28 volumio volumio[992]: info: FusionDsp - If filter freq >samplerate/2 then disable it Nov 03 22:08:28 volumio volumio[992]: info: FusionDsp - {"Reload":{"result":"Ok"}} Nov 03 22:08:28 volumio volumio[992]: info: CoreCommandRouter::getUIConfigOnPlugin Nov 03 22:08:28 volumio volumio[992]: info: CoreCommandRouter::Close All Modals sent Nov 03 22:08:28 volumio volumio[992]: info: FusionDsp - Voice-FusionDsp Nov 03 22:08:29 volumio volumio[992]: info: FusionDsp - .Bass-FusionDsp.json,.Classic-FusionDsp.json,.Rock-FusionDsp.json,.Soundtrack-FusionDsp.json,.Voice-FusionDsp.json Nov 03 22:08:33 volumio volumio[992]: info: CALLMETHOD: audio_interface fusiondsp usethispreset [object Object] Nov 03 22:08:33 volumio volumio[992]: info: CoreCommandRouter::executeOnPlugin: fusiondsp , usethispreset Nov 03 22:08:33 volumio volumio[992]: info: FusionDsp - Value for usedpreset: Nov 03 22:08:33 volumio volumio[992]: error: FusionDsp - Value reading JSON file: {"geq15":"-0.5,1,1.5,1,0.5,1.5,1,0.5,-0.5,-1,-1,1,2,2,1.5","x2geq15":"-0.5,1,1.5,1,0.5,1.5,1,0.5,-0.5,-1,-1,1,2,2,1.5","state4preset":["None",false,false,50,0,0,0,"None",true,false,false,0,0,false]} Nov 03 22:08:33 volumio volumio[992]: info: FusionDsp - geq15 -0.5,1,1.5,1,0.5,1.5,1,0.5,-0.5,-1,-1,1,2,2,1.5 Nov 03 22:08:33 volumio volumio[992]: info: FusionDsp - value state4preset None,false,false,50,0,0,0,None,true,false,false,0,0,false Nov 03 22:08:33 volumio volumio[992]: info: FusionDsp - If filter freq >samplerate/2 then disable it Nov 03 22:08:33 volumio volumio[992]: error: FusionDsp - WebSocket error: [object Object] Nov 03 22:08:33 volumio volumio[992]: info: CoreCommandRouter::getUIConfigOnPlugin Nov 03 22:08:33 volumio volumio[992]: info: CoreCommandRouter::Close All Modals sent Nov 03 22:08:33 volumio volumio[992]: info: FusionDsp - Rock-FusionDsp Nov 03 22:08:33 volumio volumio[992]: info: FusionDsp - .Bass-FusionDsp.json,.Classic-FusionDsp.json,.Rock-FusionDsp.json,.Soundtrack-FusionDsp.json,.Voice-FusionDsp.json Nov 03 22:08:37 volumio go-librespot[5733]: time="2025-11-03T22:08:37+01:00" level=debug msg="fetched chunk 11/17, size: 524288" uri="spotify:track:2Ektwgee5sBRDqVToA9J0u" Nov 03 22:08:39 volumio volumio[992]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Nov 03 22:08:39 volumio volumio[992]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Nov 03 22:08:41 volumio volumio[992]: info: FusionDsp - Stopping FusionDsp service Nov 03 22:08:41 volumio volumio[992]: info: camilladsp stopping service pid 31647... Nov 03 22:08:41 volumio volumio[992]: info: camilladsp service terminated, instance 1 Nov 03 22:08:42 volumio volumio[992]: info: Disabling plugin fusiondsp Nov 03 22:08:42 volumio volumio[992]: info: Preparing to generate the ALSA configuration file Nov 03 22:08:42 volumio sudo[31657]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop fusiondsp.service Nov 03 22:08:42 volumio sudo[31657]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 03 22:08:42 volumio volumio[992]: info: The plugin multiroom has an ALSA contribution file volumioMultiRoomServer.postMultiRoom.1000.conf Nov 03 22:08:42 volumio volumio[992]: info: Reading ALSA contributions from plugins. Nov 03 22:08:42 volumio systemd[1]: Stopping FusionDsp Daemon... Nov 03 22:08:42 volumio volumio[21799]: Backend configuration: Nov 03 22:08:42 volumio volumio[21799]: active_config: /data/configuration/audio_interface/fusiondsp/camilladsp.yml Nov 03 22:08:42 volumio volumio[21799]: active_config_txt: null Nov 03 22:08:42 volumio volumio[21799]: camilla_host: 127.0.0.1 Nov 03 22:08:42 volumio volumio[21799]: camilla_port: 9876 Nov 03 22:08:42 volumio volumio[21799]: coeff_dir: /data/INTERNAL/FusionDsp/filters Nov 03 22:08:42 volumio volumio[21799]: config_dir: /data/configuration/audio_interface/fusiondsp Nov 03 22:08:42 volumio volumio[21799]: default_config: /data/configuration/audio_interface/fusiondsp/camilladsp.yml Nov 03 22:08:42 volumio volumio[21799]: log_file: /tmp/camilladsp.log Nov 03 22:08:42 volumio volumio[21799]: on_get_active_config: null Nov 03 22:08:42 volumio volumio[21799]: on_set_active_config: null Nov 03 22:08:42 volumio volumio[21799]: port: 5011 Nov 03 22:08:42 volumio volumio[21799]: supported_capture_types: null Nov 03 22:08:42 volumio volumio[21799]: supported_playback_types: null Nov 03 22:08:42 volumio volumio[21799]: update_config_symlink: false Nov 03 22:08:42 volumio volumio[21799]: update_config_txt: false Nov 03 22:08:42 volumio volumio[21799]: ======== Running on http://0.0.0.0:5011 ======== Nov 03 22:08:42 volumio volumio[21799]: (Press CTRL+C to quit) Nov 03 22:08:42 volumio volumio[992]: ------------------------------------ BT MESSAGE: BT STATUS: running Nov 03 22:08:42 volumio volumio[992]: ------------------------------------ BT MESSAGE: BT STATUS: running Nov 03 22:08:42 volumio volumio[992]: info: Asound.conf file written Nov 03 22:08:42 volumio sudo[31660]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf Nov 03 22:08:42 volumio sudo[31660]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 03 22:08:42 volumio sudo[31660]: pam_unix(sudo:session): session closed for user root Nov 03 22:08:42 volumio volumio[992]: xcb_connection_has_error() returned true Nov 03 22:08:42 volumio volumio[992]: /usr/sbin/alsactl: set_control:1461: Cannot write control '2:0:0:Max Overclock PLL:0' : Device or resource busy Nov 03 22:08:42 volumio volumio[992]: /usr/sbin/alsactl: set_control:1461: Cannot write control '2:0:0:Max Overclock DSP:0' : Device or resource busy Nov 03 22:08:42 volumio volumio[992]: /usr/sbin/alsactl: set_control:1461: Cannot write control '2:0:0:Max Overclock DAC:0' : Device or resource busy Nov 03 22:08:42 volumio volumio[992]: info: Output device has changed, restarting MPD Nov 03 22:08:42 volumio sudo[31665]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Nov 03 22:08:42 volumio sudo[31665]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 03 22:08:42 volumio volumio[992]: info: Output device has changed, restarting Shairport Sync Nov 03 22:08:42 volumio volumio[992]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 03 22:08:42 volumio volumio[992]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 03 22:08:42 volumio sudo[31665]: pam_unix(sudo:session): session closed for user root Nov 03 22:08:42 volumio sudo[31668]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Nov 03 22:08:42 volumio sudo[31668]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 03 22:08:42 volumio systemd[1]: fusiondsp.service: Succeeded. Nov 03 22:08:42 volumio systemd[1]: Stopped FusionDsp Daemon. Nov 03 22:08:42 volumio volumio[992]: xcb_connection_has_error() returned true Nov 03 22:08:42 volumio volumio[992]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Nov 03 22:08:42 volumio volumio[992]: xcb_connection_has_error() returned true Nov 03 22:08:42 volumio volumio[992]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Nov 03 22:08:42 volumio volumio[992]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 03 22:08:42 volumio sudo[31657]: pam_unix(sudo:session): session closed for user root Nov 03 22:08:42 volumio systemd[1]: Stopping Music Player Daemon... Nov 03 22:08:42 volumio volumio[992]: info: QobuzConnect: setDeactiveState invoked Nov 03 22:08:42 volumio volumio[992]: info: CoreCommandRouter::volumioGetState Nov 03 22:08:42 volumio volumio[992]: info: CorePlayQueue::getTrack 35 Nov 03 22:08:42 volumio vtcs[21836]: [2025-11-03 22:08:42.387] [tisoc] [warning] [SessionManagerImpl.cpp:240] Illegal State: IDLE Nov 03 22:08:42 volumio systemd[1]: mpd.service: Succeeded. Nov 03 22:08:42 volumio vtcs[21836]: [2025-11-03 22:08:42.392] [tisoc] [error] [SpkconServer.cpp:380] recv error. client fd=8 errorno=104 error=Connection reset by peer Nov 03 22:08:42 volumio vtcs[21836]: [2025-11-03 22:08:42.392] [tisoc] [error] [SpkconServer.cpp:375] recv error. socket disconnected Nov 03 22:08:42 volumio systemd[1]: Stopped Music Player Daemon. Nov 03 22:08:42 volumio volumio[992]: info: Done. Nov 03 22:08:42 volumio systemd[1]: Starting Music Player Daemon... Nov 03 22:08:42 volumio sudo[31677]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Nov 03 22:08:42 volumio sudo[31677]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 03 22:08:42 volumio sudo[31680]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Nov 03 22:08:42 volumio systemd[1]: Stopping Volumio Tidal Connect Service... Nov 03 22:08:42 volumio sudo[31680]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 03 22:08:42 volumio systemd[1]: vtcs.service: Main process exited, code=killed, status=15/TERM Nov 03 22:08:42 volumio systemd[1]: vtcs.service: Succeeded. Nov 03 22:08:42 volumio systemd[1]: Stopped Volumio Tidal Connect Service. Nov 03 22:08:42 volumio sudo[31677]: pam_unix(sudo:session): session closed for user root Nov 03 22:08:42 volumio sudo[31680]: pam_unix(sudo:session): session closed for user root Nov 03 22:08:42 volumio volumio[992]: ------------------------------------ BT MESSAGE: BT STATUS: running Nov 03 22:08:42 volumio volumio[992]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Nov 03 22:08:42 volumio sudo[31687]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed qobuz-connect.service Nov 03 22:08:42 volumio sudo[31687]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 03 22:08:42 volumio volumio[992]: ------------------------------------ BT MESSAGE: BT STATUS: running Nov 03 22:08:42 volumio volumio[992]: ------------------------------------ BT MESSAGE: BT STATUS: running Nov 03 22:08:42 volumio sudo[31675]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Nov 03 22:08:42 volumio sudo[31675]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 03 22:08:42 volumio sudo[31675]: pam_unix(sudo:session): session closed for user root Nov 03 22:08:42 volumio sudo[31687]: pam_unix(sudo:session): session closed for user root Nov 03 22:08:42 volumio sudo[31691]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart qobuz-connect.service Nov 03 22:08:42 volumio sudo[31691]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 03 22:08:42 volumio volumio[992]: ------------------------------------ BT MESSAGE: BT STATUS: running Nov 03 22:08:42 volumio volumio[992]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Nov 03 22:08:42 volumio volumio[992]: ------------------------------------ BT MESSAGE: BT STATUS: running Nov 03 22:08:42 volumio volumio[992]: error: Failed to parse min max audio card capabilities, sending default vales: TypeError: Cannot read property 'split' of undefined Nov 03 22:08:42 volumio volumio[992]: info: MPD Permissions set Nov 03 22:08:42 volumio volumio[992]: info: FusionDsp - Reporting Fusion DSP Disabled Nov 03 22:08:42 volumio volumio[992]: info: Removing fusiondspeq DSP Signal Path Element Nov 03 22:08:42 volumio volumio[992]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 03 22:08:42 volumio systemd[1]: Stopping Volumio Qobuz Connect Service... Nov 03 22:08:42 volumio qobuz-connect[21779]: 20251103 22:08:42.737 [21779.21779] INFO SampleApp: Stopping Local configuration server Nov 03 22:08:42 volumio qobuz-connect[21779]: 20251103 22:08:42.747 [21779.21779] INFO SampleApp: shat down connection on UNIX socket Nov 03 22:08:42 volumio volumio[992]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 03 22:08:42 volumio volumio[992]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 03 22:08:42 volumio systemd[1]: qobuz-connect.service: Succeeded. Nov 03 22:08:42 volumio systemd[1]: Stopped Volumio Qobuz Connect Service. Nov 03 22:08:42 volumio systemd[1]: Started Volumio Qobuz Connect Service. Nov 03 22:08:42 volumio volumio[992]: ------------------------------------ BT MESSAGE: BT STATUS: running Nov 03 22:08:42 volumio volumio[992]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Nov 03 22:08:42 volumio volumio[992]: ------------------------------------ BT MESSAGE: BT STATUS: running Nov 03 22:08:42 volumio volumio[992]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Nov 03 22:08:42 volumio sudo[31691]: pam_unix(sudo:session): session closed for user root Nov 03 22:08:42 volumio volumio[992]: info: QobuzConnect: Qobuz Connect client [object Object] disconnected Nov 03 22:08:42 volumio volumio[992]: info: QobuzConnect: setDeactiveState invoked Nov 03 22:08:42 volumio volumio[992]: info: CoreCommandRouter::volumioGetState Nov 03 22:08:42 volumio volumio[992]: info: CorePlayQueue::getTrack 35 Nov 03 22:08:42 volumio volumio[992]: info: Starting Shairport Sync Nov 03 22:08:42 volumio sudo[31701]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Nov 03 22:08:42 volumio volumio[992]: info: Executing endpoint qc_getconfig Nov 03 22:08:42 volumio sudo[31701]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 03 22:08:42 volumio volumio[992]: info: CoreCommandRouter::executeOnPlugin: qobuzconnect , onGetConfig Nov 03 22:08:42 volumio qobuz-connect[31698]: 20251103 22:08:42.854 [31698.31698] INFO SampleApp: Started connection to /tmp/qbz-connect.socket UNIX socket Nov 03 22:08:42 volumio volumio[992]: info: QobuzConnect: Qobuz Connect socket /tmp/qbz-connect.socket connected to client [object Object] Nov 03 22:08:42 volumio volumio[992]: info: QobuzConnect: QOBUZ Connect daemon connected Nov 03 22:08:42 volumio qobuz-connect[31698]: 20251103 22:08:42.862 [31698.31698] INFO VolumeManager: [0xcbc9d0]: Setting new playback volume: 75 Nov 03 22:08:42 volumio qobuz-connect[31698]: 20251103 22:08:42.862 [31698.31698] INFO VolumeManager: [0xcbc9d0]: Setting new mute state: 0 Nov 03 22:08:42 volumio qobuz-connect[31698]: 20251103 22:08:42.862 [31698.31698] INFO QobuzConnect: [0xcbd3a0]: Client initialized! Nov 03 22:08:42 volumio qobuz-connect[31698]: 20251103 22:08:42.862 [31698.31698] INFO SampleApp: Starting Avahi advertising, name: Volumio, service name: _qobuz-connect._tcp Nov 03 22:08:42 volumio qobuz-connect[31698]: 20251103 22:08:42.879 [31698.31698] INFO LocalConfigManager: [0xcbc2b0]: Starting Local Configuration server Nov 03 22:08:42 volumio qobuz-connect[31698]: 20251103 22:08:42.880 [31698.31698] INFO SampleApp: Starting Local configuration server Nov 03 22:08:42 volumio qobuz-connect[31698]: 20251103 22:08:42.880 [31698.31698] INFO SampleApp: Connected to UNIX socket client 0xcb1f60 Nov 03 22:08:42 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Nov 03 22:08:42 volumio systemd[1]: shairport-sync.service: Succeeded. Nov 03 22:08:42 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Nov 03 22:08:42 volumio volumio[992]: ------------------------------------ BT MESSAGE: BT STATUS: running Nov 03 22:08:42 volumio volumio[992]: ------------------------------------ BT MESSAGE: BT STATUS: running Nov 03 22:08:42 volumio volumio[992]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Nov 03 22:08:42 volumio volumio[992]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Nov 03 22:08:42 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Nov 03 22:08:42 volumio sudo[31701]: pam_unix(sudo:session): session closed for user root Nov 03 22:08:42 volumio volumio[992]: info: Shairport-Sync Started Nov 03 22:08:43 volumio qobuz-connect[31698]: 20251103 22:08:43.004 [31698.31698] INFO SampleApp: Playback volume changed: 75 Nov 03 22:08:43 volumio volumio[992]: info: CoreCommandRouter::volumioGetState Nov 03 22:08:43 volumio volumio[992]: info: CorePlayQueue::getTrack 35 Nov 03 22:08:44 volumio mpd[31692]: Nov 03 22:08 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Nov 03 22:08:44 volumio systemd[1]: Started Music Player Daemon. Nov 03 22:08:44 volumio sudo[31668]: pam_unix(sudo:session): session closed for user root Nov 03 22:08:44 volumio volumio[992]: error: updateQueue error: null Nov 03 22:08:45 volumio volumio[992]: info: TidalConnect service stoped! Nov 03 22:08:45 volumio volumio[992]: info: TidalConnect service stoped! Nov 03 22:08:45 volumio volumio[992]: info: Updating tc_getconfig REST Endpoint for plugin: music_service/tidalconnect Nov 03 22:08:45 volumio volumio[992]: info: Updating tc_connect REST Endpoint for plugin: music_service/tidalconnect Nov 03 22:08:45 volumio sudo[31734]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start vtcs.service Nov 03 22:08:45 volumio sudo[31734]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 03 22:08:45 volumio systemd[1]: Started Volumio Tidal Connect Service. Nov 03 22:08:45 volumio sudo[31734]: pam_unix(sudo:session): session closed for user root Nov 03 22:08:46 volumio volumio[992]: info: Executing endpoint tc_getconfig Nov 03 22:08:46 volumio volumio[992]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onGetConfig Nov 03 22:08:46 volumio vtcs[31736]: STARTING TidalConnect services, version: 1.5.1-beta1 Nov 03 22:08:46 volumio vtcs[31736]: STARTED TidalConnect services. Nov 03 22:08:46 volumio volumio[992]: info: Executing endpoint tc_connect Nov 03 22:08:46 volumio volumio[992]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onConnect Nov 03 22:08:46 volumio volumio[992]: info: Connecting to TidalConnect Nov 03 22:08:46 volumio volumio[992]: info: CoreCommandRouter::servicePushState Nov 03 22:08:46 volumio volumio[992]: info: CoreStateMachine::pushState Nov 03 22:08:46 volumio volumio[992]: info: CorePlayQueue::getTrack 35 Nov 03 22:08:46 volumio volumio[992]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 03 22:08:46 volumio volumio[992]: info: CoreCommandRouter::volumioPushState Nov 03 22:08:46 volumio volumio[992]: info: MRS: Pushing multiroomSync output update for this device Nov 03 22:08:46 volumio volumio[992]: info: MRS: Pushing multiroomSync output Nov 03 22:08:46 volumio volumio[992]: info: CoreCommandRouter::volumioGetState Nov 03 22:08:46 volumio volumio[992]: info: CorePlayQueue::getTrack 35 Nov 03 22:08:46 volumio volumio[992]: info: CorePlayQueue::getTrack 35 Nov 03 22:08:46 volumio volumio[992]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current spop Received tidalconnect Nov 03 22:08:46 volumio volumio[992]: info: CoreCommandRouter::servicePushState Nov 03 22:08:46 volumio volumio[992]: info: CoreStateMachine::pushState Nov 03 22:08:46 volumio volumio[992]: info: CorePlayQueue::getTrack 35 Nov 03 22:08:46 volumio volumio[992]: info: CoreCommandRouter::volumioPushState Nov 03 22:08:46 volumio volumio[992]: info: MRS: Pushing multiroomSync output update for this device Nov 03 22:08:46 volumio volumio[992]: info: MRS: Pushing multiroomSync output Nov 03 22:08:46 volumio volumio[992]: info: CoreCommandRouter::volumioGetState Nov 03 22:08:46 volumio volumio[992]: info: CorePlayQueue::getTrack 35 Nov 03 22:08:46 volumio volumio[992]: info: CorePlayQueue::getTrack 35 Nov 03 22:08:46 volumio volumio[992]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current spop Received tidalconnect Nov 03 22:08:46 volumio volumio[992]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Nov 03 22:08:46 volumio volumio[992]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Nov 03 22:08:48 volumio go-librespot[5733]: time="2025-11-03T22:08:48+01:00" level=debug msg="fetched chunk 12/17, size: 524288" uri="spotify:track:2Ektwgee5sBRDqVToA9J0u" Nov 03 22:08:48 volumio volumio[992]: info: TidalConnect service started! Nov 03 22:08:53 volumio volumio[992]: info: CoreCommandRouter::volumioPrevious Nov 03 22:08:53 volumio volumio[992]: info: CoreStateMachine::previous Nov 03 22:08:53 volumio volumio[992]: info: CorePlayQueue::getTrack 35 Nov 03 22:08:53 volumio volumio[992]: info: Spotify seek to: 0 Nov 03 22:08:53 volumio volumio[992]: info: Sending Spotify command with payload to local API: /player/seek Nov 03 22:08:53 volumio go-librespot[5733]: time="2025-11-03T22:08:53+01:00" level=debug msg="seek track to 0ms" Nov 03 22:08:53 volumio go-librespot[5733]: time="2025-11-03T22:08:53+01:00" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" uri="spotify:track:2Ektwgee5sBRDqVToA9J0u" Nov 03 22:08:53 volumio go-librespot[5733]: time="2025-11-03T22:08:53+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 03 22:08:53 volumio go-librespot[5733]: time="2025-11-03T22:08:53+01:00" level=trace msg="scheduling prefetch in 166s" Nov 03 22:08:53 volumio go-librespot[5733]: time="2025-11-03T22:08:53+01:00" level=trace msg="emitting websocket event: seek" Nov 03 22:08:53 volumio volumio[992]: SPOTIFY: received: {"type":"seek","data":{"context_uri":"spotify:track:7Gh6J73NeF1bgtyijbgO2k","uri":"spotify:track:2Ektwgee5sBRDqVToA9J0u","position":0,"duration":196571,"play_origin":"go-librespot"}} Nov 03 22:08:53 volumio volumio[992]: SPOTIFY: PUSH STATE SPOTIFY Nov 03 22:08:53 volumio volumio[992]: SPOTIFY: {"status":"play","service":"spop","title":"Ordinary","artist":"Cupido","album":"Ordinary","albumart":"https://i.scdn.co/image/ab67616d00001e0223a7968a3e49f46e36300562","uri":"spotify:track:2Ektwgee5sBRDqVToA9J0u","trackType":"spotify","seek":0,"duration":196,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Nov 03 22:08:53 volumio volumio[992]: info: CoreCommandRouter::servicePushState Nov 03 22:08:53 volumio volumio[992]: info: CorePlayQueue::getTrack 35 Nov 03 22:08:53 volumio volumio[992]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Ordinary","artist":"Cupido","album":"Ordinary","albumart":"https://i.scdn.co/image/ab67616d00001e0223a7968a3e49f46e36300562","uri":"spotify:track:2Ektwgee5sBRDqVToA9J0u","trackType":"spotify","seek":0,"duration":196,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Nov 03 22:08:53 volumio volumio[992]: verbose: CURRENT POSITION 35 Nov 03 22:08:53 volumio volumio[992]: info: CoreStateMachine::syncState stateService play Nov 03 22:08:53 volumio volumio[992]: info: CoreStateMachine::syncState currentStatus play Nov 03 22:08:53 volumio volumio[992]: info: Received an update from plugin. extracting info from payload Nov 03 22:08:53 volumio volumio[992]: info: CoreStateMachine::pushState Nov 03 22:08:53 volumio volumio[992]: info: CorePlayQueue::getTrack 35 Nov 03 22:08:53 volumio volumio[992]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 03 22:08:53 volumio volumio[992]: info: CoreCommandRouter::volumioPushState Nov 03 22:08:53 volumio volumio[992]: info: MRS: Pushing multiroomSync output update for this device Nov 03 22:08:53 volumio volumio[992]: info: MRS: Pushing multiroomSync output Nov 03 22:08:53 volumio volumio[992]: info: CoreCommandRouter::volumioGetState Nov 03 22:08:53 volumio volumio[992]: info: CorePlayQueue::getTrack 35 Nov 03 22:08:53 volumio volumio[992]: info: CoreStateMachine::pushState Nov 03 22:08:53 volumio volumio[992]: info: CorePlayQueue::getTrack 35 Nov 03 22:08:53 volumio volumio[992]: info: CoreCommandRouter::volumioPushState Nov 03 22:08:53 volumio volumio[992]: info: MRS: Pushing multiroomSync output update for this device Nov 03 22:08:53 volumio volumio[992]: info: MRS: Pushing multiroomSync output Nov 03 22:08:53 volumio volumio[992]: info: CoreCommandRouter::volumioGetState Nov 03 22:08:53 volumio volumio[992]: info: CorePlayQueue::getTrack 35 Nov 03 22:08:53 volumio volumio[992]: SPOTIFY: received: {"type":"seek","data":{"context_uri":"spotify:track:7Gh6J73NeF1bgtyijbgO2k","uri":"spotify:track:2Ektwgee5sBRDqVToA9J0u","position":0,"duration":196571,"play_origin":"go-librespot"}} Nov 03 22:08:53 volumio volumio[992]: SPOTIFY: PUSH STATE SPOTIFY Nov 03 22:08:53 volumio volumio[992]: SPOTIFY: {"status":"play","service":"spop","title":"Ordinary","artist":"Cupido","album":"Ordinary","albumart":"https://i.scdn.co/image/ab67616d00001e0223a7968a3e49f46e36300562","uri":"spotify:track:2Ektwgee5sBRDqVToA9J0u","trackType":"spotify","seek":0,"duration":196,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Nov 03 22:08:53 volumio volumio[992]: info: CoreCommandRouter::servicePushState Nov 03 22:08:53 volumio volumio[992]: info: CorePlayQueue::getTrack 35 Nov 03 22:08:53 volumio volumio[992]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Ordinary","artist":"Cupido","album":"Ordinary","albumart":"https://i.scdn.co/image/ab67616d00001e0223a7968a3e49f46e36300562","uri":"spotify:track:2Ektwgee5sBRDqVToA9J0u","trackType":"spotify","seek":0,"duration":196,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Nov 03 22:08:53 volumio volumio[992]: verbose: CURRENT POSITION 35 Nov 03 22:08:53 volumio volumio[992]: info: CoreStateMachine::syncState stateService play Nov 03 22:08:53 volumio volumio[992]: info: CoreStateMachine::syncState currentStatus play Nov 03 22:08:53 volumio volumio[992]: info: Received an update from plugin. extracting info from payload Nov 03 22:08:53 volumio volumio[992]: info: CoreStateMachine::pushState Nov 03 22:08:53 volumio volumio[992]: info: CorePlayQueue::getTrack 35 Nov 03 22:08:53 volumio volumio[992]: info: CoreCommandRouter::volumioPushState Nov 03 22:08:53 volumio volumio[992]: info: MRS: Pushing multiroomSync output update for this device Nov 03 22:08:53 volumio volumio[992]: info: MRS: Pushing multiroomSync output Nov 03 22:08:53 volumio volumio[992]: info: CoreCommandRouter::volumioGetState Nov 03 22:08:53 volumio volumio[992]: info: CorePlayQueue::getTrack 35 Nov 03 22:08:53 volumio volumio[992]: info: CoreStateMachine::pushState Nov 03 22:08:53 volumio volumio[992]: info: CorePlayQueue::getTrack 35 Nov 03 22:08:53 volumio volumio[992]: info: CoreCommandRouter::volumioPushState Nov 03 22:08:53 volumio volumio[992]: info: MRS: Pushing multiroomSync output update for this device Nov 03 22:08:53 volumio volumio[992]: info: MRS: Pushing multiroomSync output Nov 03 22:08:53 volumio volumio[992]: info: CoreCommandRouter::volumioGetState Nov 03 22:08:53 volumio volumio[992]: info: CorePlayQueue::getTrack 35 Nov 03 22:08:53 volumio volumio[992]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Nov 03 22:08:53 volumio volumio[992]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Nov 03 22:08:53 volumio volumio[992]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Nov 03 22:08:53 volumio volumio[992]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Nov 03 22:08:54 volumio volumio[992]: info: CoreCommandRouter::volumioPrevious Nov 03 22:08:54 volumio volumio[992]: info: CoreStateMachine::previous Nov 03 22:08:54 volumio volumio[992]: info: CorePlayQueue::getTrack 35 Nov 03 22:08:54 volumio volumio[992]: info: CoreStateMachine::stop Nov 03 22:08:54 volumio volumio[992]: info: CoreStateMachine::setConsumeUpdateService undefined Nov 03 22:08:54 volumio volumio[992]: info: CoreStateMachine::stPlaybackTimer Nov 03 22:08:54 volumio volumio[992]: info: CoreStateMachine::updateTrackBlock Nov 03 22:08:54 volumio volumio[992]: info: CorePlayQueue::getTrackBlock Nov 03 22:08:54 volumio volumio[992]: info: CoreStateMachine::pushState Nov 03 22:08:54 volumio volumio[992]: info: CorePlayQueue::getTrack 35 Nov 03 22:08:54 volumio volumio[992]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 03 22:08:54 volumio volumio[992]: info: CoreCommandRouter::volumioPushState Nov 03 22:08:54 volumio volumio[992]: info: MRS: Pushing multiroomSync output update for this device Nov 03 22:08:54 volumio volumio[992]: info: MRS: Pushing multiroomSync output Nov 03 22:08:54 volumio volumio[992]: info: CoreCommandRouter::volumioGetState Nov 03 22:08:54 volumio volumio[992]: info: CorePlayQueue::getTrack 35 Nov 03 22:08:54 volumio volumio[992]: info: CoreStateMachine::serviceStop Nov 03 22:08:54 volumio volumio[992]: info: CorePlayQueue::getTrack 35 Nov 03 22:08:54 volumio volumio[992]: info: CoreCommandRouter::serviceStop Nov 03 22:08:54 volumio volumio[992]: info: Spotify Stop Nov 03 22:08:54 volumio volumio[992]: SPOTIFY: SPOTIFY STOP Nov 03 22:08:54 volumio volumio[992]: SPOTIFY: {"status":"play","position":35,"title":"Ordinary","artist":"Cupido","album":"Ordinary","albumart":"https://i.scdn.co/image/ab67616d0000b27323a7968a3e49f46e36300562","uri":"spotify:track:2Ektwgee5sBRDqVToA9J0u","trackType":"spotify","codec":"ogg","seek":0,"duration":196,"samplerate":"320 kbps","bitdepth":"16 bit","channels":2,"random":null,"repeat":null,"repeatSingle":false,"consume":false,"volume":100,"dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} Nov 03 22:08:54 volumio volumio[992]: info: Sending Spotify command to local API: /player/pause Nov 03 22:08:54 volumio volumio[992]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Nov 03 22:08:54 volumio go-librespot[5733]: time="2025-11-03T22:08:54+01:00" level=debug msg="pause track at 922ms" Nov 03 22:08:54 volumio go-librespot[5733]: time="2025-11-03T22:08:54+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 03 22:08:54 volumio go-librespot[5733]: time="2025-11-03T22:08:54+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 03 22:08:54 volumio go-librespot[5733]: time="2025-11-03T22:08:54+01:00" level=trace msg="emitting websocket event: paused" Nov 03 22:08:54 volumio volumio[992]: SPOTIFY: received: {"type":"paused","data":{"context_uri":"spotify:track:7Gh6J73NeF1bgtyijbgO2k","uri":"spotify:track:2Ektwgee5sBRDqVToA9J0u","play_origin":"go-librespot"}} Nov 03 22:08:54 volumio volumio[992]: SPOTIFY: PUSH STATE SPOTIFY Nov 03 22:08:54 volumio volumio[992]: SPOTIFY: {"status":"pause","service":"spop","title":"Ordinary","artist":"Cupido","album":"Ordinary","albumart":"https://i.scdn.co/image/ab67616d00001e0223a7968a3e49f46e36300562","uri":"spotify:track:2Ektwgee5sBRDqVToA9J0u","trackType":"spotify","seek":1000,"duration":196,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Nov 03 22:08:54 volumio volumio[992]: info: CoreCommandRouter::servicePushState Nov 03 22:08:54 volumio volumio[992]: info: CorePlayQueue::getTrack 35 Nov 03 22:08:54 volumio volumio[992]: verbose: STATE SERVICE {"status":"pause","service":"spop","title":"Ordinary","artist":"Cupido","album":"Ordinary","albumart":"https://i.scdn.co/image/ab67616d00001e0223a7968a3e49f46e36300562","uri":"spotify:track:2Ektwgee5sBRDqVToA9J0u","trackType":"spotify","seek":1000,"duration":196,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Nov 03 22:08:54 volumio volumio[992]: verbose: CURRENT POSITION 35 Nov 03 22:08:54 volumio volumio[992]: info: CoreStateMachine::syncState stateService pause Nov 03 22:08:54 volumio volumio[992]: info: CoreStateMachine::syncState currentStatus stop Nov 03 22:08:54 volumio volumio[992]: info: CoreStateMachine::pushState Nov 03 22:08:54 volumio volumio[992]: info: CorePlayQueue::getTrack 35 Nov 03 22:08:54 volumio volumio[992]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 03 22:08:54 volumio volumio[992]: info: CoreCommandRouter::volumioPushState Nov 03 22:08:54 volumio volumio[992]: info: MRS: Pushing multiroomSync output update for this device Nov 03 22:08:54 volumio volumio[992]: info: MRS: Pushing multiroomSync output Nov 03 22:08:54 volumio volumio[992]: info: CoreCommandRouter::volumioGetState Nov 03 22:08:54 volumio volumio[992]: info: CorePlayQueue::getTrack 35 Nov 03 22:08:54 volumio volumio[992]: SPOTIFY: received: {"type":"paused","data":{"context_uri":"spotify:track:7Gh6J73NeF1bgtyijbgO2k","uri":"spotify:track:2Ektwgee5sBRDqVToA9J0u","play_origin":"go-librespot"}} Nov 03 22:08:54 volumio volumio[992]: SPOTIFY: PUSH STATE SPOTIFY Nov 03 22:08:54 volumio volumio[992]: SPOTIFY: {"status":"pause","service":"spop","title":"Ordinary","artist":"Cupido","album":"Ordinary","albumart":"https://i.scdn.co/image/ab67616d00001e0223a7968a3e49f46e36300562","uri":"spotify:track:2Ektwgee5sBRDqVToA9J0u","trackType":"spotify","seek":1000,"duration":196,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Nov 03 22:08:54 volumio volumio[992]: info: CoreCommandRouter::servicePushState Nov 03 22:08:54 volumio volumio[992]: info: CorePlayQueue::getTrack 35 Nov 03 22:08:54 volumio volumio[992]: verbose: STATE SERVICE {"status":"pause","service":"spop","title":"Ordinary","artist":"Cupido","album":"Ordinary","albumart":"https://i.scdn.co/image/ab67616d00001e0223a7968a3e49f46e36300562","uri":"spotify:track:2Ektwgee5sBRDqVToA9J0u","trackType":"spotify","seek":1000,"duration":196,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Nov 03 22:08:54 volumio volumio[992]: verbose: CURRENT POSITION 35 Nov 03 22:08:54 volumio volumio[992]: info: CoreStateMachine::syncState stateService pause Nov 03 22:08:54 volumio volumio[992]: info: CoreStateMachine::syncState currentStatus stop Nov 03 22:08:54 volumio volumio[992]: info: CoreStateMachine::pushState Nov 03 22:08:54 volumio volumio[992]: info: CorePlayQueue::getTrack 35 Nov 03 22:08:54 volumio volumio[992]: info: CoreCommandRouter::volumioPushState Nov 03 22:08:54 volumio volumio[992]: info: MRS: Pushing multiroomSync output update for this device Nov 03 22:08:54 volumio volumio[992]: info: MRS: Pushing multiroomSync output Nov 03 22:08:54 volumio volumio[992]: info: CoreCommandRouter::volumioGetState Nov 03 22:08:54 volumio volumio[992]: info: CorePlayQueue::getTrack 35 Nov 03 22:08:54 volumio volumio[992]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Nov 03 22:08:54 volumio volumio[992]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Nov 03 22:08:54 volumio volumio[992]: info: CoreStateMachine::play index undefined Nov 03 22:08:54 volumio volumio[992]: info: CoreStateMachine::setConsumeUpdateService undefined Nov 03 22:08:54 volumio volumio[992]: info: CorePlayQueue::getTrack 34 Nov 03 22:08:54 volumio volumio[992]: info: CoreStateMachine::startPlaybackTimer Nov 03 22:08:54 volumio volumio[992]: info: CorePlayQueue::getTrack 34 Nov 03 22:08:54 volumio volumio[992]: info: [1762204134769] ControllerSpotify::clearAddPlayTrack Nov 03 22:08:54 volumio volumio[992]: info: Sending Spotify command with payload to local API: /player/play Nov 03 22:08:54 volumio go-librespot[5733]: time="2025-11-03T22:08:54+01:00" level=debug msg="resolved context of track" uri="spotify:track:7Gh6J73NeF1bgtyijbgO2k" Nov 03 22:08:54 volumio go-librespot[5733]: time="2025-11-03T22:08:54+01:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:7Gh6J73NeF1bgtyijbgO2k" Nov 03 22:08:54 volumio go-librespot[5733]: time="2025-11-03T22:08:54+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:7Gh6J73NeF1bgtyijbgO2k" Nov 03 22:08:54 volumio go-librespot[5733]: time="2025-11-03T22:08:54+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 03 22:08:54 volumio go-librespot[5733]: time="2025-11-03T22:08:54+01:00" level=trace msg="emitting websocket event: will_play" Nov 03 22:08:54 volumio volumio[992]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:7Gh6J73NeF1bgtyijbgO2k","uri":"spotify:track:7Gh6J73NeF1bgtyijbgO2k","play_origin":"go-librespot"}} Nov 03 22:08:54 volumio volumio[992]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:7Gh6J73NeF1bgtyijbgO2k","uri":"spotify:track:7Gh6J73NeF1bgtyijbgO2k","play_origin":"go-librespot"}} Nov 03 22:08:54 volumio go-librespot[5733]: time="2025-11-03T22:08:54+01:00" level=debug msg="selected format OGG_VORBIS_320 (2fb7798ec9ddec9ce5af00b0f974cfd21c353ea2)" uri="spotify:track:7Gh6J73NeF1bgtyijbgO2k" Nov 03 22:08:54 volumio go-librespot[5733]: time="2025-11-03T22:08:54+01:00" level=debug msg="requested aes key for file 2fb7798ec9ddec9ce5af00b0f974cfd21c353ea2, gid: 7Gh6J73NeF1bgtyijbgO2k" Nov 03 22:08:55 volumio go-librespot[5733]: time="2025-11-03T22:08:55+01:00" level=trace msg="found 2 cdn urls" uri="spotify:track:7Gh6J73NeF1bgtyijbgO2k" Nov 03 22:08:55 volumio go-librespot[5733]: time="2025-11-03T22:08:55+01:00" level=debug msg="fetched first chunk of 11, total size is 5587731 bytes" uri="spotify:track:7Gh6J73NeF1bgtyijbgO2k" Nov 03 22:08:55 volumio go-librespot[5733]: time="2025-11-03T22:08:55+01:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 100000 us, period size = 4410 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 5 frames, PCM format = FLOAT_LE" Nov 03 22:08:55 volumio go-librespot[5733]: time="2025-11-03T22:08:55+01:00" level=info msg="loaded track \"Wicked Game\" (paused: false, position: 0ms, duration: 127895ms, prefetched: false)" uri="spotify:track:7Gh6J73NeF1bgtyijbgO2k" Nov 03 22:08:55 volumio go-librespot[5733]: time="2025-11-03T22:08:55+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 03 22:08:55 volumio go-librespot[5733]: time="2025-11-03T22:08:55+01:00" level=trace msg="scheduling prefetch in 98s" Nov 03 22:08:55 volumio go-librespot[5733]: time="2025-11-03T22:08:55+01:00" level=trace msg="emitting websocket event: metadata" Nov 03 22:08:55 volumio volumio[992]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:7Gh6J73NeF1bgtyijbgO2k","name":"Wicked Game","artist_names":["LÖVEE","HeɅven","Jessie Villa"],"album_name":"Wicked Game","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02cbb5809484ca5855c8a3ba99","position":0,"duration":127895,"release_date":"year:2024 month:5 day:31","track_number":1,"disc_number":1}} Nov 03 22:08:55 volumio go-librespot[5733]: time="2025-11-03T22:08:55+01:00" level=debug msg="fetched chunk 1/10, size: 524288" uri="spotify:track:7Gh6J73NeF1bgtyijbgO2k" Nov 03 22:08:55 volumio go-librespot[5733]: time="2025-11-03T22:08:55+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 03 22:08:55 volumio go-librespot[5733]: time="2025-11-03T22:08:55+01:00" level=trace msg="emitting websocket event: playing" Nov 03 22:08:55 volumio volumio[992]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:track:7Gh6J73NeF1bgtyijbgO2k","uri":"spotify:track:7Gh6J73NeF1bgtyijbgO2k","resume":false,"play_origin":"go-librespot"}} Nov 03 22:08:55 volumio volumio[992]: SPOTIFY: PUSH STATE SPOTIFY Nov 03 22:08:55 volumio volumio[992]: SPOTIFY: {"status":"play","service":"spop","title":"Wicked Game","artist":"LÖVEE, HeɅven, Jessie Villa","album":"Wicked Game","albumart":"https://i.scdn.co/image/ab67616d00001e02cbb5809484ca5855c8a3ba99","uri":"spotify:track:7Gh6J73NeF1bgtyijbgO2k","trackType":"spotify","seek":0,"duration":127,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Nov 03 22:08:55 volumio volumio[992]: info: CoreCommandRouter::servicePushState Nov 03 22:08:55 volumio volumio[992]: info: CorePlayQueue::getTrack 34 Nov 03 22:08:55 volumio volumio[992]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Wicked Game","artist":"LÖVEE, HeɅven, Jessie Villa","album":"Wicked Game","albumart":"https://i.scdn.co/image/ab67616d00001e02cbb5809484ca5855c8a3ba99","uri":"spotify:track:7Gh6J73NeF1bgtyijbgO2k","trackType":"spotify","seek":0,"duration":127,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Nov 03 22:08:55 volumio volumio[992]: verbose: CURRENT POSITION 34 Nov 03 22:08:55 volumio volumio[992]: info: CoreStateMachine::syncState stateService play Nov 03 22:08:55 volumio volumio[992]: info: CoreStateMachine::syncState currentStatus stop Nov 03 22:08:55 volumio volumio[992]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:track:7Gh6J73NeF1bgtyijbgO2k","uri":"spotify:track:7Gh6J73NeF1bgtyijbgO2k","resume":false,"play_origin":"go-librespot"}} Nov 03 22:08:55 volumio volumio[992]: SPOTIFY: PUSH STATE SPOTIFY Nov 03 22:08:55 volumio volumio[992]: SPOTIFY: {"status":"play","service":"spop","title":"Wicked Game","artist":"LÖVEE, HeɅven, Jessie Villa","album":"Wicked Game","albumart":"https://i.scdn.co/image/ab67616d00001e02cbb5809484ca5855c8a3ba99","uri":"spotify:track:7Gh6J73NeF1bgtyijbgO2k","trackType":"spotify","seek":0,"duration":127,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Nov 03 22:08:55 volumio volumio[992]: info: CoreCommandRouter::servicePushState Nov 03 22:08:55 volumio volumio[992]: info: CorePlayQueue::getTrack 34 Nov 03 22:08:55 volumio volumio[992]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Wicked Game","artist":"LÖVEE, HeɅven, Jessie Villa","album":"Wicked Game","albumart":"https://i.scdn.co/image/ab67616d00001e02cbb5809484ca5855c8a3ba99","uri":"spotify:track:7Gh6J73NeF1bgtyijbgO2k","trackType":"spotify","seek":0,"duration":127,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Nov 03 22:08:55 volumio volumio[992]: verbose: CURRENT POSITION 34 Nov 03 22:08:55 volumio volumio[992]: info: CoreStateMachine::syncState stateService play Nov 03 22:08:55 volumio volumio[992]: info: CoreStateMachine::syncState currentStatus play Nov 03 22:08:55 volumio volumio[992]: info: Received an update from plugin. extracting info from payload Nov 03 22:08:55 volumio volumio[992]: info: CoreStateMachine::pushState Nov 03 22:08:55 volumio volumio[992]: info: CorePlayQueue::getTrack 34 Nov 03 22:08:55 volumio volumio[992]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 03 22:08:55 volumio volumio[992]: info: CoreCommandRouter::volumioPushState Nov 03 22:08:55 volumio volumio[992]: info: MRS: Pushing multiroomSync output update for this device Nov 03 22:08:55 volumio volumio[992]: info: MRS: Pushing multiroomSync output Nov 03 22:08:55 volumio volumio[992]: info: CoreCommandRouter::volumioGetState Nov 03 22:08:55 volumio volumio[992]: info: CorePlayQueue::getTrack 34 Nov 03 22:08:55 volumio volumio[992]: info: CoreStateMachine::pushState Nov 03 22:08:55 volumio volumio[992]: info: CorePlayQueue::getTrack 34 Nov 03 22:08:55 volumio volumio[992]: info: CoreCommandRouter::volumioPushState Nov 03 22:08:55 volumio volumio[992]: info: MRS: Pushing multiroomSync output update for this device Nov 03 22:08:55 volumio volumio[992]: info: MRS: Pushing multiroomSync output Nov 03 22:08:55 volumio volumio[992]: info: CoreCommandRouter::volumioGetState Nov 03 22:08:55 volumio volumio[992]: info: CorePlayQueue::getTrack 34 Nov 03 22:08:55 volumio go-librespot[5733]: time="2025-11-03T22:08:55+01:00" level=trace msg="sent dealer ping" Nov 03 22:08:55 volumio volumio[992]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Nov 03 22:08:55 volumio volumio[992]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Nov 03 22:08:55 volumio go-librespot[5733]: time="2025-11-03T22:08:55+01:00" level=trace msg="received dealer pong" Nov 03 22:08:55 volumio go-librespot[5733]: time="2025-11-03T22:08:55+01:00" level=debug msg="fetched chunk 2/10, size: 524288" uri="spotify:track:7Gh6J73NeF1bgtyijbgO2k" Nov 03 22:08:55 volumio go-librespot[5733]: time="2025-11-03T22:08:55+01:00" level=debug msg="fetched chunk 3/10, size: 524288" uri="spotify:track:7Gh6J73NeF1bgtyijbgO2k" Nov 03 22:08:55 volumio volumio[992]: SPOTIFY: PUSH STATE SPOTIFY Nov 03 22:08:55 volumio volumio[992]: SPOTIFY: {"status":"play","service":"spop","title":"Wicked Game","artist":"LÖVEE, HeɅven, Jessie Villa","album":"Wicked Game","albumart":"https://i.scdn.co/image/ab67616d00001e02cbb5809484ca5855c8a3ba99","uri":"spotify:track:7Gh6J73NeF1bgtyijbgO2k","trackType":"spotify","seek":0,"duration":127,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Nov 03 22:08:55 volumio volumio[992]: info: CoreCommandRouter::servicePushState Nov 03 22:08:55 volumio volumio[992]: info: CorePlayQueue::getTrack 34 Nov 03 22:08:55 volumio volumio[992]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Wicked Game","artist":"LÖVEE, HeɅven, Jessie Villa","album":"Wicked Game","albumart":"https://i.scdn.co/image/ab67616d00001e02cbb5809484ca5855c8a3ba99","uri":"spotify:track:7Gh6J73NeF1bgtyijbgO2k","trackType":"spotify","seek":0,"duration":127,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Nov 03 22:08:55 volumio volumio[992]: verbose: CURRENT POSITION 34 Nov 03 22:08:55 volumio volumio[992]: info: CoreStateMachine::syncState stateService play Nov 03 22:08:55 volumio volumio[992]: info: CoreStateMachine::syncState currentStatus play Nov 03 22:08:55 volumio volumio[992]: info: Received an update from plugin. extracting info from payload Nov 03 22:08:55 volumio volumio[992]: info: CoreStateMachine::pushState Nov 03 22:08:55 volumio volumio[992]: info: CorePlayQueue::getTrack 34 Nov 03 22:08:55 volumio volumio[992]: info: CoreCommandRouter::volumioPushState Nov 03 22:08:55 volumio volumio[992]: info: MRS: Pushing multiroomSync output update for this device Nov 03 22:08:55 volumio volumio[992]: info: MRS: Pushing multiroomSync output Nov 03 22:08:55 volumio volumio[992]: info: CoreCommandRouter::volumioGetState Nov 03 22:08:55 volumio volumio[992]: info: CorePlayQueue::getTrack 34 Nov 03 22:08:55 volumio volumio[992]: info: CoreStateMachine::pushState Nov 03 22:08:55 volumio volumio[992]: info: CorePlayQueue::getTrack 34 Nov 03 22:08:55 volumio volumio[992]: info: CoreCommandRouter::volumioPushState Nov 03 22:08:55 volumio volumio[992]: info: MRS: Pushing multiroomSync output update for this device Nov 03 22:08:55 volumio volumio[992]: info: MRS: Pushing multiroomSync output Nov 03 22:08:55 volumio volumio[992]: info: CoreCommandRouter::volumioGetState Nov 03 22:08:55 volumio volumio[992]: info: CorePlayQueue::getTrack 34 Nov 03 22:08:55 volumio volumio[992]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Nov 03 22:08:55 volumio volumio[992]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Nov 03 22:08:55 volumio volumio[992]: SPOTIFY: PUSH STATE SPOTIFY Nov 03 22:08:55 volumio volumio[992]: SPOTIFY: {"status":"play","service":"spop","title":"Wicked Game","artist":"LÖVEE, HeɅven, Jessie Villa","album":"Wicked Game","albumart":"https://i.scdn.co/image/ab67616d00001e02cbb5809484ca5855c8a3ba99","uri":"spotify:track:7Gh6J73NeF1bgtyijbgO2k","trackType":"spotify","seek":0,"duration":127,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Nov 03 22:08:55 volumio volumio[992]: info: CoreCommandRouter::servicePushState Nov 03 22:08:55 volumio volumio[992]: info: CorePlayQueue::getTrack 34 Nov 03 22:08:55 volumio volumio[992]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Wicked Game","artist":"LÖVEE, HeɅven, Jessie Villa","album":"Wicked Game","albumart":"https://i.scdn.co/image/ab67616d00001e02cbb5809484ca5855c8a3ba99","uri":"spotify:track:7Gh6J73NeF1bgtyijbgO2k","trackType":"spotify","seek":0,"duration":127,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Nov 03 22:08:55 volumio volumio[992]: verbose: CURRENT POSITION 34 Nov 03 22:08:55 volumio volumio[992]: info: CoreStateMachine::syncState stateService play Nov 03 22:08:55 volumio volumio[992]: info: CoreStateMachine::syncState currentStatus play Nov 03 22:08:55 volumio volumio[992]: info: Received an update from plugin. extracting info from payload Nov 03 22:08:55 volumio volumio[992]: info: CoreStateMachine::pushState Nov 03 22:08:55 volumio volumio[992]: info: CorePlayQueue::getTrack 34 Nov 03 22:08:55 volumio volumio[992]: info: CoreCommandRouter::volumioPushState Nov 03 22:08:55 volumio volumio[992]: info: MRS: Pushing multiroomSync output update for this device Nov 03 22:08:55 volumio volumio[992]: info: MRS: Pushing multiroomSync output Nov 03 22:08:55 volumio volumio[992]: info: CoreCommandRouter::volumioGetState Nov 03 22:08:55 volumio volumio[992]: info: CorePlayQueue::getTrack 34 Nov 03 22:08:55 volumio volumio[992]: info: CoreStateMachine::pushState Nov 03 22:08:55 volumio volumio[992]: info: CorePlayQueue::getTrack 34 Nov 03 22:08:55 volumio volumio[992]: info: CoreCommandRouter::volumioPushState Nov 03 22:08:55 volumio volumio[992]: info: MRS: Pushing multiroomSync output update for this device Nov 03 22:08:55 volumio volumio[992]: info: MRS: Pushing multiroomSync output Nov 03 22:08:55 volumio volumio[992]: info: CoreCommandRouter::volumioGetState Nov 03 22:08:55 volumio volumio[992]: info: CorePlayQueue::getTrack 34 Nov 03 22:08:55 volumio volumio[992]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Nov 03 22:08:55 volumio volumio[992]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Nov 03 22:08:56 volumio volumio[992]: info: CoreCommandRouter::volumioPrevious Nov 03 22:08:56 volumio volumio[992]: info: CoreStateMachine::previous Nov 03 22:08:56 volumio volumio[992]: info: CorePlayQueue::getTrack 34 Nov 03 22:08:56 volumio volumio[992]: info: Spotify seek to: 0 Nov 03 22:08:56 volumio volumio[992]: info: Sending Spotify command with payload to local API: /player/seek Nov 03 22:08:56 volumio go-librespot[5733]: time="2025-11-03T22:08:56+01:00" level=debug msg="seek track to 0ms" Nov 03 22:08:56 volumio go-librespot[5733]: time="2025-11-03T22:08:56+01:00" level=trace msg="seek to 0ms (diff: -383ms, samples: 0, bytes: 18317)" uri="spotify:track:7Gh6J73NeF1bgtyijbgO2k" Nov 03 22:08:56 volumio go-librespot[5733]: time="2025-11-03T22:08:56+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 03 22:08:56 volumio go-librespot[5733]: time="2025-11-03T22:08:56+01:00" level=trace msg="scheduling prefetch in 98s" Nov 03 22:08:56 volumio go-librespot[5733]: time="2025-11-03T22:08:56+01:00" level=trace msg="emitting websocket event: seek" Nov 03 22:08:56 volumio volumio[992]: SPOTIFY: received: {"type":"seek","data":{"context_uri":"spotify:track:7Gh6J73NeF1bgtyijbgO2k","uri":"spotify:track:7Gh6J73NeF1bgtyijbgO2k","position":0,"duration":127895,"play_origin":"go-librespot"}} Nov 03 22:08:56 volumio volumio[992]: SPOTIFY: PUSH STATE SPOTIFY Nov 03 22:08:56 volumio volumio[992]: SPOTIFY: {"status":"play","service":"spop","title":"Wicked Game","artist":"LÖVEE, HeɅven, Jessie Villa","album":"Wicked Game","albumart":"https://i.scdn.co/image/ab67616d00001e02cbb5809484ca5855c8a3ba99","uri":"spotify:track:7Gh6J73NeF1bgtyijbgO2k","trackType":"spotify","seek":0,"duration":127,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Nov 03 22:08:56 volumio volumio[992]: info: CoreCommandRouter::servicePushState Nov 03 22:08:56 volumio volumio[992]: info: CorePlayQueue::getTrack 34 Nov 03 22:08:56 volumio volumio[992]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Wicked Game","artist":"LÖVEE, HeɅven, Jessie Villa","album":"Wicked Game","albumart":"https://i.scdn.co/image/ab67616d00001e02cbb5809484ca5855c8a3ba99","uri":"spotify:track:7Gh6J73NeF1bgtyijbgO2k","trackType":"spotify","seek":0,"duration":127,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Nov 03 22:08:56 volumio volumio[992]: verbose: CURRENT POSITION 34 Nov 03 22:08:56 volumio volumio[992]: info: CoreStateMachine::syncState stateService play Nov 03 22:08:56 volumio volumio[992]: info: CoreStateMachine::syncState currentStatus play Nov 03 22:08:56 volumio volumio[992]: info: Received an update from plugin. extracting info from payload Nov 03 22:08:56 volumio volumio[992]: info: CoreStateMachine::pushState Nov 03 22:08:56 volumio volumio[992]: info: CorePlayQueue::getTrack 34 Nov 03 22:08:56 volumio volumio[992]: info: CoreCommandRouter::volumioPushState Nov 03 22:08:56 volumio volumio[992]: info: MRS: Pushing multiroomSync output update for this device Nov 03 22:08:56 volumio volumio[992]: info: MRS: Pushing multiroomSync output Nov 03 22:08:56 volumio volumio[992]: info: CoreCommandRouter::volumioGetState Nov 03 22:08:56 volumio volumio[992]: info: CorePlayQueue::getTrack 34 Nov 03 22:08:56 volumio volumio[992]: info: CoreStateMachine::pushState Nov 03 22:08:56 volumio volumio[992]: info: CorePlayQueue::getTrack 34 Nov 03 22:08:56 volumio volumio[992]: info: CoreCommandRouter::volumioPushState Nov 03 22:08:56 volumio volumio[992]: info: MRS: Pushing multiroomSync output update for this device Nov 03 22:08:56 volumio volumio[992]: info: MRS: Pushing multiroomSync output Nov 03 22:08:56 volumio volumio[992]: info: CoreCommandRouter::volumioGetState Nov 03 22:08:56 volumio volumio[992]: info: CorePlayQueue::getTrack 34 Nov 03 22:08:56 volumio volumio[992]: SPOTIFY: received: {"type":"seek","data":{"context_uri":"spotify:track:7Gh6J73NeF1bgtyijbgO2k","uri":"spotify:track:7Gh6J73NeF1bgtyijbgO2k","position":0,"duration":127895,"play_origin":"go-librespot"}} Nov 03 22:08:56 volumio volumio[992]: SPOTIFY: PUSH STATE SPOTIFY Nov 03 22:08:56 volumio volumio[992]: SPOTIFY: {"status":"play","service":"spop","title":"Wicked Game","artist":"LÖVEE, HeɅven, Jessie Villa","album":"Wicked Game","albumart":"https://i.scdn.co/image/ab67616d00001e02cbb5809484ca5855c8a3ba99","uri":"spotify:track:7Gh6J73NeF1bgtyijbgO2k","trackType":"spotify","seek":0,"duration":127,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Nov 03 22:08:56 volumio volumio[992]: info: CoreCommandRouter::servicePushState Nov 03 22:08:56 volumio volumio[992]: info: CorePlayQueue::getTrack 34 Nov 03 22:08:56 volumio volumio[992]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Wicked Game","artist":"LÖVEE, HeɅven, Jessie Villa","album":"Wicked Game","albumart":"https://i.scdn.co/image/ab67616d00001e02cbb5809484ca5855c8a3ba99","uri":"spotify:track:7Gh6J73NeF1bgtyijbgO2k","trackType":"spotify","seek":0,"duration":127,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Nov 03 22:08:56 volumio volumio[992]: verbose: CURRENT POSITION 34 Nov 03 22:08:56 volumio volumio[992]: info: CoreStateMachine::syncState stateService play Nov 03 22:08:56 volumio volumio[992]: info: CoreStateMachine::syncState currentStatus play Nov 03 22:08:56 volumio volumio[992]: info: Received an update from plugin. extracting info from payload Nov 03 22:08:56 volumio volumio[992]: info: CoreStateMachine::pushState Nov 03 22:08:56 volumio volumio[992]: info: CorePlayQueue::getTrack 34 Nov 03 22:08:56 volumio volumio[992]: info: CoreCommandRouter::volumioPushState Nov 03 22:08:56 volumio volumio[992]: info: MRS: Pushing multiroomSync output update for this device Nov 03 22:08:56 volumio volumio[992]: info: MRS: Pushing multiroomSync output Nov 03 22:08:56 volumio volumio[992]: info: CoreCommandRouter::volumioGetState Nov 03 22:08:56 volumio volumio[992]: info: CorePlayQueue::getTrack 34 Nov 03 22:08:56 volumio volumio[992]: info: CoreStateMachine::pushState Nov 03 22:08:56 volumio volumio[992]: info: CorePlayQueue::getTrack 34 Nov 03 22:08:56 volumio volumio[992]: info: CoreCommandRouter::volumioPushState Nov 03 22:08:56 volumio volumio[992]: info: MRS: Pushing multiroomSync output update for this device Nov 03 22:08:56 volumio volumio[992]: info: MRS: Pushing multiroomSync output Nov 03 22:08:56 volumio volumio[992]: info: CoreCommandRouter::volumioGetState Nov 03 22:08:56 volumio volumio[992]: info: CorePlayQueue::getTrack 34 Nov 03 22:08:56 volumio volumio[992]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Nov 03 22:08:56 volumio volumio[992]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Nov 03 22:08:56 volumio volumio[992]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Nov 03 22:08:56 volumio volumio[992]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Nov 03 22:09:05 volumio volumio[992]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Nov 03 22:09:05 volumio volumio[992]: info: In handleBrowseUri, curUri=spotify Nov 03 22:09:06 volumio volumio[992]: info: Preload queue cleared Nov 03 22:09:06 volumio volumio[992]: info: Preload queue cleared Nov 03 22:09:06 volumio volumio[992]: info: Preload queue cleared Nov 03 22:09:06 volumio volumio[992]: info: Preload queue cleared Nov 03 22:09:08 volumio go-librespot[5733]: time="2025-11-03T22:09:08+01:00" level=debug msg="fetched chunk 4/10, size: 524288" uri="spotify:track:7Gh6J73NeF1bgtyijbgO2k" Nov 03 22:09:21 volumio go-librespot[5733]: time="2025-11-03T22:09:21+01:00" level=debug msg="fetched chunk 5/10, size: 524288" uri="spotify:track:7Gh6J73NeF1bgtyijbgO2k" Nov 03 22:09:25 volumio go-librespot[5733]: time="2025-11-03T22:09:25+01:00" level=trace msg="sent dealer ping" Nov 03 22:09:25 volumio go-librespot[5733]: time="2025-11-03T22:09:25+01:00" level=trace msg="received dealer pong" Nov 03 22:09:29 volumio volumio[992]: info: CoreCommandRouter::executeOnPlugin: multiroom , audioOutputPlay Nov 03 22:09:29 volumio volumio[992]: info: Error : CoreCommandRouter::executeOnPlugin: No method [audioOutputPlay] in plugin multiroom Nov 03 22:09:29 volumio volumio[992]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 03 22:09:29 volumio volumio[992]: TypeError: Cannot read property 'then' of undefined Nov 03 22:09:29 volumio volumio[992]: at outputs.audioOutputPlay (/volumio/app/plugins/audio_interface/outputs/index.js:367:9) Nov 03 22:09:29 volumio volumio[992]: at CoreCommandRouter.audioOutputPlay (/volumio/app/index.js:2279:30) Nov 03 22:09:29 volumio volumio[992]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:1456:26) Nov 03 22:09:29 volumio volumio[992]: at Socket.emit (events.js:315:20) Nov 03 22:09:29 volumio volumio[992]: at /volumio/node_modules/socket.io/lib/socket.js:528:12 Nov 03 22:09:29 volumio volumio[992]: at processTicksAndRejections (internal/process/task_queues.js:75:11) Nov 03 22:09:29 volumio volumio[992]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 03 22:09:29 volumio sudo[31876]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-11-03 22:08 Nov 03 22:09:29 volumio sudo[31876]: 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="29866754e5f1d7e4d0f581c10d9f22852f6f21db" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="fc4c820ddd3b5fc1a7a6b54ef112273ebd122010" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Sat 26 Jul 2025 10:25:36 AM CEST" VOLUMIO_VERSION="3.832" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="cf6e14681b2ecbbdc9a62186b0f3114c"