-- Logs begin at Thu 2025-07-10 22:01:05 EDT, end at Fri 2025-07-11 00:04:15 EDT. -- Jul 11 00:03:04 volumio volumio[866]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Jul 11 00:03:04 volumio volumio[866]: info: Preload queue cleared Jul 11 00:03:04 volumio volumio[866]: verbose: ----------------------------------- Jul 11 00:03:04 volumio volumio[866]: verbose: [yt-cast-receiver] (AID: 1298) (YouTube) Incoming message: 'noop' Jul 11 00:03:04 volumio volumio[866]: verbose: [yt-cast-receiver] (AID: 1298) (YouTube) Not handled: 'noop' Jul 11 00:03:08 volumio volumio[866]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Jul 11 00:03:08 volumio volumio[866]: info: Preload queue cleared Jul 11 00:03:19 volumio volumio[866]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Jul 11 00:03:20 volumio volumio[866]: info: Preload queue cleared Jul 11 00:03:22 volumio volumio[866]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Jul 11 00:03:22 volumio volumio[866]: info: Preload queue cleared Jul 11 00:03:27 volumio volumio[866]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Jul 11 00:03:27 volumio volumio[866]: info: Preload queue cleared Jul 11 00:03:30 volumio volumio[866]: verbose: ----------------------------------- Jul 11 00:03:30 volumio volumio[866]: verbose: [yt-cast-receiver] (AID: 1299) (YouTube) Incoming message: 'noop' Jul 11 00:03:30 volumio volumio[866]: verbose: [yt-cast-receiver] (AID: 1299) (YouTube) Not handled: 'noop' Jul 11 00:03:45 volumio volumio[866]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Jul 11 00:03:45 volumio volumio[866]: info: Preload queue cleared Jul 11 00:03:46 volumio volumio[866]: info: [ASDebug] Togle GPIO: OFF Jul 11 00:03:47 volumio volumio[866]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Jul 11 00:03:47 volumio volumio[866]: info: Preload queue cleared Jul 11 00:03:49 volumio volumio[866]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Jul 11 00:03:49 volumio volumio[866]: info: Preload queue cleared Jul 11 00:03:51 volumio volumio[866]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Jul 11 00:03:51 volumio volumio[866]: info: Preload queue cleared Jul 11 00:03:55 volumio volumio[866]: verbose: ----------------------------------- Jul 11 00:03:55 volumio volumio[866]: verbose: [yt-cast-receiver] (AID: 1300) (YouTube) Incoming message: 'noop' Jul 11 00:03:55 volumio volumio[866]: verbose: [yt-cast-receiver] (AID: 1300) (YouTube) Not handled: 'noop' Jul 11 00:04:01 volumio volumio[866]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Jul 11 00:04:01 volumio volumio[866]: info: Preload queue cleared Jul 11 00:04:01 volumio volumio[866]: info: Preloading song: upnp/http://192.168.0.210:32469/ContentDirectory/5e803d4a-8635-585a-06b7-b412f787eedc/control.xml@5fd0cca066f3746c5351 Jul 11 00:04:01 volumio volumio[866]: info: Preloading song: upnp/http://192.168.0.210:32469/ContentDirectory/5e803d4a-8635-585a-06b7-b412f787eedc/control.xml@164dab35d040f9542d46 Jul 11 00:04:01 volumio volumio[866]: info: Preloading song: upnp/http://192.168.0.210:32469/ContentDirectory/5e803d4a-8635-585a-06b7-b412f787eedc/control.xml@2f0d26239cce31d21c65 Jul 11 00:04:01 volumio volumio[866]: info: Preloading song: upnp/http://192.168.0.210:32469/ContentDirectory/5e803d4a-8635-585a-06b7-b412f787eedc/control.xml@21e1a265ea611d471fb2 Jul 11 00:04:01 volumio volumio[866]: info: Preloading song: upnp/http://192.168.0.210:32469/ContentDirectory/5e803d4a-8635-585a-06b7-b412f787eedc/control.xml@c843fbe37fa190ad09e3 Jul 11 00:04:01 volumio volumio[866]: info: Exploding uri upnp/http://192.168.0.210:32469/ContentDirectory/5e803d4a-8635-585a-06b7-b412f787eedc/control.xml@5fd0cca066f3746c5351 in service upnp_browser Jul 11 00:04:01 volumio volumio[866]: info: Exploding uri upnp/http://192.168.0.210:32469/ContentDirectory/5e803d4a-8635-585a-06b7-b412f787eedc/control.xml@164dab35d040f9542d46 in service upnp_browser Jul 11 00:04:01 volumio volumio[866]: info: Exploding uri upnp/http://192.168.0.210:32469/ContentDirectory/5e803d4a-8635-585a-06b7-b412f787eedc/control.xml@2f0d26239cce31d21c65 in service upnp_browser Jul 11 00:04:01 volumio volumio[866]: info: Exploding uri upnp/http://192.168.0.210:32469/ContentDirectory/5e803d4a-8635-585a-06b7-b412f787eedc/control.xml@21e1a265ea611d471fb2 in service upnp_browser Jul 11 00:04:01 volumio volumio[866]: info: Exploding uri upnp/http://192.168.0.210:32469/ContentDirectory/5e803d4a-8635-585a-06b7-b412f787eedc/control.xml@c843fbe37fa190ad09e3 in service upnp_browser Jul 11 00:04:03 volumio volumio[866]: info: Preload queue cleared Jul 11 00:04:03 volumio volumio[866]: info: CoreCommandRouter::volumioReplaceandPlayItems Jul 11 00:04:03 volumio volumio[866]: info: CoreStateMachine::ClearQueue Jul 11 00:04:03 volumio volumio[866]: info: CoreStateMachine::stop Jul 11 00:04:03 volumio volumio[866]: info: CoreStateMachine::serviceStop Jul 11 00:04:03 volumio volumio[866]: info: CoreCommandRouter::serviceStop Jul 11 00:04:03 volumio volumio[866]: info: QobuzConnect: Received stop Jul 11 00:04:03 volumio volumio[866]: info: CoreCommandRouter::volumioGetState Jul 11 00:04:03 volumio qobuz-connect[9009]: 20250711 00:04:03.292 [9009.9009] INFO MediaEngine: [0x1e19788]: Stopping playback, keeping tracks Jul 11 00:04:03 volumio qobuz-connect[9009]: 20250711 00:04:03.292 [9009.9009] INFO AudioRenderer: [0x1e199a8]: Stopping audio renderer Jul 11 00:04:03 volumio qobuz-connect[9009]: 20250711 00:04:03.292 [9009.9009] INFO SampleApp: Stopping playback Jul 11 00:04:03 volumio volumio[866]: info: CorePlayQueue::clearPlayQueue Jul 11 00:04:03 volumio volumio[866]: info: CorePlayQueue::saveQueue Jul 11 00:04:03 volumio volumio[866]: info: CoreCommandRouter::volumioPushQueue Jul 11 00:04:03 volumio qobuz-connect[9009]: 20250711 00:04:03.295 [9009.9009] INFO AudioStreamManager: [0x1e19870]: Clearing all streams Jul 11 00:04:03 volumio qobuz-connect[9009]: 20250711 00:04:03.295 [9009.9009] INFO AudioStreamManager: [0x1e19870]: [Stream 543]: Disposing of audio stream Jul 11 00:04:03 volumio qobuz-connect[9009]: 20250711 00:04:03.295 [9009.9009] INFO ContentFetcher: [0x1ef24e0]: Canceling download Jul 11 00:04:03 volumio volumio[866]: info: CoreStateMachine::addQueueItems Jul 11 00:04:03 volumio volumio[866]: info: CorePlayQueue::addQueueItems Jul 11 00:04:03 volumio volumio[866]: info: Preload queue cleared Jul 11 00:04:03 volumio volumio[866]: info: Adding Item to queue: upnp/http://192.168.0.210:32469/ContentDirectory/5e803d4a-8635-585a-06b7-b412f787eedc/control.xml@5fd0cca066f3746c5351 Jul 11 00:04:03 volumio volumio[866]: info: Using cached record of: upnp/http://192.168.0.210:32469/ContentDirectory/5e803d4a-8635-585a-06b7-b412f787eedc/control.xml@5fd0cca066f3746c5351 Jul 11 00:04:03 volumio volumio[866]: info: CoreCommandRouter::volumioPushQueue Jul 11 00:04:03 volumio qobuz-connect[9009]: 20250711 00:04:03.304 [9009.9009] INFO AudioStreamManager: [0x1e19870]: New stream: 545 Jul 11 00:04:03 volumio qobuz-connect[9009]: 20250711 00:04:03.304 [9009.9009] INFO HttpDownloader: [0x1ea4918]: Downloading content from: https://www.qobuz.com/api.json/0.2/track/getFileUrl?format_id=27&request_sig=3f40e912db3adf7020aa7afab632ca80&request_ts=1752206643&track_id=5363985 Jul 11 00:04:03 volumio qobuz-connect[9009]: 20250711 00:04:03.305 [9009.9009] INFO HttpDownloader: [0x1e25240]: Downloading content from: https://www.qobuz.com/api.json/0.2/track/get?track_id=5363985 Jul 11 00:04:03 volumio qobuz-connect[9009]: 20250711 00:04:03.305 [9009.9009] INFO HttpDownloader: [0x1feb950]: Downloading content from: https://www.qobuz.com/api.json/0.2/file/url?format_id=27&intent=stream&request_sig=78b8ede272c147f052605836f76b2404&request_ts=1752206643&track_id=5363985 Jul 11 00:04:03 volumio qobuz-connect[9009]: 20250711 00:04:03.305 [9009.9009] INFO AudioStreamManager: [0x1e19870]: [Stream 545]: Running audio stream Jul 11 00:04:03 volumio qobuz-connect[9009]: 20250711 00:04:03.305 [9009.9009] INFO AudioStreamManager: [0x1e19870]: New stream: 546 Jul 11 00:04:03 volumio qobuz-connect[9009]: 20250711 00:04:03.305 [9009.9009] INFO HttpDownloader: [0x2bca9a0]: Downloading content from: https://www.qobuz.com/api.json/0.2/track/getFileUrl?format_id=27&request_sig=3c6aa6c3fe66ab67544e8ce33b68681d&request_ts=1752206643&track_id=168769835 Jul 11 00:04:03 volumio qobuz-connect[9009]: 20250711 00:04:03.305 [9009.9009] INFO HttpDownloader: [0x1ef4c80]: Downloading content from: https://www.qobuz.com/api.json/0.2/track/get?track_id=168769835 Jul 11 00:04:03 volumio qobuz-connect[9009]: 20250711 00:04:03.305 [9009.9009] INFO HttpDownloader: [0x2b73938]: Downloading content from: https://www.qobuz.com/api.json/0.2/file/url?format_id=27&intent=stream&request_sig=e0b91bf8a44f9744ce470e9b6d15cc2d&request_ts=1752206643&track_id=168769835 Jul 11 00:04:03 volumio qobuz-connect[9009]: 20250711 00:04:03.307 [9009.9009] INFO SampleApp: Playback state changed: Stopped Jul 11 00:04:03 volumio qobuz-connect[9009]: 20250711 00:04:03.308 [9009.9009] INFO ProtocolHandler: [0x1e19ec8]: Need to send state update Jul 11 00:04:03 volumio qobuz-connect[9009]: 20250711 00:04:03.308 [9009.9009] INFO QConnectMessageSender: [0x1e59878]: Sending StateUpdated message Jul 11 00:04:03 volumio qobuz-connect[9009]: 20250711 00:04:03.308 [9009.9009] INFO SampleApp: [Stream 543]: Audio stream has been disposed of Jul 11 00:04:03 volumio qobuz-connect[9009]: 20250711 00:04:03.308 [9009.9009] INFO QwspMessageSender: [0x1f23e40]: Sending Payload message Jul 11 00:04:03 volumio volumio[866]: info: CorePlayQueue::saveQueue Jul 11 00:04:03 volumio volumio[866]: info: CoreStateMachine::updateTrackBlock Jul 11 00:04:03 volumio volumio[866]: info: CorePlayQueue::getTrackBlock Jul 11 00:04:03 volumio volumio[866]: info: CoreCommandRouter::volumioPlay Jul 11 00:04:03 volumio volumio[866]: verbose: UNSET VOLATILE: Service: qobuzconnect Jul 11 00:04:03 volumio volumio[866]: info: QobuzConnect: onUnsetVolatile() called, relinquishing Volumio State to another service Jul 11 00:04:03 volumio volumio[866]: info: QobuzConnect: Received stop Jul 11 00:04:03 volumio volumio[866]: info: CoreCommandRouter::volumioGetState Jul 11 00:04:03 volumio qobuz-connect[9009]: 20250711 00:04:03.315 [9009.9009] INFO MediaEngine: [0x1e19788]: Stopping playback, keeping tracks Jul 11 00:04:03 volumio volumio[866]: info: CoreStateMachine::play index 0 Jul 11 00:04:03 volumio volumio[866]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 11 00:04:03 volumio volumio[866]: info: CoreStateMachine::addQueueItems Jul 11 00:04:03 volumio volumio[866]: info: CorePlayQueue::addQueueItems Jul 11 00:04:03 volumio volumio[866]: info: Preload queue cleared Jul 11 00:04:03 volumio volumio[866]: info: Adding Item to queue: upnp/http://192.168.0.210:32469/ContentDirectory/5e803d4a-8635-585a-06b7-b412f787eedc/control.xml@164dab35d040f9542d46 Jul 11 00:04:03 volumio volumio[866]: info: Using cached record of: upnp/http://192.168.0.210:32469/ContentDirectory/5e803d4a-8635-585a-06b7-b412f787eedc/control.xml@164dab35d040f9542d46 Jul 11 00:04:03 volumio volumio[866]: info: Adding Item to queue: upnp/http://192.168.0.210:32469/ContentDirectory/5e803d4a-8635-585a-06b7-b412f787eedc/control.xml@2f0d26239cce31d21c65 Jul 11 00:04:03 volumio volumio[866]: info: Using cached record of: upnp/http://192.168.0.210:32469/ContentDirectory/5e803d4a-8635-585a-06b7-b412f787eedc/control.xml@2f0d26239cce31d21c65 Jul 11 00:04:03 volumio volumio[866]: info: Adding Item to queue: upnp/http://192.168.0.210:32469/ContentDirectory/5e803d4a-8635-585a-06b7-b412f787eedc/control.xml@21e1a265ea611d471fb2 Jul 11 00:04:03 volumio volumio[866]: info: Using cached record of: upnp/http://192.168.0.210:32469/ContentDirectory/5e803d4a-8635-585a-06b7-b412f787eedc/control.xml@21e1a265ea611d471fb2 Jul 11 00:04:03 volumio volumio[866]: info: Adding Item to queue: upnp/http://192.168.0.210:32469/ContentDirectory/5e803d4a-8635-585a-06b7-b412f787eedc/control.xml@c843fbe37fa190ad09e3 Jul 11 00:04:03 volumio volumio[866]: info: Using cached record of: upnp/http://192.168.0.210:32469/ContentDirectory/5e803d4a-8635-585a-06b7-b412f787eedc/control.xml@c843fbe37fa190ad09e3 Jul 11 00:04:03 volumio volumio[866]: info: CoreStateMachine::stop Jul 11 00:04:03 volumio volumio[866]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 11 00:04:03 volumio volumio[866]: info: CoreStateMachine::updateTrackBlock Jul 11 00:04:03 volumio volumio[866]: info: CorePlayQueue::getTrackBlock Jul 11 00:04:03 volumio volumio[866]: info: CoreStateMachine::stPlaybackTimer Jul 11 00:04:03 volumio volumio[866]: info: CoreStateMachine::pushState Jul 11 00:04:03 volumio volumio[866]: info: CorePlayQueue::getTrack 0 Jul 11 00:04:03 volumio volumio[866]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 11 00:04:03 volumio volumio[866]: info: CoreCommandRouter::volumioPushState Jul 11 00:04:03 volumio volumio[866]: info: MRS: Pushing multiroomSync output update for this device Jul 11 00:04:03 volumio volumio[866]: info: MRS: Pushing multiroomSync output Jul 11 00:04:03 volumio volumio[866]: info: CoreCommandRouter::volumioGetState Jul 11 00:04:03 volumio volumio[866]: info: CorePlayQueue::getTrack 0 Jul 11 00:04:03 volumio volumio[866]: info: CoreStateMachine::serviceStop Jul 11 00:04:03 volumio volumio[866]: info: CorePlayQueue::getTrack 0 Jul 11 00:04:03 volumio volumio[866]: info: CoreCommandRouter::serviceStop Jul 11 00:04:03 volumio volumio[866]: info: [1752206643330] ControllerUPNPBrowser::stop Jul 11 00:04:03 volumio volumio[866]: verbose: ControllerMpd::sendMpdCommand stop Jul 11 00:04:03 volumio volumio[866]: info: CoreCommandRouter::volumioPushQueue Jul 11 00:04:03 volumio volumio[866]: info: CorePlayQueue::saveQueue Jul 11 00:04:03 volumio volumio[866]: info: CoreStateMachine::updateTrackBlock Jul 11 00:04:03 volumio volumio[866]: info: CorePlayQueue::getTrackBlock Jul 11 00:04:03 volumio volumio[866]: info: QobuzConnect: playback_stop received, deferred solved Jul 11 00:04:03 volumio volumio[866]: info: QobuzConnect: playback_stop received, deferred solved Jul 11 00:04:03 volumio volumio[866]: info: CoreCommandRouter::volumioGetState Jul 11 00:04:03 volumio volumio[866]: info: CorePlayQueue::getTrack 0 Jul 11 00:04:03 volumio volumio[866]: info: CoreCommandRouter::volumioGetState Jul 11 00:04:03 volumio volumio[866]: info: CorePlayQueue::getTrack 0 Jul 11 00:04:03 volumio volumio[866]: info: [ASDebug] CurState: stop PrevState: pause Jul 11 00:04:03 volumio volumio[866]: info: [GPIO_Control] Status changed: stop Jul 11 00:04:03 volumio volumio[866]: info: [GPIO_Control] Handling event: musicStop Jul 11 00:04:03 volumio volumio[866]: info: [GPIO_Control] *** musicStop *** Jul 11 00:04:03 volumio volumio[866]: info: sendMpdCommand stop took 24 milliseconds Jul 11 00:04:03 volumio volumio[866]: info: CoreStateMachine::play index undefined Jul 11 00:04:03 volumio volumio[866]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 11 00:04:03 volumio volumio[866]: info: CorePlayQueue::getTrack 0 Jul 11 00:04:03 volumio volumio[866]: info: CoreStateMachine::startPlaybackTimer Jul 11 00:04:03 volumio volumio[866]: info: CorePlayQueue::getTrack 0 Jul 11 00:04:03 volumio volumio[866]: info: [1752206643357] ControllerUPNPBrowser::clearAddPlayTrack Jul 11 00:04:03 volumio volumio[866]: verbose: ControllerMpd::sendMpdCommand stop Jul 11 00:04:03 volumio volumio[866]: info: [GPIO_Control] Turning GPIO 6 Off (musicStop) Jul 11 00:04:03 volumio volumio[866]: info: sendMpdCommand stop took 3 milliseconds Jul 11 00:04:03 volumio volumio[866]: verbose: ControllerMpd::sendMpdCommand clear Jul 11 00:04:03 volumio volumio[866]: info: Jul 11 00:04:03 volumio volumio[866]: ---------------------------- MPD announces system playlist update Jul 11 00:04:03 volumio volumio[866]: info: Ignoring MPD Status Update Jul 11 00:04:03 volumio volumio[866]: info: sendMpdCommand clear took 5 milliseconds Jul 11 00:04:03 volumio volumio[866]: verbose: ControllerMpd::sendMpdCommand load "http://192.168.0.210:32469/object/5fd0cca066f3746c5351/file.dsf" Jul 11 00:04:03 volumio volumio[866]: info: Jul 11 00:04:03 volumio volumio[866]: ---------------------------- MPD announces system playlist update Jul 11 00:04:03 volumio volumio[866]: info: Ignoring MPD Status Update Jul 11 00:04:03 volumio volumio[866]: error: updateQueue error: null Jul 11 00:04:03 volumio volumio[866]: info: ------------------------------ 11ms Jul 11 00:04:03 volumio qobuz-connect[9009]: 20250711 00:04:03.415 [9009.9009] INFO AudioStreamManager: [0x1e19870]: [Stream 545]: Metadata became available: Jul 11 00:04:03 volumio qobuz-connect[9009]: 20250711 00:04:03.415 [9009.9009] INFO AudioStreamManager: [0x1e19870]: Title: Melina (Remaster) Jul 11 00:04:03 volumio qobuz-connect[9009]: 20250711 00:04:03.415 [9009.9009] INFO AudioStreamManager: [0x1e19870]: Artist: Bert Kaempfert Jul 11 00:04:03 volumio qobuz-connect[9009]: 20250711 00:04:03.415 [9009.9009] INFO AudioStreamManager: [0x1e19870]: Album: Bye Bye Blues (Remaster) Jul 11 00:04:03 volumio qobuz-connect[9009]: 20250711 00:04:03.415 [9009.9009] INFO AudioStreamManager: [0x1e19870]: Album art URL: https://static.qobuz.com/images/covers/45/34/0060253703445_600.jpg Jul 11 00:04:03 volumio qobuz-connect[9009]: 20250711 00:04:03.426 [9009.9009] INFO AudioStreamManager: [0x1e19870]: [Stream 546]: Metadata became available: Jul 11 00:04:03 volumio qobuz-connect[9009]: 20250711 00:04:03.426 [9009.9009] INFO AudioStreamManager: [0x1e19870]: Title: I Can't Believe that You're in Love With Me Jul 11 00:04:03 volumio qobuz-connect[9009]: 20250711 00:04:03.426 [9009.9009] INFO AudioStreamManager: [0x1e19870]: Artist: Stanley Black Jul 11 00:04:03 volumio qobuz-connect[9009]: 20250711 00:04:03.426 [9009.9009] INFO AudioStreamManager: [0x1e19870]: Album: Red Velvet & Music for Romance Jul 11 00:04:03 volumio qobuz-connect[9009]: 20250711 00:04:03.426 [9009.9009] INFO AudioStreamManager: [0x1e19870]: Album art URL: https://static.qobuz.com/images/covers/xb/lf/dna2qszq1lfxb_600.jpg Jul 11 00:04:03 volumio qobuz-connect[9009]: 20250711 00:04:03.453 [9009.9009] INFO AudioStreamManager: [0x1e19870]: [Stream 545]: track URL resolved to: https://streaming-qobuz-std.akamaized.net/file?uid=2487270&eid=5363985&fmt=6&profile=raw&app_id=174516466&cid=1726506&etsp=1752210243&hmac=kxGmUNPPnYKviLO9wrGcjyW1YSU Jul 11 00:04:03 volumio qobuz-connect[9009]: 20250711 00:04:03.515 [9009.9009] INFO AudioStreamManager: [0x1e19870]: [Stream 546]: stream information have been fetched Jul 11 00:04:03 volumio volumio[866]: verbose: ControllerMpd::sendMpdCommand add "http://192.168.0.210:32469/object/5fd0cca066f3746c5351/file.dsf" Jul 11 00:04:03 volumio volumio[866]: error: updateQueue error: null Jul 11 00:04:03 volumio volumio[866]: info: Jul 11 00:04:03 volumio volumio[866]: ---------------------------- MPD announces system playlist update Jul 11 00:04:03 volumio volumio[866]: info: Ignoring MPD Status Update Jul 11 00:04:03 volumio volumio[866]: info: ------------------------------ 238ms Jul 11 00:04:03 volumio volumio[866]: info: sendMpdCommand add "http://192.168.0.210:32469/object/5fd0cca066f3746c5351/file.dsf" took 2 milliseconds Jul 11 00:04:03 volumio volumio[866]: info: CoreStateMachine::setConsumeUpdateService mpd Jul 11 00:04:03 volumio volumio[866]: verbose: ControllerMpd::sendMpdCommand play Jul 11 00:04:03 volumio qobuz-connect[9009]: 20250711 00:04:03.608 [9009.9009] INFO AudioStreamManager: [0x1e19870]: [Stream 546]: track URL resolved to: https://streaming-qobuz-std.akamaized.net/file?uid=2487270&eid=168769835&fmt=6&profile=raw&app_id=174516466&cid=1726506&etsp=1752210243&hmac=atquc0LiUVT1xNqckmOFzONLAjk Jul 11 00:04:03 volumio volumio[866]: info: Jul 11 00:04:03 volumio volumio[866]: ---------------------------- MPD announces system playlist update Jul 11 00:04:03 volumio volumio[866]: info: Ignoring MPD Status Update Jul 11 00:04:03 volumio volumio[866]: info: ------------------------------ 7ms Jul 11 00:04:03 volumio volumio[866]: info: sendMpdCommand play took 5 milliseconds Jul 11 00:04:03 volumio volumio[866]: info: ------------------------------ 5ms Jul 11 00:04:03 volumio volumio[866]: info: Jul 11 00:04:03 volumio volumio[866]: ---------------------------- MPD announces state update: player Jul 11 00:04:03 volumio volumio[866]: info: ControllerMpd::getState Jul 11 00:04:03 volumio volumio[866]: verbose: ControllerMpd::sendMpdCommand status Jul 11 00:04:03 volumio volumio[866]: info: Jul 11 00:04:03 volumio volumio[866]: ---------------------------- MPD announces state update: player Jul 11 00:04:03 volumio volumio[866]: info: ControllerMpd::getState Jul 11 00:04:03 volumio volumio[866]: verbose: ControllerMpd::sendMpdCommand status Jul 11 00:04:03 volumio qobuz-connect[9009]: 20250711 00:04:03.631 [9009.9009] INFO AudioStreamManager: [0x1e19870]: [Stream 545]: stream information have been fetched Jul 11 00:04:03 volumio qobuz-connect[9009]: 20250711 00:04:03.632 [9009.9009] INFO UrlAudioSource: [0x1ff1358]: Starting URL audio source, initial position: 0ms, URL: https://streaming-qobuz-std.akamaized.net/file?uid=2487270&eid=5363985&fmt=6&profile=raw&app_id=174516466&cid=1726506&etsp=1752210243&hmac=kxGmUNPPnYKviLO9wrGcjyW1YSU Jul 11 00:04:03 volumio qobuz-connect[9009]: 20250711 00:04:03.632 [9009.9009] INFO ContentFetcher: [0x208d220]: Fetching content from: https://streaming-qobuz-std.akamaized.net/file?uid=2487270&eid=5363985&fmt=6&profile=raw&app_id=174516466&cid=1726506&etsp=1752210243&hmac=kxGmUNPPnYKviLO9wrGcjyW1YSU, offset: 0 Jul 11 00:04:03 volumio qobuz-connect[9009]: 20250711 00:04:03.632 [9009.9009] INFO SampleApp: [Stream 545]: New audio stream (starting from 0ms) Jul 11 00:04:03 volumio qobuz-connect[9009]: 20250711 00:04:03.632 [9009.9009] INFO SampleApp: [Stream 545]: Stream metadata became available: Jul 11 00:04:03 volumio qobuz-connect[9009]: 20250711 00:04:03.632 [9009.9009] INFO SampleApp: Title: Melina (Remaster) Jul 11 00:04:03 volumio qobuz-connect[9009]: 20250711 00:04:03.632 [9009.9009] INFO SampleApp: Artist: Bert Kaempfert Jul 11 00:04:03 volumio qobuz-connect[9009]: 20250711 00:04:03.632 [9009.9009] INFO SampleApp: Album: Bye Bye Blues (Remaster) Jul 11 00:04:03 volumio qobuz-connect[9009]: 20250711 00:04:03.632 [9009.9009] INFO SampleApp: Album art URL: https://static.qobuz.com/images/covers/45/34/0060253703445_600.jpg Jul 11 00:04:03 volumio volumio[866]: info: CoreCommandRouter::volumioGetState Jul 11 00:04:03 volumio volumio[866]: verbose: [ytcr] MPDSubsystemEventEmitter invoking 1 SubsystemEventListener callbacks for: player Jul 11 00:04:03 volumio volumio[866]: info: Jul 11 00:04:03 volumio volumio[866]: ---------------------------- MPD announces state update: player Jul 11 00:04:03 volumio volumio[866]: info: sendMpdCommand status took 33 milliseconds Jul 11 00:04:03 volumio volumio[866]: info: ControllerMpd::getState Jul 11 00:04:03 volumio volumio[866]: verbose: ControllerMpd::sendMpdCommand status Jul 11 00:04:03 volumio volumio[866]: verbose: ControllerMpd::parseState Jul 11 00:04:03 volumio volumio[866]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jul 11 00:04:03 volumio volumio[866]: info: sendMpdCommand status took 37 milliseconds Jul 11 00:04:03 volumio volumio[866]: info: sendMpdCommand status took 6 milliseconds Jul 11 00:04:03 volumio volumio[866]: verbose: ControllerMpd::parseState Jul 11 00:04:03 volumio volumio[866]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jul 11 00:04:03 volumio volumio[866]: verbose: ControllerMpd::parseState Jul 11 00:04:03 volumio volumio[866]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jul 11 00:04:03 volumio volumio[866]: info: Jul 11 00:04:03 volumio volumio[866]: ---------------------------- MPD announces state update: player Jul 11 00:04:03 volumio volumio[866]: info: ControllerMpd::getState Jul 11 00:04:03 volumio volumio[866]: verbose: ControllerMpd::sendMpdCommand status Jul 11 00:04:03 volumio volumio[866]: info: sendMpdCommand playlistinfo took 10 milliseconds Jul 11 00:04:03 volumio volumio[866]: info: sendMpdCommand playlistinfo took 6 milliseconds Jul 11 00:04:03 volumio volumio[866]: info: sendMpdCommand playlistinfo took 6 milliseconds Jul 11 00:04:03 volumio volumio[866]: verbose: ControllerMpd::parseTrackInfo Jul 11 00:04:03 volumio volumio[866]: verbose: ControllerMpd::parseTrackInfo Jul 11 00:04:03 volumio volumio[866]: verbose: ControllerMpd::parseTrackInfo Jul 11 00:04:03 volumio volumio[866]: info: ControllerMpd::pushState Jul 11 00:04:03 volumio volumio[866]: info: CoreCommandRouter::servicePushState Jul 11 00:04:03 volumio volumio[866]: info: CorePlayQueue::getTrack 0 Jul 11 00:04:03 volumio volumio[866]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":444,"samplerate":"2.82 MHz","bitdepth":"1 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"file.dsf","artist":null,"album":null,"uri":"http://192.168.0.210:32469/object/5fd0cca066f3746c5351/file.dsf","trackType":"dsf"} Jul 11 00:04:03 volumio volumio[866]: verbose: CURRENT POSITION 0 Jul 11 00:04:03 volumio volumio[866]: info: CoreStateMachine::syncState stateService play Jul 11 00:04:03 volumio volumio[866]: info: CoreStateMachine::syncState currentStatus stop Jul 11 00:04:03 volumio volumio[866]: info: ControllerMpd::pushState Jul 11 00:04:03 volumio volumio[866]: info: CoreCommandRouter::servicePushState Jul 11 00:04:03 volumio volumio[866]: info: CorePlayQueue::getTrack 0 Jul 11 00:04:03 volumio volumio[866]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":444,"samplerate":"2.82 MHz","bitdepth":"1 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"file.dsf","artist":null,"album":null,"uri":"http://192.168.0.210:32469/object/5fd0cca066f3746c5351/file.dsf","trackType":"dsf"} Jul 11 00:04:03 volumio volumio[866]: verbose: CURRENT POSITION 0 Jul 11 00:04:03 volumio volumio[866]: info: CoreStateMachine::syncState stateService play Jul 11 00:04:03 volumio volumio[866]: info: CoreStateMachine::syncState currentStatus play Jul 11 00:04:03 volumio volumio[866]: info: Received an update from plugin. extracting info from payload Jul 11 00:04:03 volumio volumio[866]: info: CoreStateMachine::pushState Jul 11 00:04:03 volumio volumio[866]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 11 00:04:03 volumio volumio[866]: info: CoreCommandRouter::volumioPushState Jul 11 00:04:03 volumio volumio[866]: info: MRS: Pushing multiroomSync output update for this device Jul 11 00:04:03 volumio volumio[866]: info: MRS: Pushing multiroomSync output Jul 11 00:04:03 volumio volumio[866]: info: CoreCommandRouter::volumioGetState Jul 11 00:04:03 volumio volumio[866]: info: CoreStateMachine::pushState Jul 11 00:04:03 volumio volumio[866]: info: CoreCommandRouter::volumioPushState Jul 11 00:04:03 volumio volumio[866]: info: MRS: Pushing multiroomSync output update for this device Jul 11 00:04:03 volumio volumio[866]: info: MRS: Pushing multiroomSync output Jul 11 00:04:03 volumio volumio[866]: info: CoreCommandRouter::volumioGetState Jul 11 00:04:03 volumio volumio[866]: info: ControllerMpd::pushState Jul 11 00:04:03 volumio volumio[866]: info: CoreCommandRouter::servicePushState Jul 11 00:04:03 volumio volumio[866]: info: CorePlayQueue::getTrack 0 Jul 11 00:04:03 volumio volumio[866]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":444,"samplerate":"2.82 MHz","bitdepth":"1 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"file.dsf","artist":null,"album":null,"uri":"http://192.168.0.210:32469/object/5fd0cca066f3746c5351/file.dsf","trackType":"dsf"} Jul 11 00:04:03 volumio volumio[866]: verbose: CURRENT POSITION 0 Jul 11 00:04:03 volumio volumio[866]: info: CoreStateMachine::syncState stateService play Jul 11 00:04:03 volumio volumio[866]: info: CoreStateMachine::syncState currentStatus play Jul 11 00:04:03 volumio volumio[866]: info: Received an update from plugin. extracting info from payload Jul 11 00:04:03 volumio volumio[866]: info: CoreStateMachine::pushState Jul 11 00:04:03 volumio volumio[866]: info: CoreCommandRouter::volumioPushState Jul 11 00:04:03 volumio volumio[866]: info: MRS: Pushing multiroomSync output update for this device Jul 11 00:04:03 volumio volumio[866]: info: MRS: Pushing multiroomSync output Jul 11 00:04:03 volumio volumio[866]: info: CoreCommandRouter::volumioGetState Jul 11 00:04:03 volumio volumio[866]: info: CoreStateMachine::pushState Jul 11 00:04:03 volumio volumio[866]: info: CoreCommandRouter::volumioPushState Jul 11 00:04:03 volumio volumio[866]: info: MRS: Pushing multiroomSync output update for this device Jul 11 00:04:03 volumio volumio[866]: info: MRS: Pushing multiroomSync output Jul 11 00:04:03 volumio volumio[866]: info: CoreCommandRouter::volumioGetState Jul 11 00:04:03 volumio volumio[866]: info: ------------------------------ 91ms Jul 11 00:04:03 volumio volumio[866]: info: ------------------------------ 110ms Jul 11 00:04:03 volumio volumio[866]: info: ------------------------------ 81ms Jul 11 00:04:03 volumio volumio[866]: verbose: [ytcr] MPDSubsystemEventEmitter invoking 1 SubsystemEventListener callbacks for: player Jul 11 00:04:03 volumio volumio[866]: info: sendMpdCommand status took 70 milliseconds Jul 11 00:04:03 volumio volumio[866]: verbose: ControllerMpd::parseState Jul 11 00:04:03 volumio volumio[866]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jul 11 00:04:03 volumio volumio[866]: info: [ASDebug] CurState: play PrevState: pause Jul 11 00:04:03 volumio volumio[866]: info: [ASDebug] Togle GPIO: ON Jul 11 00:04:03 volumio volumio[866]: info: [ASDebug] CurState: play PrevState: play Jul 11 00:04:03 volumio volumio[866]: info: [ASDebug] CurState: play PrevState: play Jul 11 00:04:03 volumio volumio[866]: info: [ASDebug] CurState: play PrevState: play Jul 11 00:04:03 volumio volumio[866]: info: [GPIO_Control] Status changed: play Jul 11 00:04:03 volumio volumio[866]: info: [GPIO_Control] Handling event: musicPlay Jul 11 00:04:03 volumio volumio[866]: info: [GPIO_Control] *** musicPlay *** Jul 11 00:04:03 volumio volumio[866]: info: [GPIO_Control] Status changed: play Jul 11 00:04:03 volumio volumio[866]: info: [GPIO_Control] Status changed: play Jul 11 00:04:03 volumio volumio[866]: info: [GPIO_Control] Status changed: play Jul 11 00:04:03 volumio volumio[866]: info: [GPIO_Control] Turning GPIO 6 On (musicPlay) Jul 11 00:04:03 volumio volumio[866]: info: sendMpdCommand playlistinfo took 36 milliseconds Jul 11 00:04:03 volumio volumio[866]: verbose: ControllerMpd::parseTrackInfo Jul 11 00:04:03 volumio volumio[866]: info: ControllerMpd::pushState Jul 11 00:04:03 volumio volumio[866]: info: CoreCommandRouter::servicePushState Jul 11 00:04:03 volumio volumio[866]: info: CorePlayQueue::getTrack 0 Jul 11 00:04:03 volumio volumio[866]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":444,"samplerate":"2.82 MHz","bitdepth":"1 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"file.dsf","artist":null,"album":null,"uri":"http://192.168.0.210:32469/object/5fd0cca066f3746c5351/file.dsf","trackType":"dsf"} Jul 11 00:04:03 volumio volumio[866]: verbose: CURRENT POSITION 0 Jul 11 00:04:03 volumio volumio[866]: info: CoreStateMachine::syncState stateService play Jul 11 00:04:03 volumio volumio[866]: info: CoreStateMachine::syncState currentStatus play Jul 11 00:04:03 volumio volumio[866]: info: Received an update from plugin. extracting info from payload Jul 11 00:04:03 volumio volumio[866]: info: CoreStateMachine::pushState Jul 11 00:04:03 volumio volumio[866]: info: CoreCommandRouter::volumioPushState Jul 11 00:04:03 volumio volumio[866]: info: MRS: Pushing multiroomSync output update for this device Jul 11 00:04:03 volumio volumio[866]: info: MRS: Pushing multiroomSync output Jul 11 00:04:03 volumio volumio[866]: info: CoreCommandRouter::volumioGetState Jul 11 00:04:03 volumio volumio[866]: info: CoreStateMachine::pushState Jul 11 00:04:03 volumio volumio[866]: info: CoreCommandRouter::volumioPushState Jul 11 00:04:03 volumio volumio[866]: info: MRS: Pushing multiroomSync output update for this device Jul 11 00:04:03 volumio volumio[866]: info: MRS: Pushing multiroomSync output Jul 11 00:04:03 volumio volumio[866]: info: CoreCommandRouter::volumioGetState Jul 11 00:04:03 volumio volumio[866]: info: ------------------------------ 132ms Jul 11 00:04:03 volumio volumio[866]: info: [ASDebug] CurState: play PrevState: play Jul 11 00:04:03 volumio volumio[866]: info: [ASDebug] CurState: play PrevState: play Jul 11 00:04:03 volumio volumio[866]: info: [GPIO_Control] Status changed: play Jul 11 00:04:03 volumio volumio[866]: info: [GPIO_Control] Status changed: play Jul 11 00:04:04 volumio qobuz-connect[9009]: 20250711 00:04:04.011 [9009.9009] INFO UrlAudioSource: [0x1ff1358]: Content info extracted Jul 11 00:04:04 volumio qobuz-connect[9009]: 20250711 00:04:04.011 [9009.9009] INFO UrlAudioSource: [0x1ff1358]: Size: 19285688 Jul 11 00:04:04 volumio qobuz-connect[9009]: 20250711 00:04:04.012 [9009.19877] INFO AudioDecoder: [0x28b05c0]: Stream info: Jul 11 00:04:04 volumio qobuz-connect[9009]: 20250711 00:04:04.012 [9009.19877] INFO AudioDecoder: [0x28b05c0]: Total samples: 8229060 Jul 11 00:04:04 volumio qobuz-connect[9009]: 20250711 00:04:04.012 [9009.19877] INFO AudioDecoder: [0x28b05c0]: Sample rate: 44100 Jul 11 00:04:04 volumio qobuz-connect[9009]: 20250711 00:04:04.012 [9009.19877] INFO AudioDecoder: [0x28b05c0]: Channel count: 2 Jul 11 00:04:04 volumio qobuz-connect[9009]: 20250711 00:04:04.012 [9009.19877] INFO AudioDecoder: [0x28b05c0]: Bits per sample: 16 Jul 11 00:04:04 volumio qobuz-connect[9009]: 20250711 00:04:04.012 [9009.19877] INFO AudioDecoder: [0x28b05c0]: Duration: 186600 Jul 11 00:04:04 volumio qobuz-connect[9009]: 20250711 00:04:04.012 [9009.9009] INFO UrlAudioSource: [0x1ff1358]: Audio properties have changed Jul 11 00:04:14 volumio volumio[866]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Jul 11 00:04:14 volumio volumio[866]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 11 00:04:14 volumio volumio[866]: TypeError: Cannot read property 'length' of undefined Jul 11 00:04:14 volumio volumio[866]: at /volumio/app/plugins/music_service/upnp_browser/index.js:341:25 Jul 11 00:04:14 volumio volumio[866]: at /volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:131:13 Jul 11 00:04:14 volumio volumio[866]: at Parser. (/volumio/node_modules/xml2js/lib/parser.js:304:18) Jul 11 00:04:14 volumio volumio[866]: at Parser.emit (events.js:315:20) Jul 11 00:04:14 volumio volumio[866]: at SAXParser.onclosetag (/volumio/node_modules/xml2js/lib/parser.js:262:26) Jul 11 00:04:14 volumio volumio[866]: at emit (/volumio/node_modules/sax/lib/sax.js:624:35) Jul 11 00:04:14 volumio volumio[866]: at emitNode (/volumio/node_modules/sax/lib/sax.js:629:5) Jul 11 00:04:14 volumio volumio[866]: at closeTag (/volumio/node_modules/sax/lib/sax.js:889:7) Jul 11 00:04:14 volumio volumio[866]: at SAXParser.write (/volumio/node_modules/sax/lib/sax.js:1436:13) Jul 11 00:04:14 volumio volumio[866]: at Parser.exports.Parser.Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:323:31) Jul 11 00:04:14 volumio volumio[866]: at Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:5:59) Jul 11 00:04:14 volumio volumio[866]: at Object.exports.parseString (/volumio/node_modules/xml2js/lib/parser.js:369:19) Jul 11 00:04:14 volumio volumio[866]: at IncomingMessage. (/volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:92:15) Jul 11 00:04:14 volumio volumio[866]: at IncomingMessage.emit (events.js:327:22) Jul 11 00:04:14 volumio volumio[866]: at endReadableNT (internal/streams/readable.js:1327:12) Jul 11 00:04:14 volumio volumio[866]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Jul 11 00:04:14 volumio volumio[866]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 11 00:04:15 volumio sudo[19915]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-07-11 00:03 Jul 11 00:04:15 volumio sudo[19915]: 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="a142ed2648fb91920de0dde3a60cd39b5d0ba4f6" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="04c18c158cc4bac70764c3360b25fcce0c69266a" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 10 Jun 2025 04:52:53 PM CEST" VOLUMIO_VERSION="3.816" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="a72866a0de4045751d03a035de6290e1"