-- Logs begin at Mon 2024-04-15 14:13:53 CEST, end at Tue 2024-04-16 17:16:41 CEST. -- Apr 16 17:15:00 rivo-streamer volumio[5764]: info: MYVOLUMIO: Adding device Apr 16 17:15:00 rivo-streamer volumio[5764]: info: MYVOLUMIO: Evaluating Server Apr 16 17:15:01 rivo-streamer volumio[5764]: error: MyVolumio Plugin failed to start in a timely fashion Apr 16 17:15:01 rivo-streamer volumio[5764]: info: BOOT COMPLETED Apr 16 17:15:01 rivo-streamer volumio[5764]: [Metrics] CommandRouter: 45s 41.85ms Apr 16 17:15:01 rivo-streamer volumio[5764]: info: CoreCommandRouter::volumiosetStartupVolume Apr 16 17:15:01 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 16 17:15:01 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 16 17:15:01 rivo-streamer volumio[5764]: info: CoreCommandRouter::Close All Modals sent Apr 16 17:15:01 rivo-streamer volumio[5764]: info: CoreCommandRouter::Close All Modals sent Apr 16 17:15:01 rivo-streamer volumio[5764]: info: Setting Geolocation for MyVolumio to eu5 Apr 16 17:15:01 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 16 17:15:01 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 16 17:15:01 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 16 17:15:01 rivo-streamer volumio[6295]: ...............................................................................................................................................................................................++++ Apr 16 17:15:01 rivo-streamer volumio[6295]: e is 65537 (0x010001) Apr 16 17:15:01 rivo-streamer volumio[6295]: writing RSA key Apr 16 17:15:02 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Apr 16 17:15:02 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Apr 16 17:15:02 rivo-streamer volumio[5764]: xcb_connection_has_error() returned true Apr 16 17:15:02 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Apr 16 17:15:02 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Apr 16 17:15:02 rivo-streamer volumio[5764]: info: Updating MyVolumio device info Apr 16 17:15:02 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 16 17:15:02 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 16 17:15:02 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 16 17:15:03 rivo-streamer volumio[5764]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Apr 16 17:15:03 rivo-streamer volumio[5764]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Apr 16 17:15:06 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Apr 16 17:15:06 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Apr 16 17:15:06 rivo-streamer volumio[5764]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 7 Apr 16 17:15:06 rivo-streamer volumio[5764]: info: CoreCommandRouter::volumioGetState Apr 16 17:15:06 rivo-streamer volumio[5764]: info: CorePlayQueue::getTrack 0 Apr 16 17:15:08 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Apr 16 17:15:08 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 16 17:15:08 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Apr 16 17:15:08 rivo-streamer volumio[5764]: info: Reinitializing MCU Serial Connection Apr 16 17:15:08 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: inputs , initializeSerialPort Apr 16 17:15:08 rivo-streamer volumio[5764]: info: Serial port is open, closing it Apr 16 17:15:08 rivo-streamer volumio[5764]: info: Initializing Serial Communication on port /dev/ttyS3 Apr 16 17:15:08 rivo-streamer kernel: meson_uart ffd22000.serial: ttyS3 use xtal(24M) 24000000 change 115200 to 115200 Apr 16 17:15:08 rivo-streamer volumio[5764]: info: Serial port opened successfully Apr 16 17:15:08 rivo-streamer volumio[5764]: info: Sending serial start messages Apr 16 17:15:08 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 16 17:15:08 rivo-streamer volumio[5764]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 8 Apr 16 17:15:08 rivo-streamer volumio-remote-updater[4506]: No test mode Apr 16 17:15:08 rivo-streamer volumio-remote-updater[4506]: No alpha test mode Apr 16 17:15:08 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled Apr 16 17:15:08 rivo-streamer volumio[5764]: info: CoreStateMachine::pushState Apr 16 17:15:08 rivo-streamer volumio[5764]: info: CorePlayQueue::getTrack 0 Apr 16 17:15:08 rivo-streamer volumio[5764]: info: CoreCommandRouter::volumioPushState Apr 16 17:15:08 rivo-streamer volumio[5764]: info: MRS: Pushing multiroomSync output update for this device Apr 16 17:15:08 rivo-streamer volumio[5764]: info: MRS: Pushing multiroomSync output Apr 16 17:15:08 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: system , setAdditionalSVInfo Apr 16 17:15:08 rivo-streamer volumio[5764]: info: Setting Additional System Software info: Hardware Revision: 2.0, Firmware Version: 0.3.3 Apr 16 17:15:08 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: system , setHwFwVersion Apr 16 17:15:08 rivo-streamer volumio[5764]: info: Setting HW Firmware info: 0.3.3 Apr 16 17:15:08 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: system , setHwVersion Apr 16 17:15:08 rivo-streamer volumio[5764]: info: Setting HW Version info: 2.0 Apr 16 17:15:08 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: system , setAdditionalSVInfo Apr 16 17:15:08 rivo-streamer volumio[5764]: info: Setting Additional System Software info: Hardware Revision: 2.0, Firmware Version: 0.3.3 Apr 16 17:15:08 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: system , setHwFwVersion Apr 16 17:15:08 rivo-streamer volumio[5764]: info: Setting HW Firmware info: 0.3.3 Apr 16 17:15:08 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: system , setHwVersion Apr 16 17:15:08 rivo-streamer volumio[5764]: info: Setting HW Version info: 2.0 Apr 16 17:15:08 rivo-streamer volumio[5764]: info: MCU Signalled PowerOff Capabilities, enabling MCU Poweroff Apr 16 17:15:08 rivo-streamer volumio[5764]: info: MCU Signalled Headphone Mode Disabled Apr 16 17:15:08 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: raat , reportHeadphoneState Apr 16 17:15:08 rivo-streamer volumio[5764]: info: MCU Signalled Sleep Mode Disabled Apr 16 17:15:08 rivo-streamer volumio[5764]: info: MCU Signalled Auto Boot Mode On Power Disabled Apr 16 17:15:08 rivo-streamer sudo[6797]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/xset dpms force on Apr 16 17:15:08 rivo-streamer sudo[6797]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 16 17:15:08 rivo-streamer sudo[6797]: pam_unix(sudo:session): session closed for user root Apr 16 17:15:08 rivo-streamer volumio[5764]: info: CoreCommandRouter::volumioGetState Apr 16 17:15:08 rivo-streamer volumio[5764]: info: CorePlayQueue::getTrack 0 Apr 16 17:15:08 rivo-streamer volumio[5764]: info: Adding Inputs via Serial API Apr 16 17:15:08 rivo-streamer volumio[5764]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Apr 16 17:15:08 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Apr 16 17:15:08 rivo-streamer volumio[5764]: info: CoreCommandRouter::servicePushState Apr 16 17:15:08 rivo-streamer volumio[5764]: info: CorePlayQueue::getTrack 0 Apr 16 17:15:08 rivo-streamer volumio[5764]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current webradio Received inputs Apr 16 17:15:08 rivo-streamer volumio[5764]: info: CoreCommandRouter::volumiosetSourceActiveno-source Apr 16 17:15:08 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 16 17:15:08 rivo-streamer volumio[5764]: Cannot find translation for source QOBUZ Apr 16 17:15:10 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Apr 16 17:15:11 rivo-streamer volumio[5764]: info: Disabling MyMusic plugin multiroom Apr 16 17:15:11 rivo-streamer volumio[5764]: info: Disabling plugin multiroom Apr 16 17:15:11 rivo-streamer volumio[5764]: info: Preparing to generate the ALSA configuration file Apr 16 17:15:11 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 16 17:15:11 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 16 17:15:11 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Apr 16 17:15:11 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Apr 16 17:15:11 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Apr 16 17:15:11 rivo-streamer volumio[5764]: info: CoreCommandRouter::volumioGetBrowseSources Apr 16 17:15:11 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Apr 16 17:15:11 rivo-streamer volumio[5764]: info: Asound.conf file written Apr 16 17:15:11 rivo-streamer sudo[6803]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf Apr 16 17:15:11 rivo-streamer sudo[6803]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 16 17:15:11 rivo-streamer sudo[6803]: pam_unix(sudo:session): session closed for user root Apr 16 17:15:11 rivo-streamer kernel: Fine tdm clk setting range (0~2000000), 12287994 Apr 16 17:15:11 rivo-streamer kernel: Fine spdif sysclk setting range(0~2000000), 5644797 Apr 16 17:15:11 rivo-streamer kernel: out of value, fixed it Apr 16 17:15:11 rivo-streamer kernel: id=0 set inskew=0 Apr 16 17:15:11 rivo-streamer volumio[5764]: xcb_connection_has_error() returned true Apr 16 17:15:11 rivo-streamer volumio[5764]: Found hardware: "AML-AUGESOUND-M" "" "" "" "" Apr 16 17:15:11 rivo-streamer volumio[5764]: Hardware is initialized using a generic method Apr 16 17:15:11 rivo-streamer volumio[5764]: /usr/sbin/alsactl: set_control:1461: Cannot write control '2:0:0:eARC_TX CDS:0' : Operation not permitted Apr 16 17:15:11 rivo-streamer volumio[5764]: /usr/sbin/alsactl: set_control:1461: Cannot write control '2:0:0:I2SIn CLK:0' : Operation not permitted Apr 16 17:15:11 rivo-streamer volumio[5764]: /usr/sbin/alsactl: set_control:1461: Cannot write control '2:0:0:SPDIFIN audio samplerate:0' : Operation not permitted Apr 16 17:15:11 rivo-streamer volumio[5764]: /usr/sbin/alsactl: set_control:1461: Cannot write control '2:0:0:SPDIFIN Audio Type:0' : Operation not permitted Apr 16 17:15:11 rivo-streamer volumio[5764]: info: Output device has changed, restarting MPD Apr 16 17:15:11 rivo-streamer sudo[6808]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Apr 16 17:15:11 rivo-streamer sudo[6808]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 16 17:15:11 rivo-streamer volumio[5764]: info: Output device has changed, restarting Shairport Sync Apr 16 17:15:11 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 16 17:15:11 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 16 17:15:11 rivo-streamer sudo[6808]: pam_unix(sudo:session): session closed for user root Apr 16 17:15:11 rivo-streamer sudo[6811]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Apr 16 17:15:11 rivo-streamer sudo[6811]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 16 17:15:11 rivo-streamer systemd[1]: Stopping Music Player Daemon... Apr 16 17:15:11 rivo-streamer volumio[5764]: xcb_connection_has_error() returned true Apr 16 17:15:11 rivo-streamer volumio[5764]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Apr 16 17:15:11 rivo-streamer volumio[5764]: xcb_connection_has_error() returned true Apr 16 17:15:11 rivo-streamer volumio[5764]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Apr 16 17:15:11 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 16 17:15:11 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 16 17:15:11 rivo-streamer volumio[5764]: info: Done. Apr 16 17:15:11 rivo-streamer volumio[5764]: info: MRS: STARTING volumioStreaming Apr 16 17:15:11 rivo-streamer kernel: aml_spdif_open Apr 16 17:15:11 rivo-streamer kernel: audio_ddr_mngr: frddrs[0] registered by device ff660000.audiobus:spdif@0 Apr 16 17:15:11 rivo-streamer kernel: spdif_a keep clk continuous Apr 16 17:15:11 rivo-streamer kernel: aml_spdif_close Apr 16 17:15:11 rivo-streamer kernel: audio_ddr_mngr: frddrs[0] released by device ff660000.audiobus:spdif@0 Apr 16 17:15:11 rivo-streamer sudo[6821]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/rm -f /tmp/hls/stream.m3u8 /tmp/hls/stream0.ts /tmp/hls/stream1.ts /tmp/hls/stream2.ts /tmp/hls/stream3.ts /tmp/hls/stream4.ts /tmp/hls/stream5.ts Apr 16 17:15:11 rivo-streamer sudo[6821]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 16 17:15:11 rivo-streamer sudo[6821]: pam_unix(sudo:session): session closed for user root Apr 16 17:15:11 rivo-streamer sudo[6823]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumioStreaming Apr 16 17:15:11 rivo-streamer sudo[6823]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 16 17:15:11 rivo-streamer volumio[5764]: ------------------------------------ BT MESSAGE: BT STATUS: running Apr 16 17:15:11 rivo-streamer systemd[1]: mpd.service: Succeeded. Apr 16 17:15:11 rivo-streamer systemd[1]: Stopped Music Player Daemon. Apr 16 17:15:11 rivo-streamer systemd[1]: Starting Music Player Daemon... Apr 16 17:15:11 rivo-streamer volumio[5764]: info: MPD Permissions set Apr 16 17:15:11 rivo-streamer volumio[5764]: info: CoreStateMachine::pushState Apr 16 17:15:11 rivo-streamer volumio[5764]: info: CorePlayQueue::getTrack 0 Apr 16 17:15:11 rivo-streamer volumio[5764]: info: CoreCommandRouter::volumioPushState Apr 16 17:15:11 rivo-streamer systemd[1]: Stopping VolumioStreamingService... Apr 16 17:15:11 rivo-streamer volumio[5764]: info: MRS: Pushing multiroomSync output update for this device Apr 16 17:15:11 rivo-streamer systemd[1]: volumioStreaming.service: Main process exited, code=killed, status=15/TERM Apr 16 17:15:11 rivo-streamer volumio[5764]: info: MRS: Pushing multiroomSync output Apr 16 17:15:11 rivo-streamer systemd[1]: volumioStreaming.service: Succeeded. Apr 16 17:15:11 rivo-streamer systemd[1]: Stopped VolumioStreamingService. Apr 16 17:15:11 rivo-streamer volumio[5764]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Apr 16 17:15:11 rivo-streamer systemd[1]: Started VolumioStreamingService. Apr 16 17:15:11 rivo-streamer sudo[6823]: pam_unix(sudo:session): session closed for user root Apr 16 17:15:11 rivo-streamer volumio[5764]: ------------------------------------ BT MESSAGE: BT STATUS: running Apr 16 17:15:11 rivo-streamer volumio[5764]: ------------------------------------ BT MESSAGE: BT STATUS: running Apr 16 17:15:11 rivo-streamer volumio[5764]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Apr 16 17:15:12 rivo-streamer sudo[6850]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/rm -f /tmp/hls/* Apr 16 17:15:12 rivo-streamer sudo[6850]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 16 17:15:12 rivo-streamer volumio[5764]: info: MRS: volumioStreaming STARTED Apr 16 17:15:12 rivo-streamer sudo[6850]: pam_unix(sudo:session): session closed for user root Apr 16 17:15:12 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 16 17:15:12 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 16 17:15:12 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 16 17:15:12 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 16 17:15:12 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 16 17:15:12 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber Apr 16 17:15:12 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 16 17:15:12 rivo-streamer volumio[5764]: info: Starting Shairport Sync Apr 16 17:15:12 rivo-streamer sudo[6873]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Apr 16 17:15:12 rivo-streamer sudo[6873]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 16 17:15:12 rivo-streamer systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Apr 16 17:15:12 rivo-streamer systemd[1]: shairport-sync.service: Succeeded. Apr 16 17:15:12 rivo-streamer volumio[5764]: ------------------------------------ BT MESSAGE: BT STATUS: running Apr 16 17:15:12 rivo-streamer systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Apr 16 17:15:12 rivo-streamer systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Apr 16 17:15:12 rivo-streamer sudo[6873]: pam_unix(sudo:session): session closed for user root Apr 16 17:15:12 rivo-streamer volumio[5764]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Apr 16 17:15:12 rivo-streamer volumio[5764]: info: Shairport-Sync Started Apr 16 17:15:13 rivo-streamer mpd[6826]: Apr 16 17:15 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Apr 16 17:15:13 rivo-streamer systemd[1]: Started Music Player Daemon. Apr 16 17:15:13 rivo-streamer sudo[6811]: pam_unix(sudo:session): session closed for user root Apr 16 17:15:13 rivo-streamer volumio[5764]: error: updateQueue error: null Apr 16 17:15:14 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Apr 16 17:15:16 rivo-streamer volumio[5764]: info: Disabling MyMusic plugin upnp Apr 16 17:15:16 rivo-streamer sudo[6902]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop upmpdcli.service Apr 16 17:15:16 rivo-streamer sudo[6902]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 16 17:15:16 rivo-streamer systemd[1]: Stopping UPnP Renderer front-end to MPD... Apr 16 17:15:16 rivo-streamer volumio[5764]: error: Upnp client error: Error: This socket has been ended by the other party Apr 16 17:15:16 rivo-streamer volumio[5764]: ------------------------------------ BT MESSAGE: BT STATUS: running Apr 16 17:15:18 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Apr 16 17:15:22 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Apr 16 17:15:23 rivo-streamer volumio[5764]: info: Disabling MyMusic plugin airplay_emulation Apr 16 17:15:23 rivo-streamer volumio[5764]: info: CoreCommandRouter::volumioRemoveToBrowseSourcesShairport-Sync Apr 16 17:15:23 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 16 17:15:23 rivo-streamer volumio[5764]: Cannot find translation for source QOBUZ Apr 16 17:15:23 rivo-streamer volumio[5764]: info: Disabling plugin airplay_emulation Apr 16 17:15:23 rivo-streamer volumio[5764]: info: Done. Apr 16 17:15:23 rivo-streamer sudo[6905]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop shairport-sync Apr 16 17:15:23 rivo-streamer sudo[6905]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 16 17:15:23 rivo-streamer systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Apr 16 17:15:23 rivo-streamer systemd[1]: shairport-sync.service: Succeeded. Apr 16 17:15:23 rivo-streamer systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Apr 16 17:15:23 rivo-streamer sudo[6905]: pam_unix(sudo:session): session closed for user root Apr 16 17:15:23 rivo-streamer volumio[5764]: ------------------------------------ BT MESSAGE: BT STATUS: running Apr 16 17:15:23 rivo-streamer volumio[5764]: info: Shairport-Sync Stopped Apr 16 17:15:26 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Apr 16 17:15:30 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Apr 16 17:15:34 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Apr 16 17:15:38 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Apr 16 17:15:42 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Apr 16 17:15:46 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Apr 16 17:15:50 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Apr 16 17:15:54 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Apr 16 17:15:55 rivo-streamer volumiologrotate[4554]: ls: cannot access '/var/log/samba/log.wb-RIVO': No such file or directory Apr 16 17:15:55 rivo-streamer volumiologrotate[4554]: ls: cannot access 'STREAMER': No such file or directory Apr 16 17:15:58 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Apr 16 17:16:02 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Apr 16 17:16:07 rivo-streamer volumio[5764]: info: CoreCommandRouter::volumioGetQueue Apr 16 17:16:07 rivo-streamer volumio[5764]: info: CoreStateMachine::getQueue Apr 16 17:16:07 rivo-streamer volumio[5764]: info: CorePlayQueue::getQueue Apr 16 17:16:09 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: qobuz , handleBrowseUri Apr 16 17:16:09 rivo-streamer volumio[5764]: info: handleBrowseUri took 354 milliseconds Apr 16 17:16:09 rivo-streamer volumio[5764]: info: Preload queue cleared Apr 16 17:16:10 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: qobuz , handleBrowseUri Apr 16 17:16:11 rivo-streamer volumio[5764]: info: handleBrowseUri took 548 milliseconds Apr 16 17:16:11 rivo-streamer volumio[5764]: info: Preload queue cleared Apr 16 17:16:13 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: qobuz , handleBrowseUri Apr 16 17:16:14 rivo-streamer volumio[5764]: info: handleBrowseUri took 556 milliseconds Apr 16 17:16:14 rivo-streamer volumio[5764]: info: Preload queue cleared Apr 16 17:16:14 rivo-streamer volumio[5764]: info: Preloading song: qobuz://song/222612970 Apr 16 17:16:14 rivo-streamer volumio[5764]: info: Preloading song: qobuz://song/222612971 Apr 16 17:16:14 rivo-streamer volumio[5764]: info: Preloading song: qobuz://song/222612972 Apr 16 17:16:14 rivo-streamer volumio[5764]: info: Preloading song: qobuz://song/222612973 Apr 16 17:16:14 rivo-streamer volumio[5764]: info: Preloading song: qobuz://song/222612974 Apr 16 17:16:14 rivo-streamer volumio[5764]: info: Preloading song: qobuz://song/222612975 Apr 16 17:16:14 rivo-streamer volumio[5764]: info: Preloading song: qobuz://song/222612976 Apr 16 17:16:14 rivo-streamer volumio[5764]: info: Preloading song: qobuz://song/222612977 Apr 16 17:16:14 rivo-streamer volumio[5764]: info: Preloading song: qobuz://song/222612978 Apr 16 17:16:14 rivo-streamer volumio[5764]: info: Preloading song: qobuz://song/222612979 Apr 16 17:16:14 rivo-streamer volumio[5764]: info: Preloading song: qobuz://song/222612980 Apr 16 17:16:14 rivo-streamer volumio[5764]: info: Preloading song: qobuz://song/222612981 Apr 16 17:16:14 rivo-streamer volumio[5764]: info: Exploding uri qobuz://song/222612970 in service qobuz Apr 16 17:16:14 rivo-streamer volumio[5764]: info: Exploding uri qobuz://song/222612971 in service qobuz Apr 16 17:16:14 rivo-streamer volumio[5764]: info: Exploding uri qobuz://song/222612972 in service qobuz Apr 16 17:16:14 rivo-streamer volumio[5764]: info: Exploding uri qobuz://song/222612973 in service qobuz Apr 16 17:16:14 rivo-streamer volumio[5764]: info: Exploding uri qobuz://song/222612974 in service qobuz Apr 16 17:16:14 rivo-streamer volumio[5764]: info: Executing endpoint getSimilarAlbums Apr 16 17:16:14 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getSimilarAlbums Apr 16 17:16:14 rivo-streamer volumio[5764]: info: Exploding uri qobuz://song/222612975 in service qobuz Apr 16 17:16:14 rivo-streamer volumio[5764]: info: Exploding uri qobuz://song/222612976 in service qobuz Apr 16 17:16:14 rivo-streamer volumio[5764]: info: Executing endpoint metavolumio Apr 16 17:16:14 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Apr 16 17:16:14 rivo-streamer volumio[5764]: info: Executing endpoint metavolumio Apr 16 17:16:14 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Apr 16 17:16:14 rivo-streamer volumio[5764]: info: Exploding uri qobuz://song/222612977 in service qobuz Apr 16 17:16:14 rivo-streamer volumio[5764]: info: Exploding uri qobuz://song/222612978 in service qobuz Apr 16 17:16:14 rivo-streamer volumio[5764]: info: Exploding uri qobuz://song/222612979 in service qobuz Apr 16 17:16:14 rivo-streamer volumio[5764]: info: Exploding uri qobuz://song/222612980 in service qobuz Apr 16 17:16:14 rivo-streamer volumio[5764]: info: Exploding uri qobuz://song/222612981 in service qobuz Apr 16 17:16:14 rivo-streamer volumio[5764]: info: explodeUri took 596 milliseconds Apr 16 17:16:14 rivo-streamer volumio[5764]: info: explodeUri took 567 milliseconds Apr 16 17:16:14 rivo-streamer volumio[5764]: info: explodeUri took 524 milliseconds Apr 16 17:16:14 rivo-streamer volumio[5764]: info: explodeUri took 587 milliseconds Apr 16 17:16:15 rivo-streamer volumio[5764]: info: explodeUri took 560 milliseconds Apr 16 17:16:15 rivo-streamer volumio[5764]: info: explodeUri took 568 milliseconds Apr 16 17:16:15 rivo-streamer volumio[5764]: info: explodeUri took 568 milliseconds Apr 16 17:16:15 rivo-streamer volumio[5764]: info: explodeUri took 582 milliseconds Apr 16 17:16:15 rivo-streamer volumio[5764]: info: explodeUri took 554 milliseconds Apr 16 17:16:15 rivo-streamer volumio[5764]: info: explodeUri took 566 milliseconds Apr 16 17:16:15 rivo-streamer volumio[5764]: info: explodeUri took 660 milliseconds Apr 16 17:16:16 rivo-streamer volumio[5764]: info: CoreCommandRouter::volumioPlay Apr 16 17:16:16 rivo-streamer volumio[5764]: info: CoreStateMachine::play index undefined Apr 16 17:16:16 rivo-streamer volumio[5764]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 16 17:16:16 rivo-streamer volumio[5764]: info: CorePlayQueue::getTrack 0 Apr 16 17:16:16 rivo-streamer volumio[5764]: info: CoreStateMachine::startPlaybackTimer Apr 16 17:16:16 rivo-streamer volumio[5764]: info: CorePlayQueue::getTrack 0 Apr 16 17:16:16 rivo-streamer volumio[5764]: info: CoreCommandRouter::volumioGetVisibleSources Apr 16 17:16:16 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 16 17:16:16 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Apr 16 17:16:16 rivo-streamer volumio[5764]: info: [1713280576181] ControllerWebradio::clearAddPlayTrack Apr 16 17:16:16 rivo-streamer volumio[5764]: verbose: ControllerMpd::sendMpdCommand stop Apr 16 17:16:16 rivo-streamer volumio[5764]: info: sendMpdCommand stop took 3 milliseconds Apr 16 17:16:16 rivo-streamer volumio[5764]: verbose: ControllerMpd::sendMpdCommand clear Apr 16 17:16:16 rivo-streamer volumio[5764]: info: Apr 16 17:16:16 rivo-streamer volumio[5764]: ---------------------------- MPD announces system playlist update Apr 16 17:16:16 rivo-streamer volumio[5764]: info: Ignoring MPD Status Update Apr 16 17:16:16 rivo-streamer volumio[5764]: info: sendMpdCommand clear took 4 milliseconds Apr 16 17:16:16 rivo-streamer volumio[5764]: verbose: ControllerMpd::sendMpdCommand load "http://yp.shoutcast.com/sbin/tunein-station.m3u?id=99499376" Apr 16 17:16:16 rivo-streamer volumio[5764]: error: updateQueue error: null Apr 16 17:16:16 rivo-streamer volumio[5764]: info: ------------------------------ 8ms Apr 16 17:16:16 rivo-streamer volumio[5764]: info: explodeUri took 1477 milliseconds Apr 16 17:16:17 rivo-streamer volumio[5764]: info: sendMpdCommand load "http://yp.shoutcast.com/sbin/tunein-station.m3u?id=99499376" took 1060 milliseconds Apr 16 17:16:17 rivo-streamer volumio[5764]: info: CoreStateMachine::setConsumeUpdateService mpd Apr 16 17:16:17 rivo-streamer volumio[5764]: verbose: ControllerMpd::sendMpdCommand play Apr 16 17:16:17 rivo-streamer volumio[5764]: info: Apr 16 17:16:17 rivo-streamer volumio[5764]: ---------------------------- MPD announces system playlist update Apr 16 17:16:17 rivo-streamer volumio[5764]: info: Ignoring MPD Status Update Apr 16 17:16:17 rivo-streamer volumio[5764]: info: sendMpdCommand play took 6 milliseconds Apr 16 17:16:17 rivo-streamer volumio[5764]: info: ------------------------------ 6ms Apr 16 17:16:17 rivo-streamer volumio[5764]: info: Apr 16 17:16:17 rivo-streamer volumio[5764]: ---------------------------- MPD announces state update: player Apr 16 17:16:17 rivo-streamer volumio[5764]: info: ControllerMpd::getState Apr 16 17:16:17 rivo-streamer volumio[5764]: verbose: ControllerMpd::sendMpdCommand status Apr 16 17:16:17 rivo-streamer kernel: aml_spdif_open Apr 16 17:16:17 rivo-streamer kernel: audio_ddr_mngr: frddrs[0] registered by device ff660000.audiobus:spdif@0 Apr 16 17:16:17 rivo-streamer kernel: set normal 512 fs /4 fs Apr 16 17:16:17 rivo-streamer kernel: set spdifout clk:5644800, mpll:22579200 Apr 16 17:16:17 rivo-streamer kernel: get spdifout clk:5644797, mpll:22579186 Apr 16 17:16:17 rivo-streamer kernel: aml_dai_set_spdif_fmt , fmt 0x4000 Apr 16 17:16:17 rivo-streamer kernel: set normal 512 fs /4 fs Apr 16 17:16:17 rivo-streamer kernel: set spdifout clk:5644800, mpll:22579200 Apr 16 17:16:17 rivo-streamer kernel: get spdifout clk:5644797, mpll:22579186 Apr 16 17:16:17 rivo-streamer kernel: spdif_info: rate: 44100, channel status ch0_l:0x100, ch0_r:0x100, ch1_l:0x0, ch1_r:0x0 Apr 16 17:16:17 rivo-streamer kernel: aml_spdif_fifo_ctrl, bit depth:24, frddr type:4, toddr:type:4 Apr 16 17:16:17 rivo-streamer volumio[5764]: info: Apr 16 17:16:17 rivo-streamer volumio[5764]: ---------------------------- MPD announces state update: player Apr 16 17:16:17 rivo-streamer volumio[5764]: info: sendMpdCommand status took 21 milliseconds Apr 16 17:16:17 rivo-streamer volumio[5764]: info: ControllerMpd::getState Apr 16 17:16:17 rivo-streamer volumio[5764]: verbose: ControllerMpd::sendMpdCommand status Apr 16 17:16:17 rivo-streamer volumio[5764]: verbose: ControllerMpd::parseState Apr 16 17:16:17 rivo-streamer volumio[5764]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 16 17:16:17 rivo-streamer volumio[5764]: info: sendMpdCommand status took 5 milliseconds Apr 16 17:16:17 rivo-streamer volumio[5764]: info: sendMpdCommand playlistinfo took 3 milliseconds Apr 16 17:16:17 rivo-streamer volumio[5764]: verbose: ControllerMpd::parseState Apr 16 17:16:17 rivo-streamer volumio[5764]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 16 17:16:17 rivo-streamer volumio[5764]: verbose: ControllerMpd::parseTrackInfo Apr 16 17:16:17 rivo-streamer volumio[5764]: info: ControllerMpd::pushState Apr 16 17:16:17 rivo-streamer volumio[5764]: info: CoreCommandRouter::servicePushState Apr 16 17:16:17 rivo-streamer volumio[5764]: info: CorePlayQueue::getTrack 0 Apr 16 17:16:17 rivo-streamer volumio[5764]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"stream","artist":"(#1 - 36/300) Retro80sRadio","album":null,"uri":"http://158.69.227.214:8113/stream","trackType":""} Apr 16 17:16:17 rivo-streamer volumio[5764]: verbose: CURRENT POSITION 0 Apr 16 17:16:17 rivo-streamer volumio[5764]: info: CoreStateMachine::syncState stateService play Apr 16 17:16:17 rivo-streamer volumio[5764]: info: CoreStateMachine::syncState currentStatus stop Apr 16 17:16:17 rivo-streamer volumio[5764]: info: ------------------------------ 46ms Apr 16 17:16:17 rivo-streamer volumio[5764]: info: sendMpdCommand playlistinfo took 13 milliseconds Apr 16 17:16:17 rivo-streamer volumio[5764]: verbose: ControllerMpd::parseTrackInfo Apr 16 17:16:17 rivo-streamer volumio[5764]: info: ControllerMpd::pushState Apr 16 17:16:17 rivo-streamer volumio[5764]: info: CoreCommandRouter::servicePushState Apr 16 17:16:17 rivo-streamer volumio[5764]: info: CorePlayQueue::getTrack 0 Apr 16 17:16:17 rivo-streamer volumio[5764]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"stream","artist":"(#1 - 36/300) Retro80sRadio","album":null,"uri":"http://158.69.227.214:8113/stream","trackType":""} Apr 16 17:16:17 rivo-streamer volumio[5764]: verbose: CURRENT POSITION 0 Apr 16 17:16:17 rivo-streamer volumio[5764]: info: CoreStateMachine::syncState stateService play Apr 16 17:16:17 rivo-streamer volumio[5764]: info: CoreStateMachine::syncState currentStatus play Apr 16 17:16:17 rivo-streamer volumio[5764]: info: Received an update from plugin. extracting info from payload Apr 16 17:16:17 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Apr 16 17:16:17 rivo-streamer volumio[5764]: info: CoreStateMachine::pushState Apr 16 17:16:17 rivo-streamer volumio[5764]: info: CorePlayQueue::getTrack 0 Apr 16 17:16:17 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 16 17:16:17 rivo-streamer volumio[5764]: info: CoreCommandRouter::volumioPushState Apr 16 17:16:17 rivo-streamer volumio[5764]: info: MRS: Pushing multiroomSync output update for this device Apr 16 17:16:17 rivo-streamer volumio[5764]: info: MRS: Pushing multiroomSync output Apr 16 17:16:17 rivo-streamer volumio[5764]: info: CoreStateMachine::pushState Apr 16 17:16:17 rivo-streamer volumio[5764]: info: CoreCommandRouter::volumioPushState Apr 16 17:16:17 rivo-streamer volumio[5764]: info: MRS: Pushing multiroomSync output update for this device Apr 16 17:16:17 rivo-streamer volumio[5764]: info: MRS: Pushing multiroomSync output Apr 16 17:16:17 rivo-streamer volumio[5764]: info: ------------------------------ 75ms Apr 16 17:16:17 rivo-streamer volumio[5764]: info: Signalling Playback active due to playback status change Apr 16 17:16:17 rivo-streamer kernel: asoc-aml-card auge_sound: S/PDIF Playback enable Apr 16 17:16:17 rivo-streamer volumio[5764]: info: MCU Signalled Playback Active Apr 16 17:16:17 rivo-streamer volumio[5764]: info: Apr 16 17:16:17 rivo-streamer volumio[5764]: ---------------------------- MPD announces system playlist update Apr 16 17:16:17 rivo-streamer volumio[5764]: info: Ignoring MPD Status Update Apr 16 17:16:17 rivo-streamer volumio[5764]: info: Apr 16 17:16:17 rivo-streamer volumio[5764]: ---------------------------- MPD announces state update: player Apr 16 17:16:17 rivo-streamer volumio[5764]: info: ControllerMpd::getState Apr 16 17:16:17 rivo-streamer volumio[5764]: verbose: ControllerMpd::sendMpdCommand status Apr 16 17:16:17 rivo-streamer volumio[5764]: info: ------------------------------ 6ms Apr 16 17:16:17 rivo-streamer volumio[5764]: info: sendMpdCommand status took 4 milliseconds Apr 16 17:16:17 rivo-streamer volumio[5764]: verbose: ControllerMpd::parseState Apr 16 17:16:17 rivo-streamer volumio[5764]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 16 17:16:17 rivo-streamer volumio[5764]: info: sendMpdCommand playlistinfo took 2 milliseconds Apr 16 17:16:17 rivo-streamer volumio[5764]: verbose: ControllerMpd::parseTrackInfo Apr 16 17:16:17 rivo-streamer volumio[5764]: info: ControllerMpd::pushState Apr 16 17:16:17 rivo-streamer volumio[5764]: info: CoreCommandRouter::servicePushState Apr 16 17:16:17 rivo-streamer volumio[5764]: info: CorePlayQueue::getTrack 0 Apr 16 17:16:17 rivo-streamer volumio[5764]: verbose: STATE SERVICE {"status":"play","position":0,"seek":857,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Elton John - Can You Feel the Love Tonight","artist":"Retro80sRadio","album":null,"uri":"http://158.69.227.214:8113/stream","trackType":""} Apr 16 17:16:17 rivo-streamer volumio[5764]: verbose: CURRENT POSITION 0 Apr 16 17:16:17 rivo-streamer volumio[5764]: info: CoreStateMachine::syncState stateService play Apr 16 17:16:17 rivo-streamer volumio[5764]: info: CoreStateMachine::syncState currentStatus play Apr 16 17:16:17 rivo-streamer volumio[5764]: info: Received an update from plugin. extracting info from payload Apr 16 17:16:17 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Apr 16 17:16:17 rivo-streamer volumio[5764]: info: CoreStateMachine::pushState Apr 16 17:16:17 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 16 17:16:17 rivo-streamer volumio[5764]: info: CoreCommandRouter::volumioPushState Apr 16 17:16:17 rivo-streamer volumio[5764]: info: MRS: Pushing multiroomSync output update for this device Apr 16 17:16:17 rivo-streamer volumio[5764]: info: MRS: Pushing multiroomSync output Apr 16 17:16:17 rivo-streamer volumio[5764]: info: CoreStateMachine::pushState Apr 16 17:16:17 rivo-streamer volumio[5764]: info: CoreCommandRouter::volumioPushState Apr 16 17:16:17 rivo-streamer volumio[5764]: info: MRS: Pushing multiroomSync output update for this device Apr 16 17:16:17 rivo-streamer volumio[5764]: info: MRS: Pushing multiroomSync output Apr 16 17:16:17 rivo-streamer volumio[5764]: info: ------------------------------ 57ms Apr 16 17:16:20 rivo-streamer volumio[5764]: info: Preload queue cleared Apr 16 17:16:20 rivo-streamer volumio[5764]: info: CoreCommandRouter::volumioReplaceandPlayItems Apr 16 17:16:20 rivo-streamer volumio[5764]: info: CoreStateMachine::ClearQueue Apr 16 17:16:20 rivo-streamer volumio[5764]: info: CoreStateMachine::stop Apr 16 17:16:20 rivo-streamer volumio[5764]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 16 17:16:20 rivo-streamer volumio[5764]: info: CoreStateMachine::stPlaybackTimer Apr 16 17:16:20 rivo-streamer volumio[5764]: info: CoreStateMachine::updateTrackBlock Apr 16 17:16:20 rivo-streamer volumio[5764]: info: CorePlayQueue::getTrackBlock Apr 16 17:16:20 rivo-streamer volumio[5764]: info: CoreStateMachine::pushState Apr 16 17:16:20 rivo-streamer volumio[5764]: info: CorePlayQueue::getTrack 0 Apr 16 17:16:20 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 16 17:16:20 rivo-streamer volumio[5764]: info: CoreCommandRouter::volumioPushState Apr 16 17:16:20 rivo-streamer volumio[5764]: info: MRS: Pushing multiroomSync output update for this device Apr 16 17:16:20 rivo-streamer volumio[5764]: info: MRS: Pushing multiroomSync output Apr 16 17:16:20 rivo-streamer volumio[5764]: info: CoreStateMachine::serviceStop Apr 16 17:16:20 rivo-streamer volumio[5764]: info: CorePlayQueue::getTrack 0 Apr 16 17:16:20 rivo-streamer volumio[5764]: info: CoreCommandRouter::serviceStop Apr 16 17:16:20 rivo-streamer volumio[5764]: info: [1713280580646] ControllerWebradio::stop Apr 16 17:16:20 rivo-streamer volumio[5764]: verbose: ControllerMpd::sendMpdCommand stop Apr 16 17:16:20 rivo-streamer volumio[5764]: info: CorePlayQueue::clearPlayQueue Apr 16 17:16:20 rivo-streamer volumio[5764]: info: CorePlayQueue::saveQueue Apr 16 17:16:20 rivo-streamer volumio[5764]: info: CoreCommandRouter::volumioPushQueue Apr 16 17:16:20 rivo-streamer volumio[5764]: info: CoreStateMachine::addQueueItems Apr 16 17:16:20 rivo-streamer volumio[5764]: info: CorePlayQueue::addQueueItems Apr 16 17:16:20 rivo-streamer volumio[5764]: info: Preload queue cleared Apr 16 17:16:20 rivo-streamer volumio[5764]: info: Adding Item to queue: qobuz://album/l2u8xuw8wsaob Apr 16 17:16:20 rivo-streamer volumio[5764]: info: Exploding uri qobuz://album/l2u8xuw8wsaob in service qobuz Apr 16 17:16:20 rivo-streamer kernel: asoc-aml-card auge_sound: S/PDIF Playback disable Apr 16 17:16:20 rivo-streamer kernel: spdif_a keep clk continuous Apr 16 17:16:20 rivo-streamer kernel: aml_spdif_close Apr 16 17:16:20 rivo-streamer kernel: audio_ddr_mngr: frddrs[0] released by device ff660000.audiobus:spdif@0 Apr 16 17:16:20 rivo-streamer volumio[5764]: info: Apr 16 17:16:20 rivo-streamer volumio[5764]: ---------------------------- MPD announces state update: player Apr 16 17:16:20 rivo-streamer volumio[5764]: info: sendMpdCommand stop took 43 milliseconds Apr 16 17:16:20 rivo-streamer volumio[5764]: info: ControllerMpd::getState Apr 16 17:16:20 rivo-streamer volumio[5764]: verbose: ControllerMpd::sendMpdCommand status Apr 16 17:16:20 rivo-streamer volumio[5764]: info: sendMpdCommand status took 16 milliseconds Apr 16 17:16:20 rivo-streamer volumio[5764]: verbose: ControllerMpd::parseState Apr 16 17:16:20 rivo-streamer volumio[5764]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 16 17:16:20 rivo-streamer volumio[5764]: info: sendMpdCommand playlistinfo took 3 milliseconds Apr 16 17:16:20 rivo-streamer volumio[5764]: verbose: ControllerMpd::parseTrackInfo Apr 16 17:16:20 rivo-streamer volumio[5764]: info: ControllerMpd::pushState Apr 16 17:16:20 rivo-streamer volumio[5764]: info: CoreCommandRouter::servicePushState Apr 16 17:16:20 rivo-streamer volumio[5764]: info: CoreStateMachine::pushState Apr 16 17:16:20 rivo-streamer volumio[5764]: info: CorePlayQueue::getTrack 0 Apr 16 17:16:20 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 16 17:16:20 rivo-streamer volumio[5764]: info: CoreCommandRouter::volumioPushState Apr 16 17:16:20 rivo-streamer volumio[5764]: info: MRS: Pushing multiroomSync output update for this device Apr 16 17:16:20 rivo-streamer volumio[5764]: info: MRS: Pushing multiroomSync output Apr 16 17:16:20 rivo-streamer volumio[5764]: info: CorePlayQueue::getTrack 0 Apr 16 17:16:20 rivo-streamer volumio[5764]: verbose: STATE SERVICE {"status":"stop","position":0,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Elton John - Can You Feel the Love Tonight","artist":"Retro80sRadio","album":null,"uri":"http://158.69.227.214:8113/stream","trackType":""} Apr 16 17:16:20 rivo-streamer volumio[5764]: verbose: CURRENT POSITION 0 Apr 16 17:16:20 rivo-streamer volumio[5764]: info: CoreStateMachine::syncState stateService stop Apr 16 17:16:20 rivo-streamer volumio[5764]: info: CoreStateMachine::syncState currentStatus stop Apr 16 17:16:20 rivo-streamer volumio[5764]: info: CoreStateMachine::pushState Apr 16 17:16:20 rivo-streamer volumio[5764]: info: CorePlayQueue::getTrack 0 Apr 16 17:16:20 rivo-streamer volumio[5764]: info: CoreCommandRouter::volumioPushState Apr 16 17:16:20 rivo-streamer volumio[5764]: info: MRS: Pushing multiroomSync output update for this device Apr 16 17:16:20 rivo-streamer volumio[5764]: info: MRS: Pushing multiroomSync output Apr 16 17:16:20 rivo-streamer volumio[5764]: info: No code Apr 16 17:16:20 rivo-streamer volumio[5764]: info: CoreStateMachine::pushState Apr 16 17:16:20 rivo-streamer volumio[5764]: info: CorePlayQueue::getTrack 0 Apr 16 17:16:20 rivo-streamer volumio[5764]: info: CoreCommandRouter::volumioPushState Apr 16 17:16:20 rivo-streamer volumio[5764]: info: MRS: Pushing multiroomSync output update for this device Apr 16 17:16:20 rivo-streamer volumio[5764]: info: MRS: Pushing multiroomSync output Apr 16 17:16:20 rivo-streamer volumio[5764]: info: ------------------------------ 84ms Apr 16 17:16:20 rivo-streamer volumio[5764]: info: MCU Signalled Playback Inactive Apr 16 17:16:21 rivo-streamer volumio[5764]: info: explodeUri took 1071 milliseconds Apr 16 17:16:21 rivo-streamer volumio[5764]: info: CoreCommandRouter::volumioPushQueue Apr 16 17:16:21 rivo-streamer volumio[5764]: info: CorePlayQueue::saveQueue Apr 16 17:16:21 rivo-streamer volumio[5764]: info: CoreStateMachine::updateTrackBlock Apr 16 17:16:21 rivo-streamer volumio[5764]: info: CorePlayQueue::getTrackBlock Apr 16 17:16:21 rivo-streamer volumio[5764]: info: CoreCommandRouter::volumioPlay Apr 16 17:16:21 rivo-streamer volumio[5764]: info: CoreStateMachine::play index 0 Apr 16 17:16:21 rivo-streamer volumio[5764]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 16 17:16:21 rivo-streamer volumio[5764]: info: CoreStateMachine::stop Apr 16 17:16:21 rivo-streamer volumio[5764]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 16 17:16:21 rivo-streamer volumio[5764]: info: CoreStateMachine::play index undefined Apr 16 17:16:21 rivo-streamer volumio[5764]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 16 17:16:21 rivo-streamer volumio[5764]: info: CorePlayQueue::getTrack 0 Apr 16 17:16:21 rivo-streamer volumio[5764]: info: CoreStateMachine::startPlaybackTimer Apr 16 17:16:21 rivo-streamer volumio[5764]: info: CorePlayQueue::getTrack 0 Apr 16 17:16:21 rivo-streamer volumio[5764]: info: [1713280581744] ControllerQobuz::clearAddPlayTrack Apr 16 17:16:21 rivo-streamer volumio[5764]: verbose: ControllerMpd::sendMpdCommand stop Apr 16 17:16:21 rivo-streamer volumio[5764]: info: sendMpdCommand stop took 8 milliseconds Apr 16 17:16:21 rivo-streamer volumio[5764]: verbose: ControllerMpd::sendMpdCommand clear Apr 16 17:16:21 rivo-streamer volumio[5764]: info: Apr 16 17:16:21 rivo-streamer volumio[5764]: ---------------------------- MPD announces system playlist update Apr 16 17:16:21 rivo-streamer volumio[5764]: info: Ignoring MPD Status Update Apr 16 17:16:21 rivo-streamer volumio[5764]: info: sendMpdCommand clear took 2 milliseconds Apr 16 17:16:21 rivo-streamer volumio[5764]: verbose: ControllerMpd::sendMpdCommand load "http://127.0.0.1:3245?data=qobuz://song/222612970" Apr 16 17:16:21 rivo-streamer volumio[5764]: error: updateQueue error: null Apr 16 17:16:21 rivo-streamer volumio[5764]: info: ------------------------------ 17ms Apr 16 17:16:21 rivo-streamer volumio[5764]: STREAMING PROXY: Handling url /?data=qobuz://song/222612970 Apr 16 17:16:21 rivo-streamer volumio[5764]: info: Executing endpoint getStreamUrlqobuz Apr 16 17:16:21 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: qobuz , getStreamUrlAPI Apr 16 17:16:22 rivo-streamer volumio[5764]: info: getStreamUrl took 473 milliseconds Apr 16 17:16:22 rivo-streamer volumio[5764]: STREAMING PROXY: Got real url: http://streaming-qobuz-std.akamaized.net:80/file?uid=2320789&eid=222612970&fmt=7&profile=raw&app_id=539451548&cid=2022515&etsp=1713284182&hmac=XdmAknb-ryk9u4dsyTCfayQcUAE Apr 16 17:16:22 rivo-streamer volumio[5764]: STREAMING PROXY: Response: 200, length: 52716982 Apr 16 17:16:22 rivo-streamer volumio[5764]: STREAMING PROXY: Client dropped request, destroying Apr 16 17:16:22 rivo-streamer volumio[5764]: verbose: ControllerMpd::sendMpdCommand add "http://127.0.0.1:3245?data=qobuz://song/222612970" Apr 16 17:16:22 rivo-streamer volumio[5764]: info: Apr 16 17:16:22 rivo-streamer volumio[5764]: ---------------------------- MPD announces system playlist update Apr 16 17:16:22 rivo-streamer volumio[5764]: info: Ignoring MPD Status Update Apr 16 17:16:22 rivo-streamer volumio[5764]: info: sendMpdCommand add "http://127.0.0.1:3245?data=qobuz://song/222612970" took 3 milliseconds Apr 16 17:16:22 rivo-streamer volumio[5764]: info: CoreStateMachine::setConsumeUpdateService mpd Apr 16 17:16:22 rivo-streamer volumio[5764]: verbose: ControllerMpd::sendMpdCommand play Apr 16 17:16:22 rivo-streamer volumio[5764]: info: ------------------------------ 5ms Apr 16 17:16:22 rivo-streamer volumio[5764]: info: sendMpdCommand play took 4 milliseconds Apr 16 17:16:22 rivo-streamer volumio[5764]: STREAMING PROXY: Handling url /?data=qobuz://song/222612970 Apr 16 17:16:22 rivo-streamer volumio[5764]: info: Executing endpoint getStreamUrlqobuz Apr 16 17:16:22 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: qobuz , getStreamUrlAPI Apr 16 17:16:23 rivo-streamer volumio[5764]: info: getStreamUrl took 482 milliseconds Apr 16 17:16:23 rivo-streamer volumio[5764]: STREAMING PROXY: Got real url: http://streaming-qobuz-std.akamaized.net:80/file?uid=2320789&eid=222612970&fmt=7&profile=raw&app_id=539451548&cid=2022515&etsp=1713284183&hmac=TCMvk3xLCCtZ7-JhbVg_DAxmivE Apr 16 17:16:23 rivo-streamer volumio[5764]: STREAMING PROXY: Response: 200, length: 52716982 Apr 16 17:16:23 rivo-streamer volumio[5764]: info: Apr 16 17:16:23 rivo-streamer volumio[5764]: ---------------------------- MPD announces state update: player Apr 16 17:16:23 rivo-streamer kernel: aml_spdif_open Apr 16 17:16:23 rivo-streamer kernel: audio_ddr_mngr: frddrs[0] registered by device ff660000.audiobus:spdif@0 Apr 16 17:16:23 rivo-streamer volumio[5764]: info: ControllerMpd::getState Apr 16 17:16:23 rivo-streamer volumio[5764]: verbose: ControllerMpd::sendMpdCommand status Apr 16 17:16:23 rivo-streamer kernel: set normal 512 fs /4 fs Apr 16 17:16:23 rivo-streamer kernel: set spdifout clk:5644800, mpll:22579200 Apr 16 17:16:23 rivo-streamer kernel: get spdifout clk:5644797, mpll:22579186 Apr 16 17:16:23 rivo-streamer kernel: aml_dai_set_spdif_fmt , fmt 0x4000 Apr 16 17:16:23 rivo-streamer kernel: set normal 512 fs /4 fs Apr 16 17:16:23 rivo-streamer kernel: set spdifout clk:5644800, mpll:22579200 Apr 16 17:16:23 rivo-streamer kernel: get spdifout clk:5644797, mpll:22579186 Apr 16 17:16:23 rivo-streamer kernel: spdif_info: rate: 44100, channel status ch0_l:0x100, ch0_r:0x100, ch1_l:0x0, ch1_r:0x0 Apr 16 17:16:23 rivo-streamer kernel: aml_spdif_fifo_ctrl, bit depth:24, frddr type:4, toddr:type:4 Apr 16 17:16:23 rivo-streamer volumio[5764]: info: Apr 16 17:16:23 rivo-streamer volumio[5764]: ---------------------------- MPD announces state update: player Apr 16 17:16:23 rivo-streamer volumio[5764]: info: sendMpdCommand status took 5 milliseconds Apr 16 17:16:23 rivo-streamer volumio[5764]: info: ControllerMpd::getState Apr 16 17:16:23 rivo-streamer volumio[5764]: verbose: ControllerMpd::sendMpdCommand status Apr 16 17:16:23 rivo-streamer volumio[5764]: verbose: ControllerMpd::parseState Apr 16 17:16:23 rivo-streamer volumio[5764]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 16 17:16:23 rivo-streamer volumio[5764]: info: sendMpdCommand status took 6 milliseconds Apr 16 17:16:23 rivo-streamer volumio[5764]: info: sendMpdCommand playlistinfo took 6 milliseconds Apr 16 17:16:23 rivo-streamer volumio[5764]: verbose: ControllerMpd::parseState Apr 16 17:16:23 rivo-streamer volumio[5764]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 16 17:16:23 rivo-streamer volumio[5764]: verbose: ControllerMpd::parseTrackInfo Apr 16 17:16:23 rivo-streamer volumio[5764]: info: ControllerMpd::pushState Apr 16 17:16:23 rivo-streamer volumio[5764]: info: CoreCommandRouter::servicePushState Apr 16 17:16:23 rivo-streamer volumio[5764]: info: CorePlayQueue::getTrack 0 Apr 16 17:16:23 rivo-streamer volumio[5764]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":238,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"222612970","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/222612970","trackType":"qobuz"} Apr 16 17:16:23 rivo-streamer volumio[5764]: verbose: CURRENT POSITION 0 Apr 16 17:16:23 rivo-streamer volumio[5764]: info: CoreStateMachine::syncState stateService play Apr 16 17:16:23 rivo-streamer volumio[5764]: info: CoreStateMachine::syncState currentStatus stop Apr 16 17:16:23 rivo-streamer volumio[5764]: info: ------------------------------ 22ms Apr 16 17:16:23 rivo-streamer volumio[5764]: info: sendMpdCommand playlistinfo took 5 milliseconds Apr 16 17:16:23 rivo-streamer volumio[5764]: verbose: ControllerMpd::parseTrackInfo Apr 16 17:16:23 rivo-streamer volumio[5764]: info: ControllerMpd::pushState Apr 16 17:16:23 rivo-streamer volumio[5764]: info: CoreCommandRouter::servicePushState Apr 16 17:16:23 rivo-streamer volumio[5764]: info: CorePlayQueue::getTrack 0 Apr 16 17:16:23 rivo-streamer volumio[5764]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":238,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"222612970","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/222612970","trackType":"qobuz"} Apr 16 17:16:23 rivo-streamer volumio[5764]: verbose: CURRENT POSITION 0 Apr 16 17:16:23 rivo-streamer volumio[5764]: info: CoreStateMachine::syncState stateService play Apr 16 17:16:23 rivo-streamer volumio[5764]: info: CoreStateMachine::syncState currentStatus play Apr 16 17:16:23 rivo-streamer volumio[5764]: info: Received an update from plugin. extracting info from payload Apr 16 17:16:23 rivo-streamer volumio[5764]: info: CoreStateMachine::pushState Apr 16 17:16:23 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 16 17:16:23 rivo-streamer volumio[5764]: info: CoreCommandRouter::volumioPushState Apr 16 17:16:23 rivo-streamer volumio[5764]: info: MRS: Pushing multiroomSync output update for this device Apr 16 17:16:23 rivo-streamer volumio[5764]: info: MRS: Pushing multiroomSync output Apr 16 17:16:23 rivo-streamer volumio[5764]: info: CoreStateMachine::pushState Apr 16 17:16:23 rivo-streamer volumio[5764]: info: CoreCommandRouter::volumioPushState Apr 16 17:16:23 rivo-streamer volumio[5764]: info: MRS: Pushing multiroomSync output update for this device Apr 16 17:16:23 rivo-streamer volumio[5764]: info: MRS: Pushing multiroomSync output Apr 16 17:16:23 rivo-streamer volumio[5764]: info: ------------------------------ 66ms Apr 16 17:16:23 rivo-streamer volumio[5764]: info: Signalling Playback active due to playback status change Apr 16 17:16:23 rivo-streamer volumio[5764]: info: MCU Signalled Playback Active Apr 16 17:16:23 rivo-streamer kernel: asoc-aml-card auge_sound: S/PDIF Playback enable Apr 16 17:16:40 rivo-streamer volumio[5764]: STREAMING PROXY: Client dropped request, destroying Apr 16 17:16:40 rivo-streamer volumio[5764]: info: CoreCommandRouter::executeOnPlugin: multiroom , disableAudioOutput Apr 16 17:16:40 rivo-streamer volumio[5764]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 16 17:16:40 rivo-streamer volumio[5764]: TypeError: Cannot read property 'then' of undefined Apr 16 17:16:40 rivo-streamer volumio[5764]: at outputs.disableAudioOutput (/volumio/app/plugins/audio_interface/outputs/index.js:273:9) Apr 16 17:16:40 rivo-streamer volumio[5764]: at CoreCommandRouter.disableAudioOutput (/volumio/app/index.js:2227:30) Apr 16 17:16:40 rivo-streamer volumio[5764]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:1399:26) Apr 16 17:16:40 rivo-streamer volumio[5764]: at Socket.emit (events.js:400:28) Apr 16 17:16:40 rivo-streamer volumio[5764]: at /volumio/node_modules/socket.io/lib/socket.js:503:12 Apr 16 17:16:40 rivo-streamer volumio[5764]: at processTicksAndRejections (internal/process/task_queues.js:77:11) Apr 16 17:16:40 rivo-streamer volumio[5764]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 16 17:16:41 rivo-streamer sudo[6992]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-04-16 17:15 Apr 16 17:16:41 rivo-streamer sudo[6992]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Debian GNU/Linux 10 (buster)" NAME="Debian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="7f9f1bf001add7a8b19a4516e3c74ef598b2730d" VOLUMIO_FE_VERSION="614d7b13ffdcb0cc5a6072e7d06f59d52e323e71" VOLUMIO_FE3_VERSION="570aaed971c1346d45d1172dc445b086b258c6d1" VOLUMIO_BE_VERSION="e831866afe2db61aee9333a8f5ba9d9fd36609c7" VOLUMIO_ARCH="armv7" VOLUMIO_VARIANT="rivo" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Sun 18 Feb 2024 11:41:55 AM CET" VOLUMIO_VERSION="3.629" VOLUMIO_HARDWARE="mp1" VOLUMIO_DEVICENAME="Volumio MP1" VOLUMIO_VENDOR_MODEL="Volumio Rivo" VOLUMIO_VENDOR="Volumio" VOLUMIO_MODEL="Rivo" VOLUMIO_HASH="b0437c7088d6645a661a49f6d9fa596a"