Transport error due to potential memory leak prevents playback on sonos devices

Kilian · January 21, 2018, 4:26pm

Running the Roon server for a few days without restart will lead to Sonos devices not being able to playback music streamed via tidal. Playback via the native Sonos app does work in this situation. The same symptoms can be observed for multiple Sonos devices, the speaker directly connected to the server via an ASIO driver does work flawlessly though. I believe that playback from a local source is still possible but I haven’t attempted to do it for a long time so don’t take my word for it.

The corresponding entry in the error log with emphasis on the System.OutOfMemoryException which will be thrown at all subsequent requests:

1/21 15:55:34 Trace: [zone Kili] Playing 1 Items
01/21 15:55:34 Trace: [zone Kili] Selecting Source state=Stopped
01/21 15:55:34 Trace: [zone Kili] Playing TransportItem
01/21 15:55:34 Trace: [Kili] [zoneplayer/sonos] endstream, zp state: Disconnected
01/21 15:55:34 Trace: [Kili] [zoneplayer/sonos] endstream, zp state: Disconnected
01/21 15:55:34 Trace: [Kili] [LowQuality, 16/48 TIDAL AAC => 16/48] [LOADING @ 0:00] Dä Plan - Querbeat
01/21 15:55:35 Warn: [music] GetExtendedTrackInfo: track 41650600 not found
01/21 15:55:35 Warn: [music] GetExtendedTrackInfo: track 41650600 not found
01/21 15:55:35 Trace: [tidal/http] GET https://api.tidalhifi.com/v1/tracks/70150472/streamurl?countryCode=DE&sessionId=f9ee54c3-90a1-4175-8f41-962b6c6e61ac&soundQuality=LOSSLESS => Success
01/21 15:55:35 Trace: [tidal/http] GET https://api.tidalhifi.com/v1/tracks/70150472?countryCode=DE&sessionId=f9ee54c3-90a1-4175-8f41-962b6c6e61ac& => Success
01/21 15:55:35 Info: [Kili] [zoneplayer] Playing: http://5e.audio-pop.tidal.com/27405107/2bf82b6d-32ea-4c70-bfdc-965a3de543e2_36.m4a
01/21 15:55:35 Trace: [Kili] [zoneplayer/sonos] endstream, zp state: Disconnected
01/21 15:55:35 Trace: [ZOTAC-ASIO] [Enhanced 2,0x, 16/44 ALAC => DSD128] [100% buf] [PLAYING @ 0:40/3:11] D.A.N.Z.E. - Funky Marys
01/21 15:55:36 Info: [Kili] [zoneplayer]     Open Result (Playing):Result[Status=Success]
01/21 15:55:36 Trace: [Kili] [zoneplayer/sonos] endstream, zp state: Disconnected
01/21 15:55:36 Info: [Kili] [zoneplayer] Starting playback
01/21 15:55:36 Trace: [Kili] [zoneplayer/sonos] backend StartStream 1, bytesperframe: 4, channels: 2, samplerate: 48000, bits per sample: 16
01/21 15:55:37 Warn: [zoneplayer] failed to start stream System.OutOfMemoryException: Eine Ausnahme vom Typ "System.OutOfMemoryException" wurde ausgelöst.
   bei Sooloos.Broker.Transport.UPNPZonePlayerBase.RingBuffer..ctor(Int32 size, Byte[] initial_contents)
   bei Sooloos.Broker.Transport.UPNPZonePlayerBase.StartStream(StartStreamParameters ps)
   bei Sooloos.Broker.Transport.ZonePlayerBase.<>c__DisplayClass61_0.<_StartStream>b__0()
   bei Sooloos.Broker.Transport.ZonePlayerBase.Prepare(Action cb_done)
   bei Sooloos.Broker.Transport.ZonePlayerBase._StartStream()
01/21 15:55:37 Info: EV PLAYBACK FAILED System.OutOfMemoryException: Eine Ausnahme vom Typ "System.OutOfMemoryException" wurde ausgelöst.
   bei Sooloos.Broker.Transport.UPNPZonePlayerBase.RingBuffer..ctor(Int32 size, Byte[] initial_contents)
   bei Sooloos.Broker.Transport.UPNPZonePlayerBase.StartStream(StartStreamParameters ps)
   bei Sooloos.Broker.Transport.ZonePlayerBase.<>c__DisplayClass61_0.<_StartStream>b__0()
   bei Sooloos.Broker.Transport.ZonePlayerBase.Prepare(Action cb_done)
   bei Sooloos.Broker.Transport.ZonePlayerBase._StartStream()
01/21 15:55:37 Warn: Track Stopped Due to Error
01/21 15:55:37 Info: [zone Kili] OnPlayFeedback StoppedEndOfMediaUnnatural
01/21 15:55:37 Debug: [zone Kili] _Advance
01/21 15:55:37 Trace: [Kili] [LowQuality, 16/48 TIDAL AAC => 16/48] [STOPPED @ 0:00] 
01/21 15:55:37 Trace: [prebuffer] ready 163200/480000 (34%) @ 0/223 sec
01/21 15:55:37 Trace: [streamingmediafile] finished caching http://5e.audio-pop.tidal.com/27405107/2bf82b6d-32ea-4c70-bfdc-965a3de543e2_36.m4a
01/21 15:55:40 Info: [stats] 1535mb Virtual, 601mb Physical, 508mb Managed, 2416 Handles, 88 Threads
01/21 15:55:41 Trace: [ZOTAC-ASIO] [Enhanced 2,0x, 16/44 ALAC => DSD128] [100% buf] [PLAYING @ 0:45/3:11] D.A.N.Z.E. - Funky Marys
01/21 15:55:42 Trace: [zone] no playback for 5s, suspending to release audio device
01/21 15:55:42 Trace: [zone Kili] Suspend
01/21 15:55:42 Trace: [zone Kili] Stop

The server runs at win 10 32 bit with the newest version of Roon installed. A restart of the server will fix the issue temporarily.

Attached you will find the log in it’s entirety. I only have access to the one log file at the moment, if the others are required as well I’ll gladly provide them.

Regards

Kilian

ben · January 22, 2018, 10:50pm

Hi Kilian,

I have an idea of where to look for the problem here, I have just two questions to help me reproduce the problem in house:

How much RAM does the system you’re running Roon on have?
You said that the system needs to be restarted every few days, how much of that time is spent with music actively playing? Just a vague estimate is good enough, I don’t need a precise number.

Thanks for the report, unfortunately I don’t think there is anything you can do other than restarting Roon to work around this. Hopefully we can get this fixed for some future release.

Kilian · January 23, 2018, 3:51pm

The server is running on a small Zotac box with 4 GB RAM. Due to it being 32 bit roughly 3.1 GB are addressable. Current utilization lays around 50% (playback on 2 devices at the same time).
Throughout the week Roon is used about 3 - 5 hours a day. Saturday and Sunday this time may exceed twofold.

Lets clarify the phrase “every few days”… This statement leans towards a week plus rather than a couple of days. I have now set up the box to restart periodically as a temporary work around.

Just out of curiosity, as you have mentioned RAM, I monitored the RAM usage for the past two hours. The first 1 1/2 hours music was played back via an asio driver connected directly to the server, the gray line indicates starting play back on a second sonos device. Nothing interesting to see here total ram usage of the system remained unchanged near the 50 % the entire time.

eric · January 26, 2018, 9:39pm

@Kilian ---- Thank you for the follow up and verifying that information for me (i.e the email address), very appreciated!

Confirming that I have enabled diagnostics on your father’s account and once the mentioned report is received I will confirm that we have it and then promptly pass over to our techs for further evaluation!

-Eric

UPDATE: Looks like it just came in