-- Logs begin at Fri 2024-08-23 00:56:11 CEST, end at Sun 2024-08-25 18:00:12 CEST. -- Aug 25 17:59:00 volumio volumio[691]: STREAMING PROXY: Client dropped request, destroying Aug 25 17:59:00 volumio volumio[691]: info: CoreCommandRouter::volumioNext Aug 25 17:59:00 volumio volumio[691]: info: CoreStateMachine::next Aug 25 17:59:00 volumio volumio[691]: info: [1724601540465] ControllerQobuz::next Aug 25 17:59:00 volumio volumio[691]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 25 17:59:00 volumio volumio[691]: info: CoreStateMachine::next Aug 25 17:59:00 volumio volumio[691]: info: CoreStateMachine::stop Aug 25 17:59:00 volumio volumio[691]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 25 17:59:00 volumio volumio[691]: info: CoreStateMachine::stPlaybackTimer Aug 25 17:59:00 volumio volumio[691]: info: CoreStateMachine::updateTrackBlock Aug 25 17:59:00 volumio volumio[691]: info: CorePlayQueue::getTrackBlock Aug 25 17:59:00 volumio volumio[691]: info: CoreStateMachine::pushState Aug 25 17:59:00 volumio volumio[691]: info: CorePlayQueue::getTrack 0 Aug 25 17:59:00 volumio volumio[691]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 25 17:59:00 volumio volumio[691]: info: CoreCommandRouter::volumioPushState Aug 25 17:59:00 volumio volumio[691]: info: CoreStateMachine::serviceStop Aug 25 17:59:00 volumio volumio[691]: info: CorePlayQueue::getTrack 0 Aug 25 17:59:00 volumio volumio[691]: info: CoreCommandRouter::serviceStop Aug 25 17:59:00 volumio volumio[691]: info: [1724601540467] ControllerQobuz::stop Aug 25 17:59:00 volumio volumio[691]: info: CoreStateMachine::setConsumeUpdateService mpd Aug 25 17:59:00 volumio volumio[691]: info: ControllerMpd::stop Aug 25 17:59:00 volumio volumio[691]: verbose: ControllerMpd::sendMpdCommand stop Aug 25 17:59:00 volumio volumio[691]: info: Aug 25 17:59:00 volumio volumio[691]: ---------------------------- MPD announces state update: player Aug 25 17:59:00 volumio volumio[691]: info: sendMpdCommand stop took 27 milliseconds Aug 25 17:59:00 volumio volumio[691]: info: ControllerMpd::getState Aug 25 17:59:00 volumio volumio[691]: verbose: ControllerMpd::sendMpdCommand status Aug 25 17:59:00 volumio volumio[691]: info: CoreStateMachine::play index undefined Aug 25 17:59:00 volumio volumio[691]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 25 17:59:00 volumio volumio[691]: info: CorePlayQueue::getTrack 1 Aug 25 17:59:00 volumio volumio[691]: info: CoreStateMachine::startPlaybackTimer Aug 25 17:59:00 volumio volumio[691]: info: CorePlayQueue::getTrack 1 Aug 25 17:59:00 volumio volumio[691]: info: [1724601540494] ControllerQobuz::clearAddPlayTrack Aug 25 17:59:00 volumio volumio[691]: verbose: ControllerMpd::sendMpdCommand stop Aug 25 17:59:00 volumio volumio[691]: info: CoreStateMachine::updateTrackBlock Aug 25 17:59:00 volumio volumio[691]: info: CorePlayQueue::getTrackBlock Aug 25 17:59:00 volumio volumio[691]: info: sendMpdCommand status took 1 milliseconds Aug 25 17:59:00 volumio volumio[691]: info: sendMpdCommand stop took 0 milliseconds Aug 25 17:59:00 volumio volumio[691]: verbose: ControllerMpd::parseState Aug 25 17:59:00 volumio volumio[691]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 25 17:59:00 volumio volumio[691]: verbose: ControllerMpd::sendMpdCommand clear Aug 25 17:59:00 volumio volumio[691]: info: Aug 25 17:59:00 volumio volumio[691]: ---------------------------- MPD announces system playlist update Aug 25 17:59:00 volumio volumio[691]: info: Ignoring MPD Status Update Aug 25 17:59:00 volumio volumio[691]: info: sendMpdCommand playlistinfo took 1 milliseconds Aug 25 17:59:00 volumio volumio[691]: info: sendMpdCommand clear took 1 milliseconds Aug 25 17:59:00 volumio volumio[691]: verbose: ControllerMpd::parseTrackInfo Aug 25 17:59:00 volumio volumio[691]: verbose: ControllerMpd::sendMpdCommand load "http://127.0.0.1:3245?data=qobuz://song/48972095" Aug 25 17:59:00 volumio volumio[691]: info: ControllerMpd::pushState Aug 25 17:59:00 volumio volumio[691]: info: CoreCommandRouter::servicePushState Aug 25 17:59:00 volumio volumio[691]: info: CoreStateMachine::pushState Aug 25 17:59:00 volumio volumio[691]: info: CorePlayQueue::getTrack 1 Aug 25 17:59:00 volumio volumio[691]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 25 17:59:00 volumio volumio[691]: info: CoreCommandRouter::volumioPushState Aug 25 17:59:00 volumio volumio[691]: info: CorePlayQueue::getTrack 1 Aug 25 17:59:00 volumio volumio[691]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current qobuz Received mpd Aug 25 17:59:00 volumio volumio[691]: STREAMING PROXY: Handling url /?data=qobuz://song/48972095 Aug 25 17:59:00 volumio volumio[691]: info: ------------------------------ 8ms Aug 25 17:59:00 volumio volumio[691]: error: updateQueue error: null Aug 25 17:59:00 volumio volumio[691]: info: ------------------------------ 5ms Aug 25 17:59:00 volumio volumio[691]: info: Executing endpoint getStreamUrlqobuz Aug 25 17:59:00 volumio volumio[691]: info: CoreCommandRouter::executeOnPlugin: qobuz , getStreamUrlAPI Aug 25 17:59:00 volumio volumio[691]: info: getStreamUrl took 308 milliseconds Aug 25 17:59:00 volumio volumio[691]: STREAMING PROXY: Got real url: http://streaming-qobuz-std.akamaized.net:80/file?uid=241217&eid=48972095&fmt=6&profile=raw&app_id=539451548&cid=1705857&etsp=1724605140&hmac=9O7p_x28icV4mv8eAkZ41q_MyQY Aug 25 17:59:00 volumio volumio[691]: STREAMING PROXY: Response: 200, length: 28712833 Aug 25 17:59:00 volumio volumio[691]: STREAMING PROXY: Client dropped request, destroying Aug 25 17:59:00 volumio volumio[691]: verbose: ControllerMpd::sendMpdCommand add "http://127.0.0.1:3245?data=qobuz://song/48972095" Aug 25 17:59:00 volumio volumio[691]: info: Aug 25 17:59:00 volumio volumio[691]: ---------------------------- MPD announces system playlist update Aug 25 17:59:00 volumio volumio[691]: info: Ignoring MPD Status Update Aug 25 17:59:00 volumio volumio[691]: info: sendMpdCommand add "http://127.0.0.1:3245?data=qobuz://song/48972095" took 1 milliseconds Aug 25 17:59:00 volumio volumio[691]: info: CoreStateMachine::setConsumeUpdateService mpd Aug 25 17:59:00 volumio volumio[691]: verbose: ControllerMpd::sendMpdCommand play Aug 25 17:59:00 volumio volumio[691]: STREAMING PROXY: Handling url /?data=qobuz://song/48972095 Aug 25 17:59:00 volumio volumio[691]: info: ------------------------------ 1ms Aug 25 17:59:00 volumio volumio[691]: info: sendMpdCommand play took 2 milliseconds Aug 25 17:59:00 volumio volumio[691]: info: Executing endpoint getStreamUrlqobuz Aug 25 17:59:00 volumio volumio[691]: info: CoreCommandRouter::executeOnPlugin: qobuz , getStreamUrlAPI Aug 25 17:59:01 volumio volumio[691]: info: getStreamUrl took 553 milliseconds Aug 25 17:59:01 volumio volumio[691]: STREAMING PROXY: Got real url: http://streaming-qobuz-std.akamaized.net:80/file?uid=241217&eid=48972095&fmt=6&profile=raw&app_id=539451548&cid=1705857&etsp=1724605141&hmac=x8EU3QF4oJ-qnyuv3u_5NQcGn3U Aug 25 17:59:01 volumio volumio[691]: STREAMING PROXY: Response: 200, length: 28712833 Aug 25 17:59:01 volumio volumio[691]: info: Aug 25 17:59:01 volumio volumio[691]: ---------------------------- MPD announces state update: player Aug 25 17:59:01 volumio volumio[691]: info: ControllerMpd::getState Aug 25 17:59:01 volumio volumio[691]: verbose: ControllerMpd::sendMpdCommand status Aug 25 17:59:01 volumio volumio[691]: info: Aug 25 17:59:01 volumio volumio[691]: ---------------------------- MPD announces state update: player Aug 25 17:59:01 volumio volumio[691]: info: sendMpdCommand status took 4 milliseconds Aug 25 17:59:01 volumio volumio[691]: info: ControllerMpd::getState Aug 25 17:59:01 volumio volumio[691]: verbose: ControllerMpd::sendMpdCommand status Aug 25 17:59:01 volumio volumio[691]: verbose: ControllerMpd::parseState Aug 25 17:59:01 volumio volumio[691]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 25 17:59:01 volumio volumio[691]: info: sendMpdCommand status took 1 milliseconds Aug 25 17:59:01 volumio volumio[691]: info: sendMpdCommand playlistinfo took 1 milliseconds Aug 25 17:59:01 volumio volumio[691]: verbose: ControllerMpd::parseState Aug 25 17:59:01 volumio volumio[691]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 25 17:59:01 volumio volumio[691]: verbose: ControllerMpd::parseTrackInfo Aug 25 17:59:01 volumio volumio[691]: info: ControllerMpd::pushState Aug 25 17:59:01 volumio volumio[691]: info: CoreCommandRouter::servicePushState Aug 25 17:59:01 volumio volumio[691]: info: CorePlayQueue::getTrack 1 Aug 25 17:59:01 volumio volumio[691]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":240,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"48972095","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/48972095","trackType":"qobuz"} Aug 25 17:59:01 volumio volumio[691]: verbose: CURRENT POSITION 1 Aug 25 17:59:01 volumio volumio[691]: info: CoreStateMachine::syncState stateService play Aug 25 17:59:01 volumio volumio[691]: info: CoreStateMachine::syncState currentStatus stop Aug 25 17:59:01 volumio volumio[691]: info: ------------------------------ 6ms Aug 25 17:59:01 volumio volumio[691]: info: sendMpdCommand playlistinfo took 1 milliseconds Aug 25 17:59:01 volumio volumio[691]: verbose: ControllerMpd::parseTrackInfo Aug 25 17:59:01 volumio volumio[691]: info: ControllerMpd::pushState Aug 25 17:59:01 volumio volumio[691]: info: CoreCommandRouter::servicePushState Aug 25 17:59:01 volumio volumio[691]: info: CorePlayQueue::getTrack 1 Aug 25 17:59:01 volumio volumio[691]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":240,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"48972095","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/48972095","trackType":"qobuz"} Aug 25 17:59:01 volumio volumio[691]: verbose: CURRENT POSITION 1 Aug 25 17:59:01 volumio volumio[691]: info: CoreStateMachine::syncState stateService play Aug 25 17:59:01 volumio volumio[691]: info: CoreStateMachine::syncState currentStatus play Aug 25 17:59:01 volumio volumio[691]: info: Received an update from plugin. extracting info from payload Aug 25 17:59:01 volumio volumio[691]: info: CoreStateMachine::pushState Aug 25 17:59:01 volumio volumio[691]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 25 17:59:01 volumio volumio[691]: info: CoreCommandRouter::volumioPushState Aug 25 17:59:01 volumio volumio[691]: info: CoreStateMachine::pushState Aug 25 17:59:01 volumio volumio[691]: info: CoreCommandRouter::volumioPushState Aug 25 17:59:01 volumio volumio[691]: info: ------------------------------ 9ms Aug 25 17:59:01 volumio volumio[691]: STREAMING PROXY: Client dropped request, destroying Aug 25 17:59:41 volumio volumio[691]: info: CoreCommandRouter::volumioPrevious Aug 25 17:59:41 volumio volumio[691]: info: CoreStateMachine::previous Aug 25 17:59:41 volumio volumio[691]: info: [1724601581173] ControllerQobuz::seek Aug 25 17:59:41 volumio volumio[691]: info: CoreStateMachine::setConsumeUpdateService mpd Aug 25 17:59:41 volumio volumio[691]: info: ControllerMpd::seek Aug 25 17:59:41 volumio volumio[691]: error: null Aug 25 17:59:41 volumio volumio[691]: info: Aug 25 17:59:41 volumio volumio[691]: ---------------------------- MPD announces state update: player Aug 25 17:59:41 volumio volumio[691]: info: ControllerMpd::getState Aug 25 17:59:41 volumio volumio[691]: verbose: ControllerMpd::sendMpdCommand status Aug 25 17:59:41 volumio volumio[691]: info: sendMpdCommand status took 1 milliseconds Aug 25 17:59:41 volumio volumio[691]: verbose: ControllerMpd::parseState Aug 25 17:59:41 volumio volumio[691]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 25 17:59:41 volumio volumio[691]: info: sendMpdCommand playlistinfo took 0 milliseconds Aug 25 17:59:41 volumio volumio[691]: verbose: ControllerMpd::parseTrackInfo Aug 25 17:59:41 volumio volumio[691]: info: ControllerMpd::pushState Aug 25 17:59:41 volumio volumio[691]: info: CoreCommandRouter::servicePushState Aug 25 17:59:41 volumio volumio[691]: info: CorePlayQueue::getTrack 1 Aug 25 17:59:41 volumio volumio[691]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":240,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"911 Kbps","isStreaming":false,"title":"48972095","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/48972095","trackType":"qobuz"} Aug 25 17:59:41 volumio volumio[691]: verbose: CURRENT POSITION 1 Aug 25 17:59:41 volumio volumio[691]: info: CoreStateMachine::syncState stateService play Aug 25 17:59:41 volumio volumio[691]: info: CoreStateMachine::syncState currentStatus play Aug 25 17:59:41 volumio volumio[691]: info: Received an update from plugin. extracting info from payload Aug 25 17:59:41 volumio volumio[691]: info: CoreStateMachine::pushState Aug 25 17:59:41 volumio volumio[691]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 25 17:59:41 volumio volumio[691]: info: CoreCommandRouter::volumioPushState Aug 25 17:59:41 volumio volumio[691]: info: CoreStateMachine::pushState Aug 25 17:59:41 volumio volumio[691]: info: CoreCommandRouter::volumioPushState Aug 25 17:59:41 volumio volumio[691]: info: ------------------------------ 17ms Aug 25 18:00:11 volumio volumio[691]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 25 18:00:11 volumio volumio[691]: Error: connect ETIMEDOUT 151.101.122.79:443 Aug 25 18:00:11 volumio volumio[691]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) { Aug 25 18:00:11 volumio volumio[691]: errno: -110, Aug 25 18:00:11 volumio volumio[691]: code: 'ETIMEDOUT', Aug 25 18:00:11 volumio volumio[691]: syscall: 'connect', Aug 25 18:00:11 volumio volumio[691]: address: '151.101.122.79', Aug 25 18:00:11 volumio volumio[691]: port: 443 Aug 25 18:00:11 volumio volumio[691]: } Aug 25 18:00:11 volumio volumio[691]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 25 18:00:12 volumio sudo[3525]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-08-25 17:59 Aug 25 18:00:12 volumio sudo[3525]: 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="7f9f1bf001add7a8b19a4516e3c74ef598b2730d" VOLUMIO_FE_VERSION="614d7b13ffdcb0cc5a6072e7d06f59d52e323e71" VOLUMIO_FE3_VERSION="570aaed971c1346d45d1172dc445b086b258c6d1" VOLUMIO_BE_VERSION="512433c3e91cdaed7ecd2808b21adeffc2137d7f" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Wed 21 Feb 2024 09:37:22 PM CET" VOLUMIO_VERSION="3.631" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="fdd9dd1169c06c1ad0a30ddd24c91b6b"