Radios streaming still gives trouble

Tor_Gunnar_Berland · August 1, 2018, 10:24am

I start radio stream; it seems to read some old buffered information for 10 seconds; then stream fails. I reclick start radio channel; it fails again; then I starts radio stream once more at it works. This seems to be a common problem and only happen with radio-streams.

08/01 12:19:19 Info: 
--[ SignalPath ]---------------------------------------------
SignalPath Quality = LowQuality
Elements:
    Source Format=Mp3 48000/24/2  Quality=LowQuality
    Raat Device=AudioByte ASIO
    Output OutputType=Local_Asio Quality=Lossless SubType= Model=AudioByte ASIO
------------------------------------------------------------
08/01 12:19:20 Trace: [AudioByte ASIO] [zoneplayer/raat] synced to endpoint AudioByte ASIO clock: realtime=5730217000000 rtt=0us offset=-73184446000us delta=-73184446000us
08/01 12:19:20 Trace: [AudioByte ASIO] [raatclient] SENT [229]{"request":"stream","stream_id":1090342009,"first_seq":-1,"nak_port":-1,"buffer_size":10,"ready_threshold":0.2}
08/01 12:19:20 Trace: [AudioByte ASIO] [raatclient] GOT [229] {"status":"Buffering"}
08/01 12:19:20 Trace: [AudioByte ASIO] [zoneplayer/raat] Endpoint AudioByte ASIO State Changed: Prepared => Buffering
08/01 12:19:20 Trace: [AudioByte ASIO] [zoneplayer/raat] [zoneplayer/raat] selected AudioByte ASIO as clock master
08/01 12:19:20 Debug: [raat/tcpaudiosource] connecting to 127.0.0.1:63171
08/01 12:19:20 Debug: [raat/tcpaudiosource] connected
08/01 12:19:20 Trace: [AudioByte ASIO] [raatclient] GOT [229] {"status":"Ready"}
08/01 12:19:20 Trace: [AudioByte ASIO] [zoneplayer/raat] Endpoint AudioByte ASIO State Changed: Buffering => Ready
08/01 12:19:20 Trace: [AudioByte ASIO] [zoneplayer/raat] wait for ready in 0ms
08/01 12:19:20 Trace: [AudioByte ASIO] [zoneplayer/raat] Doing 'ASAP' Start since we are just playing to one device
08/01 12:19:20 Trace: [AudioByte ASIO] [raatclient] SENT [230]{"request":"start","min_offset":50000000,"stream_sample":0}
08/01 12:19:20 Trace: [AudioByte ASIO] [zoneplayer/raat] Endpoint AudioByte ASIO State Changed: Ready => Playing
08/01 12:19:20 Trace: [AudioByte ASIO] [raatclient] GOT [229] {"status":"Playing"}
08/01 12:19:20 Trace: [AudioByte ASIO] [raatclient] GOT [230] {"time":5730276666666,"status":"Success"}
08/01 12:19:24 Warn: [music/slurp] Failed to push internet radio now playing: 504
<html><body><h1>504 Gateway Time-out</h1>
The server didn't respond in time.
</body></html>

08/01 12:19:25 Trace: [AudioByte ASIO] [LowQuality, 24/48 MP3 => 24/48] [100% buf] [PLAYING @ 0:05] Madonna - La Isla Bonita
08/01 12:19:26 Info: [stats] 1909mb Virtual, 670mb Physical, 385mb Managed, 1756 Handles, 86 Threads
08/01 12:19:30 Warn: [music/slurp] Failed to push internet radio now playing: 504
<html><body><h1>504 Gateway Time-out</h1>
The server didn't respond in time.
</body></html>

08/01 12:19:31 Trace: [AudioByte ASIO] [LowQuality, 24/48 MP3 => 24/48] [100% buf] [PLAYING @ 0:11] Madonna - La Isla Bonita
08/01 12:19:32 Trace: [AudioByte ASIO] [raatclient] GOT [229] {"samples":13729,"status":"Dropout"}
08/01 12:19:32 Trace: [AudioByte ASIO] [raatclient] GOT [229] {"samples":23552,"status":"Dropout"}
08/01 12:19:33 Trace: [AudioByte ASIO] [raatclient] GOT [229] {"samples":24576,"status":"Dropout"}
08/01 12:19:33 Trace: [AudioByte ASIO] [raatclient] GOT [229] {"samples":23552,"status":"Dropout"}
08/01 12:19:34 Trace: [AudioByte ASIO] [raatclient] GOT [229] {"samples":24576,"status":"Dropout"}
08/01 12:19:34 Trace: [AudioByte ASIO] [raatclient] GOT [229] {"samples":23552,"status":"Dropout"}
08/01 12:19:35 Trace: [AudioByte ASIO] [raatclient] GOT [229] {"samples":23552,"status":"Dropout"}
08/01 12:19:35 Warn: [AudioByte ASIO] [zoneplayer/raat] Too many dropouts (>3s dropped out in the last 30s). Killing stream
08/01 12:19:35 Trace: [AudioByte ASIO] [zoneplayer/raat] too many dropouts. stopping stream
08/01 12:19:35 Info: [AudioByte ASIO] [zoneplayer] advance didn't change the track. returning short read
08/01 12:19:35 Trace: [AudioByte ASIO] [zoneplayer/raat] Endpoint AudioByte ASIO State Changed: Playing => Prepared
08/01 12:19:35 Trace: [AudioByte ASIO] [raatclient] SENT [231]{"request":"end_stream"}
08/01 12:19:35 Debug: [raat/tcpaudiosource] disconnecting
08/01 12:19:35 Info: [audio/env] [zoneplayer -> stream] All streams were disposed
08/01 12:19:35 Info: [audio/env] [zoneplayer -> stream -> endpoint] All streams were disposed
08/01 12:19:35 Warn: [streammediafile] error reading stream: Unable to read data from the transport connection: A blocking operation was interrupted by a call to WSACancelBlockingCall.
08/01 12:19:35 Warn: Track Stopped Due to Slow Media
08/01 12:19:35 Info: [audio/env] [zoneplayer] All streams were disposed
08/01 12:19:35 Trace: Attempting to play channel URL: icy://edge-bauerno-02-gos1.sharp-stream.com/radionorge_no_hq?
08/01 12:19:35 Info: [zone AudioByte ASIO] OnPlayFeedback StoppedEndOfMediaUnnatural
08/01 12:19:35 Info: [zone AudioByte ASIO] OnPlayFeedback Stopped
08/01 12:19:35 Trace: [AudioByte ASIO] [LowQuality, 24/48 MP3 => 24/48] [100% buf] [STOPPED @ 0:00] Madonna - La Isla Bonita
08/01 12:19:35 Info: sleep 0ms after flush
08/01 12:19:35 Trace: [AudioByte ASIO] [raatclient] GOT [229] {"status":"Ended"}
08/01 12:19:35 Warn: [zoneplayer/raat] Error during streaming: System.NullReferenceException: Object reference not set to an instance of an object.
   at Sooloos.Broker.Transport.RaatZonePlayer.<>c__DisplayClass31_0.<_StartStream4>b__1()
08/01 12:19:35 Trace: [AudioByte ASIO] [raatclient] GOT [231] {"status":"Success"}
08/01 12:19:35 Info: [AudioByte ASIO] [zoneplayer] Playing: channel://icy%3a%2f%2fedge-bauerno-02-gos1.sharp-stream.com%2fradionorge_no_hq%3f
08/01 12:19:36 Trace: Got ICY Stream Title [Madonna - La Isla Bonita]
08/01 12:19:36 Info: [AudioByte ASIO] [zoneplayer]     Open Result (Playing):Result[Status=Success]
08/01 12:19:36 Info: [AudioByte ASIO] [zoneplayer] Aborting play because track changed
08/01 12:19:36 Warn: [streammediafile] error reading stream: Cannot access a closed Stream.
08/01 12:19:36 Info: [audio/env] [zoneplayer] All streams were disposed
08/01 12:19:39 Trace: [zone AudioByte ASIO] Playing Channel
08/01 12:19:39 Trace: [zone AudioByte ASIO] Selecting Source state=Stopped
08/01 12:19:39 Trace: [internetradio] Channel Player: Fetching URL [http://tx-bauerno.sharp-stream.com/http_live.php?i=radionorge_no_hq]
08/01 12:19:39 Trace: [AudioByte ASIO] [LowQuality, 24/48 MP3 => 24/48] [100% buf] [LOADING @ 0:00] Radio Norge
08/01 12:19:39 Trace: [musicpowerstate] music is playing, preventing idle sleep
08/01 12:19:39 Trace: [internetradio] Channel Player: Fetching URL [http://edge-bauerno-03-gos2.sharp-stream.com/radionorge_no_hq?]
08/01 12:19:40 Trace: Attempting to play channel URL: icy://edge-bauerno-03-gos2.sharp-stream.com/radionorge_no_hq?
08/01 12:19:40 Info: [AudioByte ASIO] [zoneplayer] Playing: channel://icy%3a%2f%2fedge-bauerno-03-gos2.sharp-stream.com%2fradionorge_no_hq%3f
08/01 12:19:41 Info: [stats] 1897mb Virtual, 670mb Physical, 398mb Managed, 1750 Handles, 82 Threads
08/01 12:19:41 Trace: Got ICY Stream Title [Queen - A Kind Of Magic]
08/01 12:19:41 Info: [AudioByte ASIO] [zoneplayer]     Open Result (Playing):Result[Status=Success]
08/01 12:19:41 Info: [AudioByte ASIO] [zoneplayer] Starting playback
08/01 12:19:41 Trace: [AudioByte ASIO] [zoneplayer/raat] StartStream Sooloos.Broker.Transport.RaatZonePlayer+Endpoint: StreamFormat(channels=2, bitspersample=24, samplerate=48000, isdts=False) => StreamFormat(channels=2, bitspersample=24, samplerate=48000, isdts=False) streamid=1090342010
08/01 12:19:41 Info: [zone AudioByte ASIO] OnPlayFeedback Playing
08/01 12:19:41 Trace: [AudioByte ASIO] [LowQuality, 24/48 MP3 => 24/48] [100% buf] [PLAYING @ 0:00] Radio Norge
08/01 12:19:41 Trace: [AudioByte ASIO] [zoneplayer/raat] synced to endpoint AudioByte ASIO clock: realtime=5752077334333 rtt=0us offset=-73184445665us delta=-73184445665us
08/01 12:19:41 Trace: [AudioByte ASIO] [raatclient] SENT [232]{"request":"stream","stream_id":1090342010,"first_seq":-1,"nak_port":-1,"buffer_size":10,"ready_threshold":0.2}
08/01 12:19:41 Trace: [AudioByte ASIO] [raatclient] GOT [232] {"status":"Buffering"}
08/01 12:19:41 Trace: [AudioByte ASIO] [zoneplayer/raat] Endpoint AudioByte ASIO State Changed: Prepared => Buffering
08/01 12:19:41 Trace: [AudioByte ASIO] [zoneplayer/raat] [zoneplayer/raat] selected AudioByte ASIO as clock master
08/01 12:19:41 Debug: [raat/tcpaudiosource] connecting to 127.0.0.1:63171
08/01 12:19:41 Debug: [raat/tcpaudiosource] connected
08/01 12:19:41 Trace: [AudioByte ASIO] [raatclient] GOT [232] {"status":"Ready"}
08/01 12:19:41 Trace: [AudioByte ASIO] [zoneplayer/raat] Endpoint AudioByte ASIO State Changed: Buffering => Ready
08/01 12:19:42 Trace: [AudioByte ASIO] [zoneplayer/raat] wait for ready in 0ms
08/01 12:19:42 Trace: [AudioByte ASIO] [zoneplayer/raat] Doing 'ASAP' Start since we are just playing to one device
08/01 12:19:42 Trace: [AudioByte ASIO] [raatclient] SENT [233]{"request":"start","min_offset":50000000,"stream_sample":0}
08/01 12:19:42 Trace: [AudioByte ASIO] [zoneplayer/raat] Endpoint AudioByte ASIO State Changed: Ready => Playing
08/01 12:19:42 Trace: [AudioByte ASIO] [raatclient] GOT [232] {"status":"Playing"}
08/01 12:19:42 Trace: [AudioByte ASIO] [raatclient] GOT [233] {"time":5752480666666,"status":"Success"}
08/01 12:19:42 Info: 
--[ SignalPath ]---------------------------------------------
SignalPath Quality = LowQuality
Elements:
    Source Format=Mp3 48000/24/2  Quality=LowQuality
    Raat Device=AudioByte ASIO
    Output OutputType=Local_Asio Quality=Lossless SubType= Model=AudioByte ASIO
------------------------------------------------------------
08/01 12:19:47 Trace: [AudioByte ASIO] [LowQuality 29,2x, 24/48 MP3 => 24/48] [100% buf] [PLAYING @ 0:04] Queen - A Kind Of Magic
08/01 12:19:52 Trace: [AudioByte ASIO] [LowQuality 43,9x, 24/48 MP3 => 24/48] [100% buf] [PLAYING @ 0:09] Queen - A Kind Of Magic
08/01 12:19:56 Info: [stats] 1933mb Virtual, 670mb Physical, 313mb Managed, 1687 Handles, 92 Threads
08/01 12:19:57 Trace: [AudioByte ASIO] [LowQuality 55,3x, 24/48 MP3 => 24/48] [100% buf] [PLAYING @ 0:15] Queen - A Kind Of Magic
08/01 12:20:02 Trace: [AudioByte ASIO] [LowQuality 72,2x, 24/48 MP3 => 24/48] [100% buf] [PLAYING @ 0:20] Queen - A Kind Of Magic
08/01 12:20:07 Trace: [AudioByte ASIO] [LowQuality 86,3x, 24/48 MP3 => 24/48] [100% buf] [PLAYING @ 0:25] Queen - A Kind Of Magic
08/01 12:20:11 Info: [stats] 1913mb Virtual, 669mb Physical, 313mb Managed, 1664 Handles, 87 Threads
08/01 12:20:12 Trace: [AudioByte ASIO] [zoneplayer/raat] sync AudioByte ASIO: realtime=5782292667666 rtt=0us offset=-73184446332us delta=332us drift=-666us in 30,216s (-22,063ppm, -79,428ms/hr)
08/01 12:20:13 Trace: [AudioByte ASIO] [LowQuality, 24/48 MP3 => 24/48] [100% buf] [PLAYING @ 0:30] Queen - A Kind Of Magic
08/01 12:20:18 Trace: [AudioByte ASIO] [LowQuality, 24/48 MP3 => 24/48] [100% buf] [PLAYING @ 0:35] Queen - A Kind Of Magic
08/01 12:20:23 Trace: [AudioByte ASIO] [LowQuality, 24/48 MP3 => 24/48] [100% buf] [PLAYING @ 0:41] Queen - A Kind Of Magic
08/01 12:20:24 Warn: [music/slurp] Failed to push internet radio now playing: 504
<html><body><h1>504 Gateway Time-out</h1>
The server didn't respond in time.
</body></html>

08/01 12:20:26 Info: [stats] 1905mb Virtual, 669mb Physical, 314mb Managed, 1664 Handles, 85 Threads
08/01 12:20:28 Trace: [AudioByte ASIO] [LowQuality, 24/48 MP3 => 24/48] [100% buf] [PLAYING @ 0:46] Queen - A Kind Of Magic
08/01 12:20:31 Warn: [music/slurp] Failed to push internet radio now playing: 504
<html><body><h1>504 Gateway Time-out</h1>
The server didn't respond in time.
</body></html>

08/01 12:20:33 Trace: [AudioByte ASIO] [LowQuality, 24/48 MP3 => 24/48] [100% buf] [PLAYING @ 0:51] Queen - A Kind Of Magic
08/01 12:20:39 Trace: [AudioByte ASIO] [LowQuality, 24/48 MP3 => 24/48] [100% buf] [PLAYING @ 0:56] Queen - A Kind Of Magic
08/01 12:20:41 Info: [stats] 1905mb Virtual, 669mb Physical, 314mb Managed, 1664 Handles, 85 Threads
08/01 12:20:42 Trace: [AudioByte ASIO] [zoneplayer/raat] sync AudioByte ASIO: realtime=5812527003000 rtt=0us offset=-73184446997us delta=-997us drift=-1331us in 60,451s (-22,023ppm, -79,284ms/hr)
08/01 12:20:44 Trace: [AudioByte ASIO] [LowQuality, 24/48 MP3 => 24/48] [100% buf] [PLAYING @ 1:01] Queen - A Kind Of Magic
08/01 12:20:49 Trace: [AudioByte ASIO] [LowQuality, 24/48 MP3 => 24/48] [100% buf] [PLAYING @ 1:07] Queen - A Kind Of Magic

In log above; Madonna fails after a time (if it is 10 or 30 seconds; not important; but it fails). The Madonna song is not even on the radio channel at the moment (it is for some reason this same part it starts every time it fails for this channel). The Queen - A Kind Of Magic was the content of the radio stream when I tried start playing radio stream.

If I try same URL in any other program; I get the correct song and no issues with stream stopping on what appears to be some old cached stream.

Tor_Gunnar_Berland · August 1, 2018, 10:39am

The same stuff happens on multiple radio streams; on different locations, different ISPs and different hardware using Roon.

Tested on core on Windows 8.1 (64bit); Windows 10 (64bit); MacOS 10.13.6; and via the Nucleus+). On two different physical locations and different cores.

dylan · August 1, 2018, 12:08pm

Thanks for sharing your report with us, @Tor_Gunnar_Berland!

So we can gain some greater insight into what you’re experiencing, please see the following:

Can you share a screenshot of your signal path when you are playing a station that experiences this behavior?
Does this happen for all radio stations? Are there any that do work for you?
Can you share the URL of one of the stations that this happens to?

Thanks!
Dylan

Tor_Gunnar_Berland · August 1, 2018, 12:22pm

Of course, when it fails it will not have anything in the signal path, then you have this:

Before it fails (when it will fail; you have this):

When it fails; it also states (unable to copy this part out from screenshot):
==> Radio: Unable to play this channel. Its address may have been moved or are temporary unavailable

But it plays of some buffer or cached file not being updated. So my guess is that it comes to the end of the buffer, and there is nothing more… Madonna - La Isla Bonita, have not been on the radio channels playlist for weeks

Edit:
Workaround; when Madonna starts on this channel - click stop; the start again… after 2-5 retries; it starts the real stream. This happens on other radio channel streams as well (but only in Roon).

Edit2:
It seems to be connected with change of output; if I have it working I can stop and start multiple times without any issues. Seems to be no issue on other channels running the same 48kHz, 24bit either. But if I play of some other music with 44.1kHz/16bit then go back to the radio channel again it often fails.

Same on different endpoints (output); and different devices running Roon core (even different platforms running core; same on Nucleus+; Windows 8.1; Windows 10; macOS 10.13.6); even on different places with different ISP. Local or local network content; or Tidal - no issues at all. Only these freaking radio-channels!

dylan · August 1, 2018, 12:36pm

Thanks for the details, @Tor_Gunnar_Berland!

Can you share the URL of the station you are trying to play above?

Just to clarify, when you tried on these different platforms, was it all the same database (i.e. you restored a backup on that machine) or did you try any of these out with a fresh database?

Thanks,
Dylan

Tor_Gunnar_Berland · August 1, 2018, 12:50pm

http://tx-bauerno.sharp-stream.com/http_live.php?i=radionorge_no_hq

No; not the same database - I have multiple licenses for Roon

Edit:
And I also tested the same on a few friends Roon-systems.

And the roon-core set up here at my office; actually had the same problems without any other data in the database (besides the radio-channels).

dylan · August 1, 2018, 1:25pm

Thanks for sharing the station with me, @Tor_Gunnar_Berland!

It didn’t happen at first, but after some time I was able to replicate the behavior you mentioned.

I’m going to send your report over to the technical team so they can do some further investigation here. I wasn’t able to get any of my other stations to exhibit this behavior — do you have any other radio station examples or is it just this one?

When I receive feedback from the team I’ll be sure to update this thread with their findings.

Thank you,
Dylan

Tor_Gunnar_Berland · August 1, 2018, 1:31pm

http://tx-bauerno.sharp-stream.com/http_live.php?i=radio1_no_hq
http://tx-bauerno.sharp-stream.com/http_live.php?i=vinyl_no_hq
http://tx-bauerno.sharp-stream.com/http_live.php?i=radiorock_no_hq
http://tx-bauerno.sharp-stream.com/http_live.php?i=norskpop_no_hq
http://www.listenlive.eu/p4_aac_hq.m3u
http://www.listenlive.eu/p10_aac_hq.m3u
http://www.listenlive.eu/p4_aac_hq.m3u

but the tx-beuerno links seems to get this problem more frequent. Not sure why. If I use JRiver Media Center 24; these never fail. Opening URL directly in Google chrome seems to work fine always as well.

Edit:
The streaming provider might do something “weird”, but I can not see the effect of this anywhere else (besides Roon) - which I find interesting.

dylan · August 1, 2018, 1:45pm

Hey @Tor_Gunnar_Berland,

For some additional testing, I tried these stations outside of Roon using iTunes. I tried the top two links in your post above, and I was able to replicate the behavior for both of those stations in iTunes. I tried some of my other stations and was unable to replicate this behavior in either iTunes or Roon.

Digging a little deeper, I did a search for this station and came to this site:

When I first visited the page and it started playing, it started with the same Madonna track that I heard in Roon and iTunes. After a few seconds this switched over to the actual stream.

I think that the stream provider may be handling things a little differently than typical on their end, which is why these stations are seeing this behavior. The best course of action is to contact the stream provider directly — They may be able to make a change that will resolve this issue with other sources accessing the stream.

Kind regards,
Dylan

Tor_Gunnar_Berland · August 1, 2018, 4:21pm

Thank you for investigating this; seems you are right - weird I have not been able to reproduce (I probably have not been trying hard enough).

system · August 3, 2018, 4:22am

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