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