-- Logs begin at Sun 2024-03-31 22:26:19 CEST, end at Sun 2024-03-31 23:01:45 CEST. -- Mar 31 23:00:25 rivo volumio[5444]: verbose: New Socket.io Connection to 192.168.0.253 from 192.168.0.19 UA: unknown Total Clients: 8 Mar 31 23:00:25 rivo volumio[5444]: info: CoreCommandRouter::volumioGetState Mar 31 23:00:25 rivo volumio[5444]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Mar 31 23:00:25 rivo volumio[5444]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Mar 31 23:00:27 rivo volumio[5444]: verbose: New Socket.io Connection to 192.168.0.253 from 192.168.0.19 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 17_3_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Total Clients: 9 Mar 31 23:00:27 rivo volumio[5444]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Mar 31 23:00:27 rivo volumio[5444]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Mar 31 23:00:27 rivo volumio[5444]: info: CoreCommandRouter::volumioGetVisibleSources Mar 31 23:00:27 rivo volumio[5444]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 31 23:00:27 rivo volumio[5444]: info: CoreCommandRouter::volumioGetState Mar 31 23:00:27 rivo volumio[5444]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Mar 31 23:00:27 rivo volumio[5444]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Mar 31 23:00:27 rivo volumio[5444]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Mar 31 23:00:27 rivo volumio[5444]: info: Received Get System Info Mar 31 23:00:27 rivo volumio[5444]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 31 23:00:27 rivo volumio[5444]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 31 23:00:27 rivo volumio[5444]: info: Discovery: Getting this device information Mar 31 23:00:27 rivo volumio[5444]: info: CoreCommandRouter::volumioGetState Mar 31 23:00:27 rivo volumio[5444]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 31 23:00:27 rivo volumio[5444]: info: CoreCommandRouter::volumioGetState Mar 31 23:00:27 rivo volumio[5444]: info: Listing playlists Mar 31 23:00:27 rivo volumio[5444]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Mar 31 23:00:31 rivo volumio[5444]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 31 23:00:31 rivo volumio[5444]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 31 23:00:31 rivo volumio[5444]: info: Discovery: Getting this device information Mar 31 23:00:31 rivo volumio[5444]: info: CoreCommandRouter::volumioGetState Mar 31 23:00:31 rivo volumio[5444]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 31 23:01:01 rivo volumio[5444]: info: CorePlayQueue::getTrack 6 Mar 31 23:01:01 rivo volumio[5444]: info: CorePlayQueue::getTrack 7 Mar 31 23:01:01 rivo volumio[5444]: info: Prefetching next song Mar 31 23:01:01 rivo volumio[5444]: info: [1711918861973] ControllerQobuz::prefetch Mar 31 23:01:01 rivo volumio[5444]: verbose: ControllerMpd::sendMpdCommand load "http://127.0.0.1:3245?data=qobuz://song/971818" Mar 31 23:01:01 rivo volumio[5444]: STREAMING PROXY: Handling url /?data=qobuz://song/971818 Mar 31 23:01:01 rivo volumio[5444]: info: Executing endpoint getStreamUrlqobuz Mar 31 23:01:01 rivo volumio[5444]: info: CoreCommandRouter::executeOnPlugin: qobuz , getStreamUrlAPI Mar 31 23:01:02 rivo volumio[5444]: info: getStreamUrl took 321 milliseconds Mar 31 23:01:02 rivo volumio[5444]: STREAMING PROXY: Got real url: http://streaming-qobuz-std.akamaized.net:80/file?uid=2801117&eid=971818&fmt=6&profile=raw&app_id=539451548&cid=1966015&etsp=1711922462&hmac=pWfaqeS4uUZBpjeTUTa4qMQ6ReE Mar 31 23:01:02 rivo volumio[5444]: STREAMING PROXY: Response: 200, length: 26073921 Mar 31 23:01:02 rivo volumio[5444]: STREAMING PROXY: Client dropped request, destroying Mar 31 23:01:02 rivo volumio[5444]: verbose: ControllerMpd::sendMpdCommand add "http://127.0.0.1:3245?data=qobuz://song/971818" Mar 31 23:01:02 rivo volumio[5444]: info: sendMpdCommand add "http://127.0.0.1:3245?data=qobuz://song/971818" took 3 milliseconds Mar 31 23:01:02 rivo volumio[5444]: STREAMING PROXY: Handling url /?data=qobuz://song/971818 Mar 31 23:01:02 rivo volumio[5444]: info: CoreStateMachine::setConsumeUpdateService mpd Mar 31 23:01:02 rivo volumio[5444]: verbose: ControllerMpd::sendMpdCommand consume 1 Mar 31 23:01:02 rivo volumio[5444]: info: Mar 31 23:01:02 rivo volumio[5444]: ---------------------------- MPD announces system playlist update Mar 31 23:01:02 rivo volumio[5444]: info: Ignoring MPD Status Update Mar 31 23:01:02 rivo volumio[5444]: info: sendMpdCommand consume 1 took 3 milliseconds Mar 31 23:01:02 rivo volumio[5444]: info: Mar 31 23:01:02 rivo volumio[5444]: ---------------------------- MPD announces system playlist update Mar 31 23:01:02 rivo volumio[5444]: info: Ignoring MPD Status Update Mar 31 23:01:02 rivo volumio[5444]: info: Mar 31 23:01:02 rivo volumio[5444]: ---------------------------- MPD announces system playlist update Mar 31 23:01:02 rivo volumio[5444]: info: Ignoring MPD Status Update Mar 31 23:01:02 rivo volumio[5444]: info: ------------------------------ 16ms Mar 31 23:01:02 rivo volumio[5444]: info: ------------------------------ 13ms Mar 31 23:01:02 rivo volumio[5444]: info: ------------------------------ 13ms Mar 31 23:01:02 rivo volumio[5444]: info: Executing endpoint getStreamUrlqobuz Mar 31 23:01:02 rivo volumio[5444]: info: CoreCommandRouter::executeOnPlugin: qobuz , getStreamUrlAPI Mar 31 23:01:03 rivo volumio[5444]: info: getStreamUrl took 525 milliseconds Mar 31 23:01:03 rivo volumio[5444]: STREAMING PROXY: Got real url: http://streaming-qobuz-std.akamaized.net:80/file?uid=2801117&eid=971818&fmt=6&profile=raw&app_id=539451548&cid=1966015&etsp=1711922463&hmac=j1Oqe7Y6fKvRmvLo8SDBw9Y9B0c Mar 31 23:01:03 rivo volumio[5444]: STREAMING PROXY: Response: 200, length: 26073921 Mar 31 23:01:05 rivo volumio[5444]: STREAMING PROXY: Client dropped request, destroying Mar 31 23:01:06 rivo volumio[5444]: info: CoreStateMachine::startPlaybackTimer Mar 31 23:01:06 rivo volumio[5444]: info: CorePlayQueue::getTrack 7 Mar 31 23:01:07 rivo volumio[5444]: info: CoreStateMachine::pushState Mar 31 23:01:07 rivo volumio[5444]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 31 23:01:07 rivo volumio[5444]: info: CoreCommandRouter::volumioPushState Mar 31 23:01:07 rivo volumio[5444]: info: MRS: Pushing multiroomSync output update for this device Mar 31 23:01:07 rivo volumio[5444]: info: MRS: Pushing multiroomSync output Mar 31 23:01:07 rivo volumio[5444]: info: Signalling Playback active due to playback status change Mar 31 23:01:07 rivo volumio[5444]: info: Updating RAAT Signal Path Mar 31 23:01:10 rivo volumio[5444]: info: Mar 31 23:01:10 rivo volumio[5444]: ---------------------------- MPD announces system playlist update Mar 31 23:01:10 rivo volumio[5444]: info: Ignoring MPD Status Update Mar 31 23:01:11 rivo volumio[5444]: info: Mar 31 23:01:11 rivo volumio[5444]: ---------------------------- MPD announces state update: player Mar 31 23:01:11 rivo volumio[5444]: info: ControllerMpd::getState Mar 31 23:01:11 rivo volumio[5444]: verbose: ControllerMpd::sendMpdCommand status Mar 31 23:01:11 rivo volumio[5444]: info: Mar 31 23:01:11 rivo volumio[5444]: ---------------------------- MPD announces system playlist update Mar 31 23:01:11 rivo volumio[5444]: info: Ignoring MPD Status Update Mar 31 23:01:11 rivo volumio[5444]: info: Mar 31 23:01:11 rivo volumio[5444]: ---------------------------- MPD announces state update: player Mar 31 23:01:11 rivo volumio[5444]: info: ControllerMpd::getState Mar 31 23:01:11 rivo volumio[5444]: verbose: ControllerMpd::sendMpdCommand status Mar 31 23:01:11 rivo volumio[5444]: info: Mar 31 23:01:11 rivo volumio[5444]: ---------------------------- MPD announces system playlist update Mar 31 23:01:11 rivo volumio[5444]: info: Ignoring MPD Status Update Mar 31 23:01:11 rivo volumio[5444]: info: Mar 31 23:01:11 rivo volumio[5444]: ---------------------------- MPD announces state update: player Mar 31 23:01:11 rivo volumio[5444]: info: ControllerMpd::getState Mar 31 23:01:11 rivo volumio[5444]: verbose: ControllerMpd::sendMpdCommand status Mar 31 23:01:11 rivo volumio[5444]: info: ------------------------------ 14ms Mar 31 23:01:11 rivo volumio[5444]: info: sendMpdCommand status took 13 milliseconds Mar 31 23:01:11 rivo volumio[5444]: info: ------------------------------ 13ms Mar 31 23:01:11 rivo volumio[5444]: info: sendMpdCommand status took 7 milliseconds Mar 31 23:01:11 rivo volumio[5444]: info: ------------------------------ 5ms Mar 31 23:01:11 rivo volumio[5444]: info: sendMpdCommand status took 5 milliseconds Mar 31 23:01:11 rivo volumio[5444]: verbose: ControllerMpd::parseState Mar 31 23:01:11 rivo volumio[5444]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 31 23:01:11 rivo volumio[5444]: verbose: ControllerMpd::parseState Mar 31 23:01:11 rivo volumio[5444]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 31 23:01:11 rivo volumio[5444]: verbose: ControllerMpd::parseState Mar 31 23:01:11 rivo volumio[5444]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 31 23:01:11 rivo volumio[5444]: info: sendMpdCommand playlistinfo took 4 milliseconds Mar 31 23:01:11 rivo volumio[5444]: info: sendMpdCommand playlistinfo took 3 milliseconds Mar 31 23:01:11 rivo volumio[5444]: info: sendMpdCommand playlistinfo took 4 milliseconds Mar 31 23:01:11 rivo volumio[5444]: verbose: ControllerMpd::parseTrackInfo Mar 31 23:01:11 rivo volumio[5444]: verbose: ControllerMpd::parseTrackInfo Mar 31 23:01:11 rivo volumio[5444]: verbose: ControllerMpd::parseTrackInfo Mar 31 23:01:11 rivo volumio[5444]: info: ControllerMpd::pushState Mar 31 23:01:11 rivo volumio[5444]: info: CoreCommandRouter::servicePushState Mar 31 23:01:11 rivo volumio[5444]: info: CorePlayQueue::getTrack 7 Mar 31 23:01:11 rivo volumio[5444]: verbose: STATE SERVICE {"status":"play","position":0,"seek":45,"duration":297,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"538 Kbps","isStreaming":false,"title":"971818","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/971818","trackType":"qobuz"} Mar 31 23:01:11 rivo volumio[5444]: verbose: CURRENT POSITION 7 Mar 31 23:01:11 rivo volumio[5444]: info: CoreStateMachine::syncState stateService play Mar 31 23:01:11 rivo volumio[5444]: info: CoreStateMachine::syncState currentStatus play Mar 31 23:01:11 rivo volumio[5444]: info: Received an update from plugin. extracting info from payload Mar 31 23:01:11 rivo volumio[5444]: info: CoreStateMachine::pushState Mar 31 23:01:11 rivo volumio[5444]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 31 23:01:11 rivo volumio[5444]: info: CoreCommandRouter::volumioPushState Mar 31 23:01:11 rivo volumio[5444]: info: MRS: Pushing multiroomSync output update for this device Mar 31 23:01:11 rivo volumio[5444]: info: MRS: Pushing multiroomSync output Mar 31 23:01:11 rivo volumio[5444]: info: CoreStateMachine::pushState Mar 31 23:01:11 rivo volumio[5444]: info: CoreCommandRouter::volumioPushState Mar 31 23:01:11 rivo volumio[5444]: info: MRS: Pushing multiroomSync output update for this device Mar 31 23:01:11 rivo volumio[5444]: info: MRS: Pushing multiroomSync output Mar 31 23:01:11 rivo volumio[5444]: info: ControllerMpd::pushState Mar 31 23:01:11 rivo volumio[5444]: info: CoreCommandRouter::servicePushState Mar 31 23:01:11 rivo volumio[5444]: info: CorePlayQueue::getTrack 7 Mar 31 23:01:11 rivo volumio[5444]: verbose: STATE SERVICE {"status":"play","position":0,"seek":45,"duration":297,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"538 Kbps","isStreaming":false,"title":"971818","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/971818","trackType":"qobuz"} Mar 31 23:01:11 rivo volumio[5444]: verbose: CURRENT POSITION 7 Mar 31 23:01:11 rivo volumio[5444]: info: CoreStateMachine::syncState stateService play Mar 31 23:01:11 rivo volumio[5444]: info: CoreStateMachine::syncState currentStatus play Mar 31 23:01:11 rivo volumio[5444]: info: Received an update from plugin. extracting info from payload Mar 31 23:01:11 rivo volumio[5444]: info: CoreStateMachine::pushState Mar 31 23:01:11 rivo volumio[5444]: info: CoreCommandRouter::volumioPushState Mar 31 23:01:11 rivo volumio[5444]: info: MRS: Pushing multiroomSync output update for this device Mar 31 23:01:11 rivo volumio[5444]: info: MRS: Pushing multiroomSync output Mar 31 23:01:11 rivo volumio[5444]: info: CoreStateMachine::pushState Mar 31 23:01:11 rivo volumio[5444]: info: CoreCommandRouter::volumioPushState Mar 31 23:01:11 rivo volumio[5444]: info: MRS: Pushing multiroomSync output update for this device Mar 31 23:01:11 rivo volumio[5444]: info: MRS: Pushing multiroomSync output Mar 31 23:01:11 rivo volumio[5444]: info: ControllerMpd::pushState Mar 31 23:01:11 rivo volumio[5444]: info: CoreCommandRouter::servicePushState Mar 31 23:01:11 rivo volumio[5444]: info: CorePlayQueue::getTrack 7 Mar 31 23:01:11 rivo volumio[5444]: verbose: STATE SERVICE {"status":"play","position":0,"seek":45,"duration":297,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"538 Kbps","isStreaming":false,"title":"971818","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/971818","trackType":"qobuz"} Mar 31 23:01:11 rivo volumio[5444]: verbose: CURRENT POSITION 7 Mar 31 23:01:11 rivo volumio[5444]: info: CoreStateMachine::syncState stateService play Mar 31 23:01:11 rivo volumio[5444]: info: CoreStateMachine::syncState currentStatus play Mar 31 23:01:11 rivo volumio[5444]: info: Received an update from plugin. extracting info from payload Mar 31 23:01:11 rivo volumio[5444]: info: CoreStateMachine::pushState Mar 31 23:01:11 rivo volumio[5444]: info: CoreCommandRouter::volumioPushState Mar 31 23:01:11 rivo volumio[5444]: info: MRS: Pushing multiroomSync output update for this device Mar 31 23:01:11 rivo volumio[5444]: info: MRS: Pushing multiroomSync output Mar 31 23:01:11 rivo volumio[5444]: info: CoreStateMachine::pushState Mar 31 23:01:11 rivo volumio[5444]: info: CoreCommandRouter::volumioPushState Mar 31 23:01:11 rivo volumio[5444]: info: MRS: Pushing multiroomSync output update for this device Mar 31 23:01:11 rivo volumio[5444]: info: MRS: Pushing multiroomSync output Mar 31 23:01:11 rivo volumio[5444]: info: ------------------------------ 66ms Mar 31 23:01:11 rivo volumio[5444]: info: ------------------------------ 60ms Mar 31 23:01:11 rivo volumio[5444]: info: ------------------------------ 58ms Mar 31 23:01:11 rivo volumio[5444]: info: Signalling Playback active due to playback status change Mar 31 23:01:11 rivo volumio[5444]: info: Updating RAAT Signal Path Mar 31 23:01:11 rivo volumio[5444]: info: Signalling Playback active due to playback status change Mar 31 23:01:11 rivo volumio[5444]: info: Signalling Playback active due to playback status change Mar 31 23:01:11 rivo volumio[5444]: info: Signalling Playback active due to playback status change Mar 31 23:01:11 rivo volumio[5444]: info: Signalling Playback active due to playback status change Mar 31 23:01:11 rivo volumio[5444]: info: Signalling Playback active due to playback status change Mar 31 23:01:11 rivo volumio[5444]: info: Updating RAAT Signal Path Mar 31 23:01:11 rivo volumio[5444]: info: Updating RAAT Signal Path Mar 31 23:01:11 rivo volumio[5444]: info: Updating RAAT Signal Path Mar 31 23:01:11 rivo volumio[5444]: info: Updating RAAT Signal Path Mar 31 23:01:11 rivo volumio[5444]: info: Updating RAAT Signal Path Mar 31 23:01:44 rivo volumio[5444]: info: CoreCommandRouter::executeOnPlugin: qobuz , explodeUri Mar 31 23:01:45 rivo volumio[5444]: info: explodeUri took 283 milliseconds Mar 31 23:01:45 rivo volumio[5444]: info: Saving Cloud item Scarlatti A. Magnificat Dixit Dominus Mar 31 23:01:45 rivo volumio[5444]: info: CoreCommandRouter::executeOnPlugin: my_volumio , saveCloudItem Mar 31 23:01:45 rivo volumio[5444]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 31 23:01:45 rivo volumio[5444]: Error: Reference.child failed: First argument was an invalid path = "/user_data/HChUTMmKbaa2hksy3Jz8ffWfeeU2/myPlaylists/Scarlatti A. Magnificat Dixit Dominus". Paths must be non-empty strings and can't contain ".", "#", "$", "[", or "]" Mar 31 23:01:45 rivo volumio[5444]: at validatePathString (/volumio/node_modules/@firebase/database/dist/index.node.cjs.js:1667:15) Mar 31 23:01:45 rivo volumio[5444]: at validateRootPathString (/volumio/node_modules/@firebase/database/dist/index.node.cjs.js:1679:5) Mar 31 23:01:45 rivo volumio[5444]: at Reference.child (/volumio/node_modules/@firebase/database/dist/index.node.cjs.js:13737:17) Mar 31 23:01:45 rivo volumio[5444]: at Database.ref (/volumio/node_modules/@firebase/database/dist/index.node.cjs.js:15115:48) Mar 31 23:01:45 rivo volumio[5444]: at myVolumio.syncJSONToCloud (/myvolumio/plugins/system_controller/my_volumio/my_volumio_real:1:28817) Mar 31 23:01:45 rivo volumio[5444]: at myVolumio.saveCloudMyPlaylist (/myvolumio/plugins/system_controller/my_volumio/my_volumio_real:1:23840) Mar 31 23:01:45 rivo volumio[5444]: at myVolumio.saveCloudItem (/myvolumio/plugins/system_controller/my_volumio/my_volumio_real:1:18337) Mar 31 23:01:45 rivo volumio[5444]: at CoreCommandRouter.executeOnPlugin (/volumio/app/index.js:1077:32) Mar 31 23:01:45 rivo volumio[5444]: at PlaylistManager.saveJSONFile (/volumio/app/playlistManager.js:613:31) Mar 31 23:01:45 rivo volumio[5444]: at /volumio/app/playlistManager.js:588:20 Mar 31 23:01:45 rivo volumio[5444]: at /volumio/node_modules/jsonfile/index.js:46:5 Mar 31 23:01:45 rivo volumio[5444]: at /volumio/node_modules/graceful-fs/graceful-fs.js:123:16 Mar 31 23:01:45 rivo volumio[5444]: at FSReqCallback.readFileAfterClose [as oncomplete] (internal/fs/read_file_context.js:71:3) Mar 31 23:01:45 rivo volumio[5444]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 31 23:01:45 rivo sudo[12710]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-03-31 23:00 Mar 31 23:01:45 rivo sudo[12710]: 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"