Possible API issue


(Harry ten Berge) #1

Hi @support

In RoPieee we use the Roon API for getting updates to display on the screen. Furthermore we use it for remote controls. So there’s an extension that talks to the Roon API, and this extension exposes an interface that is used by the RoPieee software.

Since a month or so I’m receiving reports of sudden stops: the information on the screen isn’t updated anymore. I’ve tried to figure out what it could be, suspecting my extension to be broken. From the logs from my users it appeared as if the extension all of a sudden does not receive updates anymore.

What makes it difficult that all this time I only had this situation myself twice. However, in most cases a restart of Roon core solves the problem. So lately I’m wondering if something could trigger Roon core to stop sending out updates.

Today I ran into the issue myself. Saved the logs of Roon core, and restarted it. This resolved the problem (where restarting the extension does not).

So, when everything is working I see this in the logs:

12/01 10:50:15 Trace: [roonapi] [apiclient 192.168.1.181:49584] CONTINUE Changed {"zones_seek_changed":[{"zone_id":"1601ba4eefe2dbc281c82643f9480c9e52bf","queue_time_remaining":26,"seek_position":569}]}
12/01 10:50:16 Trace: [Hugo2] [Enhanced, 16/44 FLAC => 32/44] [100% buf] [PLAYING @ 9:30/9:55] Happiness Is a Warm Gun - Tori Amos
12/01 10:50:16 Trace: [roonapi] [apiclient 192.168.1.138:42670] CONTINUE Changed {"zones_seek_changed":[{"zone_id":"1601ba4eefe2dbc281c82643f9480c9e52bf","queue_time_remaining":25,"seek_position":570}]}
12/01 10:50:16 Trace: [roonapi] [apiclient 192.168.1.181:49582] CONTINUE Changed {"zones_seek_changed":[{"zone_id":"1601ba4eefe2dbc281c82643f9480c9e52bf","queue_time_remaining":25,"seek_position":570}]}

And so on.

During the night something happened in my infrastructure, causing endpoints to disconnect from Roon server. This looked like this:

2/02 01:24:35 Info: [stats] 4475mb Virtual, 2079mb Physical, 830mb Managed, 0 Handles, 444 Threads
12/02 01:24:50 Info: [stats] 4476mb Virtual, 2080mb Physical, 831mb Managed, 0 Handles, 444 Threads
12/02 01:25:04 Trace: [roonapi] [apiclient 192.168.1.138:43512] CONNECTION TIMEOUT
12/02 01:25:04 Info: [roonapi] [apiclient 192.168.1.138:43512] disconnected
12/02 01:25:04 Trace: [roonapi/registry] removing [apiclient 192.168.1.138:43512] => [org.ropieee.remote, RoPieee Remote Control V2 [ropieee] v2.0.6 by Spockfish <htenberge+ropieee@gmail.com>]
12/02 01:25:04 Trace: [rnet/RnetJsonClient] no data received for >10000ms. Killing connection.
12/02 01:25:04 Trace: [raat_ll/client] [Metrum Acoustics Ambre @ 192.168.1.121:36585] no data received for >10000ms. Killing connection.
12/02 01:25:04 Trace: [push] restarting connection (Unable to read data from the transport connection: interrupted.)
12/02 01:25:04 Trace: [rnet/RnetJsonClient] no data received for >10000ms. Killing connection.
12/02 01:25:04 Trace: [push] retrying connection in 38151ms
12/02 01:25:04 Trace: [rnet/RnetJsonClient] no data received for >10000ms. Killing connection.
12/02 01:25:04 Trace: [raat_ll/client] [snd_allo_digione] no data received for >10000ms. Killing connection.
12/02 01:25:04 Trace: [raatserver] [RaatServer prince @ 127.0.0.1:33285] lost client connection. Retrying
12/02 01:25:04 Trace: [raatserver] [RaatServer prince @ 127.0.0.1:33285] connecting (attempt 1)
12/02 01:25:04 Trace: [raat] [Metrum Acoustics Ambre @ 192.168.1.121:36585] => Disconnected
12/02 01:25:04 Trace: [raat] [Metrum Acoustics Ambre @ 192.168.1.121:36585] lost client connection. Retrying
12/02 01:25:04 Trace: [raat] [Metrum Acoustics Ambre @ 192.168.1.121:36585] connecting (attempt 1)
12/02 01:25:04 Info: [transport] destroyed zone ambre was playing? False
12/02 01:25:04 Trace: [zone ambre] Suspend
12/02 01:25:04 Trace: [raatserver] [RaatServer ropieeetouch @ 192.168.1.181:33479] lost client connection. Retrying
12/02 01:25:04 Trace: [raatserver] [RaatServer ropieeetouch @ 192.168.1.181:33479] connecting (attempt 1)
12/02 01:25:04 Trace: [raatserver] [RaatServer ropieee @ 192.168.1.138:42129] lost client connection. Retrying
12/02 01:25:04 Trace: [raatserver] [RaatServer ropieee @ 192.168.1.138:42129] connecting (attempt 1)
12/02 01:25:04 Info: [transport] destroyed zone My Digione was playing? False

And then it starts to reconnect, but I see this error in my log:

12/02 01:26:25 Critical: scx: in OnExit: System.NullReferenceException: Object reference not set to an instance of an object
 at Sooloos.Broker.RoonApi.TransportService_2.EndpointToJson (Sooloos.Broker.Api.Endpoint ep) [0x00028] in <bbda6a553eb048f1b5c5c7aa2e58a1a5>:0
 at Sooloos.Broker.RoonApi.TransportService_2.<ZoneToJson>b__37_2 (Sooloos.Broker.Api.Endpoint x) [0x00000] in <bbda6a553eb048f1b5c5c7aa2e58a1a5>:0
 at System.Linq.Enumerable+SelectIListIterator`2[TSource,TResult].MoveNext () [0x00048] in <ae162b7061064bfaa55021254699ac67>:0
 at System.Collections.Generic.List`1[T]..ctor (System.Collections.Generic.IEnumerable`1[T] collection) [0x00077] in <370a0c27f4b74d1a81431037df6d75bf>:0
 at Base.JList..ctor (System.Collections.Generic.IEnumerable`1[T] l) [0x00000] in <8e2bbba085c347469d381b30fe73c82a>:0
 at Sooloos.Broker.RoonApi.TransportService_2.ZoneToJson (Sooloos.Broker.Api.Zone zone, System.Boolean for_diff) [0x000e6] in <bbda6a553eb048f1b5c5c7aa2e58a1a5>:0
 at Sooloos.Broker.RoonApi.TransportService_2._ActuallyChanged (Sooloos.Broker.Api.Zone zone) [0x00000] in <bbda6a553eb048f1b5c5c7aa2e58a1a5>:0
 at Sooloos.Broker.RoonApi.TransportService_2.<_update_subscriptions>b__25_0 (Sooloos.Broker.Api.Zone x) [0x00000] in <bbda6a553eb048f1b5c5c7aa2e58a1a5>:0
 at System.Linq.Enumerable+WhereEnumerableIterator`1[TSource].ToList () [0x0001b] in <ae162b7061064bfaa55021254699ac67>:0
 at System.Linq.Enumerable.ToList[TSource] (System.Collections.Generic.IEnumerable`1[T] source) [0x0001f] in <ae162b7061064bfaa55021254699ac67>:0
 at Sooloos.Broker.RoonApi.TransportService_2._update_subscriptions () [0x000d1] in <bbda6a553eb048f1b5c5c7aa2e58a1a5>:0
 at Sooloos.Broker.RoonApi.TransportService_2.OnThreadExit () [0x00034] in <bbda6a553eb048f1b5c5c7aa2e58a1a5>:0
 at Sooloos.Broker.RoonApi.Module.ev_exit () [0x0000b] in <bbda6a553eb048f1b5c5c7aa2e58a1a5>:0
 at Sooloos.SynchronizationContextThread.OnExit () [0x0000a] in <474fc6b46f7646c587f524cda12acaf9>:0

This error is then flooding my logs. Nothing else, only this. Music playing works obviously, but everything related to the API seems broken. Or more precise: updates on the transport subscription are not send anymore.

I’ve copied the logs, so if you need them ping me. Hopefully this gives you a hint or something what could be wrong.

Thanks!


(Dylan Caudill) #2

Hi @spockfish,

I’ll get this over to the team so they can take a closer look. Can you send me the logs as well so I can include them in my report to the team?

Thanks!


(Harry ten Berge) #4

Sure!

How would you like me to do that?
Do you have an email addr for me?

Thanks


#5

Same here. Once a zone gets powered down while grouped, the core starts spamming that unhandled exception until the core is restarted. @support Any progress addressing this?


(Harry ten Berge) #6

Yeah an update would be great @support


#7

For the record - I run into this too yesterday. Roon complained once or twice every second:

02/01 11:04:51 Critical: scx: in OnExit: System.NullReferenceException: Object reference not set to an instance of an object
  at Sooloos.Broker.RoonApi.TransportService_2.EndpointToJson (Sooloos.Broker.Api.Endpoint ep) [0x00028] in <dcbcf4f91fec401e800a83ba373c6044>:0 
  at Sooloos.Broker.RoonApi.TransportService_2.<ZoneToJson>b__37_2 (Sooloos.Broker.Api.Endpoint x) [0x00000] in <dcbcf4f91fec401e800a83ba373c6044>:0 
  at System.Linq.Enumerable+SelectIListIterator`2[TSource,TResult].MoveNext () [0x00048] in <ae162b7061064bfaa55021254699ac67>:0 
  at System.Collections.Generic.List`1[T]..ctor (System.Collections.Generic.IEnumerable`1[T] collection) [0x00077] in <370a0c27f4b74d1a81431037df6d75bf>:0 
  at Base.JList..ctor (System.Collections.Generic.IEnumerable`1[T] l) [0x00000] in <1e9187d858a94158b2a2c81586b0ef84>:0 
  at Sooloos.Broker.RoonApi.TransportService_2.ZoneToJson (Sooloos.Broker.Api.Zone zone, System.Boolean for_diff) [0x000e6] in <dcbcf4f91fec401e800a83ba373c6044>:0 
  at Sooloos.Broker.RoonApi.TransportService_2._ActuallyChanged (Sooloos.Broker.Api.Zone zone) [0x00000] in <dcbcf4f91fec401e800a83ba373c6044>:0 
  at Sooloos.Broker.RoonApi.TransportService_2.<_update_subscriptions>b__25_0 (Sooloos.Broker.Api.Zone x) [0x00000] in <dcbcf4f91fec401e800a83ba373c6044>:0 
  at System.Linq.Enumerable+WhereEnumerableIterator`1[TSource].ToList () [0x0001b] in <ae162b7061064bfaa55021254699ac67>:0 
  at System.Linq.Enumerable.ToList[TSource] (System.Collections.Generic.IEnumerable`1[T] source) [0x0001f] in <ae162b7061064bfaa55021254699ac67>:0 
  at Sooloos.Broker.RoonApi.TransportService_2._update_subscriptions () [0x000d1] in <dcbcf4f91fec401e800a83ba373c6044>:0 
  at Sooloos.Broker.RoonApi.TransportService_2.OnThreadExit () [0x00034] in <dcbcf4f91fec401e800a83ba373c6044>:0 
  at Sooloos.Broker.RoonApi.Module.ev_exit () [0x0000b] in <dcbcf4f91fec401e800a83ba373c6044>:0 
  at Sooloos.SynchronizationContextThread.OnExit () [0x0000a] in <7f0a74b68d2a4a0ba3084b62b8028591>:0

I cannot say when it started because Roon had been running out of log files already but I think it was the same root cause: powering down and starting up again selected or all devices from grouped zones in between.

First I thought to post into this thread:

… but it looks here things are more recent. :wink:


(Dylan Caudill) #8

Hi all,

Apologies for the delay here. I checked in with the team on this and they’re still actively investigating the cause of what you’re seeing. We appreciate your patience while the investigation continues. I’ll be sure to update you ASAP when I have more information from the team.


(Nathan Wilkes) #9

Thanks @dylan. I can corroborate that a reboot of ROCK is the only way to consistently fix the problem when it occurs, at least in my setup (4 RoPieee endpoints, 3 RoPieee displays, ROCK core).

Only for context, I have gone to significant lengths to remove any possibility of networking issues (everything now wired, everything around 1ms or less).