Roon Stopping (and sometimes restarting)

@noris @agillis see attached link - will leave it active for a day or so

@noris Can you let me know when you have down loaded the logs?

@noris @agillis
Noris - thought I saw a request from you to share the logs - were you able to download them? What do you see?

@noris @agillis
Noris - do you have any update?

Hi @DJD ,

Thanks for sending the log over and for your patience here. We took a look over this log, but it seems to be filled with HQPlayer traces, were you playing to the OpticalRedu via HQPlayer?

It is a bit difficult to discern where the issue occurred with so many HQPlayer traces in the logs, if the issue occurs again, can you please note the exact local time + date + track impacted?

Does the issue occur when playing to the OpticalRendu without HQPlayer as well? Let us know, thanks!

@noris
Noris the music stopped around 10/24 17:50:45-47 What made it stop?

@noris
And yes I was using HQP

Hi @DJD,

Thanks for confirming the timestamp! It looks as if Roon got a pause command from a Roon extension originating at IP 192.168.1.211. Is this IP associated with a Roon extension that you use?

@noris @agillis Noris - I do have a rooDail extension. To check if that is the problem I turned it off and it no longer shows in ROON. However a got two drops this morning(10-31-'21)while using HQP and PCM. One around 6:15am and a second a minute or so later.

I have attached the logs to my drive and included you as a share - I don’t know if that means it is sent to you or you still need to go there to get it. Please let me know.

Thanks for your help on this.

Dan

@noris @agillis Can you provide any updates Noris?

Thanks for your help
Dan

@noris @agillis
Noris,

The pause/stop occurred twice this morning. This was listening to a SonicTransporter and opticalRendu with ROON READY (no HQP).

The first stop occurred around 6:45 am (EST) Nov 5th. It was about 2:35 into the track ‘Dublin Farewell’ on ‘A Tribute to Jack Hardy’. The second stop occurred around 6:51am around the 4:00 minute mark of ‘The Tailor’ on the same album.

A couple of things to note. Looking at the logs I see some action about HQP. It was an zone option in ROON even though I was playing to the oRendu. I have since deleted it. The other note is I am using a rooDail extension (192.168.1.211 I think) to control volume. The last time I had pause/stop issues it was not connected so I am assuming it is not the problem. And have added it back into my system.

Let me know if you got the notice for the new logs (ROON logs 11.05.2021.txt) and I would appreciate ROON’s input. The info above should isolate the problem. Andrew-if you have any suggestions I am all ears.

Dan

Hello @DJD ,

Thank you for sending the logs over, I can confirm receipt!
Let me check with the team regarding log analysis and get back to you.

@noris @agillis Thanks Noris - look forward to your team’s conclusions.

@noris @agillis Noris - any news?

@noris @agillis @wes.cambell@roonlabs.com
Noris - just got a request from WesCambell for access to logs. I don’t know if it was his intention, but he asked for older logs. The most recent and relevant ones are from Nov 5th. - they correspond to the detailed time stamps I gave you on Nov 5th. I gave him access to those logs too.

Here is a copy of that info:
Noris,

The pause/stop occurred twice this morning. This was listening to a SonicTransporter and opticalRendu with ROON READY (no HQP).

The first stop occurred around 6:45 am (EST) Nov 5th. It was about 2:35 into the track ‘Dublin Farewell’ on ‘A Tribute to Jack Hardy’. The second stop occurred around 6:51am around the 4:00 minute mark of ‘The Tailor’ on the same album.

A couple of things to note. Looking at the logs I see some action about HQP. It was an zone option in ROON even though I was playing to the oRendu. I have since deleted it. The other note is I am using a rooDail extension (192.168.1.211 I think) to control volume. The last time I had pause/stop issues it was not connected so I am assuming it is not the problem. And have added it back into my system.

Let me know if you got the notice for the new logs (ROON logs 11.05.2021.txt) and I would appreciate ROON’s input. The info above should isolate the problem. Andrew-if you have any suggestions I am all ears.

Dan

1 Like

Hi @DJD ,

Thanks for your patience here while we’ve had a chance to look into this further.

Yes, Wes is a member of the Roon Staff and we were looking over the logs, which is why you saw that request.

Looking at these logs, it looks like the issue might be between the OpticalRendu and the Denefrips. There have been some reports of Denefrips sensitivity to USB connections.

This further suggests that OpticalRendu is playing a part in the issue. The team has noted that it would be helpful to see what the OpticalRendu logs show when the issue occurs.

Can you please reproduce the behavior as before, note the time + date + track of the issue, then send us a new log set and OpticalRendu logs?

You can access the OpticalRendu logs on OpticalRedu web interface, under: Apps → Roon Ready → Roon Ready Diagnostic.

Thanks!

@noris @agillis Noris, Can you be more specific on what you see in the logs on the two Nov. 5th dropouts that makes you think it is the oR or the DAC? A better description may help Andrew (oR) in helping me with the problem. I have seen the thread on the Denefrips DAC you reference - I have used multiple USB cables and still had the drop outs, so I don’t believe the cable is the issue. Once again, it would be helpful for you to describe exactly what happened when it stopped each time on the 5th (ran out of buffer? lost the internet? couldn’t find the DAC? the DAC or oR stopped? etc). I have spent a lot of time looking at the ROON logs and just don’t have the knowledge to interpret what I am reading.

As to replicating the stops - as I said in the beginning its random - if I could reproduce it I would be on my way to solving the issue…

@noris @agillis Noris, Further input on what went wrong on the two Nov 5th stops would be appreciated.

Hi @DJD ,

This is what the Roon log looked like for that timestamp:

11/05 06:45:40 Trace: [opticalRendu] [HighQuality, 16/44 QOBUZ FLAC => 16/44] [100% buf] [PLAYING @ 1:57/3:46] Dublin Farewell - Anthony da Costa
11/05 06:45:45 Trace: [opticalRendu] [HighQuality, 16/44 QOBUZ FLAC => 16/44] [100% buf] [PLAYING @ 2:02/3:46] Dublin Farewell - Anthony da Costa
11/05 06:45:50 Trace: [opticalRendu] [HighQuality, 16/44 QOBUZ FLAC => 16/44] [100% buf] [PLAYING @ 2:07/3:46] Dublin Farewell - Anthony da Costa
11/05 06:45:52 Info: [stats] 35729mb Virtual, 898mb Physical, 206mb Managed, 287 Handles, 111 Threads
11/05 06:45:54 Trace: [Sonore opticalRendu @ 192.168.1.11:34173] [raatclient] GOT [121] {"status":"Dropout","samples":1419}
11/05 06:45:55 Trace: [Sonore opticalRendu @ 192.168.1.11:34173] [raatclient] GOT [121] {"status":"Dropout","samples":22060}
11/05 06:45:55 Trace: [opticalRendu] [HighQuality, 16/44 QOBUZ FLAC => 16/44] [100% buf] [PLAYING @ 2:12/3:46] Dublin Farewell - Anthony da Costa
11/05 06:45:55 Trace: [Sonore opticalRendu @ 192.168.1.11:34173] [raatclient] GOT [121] {"status":"Dropout","samples":22060}
11/05 06:45:56 Trace: [Sonore opticalRendu @ 192.168.1.11:34173] [raatclient] GOT [121] {"status":"Dropout","samples":12133}
11/05 06:45:59 Trace: [opticalRendu] [zoneplayer/raat] sync Sonore opticalRendu: realtime=17792415427182 rtt=500us offset=-29699995572us delta=1540us drift=-28699us in 3620.156s (-7.928ppm, -28.540ms/hr)
11/05 06:46:00 Trace: [opticalRendu] [HighQuality, 16/44 QOBUZ FLAC => 16/44] [100% buf] [PLAYING @ 2:17/3:46] Dublin Farewell - Anthony da Costa
11/05 06:46:05 Trace: [opticalRendu] [HighQuality, 16/44 QOBUZ FLAC => 16/44] [100% buf] [PLAYING @ 2:22/3:46] Dublin Farewell - Anthony da Costa
11/05 06:46:07 Info: [stats] 35834mb Virtual, 903mb Physical, 245mb Managed, 287 Handles, 124 Threads
11/05 06:46:10 Trace: [opticalRendu] [HighQuality, 16/44 QOBUZ FLAC => 16/44] [100% buf] [PLAYING @ 2:27/3:46] Dublin Farewell - Anthony da Costa
11/05 06:46:14 Trace: [raat] RAATServer discovered: RaatServer iPhone @ 192.168.1.243:9200
11/05 06:46:14 Info: [raatserver] GOT SERVER 55bbfea7-4a28-4f7d-b429-944efced0dae::e9869362-e31c-483f-b2ec-df0a80830c38 @ 192.168.1.243:9200 iPhone PROTOVER=1 RAATVER=1.1.38 
11/05 06:46:14 Trace: [raatserver] [RaatServer iPhone @ 192.168.1.243:9200] connecting (attempt 1)
11/05 06:46:14 Trace: [push] restarting connection (Unable to read data from the transport connection: Software caused connection abort.)
11/05 06:46:14 Trace: [push] retrying connection in 86456ms

Roon was playing as expected with a full buffer, then there were dropouts on the OpticalRendu (unclear as to why, but the OpticalRendu logs might have more info).

Later we see a similar pattern:

11/05 06:50:56 Trace: [opticalRendu] [HighQuality, 16/44 QOBUZ FLAC => 16/44] [100% buf] [PLAYING @ 3:27/5:24] The Tailor - Terre Roche
11/05 06:51:01 Trace: [opticalRendu] [HighQuality, 16/44 QOBUZ FLAC => 16/44] [100% buf] [PLAYING @ 3:32/5:24] The Tailor - Terre Roche
11/05 06:51:04 Trace: Successful POST response from https://push.roonlabs.com/push/1/connect
11/05 06:51:04 Trace: [push] connecting to 35.196.114.77:9204
11/05 06:51:05 Trace: [push] connected
11/05 06:51:05 Trace: [opticalRendu] [zoneplayer/raat] sync Sonore opticalRendu: realtime=18098133671251 rtt=0us offset=-29699999328us delta=183us drift=-32455us in 3925.878s (-8.267ppm, -29.762ms/hr)
11/05 06:51:06 Trace: [Sonore opticalRendu @ 192.168.1.11:34173] [raatclient] GOT [121] {"status":"Dropout","samples":6563}
11/05 06:51:06 Trace: [opticalRendu] [HighQuality, 16/44 QOBUZ FLAC => 16/44] [100% buf] [PLAYING @ 3:37/5:24] The Tailor - Terre Roche
11/05 06:51:06 Trace: [Sonore opticalRendu @ 192.168.1.11:34173] [raatclient] GOT [121] {"status":"Dropout","samples":22060}
11/05 06:51:07 Trace: [Sonore opticalRendu @ 192.168.1.11:34173] [raatclient] GOT [121] {"status":"Dropout","samples":22060}
11/05 06:51:07 Trace: [Sonore opticalRendu @ 192.168.1.11:34173] [raatclient] GOT [121] {"status":"Dropout","samples":7721}
11/05 06:51:08 Info: [stats] 35754mb Virtual, 973mb Physical, 342mb Managed, 286 Handles, 113 Threads
11/05 06:51:11 Trace: [opticalRendu] [HighQuality, 16/44 QOBUZ FLAC => 16/44] [100% buf] [PLAYING @ 3:42/5:24] The Tailor - Terre Roche
11/05 06:51:16 Trace: [opticalRendu] [HighQuality, 16/44 QOBUZ FLAC => 16/44] [100% buf] [PLAYING @ 3:47/5:24] The Tailor - Terre Roche
11/05 06:51:21 Trace: [opticalRendu] [HighQuality, 16/44 QOBUZ FLAC => 16/44] [100% buf] [PLAYING @ 3:52/5:24] The Tailor - Terre Roche
11/05 06:51:23 Info: [stats] 35914mb Virtual, 906mb Physical, 230mb Managed, 286 Handles, 133 Threads
11/05 06:51:26 Trace: [opticalRendu] [HighQuality, 16/44 QOBUZ FLAC => 16/44] [100% buf] [PLAYING @ 3:57/5:24] The Tailor - Terre Roche
11/05 06:51:31 Trace: [opticalRendu] [HighQuality, 16/44 QOBUZ FLAC => 16/44] [100% buf] [PLAYING @ 4:02/5:24] The Tailor - Terre Roche
11/05 06:51:32 Info: [brokerserver] Client connected: 192.168.1.243:49194
11/05 06:51:32 Trace: [raat] [sood] Refreshing device list
11/05 06:51:32 Trace: [raatserver] [sood] Refreshing device list
11/05 06:51:32 Trace: [raat] RAATServer discovered: RaatServer iPhone @ 192.168.1.243:9200
11/05 06:51:32 Info: [raatserver] GOT SERVER 55bbfea7-4a28-4f7d-b429-944efced0dae::e9869362-e31c-483f-b2ec-df0a80830c38 @ 192.168.1.243:9200 iPhone PROTOVER=1 RAATVER=1.1.38 
11/05 06:51:32 Trace: [push] restarting connection (Unable to read data from the transport connection: Software caused connection abort.)
11/05 06:51:32 Trace: [raatserver] [RaatServer iPhone @ 192.168.1.243:9200] connecting (attempt 1)
11/05 06:51:32 Trace: [push] retrying connection in 58903ms
11/05 06:51:32 Trace: [raatserver] [RaatServer iPhone @ 192.168.1.243:9200] connected

What is interesting about the dropouts is that your iPhone and the connection from the Core to our servers also occurred around the same time, potentially suggesting that the network had a hiccup and couldn’t route network connections properly.