-- Logs begin at Sun 2024-10-27 12:16:44 CET, end at Sun 2024-10-27 14:51:09 CET. -- Oct 27 14:50:00 volumiox86 volumio[17560]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 14:50:00 volumiox86 volumio[17560]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 27 14:50:00 volumiox86 volumio[17560]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Oct 27 14:50:00 volumiox86 volumio[17560]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Oct 27 14:50:00 volumiox86 volumio[17560]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Oct 27 14:50:00 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioGetBrowseSources Oct 27 14:50:00 volumiox86 volumio[17560]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 27 14:50:01 volumiox86 volumiossh-tunnel[17913]: Warning: Permanently added '[eu4.myvolumio.org]:2222,[167.172.103.77]:2222' (RSA) to the list of known hosts. Oct 27 14:50:14 volumiox86 qobuz-connect[17856]: 20241027 14:50:14.877 [17856.17961] INFO SampleApp: API endpoint invoked: get-connect-info Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.023 [17856.17961] INFO SampleApp: API endpoint invoked: connect-to-qconnect Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.023 [17856.17961] DEBUG SampleApp: Session ID: b8b95ec3-6b69-4654-aa66-999a006fff13 Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.023 [17856.17961] DEBUG SampleApp: JWT API: Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.023 [17856.17961] DEBUG SampleApp: Endpoint: https://www.qobuz.com/api.json/0.2 Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.023 [17856.17961] DEBUG SampleApp: JWT: eyJ0eXAiOiJKV1QiLCJhbGciOiJIUzI1NiIsImtpZCI6ImJ0b0RWSXNuNnphV1dBSmlVMG0xWEIyVkxIOG9RU0RQIn0.eyJpYXQiOjE3MzAwMzcwMTQsImV4cCI6MTczMDA0MDYxNCwiaXNzIjoiUW9idXogQVBJIiwicXVpZCI6Nzg5NTk4LCJxYWlkIjoiNTAwODI3MTY5In0.LGZ1GududzOpbxhVnqMvmhE9EaoFg6iIdOyAyQg1Kjo Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.023 [17856.17961] DEBUG SampleApp: Exp: 1730040614 Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.023 [17856.17961] DEBUG SampleApp: JWT QConnect: Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.023 [17856.17961] DEBUG SampleApp: Endpoint: wss://test-server.qconnect.qobuz-dev.com/v2/dev/ws Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.023 [17856.17961] DEBUG SampleApp: JWT: eyJ0eXAiOiJKV1QiLCJhbGciOiJIUzI1NiJ9.eyJpYXQiOjE3MzAwMzcwMTQsImV4cCI6MTczMDA0MDYxNCwiaXNzIjoiUW9idXogQVBJIiwicXVpZCI6Nzg5NTk4LCJxYWlkIjoiNTAwODI3MTY5In0.AmYtuU0pelVD5FJTl2wPE04efVZegSDnsaKjN1uVbcA Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.023 [17856.17961] DEBUG SampleApp: Exp: 1730040614 Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.023 [17856.17961] DEBUG SampleApp: Become Active: true Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.023 [17856.17856] INFO EndpointManager: [0x55ddc90114b0]: Updating API endpoint Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.024 [17856.17856] TRACE EndpointManager: [0x55ddc90114b8]: API endpoint's token state changed: Invalid -> Valid Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.024 [17856.17856] DEBUG EndpointManager: [0x55ddc90114b8]: API endpoint's token will be refreshed in 3539 seconds Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.024 [17856.17856] DEBUG EndpointManager: [0x55ddc90114b8]: API endpoint's token will expire in 3599 seconds Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.024 [17856.17856] INFO EndpointManager: [0x55ddc90114b0]: Updating QConnect endpoint Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.024 [17856.17856] TRACE EndpointManager: [0x55ddc9011630]: QConnect endpoint's token state changed: Invalid -> Valid Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.024 [17856.17856] DEBUG EndpointManager: [0x55ddc9011630]: QConnect endpoint's token will be refreshed in 3539 seconds Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.024 [17856.17856] DEBUG EndpointManager: [0x55ddc9011630]: QConnect endpoint's token will expire in 3599 seconds Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.024 [17856.17856] INFO CloudClient: [0x55ddc9012d30]: Connecting to the cloud Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.024 [17856.17856] DEBUG ProtocolHandler: [0x55ddc9012f90]: Setting active state (externally): active Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.024 [17856.17856] DEBUG WebsocketClient: [0x55ddc902ab60]: Creating Websocket client Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.024 [17856.17856] TRACE WebsocketClient: [0x55ddc902ab60]: Configuring connection Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.024 [17856.17856] INFO SampleApp: Renderer is now active Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.024 [17856.17856] DEBUG PlaybackSessionManager: [0x55ddc9011d20]: Refreshing playback session Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.024 [17856.17856] INFO HttpDownloader: [0x55ddc9012050]: Downloading content from: https://www.qobuz.com/api.json/0.2/session/start Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.238 [17856.17856] TRACE WebsocketClient: [0x55ddc902ab60]: Connected, server protocols: default Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.238 [17856.17856] INFO CloudClient: [0x55ddc9012d30]: Connection established Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.238 [17856.17856] DEBUG QwspMessageSender: [0x55ddc9171fe0]: Creating QWSP Message Sender Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.238 [17856.17856] DEBUG QConnectMessageSender: [0x55ddc9172000]: Creating QConnect Message Sender Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.238 [17856.17856] INFO QwspMessageSender: [0x55ddc9171fe0]: Sending Authenticate message Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.238 [17856.17856] TRACE QwspMessageSender: [0x55ddc9171fe0]: Token: eyJ0eXAiOiJKV1QiLCJhbGciOiJIUzI1NiJ9.eyJpYXQiOjE3MzAwMzcwMTQsImV4cCI6MTczMDA0MDYxNCwiaXNzIjoiUW9idXogQVBJIiwicXVpZCI6Nzg5NTk4LCJxYWlkIjoiNTAwODI3MTY5In0.AmYtuU0pelVD5FJTl2wPE04efVZegSDnsaKjN1uVbcA Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.238 [17856.17856] TRACE ProtocolTracer: [0x55ddc9013180]: => 01 d0 01 08 01 10 c6 c5 f7 f1 ac 32 1a c4 01 65 79 4a 30 65 58 41 69 4f 69 4a 4b 56 31 51 69 4c 43 4a 68 62 47 63 69 4f 69 4a 49 55 7a 49 31 4e 69 4a 39 2e 65 79 4a 70 59 58 51 69 4f 6a 45 33 4d 7a 41 77 4d 7a 63 77 4d 54 51 73 49 6d 56 34 63 43 49 36 4d 54 63 7a 4d 44 41 30 4d 44 59 78 4e 43 77 69 61 58 4e 7a 49 6a 6f 69 55 57 39 69 64 58 6f 67 51 56 42 4a 49 69 77 69 63 58 56 70 5a 43 49 36 4e 7a 67 35 4e 54 6b 34 4c 43 4a 78 59 57 6c 6b 49 6a 6f 69 4e 54 41 77 4f 44 49 33 4d 54 59 35 49 6e 30 2e 41 6d 59 74 75 55 30 70 65 6c 56 44 35 46 4a 54 6c 32 77 50 45 30 34 65 66 56 5a 65 67 53 44 6e 73 61 4b 6a 4e 31 75 56 62 63 41 Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.238 [17856.17856] INFO QwspMessageSender: [0x55ddc9171fe0]: Sending Subscribe message Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.238 [17856.17856] TRACE QwspMessageSender: [0x55ddc9171fe0]: Protocol: QConnect Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.238 [17856.17856] TRACE QwspMessageSender: [0x55ddc9171fe0]: Channel: Backend Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.238 [17856.17856] TRACE ProtocolTracer: [0x55ddc9013180]: => 02 0e 08 02 10 c6 c5 f7 f1 ac 32 18 01 22 01 02 Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.238 [17856.17856] INFO QConnectMessageSender: [0x55ddc9172000]: Sending JoinSession message Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.238 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Reason: Controller Request Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.238 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Active: true Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.238 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Session UUID: b8b95ec3-6b69-4654-aa66-999a006fff13 Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.239 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Playback state: Stopped Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.239 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Current position: 0 Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.239 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Duration: 0 Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.239 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Queue version: 0.0 Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.239 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Current queue item ID: -2 Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.239 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Next queue item ID: -2 Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.239 [17856.17856] INFO QConnectMessageSender: [0x55ddc9172000]: Sending VolumeMuted message Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.239 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Muted: false Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.239 [17856.17856] INFO QConnectMessageSender: [0x55ddc9172000]: Sending VolumeChanged message Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.239 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Volume: 0 Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.239 [17856.17856] INFO QConnectMessageSender: [0x55ddc9172000]: Sending MaxAudioQualityChanged message Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.239 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Max quality: HIRES_L3 Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.239 [17856.17856] INFO QwspMessageSender: [0x55ddc9171fe0]: Sending Payload message Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.239 [17856.17856] TRACE QwspMessageSender: [0x55ddc9171fe0]: Protocol: QConnect Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.239 [17856.17856] TRACE QwspMessageSender: [0x55ddc9171fe0]: Channel: Backend Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.239 [17856.17856] TRACE ProtocolTracer: [0x55ddc9013180]: => 06 d1 01 08 03 10 c7 c5 f7 f1 ac 32 18 01 2a 01 02 3a c0 01 09 c7 e2 3d ce 92 01 00 00 10 01 1a 9b 01 08 15 aa 01 95 01 0a 10 b8 b9 5e c3 6b 69 46 54 aa 66 99 9a 00 6f ff 13 12 56 0a 10 9d a6 32 a9 70 f9 5e e2 90 f9 b1 66 00 4f 7d e6 12 07 76 6f 6c 75 6d 69 6f 1a 07 76 6f 6c 75 6d 69 6f 22 0c 53 61 6d 70 6c 65 20 6d 6f 64 65 6c 2a 08 31 32 33 34 35 36 37 38 30 02 3a 06 08 02 10 03 18 02 42 0e 73 64 6b 2d 30 2e 37 2e 36 2d 62 33 36 32 18 01 22 25 08 01 10 02 1a 09 09 c7 e2 3d ce 92 01 00 00 30 fe ff ff ff ff ff ff ff ff 01 38 fe ff ff ff ff ff ff ff ff 01 28 01 1a 05 08 1d ea 01 00 1a 05 08 19 ca 01 00 1a 07 08 1c e2 01 02 08 05 Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.285 [17856.17856] TRACE WebsocketClient: [0x55ddc902ab60]: Binary data received, size: 111 Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.285 [17856.17856] TRACE ProtocolTracer: [0x55ddc9013180]: <= 06 6d 08 ca 04 10 e0 c5 f7 f1 ac 32 18 01 22 01 02 3a 5c 09 e0 e2 3d ce 92 01 00 00 10 c9 04 1a 07 08 2b da 02 02 08 01 1a 45 08 29 ca 02 40 08 03 10 00 1a 04 08 03 10 02 22 19 08 05 15 90 fa c4 01 1a 10 8d ef da be b1 0e 48 1d b7 ad ce 20 ba 77 9e 74 2a 19 08 06 15 92 fa c4 01 1a 10 8d ef da be b1 0e 48 1d b7 ad ce 20 ba 77 9e 74 Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.285 [17856.17856] INFO ProtocolHandler: [0x55ddc9012f90]: Received SetActive message: active Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.285 [17856.17856] INFO ProtocolHandler: [0x55ddc9012f90]: Received SetState message: Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.285 [17856.17856] INFO ProtocolHandler: [0x55ddc9012f90]: Playing state: Paused Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.285 [17856.17856] INFO ProtocolHandler: [0x55ddc9012f90]: Playback position: 0 Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.285 [17856.17856] INFO ProtocolHandler: [0x55ddc9012f90]: Queue version: 3.2 Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.285 [17856.17856] INFO ProtocolHandler: [0x55ddc9012f90]: Current track: TID: 29686416, QID: 5, Context UUID: 8defdabe-b10e-481d-b7ad-ce20ba779e74 Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.285 [17856.17856] INFO ProtocolHandler: [0x55ddc9012f90]: Next track: TID: 29686418, QID: 6, Context UUID: 8defdabe-b10e-481d-b7ad-ce20ba779e74 Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.285 [17856.17856] INFO MediaEngine: [0x55ddc9011b50]: Stopping playback Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.285 [17856.17856] DEBUG MediaEngineCommandSequencer: [0x55ddc90125c0]: Enqueuing command: Stop Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.285 [17856.17856] DEBUG MediaEngineCommandSequencer: [0x55ddc90125c0]: Enqueuing command: SetCurrentTrack Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.285 [17856.17856] DEBUG MediaEngineCommandSequencer: [0x55ddc90125c0]: Enqueuing command: SetNextTrack Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.285 [17856.17856] INFO MediaEngine: [0x55ddc9011b50]: Starting playback Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.285 [17856.17856] DEBUG MediaEngineCommandSequencer: [0x55ddc90125c0]: Enqueuing command: Play Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.285 [17856.17856] INFO MediaEngine: [0x55ddc9011b50]: Pausing playback Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.285 [17856.17856] DEBUG MediaEngineCommandSequencer: [0x55ddc90125c0]: Enqueuing command: Pause Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.285 [17856.17856] DEBUG ProtocolHandler: [0x55ddc9012f90]: Ignoring seek request to 0 because we just started a new playback Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.285 [17856.17856] INFO RendererActionAvailabilityManager: [0x55ddc9012e50]: Renderer action 'Next' is available Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.285 [17856.17856] DEBUG MediaEngineCommandSequencer: [0x55ddc90125c0]: Executing command: Stop Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.285 [17856.17856] DEBUG MediaEngine: [0x55ddc9011b50]: Executing command: Stop Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.285 [17856.17856] DEBUG MediaEngineCommandSequencer: [0x55ddc90125c0]: Confirming command: Stop Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.285 [17856.17856] DEBUG MediaEngineCommandSequencer: [0x55ddc90125c0]: Executing command: SetCurrentTrack Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.285 [17856.17856] DEBUG MediaEngine: [0x55ddc9011b50]: Executing command: SetCurrentTrack Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.285 [17856.17856] INFO MediaEngine: [0x55ddc9011b50]: Setting current track: 29686416 Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.285 [17856.17856] INFO AudioStreamManager: [0x55ddc9011cb0]: Clearing all streams Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.285 [17856.17856] INFO AudioStreamManager: [0x55ddc9011cb0]: New stream: 1 Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.285 [17856.17856] DEBUG PlaybackUrlFetcher: [0x55ddc91e2250]: Creating Playback URL Fetcher for track: 29686416 Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.285 [17856.17856] INFO HttpDownloader: [0x55ddc91da820]: Downloading content from: https://www.qobuz.com/api.json/0.2/track/getFileUrl?format_id=27&request_sig=bd22a4cb4daa22203d143b9bf0a97cb2&request_ts=1730037015&track_id=29686416 Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.285 [17856.17856] DEBUG MetadataFetcher: [0x55ddc91c5860]: Creating Metadata Fetcher for track: 29686416 Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.285 [17856.17856] INFO HttpDownloader: [0x55ddc91c20d0]: Downloading content from: https://www.qobuz.com/api.json/0.2/track/get?track_id=29686416 Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.285 [17856.17856] INFO AudioStreamManager: [0x55ddc9011cb0]: [Stream 1]: Running audio stream Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.285 [17856.17856] DEBUG MediaEngineCommandSequencer: [0x55ddc90125c0]: Confirming command: SetCurrentTrack Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.285 [17856.17856] DEBUG MediaEngineCommandSequencer: [0x55ddc90125c0]: Executing command: SetNextTrack Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.285 [17856.17856] DEBUG MediaEngine: [0x55ddc9011b50]: Executing command: SetNextTrack Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.285 [17856.17856] INFO MediaEngine: [0x55ddc9011b50]: Setting next track: 29686418 Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.285 [17856.17856] INFO AudioStreamManager: [0x55ddc9011cb0]: New stream: 2 Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.285 [17856.17856] DEBUG PlaybackUrlFetcher: [0x55ddc91bfd90]: Creating Playback URL Fetcher for track: 29686418 Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.285 [17856.17856] INFO HttpDownloader: [0x55ddc91d0b70]: Downloading content from: https://www.qobuz.com/api.json/0.2/track/getFileUrl?format_id=27&request_sig=5f21a62813b9ad7d36331f4b07a637ef&request_ts=1730037015&track_id=29686418 Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.285 [17856.17856] DEBUG MetadataFetcher: [0x55ddc916eb60]: Creating Metadata Fetcher for track: 29686418 Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.285 [17856.17856] INFO HttpDownloader: [0x55ddc91b4500]: Downloading content from: https://www.qobuz.com/api.json/0.2/track/get?track_id=29686418 Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.285 [17856.17856] DEBUG MediaEngineCommandSequencer: [0x55ddc90125c0]: Confirming command: SetNextTrack Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.285 [17856.17856] DEBUG MediaEngine: [0x55ddc9011b50]: Current stream changed state: Nonexistent -> Created Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.285 [17856.17856] DEBUG MediaEngineCommandSequencer: [0x55ddc90125c0]: Executing command: Play Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.285 [17856.17856] DEBUG MediaEngine: [0x55ddc9011b50]: Executing command: Play Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.285 [17856.17856] INFO MediaEngine: [0x55ddc9011b50]: Waiting for current stream to start before starting audio renderer Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.285 [17856.17856] DEBUG MediaEngine: [0x55ddc9011b50]: Next stream changed state: Nonexistent -> Created Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.292 [17856.17856] INFO PlaybackSessionManager: [0x55ddc9011d20]: Playback session has been refreshed Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.292 [17856.17856] TRACE PlaybackSessionManager: [0x55ddc9011d20]: Session state changed: Inactive -> Active Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.292 [17856.17856] DEBUG PlaybackSessionManager: [0x55ddc9011d20]: Playback session will be refreshed in 3540 seconds Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.292 [17856.17856] DEBUG PlaybackSessionManager: [0x55ddc9011d20]: Playback session will expire in 3600 seconds Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.292 [17856.17856] DEBUG AudioStreamInfoFetcher: [0x55ddc903f260]: Creating Audio Stream Info Fetcher for track: 29686416 Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.292 [17856.17856] INFO HttpDownloader: [0x55ddc918d9d0]: Downloading content from: https://www.qobuz.com/api.json/0.2/file/url?format_id=27&intent=stream&request_sig=c4fb181d5e6a45199426d3dca711313d&request_ts=1730037015&track_id=29686416 Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.292 [17856.17856] DEBUG AudioStreamInfoFetcher: [0x55ddc9039900]: Creating Audio Stream Info Fetcher for track: 29686418 Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.292 [17856.17856] INFO HttpDownloader: [0x55ddc917e860]: Downloading content from: https://www.qobuz.com/api.json/0.2/file/url?format_id=27&intent=stream&request_sig=ef821d48e8f278a2472ca2a189f3a02d&request_ts=1730037015&track_id=29686418 Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.448 [17856.17856] INFO AudioStreamManager: [0x55ddc9011cb0]: [Stream 2]: track URL resolved to: https://streaming-qobuz-std.akamaized.net/file?uid=789598&eid=29686418&fmt=7&profile=raw&app_id=500827169&cid=1302541&etsp=1730040615&hmac=AsCIMzbIsfGwa7KK0H8qLj7NDKA Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.474 [17856.17856] INFO AudioStreamManager: [0x55ddc9011cb0]: [Stream 1]: track URL resolved to: https://streaming-qobuz-std.akamaized.net/file?uid=789598&eid=29686416&fmt=7&profile=raw&app_id=500827169&cid=1302541&etsp=1730040615&hmac=jsA70i0Qh5D5ATYyAI42rByoVeY Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.488 [17856.17856] INFO AudioStreamManager: [0x55ddc9011cb0]: [Stream 1]: stream information have been fetched Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.488 [17856.17856] INFO UrlAudioSource: [0x55ddc9254bd0]: Starting URL audio source, URL: https://streaming-qobuz-std.akamaized.net/file?uid=789598&eid=29686416&fmt=7&profile=raw&app_id=500827169&cid=1302541&etsp=1730040615&hmac=jsA70i0Qh5D5ATYyAI42rByoVeY Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.488 [17856.17856] TRACE AudioSource: [0x55ddc9254bd0]: State changed: Idle -> Running Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.488 [17856.17856] DEBUG Ringbuffer: [0x55ddc91a1150]: Creating Audio Ringbuffer Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.488 [17856.17856] INFO ContentFetcher: [0x55ddc916d880]: Fetching content from: https://streaming-qobuz-std.akamaized.net/file?uid=789598&eid=29686416&fmt=7&profile=raw&app_id=500827169&cid=1302541&etsp=1730040615&hmac=jsA70i0Qh5D5ATYyAI42rByoVeY, offset: 0 Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.489 [17856.17856] DEBUG MediaEngine: [0x55ddc9011b50]: Current stream changed state: Created -> Info Retrieved Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.489 [17856.17856] DEBUG MediaEngine: [0x55ddc9011b50]: Current stream changed state: Info Retrieved -> Running Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.489 [17856.17856] INFO AudioRenderer: [0x55ddc9012370]: Starting audio renderer Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.489 [17856.17856] TRACE AudioRenderer: [0x55ddc9012370]: State changed: Stopped -> Starting Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.489 [17856.17856] INFO SampleApp: [Stream 1]: New audio stream Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.489 [17856.17856] TRACE SampleApp: Wrote { Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: "delegate": "audio_source_manager", Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: "function": "audio_stream_started", Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: "args": { Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: "id": 1, Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: "duration": 283061, Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: "sample_rate": 44100, Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: "channels": 2, Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: "sample_format": "S24LE" Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: } Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: } Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: on unix socket Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.489 [17856.17856] TRACE SampleApp: Wrote { Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: "delegate": "audio_renderer", Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: "function": "playback_start" Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: } Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: on unix socket Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.489 [17856.17856] DEBUG MediaEngine: [0x55ddc9011b50]: Audio renderer state changed: Stopped -> Starting Oct 27 14:50:15 volumiox86 volumio[17560]: { Oct 27 14:50:15 volumiox86 volumio[17560]: "delegate": "audio_source_manager", Oct 27 14:50:15 volumiox86 volumio[17560]: "function": "audio_stream_started", Oct 27 14:50:15 volumiox86 volumio[17560]: "args": { Oct 27 14:50:15 volumiox86 volumio[17560]: "id": 1, Oct 27 14:50:15 volumiox86 volumio[17560]: "duration": 283061, Oct 27 14:50:15 volumiox86 volumio[17560]: "sample_rate": 44100, Oct 27 14:50:15 volumiox86 volumio[17560]: "channels": 2, Oct 27 14:50:15 volumiox86 volumio[17560]: "sample_format": "S24LE" Oct 27 14:50:15 volumiox86 volumio[17560]: } Oct 27 14:50:15 volumiox86 volumio[17560]: } Oct 27 14:50:15 volumiox86 volumio[17560]: { Oct 27 14:50:15 volumiox86 volumio[17560]: "delegate": "audio_renderer", Oct 27 14:50:15 volumiox86 volumio[17560]: "function": "playback_start" Oct 27 14:50:15 volumiox86 volumio[17560]: } Oct 27 14:50:15 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioGetState Oct 27 14:50:15 volumiox86 volumio[17560]: info: CorePlayQueue::getTrack 0 Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.489 [17856.17856] TRACE MediaEngine: [0x55ddc9011b50]: State changed: Stopped -> Buffering Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.489 [17856.17856] INFO SampleApp: Playback status changed: Playing Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.489 [17856.17856] TRACE SampleApp: Wrote { Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: "delegate": "audio_renderer", Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: "function": "playback_status_changed", Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: "args": { Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: "status": "playing" Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: } Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: } Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: on unix socket Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.489 [17856.17856] DEBUG SampleApp: Audio sink is not open, returning playback position 0 Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.489 [17856.17856] TRACE SampleApp: Wrote { Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: "delegate": "audio_renderer", Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: "function": "get_playback_position", Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: "args": { Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: "position": 0, Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: "stream_id": 1 Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: } Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: } Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: on unix socket Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.489 [17856.17856] TRACE AudioRenderer: [0x55ddc9012370]: Playback position: 0 Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.489 [17856.17856] INFO ProtocolHandler: [0x55ddc9012f90]: Need to send state update Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.489 [17856.17856] INFO QConnectMessageSender: [0x55ddc9172000]: Sending StateUpdated message Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.489 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Playback state: Buffering Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.489 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Current position: 0 Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.489 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Duration: 283061 Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.489 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Queue version: 3.2 Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.489 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Current queue item ID: 5 Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.489 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Next queue item ID: 6 Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.489 [17856.17856] INFO QwspMessageSender: [0x55ddc9171fe0]: Sending Payload message Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.489 [17856.17856] TRACE QwspMessageSender: [0x55ddc9171fe0]: Protocol: QConnect Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.489 [17856.17856] TRACE QwspMessageSender: [0x55ddc9171fe0]: Channel: Backend Oct 27 14:50:15 volumiox86 volumio[17560]: info: QobuzConnect: Currently active service: mpd Oct 27 14:50:15 volumiox86 volumio[17560]: info: QobuzConnect: setActiveState() Oct 27 14:50:15 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioGetState Oct 27 14:50:15 volumiox86 volumio[17560]: info: CorePlayQueue::getTrack 0 Oct 27 14:50:15 volumiox86 volumio[17560]: info: QobuzConnect: Currently active service: mpd Oct 27 14:50:15 volumiox86 volumio[17560]: info: QobuzConnect: setActiveState(): setting Volatile state to qobuzconnect Oct 27 14:50:15 volumiox86 volumio[17560]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 27 14:50:15 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioGetState Oct 27 14:50:15 volumiox86 volumio[17560]: info: CorePlayQueue::getTrack 0 Oct 27 14:50:15 volumiox86 volumio[17560]: info: QobuzConnect: Currently active service: mpd Oct 27 14:50:15 volumiox86 volumio[17560]: info: QobuzConnect: Stopping currently active service Oct 27 14:50:15 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioStop Oct 27 14:50:15 volumiox86 volumio[17560]: info: CoreStateMachine::stop Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.489 [17856.17856] TRACE ProtocolTracer: [0x55ddc9013180]: => 06 41 08 04 10 c1 c7 f7 f1 ac 32 18 01 2a 01 02 3a 31 09 c1 e3 3d ce 92 01 00 00 10 02 1a 24 08 17 ba 01 1f 0a 1d 08 02 10 01 1a 09 09 c1 e3 3d ce 92 01 00 00 20 b5 a3 11 2a 04 08 03 10 02 30 05 38 06 Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.490 [17856.17856] TRACE PlaybackPositionEstimator: [0x55ddc9012c70]: Synced playback position: 0ms Oct 27 14:50:15 volumiox86 volumio[17560]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 27 14:50:15 volumiox86 volumio[17560]: info: CoreCommandRouter::servicePushState Oct 27 14:50:15 volumiox86 volumio[17560]: info: CoreStateMachine::pushState Oct 27 14:50:15 volumiox86 volumio[17560]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 27 14:50:15 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioPushState Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.504 [17856.17856] INFO AudioStreamManager: [0x55ddc9011cb0]: [Stream 1]: Metadata became available: Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.504 [17856.17856] INFO AudioStreamManager: [0x55ddc9011cb0]: Title: Polymorphing Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.504 [17856.17856] INFO AudioStreamManager: [0x55ddc9011cb0]: Artist: Chairlift Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.504 [17856.17856] INFO AudioStreamManager: [0x55ddc9011cb0]: Album: Moth Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.504 [17856.17856] INFO AudioStreamManager: [0x55ddc9011cb0]: Album art URL: https://static.qobuz.com/images/covers/36/12/0886445231236_600.jpg Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.504 [17856.17856] INFO SampleApp: [Stream 1]: Stream metadata became available: Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.504 [17856.17856] INFO SampleApp: Title: Polymorphing Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.504 [17856.17856] INFO SampleApp: Artist: Chairlift Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.504 [17856.17856] INFO SampleApp: Album: Moth Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.504 [17856.17856] INFO SampleApp: Album art URL: https://static.qobuz.com/images/covers/36/12/0886445231236_600.jpg Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.504 [17856.17856] TRACE SampleApp: Wrote { Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: "delegate": "audio_source_manager", Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: "function": "audio_stream_metadata", Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: "args": { Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: "id": 1, Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: "title": "Polymorphing", Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: "artist": "Chairlift", Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: "album": "Moth", Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: "album_art_url": "https://static.qobuz.com/images/covers/36/12/0886445231236_600.jpg" Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: } Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: } Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: on unix socket Oct 27 14:50:15 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioGetState Oct 27 14:50:15 volumiox86 volumio[17560]: info: MRS: Pushing multiroomSync output update for this device Oct 27 14:50:15 volumiox86 volumio[17560]: info: MRS: Pushing multiroomSync output Oct 27 14:50:15 volumiox86 volumio[17560]: info: CorePlayQueue::getTrack 0 Oct 27 14:50:15 volumiox86 volumio[17560]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current mpd Received qobuzconnect Oct 27 14:50:15 volumiox86 volumio[17560]: { Oct 27 14:50:15 volumiox86 volumio[17560]: "delegate": "audio_renderer", Oct 27 14:50:15 volumiox86 volumio[17560]: "function": "playback_status_changed", Oct 27 14:50:15 volumiox86 volumio[17560]: "args": { Oct 27 14:50:15 volumiox86 volumio[17560]: "status": "playing" Oct 27 14:50:15 volumiox86 volumio[17560]: } Oct 27 14:50:15 volumiox86 volumio[17560]: } Oct 27 14:50:15 volumiox86 volumio[17560]: info: CoreCommandRouter::servicePushState Oct 27 14:50:15 volumiox86 volumio[17560]: info: CoreStateMachine::pushState Oct 27 14:50:15 volumiox86 volumio[17560]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 27 14:50:15 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioPushState Oct 27 14:50:15 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioGetState Oct 27 14:50:15 volumiox86 volumio[17560]: info: QobuzConnect: Currently active service: qobuzconnect Oct 27 14:50:15 volumiox86 volumio[17560]: info: MRS: Pushing multiroomSync output update for this device Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.508 [17856.17856] TRACE SampleApp: nread is 44, buf is 65536 Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.508 [17856.17856] TRACE SampleApp: received {"command":"set_volume","args":{"volume":0}} Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.508 [17856.17856] DEBUG SampleApp: Received socket command: set_volume Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.508 [17856.17856] TRACE SampleApp: Command index 0: playback_start_confirm Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.508 [17856.17856] TRACE SampleApp: Command index 1: playback_pause Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.508 [17856.17856] TRACE SampleApp: Command index 2: playback_resume Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.508 [17856.17856] TRACE SampleApp: Command index 3: playback_stop Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.508 [17856.17856] TRACE SampleApp: Command index 4: playback_next_track Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.508 [17856.17856] TRACE SampleApp: Command index 5: playback_previous_track Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.508 [17856.17856] TRACE SampleApp: Command index 6: playback_seek_time Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.508 [17856.17856] TRACE SampleApp: Command index 7: set_volume Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.508 [17856.17856] DEBUG SampleApp: Executing received command set_volume Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.508 [17856.17856] INFO VolumeManager: [0x55ddc9012750]: Setting new playback volume: 0 Oct 27 14:50:15 volumiox86 volumio[17560]: info: MRS: Pushing multiroomSync output Oct 27 14:50:15 volumiox86 volumio[17560]: { Oct 27 14:50:15 volumiox86 volumio[17560]: "delegate": "audio_renderer", Oct 27 14:50:15 volumiox86 volumio[17560]: "function": "get_playback_position", Oct 27 14:50:15 volumiox86 volumio[17560]: "args": { Oct 27 14:50:15 volumiox86 volumio[17560]: "position": 0, Oct 27 14:50:15 volumiox86 volumio[17560]: "stream_id": 1 Oct 27 14:50:15 volumiox86 volumio[17560]: } Oct 27 14:50:15 volumiox86 volumio[17560]: } Oct 27 14:50:15 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioGetState Oct 27 14:50:15 volumiox86 volumio[17560]: info: QobuzConnect: Currently active service: qobuzconnect Oct 27 14:50:15 volumiox86 volumio[17560]: info: CoreCommandRouter::servicePushState Oct 27 14:50:15 volumiox86 volumio[17560]: info: CoreStateMachine::pushState Oct 27 14:50:15 volumiox86 volumio[17560]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 27 14:50:15 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioPushState Oct 27 14:50:15 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioGetState Oct 27 14:50:15 volumiox86 volumio[17560]: info: QobuzConnect: Currently active service: qobuzconnect Oct 27 14:50:15 volumiox86 volumio[17560]: info: MRS: Pushing multiroomSync output update for this device Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.510 [17856.17856] TRACE SampleApp: nread is 44, buf is 65536 Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.510 [17856.17856] TRACE SampleApp: received {"command":"set_volume","args":{"volume":0}} Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.510 [17856.17856] DEBUG SampleApp: Received socket command: set_volume Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.510 [17856.17856] TRACE SampleApp: Command index 0: playback_start_confirm Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.510 [17856.17856] TRACE SampleApp: Command index 1: playback_pause Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.510 [17856.17856] TRACE SampleApp: Command index 2: playback_resume Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.510 [17856.17856] TRACE SampleApp: Command index 3: playback_stop Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.510 [17856.17856] TRACE SampleApp: Command index 4: playback_next_track Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.510 [17856.17856] TRACE SampleApp: Command index 5: playback_previous_track Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.510 [17856.17856] TRACE SampleApp: Command index 6: playback_seek_time Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.510 [17856.17856] TRACE SampleApp: Command index 7: set_volume Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.510 [17856.17856] DEBUG SampleApp: Executing received command set_volume Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.510 [17856.17856] INFO VolumeManager: [0x55ddc9012750]: Setting new playback volume: 0 Oct 27 14:50:15 volumiox86 volumio[17560]: info: MRS: Pushing multiroomSync output Oct 27 14:50:15 volumiox86 volumio[17560]: { Oct 27 14:50:15 volumiox86 volumio[17560]: "delegate": "audio_source_manager", Oct 27 14:50:15 volumiox86 volumio[17560]: "function": "audio_stream_metadata", Oct 27 14:50:15 volumiox86 volumio[17560]: "args": { Oct 27 14:50:15 volumiox86 volumio[17560]: "id": 1, Oct 27 14:50:15 volumiox86 volumio[17560]: "title": "Polymorphing", Oct 27 14:50:15 volumiox86 volumio[17560]: "artist": "Chairlift", Oct 27 14:50:15 volumiox86 volumio[17560]: "album": "Moth", Oct 27 14:50:15 volumiox86 volumio[17560]: "album_art_url": "https://static.qobuz.com/images/covers/36/12/0886445231236_600.jpg" Oct 27 14:50:15 volumiox86 volumio[17560]: } Oct 27 14:50:15 volumiox86 volumio[17560]: } Oct 27 14:50:15 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioGetState Oct 27 14:50:15 volumiox86 volumio[17560]: info: QobuzConnect: Currently active service: qobuzconnect Oct 27 14:50:15 volumiox86 volumio[17560]: info: CoreCommandRouter::servicePushState Oct 27 14:50:15 volumiox86 volumio[17560]: info: CoreStateMachine::pushState Oct 27 14:50:15 volumiox86 volumio[17560]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 27 14:50:15 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioPushState Oct 27 14:50:15 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioGetState Oct 27 14:50:15 volumiox86 volumio[17560]: info: QobuzConnect: Currently active service: qobuzconnect Oct 27 14:50:15 volumiox86 volumio[17560]: info: MRS: Pushing multiroomSync output update for this device Oct 27 14:50:15 volumiox86 volumio[17560]: info: MRS: Pushing multiroomSync output Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.514 [17856.17856] TRACE SampleApp: nread is 44, buf is 65536 Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.515 [17856.17856] TRACE SampleApp: received {"command":"set_volume","args":{"volume":0}} Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.515 [17856.17856] DEBUG SampleApp: Received socket command: set_volume Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.515 [17856.17856] TRACE SampleApp: Command index 0: playback_start_confirm Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.515 [17856.17856] TRACE SampleApp: Command index 1: playback_pause Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.515 [17856.17856] TRACE SampleApp: Command index 2: playback_resume Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.515 [17856.17856] TRACE SampleApp: Command index 3: playback_stop Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.515 [17856.17856] TRACE SampleApp: Command index 4: playback_next_track Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.515 [17856.17856] TRACE SampleApp: Command index 5: playback_previous_track Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.515 [17856.17856] TRACE SampleApp: Command index 6: playback_seek_time Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.515 [17856.17856] TRACE SampleApp: Command index 7: set_volume Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.515 [17856.17856] DEBUG SampleApp: Executing received command set_volume Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.515 [17856.17856] INFO VolumeManager: [0x55ddc9012750]: Setting new playback volume: 0 Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.525 [17856.17856] INFO AudioStreamManager: [0x55ddc9011cb0]: [Stream 2]: stream information have been fetched Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.525 [17856.17856] DEBUG MediaEngine: [0x55ddc9011b50]: Next stream changed state: Created -> Info Retrieved Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.593 [17856.17856] INFO AudioStreamManager: [0x55ddc9011cb0]: [Stream 2]: Metadata became available: Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.593 [17856.17856] INFO AudioStreamManager: [0x55ddc9011cb0]: Title: Ch-Ching Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.593 [17856.17856] INFO AudioStreamManager: [0x55ddc9011cb0]: Artist: Chairlift Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.593 [17856.17856] INFO AudioStreamManager: [0x55ddc9011cb0]: Album: Moth Oct 27 14:50:15 volumiox86 qobuz-connect[17856]: 20241027 14:50:15.593 [17856.17856] INFO AudioStreamManager: [0x55ddc9011cb0]: Album art URL: https://static.qobuz.com/images/covers/36/12/0886445231236_600.jpg Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.008 [17856.17856] TRACE SampleApp: nread is 36, buf is 65536 Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.008 [17856.17856] TRACE SampleApp: received {"command":"playback_start_confirm"} Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.009 [17856.17856] DEBUG SampleApp: Received socket command: playback_start_confirm Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.009 [17856.17856] TRACE SampleApp: Command index 0: playback_start_confirm Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.009 [17856.17856] DEBUG SampleApp: Executing received command playback_start_confirm Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.009 [17856.17856] INFO SampleApp: Starting playback Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.010 [17856.17856] TRACE SampleApp: ALSA PCM's descriptor count: 3 Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.010 [17856.17856] DEBUG AudioRenderer: [0x55ddc9012370]: Transition to playing state (playback start) has been acknowledged Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.010 [17856.17856] TRACE AudioRenderer: [0x55ddc9012370]: State changed: Starting -> Playing Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.010 [17856.17856] TRACE SampleApp: Wrote { Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: "delegate": "audio_renderer", Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: "function": "get_playback_position", Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: "args": { Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: "position": 0, Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: "stream_id": 1 Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: } Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: } Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: on unix socket Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.011 [17856.17856] DEBUG PlaybackProgressManager: [0x55ddc90123f0]: Audio playback started, time until playback gets near the end: 273061ms Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.011 [17856.17856] DEBUG MediaEngine: [0x55ddc9011b50]: Audio renderer state changed: Starting -> Playing Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.011 [17856.17856] TRACE MediaEngine: [0x55ddc9011b50]: State changed: Buffering -> Playing Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.011 [17856.17856] DEBUG MediaEngineCommandSequencer: [0x55ddc90125c0]: Confirming command: Play Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.011 [17856.17856] DEBUG MediaEngineCommandSequencer: [0x55ddc90125c0]: Executing command: Pause Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.011 [17856.17856] DEBUG MediaEngine: [0x55ddc9011b50]: Executing command: Pause Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.011 [17856.17856] INFO AudioRenderer: [0x55ddc9012370]: Pausing audio renderer Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.011 [17856.17856] DEBUG PlaybackProgressManager: [0x55ddc90123f0]: Audio playback is paused Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.011 [17856.17856] TRACE AudioRenderer: [0x55ddc9012370]: State changed: Playing -> Pausing Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.011 [17856.17856] TRACE SampleApp: Wrote { Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: "delegate": "audio_renderer", Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: "function": "get_playback_position", Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: "args": { Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: "position": 0, Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: "stream_id": 1 Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: } Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: } Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: on unix socket Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.011 [17856.17856] TRACE AudioRenderer: [0x55ddc9012370]: Playback position: 0 Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.011 [17856.17856] INFO PlaybackEventReporter: [0x55ddc9012a10]: Reporting streaming started event Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.011 [17856.17856] TRACE PlaybackEventReporter: [0x55ddc9012a10]: Track ID: 29686416 Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.011 [17856.17856] TRACE PlaybackEventReporter: [0x55ddc9012a10]: Start position: 0ms Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.011 [17856.17856] TRACE PlaybackEventReporter: [0x55ddc9012a10]: Context UUID: 8defdabe-b10e-481d-b7ad-ce20ba779e74 Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.011 [17856.17856] TRACE PlaybackEventReporter: [0x55ddc9012a10]: Blob ID: 100000.CWdHuxDl-htOQJZFeekZcD43W3EgHQZUN35IQ5YrlfZpMUn4g40f77NB_7xWSbUS.XO5sii1buhYya8zI6mPAfLVWxug Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.011 [17856.17856] DEBUG PlaybackEventReporter: [0x55ddc9012a10]: Sending streaming reports Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.011 [17856.17856] INFO HttpDownloader: [0x55ddc9012a90]: Downloading content from: https://www.qobuz.com/api.json/0.2/track/reportStreamingStart Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.011 [17856.17856] TRACE SampleApp: Wrote { Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: "delegate": "audio_renderer", Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: "function": "get_playback_position", Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: "args": { Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: "position": 0, Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: "stream_id": 1 Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: } Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: } Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: on unix socket Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.011 [17856.17856] TRACE AudioRenderer: [0x55ddc9012370]: Playback position: 0 Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.011 [17856.17856] INFO ProtocolHandler: [0x55ddc9012f90]: Need to send state update Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.011 [17856.17856] INFO QConnectMessageSender: [0x55ddc9172000]: Sending StateUpdated message Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.011 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Playback state: Playing Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.011 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Current position: 0 Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.011 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Duration: 283061 Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.011 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Queue version: 3.2 Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.011 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Current queue item ID: 5 Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.011 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Next queue item ID: 6 Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.011 [17856.17856] INFO QwspMessageSender: [0x55ddc9171fe0]: Sending Payload message Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.011 [17856.17856] TRACE QwspMessageSender: [0x55ddc9171fe0]: Protocol: QConnect Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.011 [17856.17856] TRACE QwspMessageSender: [0x55ddc9171fe0]: Channel: Backend Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.011 [17856.17856] TRACE ProtocolTracer: [0x55ddc9013180]: => 06 41 08 05 10 cb cb f7 f1 ac 32 18 01 2a 01 02 3a 31 09 cb e5 3d ce 92 01 00 00 10 03 1a 24 08 17 ba 01 1f 0a 1d 08 02 10 02 1a 09 09 cb e5 3d ce 92 01 00 00 20 b5 a3 11 2a 04 08 03 10 02 30 05 38 06 Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.011 [17856.17856] INFO QConnectMessageSender: [0x55ddc9172000]: Sending FileAudioQualityChanged message Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.011 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Sample rate: 44100 Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.011 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Bit depth: 24 Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.011 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Channel count: 2 Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.011 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Audio quality: HIRES_L1 Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.011 [17856.17856] INFO SampleApp: Pausing playback Oct 27 14:50:16 volumiox86 volumio[17560]: { Oct 27 14:50:16 volumiox86 volumio[17560]: "delegate": "audio_renderer", Oct 27 14:50:16 volumiox86 volumio[17560]: "function": "get_playback_position", Oct 27 14:50:16 volumiox86 volumio[17560]: "args": { Oct 27 14:50:16 volumiox86 volumio[17560]: "position": 0, Oct 27 14:50:16 volumiox86 volumio[17560]: "stream_id": 1 Oct 27 14:50:16 volumiox86 volumio[17560]: } Oct 27 14:50:16 volumiox86 volumio[17560]: } Oct 27 14:50:16 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioGetState Oct 27 14:50:16 volumiox86 volumio[17560]: info: QobuzConnect: Currently active service: qobuzconnect Oct 27 14:50:16 volumiox86 volumio[17560]: info: CoreCommandRouter::servicePushState Oct 27 14:50:16 volumiox86 volumio[17560]: info: CoreStateMachine::pushState Oct 27 14:50:16 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioPushState Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.011 [17856.17856] DEBUG AudioRenderer: [0x55ddc9012370]: Transition to paused state has been acknowledged Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.011 [17856.17856] TRACE AudioRenderer: [0x55ddc9012370]: State changed: Pausing -> Paused Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.011 [17856.17856] TRACE SampleApp: Wrote { Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: "delegate": "audio_renderer", Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: "function": "playback_pause" Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: } Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: on unix socket Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.011 [17856.17856] INFO QwspMessageSender: [0x55ddc9171fe0]: Sending Payload message Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.011 [17856.17856] TRACE QwspMessageSender: [0x55ddc9171fe0]: Protocol: QConnect Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.011 [17856.17856] TRACE QwspMessageSender: [0x55ddc9171fe0]: Channel: Backend Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.012 [17856.17856] TRACE ProtocolTracer: [0x55ddc9013180]: => 06 2c 08 06 10 cb cb f7 f1 ac 32 18 01 2a 01 02 3a 1c 09 cb e5 3d ce 92 01 00 00 10 04 1a 0f 08 1a d2 01 0a 08 c4 d8 02 10 18 18 02 20 03 Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.012 [17856.17856] INFO QConnectMessageSender: [0x55ddc9172000]: Sending DeviceAudioQualityChanged message Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.012 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Sample rate: 44100 Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.012 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Bit depth: 24 Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.012 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Channel count: 2 Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.012 [17856.17856] DEBUG MediaEngine: [0x55ddc9011b50]: Audio renderer state changed: Playing -> Pausing Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.012 [17856.17856] INFO QwspMessageSender: [0x55ddc9171fe0]: Sending Payload message Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.012 [17856.17856] TRACE QwspMessageSender: [0x55ddc9171fe0]: Protocol: QConnect Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.012 [17856.17856] TRACE QwspMessageSender: [0x55ddc9171fe0]: Channel: Backend Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.012 [17856.17856] TRACE ProtocolTracer: [0x55ddc9013180]: => 06 2a 08 07 10 cc cb f7 f1 ac 32 18 01 2a 01 02 3a 1a 09 cc e5 3d ce 92 01 00 00 10 05 1a 0d 08 1b da 01 08 08 c4 d8 02 10 18 18 02 Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.012 [17856.17856] TRACE PlaybackPositionEstimator: [0x55ddc9012c70]: Synced playback position: 0ms Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.012 [17856.17856] DEBUG MediaEngine: [0x55ddc9011b50]: Audio renderer state changed: Pausing -> Paused Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.012 [17856.17856] TRACE MediaEngine: [0x55ddc9011b50]: State changed: Playing -> Paused Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.012 [17856.17856] DEBUG MediaEngineCommandSequencer: [0x55ddc90125c0]: Confirming command: Pause Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.012 [17856.17856] INFO SampleApp: Playback status changed: Paused Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.012 [17856.17856] TRACE SampleApp: Wrote { Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: "delegate": "audio_renderer", Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: "function": "playback_status_changed", Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: "args": { Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: "status": "paused" Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: } Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: } Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: on unix socket Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.012 [17856.17856] TRACE SampleApp: Wrote { Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: "delegate": "audio_renderer", Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: "function": "get_playback_position", Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: "args": { Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: "position": 0, Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: "stream_id": 1 Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: } Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: } Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: on unix socket Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.012 [17856.17856] TRACE AudioRenderer: [0x55ddc9012370]: Playback position: 0 Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.012 [17856.17856] INFO PlaybackEventReporter: [0x55ddc9012a10]: Reporting streaming ended event Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.012 [17856.17856] TRACE PlaybackEventReporter: [0x55ddc9012a10]: End position: 0ms Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.012 [17856.17856] TRACE PlaybackEventReporter: [0x55ddc9012a10]: Duration: 0ms Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.012 [17856.17856] TRACE SampleApp: Wrote { Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: "delegate": "audio_renderer", Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: "function": "get_playback_position", Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: "args": { Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: "position": 0, Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: "stream_id": 1 Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: } Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: } Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: on unix socket Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.012 [17856.17856] TRACE AudioRenderer: [0x55ddc9012370]: Playback position: 0 Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.012 [17856.17856] INFO ProtocolHandler: [0x55ddc9012f90]: Need to send state update Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.012 [17856.17856] INFO QConnectMessageSender: [0x55ddc9172000]: Sending StateUpdated message Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.012 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Playback state: Paused Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.012 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Current position: 0 Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.012 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Duration: 283061 Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.012 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Queue version: 3.2 Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.012 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Current queue item ID: 5 Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.012 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Next queue item ID: 6 Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.012 [17856.17856] INFO QwspMessageSender: [0x55ddc9171fe0]: Sending Payload message Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.012 [17856.17856] TRACE QwspMessageSender: [0x55ddc9171fe0]: Protocol: QConnect Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.012 [17856.17856] TRACE QwspMessageSender: [0x55ddc9171fe0]: Channel: Backend Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.012 [17856.17856] TRACE ProtocolTracer: [0x55ddc9013180]: => 06 41 08 08 10 cc cb f7 f1 ac 32 18 01 2a 01 02 3a 31 09 cc e5 3d ce 92 01 00 00 10 06 1a 24 08 17 ba 01 1f 0a 1d 08 03 10 02 1a 09 09 cc e5 3d ce 92 01 00 00 20 b5 a3 11 2a 04 08 03 10 02 30 05 38 06 Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.012 [17856.17856] TRACE PlaybackPositionEstimator: [0x55ddc9012c70]: Synced playback position: 0ms Oct 27 14:50:16 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioGetState Oct 27 14:50:16 volumiox86 volumio[17560]: info: QobuzConnect: Currently active service: qobuzconnect Oct 27 14:50:16 volumiox86 volumio[17560]: info: MRS: Pushing multiroomSync output update for this device Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.016 [17856.17856] TRACE SampleApp: nread is 44, buf is 65536 Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.016 [17856.17856] TRACE SampleApp: received {"command":"set_volume","args":{"volume":0}} Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.016 [17856.17856] DEBUG SampleApp: Received socket command: set_volume Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.016 [17856.17856] TRACE SampleApp: Command index 0: playback_start_confirm Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.016 [17856.17856] TRACE SampleApp: Command index 1: playback_pause Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.016 [17856.17856] TRACE SampleApp: Command index 2: playback_resume Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.016 [17856.17856] TRACE SampleApp: Command index 3: playback_stop Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.016 [17856.17856] TRACE SampleApp: Command index 4: playback_next_track Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.016 [17856.17856] TRACE SampleApp: Command index 5: playback_previous_track Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.016 [17856.17856] TRACE SampleApp: Command index 6: playback_seek_time Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.016 [17856.17856] TRACE SampleApp: Command index 7: set_volume Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.016 [17856.17856] DEBUG SampleApp: Executing received command set_volume Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.016 [17856.17856] INFO VolumeManager: [0x55ddc9012750]: Setting new playback volume: 0 Oct 27 14:50:16 volumiox86 volumio[17560]: info: MRS: Pushing multiroomSync output Oct 27 14:50:16 volumiox86 volumio[17560]: { Oct 27 14:50:16 volumiox86 volumio[17560]: "delegate": "audio_renderer", Oct 27 14:50:16 volumiox86 volumio[17560]: "function": "get_playback_position", Oct 27 14:50:16 volumiox86 volumio[17560]: "args": { Oct 27 14:50:16 volumiox86 volumio[17560]: "position": 0, Oct 27 14:50:16 volumiox86 volumio[17560]: "stream_id": 1 Oct 27 14:50:16 volumiox86 volumio[17560]: } Oct 27 14:50:16 volumiox86 volumio[17560]: } Oct 27 14:50:16 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioGetState Oct 27 14:50:16 volumiox86 volumio[17560]: info: QobuzConnect: Currently active service: qobuzconnect Oct 27 14:50:16 volumiox86 volumio[17560]: info: CoreCommandRouter::servicePushState Oct 27 14:50:16 volumiox86 volumio[17560]: info: CoreStateMachine::pushState Oct 27 14:50:16 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioPushState Oct 27 14:50:16 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioGetState Oct 27 14:50:16 volumiox86 volumio[17560]: info: QobuzConnect: Currently active service: qobuzconnect Oct 27 14:50:16 volumiox86 volumio[17560]: info: MRS: Pushing multiroomSync output update for this device Oct 27 14:50:16 volumiox86 volumio[17560]: info: MRS: Pushing multiroomSync output Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.017 [17856.17856] TRACE SampleApp: nread is 44, buf is 65536 Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.017 [17856.17856] TRACE SampleApp: received {"command":"set_volume","args":{"volume":0}} Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.017 [17856.17856] DEBUG SampleApp: Received socket command: set_volume Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.017 [17856.17856] TRACE SampleApp: Command index 0: playback_start_confirm Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.017 [17856.17856] TRACE SampleApp: Command index 1: playback_pause Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.017 [17856.17856] TRACE SampleApp: Command index 2: playback_resume Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.017 [17856.17856] TRACE SampleApp: Command index 3: playback_stop Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.017 [17856.17856] TRACE SampleApp: Command index 4: playback_next_track Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.017 [17856.17856] TRACE SampleApp: Command index 5: playback_previous_track Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.017 [17856.17856] TRACE SampleApp: Command index 6: playback_seek_time Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.017 [17856.17856] TRACE SampleApp: Command index 7: set_volume Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.017 [17856.17856] DEBUG SampleApp: Executing received command set_volume Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.017 [17856.17856] INFO VolumeManager: [0x55ddc9012750]: Setting new playback volume: 0 Oct 27 14:50:16 volumiox86 volumio[17560]: { Oct 27 14:50:16 volumiox86 volumio[17560]: "delegate": "audio_renderer", Oct 27 14:50:16 volumiox86 volumio[17560]: "function": "get_playback_position", Oct 27 14:50:16 volumiox86 volumio[17560]: "args": { Oct 27 14:50:16 volumiox86 volumio[17560]: "position": 0, Oct 27 14:50:16 volumiox86 volumio[17560]: "stream_id": 1 Oct 27 14:50:16 volumiox86 volumio[17560]: } Oct 27 14:50:16 volumiox86 volumio[17560]: } Oct 27 14:50:16 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioGetState Oct 27 14:50:16 volumiox86 volumio[17560]: info: QobuzConnect: Currently active service: qobuzconnect Oct 27 14:50:16 volumiox86 volumio[17560]: info: CoreCommandRouter::servicePushState Oct 27 14:50:16 volumiox86 volumio[17560]: info: CoreStateMachine::pushState Oct 27 14:50:16 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioPushState Oct 27 14:50:16 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioGetState Oct 27 14:50:16 volumiox86 volumio[17560]: info: QobuzConnect: Currently active service: qobuzconnect Oct 27 14:50:16 volumiox86 volumio[17560]: info: MRS: Pushing multiroomSync output update for this device Oct 27 14:50:16 volumiox86 volumio[17560]: info: MRS: Pushing multiroomSync output Oct 27 14:50:16 volumiox86 volumio[17560]: { Oct 27 14:50:16 volumiox86 volumio[17560]: "delegate": "audio_renderer", Oct 27 14:50:16 volumiox86 volumio[17560]: "function": "playback_pause" Oct 27 14:50:16 volumiox86 volumio[17560]: } Oct 27 14:50:16 volumiox86 volumio[17560]: error: QobuzConnect: Could not process JSON: no handler defined for function playback_pause Oct 27 14:50:16 volumiox86 volumio[17560]: { Oct 27 14:50:16 volumiox86 volumio[17560]: "delegate": "audio_renderer", Oct 27 14:50:16 volumiox86 volumio[17560]: "function": "playback_status_changed", Oct 27 14:50:16 volumiox86 volumio[17560]: "args": { Oct 27 14:50:16 volumiox86 volumio[17560]: "status": "paused" Oct 27 14:50:16 volumiox86 volumio[17560]: } Oct 27 14:50:16 volumiox86 volumio[17560]: } Oct 27 14:50:16 volumiox86 volumio[17560]: info: CoreCommandRouter::servicePushState Oct 27 14:50:16 volumiox86 volumio[17560]: info: CoreStateMachine::pushState Oct 27 14:50:16 volumiox86 volumio[17560]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 27 14:50:16 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioPushState Oct 27 14:50:16 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioGetState Oct 27 14:50:16 volumiox86 volumio[17560]: info: QobuzConnect: Currently active service: qobuzconnect Oct 27 14:50:16 volumiox86 volumio[17560]: info: MRS: Pushing multiroomSync output update for this device Oct 27 14:50:16 volumiox86 volumio[17560]: info: MRS: Pushing multiroomSync output Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.022 [17856.17856] TRACE SampleApp: nread is 88, buf is 65536 Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.022 [17856.17856] TRACE SampleApp: received {"command":"set_volume","args":{"volume":0}}{"command":"set_volume","args":{"volume":0}} Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.022 [17856.17856] DEBUG SampleApp: Received socket command: set_volume Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.022 [17856.17856] TRACE SampleApp: Command index 0: playback_start_confirm Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.022 [17856.17856] TRACE SampleApp: Command index 1: playback_pause Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.022 [17856.17856] TRACE SampleApp: Command index 2: playback_resume Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.022 [17856.17856] TRACE SampleApp: Command index 3: playback_stop Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.022 [17856.17856] TRACE SampleApp: Command index 4: playback_next_track Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.022 [17856.17856] TRACE SampleApp: Command index 5: playback_previous_track Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.022 [17856.17856] TRACE SampleApp: Command index 6: playback_seek_time Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.022 [17856.17856] TRACE SampleApp: Command index 7: set_volume Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.022 [17856.17856] DEBUG SampleApp: Executing received command set_volume Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.022 [17856.17856] INFO VolumeManager: [0x55ddc9012750]: Setting new playback volume: 0 Oct 27 14:50:16 volumiox86 volumio[17560]: { Oct 27 14:50:16 volumiox86 volumio[17560]: "delegate": "audio_renderer", Oct 27 14:50:16 volumiox86 volumio[17560]: "function": "get_playback_position", Oct 27 14:50:16 volumiox86 volumio[17560]: "args": { Oct 27 14:50:16 volumiox86 volumio[17560]: "position": 0, Oct 27 14:50:16 volumiox86 volumio[17560]: "stream_id": 1 Oct 27 14:50:16 volumiox86 volumio[17560]: } Oct 27 14:50:16 volumiox86 volumio[17560]: } Oct 27 14:50:16 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioGetState Oct 27 14:50:16 volumiox86 volumio[17560]: info: QobuzConnect: Currently active service: qobuzconnect Oct 27 14:50:16 volumiox86 volumio[17560]: info: CoreCommandRouter::servicePushState Oct 27 14:50:16 volumiox86 volumio[17560]: info: CoreStateMachine::pushState Oct 27 14:50:16 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioPushState Oct 27 14:50:16 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioGetState Oct 27 14:50:16 volumiox86 volumio[17560]: info: QobuzConnect: Currently active service: qobuzconnect Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.023 [17856.17856] TRACE SampleApp: nread is 44, buf is 65536 Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.023 [17856.17856] TRACE SampleApp: received {"command":"set_volume","args":{"volume":0}} Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.023 [17856.17856] DEBUG SampleApp: Received socket command: set_volume Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.023 [17856.17856] TRACE SampleApp: Command index 0: playback_start_confirm Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.023 [17856.17856] TRACE SampleApp: Command index 1: playback_pause Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.023 [17856.17856] TRACE SampleApp: Command index 2: playback_resume Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.023 [17856.17856] TRACE SampleApp: Command index 3: playback_stop Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.023 [17856.17856] TRACE SampleApp: Command index 4: playback_next_track Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.023 [17856.17856] TRACE SampleApp: Command index 5: playback_previous_track Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.023 [17856.17856] TRACE SampleApp: Command index 6: playback_seek_time Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.023 [17856.17856] TRACE SampleApp: Command index 7: set_volume Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.023 [17856.17856] DEBUG SampleApp: Executing received command set_volume Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.023 [17856.17856] INFO VolumeManager: [0x55ddc9012750]: Setting new playback volume: 0 Oct 27 14:50:16 volumiox86 volumio[17560]: info: MRS: Pushing multiroomSync output update for this device Oct 27 14:50:16 volumiox86 volumio[17560]: info: MRS: Pushing multiroomSync output Oct 27 14:50:16 volumiox86 volumio[17560]: { Oct 27 14:50:16 volumiox86 volumio[17560]: "delegate": "audio_renderer", Oct 27 14:50:16 volumiox86 volumio[17560]: "function": "get_playback_position", Oct 27 14:50:16 volumiox86 volumio[17560]: "args": { Oct 27 14:50:16 volumiox86 volumio[17560]: "position": 0, Oct 27 14:50:16 volumiox86 volumio[17560]: "stream_id": 1 Oct 27 14:50:16 volumiox86 volumio[17560]: } Oct 27 14:50:16 volumiox86 volumio[17560]: } Oct 27 14:50:16 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioGetState Oct 27 14:50:16 volumiox86 volumio[17560]: info: QobuzConnect: Currently active service: qobuzconnect Oct 27 14:50:16 volumiox86 volumio[17560]: info: CoreCommandRouter::servicePushState Oct 27 14:50:16 volumiox86 volumio[17560]: info: CoreStateMachine::pushState Oct 27 14:50:16 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioPushState Oct 27 14:50:16 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioGetState Oct 27 14:50:16 volumiox86 volumio[17560]: info: QobuzConnect: Currently active service: qobuzconnect Oct 27 14:50:16 volumiox86 volumio[17560]: info: MRS: Pushing multiroomSync output update for this device Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.024 [17856.17856] TRACE SampleApp: nread is 44, buf is 65536 Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.024 [17856.17856] TRACE SampleApp: received {"command":"set_volume","args":{"volume":0}} Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.024 [17856.17856] DEBUG SampleApp: Received socket command: set_volume Oct 27 14:50:16 volumiox86 volumio[17560]: info: MRS: Pushing multiroomSync output Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.024 [17856.17856] TRACE SampleApp: Command index 0: playback_start_confirm Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.024 [17856.17856] TRACE SampleApp: Command index 1: playback_pause Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.024 [17856.17856] TRACE SampleApp: Command index 2: playback_resume Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.024 [17856.17856] TRACE SampleApp: Command index 3: playback_stop Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.024 [17856.17856] TRACE SampleApp: Command index 4: playback_next_track Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.024 [17856.17856] TRACE SampleApp: Command index 5: playback_previous_track Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.024 [17856.17856] TRACE SampleApp: Command index 6: playback_seek_time Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.024 [17856.17856] TRACE SampleApp: Command index 7: set_volume Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.024 [17856.17856] DEBUG SampleApp: Executing received command set_volume Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.025 [17856.17856] INFO VolumeManager: [0x55ddc9012750]: Setting new playback volume: 0 Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.094 [17856.17856] DEBUG PlaybackEventReporter: [0x55ddc9012a10]: Streaming report submitted successfully Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.094 [17856.17856] DEBUG PlaybackEventReporter: [0x55ddc9012a10]: Sending streaming reports Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.094 [17856.17856] INFO HttpDownloader: [0x55ddc9012a90]: Downloading content from: https://www.qobuz.com/api.json/0.2/track/reportStreamingEndJson Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.234 [17856.17856] INFO UrlAudioSource: [0x55ddc9254bd0]: Content info extracted Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.235 [17856.17856] INFO UrlAudioSource: [0x55ddc9254bd0]: Size: 57445957 Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.236 [17856.17966] INFO AudioDecoder: [0x55ddc9294850]: Stream info: Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.236 [17856.17966] INFO AudioDecoder: [0x55ddc9294850]: Total samples: 12483029 Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.236 [17856.17966] INFO AudioDecoder: [0x55ddc9294850]: Sample rate: 44100 Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.236 [17856.17966] INFO AudioDecoder: [0x55ddc9294850]: Channel count: 2 Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.236 [17856.17966] INFO AudioDecoder: [0x55ddc9294850]: Bits per sample: 24 Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.236 [17856.17966] INFO AudioDecoder: [0x55ddc9294850]: Duration: 283061 Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.236 [17856.17856] INFO UrlAudioSource: [0x55ddc9254bd0]: Audio properties have changed Oct 27 14:50:16 volumiox86 qobuz-connect[17856]: 20241027 14:50:16.329 [17856.17856] DEBUG PlaybackEventReporter: [0x55ddc9012a10]: Streaming report submitted successfully Oct 27 14:50:17 volumiox86 volumio[17560]: info: Executing endpoint metavolumio Oct 27 14:50:17 volumiox86 volumio[17560]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Oct 27 14:50:17 volumiox86 volumio[17560]: info: Executing endpoint metavolumio Oct 27 14:50:17 volumiox86 volumio[17560]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Oct 27 14:50:17 volumiox86 volumio[17560]: info: Executing endpoint metavolumio Oct 27 14:50:17 volumiox86 volumio[17560]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.923 [17856.17856] TRACE WebsocketClient: [0x55ddc902ab60]: Binary data received, size: 40 Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.923 [17856.17856] TRACE ProtocolTracer: [0x55ddc9013180]: <= 06 26 08 d3 04 10 f0 98 f8 f1 ac 32 18 01 22 01 02 3a 15 09 70 0c 3e ce 92 01 00 00 10 d2 04 1a 07 08 29 ca 02 02 08 02 Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.923 [17856.17856] INFO ProtocolHandler: [0x55ddc9012f90]: Received SetState message: Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.923 [17856.17856] INFO ProtocolHandler: [0x55ddc9012f90]: Playing state: Playing Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.923 [17856.17856] INFO ProtocolHandler: [0x55ddc9012f90]: Playback position: Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.923 [17856.17856] INFO ProtocolHandler: [0x55ddc9012f90]: Queue version: Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.923 [17856.17856] INFO ProtocolHandler: [0x55ddc9012f90]: Current track: Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.923 [17856.17856] INFO ProtocolHandler: [0x55ddc9012f90]: Next track: Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.923 [17856.17856] INFO MediaEngine: [0x55ddc9011b50]: Resuming playback Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.923 [17856.17856] DEBUG MediaEngineCommandSequencer: [0x55ddc90125c0]: Enqueuing command: Resume Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.923 [17856.17856] DEBUG MediaEngineCommandSequencer: [0x55ddc90125c0]: Executing command: Resume Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.923 [17856.17856] DEBUG MediaEngine: [0x55ddc9011b50]: Executing command: Resume Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.923 [17856.17856] INFO AudioRenderer: [0x55ddc9012370]: Resuming audio renderer Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.923 [17856.17856] TRACE AudioRenderer: [0x55ddc9012370]: State changed: Paused -> Resuming Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.923 [17856.17856] INFO SampleApp: Resuming playback Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.923 [17856.17856] DEBUG AudioRenderer: [0x55ddc9012370]: Transition to playing state (resume) has been acknowledged Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.923 [17856.17856] TRACE AudioRenderer: [0x55ddc9012370]: State changed: Resuming -> Playing Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.923 [17856.17856] TRACE SampleApp: Wrote { Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: "delegate": "audio_renderer", Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: "function": "playback_resume" Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: } Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: on unix socket Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.924 [17856.17856] DEBUG MediaEngine: [0x55ddc9011b50]: Audio renderer state changed: Paused -> Resuming Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.924 [17856.17856] TRACE SampleApp: Wrote { Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: "delegate": "audio_renderer", Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: "function": "get_playback_position", Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: "args": { Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: "position": 0, Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: "stream_id": 1 Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: } Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: } Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: on unix socket Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.924 [17856.17856] DEBUG PlaybackProgressManager: [0x55ddc90123f0]: Audio playback started, time until playback gets near the end: 273061ms Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.924 [17856.17856] DEBUG MediaEngine: [0x55ddc9011b50]: Audio renderer state changed: Resuming -> Playing Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.924 [17856.17856] TRACE MediaEngine: [0x55ddc9011b50]: State changed: Paused -> Playing Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.924 [17856.17856] DEBUG MediaEngineCommandSequencer: [0x55ddc90125c0]: Confirming command: Resume Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.924 [17856.17856] INFO SampleApp: Playback status changed: Playing Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.924 [17856.17856] TRACE SampleApp: Wrote { Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: "delegate": "audio_renderer", Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: "function": "playback_status_changed", Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: "args": { Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: "status": "playing" Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: } Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: } Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: on unix socket Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.924 [17856.17856] TRACE SampleApp: Wrote { Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: "delegate": "audio_renderer", Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: "function": "get_playback_position", Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: "args": { Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: "position": 0, Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: "stream_id": 1 Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: } Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: } Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: on unix socket Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.924 [17856.17856] TRACE AudioRenderer: [0x55ddc9012370]: Playback position: 0 Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.924 [17856.17856] INFO PlaybackEventReporter: [0x55ddc9012a10]: Reporting streaming started event Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.924 [17856.17856] TRACE PlaybackEventReporter: [0x55ddc9012a10]: Track ID: 29686416 Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.924 [17856.17856] TRACE PlaybackEventReporter: [0x55ddc9012a10]: Start position: 0ms Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.924 [17856.17856] TRACE PlaybackEventReporter: [0x55ddc9012a10]: Context UUID: 8defdabe-b10e-481d-b7ad-ce20ba779e74 Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.924 [17856.17856] TRACE PlaybackEventReporter: [0x55ddc9012a10]: Blob ID: 100000.CWdHuxDl-htOQJZFeekZcD43W3EgHQZUN35IQ5YrlfZpMUn4g40f77NB_7xWSbUS.XO5sii1buhYya8zI6mPAfLVWxug Oct 27 14:50:25 volumiox86 volumio[17560]: { Oct 27 14:50:25 volumiox86 volumio[17560]: "delegate": "audio_renderer", Oct 27 14:50:25 volumiox86 volumio[17560]: "function": "playback_resume" Oct 27 14:50:25 volumiox86 volumio[17560]: } Oct 27 14:50:25 volumiox86 volumio[17560]: error: QobuzConnect: Could not process JSON: no handler defined for function playback_resume Oct 27 14:50:25 volumiox86 volumio[17560]: { Oct 27 14:50:25 volumiox86 volumio[17560]: "delegate": "audio_renderer", Oct 27 14:50:25 volumiox86 volumio[17560]: "function": "get_playback_position", Oct 27 14:50:25 volumiox86 volumio[17560]: "args": { Oct 27 14:50:25 volumiox86 volumio[17560]: "position": 0, Oct 27 14:50:25 volumiox86 volumio[17560]: "stream_id": 1 Oct 27 14:50:25 volumiox86 volumio[17560]: } Oct 27 14:50:25 volumiox86 volumio[17560]: } Oct 27 14:50:25 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioGetState Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.924 [17856.17856] DEBUG PlaybackEventReporter: [0x55ddc9012a10]: Sending streaming reports Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.924 [17856.17856] INFO HttpDownloader: [0x55ddc9012a90]: Downloading content from: https://www.qobuz.com/api.json/0.2/track/reportStreamingStart Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.924 [17856.17856] TRACE SampleApp: Wrote { Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: "delegate": "audio_renderer", Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: "function": "get_playback_position", Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: "args": { Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: "position": 0, Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: "stream_id": 1 Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: } Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: } Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: on unix socket Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.924 [17856.17856] TRACE AudioRenderer: [0x55ddc9012370]: Playback position: 0 Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.924 [17856.17856] INFO ProtocolHandler: [0x55ddc9012f90]: Need to send state update Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.924 [17856.17856] INFO QConnectMessageSender: [0x55ddc9172000]: Sending StateUpdated message Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.924 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Playback state: Playing Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.924 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Current position: 0 Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.924 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Duration: 283061 Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.924 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Queue version: 3.2 Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.924 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Current queue item ID: 5 Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.924 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Next queue item ID: 6 Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.929 [17856.17856] INFO QwspMessageSender: [0x55ddc9171fe0]: Sending Payload message Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.929 [17856.17856] TRACE QwspMessageSender: [0x55ddc9171fe0]: Protocol: QConnect Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.929 [17856.17856] TRACE QwspMessageSender: [0x55ddc9171fe0]: Channel: Backend Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.929 [17856.17856] TRACE ProtocolTracer: [0x55ddc9013180]: => 06 41 08 09 10 89 99 f8 f1 ac 32 18 01 2a 01 02 3a 31 09 89 0c 3e ce 92 01 00 00 10 07 1a 24 08 17 ba 01 1f 0a 1d 08 02 10 02 1a 09 09 84 0c 3e ce 92 01 00 00 20 b5 a3 11 2a 04 08 03 10 02 30 05 38 06 Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.929 [17856.17856] TRACE PlaybackPositionEstimator: [0x55ddc9012c70]: Synced playback position: 0ms Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.930 [17856.17856] TRACE PlaybackPositionEstimator: [0x55ddc9012c70]: Synced playback position: 0ms Oct 27 14:50:25 volumiox86 volumio[17560]: info: QobuzConnect: Currently active service: qobuzconnect Oct 27 14:50:25 volumiox86 volumio[17560]: info: CoreCommandRouter::servicePushState Oct 27 14:50:25 volumiox86 volumio[17560]: info: CoreStateMachine::pushState Oct 27 14:50:25 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioPushState Oct 27 14:50:25 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioGetState Oct 27 14:50:25 volumiox86 volumio[17560]: info: QobuzConnect: Currently active service: qobuzconnect Oct 27 14:50:25 volumiox86 volumio[17560]: info: MRS: Pushing multiroomSync output update for this device Oct 27 14:50:25 volumiox86 volumio[17560]: info: MRS: Pushing multiroomSync output Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.931 [17856.17856] TRACE SampleApp: nread is 44, buf is 65536 Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.931 [17856.17856] TRACE SampleApp: received {"command":"set_volume","args":{"volume":0}} Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.931 [17856.17856] DEBUG SampleApp: Received socket command: set_volume Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.931 [17856.17856] TRACE SampleApp: Command index 0: playback_start_confirm Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.931 [17856.17856] TRACE SampleApp: Command index 1: playback_pause Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.931 [17856.17856] TRACE SampleApp: Command index 2: playback_resume Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.931 [17856.17856] TRACE SampleApp: Command index 3: playback_stop Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.931 [17856.17856] TRACE SampleApp: Command index 4: playback_next_track Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.931 [17856.17856] TRACE SampleApp: Command index 5: playback_previous_track Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.931 [17856.17856] TRACE SampleApp: Command index 6: playback_seek_time Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.931 [17856.17856] TRACE SampleApp: Command index 7: set_volume Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.931 [17856.17856] DEBUG SampleApp: Executing received command set_volume Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.931 [17856.17856] INFO VolumeManager: [0x55ddc9012750]: Setting new playback volume: 0 Oct 27 14:50:25 volumiox86 volumio[17560]: { Oct 27 14:50:25 volumiox86 volumio[17560]: "delegate": "audio_renderer", Oct 27 14:50:25 volumiox86 volumio[17560]: "function": "playback_status_changed", Oct 27 14:50:25 volumiox86 volumio[17560]: "args": { Oct 27 14:50:25 volumiox86 volumio[17560]: "status": "playing" Oct 27 14:50:25 volumiox86 volumio[17560]: } Oct 27 14:50:25 volumiox86 volumio[17560]: } Oct 27 14:50:25 volumiox86 volumio[17560]: info: CoreCommandRouter::servicePushState Oct 27 14:50:25 volumiox86 volumio[17560]: info: CoreStateMachine::pushState Oct 27 14:50:25 volumiox86 volumio[17560]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 27 14:50:25 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioPushState Oct 27 14:50:25 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioGetState Oct 27 14:50:25 volumiox86 volumio[17560]: info: QobuzConnect: Currently active service: qobuzconnect Oct 27 14:50:25 volumiox86 volumio[17560]: info: MRS: Pushing multiroomSync output update for this device Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.932 [17856.17856] TRACE SampleApp: nread is 44, buf is 65536 Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.932 [17856.17856] TRACE SampleApp: received {"command":"set_volume","args":{"volume":0}} Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.932 [17856.17856] DEBUG SampleApp: Received socket command: set_volume Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.932 [17856.17856] TRACE SampleApp: Command index 0: playback_start_confirm Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.932 [17856.17856] TRACE SampleApp: Command index 1: playback_pause Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.932 [17856.17856] TRACE SampleApp: Command index 2: playback_resume Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.932 [17856.17856] TRACE SampleApp: Command index 3: playback_stop Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.932 [17856.17856] TRACE SampleApp: Command index 4: playback_next_track Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.932 [17856.17856] TRACE SampleApp: Command index 5: playback_previous_track Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.932 [17856.17856] TRACE SampleApp: Command index 6: playback_seek_time Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.932 [17856.17856] TRACE SampleApp: Command index 7: set_volume Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.932 [17856.17856] DEBUG SampleApp: Executing received command set_volume Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.932 [17856.17856] INFO VolumeManager: [0x55ddc9012750]: Setting new playback volume: 0 Oct 27 14:50:25 volumiox86 volumio[17560]: info: MRS: Pushing multiroomSync output Oct 27 14:50:25 volumiox86 volumio[17560]: { Oct 27 14:50:25 volumiox86 volumio[17560]: "delegate": "audio_renderer", Oct 27 14:50:25 volumiox86 volumio[17560]: "function": "get_playback_position", Oct 27 14:50:25 volumiox86 volumio[17560]: "args": { Oct 27 14:50:25 volumiox86 volumio[17560]: "position": 0, Oct 27 14:50:25 volumiox86 volumio[17560]: "stream_id": 1 Oct 27 14:50:25 volumiox86 volumio[17560]: } Oct 27 14:50:25 volumiox86 volumio[17560]: } Oct 27 14:50:25 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioGetState Oct 27 14:50:25 volumiox86 volumio[17560]: info: QobuzConnect: Currently active service: qobuzconnect Oct 27 14:50:25 volumiox86 volumio[17560]: info: CoreCommandRouter::servicePushState Oct 27 14:50:25 volumiox86 volumio[17560]: info: CoreStateMachine::pushState Oct 27 14:50:25 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioPushState Oct 27 14:50:25 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioGetState Oct 27 14:50:25 volumiox86 volumio[17560]: info: QobuzConnect: Currently active service: qobuzconnect Oct 27 14:50:25 volumiox86 volumio[17560]: info: MRS: Pushing multiroomSync output update for this device Oct 27 14:50:25 volumiox86 volumio[17560]: info: MRS: Pushing multiroomSync output Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.932 [17856.17856] TRACE SampleApp: nread is 44, buf is 65536 Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.932 [17856.17856] TRACE SampleApp: received {"command":"set_volume","args":{"volume":0}} Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.932 [17856.17856] DEBUG SampleApp: Received socket command: set_volume Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.932 [17856.17856] TRACE SampleApp: Command index 0: playback_start_confirm Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.932 [17856.17856] TRACE SampleApp: Command index 1: playback_pause Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.932 [17856.17856] TRACE SampleApp: Command index 2: playback_resume Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.932 [17856.17856] TRACE SampleApp: Command index 3: playback_stop Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.932 [17856.17856] TRACE SampleApp: Command index 4: playback_next_track Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.932 [17856.17856] TRACE SampleApp: Command index 5: playback_previous_track Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.932 [17856.17856] TRACE SampleApp: Command index 6: playback_seek_time Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.932 [17856.17856] TRACE SampleApp: Command index 7: set_volume Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.932 [17856.17856] DEBUG SampleApp: Executing received command set_volume Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.932 [17856.17856] INFO VolumeManager: [0x55ddc9012750]: Setting new playback volume: 0 Oct 27 14:50:25 volumiox86 volumio[17560]: { Oct 27 14:50:25 volumiox86 volumio[17560]: "delegate": "audio_renderer", Oct 27 14:50:25 volumiox86 volumio[17560]: "function": "get_playback_position", Oct 27 14:50:25 volumiox86 volumio[17560]: "args": { Oct 27 14:50:25 volumiox86 volumio[17560]: "position": 0, Oct 27 14:50:25 volumiox86 volumio[17560]: "stream_id": 1 Oct 27 14:50:25 volumiox86 volumio[17560]: } Oct 27 14:50:25 volumiox86 volumio[17560]: } Oct 27 14:50:25 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioGetState Oct 27 14:50:25 volumiox86 volumio[17560]: info: QobuzConnect: Currently active service: qobuzconnect Oct 27 14:50:25 volumiox86 volumio[17560]: info: CoreCommandRouter::servicePushState Oct 27 14:50:25 volumiox86 volumio[17560]: info: CoreStateMachine::pushState Oct 27 14:50:25 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioPushState Oct 27 14:50:25 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioGetState Oct 27 14:50:25 volumiox86 volumio[17560]: info: QobuzConnect: Currently active service: qobuzconnect Oct 27 14:50:25 volumiox86 volumio[17560]: info: MRS: Pushing multiroomSync output update for this device Oct 27 14:50:25 volumiox86 volumio[17560]: info: MRS: Pushing multiroomSync output Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.933 [17856.17856] TRACE SampleApp: nread is 44, buf is 65536 Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.933 [17856.17856] TRACE SampleApp: received {"command":"set_volume","args":{"volume":0}} Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.933 [17856.17856] DEBUG SampleApp: Received socket command: set_volume Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.933 [17856.17856] TRACE SampleApp: Command index 0: playback_start_confirm Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.933 [17856.17856] TRACE SampleApp: Command index 1: playback_pause Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.933 [17856.17856] TRACE SampleApp: Command index 2: playback_resume Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.933 [17856.17856] TRACE SampleApp: Command index 3: playback_stop Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.933 [17856.17856] TRACE SampleApp: Command index 4: playback_next_track Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.933 [17856.17856] TRACE SampleApp: Command index 5: playback_previous_track Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.933 [17856.17856] TRACE SampleApp: Command index 6: playback_seek_time Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.933 [17856.17856] TRACE SampleApp: Command index 7: set_volume Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.933 [17856.17856] DEBUG SampleApp: Executing received command set_volume Oct 27 14:50:25 volumiox86 qobuz-connect[17856]: 20241027 14:50:25.933 [17856.17856] INFO VolumeManager: [0x55ddc9012750]: Setting new playback volume: 0 Oct 27 14:50:26 volumiox86 qobuz-connect[17856]: 20241027 14:50:26.036 [17856.17856] DEBUG PlaybackEventReporter: [0x55ddc9012a10]: Streaming report submitted successfully Oct 27 14:50:35 volumiox86 qobuz-connect[17856]: 20241027 14:50:35.924 [17856.17856] TRACE SampleApp: Wrote { Oct 27 14:50:35 volumiox86 qobuz-connect[17856]: "delegate": "audio_renderer", Oct 27 14:50:35 volumiox86 qobuz-connect[17856]: "function": "get_playback_position", Oct 27 14:50:35 volumiox86 qobuz-connect[17856]: "args": { Oct 27 14:50:35 volumiox86 qobuz-connect[17856]: "position": 9970, Oct 27 14:50:35 volumiox86 qobuz-connect[17856]: "stream_id": 1 Oct 27 14:50:35 volumiox86 qobuz-connect[17856]: } Oct 27 14:50:35 volumiox86 qobuz-connect[17856]: } Oct 27 14:50:35 volumiox86 qobuz-connect[17856]: on unix socket Oct 27 14:50:35 volumiox86 qobuz-connect[17856]: 20241027 14:50:35.924 [17856.17856] TRACE AudioRenderer: [0x55ddc9012370]: Playback position: 9970 Oct 27 14:50:35 volumiox86 qobuz-connect[17856]: 20241027 14:50:35.924 [17856.17856] INFO ProtocolHandler: [0x55ddc9012f90]: Need to send state update Oct 27 14:50:35 volumiox86 qobuz-connect[17856]: 20241027 14:50:35.924 [17856.17856] INFO QConnectMessageSender: [0x55ddc9172000]: Sending StateUpdated message Oct 27 14:50:35 volumiox86 qobuz-connect[17856]: 20241027 14:50:35.924 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Playback state: Playing Oct 27 14:50:35 volumiox86 qobuz-connect[17856]: 20241027 14:50:35.924 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Current position: 9970 Oct 27 14:50:35 volumiox86 qobuz-connect[17856]: 20241027 14:50:35.924 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Duration: 283061 Oct 27 14:50:35 volumiox86 qobuz-connect[17856]: 20241027 14:50:35.924 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Queue version: 3.2 Oct 27 14:50:35 volumiox86 qobuz-connect[17856]: 20241027 14:50:35.924 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Current queue item ID: 5 Oct 27 14:50:35 volumiox86 qobuz-connect[17856]: 20241027 14:50:35.924 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Next queue item ID: 6 Oct 27 14:50:35 volumiox86 qobuz-connect[17856]: 20241027 14:50:35.924 [17856.17856] INFO QwspMessageSender: [0x55ddc9171fe0]: Sending Payload message Oct 27 14:50:35 volumiox86 qobuz-connect[17856]: 20241027 14:50:35.924 [17856.17856] TRACE QwspMessageSender: [0x55ddc9171fe0]: Protocol: QConnect Oct 27 14:50:35 volumiox86 qobuz-connect[17856]: 20241027 14:50:35.924 [17856.17856] TRACE QwspMessageSender: [0x55ddc9171fe0]: Channel: Backend Oct 27 14:50:35 volumiox86 qobuz-connect[17856]: 20241027 14:50:35.924 [17856.17856] TRACE ProtocolTracer: [0x55ddc9013180]: => 06 44 08 0a 10 94 e7 f8 f1 ac 32 18 01 2a 01 02 3a 34 09 94 33 3e ce 92 01 00 00 10 08 1a 27 08 17 ba 01 22 0a 20 08 02 10 02 1a 0c 09 94 33 3e ce 92 01 00 00 10 f2 4d 20 b5 a3 11 2a 04 08 03 10 02 30 05 38 06 Oct 27 14:50:35 volumiox86 qobuz-connect[17856]: 20241027 14:50:35.924 [17856.17856] TRACE PlaybackPositionEstimator: [0x55ddc9012c70]: Synced playback position: 9970ms Oct 27 14:50:35 volumiox86 volumio[17560]: { Oct 27 14:50:35 volumiox86 volumio[17560]: "delegate": "audio_renderer", Oct 27 14:50:35 volumiox86 volumio[17560]: "function": "get_playback_position", Oct 27 14:50:35 volumiox86 volumio[17560]: "args": { Oct 27 14:50:35 volumiox86 volumio[17560]: "position": 9970, Oct 27 14:50:35 volumiox86 volumio[17560]: "stream_id": 1 Oct 27 14:50:35 volumiox86 volumio[17560]: } Oct 27 14:50:35 volumiox86 volumio[17560]: } Oct 27 14:50:35 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioGetState Oct 27 14:50:35 volumiox86 volumio[17560]: info: QobuzConnect: Currently active service: qobuzconnect Oct 27 14:50:35 volumiox86 volumio[17560]: info: CoreCommandRouter::servicePushState Oct 27 14:50:35 volumiox86 volumio[17560]: info: CoreStateMachine::pushState Oct 27 14:50:35 volumiox86 volumio[17560]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 27 14:50:35 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioPushState Oct 27 14:50:35 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioGetState Oct 27 14:50:35 volumiox86 volumio[17560]: info: QobuzConnect: Currently active service: qobuzconnect Oct 27 14:50:35 volumiox86 volumio[17560]: info: MRS: Pushing multiroomSync output update for this device Oct 27 14:50:35 volumiox86 volumio[17560]: info: MRS: Pushing multiroomSync output Oct 27 14:50:35 volumiox86 qobuz-connect[17856]: 20241027 14:50:35.932 [17856.17856] TRACE SampleApp: nread is 44, buf is 65536 Oct 27 14:50:35 volumiox86 qobuz-connect[17856]: 20241027 14:50:35.932 [17856.17856] TRACE SampleApp: received {"command":"set_volume","args":{"volume":0}} Oct 27 14:50:35 volumiox86 qobuz-connect[17856]: 20241027 14:50:35.932 [17856.17856] DEBUG SampleApp: Received socket command: set_volume Oct 27 14:50:35 volumiox86 qobuz-connect[17856]: 20241027 14:50:35.932 [17856.17856] TRACE SampleApp: Command index 0: playback_start_confirm Oct 27 14:50:35 volumiox86 qobuz-connect[17856]: 20241027 14:50:35.932 [17856.17856] TRACE SampleApp: Command index 1: playback_pause Oct 27 14:50:35 volumiox86 qobuz-connect[17856]: 20241027 14:50:35.932 [17856.17856] TRACE SampleApp: Command index 2: playback_resume Oct 27 14:50:35 volumiox86 qobuz-connect[17856]: 20241027 14:50:35.932 [17856.17856] TRACE SampleApp: Command index 3: playback_stop Oct 27 14:50:35 volumiox86 qobuz-connect[17856]: 20241027 14:50:35.932 [17856.17856] TRACE SampleApp: Command index 4: playback_next_track Oct 27 14:50:35 volumiox86 qobuz-connect[17856]: 20241027 14:50:35.932 [17856.17856] TRACE SampleApp: Command index 5: playback_previous_track Oct 27 14:50:35 volumiox86 qobuz-connect[17856]: 20241027 14:50:35.932 [17856.17856] TRACE SampleApp: Command index 6: playback_seek_time Oct 27 14:50:35 volumiox86 qobuz-connect[17856]: 20241027 14:50:35.932 [17856.17856] TRACE SampleApp: Command index 7: set_volume Oct 27 14:50:35 volumiox86 qobuz-connect[17856]: 20241027 14:50:35.932 [17856.17856] DEBUG SampleApp: Executing received command set_volume Oct 27 14:50:35 volumiox86 qobuz-connect[17856]: 20241027 14:50:35.933 [17856.17856] INFO VolumeManager: [0x55ddc9012750]: Setting new playback volume: 0 Oct 27 14:50:37 volumiox86 volumio[17560]: info: VolumeController::SetAlsaVolume21 Oct 27 14:50:37 volumiox86 volumio[17560]: info: CoreStateMachine::pushState Oct 27 14:50:37 volumiox86 volumio[17560]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 27 14:50:37 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioPushState Oct 27 14:50:37 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioGetState Oct 27 14:50:37 volumiox86 volumio[17560]: info: QobuzConnect: Currently active service: qobuzconnect Oct 27 14:50:37 volumiox86 volumio[17560]: info: MRS: Pushing multiroomSync output update for this device Oct 27 14:50:37 volumiox86 qobuz-connect[17856]: 20241027 14:50:37.025 [17856.17856] TRACE SampleApp: nread is 45, buf is 65536 Oct 27 14:50:37 volumiox86 qobuz-connect[17856]: 20241027 14:50:37.026 [17856.17856] TRACE SampleApp: received {"command":"set_volume","args":{"volume":21}} Oct 27 14:50:37 volumiox86 qobuz-connect[17856]: 20241027 14:50:37.026 [17856.17856] DEBUG SampleApp: Received socket command: set_volume Oct 27 14:50:37 volumiox86 qobuz-connect[17856]: 20241027 14:50:37.026 [17856.17856] TRACE SampleApp: Command index 0: playback_start_confirm Oct 27 14:50:37 volumiox86 qobuz-connect[17856]: 20241027 14:50:37.026 [17856.17856] TRACE SampleApp: Command index 1: playback_pause Oct 27 14:50:37 volumiox86 qobuz-connect[17856]: 20241027 14:50:37.026 [17856.17856] TRACE SampleApp: Command index 2: playback_resume Oct 27 14:50:37 volumiox86 qobuz-connect[17856]: 20241027 14:50:37.026 [17856.17856] TRACE SampleApp: Command index 3: playback_stop Oct 27 14:50:37 volumiox86 qobuz-connect[17856]: 20241027 14:50:37.026 [17856.17856] TRACE SampleApp: Command index 4: playback_next_track Oct 27 14:50:37 volumiox86 qobuz-connect[17856]: 20241027 14:50:37.026 [17856.17856] TRACE SampleApp: Command index 5: playback_previous_track Oct 27 14:50:37 volumiox86 qobuz-connect[17856]: 20241027 14:50:37.026 [17856.17856] TRACE SampleApp: Command index 6: playback_seek_time Oct 27 14:50:37 volumiox86 qobuz-connect[17856]: 20241027 14:50:37.026 [17856.17856] TRACE SampleApp: Command index 7: set_volume Oct 27 14:50:37 volumiox86 qobuz-connect[17856]: 20241027 14:50:37.026 [17856.17856] DEBUG SampleApp: Executing received command set_volume Oct 27 14:50:37 volumiox86 qobuz-connect[17856]: 20241027 14:50:37.026 [17856.17856] INFO VolumeManager: [0x55ddc9012750]: Setting new playback volume: 21 Oct 27 14:50:37 volumiox86 volumio[17560]: info: MRS: Pushing multiroomSync output Oct 27 14:50:37 volumiox86 volumio[17560]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: No protocol specified Oct 27 14:50:37 volumiox86 volumio[17560]: xcb_connection_has_error() returned true Oct 27 14:50:37 volumiox86 qobuz-connect[17856]: 20241027 14:50:37.175 [17856.17856] INFO SampleApp: Playback volume changed: 21 Oct 27 14:50:37 volumiox86 qobuz-connect[17856]: 20241027 14:50:37.175 [17856.17856] TRACE SampleApp: Setting volume: 21 Oct 27 14:50:37 volumiox86 qobuz-connect[17856]: 20241027 14:50:37.175 [17856.17856] TRACE SampleApp: Wrote { Oct 27 14:50:37 volumiox86 qobuz-connect[17856]: "delegate": "audio_renderer", Oct 27 14:50:37 volumiox86 qobuz-connect[17856]: "function": "playback_volume_changed", Oct 27 14:50:37 volumiox86 qobuz-connect[17856]: "args": { Oct 27 14:50:37 volumiox86 qobuz-connect[17856]: "volume": 21 Oct 27 14:50:37 volumiox86 qobuz-connect[17856]: } Oct 27 14:50:37 volumiox86 qobuz-connect[17856]: } Oct 27 14:50:37 volumiox86 qobuz-connect[17856]: on unix socket Oct 27 14:50:37 volumiox86 qobuz-connect[17856]: 20241027 14:50:37.175 [17856.17856] INFO ProtocolHandler: [0x55ddc9012f90]: Volume changed: 21 Oct 27 14:50:37 volumiox86 qobuz-connect[17856]: 20241027 14:50:37.175 [17856.17856] INFO QConnectMessageSender: [0x55ddc9172000]: Sending VolumeChanged message Oct 27 14:50:37 volumiox86 qobuz-connect[17856]: 20241027 14:50:37.175 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Volume: 21 Oct 27 14:50:37 volumiox86 qobuz-connect[17856]: 20241027 14:50:37.175 [17856.17856] INFO QwspMessageSender: [0x55ddc9171fe0]: Sending Payload message Oct 27 14:50:37 volumiox86 qobuz-connect[17856]: 20241027 14:50:37.175 [17856.17856] TRACE QwspMessageSender: [0x55ddc9171fe0]: Protocol: QConnect Oct 27 14:50:37 volumiox86 qobuz-connect[17856]: 20241027 14:50:37.175 [17856.17856] TRACE QwspMessageSender: [0x55ddc9171fe0]: Channel: Backend Oct 27 14:50:37 volumiox86 qobuz-connect[17856]: 20241027 14:50:37.175 [17856.17856] TRACE ProtocolTracer: [0x55ddc9013180]: => 06 24 08 0b 10 f7 f0 f8 f1 ac 32 18 01 2a 01 02 3a 14 09 77 38 3e ce 92 01 00 00 10 09 1a 07 08 19 ca 01 02 08 15 Oct 27 14:50:37 volumiox86 volumio[17560]: { Oct 27 14:50:37 volumiox86 volumio[17560]: "delegate": "audio_renderer", Oct 27 14:50:37 volumiox86 volumio[17560]: "function": "playback_volume_changed", Oct 27 14:50:37 volumiox86 volumio[17560]: "args": { Oct 27 14:50:37 volumiox86 volumio[17560]: "volume": 21 Oct 27 14:50:37 volumiox86 volumio[17560]: } Oct 27 14:50:37 volumiox86 volumio[17560]: } Oct 27 14:50:37 volumiox86 volumio[17560]: info: QobuzConnect: Volume: 21 Oct 27 14:50:37 volumiox86 volumio[17560]: info: VolumeController::SetAlsaVolume21 Oct 27 14:50:37 volumiox86 volumio[17560]: info: CoreStateMachine::pushState Oct 27 14:50:37 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioPushState Oct 27 14:50:37 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioGetState Oct 27 14:50:37 volumiox86 volumio[17560]: info: QobuzConnect: Currently active service: qobuzconnect Oct 27 14:50:37 volumiox86 volumio[17560]: info: MRS: Pushing multiroomSync output update for this device Oct 27 14:50:37 volumiox86 volumio[17560]: info: MRS: Pushing multiroomSync output Oct 27 14:50:37 volumiox86 volumio[17560]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: No protocol specified Oct 27 14:50:37 volumiox86 volumio[17560]: xcb_connection_has_error() returned true Oct 27 14:50:37 volumiox86 volumio[17560]: info: VolumeController::SetAlsaVolume38 Oct 27 14:50:37 volumiox86 volumio[17560]: info: CoreStateMachine::pushState Oct 27 14:50:37 volumiox86 volumio[17560]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 27 14:50:37 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioPushState Oct 27 14:50:37 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioGetState Oct 27 14:50:37 volumiox86 volumio[17560]: info: QobuzConnect: Currently active service: qobuzconnect Oct 27 14:50:37 volumiox86 volumio[17560]: info: MRS: Pushing multiroomSync output update for this device Oct 27 14:50:37 volumiox86 volumio[17560]: info: MRS: Pushing multiroomSync output Oct 27 14:50:37 volumiox86 volumio[17560]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: No protocol specified Oct 27 14:50:37 volumiox86 volumio[17560]: xcb_connection_has_error() returned true Oct 27 14:50:38 volumiox86 volumio[17560]: info: VolumeController::SetAlsaVolume67 Oct 27 14:50:38 volumiox86 volumio[17560]: info: CoreStateMachine::pushState Oct 27 14:50:38 volumiox86 volumio[17560]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 27 14:50:38 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioPushState Oct 27 14:50:38 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioGetState Oct 27 14:50:38 volumiox86 volumio[17560]: info: QobuzConnect: Currently active service: qobuzconnect Oct 27 14:50:38 volumiox86 volumio[17560]: info: MRS: Pushing multiroomSync output update for this device Oct 27 14:50:38 volumiox86 volumio[17560]: info: MRS: Pushing multiroomSync output Oct 27 14:50:38 volumiox86 volumio[17560]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: No protocol specified Oct 27 14:50:38 volumiox86 volumio[17560]: xcb_connection_has_error() returned true Oct 27 14:50:45 volumiox86 qobuz-connect[17856]: 20241027 14:50:45.924 [17856.17856] TRACE SampleApp: Wrote { Oct 27 14:50:45 volumiox86 qobuz-connect[17856]: "delegate": "audio_renderer", Oct 27 14:50:45 volumiox86 qobuz-connect[17856]: "function": "get_playback_position", Oct 27 14:50:45 volumiox86 qobuz-connect[17856]: "args": { Oct 27 14:50:45 volumiox86 qobuz-connect[17856]: "position": 19969, Oct 27 14:50:45 volumiox86 qobuz-connect[17856]: "stream_id": 1 Oct 27 14:50:45 volumiox86 qobuz-connect[17856]: } Oct 27 14:50:45 volumiox86 qobuz-connect[17856]: } Oct 27 14:50:45 volumiox86 qobuz-connect[17856]: on unix socket Oct 27 14:50:45 volumiox86 qobuz-connect[17856]: 20241027 14:50:45.924 [17856.17856] TRACE AudioRenderer: [0x55ddc9012370]: Playback position: 19969 Oct 27 14:50:45 volumiox86 qobuz-connect[17856]: 20241027 14:50:45.924 [17856.17856] INFO ProtocolHandler: [0x55ddc9012f90]: Need to send state update Oct 27 14:50:45 volumiox86 qobuz-connect[17856]: 20241027 14:50:45.924 [17856.17856] INFO QConnectMessageSender: [0x55ddc9172000]: Sending StateUpdated message Oct 27 14:50:45 volumiox86 qobuz-connect[17856]: 20241027 14:50:45.924 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Playback state: Playing Oct 27 14:50:45 volumiox86 qobuz-connect[17856]: 20241027 14:50:45.924 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Current position: 19969 Oct 27 14:50:45 volumiox86 qobuz-connect[17856]: 20241027 14:50:45.924 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Duration: 283061 Oct 27 14:50:45 volumiox86 qobuz-connect[17856]: 20241027 14:50:45.924 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Queue version: 3.2 Oct 27 14:50:45 volumiox86 qobuz-connect[17856]: 20241027 14:50:45.924 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Current queue item ID: 5 Oct 27 14:50:45 volumiox86 qobuz-connect[17856]: 20241027 14:50:45.924 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Next queue item ID: 6 Oct 27 14:50:45 volumiox86 qobuz-connect[17856]: 20241027 14:50:45.924 [17856.17856] INFO QwspMessageSender: [0x55ddc9171fe0]: Sending Payload message Oct 27 14:50:45 volumiox86 qobuz-connect[17856]: 20241027 14:50:45.924 [17856.17856] TRACE QwspMessageSender: [0x55ddc9171fe0]: Protocol: QConnect Oct 27 14:50:45 volumiox86 qobuz-connect[17856]: 20241027 14:50:45.924 [17856.17856] TRACE QwspMessageSender: [0x55ddc9171fe0]: Channel: Backend Oct 27 14:50:45 volumiox86 qobuz-connect[17856]: 20241027 14:50:45.924 [17856.17856] TRACE ProtocolTracer: [0x55ddc9013180]: => 06 45 08 0c 10 a4 b5 f9 f1 ac 32 18 01 2a 01 02 3a 35 09 a4 5a 3e ce 92 01 00 00 10 0a 1a 28 08 17 ba 01 23 0a 21 08 02 10 02 1a 0d 09 a4 5a 3e ce 92 01 00 00 10 81 9c 01 20 b5 a3 11 2a 04 08 03 10 02 30 05 38 06 Oct 27 14:50:45 volumiox86 qobuz-connect[17856]: 20241027 14:50:45.924 [17856.17856] TRACE PlaybackPositionEstimator: [0x55ddc9012c70]: Synced playback position: 19969ms Oct 27 14:50:45 volumiox86 volumio[17560]: { Oct 27 14:50:45 volumiox86 volumio[17560]: "delegate": "audio_renderer", Oct 27 14:50:45 volumiox86 volumio[17560]: "function": "get_playback_position", Oct 27 14:50:45 volumiox86 volumio[17560]: "args": { Oct 27 14:50:45 volumiox86 volumio[17560]: "position": 19969, Oct 27 14:50:45 volumiox86 volumio[17560]: "stream_id": 1 Oct 27 14:50:45 volumiox86 volumio[17560]: } Oct 27 14:50:45 volumiox86 volumio[17560]: } Oct 27 14:50:45 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioGetState Oct 27 14:50:45 volumiox86 volumio[17560]: info: QobuzConnect: Currently active service: qobuzconnect Oct 27 14:50:45 volumiox86 volumio[17560]: info: CoreCommandRouter::servicePushState Oct 27 14:50:45 volumiox86 volumio[17560]: info: CoreStateMachine::pushState Oct 27 14:50:45 volumiox86 volumio[17560]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 27 14:50:45 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioPushState Oct 27 14:50:45 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioGetState Oct 27 14:50:45 volumiox86 volumio[17560]: info: QobuzConnect: Currently active service: qobuzconnect Oct 27 14:50:45 volumiox86 volumio[17560]: info: MRS: Pushing multiroomSync output update for this device Oct 27 14:50:45 volumiox86 volumio[17560]: info: MRS: Pushing multiroomSync output Oct 27 14:50:45 volumiox86 qobuz-connect[17856]: 20241027 14:50:45.929 [17856.17856] TRACE SampleApp: nread is 45, buf is 65536 Oct 27 14:50:45 volumiox86 qobuz-connect[17856]: 20241027 14:50:45.930 [17856.17856] TRACE SampleApp: received {"command":"set_volume","args":{"volume":67}} Oct 27 14:50:45 volumiox86 qobuz-connect[17856]: 20241027 14:50:45.930 [17856.17856] DEBUG SampleApp: Received socket command: set_volume Oct 27 14:50:45 volumiox86 qobuz-connect[17856]: 20241027 14:50:45.930 [17856.17856] TRACE SampleApp: Command index 0: playback_start_confirm Oct 27 14:50:45 volumiox86 qobuz-connect[17856]: 20241027 14:50:45.930 [17856.17856] TRACE SampleApp: Command index 1: playback_pause Oct 27 14:50:45 volumiox86 qobuz-connect[17856]: 20241027 14:50:45.930 [17856.17856] TRACE SampleApp: Command index 2: playback_resume Oct 27 14:50:45 volumiox86 qobuz-connect[17856]: 20241027 14:50:45.930 [17856.17856] TRACE SampleApp: Command index 3: playback_stop Oct 27 14:50:45 volumiox86 qobuz-connect[17856]: 20241027 14:50:45.930 [17856.17856] TRACE SampleApp: Command index 4: playback_next_track Oct 27 14:50:45 volumiox86 qobuz-connect[17856]: 20241027 14:50:45.930 [17856.17856] TRACE SampleApp: Command index 5: playback_previous_track Oct 27 14:50:45 volumiox86 qobuz-connect[17856]: 20241027 14:50:45.930 [17856.17856] TRACE SampleApp: Command index 6: playback_seek_time Oct 27 14:50:45 volumiox86 qobuz-connect[17856]: 20241027 14:50:45.930 [17856.17856] TRACE SampleApp: Command index 7: set_volume Oct 27 14:50:45 volumiox86 qobuz-connect[17856]: 20241027 14:50:45.930 [17856.17856] DEBUG SampleApp: Executing received command set_volume Oct 27 14:50:45 volumiox86 qobuz-connect[17856]: 20241027 14:50:45.930 [17856.17856] INFO VolumeManager: [0x55ddc9012750]: Setting new playback volume: 67 Oct 27 14:50:46 volumiox86 qobuz-connect[17856]: 20241027 14:50:46.079 [17856.17856] INFO SampleApp: Playback volume changed: 67 Oct 27 14:50:46 volumiox86 qobuz-connect[17856]: 20241027 14:50:46.079 [17856.17856] TRACE SampleApp: Setting volume: 67 Oct 27 14:50:46 volumiox86 qobuz-connect[17856]: 20241027 14:50:46.079 [17856.17856] TRACE SampleApp: Wrote { Oct 27 14:50:46 volumiox86 qobuz-connect[17856]: "delegate": "audio_renderer", Oct 27 14:50:46 volumiox86 qobuz-connect[17856]: "function": "playback_volume_changed", Oct 27 14:50:46 volumiox86 qobuz-connect[17856]: "args": { Oct 27 14:50:46 volumiox86 qobuz-connect[17856]: "volume": 67 Oct 27 14:50:46 volumiox86 qobuz-connect[17856]: } Oct 27 14:50:46 volumiox86 qobuz-connect[17856]: } Oct 27 14:50:46 volumiox86 qobuz-connect[17856]: on unix socket Oct 27 14:50:46 volumiox86 qobuz-connect[17856]: 20241027 14:50:46.079 [17856.17856] INFO ProtocolHandler: [0x55ddc9012f90]: Volume changed: 67 Oct 27 14:50:46 volumiox86 qobuz-connect[17856]: 20241027 14:50:46.079 [17856.17856] INFO QConnectMessageSender: [0x55ddc9172000]: Sending VolumeChanged message Oct 27 14:50:46 volumiox86 qobuz-connect[17856]: 20241027 14:50:46.079 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Volume: 67 Oct 27 14:50:46 volumiox86 qobuz-connect[17856]: 20241027 14:50:46.079 [17856.17856] INFO QwspMessageSender: [0x55ddc9171fe0]: Sending Payload message Oct 27 14:50:46 volumiox86 qobuz-connect[17856]: 20241027 14:50:46.079 [17856.17856] TRACE QwspMessageSender: [0x55ddc9171fe0]: Protocol: QConnect Oct 27 14:50:46 volumiox86 qobuz-connect[17856]: 20241027 14:50:46.079 [17856.17856] TRACE QwspMessageSender: [0x55ddc9171fe0]: Channel: Backend Oct 27 14:50:46 volumiox86 qobuz-connect[17856]: 20241027 14:50:46.079 [17856.17856] TRACE ProtocolTracer: [0x55ddc9013180]: => 06 24 08 0d 10 bf b6 f9 f1 ac 32 18 01 2a 01 02 3a 14 09 3f 5b 3e ce 92 01 00 00 10 0b 1a 07 08 19 ca 01 02 08 43 Oct 27 14:50:46 volumiox86 volumio[17560]: { Oct 27 14:50:46 volumiox86 volumio[17560]: "delegate": "audio_renderer", Oct 27 14:50:46 volumiox86 volumio[17560]: "function": "playback_volume_changed", Oct 27 14:50:46 volumiox86 volumio[17560]: "args": { Oct 27 14:50:46 volumiox86 volumio[17560]: "volume": 67 Oct 27 14:50:46 volumiox86 volumio[17560]: } Oct 27 14:50:46 volumiox86 volumio[17560]: } Oct 27 14:50:46 volumiox86 volumio[17560]: info: QobuzConnect: Volume: 67 Oct 27 14:50:46 volumiox86 volumio[17560]: info: VolumeController::SetAlsaVolume67 Oct 27 14:50:46 volumiox86 volumio[17560]: info: CoreStateMachine::pushState Oct 27 14:50:46 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioPushState Oct 27 14:50:46 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioGetState Oct 27 14:50:46 volumiox86 volumio[17560]: info: QobuzConnect: Currently active service: qobuzconnect Oct 27 14:50:46 volumiox86 volumio[17560]: info: MRS: Pushing multiroomSync output update for this device Oct 27 14:50:46 volumiox86 volumio[17560]: info: MRS: Pushing multiroomSync output Oct 27 14:50:46 volumiox86 volumio[17560]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: No protocol specified Oct 27 14:50:46 volumiox86 volumio[17560]: xcb_connection_has_error() returned true Oct 27 14:50:55 volumiox86 qobuz-connect[17856]: 20241027 14:50:55.924 [17856.17856] TRACE SampleApp: Wrote { Oct 27 14:50:55 volumiox86 qobuz-connect[17856]: "delegate": "audio_renderer", Oct 27 14:50:55 volumiox86 qobuz-connect[17856]: "function": "get_playback_position", Oct 27 14:50:55 volumiox86 qobuz-connect[17856]: "args": { Oct 27 14:50:55 volumiox86 qobuz-connect[17856]: "position": 29971, Oct 27 14:50:55 volumiox86 qobuz-connect[17856]: "stream_id": 1 Oct 27 14:50:55 volumiox86 qobuz-connect[17856]: } Oct 27 14:50:55 volumiox86 qobuz-connect[17856]: } Oct 27 14:50:55 volumiox86 qobuz-connect[17856]: on unix socket Oct 27 14:50:55 volumiox86 qobuz-connect[17856]: 20241027 14:50:55.925 [17856.17856] TRACE AudioRenderer: [0x55ddc9012370]: Playback position: 29971 Oct 27 14:50:55 volumiox86 qobuz-connect[17856]: 20241027 14:50:55.925 [17856.17856] INFO ProtocolHandler: [0x55ddc9012f90]: Need to send state update Oct 27 14:50:55 volumiox86 qobuz-connect[17856]: 20241027 14:50:55.925 [17856.17856] INFO QConnectMessageSender: [0x55ddc9172000]: Sending StateUpdated message Oct 27 14:50:55 volumiox86 qobuz-connect[17856]: 20241027 14:50:55.925 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Playback state: Playing Oct 27 14:50:55 volumiox86 qobuz-connect[17856]: 20241027 14:50:55.925 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Current position: 29971 Oct 27 14:50:55 volumiox86 qobuz-connect[17856]: 20241027 14:50:55.925 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Duration: 283061 Oct 27 14:50:55 volumiox86 qobuz-connect[17856]: 20241027 14:50:55.925 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Queue version: 3.2 Oct 27 14:50:55 volumiox86 qobuz-connect[17856]: 20241027 14:50:55.925 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Current queue item ID: 5 Oct 27 14:50:55 volumiox86 qobuz-connect[17856]: 20241027 14:50:55.925 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Next queue item ID: 6 Oct 27 14:50:55 volumiox86 qobuz-connect[17856]: 20241027 14:50:55.925 [17856.17856] INFO QwspMessageSender: [0x55ddc9171fe0]: Sending Payload message Oct 27 14:50:55 volumiox86 qobuz-connect[17856]: 20241027 14:50:55.925 [17856.17856] TRACE QwspMessageSender: [0x55ddc9171fe0]: Protocol: QConnect Oct 27 14:50:55 volumiox86 qobuz-connect[17856]: 20241027 14:50:55.925 [17856.17856] TRACE QwspMessageSender: [0x55ddc9171fe0]: Channel: Backend Oct 27 14:50:55 volumiox86 qobuz-connect[17856]: 20241027 14:50:55.925 [17856.17856] TRACE ProtocolTracer: [0x55ddc9013180]: => 06 45 08 0e 10 b5 83 fa f1 ac 32 18 01 2a 01 02 3a 35 09 b5 81 3e ce 92 01 00 00 10 0c 1a 28 08 17 ba 01 23 0a 21 08 02 10 02 1a 0d 09 b5 81 3e ce 92 01 00 00 10 93 ea 01 20 b5 a3 11 2a 04 08 03 10 02 30 05 38 06 Oct 27 14:50:55 volumiox86 qobuz-connect[17856]: 20241027 14:50:55.925 [17856.17856] TRACE PlaybackPositionEstimator: [0x55ddc9012c70]: Synced playback position: 29971ms Oct 27 14:50:55 volumiox86 volumio[17560]: { Oct 27 14:50:55 volumiox86 volumio[17560]: "delegate": "audio_renderer", Oct 27 14:50:55 volumiox86 volumio[17560]: "function": "get_playback_position", Oct 27 14:50:55 volumiox86 volumio[17560]: "args": { Oct 27 14:50:55 volumiox86 volumio[17560]: "position": 29971, Oct 27 14:50:55 volumiox86 volumio[17560]: "stream_id": 1 Oct 27 14:50:55 volumiox86 volumio[17560]: } Oct 27 14:50:55 volumiox86 volumio[17560]: } Oct 27 14:50:55 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioGetState Oct 27 14:50:55 volumiox86 volumio[17560]: info: QobuzConnect: Currently active service: qobuzconnect Oct 27 14:50:55 volumiox86 volumio[17560]: info: CoreCommandRouter::servicePushState Oct 27 14:50:55 volumiox86 volumio[17560]: info: CoreStateMachine::pushState Oct 27 14:50:55 volumiox86 volumio[17560]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 27 14:50:55 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioPushState Oct 27 14:50:55 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioGetState Oct 27 14:50:55 volumiox86 volumio[17560]: info: QobuzConnect: Currently active service: qobuzconnect Oct 27 14:50:55 volumiox86 volumio[17560]: info: MRS: Pushing multiroomSync output update for this device Oct 27 14:50:55 volumiox86 volumio[17560]: info: MRS: Pushing multiroomSync output Oct 27 14:50:55 volumiox86 qobuz-connect[17856]: 20241027 14:50:55.932 [17856.17856] TRACE SampleApp: nread is 45, buf is 65536 Oct 27 14:50:55 volumiox86 qobuz-connect[17856]: 20241027 14:50:55.932 [17856.17856] TRACE SampleApp: received {"command":"set_volume","args":{"volume":67}} Oct 27 14:50:55 volumiox86 qobuz-connect[17856]: 20241027 14:50:55.932 [17856.17856] DEBUG SampleApp: Received socket command: set_volume Oct 27 14:50:55 volumiox86 qobuz-connect[17856]: 20241027 14:50:55.932 [17856.17856] TRACE SampleApp: Command index 0: playback_start_confirm Oct 27 14:50:55 volumiox86 qobuz-connect[17856]: 20241027 14:50:55.932 [17856.17856] TRACE SampleApp: Command index 1: playback_pause Oct 27 14:50:55 volumiox86 qobuz-connect[17856]: 20241027 14:50:55.932 [17856.17856] TRACE SampleApp: Command index 2: playback_resume Oct 27 14:50:55 volumiox86 qobuz-connect[17856]: 20241027 14:50:55.933 [17856.17856] TRACE SampleApp: Command index 3: playback_stop Oct 27 14:50:55 volumiox86 qobuz-connect[17856]: 20241027 14:50:55.933 [17856.17856] TRACE SampleApp: Command index 4: playback_next_track Oct 27 14:50:55 volumiox86 qobuz-connect[17856]: 20241027 14:50:55.933 [17856.17856] TRACE SampleApp: Command index 5: playback_previous_track Oct 27 14:50:55 volumiox86 qobuz-connect[17856]: 20241027 14:50:55.933 [17856.17856] TRACE SampleApp: Command index 6: playback_seek_time Oct 27 14:50:55 volumiox86 qobuz-connect[17856]: 20241027 14:50:55.933 [17856.17856] TRACE SampleApp: Command index 7: set_volume Oct 27 14:50:55 volumiox86 qobuz-connect[17856]: 20241027 14:50:55.933 [17856.17856] DEBUG SampleApp: Executing received command set_volume Oct 27 14:50:55 volumiox86 qobuz-connect[17856]: 20241027 14:50:55.933 [17856.17856] INFO VolumeManager: [0x55ddc9012750]: Setting new playback volume: 67 Oct 27 14:51:05 volumiox86 qobuz-connect[17856]: 20241027 14:51:05.924 [17856.17856] TRACE SampleApp: Wrote { Oct 27 14:51:05 volumiox86 qobuz-connect[17856]: "delegate": "audio_renderer", Oct 27 14:51:05 volumiox86 qobuz-connect[17856]: "function": "get_playback_position", Oct 27 14:51:05 volumiox86 qobuz-connect[17856]: "args": { Oct 27 14:51:05 volumiox86 qobuz-connect[17856]: "position": 39970, Oct 27 14:51:05 volumiox86 qobuz-connect[17856]: "stream_id": 1 Oct 27 14:51:05 volumiox86 qobuz-connect[17856]: } Oct 27 14:51:05 volumiox86 qobuz-connect[17856]: } Oct 27 14:51:05 volumiox86 qobuz-connect[17856]: on unix socket Oct 27 14:51:05 volumiox86 qobuz-connect[17856]: 20241027 14:51:05.924 [17856.17856] TRACE AudioRenderer: [0x55ddc9012370]: Playback position: 39970 Oct 27 14:51:05 volumiox86 qobuz-connect[17856]: 20241027 14:51:05.924 [17856.17856] INFO ProtocolHandler: [0x55ddc9012f90]: Need to send state update Oct 27 14:51:05 volumiox86 qobuz-connect[17856]: 20241027 14:51:05.924 [17856.17856] INFO QConnectMessageSender: [0x55ddc9172000]: Sending StateUpdated message Oct 27 14:51:05 volumiox86 qobuz-connect[17856]: 20241027 14:51:05.924 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Playback state: Playing Oct 27 14:51:05 volumiox86 qobuz-connect[17856]: 20241027 14:51:05.924 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Current position: 39970 Oct 27 14:51:05 volumiox86 qobuz-connect[17856]: 20241027 14:51:05.924 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Duration: 283061 Oct 27 14:51:05 volumiox86 qobuz-connect[17856]: 20241027 14:51:05.924 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Queue version: 3.2 Oct 27 14:51:05 volumiox86 qobuz-connect[17856]: 20241027 14:51:05.924 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Current queue item ID: 5 Oct 27 14:51:05 volumiox86 qobuz-connect[17856]: 20241027 14:51:05.924 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Next queue item ID: 6 Oct 27 14:51:05 volumiox86 qobuz-connect[17856]: 20241027 14:51:05.924 [17856.17856] INFO QwspMessageSender: [0x55ddc9171fe0]: Sending Payload message Oct 27 14:51:05 volumiox86 qobuz-connect[17856]: 20241027 14:51:05.924 [17856.17856] TRACE QwspMessageSender: [0x55ddc9171fe0]: Protocol: QConnect Oct 27 14:51:05 volumiox86 qobuz-connect[17856]: 20241027 14:51:05.924 [17856.17856] TRACE QwspMessageSender: [0x55ddc9171fe0]: Channel: Backend Oct 27 14:51:05 volumiox86 qobuz-connect[17856]: 20241027 14:51:05.925 [17856.17856] TRACE ProtocolTracer: [0x55ddc9013180]: => 06 45 08 0f 10 c5 d1 fa f1 ac 32 18 01 2a 01 02 3a 35 09 c4 a8 3e ce 92 01 00 00 10 0d 1a 28 08 17 ba 01 23 0a 21 08 02 10 02 1a 0d 09 c4 a8 3e ce 92 01 00 00 10 a2 b8 02 20 b5 a3 11 2a 04 08 03 10 02 30 05 38 06 Oct 27 14:51:05 volumiox86 qobuz-connect[17856]: 20241027 14:51:05.925 [17856.17856] TRACE PlaybackPositionEstimator: [0x55ddc9012c70]: Synced playback position: 39970ms Oct 27 14:51:05 volumiox86 volumio[17560]: { Oct 27 14:51:05 volumiox86 volumio[17560]: "delegate": "audio_renderer", Oct 27 14:51:05 volumiox86 volumio[17560]: "function": "get_playback_position", Oct 27 14:51:05 volumiox86 volumio[17560]: "args": { Oct 27 14:51:05 volumiox86 volumio[17560]: "position": 39970, Oct 27 14:51:05 volumiox86 volumio[17560]: "stream_id": 1 Oct 27 14:51:05 volumiox86 volumio[17560]: } Oct 27 14:51:05 volumiox86 volumio[17560]: } Oct 27 14:51:05 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioGetState Oct 27 14:51:05 volumiox86 volumio[17560]: info: QobuzConnect: Currently active service: qobuzconnect Oct 27 14:51:05 volumiox86 volumio[17560]: info: CoreCommandRouter::servicePushState Oct 27 14:51:05 volumiox86 volumio[17560]: info: CoreStateMachine::pushState Oct 27 14:51:05 volumiox86 volumio[17560]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 27 14:51:05 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioPushState Oct 27 14:51:05 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioGetState Oct 27 14:51:05 volumiox86 volumio[17560]: info: QobuzConnect: Currently active service: qobuzconnect Oct 27 14:51:05 volumiox86 volumio[17560]: info: MRS: Pushing multiroomSync output update for this device Oct 27 14:51:05 volumiox86 qobuz-connect[17856]: 20241027 14:51:05.932 [17856.17856] TRACE SampleApp: nread is 45, buf is 65536 Oct 27 14:51:05 volumiox86 qobuz-connect[17856]: 20241027 14:51:05.932 [17856.17856] TRACE SampleApp: received {"command":"set_volume","args":{"volume":67}} Oct 27 14:51:05 volumiox86 qobuz-connect[17856]: 20241027 14:51:05.932 [17856.17856] DEBUG SampleApp: Received socket command: set_volume Oct 27 14:51:05 volumiox86 qobuz-connect[17856]: 20241027 14:51:05.932 [17856.17856] TRACE SampleApp: Command index 0: playback_start_confirm Oct 27 14:51:05 volumiox86 qobuz-connect[17856]: 20241027 14:51:05.932 [17856.17856] TRACE SampleApp: Command index 1: playback_pause Oct 27 14:51:05 volumiox86 qobuz-connect[17856]: 20241027 14:51:05.932 [17856.17856] TRACE SampleApp: Command index 2: playback_resume Oct 27 14:51:05 volumiox86 qobuz-connect[17856]: 20241027 14:51:05.932 [17856.17856] TRACE SampleApp: Command index 3: playback_stop Oct 27 14:51:05 volumiox86 qobuz-connect[17856]: 20241027 14:51:05.932 [17856.17856] TRACE SampleApp: Command index 4: playback_next_track Oct 27 14:51:05 volumiox86 qobuz-connect[17856]: 20241027 14:51:05.932 [17856.17856] TRACE SampleApp: Command index 5: playback_previous_track Oct 27 14:51:05 volumiox86 qobuz-connect[17856]: 20241027 14:51:05.932 [17856.17856] TRACE SampleApp: Command index 6: playback_seek_time Oct 27 14:51:05 volumiox86 qobuz-connect[17856]: 20241027 14:51:05.932 [17856.17856] TRACE SampleApp: Command index 7: set_volume Oct 27 14:51:05 volumiox86 qobuz-connect[17856]: 20241027 14:51:05.932 [17856.17856] DEBUG SampleApp: Executing received command set_volume Oct 27 14:51:05 volumiox86 qobuz-connect[17856]: 20241027 14:51:05.932 [17856.17856] INFO VolumeManager: [0x55ddc9012750]: Setting new playback volume: 67 Oct 27 14:51:05 volumiox86 volumio[17560]: info: MRS: Pushing multiroomSync output Oct 27 14:51:06 volumiox86 volumio[17560]: info: Preload queue cleared Oct 27 14:51:06 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioReplaceandPlayItems Oct 27 14:51:06 volumiox86 volumio[17560]: info: CoreStateMachine::ClearQueue Oct 27 14:51:06 volumiox86 volumio[17560]: info: CoreStateMachine::stop Oct 27 14:51:06 volumiox86 volumio[17560]: info: CoreStateMachine::serviceStop Oct 27 14:51:06 volumiox86 volumio[17560]: info: CoreCommandRouter::serviceStop Oct 27 14:51:06 volumiox86 volumio[17560]: info: QobuzConnect: Received stop Oct 27 14:51:06 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioGetState Oct 27 14:51:06 volumiox86 volumio[17560]: info: QobuzConnect: Currently active service: qobuzconnect Oct 27 14:51:06 volumiox86 volumio[17560]: info: CorePlayQueue::clearPlayQueue Oct 27 14:51:06 volumiox86 qobuz-connect[17856]: 20241027 14:51:06.997 [17856.17856] TRACE SampleApp: nread is 27, buf is 65536 Oct 27 14:51:06 volumiox86 qobuz-connect[17856]: 20241027 14:51:06.997 [17856.17856] TRACE SampleApp: received {"command":"playback_stop"} Oct 27 14:51:06 volumiox86 qobuz-connect[17856]: 20241027 14:51:06.997 [17856.17856] DEBUG SampleApp: Received socket command: playback_stop Oct 27 14:51:06 volumiox86 qobuz-connect[17856]: 20241027 14:51:06.997 [17856.17856] TRACE SampleApp: Command index 0: playback_start_confirm Oct 27 14:51:06 volumiox86 qobuz-connect[17856]: 20241027 14:51:06.997 [17856.17856] TRACE SampleApp: Command index 1: playback_pause Oct 27 14:51:06 volumiox86 qobuz-connect[17856]: 20241027 14:51:06.997 [17856.17856] TRACE SampleApp: Command index 2: playback_resume Oct 27 14:51:06 volumiox86 qobuz-connect[17856]: 20241027 14:51:06.997 [17856.17856] TRACE SampleApp: Command index 3: playback_stop Oct 27 14:51:06 volumiox86 qobuz-connect[17856]: 20241027 14:51:06.997 [17856.17856] DEBUG SampleApp: Executing received command playback_stop Oct 27 14:51:06 volumiox86 qobuz-connect[17856]: 20241027 14:51:06.997 [17856.17856] INFO MediaEngine: [0x55ddc9011b50]: Stopping playback Oct 27 14:51:06 volumiox86 qobuz-connect[17856]: 20241027 14:51:06.997 [17856.17856] DEBUG MediaEngineCommandSequencer: [0x55ddc90125c0]: Enqueuing command: Stop Oct 27 14:51:06 volumiox86 qobuz-connect[17856]: 20241027 14:51:06.997 [17856.17856] DEBUG MediaEngineCommandSequencer: [0x55ddc90125c0]: Executing command: Stop Oct 27 14:51:06 volumiox86 qobuz-connect[17856]: 20241027 14:51:06.997 [17856.17856] DEBUG MediaEngine: [0x55ddc9011b50]: Executing command: Stop Oct 27 14:51:06 volumiox86 qobuz-connect[17856]: 20241027 14:51:06.997 [17856.17856] INFO AudioRenderer: [0x55ddc9012370]: Stopping audio renderer Oct 27 14:51:06 volumiox86 qobuz-connect[17856]: 20241027 14:51:06.997 [17856.17856] DEBUG PlaybackProgressManager: [0x55ddc90123f0]: Audio playback is stopped Oct 27 14:51:06 volumiox86 qobuz-connect[17856]: 20241027 14:51:06.997 [17856.17856] TRACE AudioRenderer: [0x55ddc9012370]: State changed: Playing -> Stopping Oct 27 14:51:06 volumiox86 qobuz-connect[17856]: 20241027 14:51:06.997 [17856.17856] INFO SampleApp: Stopping playback Oct 27 14:51:06 volumiox86 qobuz-connect[17856]: 20241027 14:51:06.997 [17856.17856] DEBUG AudioRenderer: [0x55ddc9012370]: Transition to stopped state has been acknowledged Oct 27 14:51:06 volumiox86 qobuz-connect[17856]: 20241027 14:51:06.997 [17856.17856] TRACE AudioRenderer: [0x55ddc9012370]: State changed: Stopping -> Stopped Oct 27 14:51:06 volumiox86 qobuz-connect[17856]: 20241027 14:51:06.997 [17856.17856] TRACE SampleApp: Wrote { Oct 27 14:51:06 volumiox86 qobuz-connect[17856]: "delegate": "audio_renderer", Oct 27 14:51:06 volumiox86 qobuz-connect[17856]: "function": "playback_stop" Oct 27 14:51:06 volumiox86 qobuz-connect[17856]: } Oct 27 14:51:06 volumiox86 qobuz-connect[17856]: on unix socket Oct 27 14:51:06 volumiox86 qobuz-connect[17856]: 20241027 14:51:06.997 [17856.17856] DEBUG MediaEngine: [0x55ddc9011b50]: Audio renderer state changed: Playing -> Stopping Oct 27 14:51:06 volumiox86 qobuz-connect[17856]: 20241027 14:51:06.997 [17856.17856] DEBUG MediaEngine: [0x55ddc9011b50]: Audio renderer state changed: Stopping -> Stopped Oct 27 14:51:06 volumiox86 volumio[17560]: info: CorePlayQueue::saveQueue Oct 27 14:51:06 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioPushQueue Oct 27 14:51:06 volumiox86 qobuz-connect[17856]: 20241027 14:51:06.998 [17856.17856] TRACE MediaEngine: [0x55ddc9011b50]: State changed: Playing -> Stopped Oct 27 14:51:06 volumiox86 qobuz-connect[17856]: 20241027 14:51:06.998 [17856.17856] TRACE MediaEngine: [0x55ddc9011b50]: Recreating audio streams Oct 27 14:51:06 volumiox86 qobuz-connect[17856]: 20241027 14:51:06.998 [17856.17856] INFO AudioStreamManager: [0x55ddc9011cb0]: Clearing all streams Oct 27 14:51:06 volumiox86 qobuz-connect[17856]: 20241027 14:51:06.998 [17856.17856] INFO AudioStreamManager: [0x55ddc9011cb0]: [Stream 1]: Disposing of audio stream Oct 27 14:51:06 volumiox86 qobuz-connect[17856]: 20241027 14:51:06.998 [17856.17856] INFO ContentFetcher: [0x55ddc916d880]: Canceling download Oct 27 14:51:06 volumiox86 qobuz-connect[17856]: 20241027 14:51:06.998 [17856.17856] DEBUG Ringbuffer: [0x55ddc91a1150]: Freeing Audio Ringbuffer Oct 27 14:51:07 volumiox86 volumio[17560]: info: CoreStateMachine::addQueueItems Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.000 [17856.17856] DEBUG AudioStreamInfoFetcher: [0x55ddc903f260]: Freeing Audio Stream Info Fetcher Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.000 [17856.17856] DEBUG MetadataFetcher: [0x55ddc91c5860]: Freeing Metadata Fetcher Oct 27 14:51:07 volumiox86 volumio[17560]: info: CorePlayQueue::addQueueItems Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.000 [17856.17856] DEBUG PlaybackUrlFetcher: [0x55ddc91e2250]: Freeing Playback URL Fetcher Oct 27 14:51:07 volumiox86 volumio[17560]: info: Preload queue cleared Oct 27 14:51:07 volumiox86 volumio[17560]: info: Adding Item to queue: music-library/INTERNAL/Balligomingo/Beneath the surface/01 - Purify.ogg Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.000 [17856.17856] DEBUG AudioStreamInfoFetcher: [0x55ddc9039900]: Freeing Audio Stream Info Fetcher Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.000 [17856.17856] DEBUG MetadataFetcher: [0x55ddc916eb60]: Freeing Metadata Fetcher Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.000 [17856.17856] DEBUG PlaybackUrlFetcher: [0x55ddc91bfd90]: Freeing Playback URL Fetcher Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.000 [17856.17856] INFO AudioStreamManager: [0x55ddc9011cb0]: New stream: 3 Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.000 [17856.17856] DEBUG PlaybackUrlFetcher: [0x55ddc91bfd90]: Creating Playback URL Fetcher for track: 29686416 Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.000 [17856.17856] INFO HttpDownloader: [0x55ddc916f9e0]: Downloading content from: https://www.qobuz.com/api.json/0.2/track/getFileUrl?format_id=27&request_sig=771649a6e462eec27dec793464680507&request_ts=1730037067&track_id=29686416 Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.001 [17856.17856] DEBUG MetadataFetcher: [0x55ddc9250aa0]: Creating Metadata Fetcher for track: 29686416 Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.001 [17856.17856] INFO HttpDownloader: [0x55ddc91c5d80]: Downloading content from: https://www.qobuz.com/api.json/0.2/track/get?track_id=29686416 Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.001 [17856.17856] DEBUG AudioStreamInfoFetcher: [0x55ddc9175390]: Creating Audio Stream Info Fetcher for track: 29686416 Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.001 [17856.17856] INFO HttpDownloader: [0x55ddc91ba7b0]: Downloading content from: https://www.qobuz.com/api.json/0.2/file/url?format_id=27&intent=stream&request_sig=e7cd2ad444363a7babf39cbc6b9ea761&request_ts=1730037067&track_id=29686416 Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.001 [17856.17856] INFO AudioStreamManager: [0x55ddc9011cb0]: [Stream 3]: Running audio stream Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.001 [17856.17856] INFO AudioStreamManager: [0x55ddc9011cb0]: New stream: 4 Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.001 [17856.17856] DEBUG PlaybackUrlFetcher: [0x55ddc902aaf0]: Creating Playback URL Fetcher for track: 29686418 Oct 27 14:51:07 volumiox86 volumio[17560]: info: Exploding uri music-library/INTERNAL/Balligomingo/Beneath the surface/01 - Purify.ogg in service mpd Oct 27 14:51:07 volumiox86 volumio[17560]: info: Adding Item to queue: music-library/INTERNAL/Balligomingo/Beneath the surface/02 - Escape.ogg Oct 27 14:51:07 volumiox86 volumio[17560]: info: Exploding uri music-library/INTERNAL/Balligomingo/Beneath the surface/02 - Escape.ogg in service mpd Oct 27 14:51:07 volumiox86 volumio[17560]: info: Adding Item to queue: music-library/INTERNAL/Balligomingo/Beneath the surface/03 - Falling.ogg Oct 27 14:51:07 volumiox86 volumio[17560]: info: Exploding uri music-library/INTERNAL/Balligomingo/Beneath the surface/03 - Falling.ogg in service mpd Oct 27 14:51:07 volumiox86 volumio[17560]: info: Adding Item to queue: music-library/INTERNAL/Balligomingo/Beneath the surface/04 - Sweet Allure.ogg Oct 27 14:51:07 volumiox86 volumio[17560]: info: Exploding uri music-library/INTERNAL/Balligomingo/Beneath the surface/04 - Sweet Allure.ogg in service mpd Oct 27 14:51:07 volumiox86 volumio[17560]: info: Adding Item to queue: music-library/INTERNAL/Balligomingo/Beneath the surface/05 - Wild Butterfly.ogg Oct 27 14:51:07 volumiox86 volumio[17560]: info: Exploding uri music-library/INTERNAL/Balligomingo/Beneath the surface/05 - Wild Butterfly.ogg in service mpd Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.001 [17856.17856] INFO HttpDownloader: [0x55ddc91a1130]: Downloading content from: https://www.qobuz.com/api.json/0.2/track/getFileUrl?format_id=27&request_sig=73e6e62b3a7ac3d4e5e3adb0071cbdb6&request_ts=1730037067&track_id=29686418 Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.001 [17856.17856] DEBUG MetadataFetcher: [0x55ddc9171fa0]: Creating Metadata Fetcher for track: 29686418 Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.001 [17856.17856] INFO HttpDownloader: [0x55ddc917adf0]: Downloading content from: https://www.qobuz.com/api.json/0.2/track/get?track_id=29686418 Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.001 [17856.17856] DEBUG AudioStreamInfoFetcher: [0x55ddc916a1e0]: Creating Audio Stream Info Fetcher for track: 29686418 Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.001 [17856.17856] INFO HttpDownloader: [0x55ddc919fda0]: Downloading content from: https://www.qobuz.com/api.json/0.2/file/url?format_id=27&intent=stream&request_sig=329bf56f99b3d4df12cb985438fd26f7&request_ts=1730037067&track_id=29686418 Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.001 [17856.17856] DEBUG MediaEngineCommandSequencer: [0x55ddc90125c0]: Confirming command: Stop Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.002 [17856.17856] DEBUG MediaEngine: [0x55ddc9011b50]: Current stream changed state: Running -> Nonexistent Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.002 [17856.17856] INFO SampleApp: [Stream 1]: Audio stream has been disposed of Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.002 [17856.17856] TRACE SampleApp: Wrote { Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: "delegate": "audio_source_manager", Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: "function": "audio_stream_dispose", Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: "args": { Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: "id": 1 Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: } Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: } Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: on unix socket Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.002 [17856.17856] INFO SampleApp: Playback status changed: Stopped Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.002 [17856.17856] TRACE SampleApp: Wrote { Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: "delegate": "audio_renderer", Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: "function": "playback_status_changed", Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: "args": { Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: "status": "stopped" Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: } Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: } Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: on unix socket Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.002 [17856.17856] INFO PlaybackEventReporter: [0x55ddc9012a10]: Reporting streaming ended event Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.002 [17856.17856] TRACE PlaybackEventReporter: [0x55ddc9012a10]: End position: 41047ms Oct 27 14:51:07 volumiox86 volumio[17560]: info: Adding Item to queue: music-library/INTERNAL/Balligomingo/Beneath the surface/06 - Beyond.ogg Oct 27 14:51:07 volumiox86 volumio[17560]: info: Exploding uri music-library/INTERNAL/Balligomingo/Beneath the surface/06 - Beyond.ogg in service mpd Oct 27 14:51:07 volumiox86 volumio[17560]: info: Adding Item to queue: music-library/INTERNAL/Balligomingo/Beneath the surface/07 - Privilege.ogg Oct 27 14:51:07 volumiox86 volumio[17560]: info: Exploding uri music-library/INTERNAL/Balligomingo/Beneath the surface/07 - Privilege.ogg in service mpd Oct 27 14:51:07 volumiox86 volumio[17560]: info: Adding Item to queue: music-library/INTERNAL/Balligomingo/Beneath the surface/08 - Heat.ogg Oct 27 14:51:07 volumiox86 volumio[17560]: info: Exploding uri music-library/INTERNAL/Balligomingo/Beneath the surface/08 - Heat.ogg in service mpd Oct 27 14:51:07 volumiox86 volumio[17560]: info: Adding Item to queue: music-library/INTERNAL/Balligomingo/Beneath the surface/09 - Lost.ogg Oct 27 14:51:07 volumiox86 volumio[17560]: info: Exploding uri music-library/INTERNAL/Balligomingo/Beneath the surface/09 - Lost.ogg in service mpd Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.002 [17856.17856] TRACE PlaybackEventReporter: [0x55ddc9012a10]: Duration: 41047ms Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.002 [17856.17856] DEBUG PlaybackEventReporter: [0x55ddc9012a10]: Sending streaming reports Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.002 [17856.17856] INFO HttpDownloader: [0x55ddc9012a90]: Downloading content from: https://www.qobuz.com/api.json/0.2/track/reportStreamingEndJson Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.002 [17856.17856] DEBUG SampleApp: Audio sink is not open, returning playback position 0 Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.002 [17856.17856] TRACE SampleApp: Wrote { Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: "delegate": "audio_renderer", Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: "function": "get_playback_position", Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: "args": { Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: "position": 0, Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: "stream_id": 0 Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: } Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: } Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: on unix socket Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.002 [17856.17856] TRACE AudioRenderer: [0x55ddc9012370]: Playback position: 0 Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.002 [17856.17856] INFO ProtocolHandler: [0x55ddc9012f90]: Need to send state update Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.002 [17856.17856] INFO QConnectMessageSender: [0x55ddc9172000]: Sending StateUpdated message Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.002 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Playback state: Stopped Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.002 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Current position: 0 Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.002 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Duration: 0 Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.002 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Queue version: 3.2 Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.002 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Current queue item ID: 5 Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.002 [17856.17856] TRACE QConnectMessageSender: [0x55ddc9172000]: Next queue item ID: 6 Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.002 [17856.17856] INFO QwspMessageSender: [0x55ddc9171fe0]: Sending Payload message Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.002 [17856.17856] TRACE QwspMessageSender: [0x55ddc9171fe0]: Protocol: QConnect Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.002 [17856.17856] TRACE QwspMessageSender: [0x55ddc9171fe0]: Channel: Backend Oct 27 14:51:07 volumiox86 volumio[17560]: info: Adding Item to queue: music-library/INTERNAL/Balligomingo/Beneath the surface/10 - Marooned.ogg Oct 27 14:51:07 volumiox86 volumio[17560]: info: Exploding uri music-library/INTERNAL/Balligomingo/Beneath the surface/10 - Marooned.ogg in service mpd Oct 27 14:51:07 volumiox86 volumio[17560]: info: Adding Item to queue: music-library/INTERNAL/Balligomingo/Beneath the surface/11 - Lust.ogg Oct 27 14:51:07 volumiox86 volumio[17560]: info: Exploding uri music-library/INTERNAL/Balligomingo/Beneath the surface/11 - Lust.ogg in service mpd Oct 27 14:51:07 volumiox86 volumio[17560]: info: Adding Item to queue: music-library/INTERNAL/Balligomingo/Beneath the surface/12 - Being (Bonus).ogg Oct 27 14:51:07 volumiox86 volumio[17560]: info: Exploding uri music-library/INTERNAL/Balligomingo/Beneath the surface/12 - Being (Bonus).ogg in service mpd Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.002 [17856.17856] TRACE ProtocolTracer: [0x55ddc9013180]: => 06 3d 08 10 10 fa d9 fa f1 ac 32 18 01 2a 01 02 3a 2d 09 fa ac 3e ce 92 01 00 00 10 0e 1a 20 08 17 ba 01 1b 0a 19 08 01 10 02 1a 09 09 fa ac 3e ce 92 01 00 00 2a 04 08 03 10 02 30 05 38 06 Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.003 [17856.17856] DEBUG MediaEngine: [0x55ddc9011b50]: Current stream changed state: Info Retrieved -> Nonexistent Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.003 [17856.17856] TRACE PlaybackPositionEstimator: [0x55ddc9012c70]: Synced playback position: 0ms Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.003 [17856.17856] DEBUG MediaEngine: [0x55ddc9011b50]: Current stream changed state: Nonexistent -> Created Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.003 [17856.17856] DEBUG MediaEngine: [0x55ddc9011b50]: Next stream changed state: Nonexistent -> Created Oct 27 14:51:07 volumiox86 volumio[17560]: { Oct 27 14:51:07 volumiox86 volumio[17560]: "delegate": "audio_renderer", Oct 27 14:51:07 volumiox86 volumio[17560]: "function": "playback_stop" Oct 27 14:51:07 volumiox86 volumio[17560]: } Oct 27 14:51:07 volumiox86 volumio[17560]: error: QobuzConnect: Could not process JSON: TypeError: Cannot read property 'resolve' of undefined Oct 27 14:51:07 volumiox86 volumio[17560]: { Oct 27 14:51:07 volumiox86 volumio[17560]: "delegate": "audio_source_manager", Oct 27 14:51:07 volumiox86 volumio[17560]: "function": "audio_stream_dispose", Oct 27 14:51:07 volumiox86 volumio[17560]: "args": { Oct 27 14:51:07 volumiox86 volumio[17560]: "id": 1 Oct 27 14:51:07 volumiox86 volumio[17560]: } Oct 27 14:51:07 volumiox86 volumio[17560]: } Oct 27 14:51:07 volumiox86 volumio[17560]: { Oct 27 14:51:07 volumiox86 volumio[17560]: "delegate": "audio_renderer", Oct 27 14:51:07 volumiox86 volumio[17560]: "function": "playback_status_changed", Oct 27 14:51:07 volumiox86 volumio[17560]: "args": { Oct 27 14:51:07 volumiox86 volumio[17560]: "status": "stopped" Oct 27 14:51:07 volumiox86 volumio[17560]: } Oct 27 14:51:07 volumiox86 volumio[17560]: } Oct 27 14:51:07 volumiox86 volumio[17560]: info: CoreCommandRouter::servicePushState Oct 27 14:51:07 volumiox86 volumio[17560]: info: CoreStateMachine::pushState Oct 27 14:51:07 volumiox86 volumio[17560]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 27 14:51:07 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioPushState Oct 27 14:51:07 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioGetState Oct 27 14:51:07 volumiox86 volumio[17560]: info: QobuzConnect: Currently active service: qobuzconnect Oct 27 14:51:07 volumiox86 volumio[17560]: info: MRS: Pushing multiroomSync output update for this device Oct 27 14:51:07 volumiox86 volumio[17560]: info: MRS: Pushing multiroomSync output Oct 27 14:51:07 volumiox86 volumio[17560]: { Oct 27 14:51:07 volumiox86 volumio[17560]: "delegate": "audio_renderer", Oct 27 14:51:07 volumiox86 volumio[17560]: "function": "get_playback_position", Oct 27 14:51:07 volumiox86 volumio[17560]: "args": { Oct 27 14:51:07 volumiox86 volumio[17560]: "position": 0, Oct 27 14:51:07 volumiox86 volumio[17560]: "stream_id": 0 Oct 27 14:51:07 volumiox86 volumio[17560]: } Oct 27 14:51:07 volumiox86 volumio[17560]: } Oct 27 14:51:07 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioGetState Oct 27 14:51:07 volumiox86 volumio[17560]: info: QobuzConnect: Currently active service: qobuzconnect Oct 27 14:51:07 volumiox86 volumio[17560]: info: CoreCommandRouter::servicePushState Oct 27 14:51:07 volumiox86 volumio[17560]: info: CoreStateMachine::pushState Oct 27 14:51:07 volumiox86 volumio[17560]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 27 14:51:07 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioPushState Oct 27 14:51:07 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioGetState Oct 27 14:51:07 volumiox86 volumio[17560]: info: QobuzConnect: Currently active service: qobuzconnect Oct 27 14:51:07 volumiox86 volumio[17560]: info: MRS: Pushing multiroomSync output update for this device Oct 27 14:51:07 volumiox86 volumio[17560]: info: MRS: Pushing multiroomSync output Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.010 [17856.17856] TRACE SampleApp: nread is 90, buf is 65536 Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.010 [17856.17856] TRACE SampleApp: received {"command":"set_volume","args":{"volume":67}}{"command":"set_volume","args":{"volume":67}} Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.010 [17856.17856] DEBUG SampleApp: Received socket command: set_volume Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.010 [17856.17856] TRACE SampleApp: Command index 0: playback_start_confirm Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.010 [17856.17856] TRACE SampleApp: Command index 1: playback_pause Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.010 [17856.17856] TRACE SampleApp: Command index 2: playback_resume Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.010 [17856.17856] TRACE SampleApp: Command index 3: playback_stop Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.011 [17856.17856] TRACE SampleApp: Command index 4: playback_next_track Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.011 [17856.17856] TRACE SampleApp: Command index 5: playback_previous_track Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.013 [17856.17856] TRACE SampleApp: Command index 6: playback_seek_time Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.013 [17856.17856] TRACE SampleApp: Command index 7: set_volume Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.013 [17856.17856] DEBUG SampleApp: Executing received command set_volume Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.013 [17856.17856] INFO VolumeManager: [0x55ddc9012750]: Setting new playback volume: 67 Oct 27 14:51:07 volumiox86 volumio[17560]: info: ALBUMART /albumart?cacheid=581&web=Balligomingo/Beneath%20The%20Surface/extralarge&path=%2Fmnt%2FINTERNAL%2FBalligomingo%2FBeneath%20the%20surface%2F01%20-%20Purify.ogg&metadata=false Oct 27 14:51:07 volumiox86 volumio[17560]: info: URI /mnt/INTERNAL/Balligomingo/Beneath the surface/01 - Purify.ogg Oct 27 14:51:07 volumiox86 volumio[17560]: info: ALBUMART /albumart?cacheid=581&web=Balligomingo/Beneath%20The%20Surface/extralarge&path=%2Fmnt%2FINTERNAL%2FBalligomingo%2FBeneath%20the%20surface%2F02%20-%20Escape.ogg&metadata=false Oct 27 14:51:07 volumiox86 volumio[17560]: info: URI /mnt/INTERNAL/Balligomingo/Beneath the surface/02 - Escape.ogg Oct 27 14:51:07 volumiox86 volumio[17560]: info: ALBUMART /albumart?cacheid=581&web=Balligomingo/Beneath%20The%20Surface/extralarge&path=%2Fmnt%2FINTERNAL%2FBalligomingo%2FBeneath%20the%20surface%2F03%20-%20Falling.ogg&metadata=false Oct 27 14:51:07 volumiox86 volumio[17560]: info: URI /mnt/INTERNAL/Balligomingo/Beneath the surface/03 - Falling.ogg Oct 27 14:51:07 volumiox86 volumio[17560]: info: ALBUMART /albumart?cacheid=581&web=Balligomingo/Beneath%20The%20Surface/extralarge&path=%2Fmnt%2FINTERNAL%2FBalligomingo%2FBeneath%20the%20surface%2F04%20-%20Sweet%20Allure.ogg&metadata=false Oct 27 14:51:07 volumiox86 volumio[17560]: info: URI /mnt/INTERNAL/Balligomingo/Beneath the surface/04 - Sweet Allure.ogg Oct 27 14:51:07 volumiox86 volumio[17560]: info: ALBUMART /albumart?cacheid=581&web=Balligomingo/Beneath%20The%20Surface/extralarge&path=%2Fmnt%2FINTERNAL%2FBalligomingo%2FBeneath%20the%20surface%2F05%20-%20Wild%20Butterfly.ogg&metadata=false Oct 27 14:51:07 volumiox86 volumio[17560]: info: URI /mnt/INTERNAL/Balligomingo/Beneath the surface/05 - Wild Butterfly.ogg Oct 27 14:51:07 volumiox86 volumio[17560]: info: ALBUMART /albumart?cacheid=581&web=Balligomingo/Beneath%20The%20Surface/extralarge&path=%2Fmnt%2FINTERNAL%2FBalligomingo%2FBeneath%20the%20surface%2F06%20-%20Beyond.ogg&metadata=false Oct 27 14:51:07 volumiox86 volumio[17560]: info: URI /mnt/INTERNAL/Balligomingo/Beneath the surface/06 - Beyond.ogg Oct 27 14:51:07 volumiox86 volumio[17560]: info: ALBUMART /albumart?cacheid=581&web=Balligomingo/Beneath%20The%20Surface/extralarge&path=%2Fmnt%2FINTERNAL%2FBalligomingo%2FBeneath%20the%20surface%2F07%20-%20Privilege.ogg&metadata=false Oct 27 14:51:07 volumiox86 volumio[17560]: info: URI /mnt/INTERNAL/Balligomingo/Beneath the surface/07 - Privilege.ogg Oct 27 14:51:07 volumiox86 volumio[17560]: info: ALBUMART /albumart?cacheid=581&web=Balligomingo/Beneath%20The%20Surface/extralarge&path=%2Fmnt%2FINTERNAL%2FBalligomingo%2FBeneath%20the%20surface%2F08%20-%20Heat.ogg&metadata=false Oct 27 14:51:07 volumiox86 volumio[17560]: info: URI /mnt/INTERNAL/Balligomingo/Beneath the surface/08 - Heat.ogg Oct 27 14:51:07 volumiox86 volumio[17560]: info: ALBUMART /albumart?cacheid=581&web=Balligomingo/Beneath%20The%20Surface/extralarge&path=%2Fmnt%2FINTERNAL%2FBalligomingo%2FBeneath%20the%20surface%2F09%20-%20Lost.ogg&metadata=false Oct 27 14:51:07 volumiox86 volumio[17560]: info: URI /mnt/INTERNAL/Balligomingo/Beneath the surface/09 - Lost.ogg Oct 27 14:51:07 volumiox86 volumio[17560]: info: ALBUMART /albumart?cacheid=581&web=Balligomingo/Beneath%20The%20Surface/extralarge&path=%2Fmnt%2FINTERNAL%2FBalligomingo%2FBeneath%20the%20surface%2F10%20-%20Marooned.ogg&metadata=false Oct 27 14:51:07 volumiox86 volumio[17560]: info: URI /mnt/INTERNAL/Balligomingo/Beneath the surface/10 - Marooned.ogg Oct 27 14:51:07 volumiox86 volumio[17560]: info: ALBUMART /albumart?cacheid=581&web=Balligomingo/Beneath%20The%20Surface/extralarge&path=%2Fmnt%2FINTERNAL%2FBalligomingo%2FBeneath%20the%20surface%2F11%20-%20Lust.ogg&metadata=false Oct 27 14:51:07 volumiox86 volumio[17560]: info: URI /mnt/INTERNAL/Balligomingo/Beneath the surface/11 - Lust.ogg Oct 27 14:51:07 volumiox86 volumio[17560]: info: ALBUMART /albumart?cacheid=581&web=Balligomingo/Beneath%20The%20Surface/extralarge&path=%2Fmnt%2FINTERNAL%2FBalligomingo%2FBeneath%20the%20surface%2F12%20-%20Being%20(Bonus).ogg&metadata=false Oct 27 14:51:07 volumiox86 volumio[17560]: info: URI /mnt/INTERNAL/Balligomingo/Beneath the surface/12 - Being (Bonus).ogg Oct 27 14:51:07 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioPushQueue Oct 27 14:51:07 volumiox86 volumio[17560]: info: CorePlayQueue::saveQueue Oct 27 14:51:07 volumiox86 volumio[17560]: info: CoreStateMachine::updateTrackBlock Oct 27 14:51:07 volumiox86 volumio[17560]: info: CorePlayQueue::getTrackBlock Oct 27 14:51:07 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioPlay Oct 27 14:51:07 volumiox86 volumio[17560]: verbose: UNSET VOLATILE: Service: qobuzconnect Oct 27 14:51:07 volumiox86 volumio[17560]: info: QobuzConnect: onUnsetVolatile() called, relinquishing Volumio State to another service Oct 27 14:51:07 volumiox86 volumio[17560]: info: QobuzConnect: Received stop Oct 27 14:51:07 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioGetState Oct 27 14:51:07 volumiox86 volumio[17560]: info: QobuzConnect: Currently active service: qobuzconnect Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.017 [17856.17856] TRACE SampleApp: nread is 27, buf is 65536 Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.017 [17856.17856] TRACE SampleApp: received {"command":"playback_stop"} Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.017 [17856.17856] DEBUG SampleApp: Received socket command: playback_stop Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.017 [17856.17856] TRACE SampleApp: Command index 0: playback_start_confirm Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.017 [17856.17856] TRACE SampleApp: Command index 1: playback_pause Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.017 [17856.17856] TRACE SampleApp: Command index 2: playback_resume Oct 27 14:51:07 volumiox86 volumio[17560]: info: CoreStateMachine::play index 0 Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.018 [17856.17856] TRACE SampleApp: Command index 3: playback_stop Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.018 [17856.17856] DEBUG SampleApp: Executing received command playback_stop Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.018 [17856.17856] INFO MediaEngine: [0x55ddc9011b50]: Stopping playback Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.018 [17856.17856] DEBUG MediaEngineCommandSequencer: [0x55ddc90125c0]: Enqueuing command: Stop Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.018 [17856.17856] DEBUG MediaEngineCommandSequencer: [0x55ddc90125c0]: Executing command: Stop Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.018 [17856.17856] DEBUG MediaEngine: [0x55ddc9011b50]: Executing command: Stop Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.018 [17856.17856] DEBUG MediaEngineCommandSequencer: [0x55ddc90125c0]: Confirming command: Stop Oct 27 14:51:07 volumiox86 volumio[17560]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 27 14:51:07 volumiox86 volumio[17560]: info: CoreStateMachine::stop Oct 27 14:51:07 volumiox86 volumio[17560]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 27 14:51:07 volumiox86 volumio[17560]: info: CoreStateMachine::updateTrackBlock Oct 27 14:51:07 volumiox86 volumio[17560]: info: CorePlayQueue::getTrackBlock Oct 27 14:51:07 volumiox86 volumio[17560]: info: CoreStateMachine::stPlaybackTimer Oct 27 14:51:07 volumiox86 volumio[17560]: info: CoreStateMachine::pushState Oct 27 14:51:07 volumiox86 volumio[17560]: info: CorePlayQueue::getTrack 0 Oct 27 14:51:07 volumiox86 volumio[17560]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 27 14:51:07 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioPushState Oct 27 14:51:07 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioGetState Oct 27 14:51:07 volumiox86 volumio[17560]: info: CorePlayQueue::getTrack 0 Oct 27 14:51:07 volumiox86 volumio[17560]: info: QobuzConnect: Currently active service: mpd Oct 27 14:51:07 volumiox86 volumio[17560]: info: MRS: Pushing multiroomSync output update for this device Oct 27 14:51:07 volumiox86 volumio[17560]: info: MRS: Pushing multiroomSync output Oct 27 14:51:07 volumiox86 volumio[17560]: info: CoreStateMachine::serviceStop Oct 27 14:51:07 volumiox86 volumio[17560]: info: CorePlayQueue::getTrack 0 Oct 27 14:51:07 volumiox86 volumio[17560]: info: CoreCommandRouter::serviceStop Oct 27 14:51:07 volumiox86 volumio[17560]: info: ControllerMpd::stop Oct 27 14:51:07 volumiox86 volumio[17560]: verbose: ControllerMpd::sendMpdCommand stop Oct 27 14:51:07 volumiox86 volumio[17560]: info: sendMpdCommand stop took 3 milliseconds Oct 27 14:51:07 volumiox86 volumio[17560]: info: CoreStateMachine::play index undefined Oct 27 14:51:07 volumiox86 volumio[17560]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 27 14:51:07 volumiox86 volumio[17560]: info: CorePlayQueue::getTrack 0 Oct 27 14:51:07 volumiox86 volumio[17560]: info: CoreStateMachine::startPlaybackTimer Oct 27 14:51:07 volumiox86 volumio[17560]: info: CorePlayQueue::getTrack 0 Oct 27 14:51:07 volumiox86 volumio[17560]: verbose: ControllerMpd::clearAddPlayTracks INTERNAL/Balligomingo/Beneath the surface/01 - Purify.ogg Oct 27 14:51:07 volumiox86 volumio[17560]: verbose: ControllerMpd::sendMpdCommand stop Oct 27 14:51:07 volumiox86 volumio[17560]: info: sendMpdCommand stop took 2 milliseconds Oct 27 14:51:07 volumiox86 volumio[17560]: verbose: ControllerMpd::sendMpdCommand clear Oct 27 14:51:07 volumiox86 volumio[17560]: info: Oct 27 14:51:07 volumiox86 volumio[17560]: ---------------------------- MPD announces system playlist update Oct 27 14:51:07 volumiox86 volumio[17560]: info: Ignoring MPD Status Update Oct 27 14:51:07 volumiox86 volumio[17560]: info: sendMpdCommand clear took 5 milliseconds Oct 27 14:51:07 volumiox86 volumio[17560]: verbose: ControllerMpd::sendMpdCommand add "INTERNAL/Balligomingo/Beneath the surface/01 - Purify.ogg" Oct 27 14:51:07 volumiox86 volumio[17560]: error: updateQueue error: null Oct 27 14:51:07 volumiox86 volumio[17560]: info: Oct 27 14:51:07 volumiox86 volumio[17560]: ---------------------------- MPD announces system playlist update Oct 27 14:51:07 volumiox86 volumio[17560]: info: Ignoring MPD Status Update Oct 27 14:51:07 volumiox86 volumio[17560]: info: ------------------------------ 1ms Oct 27 14:51:07 volumiox86 volumio[17560]: info: sendMpdCommand add "INTERNAL/Balligomingo/Beneath the surface/01 - Purify.ogg" took 0 milliseconds Oct 27 14:51:07 volumiox86 volumio[17560]: verbose: ControllerMpd::sendMpdCommand play Oct 27 14:51:07 volumiox86 volumio[17560]: info: Oct 27 14:51:07 volumiox86 volumio[17560]: ---------------------------- MPD announces state update: player Oct 27 14:51:07 volumiox86 volumio[17560]: info: ------------------------------ 5ms Oct 27 14:51:07 volumiox86 volumio[17560]: info: sendMpdCommand play took 5 milliseconds Oct 27 14:51:07 volumiox86 volumio[17560]: info: ControllerMpd::getState Oct 27 14:51:07 volumiox86 volumio[17560]: verbose: ControllerMpd::sendMpdCommand status Oct 27 14:51:07 volumiox86 volumio[17560]: info: Oct 27 14:51:07 volumiox86 volumio[17560]: ---------------------------- MPD announces state update: player Oct 27 14:51:07 volumiox86 volumio[17560]: info: ControllerMpd::getState Oct 27 14:51:07 volumiox86 volumio[17560]: verbose: ControllerMpd::sendMpdCommand status Oct 27 14:51:07 volumiox86 volumio[17560]: info: sendMpdCommand status took 3 milliseconds Oct 27 14:51:07 volumiox86 volumio[17560]: verbose: ControllerMpd::parseState Oct 27 14:51:07 volumiox86 volumio[17560]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 27 14:51:07 volumiox86 volumio[17560]: info: sendMpdCommand status took 1 milliseconds Oct 27 14:51:07 volumiox86 volumio[17560]: info: sendMpdCommand playlistinfo took 1 milliseconds Oct 27 14:51:07 volumiox86 volumio[17560]: verbose: ControllerMpd::parseState Oct 27 14:51:07 volumiox86 volumio[17560]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 27 14:51:07 volumiox86 volumio[17560]: verbose: ControllerMpd::parseTrackInfo Oct 27 14:51:07 volumiox86 volumio[17560]: info: ControllerMpd::pushState Oct 27 14:51:07 volumiox86 volumio[17560]: info: CoreCommandRouter::servicePushState Oct 27 14:51:07 volumiox86 volumio[17560]: info: CorePlayQueue::getTrack 0 Oct 27 14:51:07 volumiox86 volumio[17560]: verbose: STATE SERVICE {"status":"play","position":0,"seek":1104,"duration":255,"samplerate":44.1,"bitdepth":"32 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Purify","artist":"Balligomingo","album":"Beneath The Surface","uri":"INTERNAL/Balligomingo/Beneath the surface/01 - Purify.ogg","trackType":"ogg"} Oct 27 14:51:07 volumiox86 volumio[17560]: verbose: CURRENT POSITION 0 Oct 27 14:51:07 volumiox86 volumio[17560]: info: CoreStateMachine::syncState stateService play Oct 27 14:51:07 volumiox86 volumio[17560]: info: CoreStateMachine::syncState currentStatus stop Oct 27 14:51:07 volumiox86 volumio[17560]: info: ------------------------------ 5ms Oct 27 14:51:07 volumiox86 volumio[17560]: info: sendMpdCommand playlistinfo took 2 milliseconds Oct 27 14:51:07 volumiox86 volumio[17560]: verbose: ControllerMpd::parseTrackInfo Oct 27 14:51:07 volumiox86 volumio[17560]: info: ControllerMpd::pushState Oct 27 14:51:07 volumiox86 volumio[17560]: info: CoreCommandRouter::servicePushState Oct 27 14:51:07 volumiox86 volumio[17560]: info: CorePlayQueue::getTrack 0 Oct 27 14:51:07 volumiox86 volumio[17560]: verbose: STATE SERVICE {"status":"play","position":0,"seek":1104,"duration":255,"samplerate":44.1,"bitdepth":"32 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Purify","artist":"Balligomingo","album":"Beneath The Surface","uri":"INTERNAL/Balligomingo/Beneath the surface/01 - Purify.ogg","trackType":"ogg"} Oct 27 14:51:07 volumiox86 volumio[17560]: verbose: CURRENT POSITION 0 Oct 27 14:51:07 volumiox86 volumio[17560]: info: CoreStateMachine::syncState stateService play Oct 27 14:51:07 volumiox86 volumio[17560]: info: CoreStateMachine::syncState currentStatus play Oct 27 14:51:07 volumiox86 volumio[17560]: info: Received an update from plugin. extracting info from payload Oct 27 14:51:07 volumiox86 volumio[17560]: info: CoreStateMachine::pushState Oct 27 14:51:07 volumiox86 volumio[17560]: info: CorePlayQueue::getTrack 0 Oct 27 14:51:07 volumiox86 volumio[17560]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 27 14:51:07 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioPushState Oct 27 14:51:07 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioGetState Oct 27 14:51:07 volumiox86 volumio[17560]: info: CorePlayQueue::getTrack 0 Oct 27 14:51:07 volumiox86 volumio[17560]: info: QobuzConnect: Currently active service: mpd Oct 27 14:51:07 volumiox86 volumio[17560]: info: MRS: Pushing multiroomSync output update for this device Oct 27 14:51:07 volumiox86 volumio[17560]: info: MRS: Pushing multiroomSync output Oct 27 14:51:07 volumiox86 volumio[17560]: info: CoreStateMachine::pushState Oct 27 14:51:07 volumiox86 volumio[17560]: info: CorePlayQueue::getTrack 0 Oct 27 14:51:07 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioPushState Oct 27 14:51:07 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioGetState Oct 27 14:51:07 volumiox86 volumio[17560]: info: CorePlayQueue::getTrack 0 Oct 27 14:51:07 volumiox86 volumio[17560]: info: QobuzConnect: Currently active service: mpd Oct 27 14:51:07 volumiox86 volumio[17560]: info: MRS: Pushing multiroomSync output update for this device Oct 27 14:51:07 volumiox86 volumio[17560]: info: MRS: Pushing multiroomSync output Oct 27 14:51:07 volumiox86 volumio[17560]: info: ------------------------------ 10ms Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.157 [17856.17856] INFO AudioStreamManager: [0x55ddc9011cb0]: [Stream 3]: Metadata became available: Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.157 [17856.17856] INFO AudioStreamManager: [0x55ddc9011cb0]: Title: Polymorphing Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.157 [17856.17856] INFO AudioStreamManager: [0x55ddc9011cb0]: Artist: Chairlift Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.157 [17856.17856] INFO AudioStreamManager: [0x55ddc9011cb0]: Album: Moth Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.157 [17856.17856] INFO AudioStreamManager: [0x55ddc9011cb0]: Album art URL: https://static.qobuz.com/images/covers/36/12/0886445231236_600.jpg Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.177 [17856.17856] INFO AudioStreamManager: [0x55ddc9011cb0]: [Stream 4]: track URL resolved to: https://streaming-qobuz-std.akamaized.net/file?uid=789598&eid=29686418&fmt=7&profile=raw&app_id=500827169&cid=1302541&etsp=1730040667&hmac=MLD6zBihjkJxJpxqTGQDTZ7tEOg Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.190 [17856.17856] INFO AudioStreamManager: [0x55ddc9011cb0]: [Stream 4]: Metadata became available: Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.190 [17856.17856] INFO AudioStreamManager: [0x55ddc9011cb0]: Title: Ch-Ching Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.190 [17856.17856] INFO AudioStreamManager: [0x55ddc9011cb0]: Artist: Chairlift Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.190 [17856.17856] INFO AudioStreamManager: [0x55ddc9011cb0]: Album: Moth Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.191 [17856.17856] INFO AudioStreamManager: [0x55ddc9011cb0]: Album art URL: https://static.qobuz.com/images/covers/36/12/0886445231236_600.jpg Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.214 [17856.17856] INFO AudioStreamManager: [0x55ddc9011cb0]: [Stream 3]: stream information have been fetched Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.214 [17856.17856] DEBUG MediaEngine: [0x55ddc9011b50]: Current stream changed state: Created -> Info Retrieved Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.237 [17856.17856] INFO AudioStreamManager: [0x55ddc9011cb0]: [Stream 4]: stream information have been fetched Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.237 [17856.17856] DEBUG MediaEngine: [0x55ddc9011b50]: Next stream changed state: Created -> Info Retrieved Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.284 [17856.17856] DEBUG PlaybackEventReporter: [0x55ddc9012a10]: Streaming report submitted successfully Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.318 [17856.17856] INFO AudioStreamManager: [0x55ddc9011cb0]: [Stream 3]: track URL resolved to: https://streaming-qobuz-std.akamaized.net/file?uid=789598&eid=29686416&fmt=7&profile=raw&app_id=500827169&cid=1302541&etsp=1730040667&hmac=hAl1NXnR7tGWkFlkVZXOHo5teBU Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.318 [17856.17856] INFO UrlAudioSource: [0x55ddc9259350]: Starting URL audio source, URL: https://streaming-qobuz-std.akamaized.net/file?uid=789598&eid=29686416&fmt=7&profile=raw&app_id=500827169&cid=1302541&etsp=1730040667&hmac=hAl1NXnR7tGWkFlkVZXOHo5teBU Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.318 [17856.17856] TRACE AudioSource: [0x55ddc9259350]: State changed: Idle -> Running Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.318 [17856.17856] DEBUG Ringbuffer: [0x55ddc9162d90]: Creating Audio Ringbuffer Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.318 [17856.17856] INFO ContentFetcher: [0x55ddc903a510]: Fetching content from: https://streaming-qobuz-std.akamaized.net/file?uid=789598&eid=29686416&fmt=7&profile=raw&app_id=500827169&cid=1302541&etsp=1730040667&hmac=hAl1NXnR7tGWkFlkVZXOHo5teBU, offset: 0 Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.318 [17856.17856] DEBUG MediaEngine: [0x55ddc9011b50]: Current stream changed state: Info Retrieved -> Running Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.318 [17856.17856] INFO SampleApp: [Stream 3]: New audio stream Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.318 [17856.17856] TRACE SampleApp: Wrote { Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: "delegate": "audio_source_manager", Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: "function": "audio_stream_started", Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: "args": { Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: "id": 3, Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: "duration": 283061, Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: "sample_rate": 44100, Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: "channels": 2, Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: "sample_format": "S24LE" Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: } Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: } Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: on unix socket Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.318 [17856.17856] INFO SampleApp: [Stream 3]: Stream metadata became available: Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.318 [17856.17856] INFO SampleApp: Title: Polymorphing Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.318 [17856.17856] INFO SampleApp: Artist: Chairlift Oct 27 14:51:07 volumiox86 volumio[17560]: { Oct 27 14:51:07 volumiox86 volumio[17560]: "delegate": "audio_source_manager", Oct 27 14:51:07 volumiox86 volumio[17560]: "function": "audio_stream_started", Oct 27 14:51:07 volumiox86 volumio[17560]: "args": { Oct 27 14:51:07 volumiox86 volumio[17560]: "id": 3, Oct 27 14:51:07 volumiox86 volumio[17560]: "duration": 283061, Oct 27 14:51:07 volumiox86 volumio[17560]: "sample_rate": 44100, Oct 27 14:51:07 volumiox86 volumio[17560]: "channels": 2, Oct 27 14:51:07 volumiox86 volumio[17560]: "sample_format": "S24LE" Oct 27 14:51:07 volumiox86 volumio[17560]: } Oct 27 14:51:07 volumiox86 volumio[17560]: } Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.319 [17856.17856] INFO SampleApp: Album: Moth Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.319 [17856.17856] INFO SampleApp: Album art URL: https://static.qobuz.com/images/covers/36/12/0886445231236_600.jpg Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.319 [17856.17856] TRACE SampleApp: Wrote { Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: "delegate": "audio_source_manager", Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: "function": "audio_stream_metadata", Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: "args": { Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: "id": 3, Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: "title": "Polymorphing", Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: "artist": "Chairlift", Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: "album": "Moth", Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: "album_art_url": "https://static.qobuz.com/images/covers/36/12/0886445231236_600.jpg" Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: } Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: } Oct 27 14:51:07 volumiox86 volumio[17560]: { Oct 27 14:51:07 volumiox86 volumio[17560]: "delegate": "audio_source_manager", Oct 27 14:51:07 volumiox86 volumio[17560]: "function": "audio_stream_metadata", Oct 27 14:51:07 volumiox86 volumio[17560]: "args": { Oct 27 14:51:07 volumiox86 volumio[17560]: "id": 3, Oct 27 14:51:07 volumiox86 volumio[17560]: "title": "Polymorphing", Oct 27 14:51:07 volumiox86 volumio[17560]: "artist": "Chairlift", Oct 27 14:51:07 volumiox86 volumio[17560]: "album": "Moth", Oct 27 14:51:07 volumiox86 volumio[17560]: "album_art_url": "https://static.qobuz.com/images/covers/36/12/0886445231236_600.jpg" Oct 27 14:51:07 volumiox86 volumio[17560]: } Oct 27 14:51:07 volumiox86 volumio[17560]: } Oct 27 14:51:07 volumiox86 volumio[17560]: info: CoreCommandRouter::volumioGetState Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: on unix socket Oct 27 14:51:07 volumiox86 volumio[17560]: info: CorePlayQueue::getTrack 0 Oct 27 14:51:07 volumiox86 volumio[17560]: info: QobuzConnect: Currently active service: mpd Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.626 [17856.17856] INFO UrlAudioSource: [0x55ddc9259350]: Content info extracted Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.626 [17856.17856] INFO UrlAudioSource: [0x55ddc9259350]: Size: 57445957 Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.628 [17856.18014] INFO AudioDecoder: [0x55ddc92b7730]: Stream info: Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.628 [17856.18014] INFO AudioDecoder: [0x55ddc92b7730]: Total samples: 12483029 Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.628 [17856.18014] INFO AudioDecoder: [0x55ddc92b7730]: Sample rate: 44100 Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.628 [17856.18014] INFO AudioDecoder: [0x55ddc92b7730]: Channel count: 2 Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.628 [17856.18014] INFO AudioDecoder: [0x55ddc92b7730]: Bits per sample: 24 Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.628 [17856.18014] INFO AudioDecoder: [0x55ddc92b7730]: Duration: 283061 Oct 27 14:51:07 volumiox86 qobuz-connect[17856]: 20241027 14:51:07.629 [17856.17856] INFO UrlAudioSource: [0x55ddc9259350]: Audio properties have changed Oct 27 14:51:08 volumiox86 volumio[17560]: info: QobuzConnect: -- promise resolved -- Oct 27 14:51:09 volumiox86 volumio[17560]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 27 14:51:09 volumiox86 volumio[17560]: TypeError: Cannot read property 'resolve' of undefined Oct 27 14:51:09 volumiox86 volumio[17560]: at Timeout._onTimeout (/home/volumio/qobuz-connect-plugin/index.js:299:15) Oct 27 14:51:09 volumiox86 volumio[17560]: at listOnTimeout (internal/timers.js:557:17) Oct 27 14:51:09 volumiox86 volumio[17560]: at processTimers (internal/timers.js:500:7) Oct 27 14:51:09 volumiox86 volumio[17560]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 27 14:51:09 volumiox86 sudo[18024]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-10-27 14:50 Oct 27 14:51:09 volumiox86 sudo[18024]: 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="4b122b2365bb8c09786cd63b50d1ea6db780eb4e" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="49f98390f2d84c6549f33dc85b694fbd99e4c720" VOLUMIO_ARCH="x64" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 04 Jun 2024 09:13:11 PM CEST" VOLUMIO_VERSION="3.703" VOLUMIO_HARDWARE="x86_amd64" VOLUMIO_DEVICENAME="x86_64" VOLUMIO_HASH="ac782621640fcc70c07e91a81b6d958b"