Roon skips some tracks and then finally plays one

Peter_Galvin1 · August 31, 2020, 4:06pm

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

2020 iMac, macOS 10.15.6

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

Ethernet to SoTM SM-200 Neo

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

TEXT GOES HERE

Description Of Issue

This happens occasionally but finally captured the details. Let me know if you want the log file from 12:02 pm today.

I select a local album (as opposed to Tidal, where this also happens)
I click “play”,
Roon skips down through each track, and finally (in this instance) the last track starts playing.
Clicking play again, the same thing happens. I think I can fix it by restarting Roon, but that’s annoying.
I verified the first track exists on the file system etc…

nuwriy · September 2, 2020, 2:33pm

Hello @Peter_Galvin1, and thanks for your report! Are you seeing this behavior when playing to any endpoint? How about playing to system output?

Peter_Galvin1 · October 6, 2020, 9:18pm

Just happened again.
Tried to play local album “Van Halen”.
Skipped several tracks before starting to play one.
Switched from SOtM to system system output. Same problem.
Restarted roon, the problem went away.

nuwriy · October 8, 2020, 2:21pm

Hello @Peter_Galvin1,

I have enabled diagnostics on your account so our technical staff can get some more insight into what’s going on here. The next time your Core is active a diagnostics report will automatically be generated and uploaded directly to our servers

Once that’s been received, I’ll be sure to update this thread and pass the diagnostics over to the team for further analysis.

Peter_Galvin1 · October 14, 2020, 9:13pm

It just happens again. Seems to happen for example if I don’t use roon for 24 hours (or more) while leaving it open. 5:12PM EDT 10/14/2020

Peter_Galvin1 · October 19, 2020, 8:39pm

Any ideas?

Peter_Galvin1 · October 19, 2020, 9:10pm

I just updated roon to latest build on my mac,
selected the newest album I’ve added to play. (It played earlier today, then skipped later, so restarted roon, got the notice about the update, updated…)
Album play attempt skipped through all the tracks, not playing any on the album.
The errors all seem to be along these lines:

10/19 17:06:12 Info: [SOtM] [zoneplayer] Playing: /Volumes/macbt/itunes/music/Jorma Kaukonen/Blue Country Heart/04 - Red River Blues.wav
10/19 17:06:12 Info: [SOtM] [zoneplayer] Queueing: /Volumes/macbt/itunes/music/Jorma Kaukonen/Blue Country Heart/05 - Bread Line Blues.wav
10/19 17:06:12 Trace: [dbperf] flush 0 bytes, 0 ops in 2 ms (cumulative 41691257 bytes, 19169 ops in 28428 ms)
10/19 17:06:12 Info: [library/albumdetails] Created album details screen for LibraryAlbum[7344175, Jorma Kaukonen - Blue Country Heart]
10/19 17:06:12 Info: [library/albumdetails] 79004d5730303030363539393034, 79004d5230303031323433343832, 79004d5230303031303131323539, 79004d5230303030333030393938, 79004d5230303031343236393336, 3e01867e0866d6474d498ddf19a86612bf15, 3e01c371ae4874089a449ecc913dd1f50d3b, 3e01f43b8a52fad58a4e9b119b37d4f0fe70, a60031323734343530, a6003130303433, a600313230393239313234, c80035303939373530383135353236, c80030363936393938363339343233, be00363033393930, be003136343632373836
10/19 17:06:12 Trace: waveformshader(2420) texture loaded: 111, 2000 bytes.
10/19 17:06:12 Trace: [dbperf] flush 0 bytes, 0 ops in 2 ms (cumulative 41691257 bytes, 19169 ops in 28430 ms)
10/19 17:06:12 Critical: [easyhttp] [21] Post https://metadata.roonlabs.net/1/works/translate?c=tidal-us web exception without response: : System.Net.WebException: Error: ConnectFailure (Could not register to wait for file descriptor 2129) —> System.NotSupportedException: Could not register to wait for file descriptor 2129
at (wrapper managed-to-native) System.IOSelector.Add(intptr,System.IOSelectorJob)
at System.Net.Sockets.Socket.BeginSConnect (System.Net.Sockets.SocketAsyncResult sockares) [0x001da] in :0
at System.Net.Sockets.Socket.BeginConnect (System.Net.EndPoint remoteEP, System.AsyncCallback callback, System.Object state) [0x0002b] in :0
at System.Net.WebConnection+<>c.b__16_0 (System.Net.IPEndPoint targetEndPoint, System.AsyncCallback callback, System.Object state) [0x00000] in :0
at System.Threading.Tasks.TaskFactory1[TResult].FromAsyncImpl[TArg1] (System.Func4[T1,T2,T3,TResult] beginMethod, System.Func2[T,TResult] endFunction, System.Action1[T] endAction, TArg1 arg1, System.Object state, System.Threading.Tasks.TaskCreationOptions creationOptions) [0x000f9] in :0
at System.Threading.Tasks.TaskFactory.FromAsync[TArg1] (System.Func4[T1,T2,T3,TResult] beginMethod, System.Action1[T] endMethod, TArg1 arg1, System.Object state, System.Threading.Tasks.TaskCreationOptions creationOptions) [0x00000] in :0
at System.Threading.Tasks.TaskFactory.FromAsync[TArg1] (System.Func4[T1,T2,T3,TResult] beginMethod, System.Action1[T] endMethod, TArg1 arg1, System.Object state) [0x00000] in :0
at System.Net.WebConnection.Connect (System.Net.WebOperation operation, System.Threading.CancellationToken cancellationToken) [0x0013b] in :0
— End of inner exception stack trace —
at System.Net.WebConnection.Connect (System.Net.WebOperation operation, System.Threading.CancellationToken cancellationToken) [0x0025d] in :0
at System.Net.WebConnection.InitConnection (System.Net.WebOperation operation, System.Threading.CancellationToken cancellationToken) [0x000cc] in :0
at System.Net.WebOperation.Run () [0x0009a] in :0
at System.Net.WebCompletionSource1[T].WaitForCompletion () [0x00094] in <f34012a0712d47c3928ecd2def984fcd>:0 at System.Net.HttpWebRequest.RunWithTimeoutWorker[T] (System.Threading.Tasks.Task1[TResult] workerTask, System.Int32 timeout, System.Action abort, System.Func1[TResult] aborted, System.Threading.CancellationTokenSource cts) [0x000f8] in <f34012a0712d47c3928ecd2def984fcd>:0 at System.Net.HttpWebRequest.EndGetRequestStream (System.IAsyncResult asyncResult) [0x00020] in <f34012a0712d47c3928ecd2def984fcd>:0 at System.Threading.Tasks.TaskFactory1[TResult].FromAsyncCoreLogic (System.IAsyncResult iar, System.Func2[T,TResult] endFunction, System.Action1[T] endAction, System.Threading.Tasks.Task`1[TResult] promise, System.Boolean requiresSynchronization) [0x0000f] in :0
— End of stack trace from previous location where exception was thrown —

nuwriy · October 21, 2020, 12:50pm

Hello @Peter_Galvin1, and thanks for the trace! I’ll add it to your ticket. The team also wanted to know if you were using DSP when you have this issue? Also could you please send me a screenshot of your signal path?

Peter_Galvin1 · October 21, 2020, 1:27pm

No DSP. Here it is plus the signal path.

nuwriy · October 22, 2020, 7:08pm

Hello @Peter_Galvin1, and thanks for your patience while the team discussed the issue. We found the following trace multiple times in your log which seemed to stop after a reboot:

10/05 23:58:13 Error: [transport] emptying out corrupt zone database 22:1:6b0230d1-416a-a636-da9d-f1f454742e91
10/05 23:58:13 Critical: scx: in OnExit: System.NullReferenceException: Object reference not set to an instance of an object
  at Sooloos.Broker.Transport.Zone._CancelPendingSleep () [0x00000] in <544635550a274f9f9fb369314b5a751b>:0 
  at Sooloos.Broker.Transport.Zone._StopWithoutTouchingDatabases () [0x00007] in <544635550a274f9f9fb369314b5a751b>:0 
  at Sooloos.Broker.Transport.Module.NotifyCorruptZoneDatabases (Sooloos.Broker.Transport.IZone zone, System.Exception e) [0x0005b] in <544635550a274f9f9fb369314b5a751b>:0 
  at Sooloos.Broker.Transport.Zone..ctor (Sooloos.Broker.State state, Sooloos.Broker.Transport.Module module, System.Sooid zoneid, System.Collections.Generic.IEnumerable`1[T] endpoints) [0x00133] in <544635550a274f9f9fb369314b5a751b>:0 
  at Sooloos.Broker.Transport.Module.NewZone (Sooloos.Broker.State state, Sooloos.Broker.Transport.Module module, System.Sooid zoneid, System.Collections.Generic.IEnumerable`1[T] endpoints) [0x00000] in <544635550a274f9f9fb369314b5a751b>:0 
  at Sooloos.Broker.Transport.Module.ev_threadexit () [0x009fe] in <544635550a274f9f9fb369314b5a751b>:0 
  at Sooloos.SynchronizationContextThread.OnExit () [0x0000a] in <ca6f693f07f44c41b45930c645d55e7d>:0 
10/05 23:58:13 Debug: NotifyCorruptZoneDatabases Exception LevelDb.Exception: IO error: /Users/pbg/Library/Roon/Database/Core/6fbfe46f171c4fb59a4974c86cf998fd/transport/zone_1601d130026b6a4136a6da9df1f454742e91.db/LOCK: Too many open files
  at LevelDb.Database._CheckError (System.IntPtr err) [0x00037] in <86505ae99ab946f9b432f1a335c76c2a>:0 
  at LevelDb.Database..ctor (System.String path) [0x00075] in <86505ae99ab946f9b432f1a335c76c2a>:0 
  at Sooloos.Broker.Transport.ZoneDb..ctor (System.String dbpath) [0x0000d] in <544635550a274f9f9fb369314b5a751b>:0 
  at Sooloos.Broker.Transport.Zone..ctor (Sooloos.Broker.State state, Sooloos.Broker.Transport.Module module, System.Sooid zoneid, System.Collections.Generic.IEnumerable`1[T] endpoints) [0x0010f] in <544635550a274f9f9fb369314b5a751b>:0

Our team would like to do some network troubleshooting for the issue, would you kindly test the following and let me know the results?

Could you connect to a mobile hotspot and try to reproduce the issue? We’d like to see if this happens on a different network.
Please reply here with a timestamp of when you test this so I can collect more diagnostics for the report.

Peter_Galvin1 · October 23, 2020, 12:06am

So you want me to disconnect my imac from wifi and ethernet, have it use my phone as a hotspot, and then have it play music to my SoTM?

Peter_Galvin1 · October 24, 2020, 2:42pm

Happened again at 9:30 this morning.
Restarting roon solves the problem. I don’t think it has anything to do with my local network.

nuwriy · October 26, 2020, 8:13pm

Hello @Peter_Galvin1, connecting to your phone would be correct. Let me know if the issue persists on a hotspot! The main purpose of this test is to have our QA team compare log traces.

Peter_Galvin1 · November 27, 2020, 5:51pm

Tried the following experiments. All had the same skipping problem sooner or later:
Turn off wifi, use wired
Disconnect wired, use wifi
Disconnect wired, use hotspot from cell phone

Peter_Galvin1 · December 8, 2020, 4:27pm

Still having these skipping tracks problems frequently. Pretty much every day.
Sometimes after noon using roon for a while (leaving it open over night), but sometimes right after starting it up.
Sometimes it goes away on its own but mostly I restart roon and see if that fixes it.
Happens when the output is set to my SoTM, and to system output.
Usually skips an entire album’s worth of tracks, but sometimes if I try again skips some and then finally starts playing.
I don’t know what file descriptor it’s trying to wait for and failing to do but it’s making roon barely usable for me…

Blockquote
–[ SignalPath ]---------------------------------------------
SignalPath Quality = HighQuality
Elements:
Source Format=Aiff 44100/16/2 BitRate=1411 Quality=Lossless
Raat Device=System Output
Output OutputType=Local_SharedMode_CoreAudio Quality=HighQuality SubType= Model=System Output
'------------------------------------------------------------
12/08 11:24:28 Info: sleep 2000ms after flush
12/08 11:24:28 Info: [System Output] [zoneplayer] Open Result (Playing):Result[Status=Success]
12/08 11:24:28 Info: [System Output] [zoneplayer] Starting playback
12/08 11:24:28 Trace: [System Output] [zoneplayer/raat] StartStream Sooloos.Broker.Transport.RaatZonePlayer+Endpoint: StreamFormat(channels=2, bitspersample=16, samplerate=44100, isdts=False) => StreamFormat(channels=2, bitspersample=16, samplerate=44100, isdts=False) streamid=1121378138
12/08 11:24:28 Info: [zone System Output] OnPlayFeedback Playing
12/08 11:24:28 Trace: [System Output] [HighQuality, 16/44 AIFF => 16/44] [100% buf] [PLAYING @ 0:00] 720 In The Books - Ella Fitzgerald
12/08 11:24:28 Trace: [prebuffer] ready 149940/441000 (34%) @ 0/174 sec
12/08 11:24:29 Trace: [System Output] [zoneplayer/raat] synced to endpoint System Output clock: realtime=29622781981 rtt=0us offset=-2338393218us delta=-2338393218us
12/08 11:24:29 Trace: [System Output] [raatclient] SENT [37]{“request”:“stream”,“stream_id”:1121378138,“first_seq”:-1,“nak_port”:-1,“buffer_size”:10,“ready_threshold”:0.2}
12/08 11:24:29 Trace: [System Output] [raatclient] GOT [37] {“status”:“Buffering”}
12/08 11:24:29 Trace: [System Output] [zoneplayer/raat] Endpoint System Output State Changed: Prepared => Buffering
12/08 11:24:29 Trace: [System Output] [zoneplayer/raat] [zoneplayer/raat] selected System Output as clock master
12/08 11:24:29 Debug: [raat/tcpaudiosource] connecting to 127.0.0.1:61924
12/08 11:24:29 Warn: [zoneplayer/raat] Error during streaming: System.NotSupportedException: Could not register to wait for file descriptor 2562
at (wrapper managed-to-native) System.IOSelector.Add(intptr,System.IOSelectorJob)
at System.Net.Sockets.Socket.BeginSConnect (System.Net.Sockets.SocketAsyncResult sockares) [0x001da] in :0
at System.Net.Sockets.Socket.BeginConnect (System.Net.EndPoint remoteEP, System.AsyncCallback callback, System.Object state) [0x0002b] in :0
at Sooloos.Broker.Transport.RaatTcpAudioSource._Spin () [0x000a0] in <3deaa7333e174f27bbd18500ac7eed87>:0
at Sooloos.Broker.Transport.RaatTcpAudioSource.SendFrames (System.Net.IPEndPoint ep, System.Int32 stream_id, System.Int64 streamsample, System.Double buffersize, Sooloos.Audio.StreamFormat format, System.Double gain, System.Double peak, System.Byte[] buf, System.Int32 nsamples) [0x00613] in <3deaa7333e174f27bbd18500ac7eed87>:0
at Sooloos.Broker.Transport.RaatZonePlayer+<>c__DisplayClass31_0.<_StartStream4>b__1 () [0x00586] in <3deaa7333e174f27bbd18500ac7eed87>:0
12/08 11:24:29 Warn: [zone System Output] Track Stopped Due to Error
12/08 11:24:29 Info: [zone System Output] OnPlayFeedback StoppedEndOfMediaUnnatural
12/08 11:24:29 Debug: [zone System Output] _Advance
12/08 11:24:29 Trace: [System Output] [HighQuality, 16/44 AIFF => 16/44] [100% buf] [STOPPED @ 0:00]
12/08 11:24:29 Info: MPNowPlayingInfoCenter: Connect
12/08 11:24:29 Debug: GMS: saving nav stack
12/08 11:24:29 Info: MPNowPlayingInfoCenter: Disconnect
12/08 11:24:29 Debug: GMS: done saving nav stack

Peter_Galvin1 · December 18, 2020, 8:50pm

Well, for the past couple of days, Roon seems to be working flawlessly for me. This after upgrading to 1.7 (build 710). Perhaps some bug was fixed, or my network is behaving better.
Keeping fingers crossed!

Peter_Galvin1 · December 28, 2020, 3:49pm

Alas spoke too soon. Back to frequent track-skipping problems.

James_Ockers · January 2, 2021, 4:14am

Hi @Peter_Galvin1,

Could you please try switching everything to wired ethernet and reboot your ethernet switch? I had an ethernet switch with buffer issues which caused loss of bandwidth or packet loss which would cause Roon to skip tracks.

I’m not an ethernet switch expert so my guess of what was causing the problem is my cheap ethernet switch had a slow memory leak in which packet buffer memory would get allocated but not de-allocated and would eventually fill up. The lack of buffers would cause the switch to have to drop packets if it was momentarily busy, instead of buffering them until it could process the packets.

In that case, rebooting the switch would clear all the buffers and all ports would work fine for a while. I solved the root cause by buying a much more expensive managed ethernet switch, and I’ve had no further track skipping issues.

Additionally, I’ve had to make sure all my Roon devices with wifi connections have 5GHz connectivity and <5ms ping times for reliable streaming, for example I have a Raspberry Pi device with 5GHz wifi “Bit Rate:434 Mb/s” which works fine. Any 2.4GHz with ~50Mbps wifi connections are too slow.

Buffer related packet loss might not be your problem, but I wanted to suggest it as something you could try.

Cheers,
Jim

Peter_Galvin1 · January 2, 2021, 3:21pm

hi James, interesting theory!
Thanks for the ideas, trying them out.
I thought my switch was solid (Cisco SR2024) but see some reviews complaining of problems with it.
So ordering up a new switch as well…

Peter_Galvin1 · January 3, 2021, 10:55pm

Replaced the previous switch with the tp-link 16-port gigabit easy smart switch
Same result.
I don’t think it’s a network problem.
Got the new maccartney III album, ripped it via itunes
Roon spotted it and added it to my library
Output device is the SOtM 2000 Neo
Pressed “play on the album”
I took a screen video capture but the forums don’t allow its upload.
Here is a log file entry
Errors look like operating system network socket errors, not timeouts our packet drops:

01/03 17:48:21 Warn: [zoneplayer/raat] Error during streaming: System.NotSupportedException: Could not register to wait for file descriptor 3113
at (wrapper managed-to-native) System.IOSelector.Add(intptr,System.IOSelectorJob)
at System.Net.Sockets.Socket.BeginSConnect (System.Net.Sockets.SocketAsyncResult sockares) [0x001da] in :0
at System.Net.Sockets.Socket.BeginConnect (System.Net.EndPoint remoteEP, System.AsyncCallback callback, System.Object state) [0x0002b] in :0
at Sooloos.Broker.Transport.RaatTcpAudioSource._Spin () [0x000a0] in :0
at Sooloos.Broker.Transport.RaatTcpAudioSource.SendFrames (System.Net.IPEndPoint ep, System.Int32 stream_id, System.Int64 streamsample, System.Double buffersize, Sooloos.Audio.StreamFormat format, System.Double gain, System.Double peak, System.Byte[] buf, System.Int32 nsamples) [0x00613] in :0
at Sooloos.Broker.Transport.RaatZonePlayer+<>c__DisplayClass31_0.<_StartStream4>b__1 () [0x00586] in :0

Restarted roon, pressed play on the album, and it’s playing fine (for now). Will have this same problem again, tonight if not tomorrow…