-- Logs begin at Thu 2019-02-14 19:11:59 KST, end at Thu 2025-09-11 12:24:43 KST. -- Sep 11 12:23:38 hswhdx volumio[782]: Searching plugin music_service/tidal Sep 11 12:23:38 hswhdx volumio[782]: info: CoreCommandRouter::executeOnPlugin: tidal , search Sep 11 12:23:39 hswhdx volumio[782]: info: searchTIDALUri took 873 milliseconds Sep 11 12:23:39 hswhdx volumio[782]: info: search took 874 milliseconds Sep 11 12:23:39 hswhdx volumio[782]: info: All search sources collected, pushing search results Sep 11 12:23:51 hswhdx volumio[782]: info: CoreCommandRouter::executeOnPlugin: tidal , handleBrowseUri Sep 11 12:23:52 hswhdx volumio[782]: info: browseTIDALUri took 623 milliseconds Sep 11 12:23:52 hswhdx volumio[782]: info: Preload queue cleared Sep 11 12:23:52 hswhdx volumio[782]: info: Preloading song: tidal://song/4096983 Sep 11 12:23:52 hswhdx volumio[782]: info: Preloading song: tidal://song/4096984 Sep 11 12:23:52 hswhdx volumio[782]: info: Preloading song: tidal://song/4096985 Sep 11 12:23:52 hswhdx volumio[782]: info: Exploding uri tidal://song/4096983 in service tidal Sep 11 12:23:52 hswhdx volumio[782]: info: Exploding uri tidal://song/4096984 in service tidal Sep 11 12:23:52 hswhdx volumio[782]: info: Exploding uri tidal://song/4096985 in service tidal Sep 11 12:23:53 hswhdx volumio[782]: info: explodeTIDALUri took 570 milliseconds Sep 11 12:23:53 hswhdx volumio[782]: info: explodeTIDALUri took 620 milliseconds Sep 11 12:23:53 hswhdx volumio[782]: info: explodeTIDALUri took 632 milliseconds Sep 11 12:24:00 hswhdx volumio[782]: info: Listing playlists Sep 11 12:24:30 hswhdx volumio[782]: info: CoreCommandRouter::executeOnPlugin: tidal , handleBrowseUri Sep 11 12:24:31 hswhdx volumio[782]: info: browseTIDALUri took 646 milliseconds Sep 11 12:24:31 hswhdx volumio[782]: info: Preload queue cleared Sep 11 12:24:31 hswhdx volumio[782]: info: Preloading song: tidal://song/4103480 Sep 11 12:24:31 hswhdx volumio[782]: info: Preloading song: tidal://song/4103481 Sep 11 12:24:31 hswhdx volumio[782]: info: Preloading song: tidal://song/4103482 Sep 11 12:24:31 hswhdx volumio[782]: info: Exploding uri tidal://song/4103480 in service tidal Sep 11 12:24:31 hswhdx volumio[782]: info: Exploding uri tidal://song/4103481 in service tidal Sep 11 12:24:31 hswhdx volumio[782]: info: Exploding uri tidal://song/4103482 in service tidal Sep 11 12:24:32 hswhdx volumio[782]: info: explodeTIDALUri took 589 milliseconds Sep 11 12:24:32 hswhdx volumio[782]: info: explodeTIDALUri took 566 milliseconds Sep 11 12:24:32 hswhdx volumio[782]: info: explodeTIDALUri took 652 milliseconds Sep 11 12:24:33 hswhdx volumio[782]: info: Preload queue cleared Sep 11 12:24:33 hswhdx volumio[782]: info: CoreCommandRouter::volumioReplaceandPlayItems Sep 11 12:24:33 hswhdx volumio[782]: info: CoreStateMachine::ClearQueue Sep 11 12:24:33 hswhdx volumio[782]: info: CoreStateMachine::stop Sep 11 12:24:33 hswhdx volumio[782]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 11 12:24:33 hswhdx volumio[782]: info: CoreStateMachine::stPlaybackTimer Sep 11 12:24:33 hswhdx volumio[782]: info: CoreStateMachine::updateTrackBlock Sep 11 12:24:33 hswhdx volumio[782]: info: CorePlayQueue::getTrackBlock Sep 11 12:24:33 hswhdx volumio[782]: info: CoreStateMachine::pushState Sep 11 12:24:33 hswhdx volumio[782]: info: CorePlayQueue::getTrack 0 Sep 11 12:24:33 hswhdx volumio[782]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 11 12:24:33 hswhdx volumio[782]: info: CoreCommandRouter::volumioPushState Sep 11 12:24:33 hswhdx volumio[782]: info: CoreCommandRouter::volumioGetState Sep 11 12:24:33 hswhdx volumio[782]: info: CorePlayQueue::getTrack 0 Sep 11 12:24:33 hswhdx volumio[782]: info: CoreStateMachine::serviceStop Sep 11 12:24:33 hswhdx volumio[782]: info: CorePlayQueue::getTrack 0 Sep 11 12:24:33 hswhdx volumio[782]: info: CoreCommandRouter::serviceStop Sep 11 12:24:33 hswhdx volumio[782]: info: [1757561073555] ControllerWebradio::stop Sep 11 12:24:33 hswhdx volumio[782]: verbose: ControllerMpd::sendMpdCommand stop Sep 11 12:24:33 hswhdx volumio[782]: info: CorePlayQueue::clearPlayQueue Sep 11 12:24:33 hswhdx volumio[782]: info: CorePlayQueue::saveQueue Sep 11 12:24:33 hswhdx volumio[782]: info: CoreCommandRouter::volumioPushQueue Sep 11 12:24:33 hswhdx volumio[782]: info: CoreStateMachine::addQueueItems Sep 11 12:24:33 hswhdx volumio[782]: info: CorePlayQueue::addQueueItems Sep 11 12:24:33 hswhdx volumio[782]: info: Preload queue cleared Sep 11 12:24:33 hswhdx volumio[782]: info: Adding Item to queue: tidal://song/4103480 Sep 11 12:24:33 hswhdx volumio[782]: info: Using cached record of: tidal://song/4103480 Sep 11 12:24:33 hswhdx volumio[782]: info: CoreCommandRouter::volumioPushQueue Sep 11 12:24:33 hswhdx volumio[782]: info: CorePlayQueue::saveQueue Sep 11 12:24:33 hswhdx volumio[782]: info: CoreStateMachine::updateTrackBlock Sep 11 12:24:33 hswhdx volumio[782]: info: CorePlayQueue::getTrackBlock Sep 11 12:24:33 hswhdx volumio[782]: info: CoreCommandRouter::volumioPlay Sep 11 12:24:33 hswhdx volumio[782]: info: CoreStateMachine::play index 0 Sep 11 12:24:33 hswhdx volumio[782]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 11 12:24:33 hswhdx volumio[782]: info: CoreStateMachine::addQueueItems Sep 11 12:24:33 hswhdx volumio[782]: info: CorePlayQueue::addQueueItems Sep 11 12:24:33 hswhdx volumio[782]: info: Preload queue cleared Sep 11 12:24:33 hswhdx volumio[782]: info: Adding Item to queue: tidal://song/4103481 Sep 11 12:24:33 hswhdx volumio[782]: info: Using cached record of: tidal://song/4103481 Sep 11 12:24:33 hswhdx volumio[782]: info: Adding Item to queue: tidal://song/4103482 Sep 11 12:24:33 hswhdx volumio[782]: info: Using cached record of: tidal://song/4103482 Sep 11 12:24:33 hswhdx volumio[782]: info: CoreStateMachine::stop Sep 11 12:24:33 hswhdx volumio[782]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 11 12:24:33 hswhdx volumio[782]: info: CoreCommandRouter::volumioPushQueue Sep 11 12:24:33 hswhdx volumio[782]: info: CorePlayQueue::saveQueue Sep 11 12:24:33 hswhdx volumio[782]: info: CoreStateMachine::play index undefined Sep 11 12:24:33 hswhdx volumio[782]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 11 12:24:33 hswhdx volumio[782]: info: CoreStateMachine::updateTrackBlock Sep 11 12:24:33 hswhdx volumio[782]: info: CorePlayQueue::getTrackBlock Sep 11 12:24:33 hswhdx volumio[782]: info: CorePlayQueue::getTrack 0 Sep 11 12:24:33 hswhdx volumio[782]: info: CoreStateMachine::startPlaybackTimer Sep 11 12:24:33 hswhdx volumio[782]: info: CorePlayQueue::getTrack 0 Sep 11 12:24:33 hswhdx volumio[782]: info: [1757561073592] ControllerTidal::clearAddPlayTrack Sep 11 12:24:33 hswhdx volumio[782]: info: Getting stream with soundQuality HIGH Sep 11 12:24:33 hswhdx volumio[782]: verbose: ControllerMpd::sendMpdCommand stop Sep 11 12:24:33 hswhdx volumio[782]: info: Sep 11 12:24:33 hswhdx volumio[782]: ---------------------------- MPD announces state update: player Sep 11 12:24:33 hswhdx volumio[782]: info: sendMpdCommand stop took 56 milliseconds Sep 11 12:24:33 hswhdx volumio[782]: info: ControllerMpd::getState Sep 11 12:24:33 hswhdx volumio[782]: verbose: ControllerMpd::sendMpdCommand status Sep 11 12:24:33 hswhdx volumio[782]: info: sendMpdCommand stop took 17 milliseconds Sep 11 12:24:33 hswhdx volumio[782]: verbose: ControllerMpd::sendMpdCommand clear Sep 11 12:24:33 hswhdx volumio[782]: info: Sep 11 12:24:33 hswhdx volumio[782]: ---------------------------- MPD announces system playlist update Sep 11 12:24:33 hswhdx volumio[782]: info: Ignoring MPD Status Update Sep 11 12:24:33 hswhdx volumio[782]: info: sendMpdCommand status took 3 milliseconds Sep 11 12:24:33 hswhdx volumio[782]: info: sendMpdCommand clear took 3 milliseconds Sep 11 12:24:33 hswhdx volumio[782]: verbose: ControllerMpd::parseState Sep 11 12:24:33 hswhdx volumio[782]: verbose: ControllerMpd::sendMpdCommand playlistinfo Sep 11 12:24:33 hswhdx volumio[782]: verbose: ControllerMpd::sendMpdCommand add "http://127.0.0.1:3245?data=tidal://song/4103480&soundQuality=HIGH" Sep 11 12:24:33 hswhdx volumio[782]: error: updateQueue error: null Sep 11 12:24:33 hswhdx volumio[782]: info: Sep 11 12:24:33 hswhdx volumio[782]: ---------------------------- MPD announces system playlist update Sep 11 12:24:33 hswhdx volumio[782]: info: Ignoring MPD Status Update Sep 11 12:24:33 hswhdx volumio[782]: info: ------------------------------ 6ms Sep 11 12:24:33 hswhdx volumio[782]: info: sendMpdCommand playlistinfo took 3 milliseconds Sep 11 12:24:33 hswhdx volumio[782]: info: sendMpdCommand add "http://127.0.0.1:3245?data=tidal://song/4103480&soundQuality=HIGH" took 4 milliseconds Sep 11 12:24:33 hswhdx volumio[782]: verbose: ControllerMpd::parseTrackInfo Sep 11 12:24:33 hswhdx volumio[782]: info: CoreStateMachine::setConsumeUpdateService mpd Sep 11 12:24:33 hswhdx volumio[782]: verbose: ControllerMpd::sendMpdCommand play Sep 11 12:24:33 hswhdx volumio[782]: error: ControllerMpd::pushError: TypeError: Cannot read property 'split' of undefined Sep 11 12:24:33 hswhdx volumio[782]: info: ------------------------------ 13ms Sep 11 12:24:33 hswhdx volumio[782]: info: ------------------------------ 12ms Sep 11 12:24:33 hswhdx volumio[782]: info: sendMpdCommand play took 9 milliseconds Sep 11 12:24:33 hswhdx volumio[782]: STREAMING PROXY: Handling url /?data=tidal://song/4103480&soundQuality=HIGH Sep 11 12:24:33 hswhdx volumio[782]: info: Executing endpoint getStreamUrltidal Sep 11 12:24:33 hswhdx volumio[782]: info: CoreCommandRouter::executeOnPlugin: tidal , getStreamUrlAPI Sep 11 12:24:34 hswhdx volumio[782]: info: getStreamUrl took 634 milliseconds Sep 11 12:24:34 hswhdx volumio[782]: STREAMING PROXY: Got real url: http://amz-pr-fa.audio.tidal.com/0843014/3b7f433ac675f54ce359f20e0448b50a_36.m4a?token=1757564674~ODU1NWJkN2FmNTk3YzVlOTZmODk2MzRkNDJhNmI1N2MyNjdiNWVjZA== Sep 11 12:24:35 hswhdx volumio[782]: STREAMING PROXY: Response: 200, length: 5780462 Sep 11 12:24:35 hswhdx volumio[782]: info: Sep 11 12:24:35 hswhdx volumio[782]: ---------------------------- MPD announces state update: player Sep 11 12:24:35 hswhdx volumio[782]: info: ControllerMpd::getState Sep 11 12:24:35 hswhdx volumio[782]: verbose: ControllerMpd::sendMpdCommand status Sep 11 12:24:35 hswhdx volumio[782]: info: Sep 11 12:24:35 hswhdx volumio[782]: ---------------------------- MPD announces state update: player Sep 11 12:24:35 hswhdx volumio[782]: info: ControllerMpd::getState Sep 11 12:24:35 hswhdx volumio[782]: verbose: ControllerMpd::sendMpdCommand status Sep 11 12:24:35 hswhdx volumio[782]: info: sendMpdCommand status took 4 milliseconds Sep 11 12:24:35 hswhdx volumio[782]: verbose: ControllerMpd::parseState Sep 11 12:24:35 hswhdx volumio[782]: verbose: ControllerMpd::sendMpdCommand playlistinfo Sep 11 12:24:35 hswhdx volumio[782]: info: sendMpdCommand status took 4 milliseconds Sep 11 12:24:35 hswhdx volumio[782]: info: sendMpdCommand playlistinfo took 2 milliseconds Sep 11 12:24:35 hswhdx volumio[782]: verbose: ControllerMpd::parseState Sep 11 12:24:35 hswhdx volumio[782]: verbose: ControllerMpd::sendMpdCommand playlistinfo Sep 11 12:24:35 hswhdx volumio[782]: verbose: ControllerMpd::parseTrackInfo Sep 11 12:24:35 hswhdx volumio[782]: info: ControllerMpd::pushState Sep 11 12:24:35 hswhdx volumio[782]: info: CoreCommandRouter::servicePushState Sep 11 12:24:35 hswhdx volumio[782]: info: CorePlayQueue::getTrack 0 Sep 11 12:24:35 hswhdx volumio[782]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":476,"samplerate":44.1,"bitdepth":"32 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"4103480&soundQuality=HIGH","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=tidal://song/4103480&soundQuality=HIGH","trackType":"tidal"} Sep 11 12:24:35 hswhdx volumio[782]: verbose: CURRENT POSITION 0 Sep 11 12:24:35 hswhdx volumio[782]: info: CoreStateMachine::syncState stateService play Sep 11 12:24:35 hswhdx volumio[782]: info: CoreStateMachine::syncState currentStatus stop Sep 11 12:24:35 hswhdx volumio[782]: info: ------------------------------ 17ms Sep 11 12:24:35 hswhdx volumio[782]: info: sendMpdCommand playlistinfo took 6 milliseconds Sep 11 12:24:35 hswhdx volumio[782]: verbose: ControllerMpd::parseTrackInfo Sep 11 12:24:35 hswhdx volumio[782]: info: ControllerMpd::pushState Sep 11 12:24:35 hswhdx volumio[782]: info: CoreCommandRouter::servicePushState Sep 11 12:24:35 hswhdx volumio[782]: info: CorePlayQueue::getTrack 0 Sep 11 12:24:35 hswhdx volumio[782]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":476,"samplerate":44.1,"bitdepth":"32 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"4103480&soundQuality=HIGH","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=tidal://song/4103480&soundQuality=HIGH","trackType":"tidal"} Sep 11 12:24:35 hswhdx volumio[782]: verbose: CURRENT POSITION 0 Sep 11 12:24:35 hswhdx volumio[782]: info: CoreStateMachine::syncState stateService play Sep 11 12:24:35 hswhdx volumio[782]: info: CoreStateMachine::syncState currentStatus play Sep 11 12:24:35 hswhdx volumio[782]: info: Received an update from plugin. extracting info from payload Sep 11 12:24:35 hswhdx volumio[782]: info: CoreStateMachine::pushState Sep 11 12:24:35 hswhdx volumio[782]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 11 12:24:35 hswhdx volumio[782]: info: CoreCommandRouter::volumioPushState Sep 11 12:24:35 hswhdx volumio[782]: info: CoreCommandRouter::volumioGetState Sep 11 12:24:35 hswhdx volumio[782]: info: CoreStateMachine::pushState Sep 11 12:24:35 hswhdx volumio[782]: info: CoreCommandRouter::volumioPushState Sep 11 12:24:35 hswhdx volumio[782]: info: CoreCommandRouter::volumioGetState Sep 11 12:24:35 hswhdx volumio[782]: info: ------------------------------ 54ms Sep 11 12:24:36 hswhdx volumio[782]: STREAMING PROXY: Client dropped request, destroying Sep 11 12:24:43 hswhdx volumio[782]: info: CoreCommandRouter::volumioSaveQueueToPlaylist Sep 11 12:24:43 hswhdx volumio[782]: info: CoreStateMachine::getQueue Sep 11 12:24:43 hswhdx volumio[782]: info: CorePlayQueue::getQueue Sep 11 12:24:43 hswhdx volumio[782]: info: Saving Cloud item Keyboard Concerto in D major No. 11 Sep 11 12:24:43 hswhdx volumio[782]: info: CoreCommandRouter::executeOnPlugin: my_volumio , saveCloudItem Sep 11 12:24:43 hswhdx volumio[782]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 11 12:24:43 hswhdx volumio[782]: Error: Reference.child failed: First argument was an invalid path = "/user_data/Y1tqxwgnPBO41HjZ1ERZzk9xxef1/myPlaylists/Keyboard Concerto in D major No. 11". Paths must be non-empty strings and can't contain ".", "#", "$", "[", or "]" Sep 11 12:24:43 hswhdx volumio[782]: at validatePathString (/volumio/node_modules/@firebase/database/dist/index.node.cjs.js:1667:15) Sep 11 12:24:43 hswhdx volumio[782]: at validateRootPathString (/volumio/node_modules/@firebase/database/dist/index.node.cjs.js:1679:5) Sep 11 12:24:43 hswhdx volumio[782]: at Reference.child (/volumio/node_modules/@firebase/database/dist/index.node.cjs.js:13737:17) Sep 11 12:24:43 hswhdx volumio[782]: at Database.ref (/volumio/node_modules/@firebase/database/dist/index.node.cjs.js:15115:48) Sep 11 12:24:43 hswhdx volumio[782]: at myVolumio.syncJSONToCloud (/myvolumio/plugins/system_controller/my_volumio/my_volumio_real:1:28817) Sep 11 12:24:43 hswhdx volumio[782]: at myVolumio.saveCloudMyPlaylist (/myvolumio/plugins/system_controller/my_volumio/my_volumio_real:1:23840) Sep 11 12:24:43 hswhdx volumio[782]: at myVolumio.saveCloudItem (/myvolumio/plugins/system_controller/my_volumio/my_volumio_real:1:18337) Sep 11 12:24:43 hswhdx volumio[782]: at CoreCommandRouter.executeOnPlugin (/volumio/app/index.js:1096:32) Sep 11 12:24:43 hswhdx volumio[782]: at PlaylistManager.saveJSONFile (/volumio/app/playlistManager.js:613:31) Sep 11 12:24:43 hswhdx volumio[782]: at PlaylistManager.commonAddItemsToPlaylist (/volumio/app/playlistManager.js:834:8) Sep 11 12:24:43 hswhdx volumio[782]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 11 12:24:43 hswhdx sudo[32208]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-09-11 12:23 Sep 11 12:24:43 hswhdx sudo[32208]: 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"