Roon randomly stops playing local files (!) because of network (?) issue

econaut · April 29, 2022, 5:09pm

Roon Core Machine

Windows 10, Intel i7 6800 K, 32GB RAM

Networking Gear & Setup Details

Router: Fritz!Box 6660 → ethernet → Windows PC with Roon Core

Router: Fritz!Box 6660 → ethernet → fibre media converter → fibre → switch: Ether Regen → ethernet → SOtM sMS200 Ultra Neo → USB → Schiit Yggdrasil DAC

Connected Audio Devices

see above

Number of Tracks in Library

11759 tracks

Description of Issue

This situation happens every now and then and it’s very annoying. I listen to local files (music is on the same SSD as the Roon Core) and playback stops suddenly in the middle of a track. I see that Roon says there’s a disconnect of Tidal and/or Qobuz. Streaming services connect again after a few seconds. Then I have to start playback again manually.

I have saved the log file and would appreciate someone to have a look at it. Problem starts at 18:39 time:

Many thanks!

AMP · April 29, 2022, 6:54pm

These errors:

04/29 18:39:06 Trace: [SOtM sMS-200 () @ 192.168.178.22:40483] [raatclient] GOT [13] {"status":"Dropout","samples":22776}
04/29 18:39:06 Trace: [SOtM sMS-200 () @ 192.168.178.22:40483] [raatclient] GOT [13] {"status":"Dropout","samples":24000}
04/29 18:39:06 Trace: [SOtM sMS-200 () @ 192.168.178.22:40483] [raatclient] GOT [13] {"status":"Dropout","samples":24000}
04/29 18:39:06 Trace: [SOtM sMS-200 () @ 192.168.178.22:40483] [raatclient] GOT [13] {"status":"Dropout","samples":36000}
04/29 18:39:06 Trace: [SOtM sMS-200 () @ 192.168.178.22:40483] [raatclient] GOT [13] {"status":"Dropout","samples":24000}
04/29 18:39:06 Trace: [SOtM sMS-200 () @ 192.168.178.22:40483] [raatclient] GOT [13] {"status":"Dropout","samples":24000}
04/29 18:39:06 Trace: [SOtM sMS-200 () @ 192.168.178.22:40483] [raatclient] GOT [13] {"status":"Dropout","samples":24000}
04/29 18:39:06 Trace: [SOtM sMS-200 () @ 192.168.178.22:40483] [raatclient] GOT [13] {"status":"Dropout","samples":24000}
04/29 18:39:06 Trace: [SOtM sMS-200 () @ 192.168.178.22:40483] [raatclient] GOT [13] {"status":"Dropout","samples":24000}

and

04/29 18:39:06 Warn: [Yggdrasil] [zoneplayer/raat] Too many dropouts (>3s dropped out in the last 30s). Killing stream
04/29 18:39:06 Trace: [Yggdrasil] [zoneplayer/raat] too many dropouts. stopping stream
04/29 18:39:06 Trace: [raat] [SOtM sMS-200 () @ 192.168.178.22:40483] => Connecting
04/29 18:39:06 Warn: [Yggdrasil] [zoneplayer/raat] Too many dropouts (>3s dropped out in the last 30s). Killing stream
04/29 18:39:06 Trace: [Yggdrasil] [zoneplayer/raat] too many dropouts. stopping stream
04/29 18:39:06 Warn: [Yggdrasil] [zoneplayer/raat] Too many dropouts (>3s dropped out in the last 30s). Killing stream
04/29 18:39:06 Trace: [Yggdrasil] [zoneplayer/raat] too many dropouts. stopping stream
04/29 18:39:06 Warn: [Yggdrasil] [zoneplayer/raat] Too many dropouts (>3s dropped out in the last 30s). Killing stream
04/29 18:39:06 Trace: [Yggdrasil] [zoneplayer/raat] too many dropouts. stopping stream

Indicate that your core is not able to make consistent contact with your sMS200. This is purely a networking issue and I suspect (based on many negative experiences with the same) that either the fiber media converter or the EtherRegen (or both) are causing intermittent connectivity from your core to the rest of your network.

For instance your core is not able to make a reliable connection to Roon’s cloud service as evidenced by these messages:

4/29 18:39:02 Warn: [easyhttp] [1249] Get https://internetradio.roonlabs.net/2/api/stations/all?count=100&sortby=popular&location=auto&maxDistance=100&format=msgpack& web exception without response: Die Verbindung mit dem Remoteserver kann nicht hergestellt werden. Der Host war bei einem Socketvorgang nicht erreichbar 35.231.208.158:443
04/29 18:39:02 Warn: [easyhttp] [1250] Get https://discover.roonlabs.net/1/albums/121:0:MW0003306502/performers/similar?profileId=d70799f7-1950-45c5-8491-9831afce625b web exception without response: Die Verbindung mit dem Remoteserver kann nicht hergestellt werden. Der Host war bei einem Socketvorgang nicht erreichbar 35.231.208.158:443

I recommend that you remove the media coverter and the EtherRegen from your network and re-test. That will almost surely clear these faults.

econaut · April 29, 2022, 7:12pm

Many thanks for the quick reply. I apologize for not being clear in the network setup details above.

Let me specify (I also updated the info in the first post):

The core is connected directly to the cable router.

The chain with the fibre media converter, Ether Regen, sMS-200 and DAC is also connected to the cable router via ethernet cable at a different port.

The core being connected directly to the router - So your assumption with the FMC and the Ether Regen being the culprits can’t be the case, right?

Robert_F · April 29, 2022, 7:20pm

The EtherREGEN or the media converter may still be an issue as they sit, in the network, between the Core PC and the Yggdrasil, which may be the reason the Yggdrasil is showing so many dropouts.

The issue of the Core not being able to contact Roon’s servers may be a different issue and may result in the dropouts of the DAC. What DNS servers are you using on the FritzBox? Is the DNS something you can change?

PixelPopper · April 30, 2022, 4:04am

That is good advice, as your devices are all in the same local network the above recommendation will take a few minutes and will prove the where the problem is, or isn’t.

econaut · April 30, 2022, 12:07pm

These are good hints.

I was using DNS over TLS (DoT) with different DNS servers than my provider offers. I switched to the default DNS servers in my router settings now.

I only do one change at a time, in order to be able to check if this solves the problem already.

Unfortunately, it’s not a matter of minutes. I can listen to music for hours before this disconnect happens.

EDIT:

As far as I can see there are three errors: the dropouts of the sMS-200, the dropouts of the DAC and the easyhttp warnings.

I see that the first two are probably related, but the third one is not, is it?

I wonder why Roon would stop playing when it loses contact ot the Roon servers as you suggest. This should not be a thing.

Thanks for any clarification

EDIT 2:

I just had a dropout when streaming Qobuz in Roon. I will try without the FMC and Ether Regen now.

econaut · May 28, 2022, 5:30pm

Ok, so I took the fibre out of the network and I think the dropouts of the DAC disappeared. Because there was no unexpected stop of the music for quite some time until now.

I just got a Tidal disconnect in Roon when listening to music from Tidal and the logs don’t say anything about a dropout of the DAC. So far so good, but how do I find out where this problem comes from? I can also imagine it might be a problem of the DNS servers or my ISP?

Here’s the log:

https://pastebin.com/DnbsY2hC

Many thanks!

Robert_F · May 28, 2022, 5:41pm

Good that there is some progress. Can’t say for sure where the Tidal drop could come from, anything from Tidal itself to any point outside or inside your network. I am still getting up to speed on DoT and have not switched to that on my LAN, so not sure if that is an issue.

Roon recommends using Google DNS (8.8.8.8 or 8.8.4.4) or Cloudflare (1.1.1.1 and many others). I know that when I moved my DNS from AT&T to Google’s servers everything, Roon and all other home networking, improved dramatically. Does your ISP or the Fritzbox administration page allow you to change to Google or Cloudflare?

econaut · May 28, 2022, 5:53pm

Thanks, I had switched back from DoT to my ISP’s default DNS servers. Now I switched to google as you suggest (and Roon recommended in the webinar yesterday, didn’t know that before).

Let’s see if that helps. An occasional disconnect every few days might be normal?

Most important thing is that the dropouts seem to have stopped.

EDIT: Switched to Cloudflare due to privacy concerns.

Robert_F · May 28, 2022, 6:02pm

I have not experienced occassional disconnects (AT&T is pretty reliable for me after the DNS change), so hopefully this helps and stablizes everything for you.

econaut · May 29, 2022, 5:00pm

Unfortunately I had two disconnects again today, both times after just about 10 minutes of listening to music:

Socketvorgang nicht erreichbar 35.231.208.158:443
05/29 18:47:28 Warn: [easyhttp] [486] Post https://discovery.roonlabs.net/1/query web exception without response: Die Verbindung mit dem Remoteserver kann nicht hergestellt werden. Der Host war bei einem Socketvorgang nicht erreichbar 35.231.208.158:443
05/29 18:47:28 Warn: [easyhttp] [484] Post https://accounts5.roonlabs.com/accounts/3/login web exception without response: Die Verbindung mit dem Remoteserver kann nicht hergestellt werden. Der Host war bei einem Socketvorgang nicht erreichbar 34.148.110.116:443
05/29 18:47:28 Warn: [easyhttp] [483] Post https://discovery.roonlabs.net/1/query web exception without response: Die Verbindung mit dem Remoteserver kann nicht hergestellt werden. Der Host war bei einem Socketvorgang nicht erreichbar 35.231.208.158:443
05/29 18:47:28 Warn: [easyhttp] [482] Get https://push-manager.roonlabs.net/1/connect web exception without response: Die Verbindung mit dem Remoteserver kann nicht hergestellt werden. Der Host war bei einem Socketvorgang nicht erreichbar 35.231.208.158:443
05/29 18:47:28 Trace: [client/roonbridges] network reachability changed, sending discovery query
05/29 18:47:28 Trace: [roonbridge] [sood] Refreshing device list
05/29 18:47:28 Warn: [easyhttp] [487] Get https://internetradio.roonlabs.net/2/api/location?format=msgpack& web exception without response: Die Verbindung mit dem Remoteserver kann nicht hergestellt werden. Der Host war bei einem Socketvorgang nicht erreichbar 35.231.208.158:443
05/29 18:47:28 Debug: [tidal] network reachability changed. refreshing token
05/29 18:47:28 Warn: [easyhttp] [488] Get https://oauthcb.roonlabs.net/2/tidal/refresh?token=eyJraWQiOiJoUzFKYTdVMCIsImFsZyI6IkVTNTEyIn0.eyJ0eXBlIjoibzJfcmVmcmVzaCIsInVpZCI6MTI1MzY3MDcyLCJzY29wZSI6Indfc3ViIHJfdXNyIHdfdXNyIiwiY2lkIjoyNDI1LCJzVmVyIjowLCJnVmVyIjowLCJpc3MiOiJodHRwczovL2F1dGgudGlkYWwuY29tL3YxIn0.AdqEdWziqYJtMZkscKNAFK3yoEHPRV5I_uocQr5beuol_TzQu7wdjn9gQT4JbD4dUQtPBRh6NGdVJzPiJPMWHkfOADPmQhtGZKTgfd1bo87Cygc8TjWEue1XBBPz_Qx6iW-wvT9YnFiQJ4i_Nly_Hbe_zaCevE4srCApTK0NfXZUEpgr web exception without response: Die Verbindung mit dem Remoteserver kann nicht hergestellt werden. Der Host war bei einem Socketvorgang nicht erreichbar 35.231.208.158:443
05/29 18:47:28 Warn: [easyhttp] [489] Get https://www.qobuz.com/api.json/0.2/user/login?request_sig=0f9a50b8397913363c582dd98fa269c0&request_ts=1653842848 web exception without response: Die Verbindung mit dem Remoteserver kann nicht hergestellt werden. Der Host war bei einem Socketvorgang nicht erreichbar 54.77.101.64:443
05/29 18:47:28 Trace: [raat] [sood] Refreshing device list
05/29 18:47:28 Trace: [raatserver] [sood] Refreshing device list
05/29 18:47:28 Warn: [inetdiscovery] failed to query for services 'com.roonlabs.roon.broker.http|com.roonlabs.roon.broker.tcp|com.roonlabs.roon.broker.tcpv2' in domains 'addr:__ADDR__': Result[Status=NetworkError]
05/29 18:47:28 Warn: [radio/library] got location failed Result[Status=NetworkError]
05/29 18:47:28 Warn: [inetdiscovery] failed to query for services 'com.roonlabs.roonbridge.tcp' in domains 'addr:__ADDR__': Result[Status=NetworkError]
05/29 18:47:28 Warn: [inetdiscovery] failed to query for services 'com.roonlabs.raatserver.tcp' in domains 'addr:__ADDR__': Result[Status=NetworkError]
05/29 18:47:28 Warn: [broker/accounts] failed to refresh account info: Result[Status=NetworkError]
05/29 18:47:28 Trace: [push2] request to push manager failed (https://push-manager.roonlabs.net/1/connect): System.Net.WebException: Die Verbindung mit dem Remoteserver kann nicht hergestellt werden. ---> System.Net.Sockets.SocketException: Der Host war bei einem Socketvorgang nicht erreichbar 35.231.208.158:443
   bei System.Net.Sockets.Socket.InternalEndConnect(IAsyncResult asyncResult)
   bei System.Net.Sockets.Socket.EndConnect(IAsyncResult asyncResult)
   bei System.Net.ServicePoint.ConnectSocketInternal(Boolean connectFailure, Socket s4, Socket s6, Socket& socket, IPAddress& address, ConnectSocketState state, IAsyncResult asyncResult, Exception& exception)
   --- Ende der internen Ausnahmestapelüberwachung ---
   bei System.Net.HttpWebRequest.EndGetResponse(IAsyncResult asyncResult)
   bei System.Threading.Tasks.TaskFactory`1.FromAsyncCoreLogic(IAsyncResult iar, Func`2 endFunction, Action`1 endAction, Task`1 promise, Boolean requiresSynchronization)
--- Ende der Stapelüberwachung vom vorhergehenden Ort, an dem die Ausnahme ausgelöst wurde ---
   bei System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   bei System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   bei Base.EasyHttp.<QueryAsyncInternal>d__11.MoveNext()
05/29 18:47:28 Trace: [push2] retrying connection in 28341ms
05/29 18:47:28 Warn: [qobuz] [http] error result from http request: System.Net.WebException: Die Verbindung mit dem Remoteserver kann nicht hergestellt werden. ---> System.Net.Sockets.SocketException: Der Host war bei einem Socketvorgang nicht erreichbar 54.77.101.64:443
   bei System.Net.Sockets.Socket.InternalEndConnect(IAsyncResult asyncResult)
   bei System.Net.Sockets.Socket.EndConnect(IAsyncResult asyncResult)
   bei System.Net.ServicePoint.ConnectSocketInternal(Boolean connectFailure, Socket s4, Socket s6, Socket& socket, IPAddress& address, ConnectSocketState state, IAsyncResult asyncResult, Exception& exception)
   --- Ende der internen Ausnahmestapelüberwachung ---
   bei System.Net.HttpWebRequest.EndGetResponse(IAsyncResult asyncResult)
   bei System.Threading.Tasks.TaskFactory`1.FromAsyncCoreLogic(IAsyncResult iar, Func`2 endFunction, Action`1 endAction, Task`1 promise, Boolean requiresSynchronization)
--- Ende der Stapelüberwachung vom vorhergehenden Ort, an dem die Ausnahme ausgelöst wurde ---
   bei System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   bei System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   bei Base.EasyHttp.<QueryAsyncInternal>d__11.MoveNext()
05/29 18:47:28 Warn: [metadata_context.cs][qobuz] SetCollection 1, collection: <<null>>
05/29 18:47:28 Info: [qobuz] [module] update qobuz location True => False
05/29 18:47:28 Info: [broker/locations] updating location Qobuz:Name=QOBUZ:Id=f4845d8f-2574-4afe-9fbf-0a3ba8f37867
05/29 18:47:28 Info: [broker/locations] media availability: Qobuz:Name=QOBUZ:Id=f4845d8f-2574-4afe-9fbf-0a3ba8f37867 is offline
05/29 18:47:28 Info: [broker/locations] updating location Qobuz:Name=QOBUZ:Id=f4845d8f-2574-4afe-9fbf-0a3ba8f37867
05/29 18:47:28 Trace: [tidal] transition loginstatus from LoginSucceeded to UnknownError
05/29 18:47:28 Debug: [tidal/storage] dispose
05/29 18:47:28 Warn: [metadata_context.cs][tidal] SetCollection 1, collection: <<null>>
05/29 18:47:28 Info: [broker/locations] removing location Qobuz:Name=qobuz Library:Id=3ae48871-628f-8bc7-1661-77bdaf84af1b
05/29 18:47:28 Info: [broker/locations] media availability: Qobuz:Name=qobuz Library:Id=3ae48871-628f-8bc7-1661-77bdaf84af1b is offline
05/29 18:47:28 Info: [broker/locations] updating location Tidal:Name=TIDAL:Id=a2bc918b-81fb-abc3-f24b-19bcfed910a2
05/29 18:47:28 Info: [broker/locations] media availability: Tidal:Name=TIDAL:Id=a2bc918b-81fb-abc3-f24b-19bcfed910a2 is offline
05/29 18:47:28 Info: [broker/locations] updating location Tidal:Name=TIDAL:Id=a2bc918b-81fb-abc3-f24b-19bcfed910a2
05/29 18:47:28 Info: [broker/locations] removing location Tidal:Name=TIDAL Library:Id=88524181-9894-986a-181d-617c98bc1fda
05/29 18:47:28 Info: [broker/locations] media availability: Tidal:Name=TIDAL Library:Id=88524181-9894-986a-181d-617c98bc1fda is offline
05/29 18:47:28 Warn: AddTopLevel: dimlayer(10022)
05/29 18:47:28 Info: [library] releasing all genres since we have no streaming service
05/29 18:47:28 Warn: AddTopLevel: capturelayer(10023)
05/29 18:47:28 Warn: AddTopLevel: capturelayer(10023)
05/29 18:47:28 Warn: AddTopLevel: win_spinner(10018)
05/29 18:47:28 Warn: AddTopLevel: win_spinner(10018)
05/29 18:47:28 Trace: [inetdiscovery] using cache for services 'com.roonlabs.roonbridge.tcp' in domains 'addr:__ADDR__'
05/29 18:47:28 Trace: [inetdiscovery] using cache for services 'com.roonlabs.raatserver.tcp' in domains 'addr:__ADDR__'
05/29 18:47:28 Trace: [inetdiscovery] using cache for services 'com.roonlabs.roon.broker.http|com.roonlabs.roon.broker.tcp|com.roonlabs.roon.broker.tcpv2' in domains 'addr:__ADDR__'
05/29 18:47:28 Info: [music/storage] Unloading storage backend Qobuz Storage Library
05/29 18:47:28 Warn: AddTopLevel: capturelayer(10023)
05/29 18:47:28 Warn: AddTopLevel: win_spinner(10018)
05/29 18:47:28 Info: [ui] loading home screen
05/29 18:47:28 Trace: [storage/streaming] [Qobuz] ending change detection
05/29 18:47:28 Info: [library] releasing 2156 tracks, 0 auxfiles for storage backend 3ae48871-628f-8bc7-1661-77bdaf84af1b (Qobuz Storage Library)
05/29 18:47:28 Trace: DisposeReusableCellCache: scrollpanel(8725), 0 disposed from cache.
05/29 18:47:28 Info: [zone Yggdrasil] OnPlayFeedback Stopped
05/29 18:47:28 Trace: [Yggdrasil] [Inactive 72,5x] [100% buf] [STOPPED @ 2:31/3:28] Blade and the Will - Unto Others
05/29 18:47:28 Debug: FTMSI-B closed file for qo/3FC98611; open files:0
05/29 18:47:28 Debug: FTMSI-B qo/3FC98611 download status: AllBlocksDownloaded accessTimeout:True openFiles:0 prev:(AllBlocksDownloaded,True,1)
05/29 18:47:28 Trace: [roonapi] network reachability changed. Kicking off discovery cycle
05/29 18:47:28 Debug: FTMSI-B closed file for qo/98EA2C6C; open files:0
05/29 18:47:28 Debug: FTMSI-B qo/98EA2C6C download status: AllBlocksDownloaded accessTimeout:True openFiles:0 prev:(AllBlocksDownloaded,True,1)
05/29 18:47:28 Info: [audio/env] [zoneplayer] All streams were disposed
05/29 18:47:28 Info: [audio/env] [zoneplayer -> stream] All streams were disposed
05/29 18:47:28 Trace: [Yggdrasil] [zoneplayer/raat] Endpoint SOtM sMS-200 () State Changed: Playing => Prepared
05/29 18:47:28 Trace: [SOtM sMS-200 () @ 192.168.178.22:36455] [raatclient] SENT [9]{"request":"end_stream"}
05/29 18:47:28 Debug: [raat/tcpaudiosource] disconnecting
05/29 18:47:28 Info: [audio/env] [zoneplayer -> stream -> endpoint] All streams were disposed
05/29 18:47:28 Debug: unhandled selection type: 
05/29 18:47:28 Warn: AddTopLevel: dimlayer(10022)
05/29 18:47:28 Warn: AddTopLevel: capturelayer(10023)
05/29 18:47:28 Warn: AddTopLevel: capturelayer(10023)
05/29 18:47:28 Warn: AddTopLevel: win_spinner(10018)
05/29 18:47:28 Warn: AddTopLevel: win_spinner(10018)
05/29 18:47:28 Warn: AddTopLevel: capturelayer(10023)
05/29 18:47:28 Warn: AddTopLevel: win_spinner(10018)
05/29 18:47:28 Info: [ui] loading home screen
05/29 18:47:28 Debug: unhandled selection type: 
05/29 18:47:28 Trace: [library] finished with 2597 dirty tracks 349 dirty albums 3318 dirty performers 1505 dirty works 1859 dirty performances 1030 dirty genres 11 dirty countries 1 dirty forms 372 dirty places 84 dirty creditroles 86 dirty labels 0 clumping tracks, 0 clumping auxfiles 0 compute tracks, 0 deleted tracks, 0 tracks to (re)load, 0 tracks to retain, 0 auxfiles to (re)load, 0 auxfiles to retain, and 10217 changed objects
05/29 18:47:28 Info: [library/albumdetails] found 1 ingroup alternates, 0 other alternates
05/29 18:47:28 Warn: AddTopLevel: dimlayer(10022)
05/29 18:47:28 Warn: AddTopLevel: capturelayer(10023)
05/29 18:47:28 Warn: AddTopLevel: capturelayer(10023)
05/29 18:47:28 Warn: AddTopLevel: win_spinner(10018)
05/29 18:47:28 Warn: AddTopLevel: win_spinner(10018)
05/29 18:47:28 Info: [ui] performerdetails.load
05/29 18:47:28 Warn: AddTopLevel: capturelayer(10023)
05/29 18:47:28 Warn: AddTopLevel: win_spinner(10018)
05/29 18:47:28 Trace: [dbperf] flush 0 bytes, 0 ops in 18 ms (cumulative 80714 bytes, 65 ops in 2228 ms)
05/29 18:47:28 Trace: [library] endmutation in 83ms
05/29 18:47:28 Debug: album details have changed, aborting load
05/29 18:47:28 Info: sleep 500ms after flush
05/29 18:47:29 Debug: [music/profilestats] Computed stats in 232ms, got 50 top albums, 50 top performers, 72 genres
05/29 18:47:29 Trace: [dbperf] flush 0 bytes, 0 ops in 36 ms (cumulative 80714 bytes, 65 ops in 2264 ms)
05/29 18:47:29 Trace: [radio/query] performing channel query
05/29 18:47:29 Trace: [radio/query] query returned 0 Sooloos.Broker.Api.Channel(s)
05/29 18:47:29 Debug: PathForResource, filename: genrerules.csv
05/29 18:47:29 Debug: PathForResource, candidate: C:\Users\\AppData\Local\Roon\Application\genrerules.csv
05/29 18:47:29 Debug: PathForResource, candidate: C:\Users\\AppData\Local\Roon\Application\100800952\genrerules.csv
05/29 18:47:29 Trace: [radio/genrerules] loading genre rules from C:\Users\\AppData\Local\Roon\Application\100800952\genrerules.csv
05/29 18:47:29 Trace: [library] finished with 10 dirty genres 0 clumping tracks, 0 clumping auxfiles 0 compute tracks, 0 deleted tracks, 0 tracks to (re)load, 0 tracks to retain, 0 auxfiles to (re)load, 0 auxfiles to retain, and 10 changed objects
05/29 18:47:29 Info: [music/search] [search] library boosting: True
05/29 18:47:29 Trace: [music/search] starting search
05/29 18:47:29 Trace: [music/query] performing album query
05/29 18:47:29 Trace: [music/query] query returned 1074 Sooloos.Broker.Api.AlbumLite(s)
05/29 18:47:29 Debug: GMS: saving nav stack
05/29 18:47:29 Debug: unhandled selection type: 
05/29 18:47:29 Debug: [music/profilestats] Computed stats in 159ms, got 50 top albums, 50 top performers, 72 genres
05/29 18:47:29 Trace: [dbperf] flush 0 bytes, 0 ops in 31 ms (cumulative 80714 bytes, 65 ops in 2295 ms)
05/29 18:47:29 Trace: [radio/query] performing channel query
05/29 18:47:29 Trace: [radio/query] query returned 0 Sooloos.Broker.Api.Channel(s)
05/29 18:47:29 Info: [music/storage] Unloading storage backend My Tidal Library
05/29 18:47:29 Trace: [tidal] ending change detection
05/29 18:47:29 Info: [library] releasing 2297 tracks, 0 auxfiles for storage backend 88524181-9894-986a-181d-617c98bc1fda (My Tidal Library)
05/29 18:47:29 Trace: [library] finished with 2693 dirty tracks 364 dirty albums 4584 dirty performers 1404 dirty works 1850 dirty performances 570 dirty genres 13 dirty countries 5 dirty periods 6 dirty forms 585 dirty places 194 dirty creditroles 875 dirty labels 0 clumping tracks, 0 clumping auxfiles 0 compute tracks, 0 deleted tracks, 0 tracks to (re)load, 0 tracks to retain, 0 auxfiles to (re)load, 0 auxfiles to retain, and 11069 changed objects
05/29 18:47:29 Trace: [dbperf] flush 0 bytes, 0 ops in 17 ms (cumulative 80714 bytes, 65 ops in 2312 ms)
05/29 18:47:29 Trace: [library] endmutation in 76ms
05/29 18:47:29 Info: [music/search] [search] library boosting: True
05/29 18:47:29 Trace: [music/search] starting search
05/29 18:47:29 Trace: [library] endmutation in 12ms
05/29 18:47:29 Trace: [music/searchindex] [search-index]  removed: 349 albums, 2156 tracks, 957 works, 2882 performers, 86 labels, 557 genres
05/29 18:47:29 Trace: [music/searchindex] [search-index] added in 1651ms: 72 albums, 0 tracks, 0 works, 0 performers, 0 labels, 0 genres
05/29 18:47:29 Debug: GMS: done saving nav stack
05/29 18:47:29 Trace: [library] endmutation in 1097ms
05/29 18:47:29 Trace: [music/searchindex] [search-index]  removed: 364 albums, 2297 tracks, 889 works, 4220 performers, 875 labels, 108 genres
05/29 18:47:29 Trace: [music/searchindex] [search-index] added in 1651ms: 39 albums, 0 tracks, 0 works, 0 performers, 0 labels, 0 genres
05/29 18:47:29 Trace: [library] endmutation in 230ms
05/29 18:47:29 Debug: GMS: saving nav stack
05/29 18:47:29 Debug: GMS: done saving nav stack
05/29 18:47:29 Debug: [easyhttp] [490] GET to https://internetradio.roonlabs.net/2/api/stations/all?count=100&sortby=popular&location=auto&maxDistance=100&format=msgpack& returned after 566 ms, status code: 200
05/29 18:47:29 Info: [stats] 6917mb Virtual, 1169mb Physical, 420mb Managed, 2717 Handles, 188 Threads
05/29 18:47:29 Debug: [easyhttp] [491] GET to https://internetradio.roonlabs.net/2/api/stations/search?query=unto others&count=50&format=msgpack& returned after 748 ms, status code: 200
05/29 18:47:29 Debug: [easyhttp] [492] GET to https://internetradio.roonlabs.net/2/api/stations/all?count=100&sortby=popular&location=auto&maxDistance=100&format=msgpack& returned after 582 ms, status code: 200

Switching to the Google DNS servers now.

There’s no fibre in the setup right now and I don’t understand how the network leg from the router to the DAC could be the culprit here. I’d rather think about the cable from the router to the core or the DNS servers or my ISP?

By the way, how can one make this paste of the log file scrollable an/or collapsible? In other forums this is called spoiler, but I can’t find it here.

Rugby · May 29, 2022, 5:40pm

There were network errors trying to reach 35.231.208.158 in your logs, as well as 34.148.110.116. I am able to ping both IPs and get an acceptable response time, and running a tracerts, I’m getting about a 27ms route time to Google’s Servers.

You might try running ping and trace routes and see what you get.

econaut · May 29, 2022, 6:16pm

Thanks for the suggestion. A little (?) slower here and while doing several pings I had a lost packet once.

C:\Users\econaut>tracert 35.231.208.158

Routenverfolgung zu 158.208.231.35.bc.googleusercontent.com [35.231.208.158]
über maximal 30 Hops:

  1     1 ms     1 ms     1 ms  fritz.box [192.168.178.1]
  2    14 ms     9 ms    10 ms  ip4d1677fe.dynamic.kabel-deutschland.de [77.22.119.254]
  3     8 ms     8 ms     9 ms  ip53a99a6e.static.kabel-deutschland.de [83.169.154.110]
  4    12 ms    12 ms     8 ms  ip5886bbd7.dynamic.kabel-deutschland.de [88.134.187.215]
  5    12 ms    13 ms    11 ms  145.254.3.136
  6    28 ms    12 ms    15 ms  145.254.2.215
  7    11 ms    13 ms    10 ms  145.254.2.215
  8    13 ms    12 ms    12 ms  72.14.216.250
  9   128 ms   108 ms   108 ms  158.208.231.35.bc.googleusercontent.com [35.231.208.158]

Ablaufverfolgung beendet.

C:\Users\econaut>tracert 34.148.110.116

Routenverfolgung zu 116.110.148.34.bc.googleusercontent.com [34.148.110.116]
über maximal 30 Hops:

  1     1 ms     1 ms     1 ms  fritz.box [192.168.178.1]
  2    11 ms    11 ms    10 ms  ip4d1677fe.dynamic.kabel-deutschland.de [77.22.119.254]
  3    14 ms    22 ms    21 ms  ip53a99a6e.static.kabel-deutschland.de [83.169.154.110]
  4    10 ms    11 ms     9 ms  ip5886bbd7.dynamic.kabel-deutschland.de [88.134.187.215]
  5    11 ms     8 ms     8 ms  145.254.3.136
  6     *        *       13 ms  145.254.2.215
  7     *       16 ms    11 ms  145.254.2.215
  8    11 ms    12 ms    11 ms  72.14.216.250
  9   108 ms   109 ms   107 ms  116.110.148.34.bc.googleusercontent.com [34.148.110.116]

Ablaufverfolgung beendet.

But connection to google in Germany is faster, of course:

C:\Users\econaut>tracert google.de

Routenverfolgung zu google.de [172.217.16.67]
über maximal 30 Hops:

  1    <1 ms     1 ms     1 ms  fritz.box [192.168.178.1]
  2    13 ms    11 ms    12 ms  ip4d1677fe.dynamic.kabel-deutschland.de [77.22.119.254]
  3    10 ms    10 ms    12 ms  ip53a99a6e.static.kabel-deutschland.de [83.169.154.110]
  4     9 ms     9 ms    10 ms  ip5886bbd7.dynamic.kabel-deutschland.de [88.134.187.215]
  5    10 ms    11 ms    10 ms  145.254.3.136
  6    12 ms    13 ms    11 ms  145.254.2.215
  7    12 ms    11 ms    13 ms  145.254.2.215
  8    11 ms    13 ms    11 ms  72.14.216.250
  9    14 ms    15 ms    14 ms  216.239.63.21
 10    13 ms    13 ms    12 ms  216.239.49.249
 11    16 ms     9 ms    11 ms  par03s13-in-f67.1e100.net [172.217.16.67]

Ablaufverfolgung beendet.

noris · June 15, 2022, 11:07pm

Hi @econaut ,

Are you still seeing any issues at the present time? In your last log, it looked like you had a network reachability event, and then couldn’t access Qobuz or Roon servers, almost as if the router or Core connection to the internet went down.

econaut:

05/29 18:47:28 Trace: [client/roonbridges] network reachability changed, sending discovery query
05/29 18:47:28 Trace: [roonbridge] [sood] Refreshing device list
05/29 18:47:28 Warn: [easyhttp] [487] Get https://internetradio.roonlabs.net/2/api/location?format=msgpack& web exception without response: Die Verbindung mit dem Remoteserver kann nicht hergestellt werden. Der Host war bei einem Socketvorgang nicht erreichbar 35.231.208.158:443
05/29 18:47:28 Debug: [tidal] network reachability changed. refreshing token
05/29 18:47:28 Warn: [easyhttp] [488] Get https://oauthcb.roonlabs.net/2/tidal/refresh?token=eyJraWQiOiJoUzFKYTdVMCIsImFsZyI6IkVTNTEyIn0.eyJ0eXBlIjoibzJfcmVmcmVzaCIsInVpZCI6MTI1MzY3MDcyLCJzY29wZSI6Indfc3ViIHJfdXNyIHdfdXNyIiwiY2lkIjoyNDI1LCJzVmVyIjowLCJnVmVyIjowLCJpc3MiOiJodHRwczovL2F1dGgudGlkYWwuY29tL3YxIn0.AdqEdWziqYJtMZkscKNAFK3yoEHPRV5I_uocQr5beuol_TzQu7wdjn9gQT4JbD4dUQtPBRh6NGdVJzPiJPMWHkfOADPmQhtGZKTgfd1bo87Cygc8TjWEue1XBBPz_Qx6iW-wvT9YnFiQJ4i_Nly_Hbe_zaCevE4srCApTK0NfXZUEpgr web exception without response: Die Verbindung mit dem Remoteserver kann nicht hergestellt werden. Der Host war bei einem Socketvorgang nicht erreichbar 35.231.208.158:443
05/29 18:47:28 Warn: [easyhttp] [489] Get https://www.qobuz.com/api.json/0.2/user/login?request_sig=0f9a50b8397913363c582dd98fa269c0&request_ts=1653842848 web exception without response: Die Verbindung mit dem Remoteserver kann nicht hergestellt werden. Der Host war bei einem Socketvorgang nicht erreichbar 54.77.101.64:443

econaut · June 16, 2022, 7:30am

Hi @noris ,

thanks for reaching out to me.

Unfortunately, I still have these issues and it gets a little over my head, because I am not proficient enough to understand the log files.

What I did:

I am using the Google DNS servers now.
I took the fibre out and it reduced the dropouts, but there still was one without fibre and with Google DNS playing a local file (log from 04.06.)
I ordered an opticalRendu and got rid of the cheap FMC, so the network is simpler and better now but I still have dropouts.

The problem is that I don’t understand if it is one or two different errors and what is causing them exactly: The dropouts and the disconnects to the servers.

There are log files where it seems that first there is the disconnect to the servers and then the dropout follows after that (log from 11.06.). As far as I understand fibre can’t be causing this, as there is no fibre between the core and the router. So this seems to me an “internet” thing and not a LAN thing.

I zipped the log files that I saved after connection issues. There were a few more, but I do not save everytime.

Attached is the network setup since yesterday.

econaut · June 19, 2022, 10:30am

I got the advice to separate my audio network from the router.

So I added a cheap switch between the router and Roon core and the streamer. See diagram.

The hypothesis is that the Fritz!Box router has not the best quality parts inside and that one should only let it do the routing and use a separate switch for that switching duties and also separate wifi from the router. I will do the latter in a next step.

This seems to make a difference as I did not have a dropout since Thursday night and I listened to music many hours every day. So I believe this is an improvement, because normally there would have been more dropouts - but it could also be merely coincidence, although rather unlikely, I think.

Unfortunately, I just had a droput again (log file 11:57). But I wonder if this was a disconnect by/to Qobuz or my particular dropout problem in my home network.

Maybe someone more knowledgable than me can chime in and interpret this log file? Many thanks!


06/19 11:53:14 Trace: [Yggdrasil] [Enhanced 70,9x, 16/44 QOBUZ FLAC => 32/44] [100% buf] [PLAYING @ 1:16/8:20] Aftermath 3 - AES Dana
06/19 11:53:19 Trace: [Yggdrasil] [Enhanced 70,8x, 16/44 QOBUZ FLAC => 32/44] [100% buf] [PLAYING @ 1:21/8:20] Aftermath 3 - AES Dana
06/19 11:53:21 Trace: [Yggdrasil] [zoneplayer/raat] sync Sonore opticalRendu: realtime=17474201602856 rtt=500us offset=11585678602us delta=-15us drift=-16083us in 939,7555s (-17,115ppm, -61,613ms/hr)
06/19 11:53:24 Trace: [Yggdrasil] [Enhanced 71,0x, 16/44 QOBUZ FLAC => 32/44] [100% buf] [PLAYING @ 1:26/8:20] Aftermath 3 - AES Dana
06/19 11:53:26 Info: [stats] 7307mb Virtual, 1225mb Physical, 393mb Managed, 2842 Handles, 189 Threads
06/19 11:53:29 Trace: [Yggdrasil] [Enhanced 71,0x, 16/44 QOBUZ FLAC => 32/44] [100% buf] [PLAYING @ 1:31/8:20] Aftermath 3 - AES Dana
06/19 11:53:34 Trace: [Yggdrasil] [Enhanced 71,2x, 16/44 QOBUZ FLAC => 32/44] [100% buf] [PLAYING @ 1:36/8:20] Aftermath 3 - AES Dana
06/19 11:53:39 Trace: [Yggdrasil] [Enhanced 71,1x, 16/44 QOBUZ FLAC => 32/44] [100% buf] [PLAYING @ 1:41/8:20] Aftermath 3 - AES Dana
06/19 11:53:41 Info: [stats] 7307mb Virtual, 1225mb Physical, 395mb Managed, 2841 Handles, 189 Threads
06/19 11:53:44 Trace: [Yggdrasil] [Enhanced 71,2x, 16/44 QOBUZ FLAC => 32/44] [100% buf] [PLAYING @ 1:46/8:20] Aftermath 3 - AES Dana
06/19 11:53:50 Trace: [Yggdrasil] [Enhanced 71,3x, 16/44 QOBUZ FLAC => 32/44] [100% buf] [PLAYING @ 1:52/8:20] Aftermath 3 - AES Dana
06/19 11:53:51 Trace: [Yggdrasil] [zoneplayer/raat] sync Sonore opticalRendu: realtime=17504585984678 rtt=500us offset=11585676984us delta=-244us drift=-17701us in 970,1415s (-18,247ppm, -65,688ms/hr)
06/19 11:53:55 Trace: [Yggdrasil] [Enhanced 71,3x, 16/44 QOBUZ FLAC => 32/44] [100% buf] [PLAYING @ 1:57/8:20] Aftermath 3 - AES Dana
06/19 11:53:56 Info: [stats] 7307mb Virtual, 1225mb Physical, 399mb Managed, 2841 Handles, 189 Threads
06/19 11:54:00 Trace: [Yggdrasil] [Enhanced 71,4x, 16/44 QOBUZ FLAC => 32/44] [100% buf] [PLAYING @ 2:02/8:20] Aftermath 3 - AES Dana
06/19 11:54:05 Trace: [Yggdrasil] [Enhanced 71,6x, 16/44 QOBUZ FLAC => 32/44] [100% buf] [PLAYING @ 2:07/8:20] Aftermath 3 - AES Dana
06/19 11:54:10 Trace: [Yggdrasil] [Enhanced 71,5x, 16/44 QOBUZ FLAC => 32/44] [100% buf] [PLAYING @ 2:12/8:20] Aftermath 3 - AES Dana
06/19 11:54:11 Info: [stats] 7307mb Virtual, 1225mb Physical, 400mb Managed, 2841 Handles, 189 Threads
06/19 11:54:15 Trace: [Yggdrasil] [Enhanced 71,5x, 16/44 QOBUZ FLAC => 32/44] [100% buf] [PLAYING @ 2:17/8:20] Aftermath 3 - AES Dana
06/19 11:54:20 Trace: [Yggdrasil] [Enhanced 71,6x, 16/44 QOBUZ FLAC => 32/44] [100% buf] [PLAYING @ 2:22/8:20] Aftermath 3 - AES Dana
06/19 11:54:22 Trace: [Yggdrasil] [zoneplayer/raat] sync Sonore opticalRendu: realtime=17535031395850 rtt=0us offset=11585676395us delta=-72us drift=-18290us in 1000,588s (-18,280ppm, -65,807ms/hr)
06/19 11:54:25 Trace: [Yggdrasil] [Enhanced 71,7x, 16/44 QOBUZ FLAC => 32/44] [100% buf] [PLAYING @ 2:27/8:20] Aftermath 3 - AES Dana
06/19 11:54:26 Info: [stats] 7307mb Virtual, 1225mb Physical, 404mb Managed, 2841 Handles, 189 Threads
06/19 11:54:30 Trace: [Yggdrasil] [Enhanced 71,7x, 16/44 QOBUZ FLAC => 32/44] [100% buf] [PLAYING @ 2:32/8:20] Aftermath 3 - AES Dana
06/19 11:54:35 Trace: [Yggdrasil] [Enhanced 71,8x, 16/44 QOBUZ FLAC => 32/44] [100% buf] [PLAYING @ 2:37/8:20] Aftermath 3 - AES Dana
06/19 11:54:41 Info: [stats] 7311mb Virtual, 1225mb Physical, 390mb Managed, 2846 Handles, 190 Threads
06/19 11:54:41 Trace: [Yggdrasil] [Enhanced 71,9x, 16/44 QOBUZ FLAC => 32/44] [100% buf] [PLAYING @ 2:43/8:20] Aftermath 3 - AES Dana
06/19 11:54:46 Trace: [Yggdrasil] [Enhanced 71,9x, 16/44 QOBUZ FLAC => 32/44] [100% buf] [PLAYING @ 2:48/8:20] Aftermath 3 - AES Dana
06/19 11:54:51 Trace: [Yggdrasil] [Enhanced 72,0x, 16/44 QOBUZ FLAC => 32/44] [100% buf] [PLAYING @ 2:53/8:20] Aftermath 3 - AES Dana
06/19 11:54:52 Trace: [Yggdrasil] [zoneplayer/raat] sync Sonore opticalRendu: realtime=17565210522302 rtt=500us offset=11585675522us delta=-143us drift=-19164us in 1030,7675s (-18,592ppm, -66,931ms/hr)
06/19 11:54:54 Trace: [broker/accounts] [heartbeat] now=19.06.2022 09:54:53 nextauthrefresh=19.06.2022 10:19:54 nextmachineallocate=19.06.2022 12:14:53
06/19 11:54:56 Info: [stats] 7311mb Virtual, 1225mb Physical, 391mb Managed, 2846 Handles, 190 Threads
06/19 11:54:56 Trace: [Yggdrasil] [Enhanced 72,2x, 16/44 QOBUZ FLAC => 32/44] [100% buf] [PLAYING @ 2:58/8:20] Aftermath 3 - AES Dana
06/19 11:55:01 Trace: [Yggdrasil] [Enhanced 72,2x, 16/44 QOBUZ FLAC => 32/44] [100% buf] [PLAYING @ 3:03/8:20] Aftermath 3 - AES Dana
06/19 11:55:06 Trace: [Yggdrasil] [Enhanced 72,2x, 16/44 QOBUZ FLAC => 32/44] [100% buf] [PLAYING @ 3:08/8:20] Aftermath 3 - AES Dana
06/19 11:55:11 Info: [stats] 7307mb Virtual, 1225mb Physical, 397mb Managed, 2843 Handles, 189 Threads
06/19 11:55:11 Trace: [Yggdrasil] [Enhanced 72,2x, 16/44 QOBUZ FLAC => 32/44] [100% buf] [PLAYING @ 3:13/8:20] Aftermath 3 - AES Dana
06/19 11:55:16 Trace: [Yggdrasil] [Enhanced 72,3x, 16/44 QOBUZ FLAC => 32/44] [100% buf] [PLAYING @ 3:18/8:20] Aftermath 3 - AES Dana
06/19 11:55:21 Trace: [Yggdrasil] [Enhanced 72,3x, 16/44 QOBUZ FLAC => 32/44] [100% buf] [PLAYING @ 3:23/8:20] Aftermath 3 - AES Dana
06/19 11:55:22 Trace: [Yggdrasil] [zoneplayer/raat] sync Sonore opticalRendu: realtime=17595523105149 rtt=0us offset=11585675105us delta=-732us drift=-19581us in 1061,081s (-18,454ppm, -66,435ms/hr)
06/19 11:55:26 Info: [stats] 7307mb Virtual, 1225mb Physical, 395mb Managed, 2843 Handles, 189 Threads
06/19 11:55:26 Trace: [Yggdrasil] [Enhanced 72,4x, 16/44 QOBUZ FLAC => 32/44] [100% buf] [PLAYING @ 3:28/8:20] Aftermath 3 - AES Dana
06/19 11:55:32 Trace: [Yggdrasil] [Enhanced 72,5x, 16/44 QOBUZ FLAC => 32/44] [100% buf] [PLAYING @ 3:34/8:20] Aftermath 3 - AES Dana
06/19 11:55:37 Trace: [Yggdrasil] [Enhanced 72,6x, 16/44 QOBUZ FLAC => 32/44] [100% buf] [PLAYING @ 3:39/8:20] Aftermath 3 - AES Dana
06/19 11:55:41 Info: [stats] 7307mb Virtual, 1225mb Physical, 398mb Managed, 2843 Handles, 189 Threads
06/19 11:55:42 Trace: [Yggdrasil] [Enhanced 72,5x, 16/44 QOBUZ FLAC => 32/44] [100% buf] [PLAYING @ 3:44/8:20] Aftermath 3 - AES Dana
06/19 11:55:47 Trace: [Yggdrasil] [Enhanced 72,6x, 16/44 QOBUZ FLAC => 32/44] [100% buf] [PLAYING @ 3:48/8:20] Aftermath 3 - AES Dana
06/19 11:55:52 Trace: [Yggdrasil] [Enhanced 72,6x, 16/44 QOBUZ FLAC => 32/44] [100% buf] [PLAYING @ 3:54/8:20] Aftermath 3 - AES Dana
06/19 11:55:53 Trace: [Yggdrasil] [zoneplayer/raat] sync Sonore opticalRendu: realtime=17625988742321 rtt=500us offset=11585674742us delta=566us drift=-19944us in 1091,5465s (-18,271ppm, -65,777ms/hr)
06/19 11:55:56 Info: [stats] 7307mb Virtual, 1225mb Physical, 397mb Managed, 2843 Handles, 189 Threads
06/19 11:55:57 Trace: [Yggdrasil] [Enhanced 72,6x, 16/44 QOBUZ FLAC => 32/44] [100% buf] [PLAYING @ 3:59/8:20] Aftermath 3 - AES Dana
06/19 11:56:02 Trace: [Yggdrasil] [Enhanced 72,6x, 16/44 QOBUZ FLAC => 32/44] [100% buf] [PLAYING @ 4:04/8:20] Aftermath 3 - AES Dana
06/19 11:56:07 Trace: [Yggdrasil] [Enhanced 72,7x, 16/44 QOBUZ FLAC => 32/44] [100% buf] [PLAYING @ 4:09/8:20] Aftermath 3 - AES Dana
06/19 11:56:11 Info: [stats] 7307mb Virtual, 1225mb Physical, 398mb Managed, 2841 Handles, 189 Threads
06/19 11:56:12 Trace: [Yggdrasil] [Enhanced 72,8x, 16/44 QOBUZ FLAC => 32/44] [100% buf] [PLAYING @ 4:14/8:20] Aftermath 3 - AES Dana
06/19 11:56:18 Trace: [Yggdrasil] [Enhanced 72,7x, 16/44 QOBUZ FLAC => 32/44] [100% buf] [PLAYING @ 4:20/8:20] Aftermath 3 - AES Dana
06/19 11:56:23 Trace: [Yggdrasil] [zoneplayer/raat] sync Sonore opticalRendu: realtime=17656284875162 rtt=500us offset=11585673875us delta=-164us drift=-20811us in 1121,8435s (-18,551ppm, -66,783ms/hr)
06/19 11:56:23 Trace: [Yggdrasil] [Enhanced 72,9x, 16/44 QOBUZ FLAC => 32/44] [100% buf] [PLAYING @ 4:25/8:20] Aftermath 3 - AES Dana
06/19 11:56:26 Info: [stats] 7311mb Virtual, 1225mb Physical, 390mb Managed, 2846 Handles, 190 Threads
06/19 11:56:28 Trace: [Yggdrasil] [Enhanced 73,0x, 16/44 QOBUZ FLAC => 32/44] [100% buf] [PLAYING @ 4:30/8:20] Aftermath 3 - AES Dana
06/19 11:56:33 Trace: [Yggdrasil] [Enhanced 72,9x, 16/44 QOBUZ FLAC => 32/44] [100% buf] [PLAYING @ 4:35/8:20] Aftermath 3 - AES Dana
06/19 11:56:38 Trace: [Yggdrasil] [Enhanced 73,0x, 16/44 QOBUZ FLAC => 32/44] [100% buf] [PLAYING @ 4:40/8:20] Aftermath 3 - AES Dana
06/19 11:56:41 Info: [stats] 7307mb Virtual, 1225mb Physical, 391mb Managed, 2841 Handles, 189 Threads
06/19 11:56:43 Trace: [Yggdrasil] [Enhanced 73,1x, 16/44 QOBUZ FLAC => 32/44] [100% buf] [PLAYING @ 4:45/8:20] Aftermath 3 - AES Dana
06/19 11:56:48 Trace: [Yggdrasil] [Enhanced 73,1x, 16/44 QOBUZ FLAC => 32/44] [100% buf] [PLAYING @ 4:50/8:20] Aftermath 3 - AES Dana
06/19 11:56:53 Trace: [Yggdrasil] [Enhanced 73,1x, 16/44 QOBUZ FLAC => 32/44] [100% buf] [PLAYING @ 4:55/8:20] Aftermath 3 - AES Dana
06/19 11:56:53 Trace: [Yggdrasil] [zoneplayer/raat] sync Sonore opticalRendu: realtime=17686684983338 rtt=500us offset=11585672983us delta=-255us drift=-21703us in 1152,2445s (-18,835ppm, -67,808ms/hr)
06/19 11:56:56 Info: [stats] 7307mb Virtual, 1225mb Physical, 395mb Managed, 2841 Handles, 189 Threads
06/19 11:56:58 Trace: [Yggdrasil] [Enhanced 73,2x, 16/44 QOBUZ FLAC => 32/44] [100% buf] [PLAYING @ 5:00/8:20] Aftermath 3 - AES Dana
06/19 11:57:03 Trace: [Yggdrasil] [Enhanced 73,3x, 16/44 QOBUZ FLAC => 32/44] [100% buf] [PLAYING @ 5:05/8:20] Aftermath 3 - AES Dana
06/19 11:57:09 Trace: [Yggdrasil] [Enhanced 73,3x, 16/44 QOBUZ FLAC => 32/44] [100% buf] [PLAYING @ 5:11/8:20] Aftermath 3 - AES Dana
06/19 11:57:11 Info: [stats] 7307mb Virtual, 1225mb Physical, 395mb Managed, 2841 Handles, 189 Threads
06/19 11:57:14 Trace: [Yggdrasil] [Enhanced 73,4x, 16/44 QOBUZ FLAC => 32/44] [100% buf] [PLAYING @ 5:16/8:20] Aftermath 3 - AES Dana
06/19 11:57:19 Trace: [Yggdrasil] [Enhanced 73,5x, 16/44 QOBUZ FLAC => 32/44] [100% buf] [PLAYING @ 5:21/8:20] Aftermath 3 - AES Dana
06/19 11:57:24 Trace: [Yggdrasil] [zoneplayer/raat] sync Sonore opticalRendu: realtime=17717158296177 rtt=500us offset=11585672296us delta=-1027us drift=-22390us in 1182,7185s (-18,931ppm, -68,152ms/hr)
06/19 11:57:24 Trace: [Yggdrasil] [Enhanced 73,6x, 16/44 QOBUZ FLAC => 32/44] [100% buf] [PLAYING @ 5:26/8:20] Aftermath 3 - AES Dana
06/19 11:57:26 Info: [stats] 7307mb Virtual, 1225mb Physical, 397mb Managed, 2841 Handles, 189 Threads
06/19 11:57:29 Trace: [Yggdrasil] [Enhanced 73,6x, 16/44 QOBUZ FLAC => 32/44] [100% buf] [PLAYING @ 5:31/8:20] Aftermath 3 - AES Dana
06/19 11:57:33 Trace: [Sonore opticalRendu @ 192.168.178.39:36709] [raatclient] GOT [63] {"status":"Dropout","samples":261}
06/19 11:57:34 Trace: [Sonore opticalRendu @ 192.168.178.39:36709] [raatclient] GOT [63] {"status":"Dropout","samples":22060}
06/19 11:57:34 Trace: [Yggdrasil] [Enhanced 73,6x, 16/44 QOBUZ FLAC => 32/44] [100% buf] [PLAYING @ 5:36/8:20] Aftermath 3 - AES Dana
06/19 11:57:34 Trace: [Sonore opticalRendu @ 192.168.178.39:36709] [raatclient] GOT [63] {"status":"Dropout","samples":22060}
06/19 11:57:35 Trace: [Sonore opticalRendu @ 192.168.178.39:36709] [raatclient] GOT [63] {"status":"Dropout","samples":22060}
06/19 11:57:35 Trace: [Sonore opticalRendu @ 192.168.178.39:36709] [raatclient] GOT [63] {"status":"Dropout","samples":22060}
06/19 11:57:36 Trace: [Sonore opticalRendu @ 192.168.178.39:36709] [raatclient] GOT [63] {"status":"Dropout","samples":22060}
06/19 11:57:36 Trace: [Sonore opticalRendu @ 192.168.178.39:36709] [raatclient] GOT [63] {"status":"Dropout","samples":22060}
06/19 11:57:36 Warn: [Yggdrasil] [zoneplayer/raat] Too many dropouts (>3s dropped out in the last 30s). Killing stream
06/19 11:57:36 Trace: [Yggdrasil] [zoneplayer/raat] too many dropouts. stopping stream
06/19 11:57:36 Debug: FTMSI-B closed file for qo/678126CD; open files:0
06/19 11:57:36 Debug: FTMSI-B closed file for qo/3A6976B9; open files:0
06/19 11:57:36 Debug: FTMSI-B qo/678126CD download status: AllBlocksDownloaded accessTimeout:True openFiles:0 prev:(AllBlocksDownloaded,True,1)
06/19 11:57:36 Debug: FTMSI-B qo/3A6976B9 download status: AllBlocksDownloaded accessTimeout:False openFiles:0 prev:(AllBlocksDownloaded,False,1)
06/19 11:57:36 Info: [audio/env] [zoneplayer -> stream] All streams were disposed
06/19 11:57:36 Trace: [Yggdrasil] [zoneplayer/raat] Endpoint Sonore opticalRendu State Changed: Playing => Prepared
06/19 11:57:36 Trace: [Sonore opticalRendu @ 192.168.178.39:36709] [raatclient] SENT [65]{"request":"end_stream"}
06/19 11:57:36 Debug: [raat/tcpaudiosource] disconnecting
06/19 11:57:36 Info: [audio/env] [zoneplayer] All streams were disposed
06/19 11:57:36 Warn: [zone Yggdrasil] Track Stopped Due to Slow Media
06/19 11:57:36 Info: [audio/env] [zoneplayer -> stream -> endpoint] All streams were disposed
06/19 11:57:36 Warn: [raat/tcpaudiosource] send failed: Der Objektverweis wurde nicht auf eine Objektinstanz festgelegt.
06/19 11:57:36 Warn: [raat/tcpaudiosource] disconnecting + retrying
06/19 11:57:36 Trace: [Sonore opticalRendu @ 192.168.178.39:36709] [raatclient] GOT [63] {"status":"Ended"}
06/19 11:57:36 Debug: Lastfm 'fpBZV_fac0DqdWWD0HHUGrgUqxqaOyu6' DONE: AES Dana - Aftermath 3 
06/19 11:57:36 Info: [library] recorded play for profile d70799f7-1950-45c5-8491-9831afce625b: mediaid=202:0:23686938 metadataid= contentid=202:0:23686938 libraryid= isfromradio=False isfrommix=False isfrommobile=
06/19 11:57:36 Info: 
--[ SignalPath ]---------------------------------------------
SignalPath Quality = Inactive
Elements:
------------------------------------------------------------
06/19 11:57:36 Warn: inactive signal path :(
06/19 11:57:36 Info: [zone Yggdrasil] OnPlayFeedback StoppedEndOfMediaUnnatural
06/19 11:57:36 Debug: [zone Yggdrasil] _Advance
06/19 11:57:36 Trace: [Yggdrasil] [Enhanced, 16/44 QOBUZ FLAC => 32/44] [100% buf] [LOADING @ 0:00] Culture - Tikal
06/19 11:57:36 Info: Alert: qobuz: qobuz_media_slow
06/19 11:57:36 Warn: AddTopLevel: win_alert(10153)
06/19 11:57:36 Info: Alert: qobuz: qobuz_media_slow
06/19 11:57:36 Info: sleep 50ms after flush
06/19 11:57:36 Info: [Yggdrasil] [zoneplayer] BufferingTrack == NextTrack during ClearQueuedMedia, setting _stop_on_next_track_transition
06/19 11:57:36 Trace: [Sonore opticalRendu @ 192.168.178.39:36709] [raatclient] GOT [65] {"status":"Success"}
06/19 11:57:36 Debug: [easyhttp] [1536] POST to http://ws.audioscrobbler.com/2.0/ returned after 170 ms, status code: 200
06/19 11:57:36 Debug: [easyhttp] [1538] GET to https://www.qobuz.com/api.json/0.2/track/getFileUrl?format_id=27&intent=stream&request_sig=92de59b00027e23ecb05da99183461d6&request_ts=1655632656&track_id=23686940 returned after 195 ms, status code: 200
06/19 11:57:36 Debug: [easyhttp] [1537] GET to https://www.qobuz.com/api.json/0.2/track/getFileUrl?format_id=27&intent=stream&request_sig=050efba2017acff6df4e7fe8f989a5c7&request_ts=1655632656&track_id=23686939 returned after 317 ms, status code: 200
06/19 11:57:36 Info: [Yggdrasil] [zoneplayer] Playing: https://streaming-qobuz-std.akamaized.net/file
06/19 11:57:36 Info: [Yggdrasil] [zoneplayer] Queueing: https://streaming-qobuz-std.akamaized.net/file
06/19 11:57:36 Info: FTMSI-B new FileCache qo/113BCC19
>>> C:\Users\ \AppData\Local\Roon\Cache\smc.db\bfc\13.cache
>>> https://streaming-qobuz-std.akamaized.net/file
06/19 11:57:36 Debug: FTMSI-B Cache open file qo/113BCC19 domain: zoneplayer:1 ordinal:35
06/19 11:57:36 Debug: FTMSI-B qo/113BCC19 download status: DownloadNotStarted accessTimeout:False openFiles:1 prev:no
06/19 11:57:36 Info: FTMSI-B qo/113BCC19: allocated bw changed from 0 to 51200 kbps
06/19 11:57:36 Info: FTMSI-B 1 FileCache qo/113BCC19 dwStatus:DownloadNotStarted files:1 accessTimeOut:False priorities: ('zoneplayer:1':35) --> bw limit:51200kbps
06/19 11:57:36 Info: FTMSI-B 2 FileCache qo/3A6976B9 dwStatus:AllBlocksDownloaded files:0 accessTimeOut:False priorities: ('zoneplayer:1':33) --> bw limit:0kbps
06/19 11:57:36 Info: FTMSI-B 3 FileCache qo/678126CD dwStatus:AllBlocksDownloaded files:0 accessTimeOut:True priorities: ('zoneplayer:1':34) --> bw limit:0kbps
06/19 11:57:36 Info: FTMSI-B FileCache removed qo/3A6976B9
06/19 11:57:36 Debug: FTMSI-B-OE qo/3A6976B9 exit thread signalled
06/19 11:57:36 Trace: FTMSI-B 1 FileCache qo/113BCC19 dwStatus:DownloadNotStarted files:1 accessTimeOut:False priorities: ('zoneplayer:1':35) --> bw limit:51200kbps
06/19 11:57:36 Debug: FTMSI-B-OE qo/3A6976B9 exit thread signalled
06/19 11:57:36 Trace: FTMSI-B 2 FileCache qo/678126CD dwStatus:AllBlocksDownloaded files:0 accessTimeOut:True priorities: ('zoneplayer:1':34) --> bw limit:0kbps
06/19 11:57:36 Debug: FTMSI-B-OE qo/113BCC19 created new req 1 for block 0 p 4294967295; active requests 1
06/19 11:57:36 Info: FTMSI-B FileCache disposed qo/3A6976B9
06/19 11:57:36 Info: FTMSI-B new FileCache qo/A47AE575
>>> C:\Users\ \AppData\Local\Roon\Cache\smc.db\bfc\14.cache
>>> https://streaming-qobuz-std.akamaized.net/file
06/19 11:57:36 Debug: FTMSI-B Cache open file qo/A47AE575 domain: zoneplayer:1 ordinal:36
06/19 11:57:36 Debug: FTMSI-B qo/A47AE575 download status: DownloadNotStarted accessTimeout:False openFiles:1 prev:no
06/19 11:57:36 Info: FTMSI-B FileCache removed qo/678126CD
06/19 11:57:36 Debug: FTMSI-B-OE qo/678126CD exit thread signalled
06/19 11:57:36 Trace: FTMSI-B 1 FileCache qo/113BCC19 dwStatus:DownloadNotStarted files:1 accessTimeOut:False priorities: ('zoneplayer:1':35) --> bw limit:51200kbps
06/19 11:57:36 Trace: FTMSI-B 2 FileCache qo/A47AE575 dwStatus:DownloadNotStarted files:1 accessTimeOut:False priorities: ('zoneplayer:1':36) --> bw limit:0kbps
06/19 11:57:36 Debug: FTMSI-B-OE qo/678126CD exit thread signalled
06/19 11:57:36 Info: FTMSI-B FileCache disposed qo/678126CD
06/19 11:57:36 Debug: [easyhttp] [1547] GET to https://streaming-qobuz-std.akamaized.net/file?uid=1488110&eid=23686939&fmt=6&profile=raw&app_id=188245549&cid=1395411&etsp=1655636255&hmac=smxaAhNT8j2PDp9j25dx0s-NHVs returned after 73 ms, status code: 200
06/19 11:57:36 Debug: FTMSI-B got length for qo/113BCC19; 55,1 MBytes
06/19 11:57:36 Debug: FTMSI-B qo/113BCC19 download status: FileLengthRetrieved accessTimeout:False openFiles:1 prev:(DownloadNotStarted,False,1)
06/19 11:57:36 Debug: FTMSI-B-OE set min bandwidth for qo/113BCC19 to 1048 kbps
06/19 11:57:36 Info: FTMSI-B-OE qo/113BCC19 rid:1 response took 75ms
06/19 11:57:36 Debug: FTMSI-B qo/113BCC19 download status: FirstBlockRetrieved accessTimeout:False openFiles:1 prev:(FileLengthRetrieved,False,1)
06/19 11:57:36 Debug: [easyhttp] [1535] POST to https://www.qobuz.com/api.json/0.2/track/reportStreamingEnd? returned after 420 ms, status code: 200
06/19 11:57:37 Debug: [easyhttp] [1539] GET to https://metadata.roonlabs.net/1/performers/94:1:056803e7-7f67-4b0c-b5a8-57ecef7bd3f2?c=tidal-de,qobuz-de returned after 451 ms, status code: 200
06/19 11:57:37 Debug: [easyhttp] [1544] GET to https://metadata.roonlabs.net/1/performers/94:1:056803e7-7f67-4b0c-b5a8-57ecef7bd3f2/relationships?c=tidal-de,qobuz-de returned after 454 ms, status code: 200
06/19 11:57:37 Debug: [easyhttp] [1540] GET to https://metadata.roonlabs.net/1/performers/94:1:056803e7-7f67-4b0c-b5a8-57ecef7bd3f2/relationships?c=tidal-de,qobuz-de returned after 457 ms, status code: 200
06/19 11:57:37 Debug: [easyhttp] [1546] GET to https://metadata.roonlabs.net/1/performers/94:1:056803e7-7f67-4b0c-b5a8-57ecef7bd3f2/biographies?c=tidal-de,qobuz-de returned after 468 ms, status code: 200
06/19 11:57:37 Debug: [easyhttp] [1543] GET to https://metadata.roonlabs.net/1/performers/94:1:056803e7-7f67-4b0c-b5a8-57ecef7bd3f2?c=tidal-de,qobuz-de returned after 470 ms, status code: 200
06/19 11:57:37 Debug: [easyhttp] [1545] GET to https://metadata.roonlabs.net/1/performers/94:1:056803e7-7f67-4b0c-b5a8-57ecef7bd3f2/refs?c=tidal-de,qobuz-de returned after 470 ms, status code: 200
06/19 11:57:37 Debug: [easyhttp] [1542] GET to https://metadata.roonlabs.net/1/performers/94:1:056803e7-7f67-4b0c-b5a8-57ecef7bd3f2/biographies?c=tidal-de,qobuz-de returned after 471 ms, status code: 200
06/19 11:57:37 Debug: [easyhttp] [1541] GET to https://metadata.roonlabs.net/1/performers/94:1:056803e7-7f67-4b0c-b5a8-57ecef7bd3f2/refs?c=tidal-de,qobuz-de returned after 518 ms, status code: 200
06/19 11:57:37 Debug: GMS: saving nav stack
06/19 11:57:37 Debug: GMS: trying to save nav stack, but nav stack stuff was in progress
06/19 11:57:37 Debug: GMS: done saving nav stack
06/19 11:57:37 Info: [Yggdrasil] [zoneplayer]     Open Result (Playing):Result[Status=Success]
06/19 11:57:37 Info: [Yggdrasil] [zoneplayer] Starting playback
06/19 11:57:37 Debug: [convolution] adjusted filter length from 87586 to 87562 since filter had trailing zeroes
06/19 11:57:37 Trace: [prebuffer] ready 149940/441000 (34%) @ 0/517 sec
06/19 11:57:37 Debug: [convolution] performing convolution with 4 paths
06/19 11:57:37 Trace: [Yggdrasil] [zoneplayer/raat] StartStream Sooloos.Broker.Transport.RaatZonePlayer+Endpoint: StreamFormat(channels=2, bitspersample=16, samplerate=44100, isdts=False) => StreamFormat(channels=2, bitspersample=32, samplerate=44100, isdts=False) streamid=1096490366
06/19 11:57:37 Debug: Lastfm 'fpBZV_fac0DqdWWD0HHUGrgUqxqaOyu6' START: Tikal - Culture 
06/19 11:57:37 Info: [zone Yggdrasil] OnPlayFeedback Playing
06/19 11:57:37 Trace: [Yggdrasil] [Enhanced, 16/44 QOBUZ FLAC => 32/44] [100% buf] [PLAYING @ 0:00] Culture - Tikal
06/19 11:57:37 Trace: [Yggdrasil] [zoneplayer/raat] synced to endpoint Sonore opticalRendu clock: realtime=17730123681197 rtt=500us offset=11585671681us delta=11585671681us
06/19 11:57:37 Trace: [Sonore opticalRendu @ 192.168.178.39:36709] [raatclient] SENT [66]{"request":"stream","stream_id":1096490366,"first_seq":-1,"nak_port":-1,"buffer_size":10,"ready_threshold":0.2}
06/19 11:57:37 Trace: [Sonore opticalRendu @ 192.168.178.39:36709] [raatclient] GOT [66] {"status":"Buffering"}
06/19 11:57:37 Trace: [Yggdrasil] [zoneplayer/raat] Endpoint Sonore opticalRendu State Changed: Prepared => Buffering
06/19 11:57:37 Trace: [Yggdrasil] [zoneplayer/raat] [zoneplayer/raat] selected Sonore opticalRendu as clock master
06/19 11:57:37 Debug: [easyhttp] [1548] POST to https://www.qobuz.com/api.json/0.2/track/reportStreamingStart? returned after 102 ms, status code: 201
06/19 11:57:37 Debug: [raat/tcpaudiosource] connecting to 192.168.178.39:34779
06/19 11:57:37 Debug: [raat/tcpaudiosource] connected
06/19 11:57:37 Debug: [easyhttp] [1549] POST to http://ws.audioscrobbler.com/2.0/ returned after 141 ms, status code: 200
06/19 11:57:37 Trace: [Sonore opticalRendu @ 192.168.178.39:36709] [raatclient] GOT [66] {"status":"Ready"}
06/19 11:57:37 Trace: [Yggdrasil] [zoneplayer/raat] Endpoint Sonore opticalRendu State Changed: Buffering => Ready
06/19 11:57:37 Info: 
--[ SignalPath ]---------------------------------------------
SignalPath Quality = Enhanced
Elements:
    Source Format=Flac 44100/16/2  Quality=Lossless
    UpgradeBitDepth FromBitsPerSample=16 ToBitsPerSample=64 Quality=Lossless
    Convolution
    Truncate FromBitsPerSample=64 ToBitsPerSample=32 Quality=Lossless
    Raat Device=Sonore opticalRendu
    Output OutputType=Local_Usb Quality=Lossless SubType= Model=
------------------------------------------------------------
06/19 11:57:37 Trace: [Yggdrasil] [zoneplayer/raat] wait for ready in 0ms
06/19 11:57:37 Trace: [Yggdrasil] [zoneplayer/raat] Adjusting playback start offset from 50ms to 70ms
06/19 11:57:37 Trace: [Yggdrasil] [zoneplayer/raat] Doing 'ASAP' Start since we are just playing to one device
06/19 11:57:37 Trace: [Sonore opticalRendu @ 192.168.178.39:36709] [raatclient] SENT [67]{"request":"start","min_offset":70929705,"stream_sample":0}
06/19 11:57:37 Trace: [Yggdrasil] [zoneplayer/raat] Endpoint Sonore opticalRendu State Changed: Ready => Playing
06/19 11:57:37 Trace: [Sonore opticalRendu @ 192.168.178.39:36709] [raatclient] GOT [66] {"status":"Playing"}
06/19 11:57:37 Trace: [Sonore opticalRendu @ 192.168.178.39:36709] [raatclient] GOT [67] {"status":"Success","time":17730738810335}
06/19 11:57:38 Debug: FTMSI-B qo/113BCC19 download status: FirstBlockRetrieved accessTimeout:True openFiles:1 prev:(FirstBlockRetrieved,False,1)
06/19 11:57:39 Debug: GETKEY. KeyToChar(Capital, False, False) -> 
06/19 11:57:39 Debug: GETKEY. KeyToChar(Capital, False, False) -> 
06/19 11:57:40 Debug: FTMSI-B qo/113BCC19 download status: FirstBlockRetrieved accessTimeout:False openFiles:1 prev:(FirstBlockRetrieved,True,1)
06/19 11:57:41 Info: [stats] 7335mb Virtual, 1226mb Physical, 427mb Managed, 2924 Handles, 196 Threads
06/19 11:57:41 Debug: FTMSI-B qo/113BCC19 download status: FirstBlockRetrieved accessTimeout:True openFiles:1 prev:(FirstBlockRetrieved,False,1)
06/19 11:57:42 Debug: UI-NAV: queue
06/19 11:57:42 Debug: UI-FORCE-LAZY: mode: nowplaying
06/19 11:57:42 Debug: UI-FORCE-LAZY: mode: artistdetails
06/19 11:57:42 Debug: GMS: saving nav stack
06/19 11:57:42 Debug: UI-NAV: queue
06/19 11:57:42 Debug: unhandled selection type: 
06/19 11:57:42 Debug: GMS: done saving nav stack
06/19 11:57:42 Trace: [Yggdrasil] [Enhanced 67,0x, 16/44 QOBUZ FLAC => 32/44] [100% buf] [PLAYING @ 0:04/8:37] Culture - Tikal
06/19 11:57:42 Trace: GetImageData[Remote](id=3960 spec=256 key=iwfaaaaa uri=https://imagecache.roonlabs.net/im/1/albums/79004d5730303032363036383136/cover/256.jpg) => fetched in 64ms status=304 size=0 overalltime=66ms
06/19 11:57:42 Debug: [easyhttp] [1550] GET to http://127.0.0.1:9300/image/iwfaaaaa.256.jpg returned after 72 ms, status code: 304
06/19 11:57:44 Debug: FTMSI-B qo/113BCC19 download status: FirstBlockRetrieved accessTimeout:False openFiles:1 prev:(FirstBlockRetrieved,True,1)
06/19 11:57:45 Info: [ui] [popups] Pause button clicked: play_pause()
06/19 11:57:45 Trace: [zone Yggdrasil] PlayPause
06/19 11:57:45 Trace: [zone Yggdrasil] Pause
06/19 11:57:45 Info: [zone Yggdrasil] Canceling Pending Sleep
06/19 11:57:45 Trace: [Yggdrasil] [zoneplayer/raat] Pausing at streamtime_ns 7666275031 now_ns 17738405085366
06/19 11:57:45 Trace: [Sonore opticalRendu @ 192.168.178.39:36709] [raatclient] SENT [68]{"request":"stop"}
06/19 11:57:45 Info: [zone Yggdrasil] OnPlayFeedback Paused
06/19 11:57:45 Trace: [Yggdrasil] [Enhanced, 16/44 QOBUZ FLAC => 32/44] [100% buf] [PAUSED @ 0:07/8:37] Culture - Tikal
06/19 11:57:45 Trace: [Yggdrasil] [zoneplayer/raat] Endpoint Sonore opticalRendu State Changed: Playing => Paused
06/19 11:57:45 Trace: [Sonore opticalRendu @ 192.168.178.39:36709] [raatclient] GOT [66] {"status":"Stopped"}
06/19 11:57:45 Debug: FTMSI-B qo/113BCC19 download status: FirstBlockRetrieved accessTimeout:True openFiles:1 prev:(FirstBlockRetrieved,False,1)
06/19 11:57:45 Trace: [Sonore opticalRendu @ 192.168.178.39:36709] [raatclient] GOT [68] {"status":"Success"}
06/19 11:57:50 Trace: [zone Yggdrasil] Suspend
06/19 11:57:50 Trace: [zone Yggdrasil] Stop
06/19 11:57:50 Info: [zone Yggdrasil] OnPlayFeedback Stopped
06/19 11:57:50 Info: [zone Yggdrasil] Canceling Pending Sleep
06/19 11:57:50 Debug: FTMSI-B closed file for qo/113BCC19; open files:0
06/19 11:57:50 Debug: FTMSI-B qo/113BCC19 download status: FirstBlockRetrieved accessTimeout:True openFiles:0 prev:(FirstBlockRetrieved,True,1)
06/19 11:57:50 Info: [audio/env] [zoneplayer -> stream] All streams were disposed
06/19 11:57:50 Info: FTMSI-B qo/113BCC19: allocated bw changed from 51200 to 0 kbps
06/19 11:57:50 Info: FTMSI-B qo/A47AE575: allocated bw changed from 0 to 51200 kbps
06/19 11:57:50 Info: FTMSI-B 1 FileCache qo/113BCC19 dwStatus:FirstBlockRetrieved files:0 accessTimeOut:True priorities: ('zoneplayer:1':35) --> bw limit:0kbps
06/19 11:57:50 Info: FTMSI-B 2 FileCache qo/A47AE575 dwStatus:DownloadNotStarted files:1 accessTimeOut:True priorities: ('zoneplayer:1':36) --> bw limit:51200kbps
06/19 11:57:50 Trace: [Yggdrasil] [zoneplayer/raat] Endpoint Sonore opticalRendu State Changed: Paused => Prepared
06/19 11:57:50 Info: [audio/env] [zoneplayer] All streams were disposed
06/19 11:57:50 Info: [audio/env] [zoneplayer -> stream -> endpoint] All streams were disposed
06/19 11:57:50 Trace: [Sonore opticalRendu @ 192.168.178.39:36709] [raatclient] SENT [69]{"request":"end_stream"}
06/19 11:57:50 Trace: [Sonore opticalRendu @ 192.168.178.39:36709] [raatclient] SENT [70]{"request":"teardown"}
06/19 11:57:50 Trace: [Yggdrasil] [zoneplayer/raat] Endpoint Sonore opticalRendu State Changed: Prepared => Idle
06/19 11:57:50 Debug: [raat/tcpaudiosource] disconnecting
06/19 11:57:50 Debug: FTMSI-B-OE qo/A47AE575 created new req 1 for block 0 p 4294967295; active requests 1
06/19 11:57:50 Trace: [transport] disabling transport
06/19 11:57:50 Trace: [zone Yggdrasil] Suspend
06/19 11:57:50 Info: [zone Yggdrasil] Canceling Pending Sleep
06/19 11:57:50 Info: [zone Yggdrasil] Canceling Pending Sleep
06/19 11:57:50 Trace: [raat] disposing
06/19 11:57:50 Trace: [airplay] disposing
06/19 11:57:50 Trace: [devialet] disposing
06/19 11:57:50 Trace: [devicemanager/sonos] disposing
06/19 11:57:50 Trace: [devicemanager/kef] disposing
06/19 11:57:50 Trace: [hqplayer] disposing
06/19 11:57:50 Trace: [meridian] disposing
06/19 11:57:50 Info: sleep 50ms after flush
06/19 11:57:50 Debug: [easyhttp] [1554] POST to https://discovery.roonlabs.net/1/unregister returned after 227 ms, status code: 200
06/19 11:57:50 Trace: [inetdiscovery] unregistered 1 devices
06/19 11:57:50 Debug: [easyhttp] [1552] POST to https://www.qobuz.com/api.json/0.2/track/reportStreamingEnd? returned after 263 ms, status code: 200
06/19 11:57:50 Debug: [easyhttp] [1553] GET to https://streaming-qobuz-std.akamaized.net/file?uid=1488110&eid=23686940&fmt=6&profile=raw&app_id=188245549&cid=1395411&etsp=1655636255&hmac=DTlbXknDeiIa_ZuNEXGKQemUXfE returned after 549 ms, status code: 200
06/19 11:57:50 Debug: FTMSI-B got length for qo/A47AE575; 46,6 MBytes
06/19 11:57:50 Debug: FTMSI-B qo/A47AE575 download status: FileLengthRetrieved accessTimeout:True openFiles:1 prev:(DownloadNotStarted,True,1)
06/19 11:57:50 Debug: FTMSI-B-OE set min bandwidth for qo/A47AE575 to 994 kbps
06/19 11:57:50 Info: FTMSI-B-OE qo/A47AE575 rid:1 response took 549ms
06/19 11:57:51 Debug: FTMSI-B qo/A47AE575 download status: FirstBlockRetrieved accessTimeout:False openFiles:1 prev:(FileLengthRetrieved,False,1)
06/19 11:57:51 Info: [Yggdrasil] [zoneplayer] Open result (Queueing): Result[Status=Success]
06/19 11:57:51 Debug: FTMSI-B closed file for qo/A47AE575; open files:0
06/19 11:57:51 Debug: FTMSI-B qo/A47AE575 download status: FirstBlockRetrieved accessTimeout:False openFiles:0 prev:(FirstBlockRetrieved,False,1)
06/19 11:57:51 Info: FTMSI-B qo/A47AE575: allocated bw changed from 51200 to 0 kbps
06/19 11:57:51 Info: FTMSI-B 1 FileCache qo/113BCC19 dwStatus:FirstBlockRetrieved files:0 accessTimeOut:True priorities: ('zoneplayer:1':35) --> bw limit:0kbps
06/19 11:57:51 Info: FTMSI-B 2 FileCache qo/A47AE575 dwStatus:FirstBlockRetrieved files:0 accessTimeOut:False priorities: ('zoneplayer:1':36) --> bw limit:0kbps
06/19 11:57:51 Info: [audio/env] [zoneplayer] All streams were disposed
06/19 11:57:51 Debug: [storage] dispose deleting: C:\Users\ \AppData\Local\Roon\Temp\3932bc4663014cd499e42f4aaaa9738a
06/19 11:57:51 Warn: [storage] [directory] [itunes] dispose !!!!
06/19 11:57:51 Debug: [tidal/storage] dispose

noris · June 22, 2022, 5:49pm

Hello @econaut ,

Thank you for the update here and glad to hear that there’s been an improvement!

econaut:

06/19 11:57:29 Trace: [Yggdrasil] [Enhanced 73,6x, 16/44 QOBUZ FLAC => 32/44] [100% buf] [PLAYING @ 5:31/8:20] Aftermath 3 - AES Dana
06/19 11:57:33 Trace: [Sonore opticalRendu @ 192.168.178.39:36709] [raatclient] GOT [63] {"status":"Dropout","samples":261}
06/19 11:57:34 Trace: [Sonore opticalRendu @ 192.168.178.39:36709] [raatclient] GOT [63] {"status":"Dropout","samples":22060}
06/19 11:57:34 Trace: [Yggdrasil] [Enhanced 73,6x, 16/44 QOBUZ FLAC => 32/44] [100% buf] [PLAYING @ 5:36/8:20] Aftermath 3 - AES Dana
06/19 11:57:34 Trace: [Sonore opticalRendu @ 192.168.178.39:36709] [raatclient] GOT [63] {"status":"Dropout","samples":22060}

Looking over that trace, it looks like the Dropout occurred when the buffer was at 100% and the Core processing speed was good (73.6x). I would say that this issue could be due to the OpticalRendu dropping out, or something with the chain to reach the OpticalRendu.

As a test, if you have multiple zones playing, for example, the OpticalRendu and the System Ouput on the PC, do you notice only the OpticalRendu has the dropouts while the PC keeps playing? Are you also able to connect any other zones from the OpticalRendu to see if DACs other than the Schitt also exhibit the behavior?

system · August 6, 2022, 5:49pm

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

econaut · August 21, 2022, 3:14pm

Maybe others stumble over this and are interested in the solution that worked for me.

As mentioned above: Adding the el cheapo switch in order to separate the audio network from the other network and thus taking switch duties off the router already made a huge improvement. So it’s this principle that’s the solution, I think.

Shortly after I upgraded the switch to an industrial managed one with SFP ports and made sure it had flow control enabled. I also added an optical fiber card in my Roon core.

My system has never sounded better and gladly the network is stable now. I had only one dropout/disconnect in the last two months, which could have been caused by anything.

Thinking of it, I will enable DNS over TLS (DoT) in my router again now. Let’s see if things will stay stable - I am pretty sure they will