Roon 1.3-196 & Sonos - Radio playback sometimes stops while playing from Tidal

I was having this problem a lot with the AirSonos + Roon 1.2 combo, but Roon 1.3 with native Sonos support has been more stable. However, there’s one problem that has happened a few times per day. At random, sound output from the Sonos will simply stop. If you look at the transport in Roon, it shows that it’s playing but there’s no sound. Hitting next then previous, or playing from another track usually corrects it.

As far as I can tell, the problem usually starts with a Tidal track, not local files.

What do you need to help narrow this down?

I didn’t write down exactly when it started, but I think this could be it:

02/06 23:32:59 Warn: [zoneplayer] Corrupt Media Detected
02/06 23:32:59 Info: [zoneplayer/base] Open result (Queueing): Result[Status=CorruptMedia]
02/06 23:32:59 Warn: [zoneplayer] couldn't queue URL http://69.audio-pop.tidal.com/79887763/3a97e7b3bebd3de4874918383bfb1be8_26.flac?__token__=exp=1486425770~hmac=1781a6225f0bfb7190458daca3e97aa1e97487050b2c6dbc2fb0b6d4c4b1fa11: corrupt media

Got a closer log set:

02/07 01:18:03 Info: [stats] 1606mb Virtual, 537mb Physical, 152mb Managed, 0 Handles, 54 Threads
02/07 01:18:06 Trace: [prebuffer] status 219910/441000 (49%) @ 281/286 sec
02/07 01:18:06 Trace: [prebuffer] status 197860/441000 (44%) @ 282/286 sec
02/07 01:18:07 Trace: [prebuffer] status 173605/441000 (39%) @ 282/286 sec
02/07 01:18:07 Trace: [prebuffer] status 149350/441000 (33%) @ 283/286 sec
02/07 01:18:08 Trace: [prebuffer] status 122890/441000 (27%) @ 283/286 sec
02/07 01:18:08 Trace: [prebuffer] status 100840/441000 (22%) @ 284/286 sec
02/07 01:18:09 Trace: [prebuffer] status 78790/441000 (17%) @ 284/286 sec
02/07 01:18:09 Trace: [prebuffer] status 54535/441000 (12%) @ 285/286 sec
02/07 01:18:10 Trace: [prebuffer] status 30280/441000 (6%) @ 285/286 sec
02/07 01:18:10 Trace: [prebuffer] status 6025/441000 (1%) @ 286/286 sec
02/07 01:18:13 Trace: [zone] [Living Room + Studio + Master Bedroom] auto-swim based on Bent - Now I Must Remember
02/07 01:18:13 Trace: [dbperf] flush 0 bytes, 0 ops in 6 ms (cumulative 61354819 bytes, 68902 ops in 18737 ms)
02/07 01:18:13 Trace: [zone] [Living Room + Studio + Master Bedroom] Playing Swim
02/07 01:18:13 Trace: [tidal/http] GET https://api.tidalhifi.com/v1/tracks/69144304/streamurl?countryCode=US&sessionId=ae7e6eb5-eb8f-434c-aa
6d-b57bc7e0a782&soundQuality=LOSSLESS => Success
02/07 01:18:13 Trace: [tidal/http] GET https://api.tidalhifi.com/v1/tracks/69144304?countryCode=US&sessionId=ae7e6eb5-eb8f-434c-aa6d-b57bc7e
0a782& => Success
02/07 01:18:13 Info: [zoneplayer/base] BufferingTrack != PlayingTrack during _Queue. Refusing to queue
02/07 01:18:17 Info: [zoneplayer/sonos] GOT REQUEST Get /9d0b55df67d148d9ba2551d53014e0bc/Roon.wav
02/07 01:18:17 Trace: [zoneplayer/sonos] request matches current stream
02/07 01:18:18 Info: [stats] 1608mb Virtual, 539mb Physical, 156mb Managed, 0 Handles, 54 Threads
02/07 01:18:22 Trace: [zoneplayer/sonos] position timer, stream ended, path: /9d0b55df67d148d9ba2551d53014e0bc/Roon.wav
02/07 01:18:22 Trace: [zoneplayer/sonos] State transition Playing => EndStreamLimbo
02/07 01:18:22 Info: [zoneplayer/base] BufferingTrack == NextTrack during ClearQueuedMedia, setting _stop_on_next_track_transition
02/07 01:18:22 Info: [library] recorded play for profile eacb4061-bf99-43ee-967b-9f9cc5746f1b: mediaid=50:1:716ce63a-f064-4791-8dc7-7eeffff1665c metadataid= contentid=168:0:38466296 libraryid=50:1:716ce63a-f064-4791-8dc7-7eeffff1665c
02/07 01:18:22 Trace: [library] finished with 46 dirty tracks 3 dirty albums 6 dirty performers 12 dirty works 12 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 34 changed objects
02/07 01:18:22 Debug: [library/index] updating search indices: 8 ops 0 adds, 0 removes
02/07 01:18:22 Trace: [library] endmutation in 21ms
02/07 01:18:22 Trace: [tidal/http] GET https://api.tidalhifi.com/v1/tracks/69144304/streamurl?countryCode=US&sessionId=ae7e6eb5-eb8f-434c-aa6d-b57bc7e0a782&soundQuality=LOSSLESS => Success
02/07 01:18:22 Trace: [dbperf] flush 0 bytes, 0 ops in 1 ms (cumulative 61354819 bytes, 68902 ops in 18738 ms)
02/07 01:18:22 Trace: [tidal/http] GET https://api.tidalhifi.com/v1/tracks/69144304?countryCode=US&sessionId=ae7e6eb5-eb8f-434c-aa6d-b57bc7e0a782& => Success
02/07 01:18:22 Info: [zoneplayer/base] Playing: http://9b.audio-pop.tidal.com/f37b0b3e802698d49475d2fc16fa65c7_26.flac
02/07 01:18:22 Trace: [zoneplayer/sonos] State transition EndStreamLimbo => Disconnected
02/07 01:18:22 Info: [audio/env] [zoneplayer -> stream] All streams were disposed
02/07 01:18:22 Trace: [tidal/http] GET https://api.tidalhifi.com/v1/tracks/44799560/streamurl?countryCode=US&sessionId=ae7e6eb5-eb8f-434c-aa6d-b57bc7e0a782&soundQuality=LOSSLESS => Success
02/07 01:18:22 Trace: [tidal/http] GET https://api.tidalhifi.com/v1/tracks/44799560?countryCode=US&sessionId=ae7e6eb5-eb8f-434c-aa6d-b57bc7e0a782& => Success
02/07 01:18:22 Info: [zoneplayer/base] Queueing: http://38.audio-pop.tidal.com/29ba459804ddfc603053d2d901131101_26.flac
02/07 01:18:23 Info: [zoneplayer/base]     Open Result (Playing):Result[Status=Success]
02/07 01:18:23 Info: [zoneplayer/base] Starting playback
02/07 01:18:23 Trace: [zoneplayer/sonos] State transition Disconnected => WaitForHttp
02/07 01:18:23 Debug: [sonos] seturiasync
02/07 01:18:23 Debug: [sonos] seturiasync
02/07 01:18:23 Debug: [sonos] seturiasync
02/07 01:18:23 Debug: [sonos] seturi1
02/07 01:18:23 Debug: [sonos] seturi1
02/07 01:18:23 Debug: [sonos] seturi1
02/07 01:18:23 Trace: [zoneplayer/sonos] in Sonos backend StartStream end
02/07 01:18:23 Info:
--[ SignalPath ]---------------------------------------------
SignalPath Quality = Lossless
Elements:
    Source Format=Flac 44100/16/2  Quality=Lossless
    Output OutputType=Sonos Quality=Lossless
------------------------------------------------------------

02/07 01:18:23 Info:
--[ SignalPath ]---------------------------------------------
SignalPath Quality = Lossless
Elements:
    Source Format=Flac 44100/16/2  Quality=Lossless
    Output OutputType=Sonos Quality=Lossless
------------------------------------------------------------

02/07 01:18:23 Info:
--[ SignalPath ]---------------------------------------------
SignalPath Quality = Lossless
Elements:
    Source Format=Flac 44100/16/2  Quality=Lossless
    Output OutputType=Sonos Quality=Lossless
------------------------------------------------------------

02/07 01:18:23 Info:
--[ SignalPath ]---------------------------------------------
SignalPath Quality = Lossless
Elements:
    Source Format=Flac 44100/16/2  Quality=Lossless
    Output OutputType=Sonos Quality=Lossless
------------------------------------------------------------

02/07 01:18:23 Info:
--[ SignalPath ]---------------------------------------------
SignalPath Quality = Lossless
Elements:
    Source Format=Flac 44100/16/2  Quality=Lossless
    Output OutputType=Sonos Quality=Lossless
------------------------------------------------------------


02/07 01:18:23 Debug: [sonos] seturi2
02/07 01:18:23 Debug: [sonos] seturi3
02/07 01:18:23 Info: [zoneplayer/sonos] GOT REQUEST Get /c13cf98fae334fddb0db2a96c4852818/Roon.wav
02/07 01:18:23 Trace: [zoneplayer/sonos] request matches current stream
02/07 01:18:23 Trace: [zoneplayer/sonos] State transition WaitForHttp => WaitForStatus
02/07 01:18:23 Trace: [prebuffer] status 52920/441000 (12%) @ 0/302 sec
02/07 01:18:23 Trace: [prebuffer] ready 149940/441000 (34%) @ 0/302 sec
02/07 01:18:23 Debug: [sonos] seturi2
02/07 01:18:23 Debug: [sonos] seturi3
02/07 01:18:23 Debug: [sonos] seturi2
02/07 01:18:23 Debug: [sonos] seturi3
02/07 01:18:23 Debug: [sonos] playasync
02/07 01:18:23 Debug: [sonos] play1
02/07 01:18:23 Info: [zoneplayer/sonos] GOT REQUEST Get /c13cf98fae334fddb0db2a96c4852818/Roon.wav
02/07 01:18:23 Trace: [zoneplayer/sonos] request matches current stream
02/07 01:18:24 Trace: [prebuffer] status 147735/441000 (33%) @ 7/302 sec
02/07 01:18:24 Debug: [sonos] play2
02/07 01:18:24 Debug: groupandplay end
02/07 01:18:24 Info: [zoneplayer/base] Open result (Queueing): Result[Status=Success]
02/07 01:18:24 Trace: [prebuffer] ready 149940/441000 (34%) @ 0/397 sec
02/07 01:18:25 Trace: [zoneplayer/sonos] State transition WaitForStatus => Playing
02/07 01:18:29 Trace: [prebuffer] status 441000/441000 (100%) @ 16/302 sec
02/07 01:18:33 Info: [stats] 1613mb Virtual, 538mb Physical, 160mb Managed, 0 Handles, 56 Threads
02/07 01:18:34 Trace: [prebuffer] status 441000/441000 (100%) @ 22/302 sec
02/07 01:18:37 Trace: [streamingmediafile] finished caching http://9b.audio-pop.tidal.com/f37b0b3e802698d49475d2fc16fa65c7_26.flac
02/07 01:18:39 Trace: [prebuffer] status 441000/441000 (100%) @ 27/302 sec
02/07 01:18:41 Trace: [streamingmediafile] finished caching http://38.audio-pop.tidal.com/29ba459804ddfc603053d2d901131101_26.flac
02/07 01:18:44 Trace: [prebuffer] status 441000/441000 (100%) @ 32/302 sec
02/07 01:18:48 Info: [stats] 1610mb Virtual, 540mb Physical, 157mb Managed, 0 Handles, 56 Threads
02/07 01:18:49 Trace: [prebuffer] status 441000/441000 (100%) @ 37/302 sec
02/07 01:18:54 Trace: [prebuffer] status 441000/441000 (100%) @ 42/302 sec
02/07 01:18:59 Trace: [prebuffer] status 441000/441000 (100%) @ 47/302 sec
02/07 01:19:03 Info: [stats] 1607mb Virtual, 537mb Physical, 132mb Managed, 0 Handles, 56 Threads
02/07 01:19:04 Trace: [prebuffer] status 441000/441000 (100%) @ 52/302 sec
02/07 01:19:06 Info: [brokerserver] Client connected: 192.168.1.116:58308
02/07 01:19:06 Trace: [SOOD] Adding User IP 192.168.1.116
02/07 01:19:06 Trace: [raat] [sood] Refreshing device list
02/07 01:19:06 Trace: [raatserver] [sood] Refreshing device list
02/07 01:19:06 Trace: SENT NONFINAL DistributedBroker.ConnectResponse={ BrokerId=6e11d237-e5de-4d9c-8c4e-16426a6e9944 BrokerName='coldbrew' }
02/07 01:19:06 Trace: SENT NONFINAL DistributedBroker.UpdatesChangedResponse={ IsSupported=True WasJustUpdated=False Status='UpToDate' HasChangeLog=False CurrentVersion={ MachineValue=100300196 DisplayValue='1.3 (build 196) stable' Branch='stable' } }
02/07 01:19:07 Debug: GET /image/tmgaaaaa.256.jpg
02/07 01:19:07 Trace: [music/query] performing history query
02/07 01:19:07 Debug: [history] loading history for eacb4061-bf99-43ee-967b-9f9cc5746f1b
02/07 01:19:07 Debug: GET /image/tmgaaaaa.1024.jpg
02/07 01:19:08 Trace: [music/query] query returned 2798 Sooloos.Broker.Api.HistoryPlay(s)
02/07 01:19:08 Trace: [dbperf] flush 0 bytes, 0 ops in 17 ms (cumulative 61354819 bytes, 68902 ops in 18755 ms)
02/07 01:19:08 Trace: [music/query] performing history query
02/07 01:19:08 Trace: [music/query] query returned 2798 Sooloos.Broker.Api.HistoryPlay(s)
02/07 01:19:09 Trace: [prebuffer] status 441000/441000 (100%) @ 57/302 sec
02/07 01:19:14 Trace: [prebuffer] status 441000/441000 (100%) @ 62/302 sec
02/07 01:19:17 Trace: [zone] [Living Room + Studio + Master Bedroom] PlayPause
02/07 01:19:17 Trace: [zone] [Living Room + Studio + Master Bedroom] Pause
02/07 01:19:17 Trace: [zoneplayer/sonos] State transition Playing => Paused
02/07 01:19:18 Info: [stats] 1600mb Virtual, 508mb Physical, 162mb Managed, 0 Handles, 57 Threads
02/07 01:19:22 Trace: [zone] no playback for 5s, suspending to release audio device
02/07 01:19:22 Trace: [zone] [Living Room + Studio + Master Bedroom] Suspend
02/07 01:19:22 Trace: [zone] [Living Room + Studio + Master Bedroom] Stop
02/07 01:19:22 Trace: [zoneplayer/sonos] State transition Paused => Disconnected
02/07 01:19:22 Info: [audio/env] [zoneplayer -> stream] All streams were disposed
02/07 01:19:33 Info: [stats] 1594mb Virtual, 499mb Physical, 164mb Managed, 0 Handles, 49 Threads
02/07 01:19:48 Info: [stats] 1590mb Virtual, 495mb Physical, 160mb Managed, 0 Handles, 49 Threads
02/07 01:19:50 Info: [brokerserver] Client disconnected: 192.168.1.116:58308
02/07 01:19:50 Info: [brokerserver] Client connected: 192.168.1.116:58316
02/07 01:19:50 Trace: [SOOD] Adding User IP 192.168.1.116
02/07 01:19:50 Trace: [raat] [sood] Refreshing device list
02/07 01:19:50 Trace: [raatserver] [sood] Refreshing device list
02/07 01:19:51 Trace: SENT NONFINAL DistributedBroker.ConnectResponse={ BrokerId=6e11d237-e5de-4d9c-8c4e-16426a6e9944 BrokerName='coldbrew' }
02/07 01:19:51 Trace: SENT NONFINAL DistributedBroker.UpdatesChangedResponse={ IsSupported=True WasJustUpdated=False Status='UpToDate' HasChangeLog=False CurrentVersion={ MachineValue=100300196 DisplayValue='1.3 (build 196) stable' Branch='stable' } }
02/07 01:19:51 Trace: [music/query] performing history query
02/07 01:19:51 Trace: [music/query] query returned 2798 Sooloos.Broker.Api.HistoryPlay(s)
02/07 01:19:53 Trace: [zone] [Living Room + Studio + Master Bedroom] PlayPause
02/07 01:19:53 Trace: [zone] [Living Room + Studio + Master Bedroom] Unpause
02/07 01:19:53 Trace: [zone] [Living Room + Studio + Master Bedroom] Selecting Source
02/07 01:19:53 Trace: [zone] [Living Room + Studio + Master Bedroom] Unsuspend
02/07 01:19:54 Trace: [tidal/http] GET https://api.tidalhifi.com/v1/tracks/69144304/streamurl?countryCode=US&sessionId=ae7e6eb5-eb8f-434c-aa6d-b57bc7e0a782&soundQuality=LOSSLESS => Success
02/07 01:19:54 Trace: [tidal/http] GET https://api.tidalhifi.com/v1/tracks/69144304?countryCode=US&sessionId=ae7e6eb5-eb8f-434c-aa6d-b57bc7e0a782& => Success
02/07 01:19:54 Info: [zoneplayer/base] Playing: http://9b.audio-pop.tidal.com/f37b0b3e802698d49475d2fc16fa65c7_26.flac
02/07 01:19:54 Info: [zoneplayer/base]     Open Result (Playing):Result[Status=Success]
02/07 01:19:54 Info: [zoneplayer/base] Performing initial seek to 54000
02/07 01:19:54 Debug: [prebuffer] seeking backing to 12s (2381400 frames @ 44100hz)
02/07 01:19:54 Info: [zoneplayer/base] Starting playback
02/07 01:19:54 Trace: [zoneplayer/sonos] State transition Disconnected => WaitForHttp
02/07 01:19:54 Debug: [sonos] seturiasync
02/07 01:19:54 Debug: [sonos] seturi1
02/07 01:19:54 Debug: [sonos] seturiasync
02/07 01:19:54 Debug: [sonos] seturi1
02/07 01:19:54 Debug: [sonos] seturiasync
02/07 01:19:54 Debug: [sonos] seturi1
02/07 01:19:54 Trace: [zoneplayer/sonos] in Sonos backend StartStream end
02/07 01:19:54 Info:
--[ SignalPath ]---------------------------------------------
SignalPath Quality = Lossless
Elements:
    Source Format=Flac 44100/16/2  Quality=Lossless
    Output OutputType=Sonos Quality=Lossless
------------------------------------------------------------

02/07 01:19:54 Info:
--[ SignalPath ]---------------------------------------------
SignalPath Quality = Lossless
Elements:
    Source Format=Flac 44100/16/2  Quality=Lossless
    Output OutputType=Sonos Quality=Lossless
------------------------------------------------------------

02/07 01:19:54 Info:
--[ SignalPath ]---------------------------------------------
SignalPath Quality = Lossless
Elements:
    Source Format=Flac 44100/16/2  Quality=Lossless
    Output OutputType=Sonos Quality=Lossless
------------------------------------------------------------

02/07 01:19:54 Info:
--[ SignalPath ]---------------------------------------------
SignalPath Quality = Lossless
Elements:
    Source Format=Flac 44100/16/2  Quality=Lossless
    Output OutputType=Sonos Quality=Lossless
------------------------------------------------------------

02/07 01:19:54 Info:
--[ SignalPath ]---------------------------------------------
SignalPath Quality = Lossless
Elements:
    Source Format=Flac 44100/16/2  Quality=Lossless
    Output OutputType=Sonos Quality=Lossless
------------------------------------------------------------

02/07 01:19:54 Info:
--[ SignalPath ]---------------------------------------------
SignalPath Quality = Lossless
Elements:
    Source Format=Flac 44100/16/2  Quality=Lossless
    Output OutputType=Sonos Quality=Lossless
------------------------------------------------------------

02/07 01:19:54 Info:
--[ SignalPath ]---------------------------------------------
SignalPath Quality = Lossless
Elements:
    Source Format=Flac 44100/16/2  Quality=Lossless
    Output OutputType=Sonos Quality=Lossless
------------------------------------------------------------

02/07 01:19:54 Info:
--[ SignalPath ]---------------------------------------------
SignalPath Quality = Lossless
Elements:
    Source Format=Flac 44100/16/2  Quality=Lossless
    Output OutputType=Sonos Quality=Lossless
------------------------------------------------------------

02/07 01:19:54 Info:
--[ SignalPath ]---------------------------------------------
SignalPath Quality = Lossless
Elements:
    Source Format=Flac 44100/16/2  Quality=Lossless
    Output OutputType=Sonos Quality=Lossless
------------------------------------------------------------

02/07 01:19:54 Trace: [musicpowerstate] music is playing, preventing idle sleep
02/07 01:19:54 Trace: [streamingmediafile] immediate read of http://9b.audio-pop.tidal.com/f37b0b3e802698d49475d2fc16fa65c7_26.flac at 4871060 length=32156828

And just caught one again.

02/07 02:29:59 Trace: [zoneplayer/sonos] State transition EndStreamLimbo => Disconnected
02/07 02:29:59 Info: [audio/env] [zoneplayer -> stream] All streams were disposed

It looks like the “EndStreamLimbo” state is logged whenever the music stops. Grepping the logs shows the right timestamps

paging @ben, when you have a chance.

The “EndStreamLimbo” state is a symptom, not a cause. It’s the state machine that manages the Sonos system saying that it has decided that the music has already been stopped.

Can you zip up all the files in the logs folder and upload them somewhere for me? If you don’t have a convenient place I can PM you with instructions to upload to one of our servers.

PM sent

Here’s my network topology. I’m using the SonosNet mode on a separate orthogonal channel from my wifi access points.

Virtualization server -> Fileserver VM, VM running Sonos in Docker -> Mikrotik RB750g3 -> D-Link gigabit switch -> Sonos Connect:Amp on Ethernet

The other Sonos devices (Play:3, Connect: Amp) are connected via SonosNet. Sonos creates network loops if you have more than one device plugged into Ethernet :frowning:

Any update here? I sent logs but haven’t heard back.

This one is in the awkward place where I have a vague idea of what the problem might be, but can’t reproduce it reliably enough to be sure. I also get what seem to be similar playback stops with Tidal/Sonos, but it’s something like once every 3-6 hours and I haven’t found a specific cause that makes it stop on command.

I’m going to keep working on this, and I do have an idea of some things I could probably be doing better that might fix it, but I don’t think it will be a quick fix.

Alright, let me know if you want me to run a build with extra logging or something enabled.

It definitely seems pretty random. It will often work for 3+ hours with no problems or sometimes break twice an hour apart.

Hi Patrick, sorry about the delay here.

There is a -sonostrace command line option, logs with that would help a little. I think you’re running on Linux, the easiest way to do command line flags is to find the RoonAppliance script and add the flag to the end of the last line so that it looks something like this:
exec "$HARDLINK" --debug --gc=sgen --server "$SCRIPT.exe" "$@" -sonostrace

By default that file is /opt/RoonServer/Appliance/RoonAppliance but you seem to have a relatively non-standard setup, so it might be somewhere else.

Thanks, and hopefully I can get this nailed down relatively soon.

Alright, I have that enabled. I’ll PM logs the next time I hit this. I still use your published script to set things up so all the locations are the same. It’s just running in a container for isolation and easier deployment.

Is this the default Linux startup script? I see --debug is in there, does it have no affect with out the trailing -xxxxtrace option or should it be removed to stop debug logging?

Per the KB:

Linux

  1. Find and open the RoonAppliance startup script. This file is /opt/RoonServer/Appliance/RoonAppliance by default, but individual Linux installations may vary.
  2. Add the flag to the end of the last line in the script, giving something like exec "$HARDLINK" --debug --gc=sgen --server "$SCRIPT.exe" "$@" -storagetrace
  3. Restart RoonServer. To do this, open a terminal and type sudo pkill start.sh You will be prompted for your password, type it in and then press enter, then wait for RoonServer to be restarted.
  4. After uploading the logs for Roon Support, remember to go back and remove the flag from the script and restart RoonServer again.

My system was preinstalled so I don’t know what the default should be?

Hi @Larry_Post,

That is indeed the default for RoonServer on Linux. The --debug is normal and expected, and unrelated to the command line flags we’re trying to set on RoonServer here.

The KB article is still correct. The thing to be removed in step 4 is the -xxxxtrace flag set in step 2.

Let me know if you have any other questions, I’d like to help if I can. I’m also not sure what the problem you’re trying to debug here is, can you give us any more details on what you are doing, what you expect to have happen, and what happens instead?

Thanks!

1 Like

Excellent, thank you.