Interpreting Roon Server Logs to Diagnose (Qobuz) Track Skipping

Core Machine (Operating system/System info/Roon build number)

Roon Server on Mac Mini quad core i7, up to date, ethernet to router

Network Details (Including networking gear model/manufacturer and if on WiFi/Ethernet)

1GB fibre in, Synology Router, ethernet to everywhere (a couple of 10G switches in there)

Audio Devices (Specify what device you’re using and its connection type - USB/HDMI/etc.)

a. ethernet to Allo USBridge running latest Ropieee, USB to DAC
b. ethernet to Blusound Pulse Flex pair
c. ethernet to Allo Digione running latest Ropieee, SPDIF to DAC

Description Of Issue

24/192 tracks often skip to next track part way through song. Haven’t seen it with 24/96 or lower. 95% of content is via Qobuz but I think it only happens with Qobuz content. I play to a single zone Allo USBridge as per above or sometime I group both above and play to group zone. I believe that the skipping happens in both cases.

I am trying to interpret the Roon Logs to determine the cause of this - is it the connection to Qobuz to Roon core or is it networking issues after that.

The only thing I see in the Roon logs is that the endpoint buffers start decreasing from 100% down to 0% over the course of a number of seconds. And then the track skips. This happened on both endpoints when grouped.
All of this suggests to me a problem with the 24/192 streaming connection to Qobuz to Roon Server. But most of the time I do NOT get any error message on Roon Control app (on another networked device) and it just skips. Only very infrequently do I see the “Qobuz media is loading slowly” so I am uncertain.

Is there anything definitive in Roon server logs that helps one determine the cause of a track stopping play??? Here is the relevant section from most recent skip … where you can see endpoint buffers drop … is this because the source is not sending data or there is network issue? I assume the former.

05/23 09:46:02 Trace: [dbperf] flush 0 bytes, 0 ops in 7 ms (cumulative 166171505 bytes, 129692 ops in 49393 ms)
05/23 09:46:02 Trace: [Living Room USB + Kitchen] [zoneplayer/raat] sync Bluesound PULSE FLEX -> JLsounds Hi-Rez Audio 2.0 result: Success
05/23 09:46:04 Trace: [prebuffer] short read: 0 / 38400 fill=1536928
05/23 09:46:04 Trace: [Kitchen] [Enhanced, 24/192 QOBUZ FLAC => 24/192] [100% buf] [PLAYING @ 0:42/7:15] Late Date - Ben Webster / Ben Webster Quintet / Ben Webster Quartet / Neal Hefti
05/23 09:46:04 Trace: [Living Room USB + Kitchen] [zoneplayer/raat] sync Bluesound PULSE FLEX -> JLsounds Hi-Rez Audio 2.0 result: Success
05/23 09:46:04 Trace: [Living Room USB] [Enhanced 19.6x, 24/192 QOBUZ FLAC => 32/192] [100% buf] [PLAYING @ 0:43/7:15] Late Date - Ben Webster / Ben Webster Quintet / Ben Webster Quartet / Neal Hefti
05/23 09:46:06 Trace: [Living Room USB + Kitchen] [zoneplayer/raat] sync Bluesound PULSE FLEX -> JLsounds Hi-Rez Audio 2.0 result: Success
05/23 09:46:09 Trace: [Kitchen] [Enhanced, 24/192 QOBUZ FLAC => 24/192] [80% buf] [PLAYING @ 0:47/7:15] Late Date - Ben Webster / Ben Webster Quintet / Ben Webster Quartet / Neal Hefti
05/23 09:46:09 Trace: [Living Room USB + Kitchen] [zoneplayer/raat] sync Bluesound PULSE FLEX -> JLsounds Hi-Rez Audio 2.0 result: Success
05/23 09:46:10 Trace: [Living Room USB] [Enhanced 19.7x, 24/192 QOBUZ FLAC => 32/192] [54% buf] [PLAYING @ 0:49/7:15] Late Date - Ben Webster / Ben Webster Quintet / Ben Webster Quartet / Neal Hefti
05/23 09:46:11 Trace: [Living Room USB + Kitchen] [zoneplayer/raat] sync Bluesound PULSE FLEX -> JLsounds Hi-Rez Audio 2.0 result: Success
05/23 09:46:12 Trace: [prebuffer] ready 652800/1920000 (34%) @ 0/259 sec
05/23 09:46:13 Info: [stats] 7393mb Virtual, 2608mb Physical, 1258mb Managed, 117 Threads,  FDs 
05/23 09:46:13 Trace: [Living Room USB + Kitchen] [zoneplayer/raat] sync Bluesound PULSE FLEX -> JLsounds Hi-Rez Audio 2.0 result: Success
05/23 09:46:14 Trace: [Kitchen] [Enhanced, 24/192 QOBUZ FLAC => 24/192] [26% buf] [PLAYING @ 0:52/7:15] Late Date - Ben Webster / Ben Webster Quintet / Ben Webster Quartet / Neal Hefti
05/23 09:46:15 Trace: [Living Room USB + Kitchen] [zoneplayer/raat] sync Bluesound PULSE FLEX -> JLsounds Hi-Rez Audio 2.0 result: Success
05/23 09:46:15 Trace: [Living Room USB] [Enhanced 19.7x, 24/192 QOBUZ FLAC => 32/192] [26% buf] [PLAYING @ 0:54/7:15] Late Date - Ben Webster / Ben Webster Quintet / Ben Webster Quartet / Neal Hefti
05/23 09:46:17 Trace: [Living Room USB + Kitchen] [zoneplayer/raat] sync Bluesound PULSE FLEX -> JLsounds Hi-Rez Audio 2.0 result: Success
05/23 09:46:19 Trace: [Living Room USB + Kitchen] [zoneplayer/raat] sync Bluesound PULSE FLEX -> JLsounds Hi-Rez Audio 2.0 result: Success
05/23 09:46:19 Trace: [Kitchen] [Enhanced, 24/192 QOBUZ FLAC => 24/192] [26% buf] [PLAYING @ 0:58/7:15] Late Date - Ben Webster / Ben Webster Quintet / Ben Webster Quartet / Neal Hefti
05/23 09:46:20 Debug: [smc] [zoneplayer:43] Removing ordinal 96
05/23 09:46:20 Debug: [easyhttp] [6282] POST to https://www.qobuz.com/api.json/0.2/track/reportStreamingEnd?
05/23 09:46:20 Info: [library] recorded play for profile 53ac136d-6595-4890-8100-cdca55a63cbc: mediaid=202:0:61236273 metadataid= contentid=202:0:61236273 libraryid= isfromswim=False
05/23 09:46:20 Info: [zone Living Room USB + Kitchen] OnPlayFeedback OnToNext
05/23 09:46:20 Debug: [zone Living Room USB + Kitchen] _Advance
05/23 09:46:20 Debug: [query] Sooloos.Broker.Transport.TransportItem: 5000 dirty items. rebuilding query instead of re-sorting item-by-item (internaltype=TransportItem)
05/23 09:46:20 Debug: [query] Sooloos.Broker.Transport.TransportItem: 5000 dirty items. rebuilding query instead of re-sorting item-by-item (internaltype=TransportItem)
05/23 09:46:20 Debug: [easyhttp] [6283] POST to https://www.qobuz.com/api.json/0.2/track/reportStreamingStart?
05/23 09:46:20 Info: [zone Living Room USB + Kitchen] OnPlayFeedback Playing

Do you get the same behavior if the endpoints are not grouped?

I believe so but I am running the same album that if often happens on to the single endpoint and trying to replicate and capture logs. Will update in a while.

There must be something in the roon logs that indicates why a track is stopped? The buffers draining from 100% to 0% over the course of x seconds suggests that inbound data to the endpoints has stopped. One can see at the end of a track - the RAAT endpoint buffer naturally drains as expected. But then it happens part way through a song and track skips. That’s not the cause in and of itself obviously. Is it because data from qobuz -> roon core has stopped/slowed or there is something after that? You would think there would be something in roon server logs …

ok so i just got this while testing the single endpoint and it happened at roughly the same point in the same track as above to both endpoints (0:47) … but this time I got an actually error in the logs. Still trying to interpret the error/stack trace.

Of course I play it again and it’s fine.

    05/23 11:46:02 Debug: [smc] [zoneplayer:56] Ordinal 26 is good to go
05/23 11:46:02 Trace: [streamingmediafile] immediate read of https://streaming-std.qobuz.com/file at 262144 length=138656977
05/23 11:46:02 Trace: [streamingmediafile] immediate read of https://streaming-std.qobuz.com/file at 524288 length=138656977
05/23 11:46:03 Trace: [streamingmediafile] immediate read of https://streaming-std.qobuz.com/file at 786432 length=138656977
05/23 11:46:03 Info: [Living Room USB] [zoneplayer] Open result (Queueing): Result[Status=Success]
05/23 11:46:03 Trace: [Living Room USB] [Enhanced 18.3x, 24/192 QOBUZ FLAC => 32/192] [100% buf] [PLAYING @ 0:05/7:15] Late Date - Ben Webster / Ben Webster Quintet / Ben Webster Quartet / Neal Hefti
05/23 11:46:08 Trace: [Living Room USB] [Enhanced 18.3x, 24/192 QOBUZ FLAC => 32/192] [100% buf] [PLAYING @ 0:09/7:15] Late Date - Ben Webster / Ben Webster Quintet / Ben Webster Quartet / Neal Hefti
05/23 11:46:11 Info: [stats] 7497mb Virtual, 2158mb Physical, 1496mb Managed, 112 Threads,  FDs 
05/23 11:46:14 Trace: [Living Room USB] [Enhanced 18.4x, 24/192 QOBUZ FLAC => 32/192] [100% buf] [PLAYING @ 0:16/7:15] Late Date - Ben Webster / Ben Webster Quintet / Ben Webster Quartet / Neal Hefti
05/23 11:46:19 Trace: [Living Room USB] [Enhanced 18.4x, 24/192 QOBUZ FLAC => 32/192] [100% buf] [PLAYING @ 0:21/7:15] Late Date - Ben Webster / Ben Webster Quintet / Ben Webster Quartet / Neal Hefti
05/23 11:46:24 Trace: [Living Room USB] [Enhanced 18.5x, 24/192 QOBUZ FLAC => 32/192] [100% buf] [PLAYING @ 0:26/7:15] Late Date - Ben Webster / Ben Webster Quintet / Ben Webster Quartet / Neal Hefti
05/23 11:46:27 Info: [stats] 7405mb Virtual, 2084mb Physical, 1265mb Managed, 112 Threads,  FDs 
05/23 11:46:29 Trace: [Living Room USB] [Enhanced 18.5x, 24/192 QOBUZ FLAC => 32/192] [100% buf] [PLAYING @ 0:31/7:15] Late Date - Ben Webster / Ben Webster Quintet / Ben Webster Quartet / Neal Hefti
05/23 11:46:33 Trace: [Living Room USB] [zoneplayer/raat] sync JLsounds Hi-Rez Audio 2.0: realtime=17949160824741 rtt=1000us offset=12710326824us delta=-88us drift=-15108us in 521.603s (-28.965ppm, -104.275ms/hr
)
05/23 11:46:34 Trace: [Living Room USB] [Enhanced 18.5x, 24/192 QOBUZ FLAC => 32/192] [100% buf] [PLAYING @ 0:36/7:15] Late Date - Ben Webster / Ben Webster Quintet / Ben Webster Quartet / Neal Hefti
05/23 11:46:40 Trace: [Living Room USB] [Enhanced 18.5x, 24/192 QOBUZ FLAC => 32/192] [100% buf] [PLAYING @ 0:42/7:15] Late Date - Ben Webster / Ben Webster Quintet / Ben Webster Quartet / Neal Hefti
05/23 11:46:42 Info: [stats] 7405mb Virtual, 2084mb Physical, 1500mb Managed, 112 Threads,  FDs 
05/23 11:46:45 Trace: [Living Room USB] [Enhanced 18.6x, 24/192 QOBUZ FLAC => 32/192] [100% buf] [PLAYING @ 0:47/7:15] Late Date - Ben Webster / Ben Webster Quintet / Ben Webster Quartet / Neal Hefti
05/23 11:46:46 Error: [cachingseekableurimediafile] while reading: System.ArgumentException: Offset and length were out of bounds for the array or count is greater than the number of elements from index to the e
nd of the source collection.
  at System.Buffer.BlockCopy (System.Array src, System.Int32 srcOffset, System.Array dst, System.Int32 dstOffset, System.Int32 count) [0x0007e] in <ba70b91736bd40cb990a357097dba9c3>:0 
  at Sooloos.Media.StreamingMediaFileImpl._Read (System.Int64 file_off, System.Byte[] buf, System.Int32 off, System.Int32 count) [0x00066] in <8d4c1eb81906493983c7a625495530c8>:0 
  at Sooloos.Media.StreamingMediaFileImpl.Read (System.Int64 file_off, System.Byte[] buf, System.Int32 off, System.Int32 count) [0x0005e] in <8d4c1eb81906493983c7a625495530c8>:0 
  at Sooloos.Media.StreamingMediaFile.Read (System.Int64 file_off, System.Byte[] buf, System.Int32 off, System.Int32 count) [0x00000] in <8d4c1eb81906493983c7a625495530c8>:0 
  at Sooloos.Media.CachingSeekableUriMediaFile.ReadCallback (System.IntPtr userdata, System.IntPtr buf, System.IntPtr count, System.IntPtr& out_bytesread) [0x00055] in <8d4c1eb81906493983c7a625495530c8>:0 
05/23 11:46:46 Warn: [prebuffer] in buffer threadSystem.Exception: Read failure: IoFailure
  at Sooloos.Audio.MediaDecoderAudioSignal.Read (System.Byte[] buffer, System.Int32 offset, System.Int32 frames) [0x0024a] in <4aa2cfc171d841669e54b0b916777579>:0 
  at Sooloos.Broker.Transport.FormatDetectAudioSignal.Read (System.Byte[] buffer, System.Int32 offset, System.Int32 frames) [0x000ca] in <551cd8c4d7144641b9d9a5e21307ceb8>:0 
  at Sooloos.Audio.SeekableBufferedAudioSignal._Buffer (System.Int32 buffer_seq) [0x0003e] in <4aa2cfc171d841669e54b0b916777579>:0 
  at Sooloos.Audio.SeekableBufferedAudioSignal+<>c__DisplayClass31_0.<_StartBuffering>b__0 () [0x00000] in <4aa2cfc171d841669e54b0b916777579>:0 
05/23 11:46:48 Info: [Living Room USB] [zoneplayer] Track ended unexpectedly: Sooloos.Audio.BufferedReadException: error during buffered read ---> System.Exception: Read failure: IoFailure
  at Sooloos.Audio.MediaDecoderAudioSignal.Read (System.Byte[] buffer, System.Int32 offset, System.Int32 frames) [0x0024a] in <4aa2cfc171d841669e54b0b916777579>:0 
  at Sooloos.Broker.Transport.FormatDetectAudioSignal.Read (System.Byte[] buffer, System.Int32 offset, System.Int32 frames) [0x000ca] in <551cd8c4d7144641b9d9a5e21307ceb8>:0 
  at Sooloos.Audio.SeekableBufferedAudioSignal._Buffer (System.Int32 buffer_seq) [0x0003e] in <4aa2cfc171d841669e54b0b916777579>:0 
  at Sooloos.Audio.SeekableBufferedAudioSignal+<>c__DisplayClass31_0.<_StartBuffering>b__0 () [0x00000] in <4aa2cfc171d841669e54b0b916777579>:0 
   --- End of inner exception stack trace ---
  at Sooloos.Audio.SeekableBufferedAudioSignal.Read (System.Byte[] buffer, System.Int32 offset, System.Int32 frames) [0x0004f] in <4aa2cfc171d841669e54b0b916777579>:0 
  at Sooloos.Broker.Transport.ZonePlayerTrack._ReadBacking (System.Byte[] buffer, System.Int32 offset, System.Int32 frames) [0x00041] in <551cd8c4d7144641b9d9a5e21307ceb8>:0 
  at Sooloos.Broker.Transport.ZonePlayerTrack+_Stream.ReadImp (Sooloos.Audio.AudioBuffer buf, System.Int32 nsamples) [0x00041] in <551cd8c4d7144641b9d9a5e21307ceb8>:0 
  at Sooloos.Audio.AudioStream.Read (Sooloos.Audio.AudioBuffer buf, System.Int32 nsamples) [0x0005e] in <0c178ea689104a34b8045b6733d31e17>:0 
  at Sooloos.Broker.Transport.ZonePlayerBase.ReadImp (Sooloos.Audio.AudioBuffer buf, System.Int32 nsamples) [0x00105] in <551cd8c4d7144641b9d9a5e21307ceb8>:0 
05/23 11:46:48 Debug: [smc] [zoneplayer:56] Removing ordinal 26
05/23 11:46:48 Warn: Track Stopped Due to Error
05/23 11:46:48 Debug: [smc] [zoneplayer:56] Destroyed domain
05/23 11:46:48 Debug: [easyhttp] [6558] POST to https://www.qobuz.com/api.json/0.2/track/reportStreamingEnd?
05/23 11:46:48 Debug: [smc] [zoneplayer:56] Created domain
05/23 11:46:48 Debug: [smc] [zoneplayer:56] Removing ordinal 26
05/23 11:46:48 Info: [library] recorded play for profile 53ac136d-6595-4890-8100-cdca55a63cbc: mediaid=202:0:61236273 metadataid= contentid=202:0:61236273 libraryid= isfromswim=False
05/23 11:46:48 Debug: [smc] [zoneplayer:56] Destroyed domain
05/23 11:46:48 Info: [zone Living Room USB] OnPlayFeedback StoppedEndOfMediaUnnatural
05/23 11:46:48 Debug: [zone Living Room USB] _Advance

So a quick grep of RoonServer logs shows that I was also getting this error to a 3rd endpoint in a different room a few days ago, when playing just to that endpoint. Also an Allo device running Ropieee connected via ethernet to the Roon core via router.

Can Roon support clarify what the below error means? does it imply a problem parsing the upstream streaming feed from qobuz or a problem with sending data to the endpoint? The first exception in Sooloos.Media.StreamingMediaFile.Read suggests the former to me …

05/18 22:58:54 Trace: [Family Room] [Lossless, 24/192 QOBUZ FLAC => 24/192] [100% buf] [PLAYING @ 0:39/3:35] Samba Dees Days - Charlie Byrd / Stan Getz
05/18 22:58:57 Error: [cachingseekableurimediafile] while reading: System.ArgumentException: Offset and length were out of bounds for the array or count is greater than the number of elements from index to the e
nd of the source collection.
  at System.Buffer.BlockCopy (System.Array src, System.Int32 srcOffset, System.Array dst, System.Int32 dstOffset, System.Int32 count) [0x0007e] in <ba70b91736bd40cb990a357097dba9c3>:0 
  at Sooloos.Media.StreamingMediaFileImpl._Read (System.Int64 file_off, System.Byte[] buf, System.Int32 off, System.Int32 count) [0x00066] in <8d4c1eb81906493983c7a625495530c8>:0 
  at Sooloos.Media.StreamingMediaFileImpl.Read (System.Int64 file_off, System.Byte[] buf, System.Int32 off, System.Int32 count) [0x0005e] in <8d4c1eb81906493983c7a625495530c8>:0 
  at Sooloos.Media.StreamingMediaFile.Read (System.Int64 file_off, System.Byte[] buf, System.Int32 off, System.Int32 count) [0x00000] in <8d4c1eb81906493983c7a625495530c8>:0 
  at Sooloos.Media.CachingSeekableUriMediaFile.ReadCallback (System.IntPtr userdata, System.IntPtr buf, System.IntPtr count, System.IntPtr& out_bytesread) [0x00055] in <8d4c1eb81906493983c7a625495530c8>:0 
05/18 22:58:57 Warn: [prebuffer] in buffer threadSystem.Exception: Read failure: IoFailure
  at Sooloos.Audio.MediaDecoderAudioSignal.Read (System.Byte[] buffer, System.Int32 offset, System.Int32 frames) [0x0024a] in <4aa2cfc171d841669e54b0b916777579>:0 
  at Sooloos.Broker.Transport.FormatDetectAudioSignal.Read (System.Byte[] buffer, System.Int32 offset, System.Int32 frames) [0x000ca] in <551cd8c4d7144641b9d9a5e21307ceb8>:0 
  at Sooloos.Audio.SeekableBufferedAudioSignal._Buffer (System.Int32 buffer_seq) [0x0003e] in <4aa2cfc171d841669e54b0b916777579>:0 
  at Sooloos.Audio.SeekableBufferedAudioSignal+<>c__DisplayClass31_0.<_StartBuffering>b__0 () [0x00000] in <4aa2cfc171d841669e54b0b916777579>:0 
05/18 22:58:58 Info: [Family Room] [zoneplayer] Track ended unexpectedly: Sooloos.Audio.BufferedReadException: error during buffered read ---> System.Exception: Read failure: IoFailure
  at Sooloos.Audio.MediaDecoderAudioSignal.Read (System.Byte[] buffer, System.Int32 offset, System.Int32 frames) [0x0024a] in <4aa2cfc171d841669e54b0b916777579>:0 
  at Sooloos.Broker.Transport.FormatDetectAudioSignal.Read (System.Byte[] buffer, System.Int32 offset, System.Int32 frames) [0x000ca] in <551cd8c4d7144641b9d9a5e21307ceb8>:0 
  at Sooloos.Audio.SeekableBufferedAudioSignal._Buffer (System.Int32 buffer_seq) [0x0003e] in <4aa2cfc171d841669e54b0b916777579>:0 
  at Sooloos.Audio.SeekableBufferedAudioSignal+<>c__DisplayClass31_0.<_StartBuffering>b__0 () [0x00000] in <4aa2cfc171d841669e54b0b916777579>:0 
   --- End of inner exception stack trace ---
  at Sooloos.Audio.SeekableBufferedAudioSignal.Read (System.Byte[] buffer, System.Int32 offset, System.Int32 frames) [0x0004f] in <4aa2cfc171d841669e54b0b916777579>:0 
  at Sooloos.Broker.Transport.ZonePlayerTrack._ReadBacking (System.Byte[] buffer, System.Int32 offset, System.Int32 frames) [0x00041] in <551cd8c4d7144641b9d9a5e21307ceb8>:0 
  at Sooloos.Broker.Transport.ZonePlayerTrack+_Stream.ReadImp (Sooloos.Audio.AudioBuffer buf, System.Int32 nsamples) [0x00041] in <551cd8c4d7144641b9d9a5e21307ceb8>:0 
  at Sooloos.Audio.AudioStream.Read (Sooloos.Audio.AudioBuffer buf, System.Int32 nsamples) [0x0005e] in <0c178ea689104a34b8045b6733d31e17>:0 
  at Sooloos.Broker.Transport.ZonePlayerBase.ReadImp (Sooloos.Audio.AudioBuffer buf, System.Int32 nsamples) [0x00105] in <551cd8c4d7144641b9d9a5e21307ceb8>:0 
05/18 22:58:58 Debug: [smc] [zoneplayer:12] Created domain
05/18 22:58:58 Debug: [smc] [zoneplayer:12] Removing ordinal 7
05/18 22:58:58 Warn: Track Stopped Due to Error
05/18 22:58:58 Debug: [smc] [zoneplayer:12] Destroyed domain
05/18 22:58:58 Debug: [easyhttp] [976] POST to https://www.qobuz.com/api.json/0.2/track/reportStreamingEnd?

These errors always seem to happen before a given streaming file has finished cacheing as per ‘grep streaming-std RoonServer_log.txt’. The first log above did not have this error, but again, the streaming file had not finished reading/cacheing. So maybe it just timed out instead of creating what looks to be a data error. Along with other similar reports like Tidal playback randomly skips to next track part way through playback, and the nature of the stack traces, I think this has to do with the connection between my roon core and Qobuz.

I have restarted my router, disabled EEE (energy efficient ethernet). I have a pretty vanilla setup and speed tests from the roon core server show 2 ms latency, 800Mbps + down, and almost 1Gbps up. Weird …