-- Logs begin at Fri 2025-05-16 03:05:27 EDT, end at Mon 2025-06-02 20:34:05 EDT. -- Jun 02 20:33:01 rivoplus volumio[3139]: info: CALLMETHOD: music_service pandora setMQTTOptionsConf [object Object] Jun 02 20:33:01 rivoplus volumio[3139]: info: CoreCommandRouter::executeOnPlugin: pandora , setMQTTOptionsConf Jun 02 20:33:01 rivoplus volumio[3139]: info: [1748910781515] ControllerPandora::setMQTTOptionsConf Jun 02 20:33:01 rivoplus volumio[3139]: info: [1748910781519] ControllerPandora::initializeMQTT Jun 02 20:33:01 rivoplus volumio[3139]: info: [1748910781520] [Pandora] initializeMQTT: MQTT is not enabled in Plugin Configuration Jun 02 20:33:07 rivoplus volumio[3139]: info: CoreCommandRouter::volumioGetState Jun 02 20:33:07 rivoplus volumio[3139]: info: CorePlayQueue::getTrack 7 Jun 02 20:33:09 rivoplus volumio[3139]: info: Executing endpoint metavolumio Jun 02 20:33:09 rivoplus volumio[3139]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jun 02 20:33:09 rivoplus volumio[3139]: info: Executing endpoint metavolumio Jun 02 20:33:09 rivoplus volumio[3139]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jun 02 20:33:09 rivoplus volumio[3139]: info: Executing endpoint metavolumio Jun 02 20:33:09 rivoplus volumio[3139]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jun 02 20:33:15 rivoplus volumio[3139]: info: CoreCommandRouter::executeOnPlugin: pandora , handleBrowseUri Jun 02 20:33:15 rivoplus volumio[3139]: error: Failed to execute browseSource, failure: TypeError: Cannot read property 'BROWSE' of undefined Jun 02 20:33:24 rivoplus go-librespot[8457]: time="2025-06-02T20:33:24-04:00" level=trace msg="sent dealer ping" Jun 02 20:33:24 rivoplus go-librespot[8457]: time="2025-06-02T20:33:24-04:00" level=trace msg="received dealer pong" Jun 02 20:33:50 rivoplus volumio[3139]: info: CorePlayQueue::getTrack 7 Jun 02 20:33:50 rivoplus volumio[3139]: info: CorePlayQueue::getTrack 8 Jun 02 20:33:50 rivoplus volumio[3139]: info: Prefetching next song Jun 02 20:33:50 rivoplus volumio[3139]: info: [1748910830934] ControllerQobuz::prefetch Jun 02 20:33:50 rivoplus volumio[3139]: verbose: ControllerMpd::sendMpdCommand load "http://127.0.0.1:3245?data=qobuz://song/80111835" Jun 02 20:33:50 rivoplus volumio[3139]: STREAMING PROXY: Handling url /?data=qobuz://song/80111835 Jun 02 20:33:50 rivoplus volumio[3139]: info: Executing endpoint getStreamUrlqobuz Jun 02 20:33:50 rivoplus volumio[3139]: info: CoreCommandRouter::executeOnPlugin: qobuz , getStreamUrlAPI Jun 02 20:33:51 rivoplus volumio[3139]: info: getStreamUrl took 431 milliseconds Jun 02 20:33:51 rivoplus volumio[3139]: STREAMING PROXY: Got real url: https://streaming-qobuz-std.akamaized.net/file?uid=2312871&eid=80111835&fmt=6&profile=raw&app_id=539451548&cid=1604404&etsp=1748914431&hmac=d47Z8OYJnm8EViGEHTkqOx3z5f8 Jun 02 20:33:52 rivoplus volumio[3139]: STREAMING PROXY: Response: 200, length: 32849600 Jun 02 20:33:52 rivoplus volumio[3139]: STREAMING PROXY: Client dropped request, destroying Jun 02 20:33:52 rivoplus volumio[3139]: verbose: ControllerMpd::sendMpdCommand add "http://127.0.0.1:3245?data=qobuz://song/80111835" Jun 02 20:33:52 rivoplus volumio[3139]: info: Jun 02 20:33:52 rivoplus volumio[3139]: ---------------------------- MPD announces system playlist update Jun 02 20:33:52 rivoplus volumio[3139]: info: Ignoring MPD Status Update Jun 02 20:33:52 rivoplus volumio[3139]: info: sendMpdCommand add "http://127.0.0.1:3245?data=qobuz://song/80111835" took 3 milliseconds Jun 02 20:33:52 rivoplus volumio[3139]: STREAMING PROXY: Handling url /?data=qobuz://song/80111835 Jun 02 20:33:52 rivoplus volumio[3139]: info: CoreStateMachine::setConsumeUpdateService mpd Jun 02 20:33:52 rivoplus volumio[3139]: verbose: ControllerMpd::sendMpdCommand consume 1 Jun 02 20:33:52 rivoplus volumio[3139]: info: ------------------------------ 5ms Jun 02 20:33:52 rivoplus volumio[3139]: info: sendMpdCommand consume 1 took 3 milliseconds Jun 02 20:33:52 rivoplus volumio[3139]: info: Executing endpoint getStreamUrlqobuz Jun 02 20:33:52 rivoplus volumio[3139]: info: CoreCommandRouter::executeOnPlugin: qobuz , getStreamUrlAPI Jun 02 20:33:52 rivoplus volumio[3139]: info: getStreamUrl took 407 milliseconds Jun 02 20:33:52 rivoplus volumio[3139]: STREAMING PROXY: Got real url: https://streaming-qobuz-std.akamaized.net/file?uid=2312871&eid=80111835&fmt=6&profile=raw&app_id=539451548&cid=1604404&etsp=1748914432&hmac=ZS1kV20wjOhVabC9fg9J62m0N7U Jun 02 20:33:52 rivoplus volumio[3139]: STREAMING PROXY: Response: 200, length: 32849600 Jun 02 20:33:52 rivoplus volumio[3139]: info: CoreCommandRouter::volumioGetState Jun 02 20:33:54 rivoplus go-librespot[8457]: time="2025-06-02T20:33:54-04:00" level=trace msg="sent dealer ping" Jun 02 20:33:54 rivoplus go-librespot[8457]: time="2025-06-02T20:33:54-04:00" level=trace msg="received dealer pong" Jun 02 20:33:54 rivoplus volumio[3139]: info: Executing endpoint metavolumio Jun 02 20:33:54 rivoplus volumio[3139]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jun 02 20:33:55 rivoplus volumio[3139]: info: Executing endpoint metavolumio Jun 02 20:33:55 rivoplus volumio[3139]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jun 02 20:33:55 rivoplus volumio[3139]: info: Executing endpoint metavolumio Jun 02 20:33:55 rivoplus volumio[3139]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jun 02 20:33:55 rivoplus volumio[3139]: STREAMING PROXY: Client dropped request, destroying Jun 02 20:33:55 rivoplus volumio[3139]: info: CoreStateMachine::startPlaybackTimer Jun 02 20:33:55 rivoplus volumio[3139]: info: CorePlayQueue::getTrack 8 Jun 02 20:33:55 rivoplus volumio[3139]: info: CoreStateMachine::pushState Jun 02 20:33:55 rivoplus volumio[3139]: info: CorePlayQueue::getTrack 8 Jun 02 20:33:55 rivoplus volumio[3139]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 02 20:33:55 rivoplus volumio[3139]: info: CoreCommandRouter::volumioPushState Jun 02 20:33:55 rivoplus volumio[3139]: info: CoreCommandRouter::volumioGetState Jun 02 20:33:55 rivoplus volumio[3139]: info: CorePlayQueue::getTrack 8 Jun 02 20:33:55 rivoplus volumio[3139]: info: Signalling Playback active due to playback status change Jun 02 20:33:55 rivoplus volumio[3139]: info: Updating RAAT Signal Path Jun 02 20:33:56 rivoplus volumio[3139]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jun 02 20:33:56 rivoplus volumio[3139]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Jun 02 20:33:56 rivoplus volumio[3139]: info: Jun 02 20:33:56 rivoplus volumio[3139]: ---------------------------- MPD announces system playlist update Jun 02 20:33:56 rivoplus volumio[3139]: info: Ignoring MPD Status Update Jun 02 20:33:56 rivoplus volumio[3139]: info: Jun 02 20:33:56 rivoplus volumio[3139]: ---------------------------- MPD announces state update: player Jun 02 20:33:56 rivoplus volumio[3139]: info: ControllerMpd::getState Jun 02 20:33:56 rivoplus volumio[3139]: verbose: ControllerMpd::sendMpdCommand status Jun 02 20:33:56 rivoplus volumio[3139]: info: ------------------------------ 5ms Jun 02 20:33:56 rivoplus volumio[3139]: info: sendMpdCommand status took 4 milliseconds Jun 02 20:33:56 rivoplus volumio[3139]: verbose: ControllerMpd::parseState Jun 02 20:33:56 rivoplus volumio[3139]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 02 20:33:56 rivoplus volumio[3139]: info: sendMpdCommand playlistinfo took 1 milliseconds Jun 02 20:33:56 rivoplus volumio[3139]: verbose: ControllerMpd::parseTrackInfo Jun 02 20:33:56 rivoplus volumio[3139]: info: ControllerMpd::pushState Jun 02 20:33:56 rivoplus volumio[3139]: info: CoreCommandRouter::servicePushState Jun 02 20:33:56 rivoplus volumio[3139]: info: CorePlayQueue::getTrack 8 Jun 02 20:33:56 rivoplus volumio[3139]: verbose: STATE SERVICE {"status":"play","position":0,"seek":68,"duration":300,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"873 Kbps","isStreaming":false,"title":"80111835","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/80111835","trackType":"qobuz"} Jun 02 20:33:56 rivoplus volumio[3139]: verbose: CURRENT POSITION 8 Jun 02 20:33:56 rivoplus volumio[3139]: info: CoreStateMachine::syncState stateService play Jun 02 20:33:56 rivoplus volumio[3139]: info: CoreStateMachine::syncState currentStatus play Jun 02 20:33:56 rivoplus volumio[3139]: info: Received an update from plugin. extracting info from payload Jun 02 20:33:56 rivoplus volumio[3139]: info: CoreStateMachine::pushState Jun 02 20:33:56 rivoplus volumio[3139]: info: CorePlayQueue::getTrack 8 Jun 02 20:33:56 rivoplus volumio[3139]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 02 20:33:56 rivoplus volumio[3139]: info: CoreCommandRouter::volumioPushState Jun 02 20:33:56 rivoplus volumio[3139]: info: CoreCommandRouter::volumioGetState Jun 02 20:33:56 rivoplus volumio[3139]: info: CorePlayQueue::getTrack 8 Jun 02 20:33:56 rivoplus volumio[3139]: info: CoreStateMachine::pushState Jun 02 20:33:56 rivoplus volumio[3139]: info: CorePlayQueue::getTrack 8 Jun 02 20:33:56 rivoplus volumio[3139]: info: CoreCommandRouter::volumioPushState Jun 02 20:33:56 rivoplus volumio[3139]: info: CoreCommandRouter::volumioGetState Jun 02 20:33:56 rivoplus volumio[3139]: info: CorePlayQueue::getTrack 8 Jun 02 20:33:56 rivoplus volumio[3139]: info: ------------------------------ 29ms Jun 02 20:33:56 rivoplus volumio[3139]: info: Signalling Playback active due to playback status change Jun 02 20:33:56 rivoplus volumio[3139]: info: Signalling Playback active due to playback status change Jun 02 20:33:56 rivoplus volumio[3139]: info: Updating RAAT Signal Path Jun 02 20:33:56 rivoplus volumio[3139]: info: Updating RAAT Signal Path Jun 02 20:33:58 rivoplus volumio[3139]: info: Executing endpoint metavolumio Jun 02 20:33:58 rivoplus volumio[3139]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jun 02 20:33:58 rivoplus volumio[3139]: info: Executing endpoint metavolumio Jun 02 20:33:58 rivoplus volumio[3139]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jun 02 20:33:58 rivoplus volumio[3139]: info: Executing endpoint metavolumio Jun 02 20:33:58 rivoplus volumio[3139]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jun 02 20:34:05 rivoplus volumio[3139]: info: [1748910845156] ControllerPandora::MQTTHandler::disconnect Jun 02 20:34:05 rivoplus volumio[3139]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 02 20:34:05 rivoplus volumio[3139]: TypeError: Cannot read property 'end' of undefined Jun 02 20:34:05 rivoplus volumio[3139]: at MQTTHandler.disconnect (/data/plugins/music_service/pandora/mqtt_handler.js:73:17) Jun 02 20:34:05 rivoplus volumio[3139]: at ControllerPandora.onStop (/data/plugins/music_service/pandora/index.js:85:68) Jun 02 20:34:05 rivoplus volumio[3139]: at PluginManager.stopPlugin (/volumio/app/pluginmanager.js:460:30) Jun 02 20:34:05 rivoplus volumio[3139]: at PluginManager.disableAndStopPlugin (/volumio/app/pluginmanager.js:1883:8) Jun 02 20:34:05 rivoplus volumio[3139]: at CoreCommandRouter.disableAndStopPlugin (/volumio/app/index.js:1556:29) Jun 02 20:34:05 rivoplus volumio[3139]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:1401:47) Jun 02 20:34:05 rivoplus volumio[3139]: at Socket.emit (events.js:400:28) Jun 02 20:34:05 rivoplus volumio[3139]: at /volumio/node_modules/socket.io/lib/socket.js:528:12 Jun 02 20:34:05 rivoplus volumio[3139]: at processTicksAndRejections (internal/process/task_queues.js:77:11) Jun 02 20:34:05 rivoplus volumio[3139]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 02 20:34:05 rivoplus sudo[17039]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-06-02 20:33 Jun 02 20:34:05 rivoplus sudo[17039]: 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="570c5791513f5bac7da274aba6690c1a961705de" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="35e4a13c94df42ebab19fd6178d6be47190c244d" VOLUMIO_ARCH="armv7" VOLUMIO_VARIANT="rivoplus" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 13 May 2025 06:04:38 PM CEST" VOLUMIO_VERSION="3.812" VOLUMIO_HARDWARE="mp1" VOLUMIO_DEVICENAME="Volumio MP1" VOLUMIO_VENDOR_MODEL="Volumio Rivo" VOLUMIO_VENDOR="Volumio" VOLUMIO_MODEL="Rivo" VOLUMIO_HASH="0064c1a7ac4363e567dacab062cb5da8"