Slow (>10000ms) Qobuz API GET response kills Qobuz AND TIDAL playback

Chris_Lewicki · April 6, 2023, 7:11pm

Roon Core Machine

Ubuntu 22.04.2 LTS running on 8-Core ESXi VM 32GB RAM, on Intel(R) Xeon(R) CPU E5-2640 v3 @ 2.60GHz

Networking Gear & Setup Details

Core connected to MacOS Client via 10Gbe connection on Ubiquity USW-Aggregation

Connected Audio Devices

PS Audio Sprout (original version)
Connected via XMOS USB 2.0 Audio Out, CoreAudio Exclusive mode

Number of Tracks in Library

~20,000 tracks

Description of Issue

I regularly experience Roon appearing to loose connection (with something) and the song stopping mid-playback. The playbar shows “Nothing playing” at this point, and after about ~90 seconds, I’m able to press play to continue the song where it was interrupted.

The playback queue shows as “empty” during this period, which means that I can’t examine the client to figure out if it was a Qobuz or Tidal song that caused the problem until the track returns after 90 seconds.

I experienced this problem about 14 times across ~4 hours of playback today, I don’t have this problem when playing local content, and a speedtest to the internet during this period shows 420Mbps down / 20.5Mbps up. All devices are hard wired.

It happens for both Qobuz and Tidal, but the reasons seem different. The Qobuz error appears to clearly be a streaming timeout, but the Tidal problems are less obvious.

In examining the logs on both the Client and the Core, it appears that this behavior is triggered with a GET request to the Qobuz API server takes longer than 10000ms to respond. Oddly enough, while debugging the issue for this blog post, and playing 4 test songs on either Qobuz or TIDAL (both are connected, at the highest resolution available), I found that a GET query was still being made to Qobuz during TIDAL playback, and the slow query response Qobuz (not playing) would cause the TIDAL playback to stop!

For the Qobuz interruption, here’s what the logs look like around the problem:

Client RAATServer_log.txt

04/06 10:41:36 Trace: [RAAT::XMOS USB 2.0 Audio Out] [lua@0x11800e008] [10.41.41.10:57580]  SENT [6] {"status":"Success","audio_port":0,"audio_port_tcp":55819,"clock_port":54397}
04/06 10:41:38 Trace: [RAAT::XMOS USB 2.0 Audio Out] [lua@0x11800e008] [10.41.41.10:57580]  GOT [7] {"request":"stream","stream_id":144243657,"first_seq":-1,"nak_port":-1,"buffer_size":10,"ready_threshold":0.2}
04/06 10:41:38 Trace: [RAAT::XMOS USB 2.0 Audio Out] [lua@0x11800e008] [10.41.41.10:57580]  SENT [7] {"status":"Buffering"}
04/06 10:41:38 Trace: [RAAT::XMOS USB 2.0 Audio Out] [lua@0x11800e008] [10.41.41.10:57580]  SENT [7] {"status":"Ready"}
04/06 10:41:38 Trace: [RAAT::XMOS USB 2.0 Audio Out] [lua@0x11800e008] [10.41.41.10:57580]  GOT [8] {"request":"start","min_offset":123010416,"stream_sample":0}
04/06 10:41:38 Trace: [RAAT::XMOS USB 2.0 Audio Out] [lua@0x11800e008] [10.41.41.10:57580]  Doing ASAP start based on current device clock (min_offset=123010416)
04/06 10:41:38 Trace: [RAAT::XMOS USB 2.0 Audio Out] [lua@0x11800e008] [10.41.41.10:57580]  SENT [7] {"status":"Playing"}
04/06 10:41:38 Trace: [RAAT::XMOS USB 2.0 Audio Out] [lua@0x11800e008] [10.41.41.10:57580]  SENT [8] {"status":"Success","time":1042459015833}
04/06 10:41:38 Trace: [RAAT::XMOS USB 2.0 Audio Out] [coreaudio] waiting for start time...
04/06 10:41:38 Trace: [RAAT::XMOS USB 2.0 Audio Out] [coreaudio] starting playback: now (1042432000000ns) + ns_per_buf(42666666ns) = 1042474666666ns > 1042459015833ns streamsample=0
04/06 10:45:55 Trace: [jsonserver] [10.41.41.10:58842] read: eof
04/06 10:45:55 Trace: [jsonserver] [10.41.41.10:58842] destroying client
04/06 10:45:55 Trace: [RAAT::XMOS USB 2.0 Audio Out] [server] [10.41.41.10:57580] read error: connection reset by peer
04/06 10:45:55 Trace: [RAAT::XMOS USB 2.0 Audio Out] [server] [10.41.41.10:57580] destroying client
04/06 10:45:55 Trace: [RAAT::XMOS USB 2.0 Audio Out] [session] [10.41.41.10:57580] destroying session
04/06 10:45:55 Trace: [RAAT::XMOS USB 2.0 Audio Out] [lua@0x11800e008] [10.41.41.10:57580]  SENT [7] {"status":"Ended"}
04/06 10:45:55 Trace: [RAAT::XMOS USB 2.0 Audio Out] [coreaudio] teardown
04/06 10:45:55 Trace: [jsonserver] [10.41.40.10:40884] accepted connection
04/06 10:45:56 Warn: [RAAT::XMOS USB 2.0 Audio Out] [server] failed to write to 10.41.41.10:57580: broken pipe. Closing connection.

MacOS Client Roon_log.txt during the same window

04/06 10:41:35 Trace: [platformnowplaying/mac] MPNowPlayingInfoCenter: Connect
04/06 10:41:45 Info: [stats] 403683mb Virtual, 740mb Physical, 218mb Managed
04/06 10:41:46 Debug: KEYDOWN: TAB
04/06 10:41:46 Debug: testing key with win_main(206)
04/06 10:41:46 Debug: window handled key
04/06 10:42:00 Info: [stats] 403686mb Virtual, 740mb Physical, 217mb Managed
04/06 10:42:15 Info: [stats] 403685mb Virtual, 740mb Physical, 219mb Managed
04/06 10:42:30 Info: [stats] 403690mb Virtual, 740mb Physical, 220mb Managed
04/06 10:42:45 Info: [stats] 403691mb Virtual, 740mb Physical, 220mb Managed
04/06 10:43:00 Trace: [broker/accounts] [heartbeat] now=4/6/2023 5:43:00 PM nextauthrefresh=4/6/2023 6:13:00 PM nextmachineallocate=4/6/2023 9:13:00 PM
04/06 10:43:00 Info: [stats] 403690mb Virtual, 741mb Physical, 221mb Managed
04/06 10:43:15 Info: [stats] 403690mb Virtual, 741mb Physical, 222mb Managed
04/06 10:43:30 Info: [stats] 403690mb Virtual, 741mb Physical, 222mb Managed
04/06 10:43:45 Info: [stats] 403691mb Virtual, 741mb Physical, 223mb Managed
04/06 10:44:00 Info: [stats] 403687mb Virtual, 741mb Physical, 225mb Managed
04/06 10:44:15 Info: [stats] 403685mb Virtual, 740mb Physical, 217mb Managed
04/06 10:44:30 Info: [stats] 403685mb Virtual, 741mb Physical, 218mb Managed
04/06 10:44:45 Info: [stats] 403677mb Virtual, 740mb Physical, 218mb Managed
04/06 10:45:00 Info: [stats] 403684mb Virtual, 740mb Physical, 219mb Managed
04/06 10:45:15 Info: [stats] 403685mb Virtual, 740mb Physical, 220mb Managed
04/06 10:45:30 Info: [stats] 403685mb Virtual, 741mb Physical, 221mb Managed
04/06 10:45:45 Info: [stats] 403678mb Virtual, 740mb Physical, 220mb Managed
04/06 10:45:56 Trace: [platformnowplaying/mac] MPNowPlayingInfoCenter: Disconnect
04/06 10:45:56 Trace: [platformnowplaying/mac] MPNowPlayingInfoCenter: Connect
04/06 10:45:56 Debug: GMS: saving nav stack
04/06 10:45:56 Debug: GMS: done saving nav stack
04/06 10:45:56 Trace: [platformnowplaying/mac] MPNowPlayingInfoCenter: Connect

Linux RoonServer_log.txt (UTC times, so add 7 hours to PST

04/06 17:45:50 Trace: [Sprout XMOS USB 2.0] [Enhanced, 24/96 QOBUZ FLAC => 24/96] [100% buf] [PLAYING @ 5:57/7:39] 72 Seasons - Metallica                                                  
04/06 17:45:53 Trace: [library] endmutation in 53ms                                                                                                                                        
04/06 17:45:55 Trace: [Sprout XMOS USB 2.0] [Enhanced, 24/96 QOBUZ FLAC => 24/96] [100% buf] [PLAYING @ 6:03/7:39] 72 Seasons - Metallica                                                  
04/06 17:45:55 Trace: [rnet/RnetJsonClient] no data received for >10000ms. Killing connection.                                                                                             
04/06 17:45:55 Trace: [raatserver] [RaatServer plex @ 127.0.0.1:9200] lost client connection. Retrying                                                                                     
04/06 17:45:55 Trace: [raatserver] [RaatServer plex @ 127.0.0.1:9200] connecting (attempt 1)                                                                                               
04/06 17:45:55 Trace: [rnet/RnetJsonClient] no data received for >10000ms. Killing connection.                                                                                             
04/06 17:45:55 Trace: [raatserver] [RaatServer ChriBook-Pro-2 @ 10.41.40.245:9200] lost client connection. Retrying                                                                        
04/06 17:45:55 Trace: [raatserver] [RaatServer ChriBook-Pro-2 @ 10.41.40.245:9200] connecting (attempt 1)                                                                                  
04/06 17:45:55 Trace: [zone Sprout XMOS USB 2.0] Suspend                                                                                                                                   
04/06 17:45:55 Debug: FTMSI-B closed file for qo/7577EAA1; open files:0                                                                                                                    
04/06 17:45:55 Trace: [Sprout XMOS USB 2.0] [zoneplayer/raat] Endpoint XMOS USB 2.0 Audio Out State Changed: Playing => Prepared                                                           
04/06 17:45:55 Debug: FTMSI-B qo/7577EAA1 download status: EndOfFileReached accessTimeout:False openFiles:0 prev:(EndOfFileReached,False,1)                                                
04/06 17:45:55 Debug: [raat/tcpaudiosource] disconnecting                                                                                                                                  
04/06 17:45:55 Trace: [Sprout XMOS USB 2.0] [zoneplayer/raat] Endpoint XMOS USB 2.0 Audio Out State Changed: Prepared => Idle                                                              
04/06 17:45:56 Error: getting null client....                                                                                                                                              
04/06 17:45:56 Trace: [raatserver] [RaatServer plex @ 127.0.0.1:9200] connected                                                                                                            
04/06 17:45:56 Trace: [rnet/RnetJsonClient] SENT {"request":"enumerate_devices","subscription_id":"0"}                                                                                     ┤
04/06 17:45:56 Trace: [raatserver] [RaatServer ChriBook-Pro-2 @ 10.41.40.245:9200] connected                                                                                               
04/06 17:45:56 Trace: [rnet/RnetJsonClient] SENT {"request":"enumerate_devices","subscription_id":"0"}                                                                                     
04/06 17:45:56 Trace: [rnet/RnetJsonClient] GOT NONFINAL {"devices": [], "status": "Success"}                                                                                              
04/06 17:45:56 Trace: [rnet/RnetJsonClient] GOT NONFINAL {"status": "Success", "devices": [{"device_id": "10ACBD40-0000-0000-3219-0104A53C2278", "type": "coreaudio", "name": "DELL P2715Q"
04/06 17:45:56 Trace: [rnet/RnetJsonClient] SENT {"request":"enable_device","device_id":"AppleUSBAudioEngine:XMOS :XMOS USB Audio 2.0:3123000:1","subscription_id":"156"}                  
04/06 17:45:56 Trace: [rnet/RnetJsonClient] GOT NONFINAL {"status": "Success"}                                                                                                             
04/06 17:45:56 Trace: [XMOS USB 2.0 Audio Out] [raatclient] Initializing RAAT session                                                                                                      
04/06 17:45:57 Trace: [library] endmutation in 1082ms
04/06 17:45:57 Debug: [easyhttp] [35849] POST to https://www.qobuz.com/api.json/0.2/track/reportStreamingEnd? returned after 1676 ms, status code: 200, request body size: 362 B
04/06 17:45:58 Debug: [easyhttp] [35848] GET to https://www.qobuz.com/api.json/0.2/user/login?request_sig=93d93191e925b8bee2d30b67a0f93f51&request_ts=1680803143 returned after 12858 ms, sta
tus code: 200, request body size: 0 B
04/06 17:46:02 Trace: [library] endmutation in 680ms
04/06 17:46:02 Info: [stats] 31990mb Virtual, 13602mb Physical, 5060mb Managed, 1011 Handles, 243 Threads
04/06 17:46:06 Debug: [easyhttp] [35850] POST to https://api.roonlabs.net/device-map/1/register returned after 236 ms, status code: 200, request body size: 8 KB
04/06 17:46:06 Trace: [devicemap] device map updated

To debug the behavior I tried playing the same tracks in TIDAL, and experienced a similar problem. This song exhibited the same behavior right at the end of the song.

Roon Core RoonServer_log.txt

04/06 18:45:28 Info: [stats] 31202mb Virtual, 13532mb Physical, 4850mb Managed, 1021 Handles, 147 Threads
04/06 18:45:32 Trace: [Sprout XMOS USB 2.0] [Enhanced 60.7x, 24/48 MQA TIDAL FLAC => 24/48] [100% buf] [PLAYING @ 5:08/5:30] Screaming Suicide - Metallica
04/06 18:45:37 Trace: [Sprout XMOS USB 2.0] [Enhanced 60.8x, 24/48 MQA TIDAL FLAC => 24/48] [100% buf] [PLAYING @ 5:13/5:30] Screaming Suicide - Metallica
04/06 18:45:38 Trace: [Sprout XMOS USB 2.0] [zoneplayer/raat] sync XMOS USB 2.0 Audio Out: realtime=5918269962708 rtt=1500us offset=5036438962us delta=53us drift=497us in 519.775s (0.957ppm, 3.445ms/hr)
04/06 18:45:38 Trace: [prebuffer] short read: 0 / 9600 fill=472960
04/06 18:45:42 Trace: [Sprout XMOS USB 2.0] [Enhanced 60.9x, 24/48 MQA TIDAL FLAC => 24/48] [72% buf] [PLAYING @ 5:18/5:30] Screaming Suicide - Metallica
04/06 18:45:43 Info: [stats] 31202mb Virtual, 13532mb Physical, 4892mb Managed, 1021 Handles, 146 Threads
04/06 18:45:43 Trace: [roondns] flushed 21 last-known-good entries
04/06 18:45:47 Trace: [Sprout XMOS USB 2.0] [Enhanced 61.0x, 24/48 MQA TIDAL FLAC => 24/48] [18% buf] [PLAYING @ 5:22/5:30] Screaming Suicide - Metallica
04/06 18:45:49 Trace: [prebuffer] ready 163200/480000 (34%) @ 0/396 sec
04/06 18:45:49 Info:
--[ SignalPath ]---------------------------------------------
SignalPath Quality = Enhanced
Elements:
    Source Format=Flac 48000/24/2  Quality=Lossless MQA 96000
    MQA Subtype=authentication LightState=authored OriginalSampleRate=96000 OutputSampleRate= OutputBitsPerSample=
    UpgradeBitDepth FromBitsPerSample=24 ToBitsPerSample=64 Quality=Lossless
    VolumeNormaliation GainDb=-5.16 Quality=Enhanced
    Truncate FromBitsPerSample=64 ToBitsPerSample=24 Quality=Lossless
    Raat Device=XMOS USB 2.0 Audio Out
    Output OutputType=Local_ExclusiveMode_CoreAudio Quality=Lossless SubType= Model=XMOS USB 2.0 Audio Out
------------------------------------------------------------
04/06 18:45:53 Trace: [Sprout XMOS USB 2.0] [Enhanced 61.1x, 24/48 MQA TIDAL FLAC => 24/48] [2% buf] [PLAYING @ 5:29/5:30] Screaming Suicide - Metallica
04/06 18:45:53 Trace: [rnet/RnetJsonClient] no data received for >10000ms. Killing connection.
04/06 18:45:53 Trace: [raatserver] [RaatServer ShopMac @ 10.41.40.161:9200] lost client connection. Retrying
04/06 18:45:53 Trace: [raatserver] [RaatServer ShopMac @ 10.41.40.161:9200] connecting (attempt 1)
04/06 18:45:53 Info: [transport] destroyed zone ShopMac was playing? False
04/06 18:45:53 Trace: [zone ShopMac] Suspend
04/06 18:45:53 Info: [zone ShopMac] Canceling Pending Sleep
04/06 18:45:53 Info: [zone ShopMac] Canceling Pending Sleep
04/06 18:45:53 Trace: [rnet/RnetJsonClient] no data received for >10000ms. Killing connection.
04/06 18:45:53 Trace: [raatserver] [RaatServer ChriBook-Pro-2 @ 10.41.40.245:9200] lost client connection. Retrying
04/06 18:45:53 Trace: [raatserver] [RaatServer ChriBook-Pro-2 @ 10.41.40.245:9200] connecting (attempt 1)
04/06 18:45:53 Info: [transport] destroyed zone Sprout XMOS USB 2.0 was playing? True
04/06 18:45:53 Trace: [zone Sprout XMOS USB 2.0] Suspend
04/06 18:45:53 Info:
--[ SignalPath ]---------------------------------------------
SignalPath Quality = Enhanced
Elements:
    Source Format=Flac 48000/24/2  Quality=Lossless MQA 96000
    MQA Subtype=authentication LightState=authored OriginalSampleRate=96000 OutputSampleRate= OutputBitsPerSample=
    UpgradeBitDepth FromBitsPerSample=24 ToBitsPerSample=64 Quality=Lossless
    VolumeNormaliation GainDb=-5.16 Quality=Enhanced
    Truncate FromBitsPerSample=64 ToBitsPerSample=24 Quality=Lossless
    Raat Device=XMOS USB 2.0 Audio Out
    Output OutputType=Local_ExclusiveMode_CoreAudio Quality=Lossless SubType= Model=XMOS USB 2.0 Audio Out
------------------------------------------------------------
04/06 18:45:53 Info: MQA authentication
04/06 18:45:53 Info: [zone Sprout XMOS USB 2.0] OnPlayFeedback Stopped
04/06 18:45:53 Info: [zone Sprout XMOS USB 2.0] Canceling Pending Sleep
04/06 18:45:53 Info: [zone Sprout XMOS USB 2.0] Canceling Pending Sleep
04/06 18:45:53 Debug: [raat/tcpaudiosource] disconnecting
04/06 18:45:53 Info: [Sprout XMOS USB 2.0] [zoneplayer] BufferingTrack == NextTrack during ClearQueuedMedia, setting _stop_on_next_track_transition
04/06 18:45:53 Debug: FTMSI-B closed file for ti/EFCC0AED; open files:0
04/06 18:45:53 Debug: FTMSI-B ti/EFCC0AED download status: AllBlocksDownloaded accessTimeout:False openFiles:0 prev:(AllBlocksDownloaded,True,1)
04/06 18:45:53 Trace: [Sprout XMOS USB 2.0] [zoneplayer/raat] Endpoint XMOS USB 2.0 Audio Out State Changed: Playing => Prepared
04/06 18:45:53 Debug: FTMSI-B closed file for ti/FCE44A7B; open files:0
04/06 18:45:53 Info: [audio/env] [zoneplayer -> stream] All streams were disposed
04/06 18:45:53 Info: [audio/env] [zoneplayer -> stream -> endpoint] All streams were disposed
04/06 18:45:53 Debug: FTMSI-B ti/FCE44A7B download status: AllBlocksDownloaded accessTimeout:True openFiles:0 prev:(AllBlocksDownloaded,True,1)
04/06 18:45:53 Info: [audio/env] [zoneplayer] All streams were disposed
04/06 18:45:54 Info: sleep 103ms after flush
04/06 18:45:54 Error: getting null client....
04/06 18:45:54 Trace: [rnet/RnetJsonClient] no data received for >10000ms. Killing connection.
04/06 18:45:54 Trace: [raatserver] [RaatServer plex @ 127.0.0.1:9200] lost client connection. Retrying
04/06 18:45:54 Trace: [raatserver] [RaatServer plex @ 127.0.0.1:9200] connecting (attempt 1)
04/06 18:45:54 Info: [transport/zonedisplay] Zone display unregistered: CastDevice[DeviceId=Chromecast-Ultra-2592cd1b50334968acd77c44d2c999fe._googlecast._tcp.local, Name=Chromecast Ultra, Address=10.41.40.18]
04/06 18:45:54 Info: [cast] lost device CastDevice[DeviceId=Chromecast-Ultra-2592cd1b50334968acd77c44d2c999fe._googlecast._tcp.local, Name=Chromecast Ultra, Address=10.41.40.18] because it disconnected
04/06 18:45:55 Trace: [raatserver] [RaatServer ShopMac @ 10.41.40.161:9200] connected
04/06 18:45:55 Trace: [rnet/RnetJsonClient] SENT {"request":"enumerate_devices","subscription_id":"0"}
04/06 18:45:55 Trace: [raatserver] [RaatServer ChriBook-Pro-2 @ 10.41.40.245:9200] connected
04/06 18:45:55 Trace: [rnet/RnetJsonClient] SENT {"request":"enumerate_devices","subscription_id":"0"}
04/06 18:45:55 Trace: [raatserver] [RaatServer plex @ 127.0.0.1:9200] connected
04/06 18:45:55 Trace: [rnet/RnetJsonClient] SENT {"request":"enumerate_devices","subscription_id":"0"}
04/06 18:45:55 Trace: [rnet/RnetJsonClient] GOT NONFINAL {"devices": [], "status": "Success"}

Another TIDAL failure while I write this post, 7 seconds into a song RoonServer_log.txt

04/06 19:00:38 Trace: [Sprout XMOS USB 2.0] [Enhanced 71.6x, 24/48 MQA TIDAL FLAC => 24/48] [24% buf] [PLAYING @ 6:28/6:36] If Darkness Had a Son - Metallica
04/06 19:00:41 Trace: [prebuffer] ready 163200/480000 (34%) @ 0/459 sec
04/06 19:00:42 Info:
--[ SignalPath ]---------------------------------------------
SignalPath Quality = Enhanced
Elements:
    Source Format=Flac 48000/24/2  Quality=Lossless MQA 96000
    MQA Subtype=authentication LightState=authored OriginalSampleRate=96000 OutputSampleRate= OutputBitsPerSample=
    UpgradeBitDepth FromBitsPerSample=24 ToBitsPerSample=64 Quality=Lossless
    VolumeNormaliation GainDb=-5.640000000000001 Quality=Enhanced
    Truncate FromBitsPerSample=64 ToBitsPerSample=24 Quality=Lossless
    Raat Device=XMOS USB 2.0 Audio Out
    Output OutputType=Local_ExclusiveMode_CoreAudio Quality=Lossless SubType= Model=XMOS USB 2.0 Audio Out
------------------------------------------------------------
04/06 19:00:44 Trace: [Sprout XMOS USB 2.0] [Enhanced 71.5x, 24/48 MQA TIDAL FLAC => 24/48] [PLAYING @ 6:34/6:36] If Darkness Had a Son - Metallica
04/06 19:00:45 Trace: [roondns] flushed 21 last-known-good entries
04/06 19:00:45 Info: [stats] 31936mb Virtual, 13577mb Physical, 5361mb Managed, 1039 Handles, 241 Threads
04/06 19:00:47 Debug: FTMSI-B closed file for ti/2D1B91D1; open files:0
04/06 19:00:47 Debug: FTMSI-B ti/2D1B91D1 download status: AllBlocksDownloaded accessTimeout:True openFiles:0 prev:(AllBlocksDownloaded,False,1)
04/06 19:00:47 Info:
--[ SignalPath ]---------------------------------------------
SignalPath Quality = Enhanced
Elements:
    Source Format=Flac 48000/24/2  Quality=Lossless MQA 96000
    MQA Subtype=authentication LightState=authored OriginalSampleRate=96000 OutputSampleRate= OutputBitsPerSample=
    UpgradeBitDepth FromBitsPerSample=24 ToBitsPerSample=64 Quality=Lossless
    VolumeNormaliation GainDb=-5.640000000000001 Quality=Enhanced
    Truncate FromBitsPerSample=64 ToBitsPerSample=24 Quality=Lossless
    Raat Device=XMOS USB 2.0 Audio Out
    Output OutputType=Local_ExclusiveMode_CoreAudio Quality=Lossless SubType= Model=XMOS USB 2.0 Audio Out
------------------------------------------------------------
04/06 19:00:47 Info: MQA authentication
04/06 19:00:47 Info: [zone Sprout XMOS USB 2.0] OnPlayFeedback OnToNext
04/06 19:00:47 Debug: [zone Sprout XMOS USB 2.0] _Advance (Track)
04/06 19:00:47 Debug: [query] Sooloos.Broker.Transport.TransportItem: 2112 dirty items. rebuilding query instead of re-sorting item-by-item (internaltype=TransportItem)
04/06 19:00:47 Debug: [query] Sooloos.Broker.Transport.TransportItem: 2112 dirty items. rebuilding query instead of re-sorting item-by-item (internaltype=TransportItem)
04/06 19:00:47 Info: [zone Sprout XMOS USB 2.0] OnPlayFeedback Playing
04/06 19:00:47 Info:
--[ SignalPath ]---------------------------------------------
SignalPath Quality = Enhanced
Elements:
    Source Format=Flac 48000/24/2  Quality=Lossless MQA 96000
    MQA Subtype=authentication LightState=authored OriginalSampleRate=96000 OutputSampleRate= OutputBitsPerSample=
    UpgradeBitDepth FromBitsPerSample=24 ToBitsPerSample=64 Quality=Lossless
    VolumeNormaliation GainDb=-5.640000000000001 Quality=Enhanced
    Truncate FromBitsPerSample=64 ToBitsPerSample=24 Quality=Lossless
    Raat Device=XMOS USB 2.0 Audio Out
    Output OutputType=Local_ExclusiveMode_CoreAudio Quality=Lossless SubType= Model=XMOS USB 2.0 Audio Out
------------------------------------------------------------
04/06 19:00:49 Trace: [Sprout XMOS USB 2.0] [Enhanced 71.6x, 24/48 MQA TIDAL FLAC => 24/48] [100% buf] [PLAYING @ 0:02/7:39] 72 Seasons - Metallica
04/06 19:00:54 Trace: [rnet/RnetJsonClient] no data received for >10000ms. Killing connection.
04/06 19:00:54 Trace: [rnet/RnetJsonClient] no data received for >10000ms. Killing connection.
04/06 19:00:54 Trace: [raatserver] [RaatServer plex @ 127.0.0.1:9200] lost client connection. Retrying
04/06 19:00:54 Trace: [raatserver] [RaatServer plex @ 127.0.0.1:9200] connecting (attempt 1)
04/06 19:00:54 Trace: [raatserver] [RaatServer ChriBook-Pro-2 @ 10.41.40.245:9200] lost client connection. Retrying
04/06 19:00:54 Trace: [raatserver] [RaatServer ChriBook-Pro-2 @ 10.41.40.245:9200] connecting (attempt 1)
04/06 19:00:54 Info: [transport] destroyed zone Sprout XMOS USB 2.0 was playing? True
04/06 19:00:54 Trace: [zone Sprout XMOS USB 2.0] Suspend
04/06 19:00:54 Info: [zone Sprout XMOS USB 2.0] OnPlayFeedback Stopped
04/06 19:00:54 Debug: FTMSI-B closed file for ti/540ECA49; open files:0
04/06 19:00:54 Trace: [Sprout XMOS USB 2.0] [zoneplayer/raat] Endpoint XMOS USB 2.0 Audio Out State Changed: Playing => Prepared
04/06 19:00:54 Debug: FTMSI-B ti/540ECA49 download status: AllBlocksDownloaded accessTimeout:False openFiles:0 prev:(AllBlocksDownloaded,False,1)
04/06 19:00:54 Debug: [raat/tcpaudiosource] disconnecting
04/06 19:00:54 Info: [audio/env] [zoneplayer -> stream] All streams were disposed
04/06 19:00:54 Info: [zone Sprout XMOS USB 2.0] Canceling Pending Sleep
04/06 19:00:54 Trace: [Sprout XMOS USB 2.0] [zoneplayer/raat] Endpoint XMOS USB 2.0 Audio Out State Changed: Prepared => Idle
04/06 19:00:54 Info: [audio/env] [zoneplayer] All streams were disposed
04/06 19:00:54 Info: [audio/env] [zoneplayer -> stream -> endpoint] All streams were disposed
04/06 19:00:54 Info: sleep 103ms after flush
04/06 19:00:54 Error: getting null client....
04/06 19:00:55 Warn: [raat/tcpaudiosource] send failed: Object reference not set to an instance of an object.
04/06 19:00:55 Trace: [mobile] [remoteconnectivity] Port Verification started due to: nat-pmp device at ip 10.41.41.1 restarted, port verification not in progress, starting a new attempt
04/06 19:00:55 Trace: [raatserver] [RaatServer plex @ 127.0.0.1:9200] connected
04/06 19:00:55 Trace: [rnet/RnetJsonClient] SENT {"request":"enumerate_devices","subscription_id":"0"}
04/06 19:00:55 Warn: [raat/tcpaudiosource] disconnecting + retrying
04/06 19:00:55 Trace: [raatserver] [RaatServer ChriBook-Pro-2 @ 10.41.40.245:9200] connected
04/06 19:00:55 Trace: [rnet/RnetJsonClient] SENT {"request":"enumerate_devices","subscription_id":"0"}
04/06 19:00:55 Trace: [rnet/RnetJsonClient] GOT NONFINAL {"devices": [], "status": "Success"}
04/06 19:00:55 Trace: [rnet/RnetJsonClient] GOT NONFINAL {"status": "Success", "devices": [{"device_id": "10ACBD40-0000-0000-3219-0104A53C2278", "type": "coreaudio", "name": "DELL P2715Q", "vendor": "DEL"}, {"device_id": "AppleUSBAudioEngine:Apple Inc.:Studio Display:00008030-001C21260CD0802E:8,9", "type": "coreaudio", "name": "Studio Display Speakers", "vendor": "Apple Inc.", "usb_id": "05ac:1114"}, {"device_id": "AppleUSBAudioEngine:BEHRINGER:UMC404HD 192k:3122000:1,2", "type": "coreaudio", "name": "UMC404HD 192k", "vendor": "BEHRINGER", "usb_id": "1397:0509"}, {"device_id": "AppleUSBAudioEngine:XMOS :XMOS USB Audio 2.0:3123000:1", "type": "coreaudio", "discovery_data": {"tcp_port": 55390, "model": "N/A", "version": "N/A", "raat_version": "1.1.39", "unique_id": "25e406f3-d39b-f9ae-0a7e-88f51029e222", "protocol_version": "3", "vendor": "N/A"}, "name": "XMOS USB 2.0 Audio Out", "config": {"unique_id": "25e406f3-d39b-f9ae-0a7e-88f51029e222", "output": {"type": "coreaudio", "integer_mode": true, "exclusive_mode": true, "device": "AppleUSBAudioEngine:XMOS :XMOS USB Audio 2.0:3123000:1", "dsd_mode": "none", "use_power_of_two_buffer_size": true, "name": "XMOS USB 2.0 Audio Out"}, "volume": {"type": "coreaudio", "exclusive_mode": true, "device": "AppleUSBAudioEngine:XMOS :XMOS USB Audio 2.0:3123000:1"}, "external_config": {"resync_delay": 1}}, "vendor": "XMOS ", "usb_id": "2616:0112"}, {"device_id": "BuiltInSpeakerDevice", "type": "coreaudio", "name": "MacBook Pro Speakers", "config": {"external_config": {}, "volume": {"type": "coreaudio", "device": "BuiltInSpeakerDevice"}, "output": {"type": "coreaudio", "device": "BuiltInSpeakerDevice", "name": "MacBook Pro Speakers"}, "unique_id": "bbeea574-cbf7-c849-e23e-e2c3cdc5b0ba"}, "vendor": "Apple Inc."}, {"device_id": "MSLoopbackDriverDevice_UID", "type": "coreaudio", "name": "Microsoft Teams Audio", "vendor": "Microsoft Corp."}, {"device_id": "default", "type": "coreaudio", "name": "System Output", "is_system_output": true, "config": {"unique_id": "06c7872c-805f-70b7-89a5-e62b7c9f9802", "output": {"type": "coreaudio", "device": "default", "name": "System Output"}, "external_config": {}, "volume": {"type": "coreaudio", "device": "default"}}}]}
04/06 19:00:55 Info: [raatserver] GOT DEVICE b2d5ce33-d6a7-4f7e-b89e-21a8423319fe::10ACBD40-0000-0000-3219-0104A53C2278 Type=coreaudio Name=DELL P2715Q Vendor=DEL
04/06 19:00:55 Info: [raatserver] GOT DEVICE b2d5ce33-d6a7-4f7e-b89e-21a8423319fe::AppleUSBAudioEngine:Apple Inc.:Studio Display:00008030-001C21260CD0802E:8,9 Type=coreaudio Name=Studio Display Speakers Vendor=Apple Inc.UsbId=05ac:1114
04/06 19:00:55 Info: [raatserver] GOT DEVICE b2d5ce33-d6a7-4f7e-b89e-21a8423319fe::AppleUSBAudioEngine:BEHRINGER:UMC404HD 192k:3122000:1,2 Type=coreaudio Name=UMC404HD 192k Vendor=BEHRINGERUsbId=1397:0509
04/06 19:00:55 Info: [raatserver] GOT DEVICE b2d5ce33-d6a7-4f7e-b89e-21a8423319fe::AppleUSBAudioEngine:XMOS :XMOS USB Audio 2.0:3123000:1 Type=coreaudio Name=XMOS USB 2.0 Audio Out Vendor=XMOS UsbId=2616:0112
04/06 19:00:55 Info: [raatserver] GOT DEVICE b2d5ce33-d6a7-4f7e-b89e-21a8423319fe::BuiltInSpeakerDevice Type=coreaudio Name=MacBook Pro Speakers Vendor=Apple Inc.
04/06 19:00:55 Info: [raatserver] GOT DEVICE b2d5ce33-d6a7-4f7e-b89e-21a8423319fe::MSLoopbackDriverDevice_UID Type=coreaudio Name=Microsoft Teams Audio Vendor=Microsoft Corp.
04/06 19:00:55 Info: [raatserver] GOT DEVICE b2d5ce33-d6a7-4f7e-b89e-21a8423319fe::default Type=coreaudio Name=System Output
04/06 19:00:55 Trace: [rnet/RnetJsonClient] SENT {"request":"enable_device","device_id":"AppleUSBAudioEngine:XMOS :XMOS USB Audio 2.0:3123000:1","subscription_id":"162"}
04/06 19:00:55 Info: [raatserver] [XMOS USB 2.0 Audio Out] connecting (attempt 1)
04/06 19:00:55 Trace: [rnet/RnetJsonClient] GOT NONFINAL {"status": "Success"}
04/06 19:00:55 Trace: [XMOS USB 2.0 Audio Out] [raatclient] Initializing RAAT session

I’ve done various tuning of my setup over the years to respond to typical Roon problems, including running dnsmasq on the Core to help with DNS caching, per Why is Roon blasting my DNS server with requests? - #5 by maniac

I’m running a 1000ms Resync delay on my PS Audio Sprout MacOS core audio device as one effort to try and deal with the TIDAL pauses at the end of songs (thinking it was a re-sync problem - I often get “Zone not available” when trying to play when my machine has been idle for a long time, or when I wake it from sleep.

A few weeks back, while trying to debug this, I followed the procedures to make a backup of my Core, uninstall and re-install it, and restore the backup.

This has obviously made streaming via Roon a very frustrating experience. I guess I’ll try and listen to only local content, or use the dedicated Tidal App and Qobuz apps for streaming until I can resolve this.

Chris_Lewicki · April 6, 2023, 7:42pm

Here’s an example where it stopped playing a TIDAL 16/44 FLAC stream (19:30:53), and there’s a > 10000ms timeout error on a Qobuz GET request at the end of the process (19:30:55):

04/06 19:30:51 Trace: [Sprout XMOS USB 2.0] [Enhanced, 16/44 TIDAL FLAC => 24/44] [100% buf] [PLAYING @ 1:52/2:19] Èlizabeth - Deraps
04/06 19:30:53 Trace: [rnet/RnetJsonClient] no data received for >10000ms. Killing connection.
04/06 19:30:53 Trace: [raatserver] [RaatServer plex @ 127.0.0.1:9200] lost client connection. Retrying
04/06 19:30:53 Trace: [raatserver] [RaatServer plex @ 127.0.0.1:9200] connecting (attempt 1)
04/06 19:30:54 Info: [transport/zonedisplay] Zone display unregistered: CastDevice[DeviceId=Chromecast-Ultra-2592cd1b50334968acd77c44d2c999fe._googlecast._tcp.local, Name=Chromecast Ultra,
Address=10.41.40.18]
04/06 19:30:54 Info: [cast] lost device CastDevice[DeviceId=Chromecast-Ultra-2592cd1b50334968acd77c44d2c999fe._googlecast._tcp.local, Name=Chromecast Ultra, Address=10.41.40.18] because it
disconnected
04/06 19:30:55 Trace: [rnet/RnetJsonClient] no data received for >10000ms. Killing connection.
04/06 19:30:55 Trace: [raatserver] [RaatServer ShopMac @ 10.41.40.161:9200] lost client connection. Retrying
04/06 19:30:55 Trace: [raatserver] [RaatServer ShopMac @ 10.41.40.161:9200] connecting (attempt 1)
04/06 19:30:55 Info: [transport] destroyed zone ShopMac was playing? False
04/06 19:30:55 Trace: [zone ShopMac] Suspend
04/06 19:30:55 Info: [zone ShopMac] Canceling Pending Sleep
04/06 19:30:55 Info: [zone ShopMac] Canceling Pending Sleep
04/06 19:30:55 Trace: [rnet/RnetJsonClient] no data received for >10000ms. Killing connection.
04/06 19:30:55 Trace: [raatserver] [RaatServer ChriBook-Pro-2 @ 10.41.40.245:9200] lost client connection. Retrying
04/06 19:30:55 Trace: [raatserver] [RaatServer ChriBook-Pro-2 @ 10.41.40.245:9200] connecting (attempt 1)
04/06 19:30:55 Info: [transport] destroyed zone Sprout XMOS USB 2.0 was playing? True
04/06 19:30:55 Trace: [zone Sprout XMOS USB 2.0] Suspend
04/06 19:30:55 Info:
--[ SignalPath ]---------------------------------------------
SignalPath Quality = Enhanced
Elements:
    Source Format=Flac 44100/16/2  Quality=Lossless
    UpgradeBitDepth FromBitsPerSample=16 ToBitsPerSample=64 Quality=Lossless
    VolumeNormaliation GainDb=-5.01 Quality=Enhanced
    Truncate FromBitsPerSample=64 ToBitsPerSample=24 Quality=Lossless
    Raat Device=XMOS USB 2.0 Audio Out
    Output OutputType=Local_ExclusiveMode_CoreAudio Quality=Lossless SubType= Model=XMOS USB 2.0 Audio Out
------------------------------------------------------------
04/06 19:30:55 Info: [zone Sprout XMOS USB 2.0] OnPlayFeedback Stopped
04/06 19:30:55 Info: [zone Sprout XMOS USB 2.0] Canceling Pending Sleep
04/06 19:30:55 Info: [zone Sprout XMOS USB 2.0] Canceling Pending Sleep
04/06 19:30:55 Debug: FTMSI-B closed file for ti/A61F1F1A; open files:0
04/06 19:30:55 Debug: FTMSI-B ti/A61F1F1A download status: AllBlocksDownloaded accessTimeout:True openFiles:0 prev:(AllBlocksDownloaded,True,1)
04/06 19:30:55 Debug: [raat/tcpaudiosource] disconnecting
04/06 19:30:55 Trace: [Sprout XMOS USB 2.0] [zoneplayer/raat] Endpoint XMOS USB 2.0 Audio Out State Changed: Playing => Prepared
04/06 19:30:55 Info: [audio/env] [zoneplayer -> stream -> endpoint] All streams were disposed
04/06 19:30:55 Debug: FTMSI-B closed file for ti/62988B35; open files:0
04/06 19:30:55 Info: [audio/env] [zoneplayer -> stream] All streams were disposed
04/06 19:30:55 Info: [audio/env] [zoneplayer] All streams were disposed
04/06 19:30:55 Debug: FTMSI-B ti/62988B35 download status: AllBlocksDownloaded accessTimeout:False openFiles:0 prev:(AllBlocksDownloaded,False,1)
04/06 19:30:55 Info: sleep 103ms after flush
04/06 19:30:55 Error: getting null client....
04/06 19:30:55 Trace: [raatserver] [RaatServer plex @ 127.0.0.1:9200] connected
04/06 19:30:55 Trace: [rnet/RnetJsonClient] SENT {"request":"enumerate_devices","subscription_id":"0"}
04/06 19:30:55 Trace: [raatserver] [RaatServer ChriBook-Pro-2 @ 10.41.40.245:9200] connected
04/06 19:30:55 Trace: [rnet/RnetJsonClient] SENT {"request":"enumerate_devices","subscription_id":"0"}
04/06 19:30:55 Trace: [raatserver] [RaatServer ShopMac @ 10.41.40.161:9200] connected
04/06 19:30:55 Trace: [rnet/RnetJsonClient] SENT {"request":"enumerate_devices","subscription_id":"0"}
04/06 19:30:55 Trace: [rnet/RnetJsonClient] GOT NONFINAL {"devices": [], "status": "Success"}
04/06 19:30:55 Trace: [rnet/RnetJsonClient] GOT NONFINAL {"status": "Success", "devices": [{"vendor": "Apple Inc.", "device_id": "AppleHDAEngineOutput:1F,3,0,1,2:0", "name": "Built-in Output", "type": "coreaudio"}, {"device_id": "default", "name": "System Output", "type": "coreaudio", "is_system_output": true, "discovery_data": {"protocol_version": "3", "tcp_port": 64757, "unique_id": "cabd027f-f8eb-53fd-fffc-78843d8b59f6", "model": "N/A", "raat_version": "1.1.39", "version": "N/A", "vendor": "N/A"}, "config": {"output": {"type": "coreaudio", "name": "System Output", "device": "default"}, "volume": {"type": "coreaudio", "device": "default"}, "unique_id": "cabd027f-f8eb-53fd-fffc-78843d8b59f6", "external_config": {}}}]}
04/06 19:30:55 Info: [raatserver] GOT DEVICE dcfff4f8-c4a2-431f-b9c5-d497baff5dce::AppleHDAEngineOutput:1F,3,0,1,2:0 Type=coreaudio Name=Built-in Output Vendor=Apple Inc.
04/06 19:30:55 Info: [raatserver] GOT DEVICE dcfff4f8-c4a2-431f-b9c5-d497baff5dce::default Type=coreaudio Name=System Output
04/06 19:30:55 Trace: [rnet/RnetJsonClient] SENT {"request":"enable_device","device_id":"default","subscription_id":"163"}
04/06 19:30:55 Info: [raatserver] [System Output] connecting (attempt 1)
04/06 19:30:55 Trace: [System Output] [raatclient] Initializing RAAT session
04/06 19:30:55 Trace: [System Output] [raatclient] Loading script raat.dat:base.lua as module base [1088 chars]
04/06 19:30:55 Trace: [rnet/RnetJsonClient] GOT NONFINAL {"status": "Success"}
04/06 19:30:55 Trace: [rnet/RnetJsonClient] GOT NONFINAL {"status": "Success", "devices": [{"device_id": "10ACBD40-0000-0000-3219-0104A53C2278", "type": "coreaudio", "name": "DELL P2715Q", "vendor": "DEL"}, {"device_id": "AppleUSBAudioEngine:Apple Inc.:Studio Display:00008030-001C21260CD0802E:8,9", "type": "coreaudio", "name": "Studio Display Speakers", "vendor": "Apple Inc.", "usb_id": "05ac:1114"}, {"device_id": "AppleUSBAudioEngine:BEHRINGER:UMC404HD 192k:3122000:1,2", "type": "coreaudio", "name": "UMC404HD 192k", "vendor": "BEHRINGER", "usb_id": "1397:0509"}, {"device_id": "AppleUSBAudioEngine:XMOS :XMOS USB Audio 2.0:3123000:1", "type": "coreaudio", "discovery_data": {"tcp_port": 55390, "model": "N/A", "version": "N/A", "raat_version": "1.1.39", "unique_id": "25e406f3-d39b-f9ae-0a7e-88f51029e222", "protocol_version": "3", "vendor": "N/A"}, "name": "XMOS USB 2.0 Audio Out", "config": {"unique_id": "25e406f3-d39b-f9ae-0a7e-88f51029e222", "output": {"type": "coreaudio", "integer_mode": true, "exclusive_mode": true, "device": "AppleUSBAudioEngine:XMOS :XMOS USB Audio 2.0:3123000:1", "dsd_mode": "none", "use_power_of_two_buffer_size": true, "name": "XMOS USB 2.0 Audio Out"}, "volume": {"type": "coreaudio", "exclusive_mode": true, "device": "AppleUSBAudioEngine:XMOS :XMOS USB Audio 2.0:3123000:1"}, "external_config": {"resync_delay": 1}}, "vendor": "XMOS ", "usb_id": "2616:0112"}, {"device_id": "BuiltInSpeakerDevice", "type": "coreaudio", "name": "MacBook Pro Speakers", "config": {"external_config": {}, "volume": {"type": "coreaudio", "device": "BuiltInSpeakerDevice"}, "output": {"type": "coreaudio", "device": "BuiltInSpeakerDevice", "name": "MacBook Pro Speakers"}, "unique_id": "bbeea574-cbf7-c849-e23e-e2c3cdc5b0ba"}, "vendor": "Apple Inc."}, {"device_id": "MSLoopbackDriverDevice_UID", "type": "coreaudio", "name": "Microsoft Teams Audio", "vendor": "Microsoft Corp."}, {"device_id": "default", "type": "coreaudio", "name": "System Output", "is_system_output": true, "config": {"unique_id": "06c7872c-805f-70b7-89a5-e62b7c9f9802", "output": {"type": "coreaudio", "device": "default", "name": "System Output"}, "external_config": {}, "volume": {"type": "coreaudio", "device": "default"}}}]}
04/06 19:30:55 Info: [raatserver] GOT DEVICE b2d5ce33-d6a7-4f7e-b89e-21a8423319fe::10ACBD40-0000-0000-3219-0104A53C2278 Type=coreaudio Name=DELL P2715Q Vendor=DEL
04/06 19:30:55 Info: [raatserver] GOT DEVICE b2d5ce33-d6a7-4f7e-b89e-21a8423319fe::AppleUSBAudioEngine:Apple Inc.:Studio Display:00008030-001C21260CD0802E:8,9 Type=coreaudio Name=Studio Display Speakers Vendor=Apple Inc.UsbId=05ac:1114
04/06 19:30:55 Info: [raatserver] GOT DEVICE b2d5ce33-d6a7-4f7e-b89e-21a8423319fe::AppleUSBAudioEngine:BEHRINGER:UMC404HD 192k:3122000:1,2 Type=coreaudio Name=UMC404HD 192k Vendor=BEHRINGERUsbId=1397:0509
04/06 19:30:55 Info: [raatserver] GOT DEVICE b2d5ce33-d6a7-4f7e-b89e-21a8423319fe::AppleUSBAudioEngine:XMOS :XMOS USB Audio 2.0:3123000:1 Type=coreaudio Name=XMOS USB 2.0 Audio Out Vendor=XMOS UsbId=2616:0112
04/06 19:30:55 Info: [raatserver] GOT DEVICE b2d5ce33-d6a7-4f7e-b89e-21a8423319fe::BuiltInSpeakerDevice Type=coreaudio Name=MacBook Pro Speakers Vendor=Apple Inc.
04/06 19:30:55 Info: [raatserver] GOT DEVICE b2d5ce33-d6a7-4f7e-b89e-21a8423319fe::MSLoopbackDriverDevice_UID Type=coreaudio Name=Microsoft Teams Audio Vendor=Microsoft Corp.
04/06 19:30:55 Info: [raatserver] GOT DEVICE b2d5ce33-d6a7-4f7e-b89e-21a8423319fe::default Type=coreaudio Name=System Output
04/06 19:30:55 Trace: [rnet/RnetJsonClient] SENT {"request":"enable_device","device_id":"AppleUSBAudioEngine:XMOS :XMOS USB Audio 2.0:3123000:1","subscription_id":"164"}
04/06 19:30:55 Info: [raatserver] [XMOS USB 2.0 Audio Out] connecting (attempt 1)
04/06 19:30:55 Trace: [System Output] [raatclient] Loading script raat.dat:dkjson.lua as module dkjson [22416 chars]
04/06 19:30:55 Trace: [rnet/RnetJsonClient] GOT NONFINAL {"status": "Success"}
04/06 19:30:55 Trace: [XMOS USB 2.0 Audio Out] [raatclient] Initializing RAAT session
04/06 19:30:55 Trace: [XMOS USB 2.0 Audio Out] [raatclient] Loading script raat.dat:base.lua as module base [1088 chars]
04/06 19:30:55 Trace: [System Output] [raatclient] Loading script raat.dat:protocol.lua as module protocol [2045 chars]
04/06 19:30:55 Trace: [XMOS USB 2.0 Audio Out] [raatclient] Loading script raat.dat:dkjson.lua as module dkjson [22416 chars]
04/06 19:30:55 Trace: [System Output] [raatclient] Loading script raat.dat:roon_tcp.lua [45309 chars]
04/06 19:30:55 Trace: [System Output] [raatclient] RAAT Session initialized in 111ms
04/06 19:30:55 Trace: [System Output] [raatclient] SENT [2]{"request":"info"}
04/06 19:30:55 Trace: [System Output] [raatclient] SENT [3]{"request":"set_client_type","client_type":"Roon"}
04/06 19:30:55 Trace: [XMOS USB 2.0 Audio Out] [raatclient] Loading script raat.dat:protocol.lua as module protocol [2045 chars]
04/06 19:30:55 Trace: [System Output] [raatclient] GOT [2] {"source_selection":{"info":[],"is_supported":false},"flags":{"has_write_chmap":true},"status":"Success","info":{"unique_id":"cabd027f-f8eb-53fd-fffc-78843d8b59f6"},"volume":{"info":{"config":{"type":"coreaudio","device":"default"}},"is_supported":true},"transport":{"info":[],"is_supported":false},"platform":{"os":"osx","uname":{"release":"21.6.0","version":"Darwin Kernel Version 21.6.0: Mon Dec 19 20:44:01 PST 2022; root:xnu-8020.240.18~2/RELEASE_X86_64","nodename":"ShopMac.dv.lewicki.com","sysname":"Darwin","machine":"x86_64"}},"output":{"supported_formats":"96000/16/1|2,44100/16/1|2,96000/24/1|2,48000/16/1|2,88200/24/1|2,48000/24/1|2,88200/16/1|2,44100/24/1|2","info":{"config":{"device":"default","name":"System Output","type":"coreaudio"}}}}
04/06 19:30:55 Trace: [raatserver] [System Output] connected
04/06 19:30:55 Info: [transport] creating endpoint for raat device cabd027f-f8eb-53fd-fffc-78843d8b59f6
04/06 19:30:55 Trace: [System Output] [raatclient] SENT [4]{"request":"subscribe_transport"}
04/06 19:30:55 Trace: [System Output] [raatclient] SENT [5]{"request":"subscribe_controls","controller_id":"6453b048-49e3-419d-981f-627bec64f44b"}
04/06 19:30:55 Trace: [dspengine] created new dsp config {"version":3,"items":[{"type":"bs2b","enabled":false},{"type":"parametric_equalizer","enabled":false},{"type":"audeze_presets","enabled":false}]}
04/06 19:30:55 Trace: [transport/audeze] picking preset lowlatency
04/06 19:30:55 Trace: [transport/audeze] picked null preset!
04/06 19:30:55 Trace: [zone ShopMac] Loading from /var/roon/RoonServer/Database/Core/36d4972ea0c343f49bdb8b39d9220964/transport/zone_16017f02bdcaebf8fd53fffc78843d8b59f6.db
04/06 19:30:55 Trace: [System Output] [raatclient] GOT [3] {"status":"Success"}
04/06 19:30:55 Trace: [zone ShopMac] Suspend
04/06 19:30:55 Info: [zone ShopMac] Canceling Pending Sleep
04/06 19:30:55 Trace: [ShopMac] [zoneplayer/raat] Endpoint System Output Initial State: Idle
04/06 19:30:55 Info: [transport] created zone ShopMac
04/06 19:30:55 Info: [transport]     with endpoint System Output (23:1:cabd027f-f8eb-53fd-fffc-78843d8b59f6) [IsAvailable=True]
04/06 19:30:55 Trace: [ShopMac] [Inactive] [STOPPED @ 0:00]
04/06 19:30:55 Trace: [XMOS USB 2.0 Audio Out] [raatclient] Loading script raat.dat:roon_tcp.lua [45309 chars]
04/06 19:30:55 Info: [transport/zonedisplay] Zone display registered: CastDevice[DeviceId=Chromecast-Ultra-2592cd1b50334968acd77c44d2c999fe._googlecast._tcp.local, Name=Chromecast Ultra, Address=10.41.40.18]
04/06 19:30:55 Trace: [System Output] [raatclient] GOT [5] {"action":"Changed","status":"Success","controls":{"volume":{"value":100,"step":1.0,"type":"number","min":0.0,"max":100.0,"mute":false,"info":{"config":{"type":"coreaudio","device":"default"}}}}}
04/06 19:30:55 Trace: [XMOS USB 2.0 Audio Out] [raatclient] RAAT Session initialized in 72ms
04/06 19:30:55 Trace: [XMOS USB 2.0 Audio Out] [raatclient] SENT [2]{"request":"info"}
04/06 19:30:55 Trace: [XMOS USB 2.0 Audio Out] [raatclient] SENT [3]{"request":"set_client_type","client_type":"Roon"}
04/06 19:30:55 Trace: [XMOS USB 2.0 Audio Out] [raatclient] GOT [2] {"transport":{"info":[],"is_supported":false},"flags":{"has_write_chmap":true},"output":{"supported_formats":"192000/16/1|2,44100/16/1|2,96000/16/1|2,88200/24/1|2,96000/24/1|2,176400/16/1|2,192000/24/1|2,48000/16/1|2,176400/24/1|2,48000/24/1|2,88200/16/1|2,44100/24/1|2","info":{"config":{"integer_mode":true,"device":"AppleUSBAudioEngine:XMOS :XMOS USB Audio 2.0:3123000:1","exclusive_mode":true,"type":"coreaudio","name":"XMOS USB 2.0 Audio Out","use_power_of_two_buffer_size":true,"dsd_mode":"none"}}},"status":"Success","platform":{"uname":{"release":"22.3.0","nodename":"ChriBook-Pro-2.local","version":"Darwin Kernel Version 22.3.0: Mon Jan 30 20:38:37 PST 2023; root:xnu-8792.81.3~2/RELEASE_ARM64_T6000","machine":"arm64","sysname":"Darwin"},"os":"osx"},"volume":{"is_supported":true,"info":{"config":{"device":"AppleUSBAudioEngine:XMOS :XMOS USB Audio 2.0:3123000:1","exclusive_mode":true,"type":"coreaudio"}}},"info":{"vendor":"N/A","model":"N/A","version":"N/A","protocol_version":"3","unique_id":"25e406f3-d39b-f9ae-0a7e-88f51029e222","raat_version":"1.1.39"},"source_selection":{"is_supported":false,"info":[]}}
04/06 19:30:55 Trace: [raatserver] [XMOS USB 2.0 Audio Out] connected
04/06 19:30:55 Info: [transport] creating endpoint for raat device 25e406f3-d39b-f9ae-0a7e-88f51029e222
04/06 19:30:55 Trace: [XMOS USB 2.0 Audio Out] [raatclient] SENT [4]{"request":"subscribe_transport"}
04/06 19:30:55 Trace: [XMOS USB 2.0 Audio Out] [raatclient] SENT [5]{"request":"subscribe_controls","controller_id":"6453b048-49e3-419d-981f-627bec64f44b"}
04/06 19:30:55 Trace: [dspengine] loaded DSP config {"version":3,"items":[{"type":"bs2b","enabled":false},{"type":"parametric_equalizer","enabled":false,"bands":[{"type":"low_shelf","frequency":100,"gain_db":0,"q":1,"is_enabled":true},{"type":"equalize_frequency","frequency":77,"gain_db":2.3000000000000003,"q":1,"is_enabled":true},{"type":"equalize_frequency","frequency":1000,"gain_db":0,"q":1,"is_enabled":true},{"type":"equalize_frequency","frequency":2000,"gain_db":0,"q":1,"is_enabled":true},{"type":"high_shelf","frequency":5739,"gain_db":1.3,"q":1,"is_enabled":true},{"type":"high_pass","frequency":20,"order":1,"is_enabled":false},{"type":"low_pass","frequency":20000,"order":1,"is_enabled":false}],"gain_db":0,"y_axis_min_db":-24,"y_axis_max_db":12},{"type":"audeze_presets","enabled":false}],"headroom_adjustment":{"type":"headroom_adjustment"},"sample_rate_conversion":{"type":"sample_rate_conversion"}}
04/06 19:30:55 Trace: [transport/audeze] picking preset lowlatency
04/06 19:30:55 Trace: [transport/audeze] picked null preset!
04/06 19:30:55 Trace: [zone Sprout XMOS USB 2.0] Loading from /var/roon/RoonServer/Database/Core/36d4972ea0c343f49bdb8b39d9220964/transport/zone_1601f306e4259bd3aef90a7e88f51029e222.db
04/06 19:30:55 Trace: [XMOS USB 2.0 Audio Out] [raatclient] GOT [3] {"status":"Success"}
04/06 19:30:55 Trace: [XMOS USB 2.0 Audio Out] [raatclient] GOT [5] {"action":"Changed","controls":{"volume":{"value":68,"step":1.0,"type":"number","info":{"config":{"device":"AppleUSBAudioEngine:XMOS :XMOS USB Audio 2.0:3123000:1","exclusive_mode":true,"type":"coreaudio"}},"max":100.0,"min":0.0,"mute":false}},"status":"Success"}
04/06 19:30:55 Trace: [zone Sprout XMOS USB 2.0] Suspend
04/06 19:30:55 Info: [zone Sprout XMOS USB 2.0] Canceling Pending Sleep
04/06 19:30:55 Trace: [Sprout XMOS USB 2.0] [zoneplayer/raat] Endpoint XMOS USB 2.0 Audio Out Initial State: Idle
04/06 19:30:55 Info: [transport] created zone Sprout XMOS USB 2.0
04/06 19:30:55 Info: [transport]     with endpoint XMOS USB 2.0 Audio Out (23:1:25e406f3-d39b-f9ae-0a7e-88f51029e222) [IsAvailable=True]
04/06 19:30:55 Trace: [Sprout XMOS USB 2.0] [Enhanced, 16/44 TIDAL FLAC => 24/44] [100% buf] [STOPPED @ 0:00]
04/06 19:30:55 Debug: [easyhttp] [36729] GET to https://www.qobuz.com/api.json/0.2/user/login?request_sig=44099d1c198acf0b61bb967b83d5cfa8&request_ts=1680809443 returned after 10746 ms, status code: 200, request body size: 0 B
04/06 19:30:56 Trace: [library] endmutation in 865ms
04/06 19:31:04 Trace: [library] endmutation in 1789ms
04/06 19:31:05 Info: [stats] 32000mb Virtual, 13587mb Physical, 6308mb Managed, 1033 Handles, 247 Threads
04/06 19:31:05 Debug: [easyhttp] [36730] POST to https://api.roonlabs.net/device-map/1/register returned after 180 ms, status code: 200, request body size: 8 KB
04/06 19:31:05 Trace: [devicemap] device map updated
04/06 19:31:16 Trace: [library] endmutation in 476ms
04/06 19:31:20 Info: [stats] 30950mb Virtual, 13600mb Physical, 7519mb Managed, 1033 Handles, 114 Threads

michaelm · April 20, 2023, 2:28pm

I am experiencing a similar issue. I had done some investigation on my case in this thread and have not fully resolved it yet. In my case though even local playback would stop occasionally.

Chris_Lewicki · April 20, 2023, 4:04pm

It’s frustrating to do so much debugging work for a product I’m paying for, and receive no response from the development team.

noris · May 3, 2023, 6:38pm

Hi @Chris_Lewicki ,

Thanks for reaching out and sincere apologies for the delay in getting back to you here. We appreciate all the logging that you provided.

Chris_Lewicki:

04/06 18:45:53 Trace: [Sprout XMOS USB 2.0] [zoneplayer/raat] Endpoint XMOS USB 2.0 Audio Out State Changed: Playing => Prepared
04/06 18:45:53 Debug: FTMSI-B closed file for ti/FCE44A7B; open files:0
04/06 18:45:53 Info: [audio/env] [zoneplayer -> stream] All streams were disposed
04/06 18:45:53 Info: [audio/env] [zoneplayer -> stream -> endpoint] All streams were disposed
04/06 18:45:53 Debug: FTMSI-B ti/FCE44A7B download status: AllBlocksDownloaded accessTimeout:True openFiles:0 prev:(AllBlocksDownloaded,True,1)
04/06 18:45:53 Info: [audio/env] [zoneplayer] All streams were disposed
04/06 18:45:54 Info: sleep 103ms after flush
04/06 18:45:54 Error: getting null client....
04/06 18:45:54 Trace: [rnet/RnetJsonClient] no data received for >10000ms. Killing connection.
04/06 18:45:54 Trace: [raatserver] [RaatServer plex @ 127.0.0.1:9200] lost client connection. Retrying
04/06 18:45:54 Trace: [raatserver] [RaatServer plex @ 127.0.0.1:9200] connecting (attempt 1)
04/06 18:45:54 Info: [transport/zonedisplay] Zone display unregistered: CastDevice[DeviceId=Chromecast-Ultra-2592cd1b50334968acd77c44d2c999fe._googlecast._tcp.local, Name=Chromecast Ultra, Address=10.41.40.18]
04/06 18:45:54 Info: [cast] lost device CastDevice[DeviceId=Chromecast-Ultra-2592cd1b50334968acd77c44d2c999fe._googlecast._tcp.local, Name=Chromecast Ultra, Address=10.41.40.18] because it disconnected
04/06 18:45:55 Trace: [raatserver] [RaatServer ShopMac @ 10.41.40.161:9200] connected

In this log set, you can see that playback stops at the same time as the Chromecast is lost, which would suggest the possibility of a general networking issue.

Can you please temporarily host the Roon Core on the MacOS client to confirm if you have the same issue there? You can use the below instructions to switch the Core:

Create a Backup of your current database
Open Roon on the other PC you wish to try as the Core
Roon Settings → General
Disconnect
On the “Choose your Core” screen, press “Use this PC”
If asked to Unauthorize, you can go ahead and do so. You are limited to one active Roon Core at a time but you are free to switch between them as often as you’d like
Verify if the same behavior occurs on the different PC

Please also note that managed switches have sometimes caused issues within Roon regarding traffic processing. Please see:

Managed Switches
Managed switches can be very robust, but they are often designed for professional installation, so in many cases the out-of-box configuration is not right. If your switch has a “flow control” setting, please make sure that it is enabled. Also, make sure that the switch is not performing any sort of throttling that might impact communication between cores, storage, remotes, and/or audio endpoints. Finally, ensure that the switch is configured to pass multicast and broadcast traffic. If in doubt about any of this, try temporarily replacing your managed switch with a “dumb” switch to see if things improve.

Chris_Lewicki · May 3, 2023, 7:36pm

Is the networking issue still relevant even if the Chromecast wasn’t in use (and hasn’t been for months)?

Will review the networking best practices as you suggest, and potentially experiment with running the Core on MacOS (although this isn’t a longterm solution for me).

system · June 17, 2023, 7:37pm

This topic was automatically closed 45 days after the last reply. New replies are no longer allowed.