Hi @support,
I’ve been having this problem on and off at least since I built a new Roon server back in August '18, possibly earlier on my older setup. I’ve been working through diagnosing it on and off and finally have enough info to post a support request. I think it is either something to do with my local network, possibly my ISP, or regional Tidal cache. I’ve read through a few posts in here where other people have had a similar problem, however the resolutions in those cases have not worked for me so far. I’m really just posting here to get some feedback on my diagnosis so far, and see if you have any other suggestions.
The problem
Part way through playback of a Tidal track, sometimes 65%, sometimes 75%, often 85% or 95%, playback suddenly stops, and then a few seconds later the next track begins playback.
This only occurs when playing back an album from Tidal. Playback of local media is always fine. More often than not, it is a track part way through the album, sometimes a much later track, and less often it happens for the first track.
The problem only seems to occur for albums I’ve never listened to before, or possibly (ie I’m not yet 100% sure about this scenario) that I haven’t listened to in a long time.
If I immediately tell Roon to replay the track that had the problem, so far it has always played back fine ie it completes 100% of playback, so the problem is not track or album specific, rather it seems to be a random streaming or connection problem.
I have a Tidal HiFi account, and the problem occurs with playback of both redbook FLAC or MQA files from Tidal.
Some days I might play 2 or 3 new albums from Tidal before the problem occurs, other days, at least one track on every new album from Tidal has an issue. Most days, I’m listening to local content or Tidal album’s I’ve been playing regularly, ie its only every week or two I go on a bit of discovery for new music and will see this issue.
The pattern of errors and warnings in the Core log file is 100% consistent every time I’ve looked, which is useful at least.
Detailed log examples follow at the end of this post, however, here’s the summary:
There is a pair of ‘Connection reset by peer’ messages from the [streamingmediafile] logger in the Core’s log whilst caching the Tidal file. Then sometime later, ie during playback of the file, playback stops and there is another error in the Core’s log from the [zoneplayer] logger that ‘Track ended unexpectedly’. Then there are log entries where it tidies that up and skips to the next track.
My setup
ADSL line enters house -> xDSL Master filter -> DrayTek Vigor 130 -> pfSense router -> Netgear GS108 switch -> Netgear Orbi Router (in AP mode) -> Netgear Orbi Satelite -> Netgear GS108 switch -> Roon Core server (with local media on SSD) -> bridged network on 2nd NIC -> KEF LS50 Wireless.
I put the xDSL master filter in 12 months ago and since then ADSL line has consistenly had a rock solid connection at 16Mb/s (as measured by SpeedTest) with no drops, and ping times to the ISP’s gateway are typically 20-25ms. On a side note, I’ve requested an upgrade to VDSL, which should go through next week sometime (scheduled for 22nd).
The Roon Core is an Intel NUC 7i7 with 8GB and 2 local SSD’s, one for OS + Roon Server + DB, and one for media. It is running Arch Linux which is updated on average every 2 weeks. I used your supplied script to install RoonServer.
All connectivity in the house is 1Gb/s ethernet over Cat6 or 6a, except the ADSL line and the Orbi Wifi backhaul.
There is triple NAT’ing because my ISP (flip.co.nz) does CG-NAT, the Vigor 130 is NAT’ing the PPoA connection and then pfSense is also NAT’ing. Ideally only the pfSense router would NAT, however a) my current ISP doesn’t offer a service without GC-NAT and b) despite trying, I have not yet been successful at setting up a PPoE/PPoA bridge mode between the Vigor 130 and pfSense. When the VDSL upgrade happens, the PPoA will change to PPoE, so I’ll be able to set that to PPoE bridged and thus drop the NAT layer on the Vigor at least.
Control points are an old Dell Laptop, iPad and iPhone on the Orbi Wifi network. There are plenty of other devices on my network, however none are involved in streaming or playback.
Over the dozens and dozens of times this has happened over the months, no other devices on the network or indeed any connectivity to the Core has been affected by any network drops or internet connectivity issues at the same time. As far as I’m aware the other devices off the Orbi satelite or the 2nd GS108 are all having no problems. That said, the AppleTV does have the very occasional (ie relatively rare compared to the Roon issue) buffering issue on Netflix or Apple Movies, however I’ve never been using it at the same time as Roon, and a few buffering issues streaming HD movies or Netflix on a 16Mb/s ADSL line is to be expected.
Everything in my setup is regularly checked and updated to latest firmware, patches etc (Vigor, pfSense, Arch, Roon, Kef).
Working theory
Something is dropping or actively closing the connection between my Core and the local Tidal cache server. I’m basing this on the relatively specific ‘Connection reset by peer’ message in the logs. From my knowledge of such things after 20+ years working in IT, I know this specific error is typically because a network device, ie a proxy, firewall, router or NAT’ing layer, etc, or the server itself has closed the connection. My current suspects are a) one of the 3 NAT’ing layers, b) the Tidal cache server.
As I say this is my current working theory, happy to hear other suggestions.
Other diagnosis notes thus far
I’ve swapped out network cables between both the Core and switch, the switch and Orbi Satelite, and the core and the Kef endpoint. No other devices running off the Orbi’s or off the switches are experiencing any drop outs (that I’m aware of).
I noted a number of people have had issues with Netgear Orbi’s in their setup, however in every case (from what I’ve read so far at least) these have been in Router mode and have been solved either by changing the IGMP proxy setup or MTU. In my case my Orbi’s are in AP mode so these are not applicable.
That said, I have also tried bypassing the Orbi’s and 2nd GS108 by running a spare 30m Cat 6a cable from the 1st GS108 directly to the Core, ie ADSL line enters house -> xDSL Master filter -> DrayTek Vigor 130 -> pfSense router -> Netgear GS108 switch -> Roon Core server (with local media on SSD) -> bridged network on 2nd NIC -> KEF LS50 Wireless. However the problem persists with this config as well.
It occurs to me as I write this I haven’t tried temporarily connecting the Kef endpoint to the GS108 and disabling the bridge network on the Core, I’ll add that to my list of things to try this week.
I initially wondered, based on some other similar posts in these forums, if it was a DNS issue, so I have experimented back and forth a number of times between my ISP’s DNS vs CloudFlare’s DNS, on a number of occasions, including reboots of the router, Orbi’s, and the Core server to flush any old state, however there is no change in behaviour.
I’ve also checked the pfSense firewall logs and there are no firewall events at the times of the playback issues or the ‘Connection reset’ errors in the Core’s log file. There are occasional entries for out of state Fin Ack or Reset Ack packets being dropped by the firewall for connections between the Core and the Tidal server, however these appear to be consistent through out playback, regardless of whether the problem occurs or playback is uninterrupted.
I’m running NetData on the Core and I see a small spike in RST’s on the network interface at the same time as the ‘Connection reset by peer’ message. Otherwise the Core server is not showing anything different from normal playback where there is no problem (or at least nothing I’ve spotted yet). NetData on the Core also shows regular UDP errors, however these are present 24/7 ie even during no playback. Note they go away if RoonServer is stopped, and come back when it is started again. I was surprised by this, as I thought Roon had stopped using UDP many releases ago?
On the odd occasion I’ve been watching the Traffic Graphs on pfSense, during Tidal playback I see the inbound bandwidth usage jump to around 16Mb/s and sit there until either the file has been cached, or until the ‘Connection reset by peer’ message appears, ie it doesn’t appear to be due to a slow internet connection.
I have checked the logs on the Vigor 130 and it’s firewall log appears to empty, which seems strange. I haven’t figured out if/where it logs NATing events yet. I’ll have a look in to that this week sometime as well.
I’m based in Wellington, New Zealand. The ping times to my local Tidal cache server from the Core server are often around 70ms, and the trace routes lead me to think it is probably based in either in Auckland, New Zealand, or a datacentre in Australia, (do Tidal use AWS?). This is fairly typical for content providers in my part of the world.
Questions
Is it possible the Tidal server is closing the connection despite not having served the entire stream? If so is there a way to determine that other than by process of elimination in all the other layers?
Why doesn’t the streamingmediafile component of the Core retry a new connection at least once before abandoning the caching of the file?
Logs
Here’s an example of the messages when the caching of the Tidal stream errors out:
01/13 08:59:51 Trace: [tidal/http] GET https://api.tidalhifi.com/v1/tracks/89267305/streamurl?countryCode=NZ&sessionId=c72fa599-c963-4af3-a63f-95889d29c58a&soundQuality=LOSSLESS => Success
01/13 08:59:51 Trace: [tidal/http] GET https://api.tidalhifi.com/v1/tracks/89267305?countryCode=NZ&sessionId=c72fa599-c963-4af3-a63f-95889d29c58a& => Success
01/13 08:59:51 Info: [Kef] [zoneplayer] Queueing: http://ab-pr-ak.audio.tidal.com/adae746a4e84adaff631fc32765f9b6a_39.flac
01/13 08:59:51 Trace: [roonapi] [apiclient 192.168.1.9:48344] CONTINUE Changed {"message":"Core paired","is_error":false}
01/13 08:59:52 Info: [stats] 2716mb Virtual, 611mb Physical, 228mb Managed, 0 Handles, 66 Threads
01/13 08:59:53 Info: [Kef] [zoneplayer] Open result (Queueing): Result[Status=Success]
01/13 08:59:53 Trace: [streamingmediafile] immediate read of http://ab-pr-ak.audio.tidal.com/adae746a4e84adaff631fc32765f9b6a_39.flac at 524288 length=40970428
01/13 08:59:54 Warn: [streamingmediafile] in immediate read: System.Net.WebException: Error getting response stream (ReadDone1): ReceiveFailure ---> System.IO.IOException: Unable to read data from the transport connection: Connection res
et by peer. ---> System.Net.Sockets.SocketException: Connection reset by peer
at System.Net.Sockets.Socket.EndReceive (System.IAsyncResult asyncResult) [0x00012] in <126998f2e5ae42fe95554117eb649feb>:0
at System.Net.Sockets.NetworkStream.EndRead (System.IAsyncResult asyncResult) [0x00057] in <126998f2e5ae42fe95554117eb649feb>:0
--- End of inner exception stack trace ---
at System.Net.Sockets.NetworkStream.EndRead (System.IAsyncResult asyncResult) [0x0009b] in <126998f2e5ae42fe95554117eb649feb>:0
at System.Net.WebConnection.ReadDone (System.IAsyncResult result) [0x0001b] in <126998f2e5ae42fe95554117eb649feb>:0
--- End of inner exception stack trace ---
at System.Net.HttpWebRequest.EndGetResponse (System.IAsyncResult asyncResult) [0x00058] in <126998f2e5ae42fe95554117eb649feb>:0
at System.Net.HttpWebRequest.GetResponse () [0x0000e] in <126998f2e5ae42fe95554117eb649feb>:0
at Sooloos.Media.StreamingMediaFileImpl._ReadImmediate (System.Int64 file_off, System.Byte[] buf, System.Int32 off, System.Int32 count) [0x00086] in <67cdbfbc98564a67a315f25b32208b8c>:0
01/13 08:59:54 Error: [cachingseekableurimediafile] while reading: System.Net.WebException: Error getting response stream (ReadDone1): ReceiveFailure ---> System.IO.IOException: Unable to read data from the transport connection: Connecti
on reset by peer. ---> System.Net.Sockets.SocketException: Connection reset by peer
at System.Net.Sockets.Socket.EndReceive (System.IAsyncResult asyncResult) [0x00012] in <126998f2e5ae42fe95554117eb649feb>:0
at System.Net.Sockets.NetworkStream.EndRead (System.IAsyncResult asyncResult) [0x00057] in <126998f2e5ae42fe95554117eb649feb>:0
--- End of inner exception stack trace ---
at System.Net.Sockets.NetworkStream.EndRead (System.IAsyncResult asyncResult) [0x0009b] in <126998f2e5ae42fe95554117eb649feb>:0
at System.Net.WebConnection.ReadDone (System.IAsyncResult result) [0x0001b] in <126998f2e5ae42fe95554117eb649feb>:0
--- End of inner exception stack trace ---
at System.Net.HttpWebRequest.EndGetResponse (System.IAsyncResult asyncResult) [0x00058] in <126998f2e5ae42fe95554117eb649feb>:0
at System.Net.HttpWebRequest.GetResponse () [0x0000e] in <126998f2e5ae42fe95554117eb649feb>:0
at Sooloos.Media.StreamingMediaFileImpl._ReadImmediate (System.Int64 file_off, System.Byte[] buf, System.Int32 off, System.Int32 count) [0x0013d] in <67cdbfbc98564a67a315f25b32208b8c>:0
at Sooloos.Media.StreamingMediaFileImpl._Read (System.Int64 file_off, System.Byte[] buf, System.Int32 off, System.Int32 count) [0x00089] in <67cdbfbc98564a67a315f25b32208b8c>:0
at Sooloos.Media.StreamingMediaFileImpl.Read (System.Int64 file_off, System.Byte[] buf, System.Int32 off, System.Int32 count) [0x0005e] in <67cdbfbc98564a67a315f25b32208b8c>:0
at Sooloos.Media.StreamingMediaFile.Read (System.Int64 file_off, System.Byte[] buf, System.Int32 off, System.Int32 count) [0x00000] in <67cdbfbc98564a67a315f25b32208b8c>:0
at Sooloos.Media.CachingSeekableUriMediaFile.ReadCallback (System.IntPtr userdata, System.IntPtr buf, System.IntPtr count, System.IntPtr& out_bytesread) [0x00055] in <67cdbfbc98564a67a315f25b32208b8c>:0
01/13 08:59:54 Warn: [prebuffer] in buffer threadSystem.Exception: Read failure: IoFailure
at Sooloos.Audio.MediaDecoderAudioSignal.Read (System.Byte[] buffer, System.Int32 offset, System.Int32 frames) [0x00232] in <5535008d6900425285ae140d60437aa6>:0
at Sooloos.Broker.Transport.FormatDetectAudioSignal.Read (System.Byte[] buffer, System.Int32 offset, System.Int32 frames) [0x000ca] in <bbda6a553eb048f1b5c5c7aa2e58a1a5>:0
at Sooloos.Audio.SeekableBufferedAudioSignal._Buffer (System.Int32 buffer_seq) [0x0003e] in <5535008d6900425285ae140d60437aa6>:0
at Sooloos.Audio.SeekableBufferedAudioSignal+<>c__DisplayClass30_0.<_StartBuffering>b__0 () [0x00000] in <5535008d6900425285ae140d60437aa6>:0
01/13 08:59:54 Trace: [Kef] [Lossless 37.2x, 24/44 MQA TIDAL FLAC => 24/88] [100% buf] [PLAYING @ 0:05/4:39] Bloodlines - The Adults / Estére / Jessb
01/13 08:59:59 Trace: [Kef] [Lossless 37.3x, 24/44 MQA TIDAL FLAC => 24/88] [100% buf] [PLAYING @ 0:10/4:39] Bloodlines - The Adults / Estére / Jessb
01/13 09:00:05 Trace: [Kef] [Lossless 37.3x, 24/44 MQA TIDAL FLAC => 24/88] [100% buf] [PLAYING @ 0:16/4:39] Bloodlines - The Adults / Estére / Jessb
01/13 09:00:07 Info: [stats] 2751mb Virtual, 643mb Physical, 301mb Managed, 0 Handles, 66 Threads
01/13 09:00:10 Trace: [Kef] [Lossless 36.9x, 24/44 MQA TIDAL FLAC => 24/88] [100% buf] [PLAYING @ 0:21/4:39] Bloodlines - The Adults / Estére / Jessb
01/13 09:00:16 Trace: [Kef] [Lossless 37.0x, 24/44 MQA TIDAL FLAC => 24/88] [100% buf] [PLAYING @ 0:26/4:39] Bloodlines - The Adults / Estére / Jessb
01/13 09:00:16 Trace: [streamingmediafile] finished caching http://ab-pr-ak.audio.tidal.com/adae746a4e84adaff631fc32765f9b6a_39.flac
01/13 09:00:21 Trace: [Kef] [Lossless 37.0x, 24/44 MQA TIDAL FLAC => 24/88] [100% buf] [PLAYING @ 0:32/4:39] Bloodlines - The Adults / Estére / Jessb
01/13 09:00:22 Info: [stats] 2708mb Virtual, 600mb Physical, 256mb Managed, 0 Handles, 66 Threads
01/13 09:00:26 Trace: [Kef] [Lossless 37.0x, 24/44 MQA TIDAL FLAC => 24/88] [100% buf] [PLAYING @ 0:37/4:39] Bloodlines - The Adults / Estére / Jessb
And here’s the same track then erroring out at the sudden end of playback about 14 seconds later:
01/13 09:04:01 Trace: [Kef] [Lossless 36.6x, 24/44 MQA TIDAL FLAC => 24/88] [70% buf] [PLAYING @ 4:11/4:39] Bloodlines - The Adults / Estére / Jessb
01/13 09:04:06 Trace: [Kef] [Lossless 36.7x, 24/44 MQA TIDAL FLAC => 24/88] [18% buf] [PLAYING @ 4:16/4:39] Bloodlines - The Adults / Estére / Jessb
01/13 09:04:07 Info: [Kef] [zoneplayer] Track ended unexpectedly: Sooloos.Audio.BufferedReadException: error during buffered read ---> System.Exception: Read failure: IoFailure
at Sooloos.Audio.MediaDecoderAudioSignal.Read (System.Byte[] buffer, System.Int32 offset, System.Int32 frames) [0x00232] in <5535008d6900425285ae140d60437aa6>:0
at Sooloos.Broker.Transport.FormatDetectAudioSignal.Read (System.Byte[] buffer, System.Int32 offset, System.Int32 frames) [0x000ca] in <bbda6a553eb048f1b5c5c7aa2e58a1a5>:0
at Sooloos.Audio.SeekableBufferedAudioSignal._Buffer (System.Int32 buffer_seq) [0x0003e] in <5535008d6900425285ae140d60437aa6>:0
at Sooloos.Audio.SeekableBufferedAudioSignal+<>c__DisplayClass30_0.<_StartBuffering>b__0 () [0x00000] in <5535008d6900425285ae140d60437aa6>:0
--- End of inner exception stack trace ---
at Sooloos.Audio.SeekableBufferedAudioSignal.Read (System.Byte[] buffer, System.Int32 offset, System.Int32 frames) [0x0003b] in <5535008d6900425285ae140d60437aa6>:0
at Sooloos.Broker.Transport.ZonePlayerTrack._ReadBacking (System.Byte[] buffer, System.Int32 offset, System.Int32 frames) [0x00041] in <bbda6a553eb048f1b5c5c7aa2e58a1a5>:0
at Sooloos.Broker.Transport.ZonePlayerTrack+_Stream.ReadImp (Sooloos.Audio.AudioBuffer buf, System.Int32 nsamples) [0x00041] in <bbda6a553eb048f1b5c5c7aa2e58a1a5>:0
at Sooloos.Audio.AudioStream.Read (Sooloos.Audio.AudioBuffer buf, System.Int32 nsamples) [0x0005e] in <ded7aa6d297649a693b703f945f65998>:0
at Sooloos.Broker.Transport.AudioFileStreamWrapper.ReadImp (Sooloos.Audio.AudioBuffer buf, System.Int32 nsamples) [0x00047] in <bbda6a553eb048f1b5c5c7aa2e58a1a5>:0
at Sooloos.Audio.AudioStream.Read (Sooloos.Audio.AudioBuffer buf, System.Int32 nsamples) [0x0005e] in <ded7aa6d297649a693b703f945f65998>:0
at Sooloos.Broker.Transport.ZonePlayerBase.ReadImp (Sooloos.Audio.AudioBuffer buf, System.Int32 nsamples) [0x00115] in <bbda6a553eb048f1b5c5c7aa2e58a1a5>:0
01/13 09:04:07 Info: [zone Kef] OnPlayFeedback StoppedEndOfMediaNatural
01/13 09:04:07 Debug: [zone Kef] _Advance
01/13 09:04:07 Info: [library] recorded play for profile 37622537-cfea-48bf-83d0-ef3c4d802e57: mediaid=50:1:bef74ea5-7733-4e15-af46-0f3af222f8f6 metadataid= contentid=168:0:89267304 libraryid=50:1:bef74ea5-7733-4e15-af46-0f3af222f8f6
01/13 09:04:07 Trace: [library] finished with 20 dirty tracks 2 dirty albums 9 dirty performers 20 dirty works 20 dirty performances 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 52 changed objects
01/13 09:04:07 Debug: [library/index] updating search indices: 10 ops 0 adds, 0 removes
01/13 09:04:07 Trace: [Kef] [Lossless 36.7x, 24/44 MQA TIDAL FLAC => 24/88] [6% buf] [LOADING @ 0:00] That Gold - The Adults / Raiza Biza / Aaradhna
01/13 09:04:07 Debug: [query] Sooloos.Broker.Transport.TransportItem: 4148 dirty items. rebuilding query instead of re-sorting item-by-item (internaltype=TransportItem)
01/13 09:04:07 Debug: [query] Sooloos.Broker.Transport.TransportItem: 4148 dirty items. rebuilding query instead of re-sorting item-by-item (internaltype=TransportItem)
01/13 09:04:07 Trace: [Kef] [zoneplayer/kef] reached end of stream, closing connection
01/13 09:04:07 Trace: [Kef] [zoneplayer/kef] transaction canceled, isplaying: True, did stream end: True, tx path: /54bc6249b68d4d098c4663b80eed8129/Roon614d9ea2054d499491dc62e200af8849.flac, stream path: /54bc6249b68d4d098c4663b80eed8129/Roon614d9ea2054d499491dc62e200af8849.flac, method: Get
01/13 09:04:08 Info: [stats] 2733mb Virtual, 626mb Physical, 291mb Managed, 0 Handles, 65 Threads
I’ll be grateful for any help, feedback, or tips!
Cheers,
Dunc