Sonos connection to devices lost after some time after adding docker container(s) to the server

patrik_gfeller · March 14, 2023, 5:31pm

Hi all,

since a couple of weeks I experience problems with my sonos system. I do not know if the problems are related with a recent sonos software update - or with my setup.

I use Ubuntu 22.04.2 LTS x86_64 (5.15.0-67-generic) as server operating system with the following java runtime:

openjdk 11.0.10 2021-01-19 LTS
OpenJDK Runtime Environment Zulu11.45+27-CA (build 11.0.10+9-LTS)
OpenJDK 64-Bit Server VM Zulu11.45+27-CA (build 11.0.10+9-LTS, mixed mode)

OpenHAB was installed from the official repository and is up-to-date: Version 3.4.2 (Build)

After a restart the sonos devices are detected and remain online for a couple of hours. But after some time all my sonos devices report offline.

2023-03-14 17:42:37.692 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Sonos player RINCON_347E5C37646001400 is not available in local network
2023-03-14 17:43:37.704 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Sonos player RINCON_347E5C37646001400 has been found in local network

Devices use the following software version:

2023-03-14 18:10:07.751 [TRACE] [s.internal.handler.ZonePlayerHandler] - Received pair 'SoftwareVersion':'71.1-38240' (service 'DeviceProperties') for thing 'sonos:SYMFONISK:RINCON_347E5C37659001400'
2023-03-14 18:10:07.752 [TRACE] [s.internal.handler.ZonePlayerHandler] - Received pair 'DisplaySoftwareVersion':'15.1.1' (service 'DeviceProperties') for thing 'sonos:SYMFONISK:RINCON_347E5C37659001400'

It is strange that after a new start with cache clean only some of the players loose connection; but connect again after some time - but after aprox. half a day all devices report offline.

I’m collecting trace logs now to potentially create a bugreport - but would know if there are ideas what else could be the problem or what info I should collect to help with trouble shooting (the trace logs will be quite big - so if I can things narrow down that would help). I can also install wireshark to monitor the network traffic if this is helpful - but I would need to know what filters make sense to get useful information.

The sonos native apps do not have problems to see the devices and do not report any problems.

Thanks for any advice :-).

with kind regards,
Patrik

Update - After 3 Hours all Sonos devices remain offline:

This is where the last time I saw kind of communication:

2023-03-14 18:35:01.826 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Sonos player RINCON_347E5C3E35B401400 is not available in local network
2023-03-14 18:35:10.992 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Sonos player RINCON_7828CA76219E01400 is not available in local network
2023-03-14 18:35:11.822 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Sonos player RINCON_48A6B824D4D801400 is not available in local network
2023-03-14 18:35:12.030 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_347E5C37646001400: Subscription to service ZoneGroupTopology failed
2023-03-14 18:35:21.002 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_347E5C3E379601400: Subscription to service RenderingControl failed
2023-03-14 18:35:21.003 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_347E5C37646001400: Subscription to service RenderingControl failed
2023-03-14 18:35:31.000 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_347E5C37646001400: Subscription to service DeviceProperties failed
2023-03-14 18:35:41.011 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_7828CAD279FE01400: Subscription to service GroupManagement failed
2023-03-14 18:35:41.028 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_7828CAD279FE01400: Subscription to service RenderingControl failed
2023-03-14 18:35:41.032 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_347E5C37646001400: Subscription to service ContentDirectory failed
2023-03-14 18:35:47.757 [TRACE] [s.internal.handler.ZonePlayerHandler] - Received pair 'ChannelFreq':'2462' (service 'DeviceProperties') for thing 'sonos:SYMFONISK:RINCON_347E5C3E379601400'
2023-03-14 18:35:47.758 [TRACE] [s.internal.handler.ZonePlayerHandler] - Received pair 'Configuration':'1' (service 'DeviceProperties') for thing 'sonos:SYMFONISK:RINCON_347E5C3E379601400'
2023-03-14 18:35:47.758 [TRACE] [s.internal.handler.ZonePlayerHandler] - Received pair 'EthLink':'true' (service 'DeviceProperties') for thing 'sonos:SYMFONISK:RINCON_347E5C3E379601400'
2023-03-14 18:35:47.758 [TRACE] [s.internal.handler.ZonePlayerHandler] - Received pair 'HTBondedZoneCommitState':'0' (service 'DeviceProperties') for thing 'sonos:SYMFONISK:RINCON_347E5C3E379601400'
2023-03-14 18:35:47.758 [TRACE] [s.internal.handler.ZonePlayerHandler] - Received pair 'ZoneName':'Büro' (service 'DeviceProperties') for thing 'sonos:SYMFONISK:RINCON_347E5C3E379601400'
2023-03-14 18:35:47.759 [TRACE] [s.internal.handler.ZonePlayerHandler] - Received pair 'ChannelMapSet':'RINCON_347E5C37659001400:LF,LF;RINCON_347E5C3E379601400:RF,RF' (service 'DeviceProperties') for thing 'sonos:SYMFONISK:RINCON_347E5C3E379601400'
2023-03-14 18:35:47.759 [TRACE] [s.internal.handler.ZonePlayerHandler] - Received pair 'SecureRegState':'3' (service 'DeviceProperties') for thing 'sonos:SYMFONISK:RINCON_347E5C3E379601400'
2023-03-14 18:35:47.759 [TRACE] [s.internal.handler.ZonePlayerHandler] - Received pair 'BehindWifiExtender':'0' (service 'DeviceProperties') for thing 'sonos:SYMFONISK:RINCON_347E5C3E379601400'
2023-03-14 18:35:47.759 [TRACE] [s.internal.handler.ZonePlayerHandler] - Received pair 'Invisible':'true' (service 'DeviceProperties') for thing 'sonos:SYMFONISK:RINCON_347E5C3E379601400'
2023-03-14 18:35:47.759 [TRACE] [s.internal.handler.ZonePlayerHandler] - Received pair 'AirPlayEnabled':'false' (service 'DeviceProperties') for thing 'sonos:SYMFONISK:RINCON_347E5C3E379601400'
2023-03-14 18:35:47.759 [TRACE] [s.internal.handler.ZonePlayerHandler] - Received pair 'RoomCalibrationState':'4' (service 'DeviceProperties') for thing 'sonos:SYMFONISK:RINCON_347E5C3E379601400'
2023-03-14 18:35:47.759 [TRACE] [s.internal.handler.ZonePlayerHandler] - Received pair 'WirelessMode':'0' (service 'DeviceProperties') for thing 'sonos:SYMFONISK:RINCON_347E5C3E379601400'
2023-03-14 18:35:47.759 [TRACE] [s.internal.handler.ZonePlayerHandler] - Received pair 'Orientation':'0' (service 'DeviceProperties') for thing 'sonos:SYMFONISK:RINCON_347E5C3E379601400'
2023-03-14 18:35:47.759 [TRACE] [s.internal.handler.ZonePlayerHandler] - Received pair 'WirelessLeafOnly':'false' (service 'DeviceProperties') for thing 'sonos:SYMFONISK:RINCON_347E5C3E379601400'
2023-03-14 18:35:47.759 [TRACE] [s.internal.handler.ZonePlayerHandler] - Received pair 'IsZoneBridge':'false' (service 'DeviceProperties') for thing 'sonos:SYMFONISK:RINCON_347E5C3E379601400'
2023-03-14 18:35:47.759 [TRACE] [s.internal.handler.ZonePlayerHandler] - Received pair 'SupportsAudioClip':'true' (service 'DeviceProperties') for thing 'sonos:SYMFONISK:RINCON_347E5C3E379601400'
2023-03-14 18:35:47.759 [TRACE] [s.internal.handler.ZonePlayerHandler] - Received pair 'SettingsReplicationState':'RINCON_347E5C37646001400,126,RINCON_FFFFFFFFFFFF99999,0,RINCON_347E5C37646001400,0,RINCON_347E5C37646001400,0,RINCON_347E5C3E35B401400,3702,RINCON_347E5CFEB09E01400,9,RINCON_347E5C37646001400,1018,RINCON_FFFFFFFFFFFF99999,0,RINCON_347E5C37646001400,8,RINCON_347E5C3E379601400,0,RINCON_7828CAD2861A01400,231,RINCON_7828CAD2861A01400,2821,RINCON_347E5C3E35B401400,6,RINCON_7828CAD2861A01400,21,RINCON_347E5C37646001400,0,RINCON_7828CAD2861A01400,132,RINCON_48A6B8EEAF2C01400,1447' (service 'DeviceProperties') for thing 'sonos:SYMFONISK:RINCON_347E5C3E379601400'
2023-03-14 18:35:47.760 [TRACE] [s.internal.handler.ZonePlayerHandler] - Received pair 'WifiEnabled':'true' (service 'DeviceProperties') for thing 'sonos:SYMFONISK:RINCON_347E5C3E379601400'
2023-03-14 18:35:47.760 [TRACE] [s.internal.handler.ZonePlayerHandler] - Received pair 'SupportsAudioIn':'false' (service 'DeviceProperties') for thing 'sonos:SYMFONISK:RINCON_347E5C3E379601400'
2023-03-14 18:35:47.760 [TRACE] [s.internal.handler.ZonePlayerHandler] - Received pair 'IsIdle':'true' (service 'DeviceProperties') for thing 'sonos:SYMFONISK:RINCON_347E5C3E379601400'
2023-03-14 18:35:47.760 [TRACE] [s.internal.handler.ZonePlayerHandler] - Received pair 'LastChangedPlayState':'PLAYING,UNPLAYABLE,MEMBER,' (service 'DeviceProperties') for thing 'sonos:SYMFONISK:RINCON_347E5C3E379601400'
2023-03-14 18:35:47.760 [TRACE] [s.internal.handler.ZonePlayerHandler] - Received pair 'Icon':'x-rincon-roomicon:office' (service 'DeviceProperties') for thing 'sonos:SYMFONISK:RINCON_347E5C3E379601400'
2023-03-14 18:35:48.760 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_7828CAD279FE01400: Subscription to service ContentDirectory failed
2023-03-14 18:35:51.202 [DEBUG] [overy.ZonePlayerDiscoveryParticipant] - Discovered a Sonos 'sonos:SYMFONISK' thing with UDN 'RINCON_347E5C37646001400'
2023-03-14 18:35:51.202 [INFO ] [s.internal.handler.ZonePlayerHandler] - UPnP device RINCON_347E5C37646001400 is absent (thing sonos:SYMFONISK:RINCON_347E5C37646001400)
2023-03-14 18:35:51.819 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2023-03-14 18:35:51.825 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2023-03-14 18:35:59.009 [INFO ] [s.internal.handler.ZonePlayerHandler] - UPnP device RINCON_347E5CFEAE0A01400 is present (thing sonos:SYMFONISK:RINCON_347E5CFEAE0A01400)
2023-03-14 18:35:59.009 [DEBUG] [overy.ZonePlayerDiscoveryParticipant] - Discovered a Sonos 'sonos:SYMFONISK' thing with UDN 'RINCON_347E5CFEAE0A01400'
2023-03-14 18:35:59.537 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2023-03-14 18:35:59.874 [DEBUG] [overy.ZonePlayerDiscoveryParticipant] - Created a DiscoveryResult for device '192.168.0.95 - SYMFONISK Bookshelf' with UDN 'RINCON_347E5CFEAE0A01400'
2023-03-14 18:36:00.991 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2023-03-14 18:36:01.821 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2023-03-14 18:36:01.828 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2023-03-14 18:36:09.541 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Sonos player RINCON_347E5CFEAE0A01400 is not available in local network
2023-03-14 18:36:09.542 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2023-03-14 18:36:10.993 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Sonos player RINCON_7828CAD279FE01400 is not available in local network
2023-03-14 18:36:11.825 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2023-03-14 18:36:11.831 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2023-03-14 18:36:11.890 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2023-03-14 18:36:20.970 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2023-03-14 18:36:20.971 [DEBUG] [s.internal.handler.ZonePlayerHandler] - UPnP device RINCON_347E5C37646001400 not yet registered
2023-03-14 18:36:21.826 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Sonos player RINCON_347E5C3E379601400 is not available in local network
2023-03-14 18:37:01.821 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2023-03-14 18:37:01.828 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2023-03-14 18:37:11.354 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2023-03-14 18:37:11.825 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2023-03-14 18:37:11.831 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2023-03-14 18:37:19.544 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2023-03-14 18:37:20.972 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2023-03-14 18:37:20.972 [DEBUG] [s.internal.handler.ZonePlayerHandler] - UPnP device RINCON_347E5C37646001400 not yet registered
2023-03-14 18:37:21.828 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2023-03-14 18:37:21.834 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2023-03-14 18:37:21.893 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2023-03-14 18:38:11.826 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2023-03-14 18:38:11.831 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2023-03-14 18:38:20.973 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2023-03-14 18:38:20.973 [DEBUG] [s.internal.handler.ZonePlayerHandler] - UPnP device RINCON_347E5C37646001400 not yet registered
2023-03-14 18:38:21.355 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2023-03-14 18:38:21.827 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2023-03-14 18:38:21.833 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2023-03-14 18:38:29.549 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2023-03-14 18:38:31.832 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2023-03-14 18:38:31.838 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2023-03-14 18:38:31.896 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2023-03-14 18:39:20.974 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2023-03-14 18:39:20.975 [DEBUG] [s.internal.handler.ZonePlayerHandler] - UPnP device RINCON_347E5C37646001400 not yet registered

After this the binding is polling and somehow recognizes the player - but claims that they are not registered … (loglevel ist set to trace, but after the last “real” communication only those debug messages repeat that the player is not registered).

patrik_gfeller · April 6, 2023, 7:37am

I did some more investigation on this - and the problem is related to my setup, as a downgrade of OH3 to a previous version did not resolve the problems.

However - I recently started to use docker containers to host additional services on my OH3 server (OH is not running in docker, but on the host os itself). Which changed the network configuration of the server significantly:

Most likely I face the same as reported in Isse #13077: [sonos] Multiple docker networks interfere with binding · Issue #13077 · openhab/openhab-addons · GitHub

I’ll try to learn more about network communication and upnp to see if this is something that should be handled by local configuration - or the binding itself. Any advice is appreciated of course .

with kind regards,
Patrik

arins · April 6, 2023, 7:58am

I gave an answer here: [sonos] Multiple docker networks interfere with binding · Issue #13077 · openhab/openhab-addons · GitHub

patrik_gfeller · April 11, 2023, 6:59pm

Thanks! - with the proposed workarraound it is working stable now; I’ve updated the issue with the information. I think this should be treated as a bug - or at least be mentioned in the binding docu. Let’s see if people that are deeper involved in docker, and/or sonos binding code have an opinion on this.

[sonos] Multiple docker networks interfere with binding #13077

(changed title of the discussion to better reflect the topic/issue)