[SOLVED][OH 3.1 Stable] - Sonos devices keep going offline (COMMUNICATION_ERROR)

Hi,

Just made an upgrade from 2.5 to 3.1.0 and got mostly everything working except can’t figure out why my SONOS devices keep going offline randomly.

2021-08-25 09:36:40.019 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'sonos:OneSL:SONOS_Fe_Soverom1' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR)
2021-08-25 09:36:40.025 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'sonos:PLAY1:SONOS_Fe_Soverom2' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR)
2021-08-25 09:36:40.028 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'sonos:Beam:SONOS_Fe_Stue' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR)
2021-08-25 09:36:40.037 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'sonos:PLAY1:SONOS_Fe_HovedSoverom' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR)
2021-08-25 09:37:17.549 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'sonos:Beam:SONOS_Fe_Stue' changed from OFFLINE (COMMUNICATION_ERROR) to OFFLINE (COMMUNICATION_ERROR): The UPnP device RINCON_949F3EC5A07B01400 is not yet registered.
2021-08-25 09:37:17.590 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'sonos:OneSL:SONOS_Fe_Soverom1' changed from OFFLINE (COMMUNICATION_ERROR) to OFFLINE (COMMUNICATION_ERROR): The UPnP device RINCON_48A6B811FCA201400 is not yet registered.
2021-08-25 09:37:17.781 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'sonos:PLAY1:SONOS_Fe_HovedSoverom' changed from OFFLINE (COMMUNICATION_ERROR) to OFFLINE (COMMUNICATION_ERROR): The UPnP device RINCON_5CAAFDC0C93601400 is not yet registered.
2021-08-25 09:37:17.787 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'sonos:PLAY1:SONOS_Fe_Soverom2' changed from OFFLINE (COMMUNICATION_ERROR) to OFFLINE (COMMUNICATION_ERROR): The UPnP device RINCON_B8E937E18E0401400 is not yet registered.

And they stay offline until I do a manual “SCAN” for new things through the Sonos binding in the UI, then they are online and working again for some random amount of time :thinking:

My items are defined in text but the Sonos devices (things) were discovered and added in the UI.

Anyone seen similar problems?

The only thing I found was a post about "HELP! My UPnP device isn't working right!" and other short stories - #4 by morph166955 . Tried doing the configuration changes mentioned there in services/runtime.cfg but nothing changed.

Seems this isn’t as random as I thought, 30 minutes almost exactly after the device is online it goes back to offline … :thinking:

2021-08-25 09:07:16.430 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'sonos:Beam:SONOS_Fe_Stue' changed from UNINITIALIZED to INITIALIZING
2021-08-25 09:07:17.124 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'sonos:Beam:SONOS_Fe_Stue' changed from INITIALIZING to ONLINE
2021-08-25 09:36:40.028 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'sonos:Beam:SONOS_Fe_Stue' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR)
2021-08-25 09:37:17.549 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'sonos:Beam:SONOS_Fe_Stue' changed from OFFLINE (COMMUNICATION_ERROR) to OFFLINE (COMMUNICATION_ERROR): The UPnP device RINCON_949F3EC5A07B01400 is not yet registered.
@12.15 I do a manual scan and it comes online again
2021-08-25 12:15:07.113 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'sonos:Beam:SONOS_Fe_Stue' changed from OFFLINE (COMMUNICATION_ERROR): The UPnP device RINCON_949F3EC5A07B01400 is not yet registered. to ONLINE
2021-08-25 12:45:08.282 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'sonos:Beam:SONOS_Fe_Stue' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR)
2021-08-25 12:45:18.087 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'sonos:Beam:SONOS_Fe_Stue' changed from OFFLINE (COMMUNICATION_ERROR) to OFFLINE (COMMUNICATION_ERROR): The UPnP device RINCON_949F3EC5A07B01400 is not yet registered.
And 30 minutes later it's offline 

That sounds like something is timing out and interrupting the traffic. What did you set your jupnp configs to in runtime.cfg?

org.jupnp:threadPoolSize=20
org.jupnp:asyncThreadPoolSize=20
:thinking:

Probably not much help but here’s the debug log of the Sonos binding:

2021-08-25 18:56:18.442 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2021-08-25 18:56:18.444 [DEBUG] [s.internal.handler.ZonePlayerHandler] - UPnP device RINCON_949F3EC5A07B01400 not yet registered
2021-08-25 18:56:18.496 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2021-08-25 18:56:18.500 [DEBUG] [s.internal.handler.ZonePlayerHandler] - UPnP device RINCON_48A6B811FCA201400 not yet registered
2021-08-25 18:56:18.763 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2021-08-25 18:56:18.764 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2021-08-25 18:56:18.765 [DEBUG] [s.internal.handler.ZonePlayerHandler] - UPnP device RINCON_5CAAFDC0C93601400 not yet registered
2021-08-25 18:56:18.765 [DEBUG] [s.internal.handler.ZonePlayerHandler] - UPnP device RINCON_B8E937E18E0401400 not yet registered
2021-08-25 18:56:39.838 [INFO ] [s.internal.handler.ZonePlayerHandler] - UPnP device RINCON_949F3EC5A07B01400 is present (thing sonos:Beam:SONOS_Fe_Stue)
2021-08-25 18:56:39.838 [DEBUG] [overy.ZonePlayerDiscoveryParticipant] - Discovered a Sonos 'sonos:Beam' thing with UDN 'RINCON_949F3EC5A07B01400'
2021-08-25 18:56:39.846 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2021-08-25 18:56:39.857 [DEBUG] [overy.ZonePlayerDiscoveryParticipant] - Created a DiscoveryResult for device '192.168.1.110 - Sonos Beam' with UDN 'RINCON_949F3EC5A07B01400'
2021-08-25 18:56:39.858 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3EC5A07B01400: Subscribing to service DeviceProperties...
2021-08-25 18:56:39.869 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3EC5A07B01400: Subscribing to service AVTransport...
2021-08-25 18:56:39.870 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3EC5A07B01400: Subscribing to service ZoneGroupTopology...
2021-08-25 18:56:39.876 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3EC5A07B01400: Subscribing to service GroupManagement...
2021-08-25 18:56:39.879 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3EC5A07B01400: Subscribing to service RenderingControl...
2021-08-25 18:56:39.881 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3EC5A07B01400: Subscribing to service AudioIn...
2021-08-25 18:56:39.883 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3EC5A07B01400: Subscribing to service HTControl...
2021-08-25 18:56:39.886 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3EC5A07B01400: Subscribing to service ContentDirectory...
2021-08-25 18:56:39.894 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'sonos:Beam:RINCON_949F3EC5A07B01400' to inbox.
2021-08-25 18:56:39.896 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3EC5A07B01400: Subscription to service AVTransport succeeded
2021-08-25 18:56:39.902 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3EC5A07B01400: Subscription to service DeviceProperties succeeded
2021-08-25 18:56:39.916 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3EC5A07B01400: Subscription to service RenderingControl succeeded
2021-08-25 18:56:39.925 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3EC5A07B01400: Subscription to service ZoneGroupTopology succeeded
2021-08-25 18:56:39.926 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3EC5A07B01400: Subscription to service HTControl succeeded
2021-08-25 18:56:39.936 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3EC5A07B01400: Subscription to service GroupManagement succeeded
2021-08-25 18:56:39.937 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3EC5A07B01400: Subscription to service ContentDirectory succeeded
2021-08-25 18:56:40.325 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3EC5A07B01400: Subscription to service ContentDirectory succeeded
2021-08-25 18:56:40.328 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3EC5A07B01400: Subscription to service RenderingControl succeeded
2021-08-25 18:56:40.333 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3EC5A07B01400: Subscription to service RenderingControl succeeded
2021-08-25 18:56:40.361 [DEBUG] [overy.ZonePlayerDiscoveryParticipant] - Discovered a Sonos 'sonos:OneSL' thing with UDN 'RINCON_48A6B811FCA201400'
2021-08-25 18:56:40.363 [INFO ] [s.internal.handler.ZonePlayerHandler] - UPnP device RINCON_48A6B811FCA201400 is present (thing sonos:OneSL:SONOS_Fe_Soverom1)
2021-08-25 18:56:40.368 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2021-08-25 18:56:40.388 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3EC5A07B01400: Subscription to service AVTransport succeeded
2021-08-25 18:56:40.395 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_48A6B811FCA201400: Subscription to service RenderingControl succeeded
2021-08-25 18:56:40.396 [DEBUG] [overy.ZonePlayerDiscoveryParticipant] - Created a DiscoveryResult for device '192.168.1.111 - Sonos One SL' with UDN 'RINCON_48A6B811FCA201400'
2021-08-25 18:56:40.405 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_48A6B811FCA201400: Subscription to service ContentDirectory succeeded
2021-08-25 18:56:40.421 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'sonos:OneSL:RINCON_48A6B811FCA201400' to inbox.
2021-08-25 18:56:40.461 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_48A6B811FCA201400: Subscription to service AVTransport succeeded
2021-08-25 18:56:40.465 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_48A6B811FCA201400: Subscribing to service DeviceProperties...
2021-08-25 18:56:40.469 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_48A6B811FCA201400: Subscribing to service ZoneGroupTopology...
2021-08-25 18:56:40.471 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_48A6B811FCA201400: Subscribing to service GroupManagement...
2021-08-25 18:56:40.473 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_48A6B811FCA201400: Subscribing to service AudioIn...
2021-08-25 18:56:40.477 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3EC5A07B01400: Subscription to service ContentDirectory succeeded
2021-08-25 18:56:40.477 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_48A6B811FCA201400: Subscribing to service HTControl...
2021-08-25 18:56:40.482 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_48A6B811FCA201400: Subscription to service AVTransport succeeded
2021-08-25 18:56:40.484 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_48A6B811FCA201400: Subscription to service RenderingControl succeeded
2021-08-25 18:56:40.485 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_48A6B811FCA201400: Subscription to service ContentDirectory succeeded
2021-08-25 18:56:40.498 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3EC5A07B01400: Subscription to service AVTransport succeeded
2021-08-25 18:56:40.520 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_48A6B811FCA201400: Subscription to service GroupManagement succeeded
2021-08-25 18:56:40.531 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_48A6B811FCA201400: Subscription to service DeviceProperties succeeded
2021-08-25 18:56:40.533 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_48A6B811FCA201400: Subscription to service ZoneGroupTopology succeeded
2021-08-25 18:56:40.564 [DEBUG] [overy.ZonePlayerDiscoveryParticipant] - Discovered a Sonos 'sonos:PLAY1' thing with UDN 'RINCON_5CAAFDC0C93601400'
2021-08-25 18:56:40.568 [INFO ] [s.internal.handler.ZonePlayerHandler] - UPnP device RINCON_5CAAFDC0C93601400 is present (thing sonos:PLAY1:SONOS_Fe_HovedSoverom)
2021-08-25 18:56:40.570 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2021-08-25 18:56:40.580 [INFO ] [s.internal.handler.ZonePlayerHandler] - UPnP device RINCON_B8E937E18E0401400 is present (thing sonos:PLAY1:SONOS_Fe_Soverom2)
2021-08-25 18:56:40.580 [DEBUG] [overy.ZonePlayerDiscoveryParticipant] - Discovered a Sonos 'sonos:PLAY1' thing with UDN 'RINCON_B8E937E18E0401400'
2021-08-25 18:56:40.581 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2021-08-25 18:56:40.583 [DEBUG] [overy.ZonePlayerDiscoveryParticipant] - Created a DiscoveryResult for device '192.168.1.114 - Sonos Play:1' with UDN 'RINCON_5CAAFDC0C93601400'
2021-08-25 18:56:40.591 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_5CAAFDC0C93601400: Subscribing to service DeviceProperties...
2021-08-25 18:56:40.594 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_5CAAFDC0C93601400: Subscribing to service AVTransport...
2021-08-25 18:56:40.598 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_B8E937E18E0401400: Subscribing to service DeviceProperties...
2021-08-25 18:56:40.599 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_5CAAFDC0C93601400: Subscribing to service ZoneGroupTopology...
2021-08-25 18:56:40.599 [DEBUG] [overy.ZonePlayerDiscoveryParticipant] - Created a DiscoveryResult for device '192.168.1.112 - Sonos Play:1' with UDN 'RINCON_B8E937E18E0401400'
2021-08-25 18:56:40.619 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_B8E937E18E0401400: Subscribing to service AVTransport...
2021-08-25 18:56:40.622 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_5CAAFDC0C93601400: Subscribing to service GroupManagement...
2021-08-25 18:56:40.641 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_B8E937E18E0401400: Subscribing to service ZoneGroupTopology...
2021-08-25 18:56:40.642 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_5CAAFDC0C93601400: Subscribing to service RenderingControl...
2021-08-25 18:56:40.660 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_B8E937E18E0401400: Subscribing to service GroupManagement...
2021-08-25 18:56:40.663 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_5CAAFDC0C93601400: Subscribing to service AudioIn...
2021-08-25 18:56:40.671 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'sonos:PLAY1:RINCON_5CAAFDC0C93601400' to inbox.
2021-08-25 18:56:40.687 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_B8E937E18E0401400: Subscribing to service RenderingControl...
2021-08-25 18:56:40.708 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_5CAAFDC0C93601400: Subscribing to service HTControl...
2021-08-25 18:56:40.709 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_B8E937E18E0401400: Subscribing to service AudioIn...
2021-08-25 18:56:40.720 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_5CAAFDC0C93601400: Subscribing to service ContentDirectory...
2021-08-25 18:56:40.720 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_B8E937E18E0401400: Subscribing to service HTControl...
2021-08-25 18:56:40.722 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_B8E937E18E0401400: Subscribing to service ContentDirectory...
2021-08-25 18:56:40.723 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'sonos:PLAY1:RINCON_B8E937E18E0401400' to inbox.
2021-08-25 18:56:40.729 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_5CAAFDC0C93601400: Subscription to service RenderingControl succeeded
2021-08-25 18:56:40.732 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_B8E937E18E0401400: Subscription to service DeviceProperties succeeded
2021-08-25 18:56:40.734 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_5CAAFDC0C93601400: Subscription to service GroupManagement succeeded
2021-08-25 18:56:40.735 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_5CAAFDC0C93601400: Subscription to service ZoneGroupTopology succeeded
2021-08-25 18:56:40.736 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_B8E937E18E0401400: Subscription to service AVTransport succeeded
2021-08-25 18:56:40.737 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_5CAAFDC0C93601400: Subscription to service DeviceProperties succeeded
2021-08-25 18:56:40.737 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_B8E937E18E0401400: Subscription to service ZoneGroupTopology succeeded
2021-08-25 18:56:40.740 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_5CAAFDC0C93601400: Subscription to service AVTransport succeeded
2021-08-25 18:56:40.742 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_B8E937E18E0401400: Subscription to service GroupManagement succeeded
2021-08-25 18:56:40.744 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_B8E937E18E0401400: Subscription to service RenderingControl succeeded
2021-08-25 18:56:40.747 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_B8E937E18E0401400: Subscription to service ContentDirectory succeeded
2021-08-25 18:56:40.755 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_5CAAFDC0C93601400: Subscription to service ContentDirectory succeeded
2021-08-25 18:57:18.447 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2021-08-25 18:57:18.502 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2021-08-25 18:57:18.768 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2021-08-25 18:57:18.768 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2021-08-25 18:58:18.455 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
..... more pollings jobs ....
2021-08-25 19:11:40.491 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3EC5A07B01400: Subscription to service RenderingControl succeeded
2021-08-25 19:11:40.498 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3EC5A07B01400: Subscription to service AVTransport succeeded
2021-08-25 19:11:40.499 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3EC5A07B01400: Subscription to service ContentDirectory succeeded
2021-08-25 19:11:41.570 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3EC5A07B01400: Subscription to service ContentDirectory succeeded
2021-08-25 19:11:41.580 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3EC5A07B01400: Subscription to service ContentDirectory succeeded
2021-08-25 19:11:41.591 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3EC5A07B01400: Subscription to service AVTransport succeeded
2021-08-25 19:11:41.593 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_5CAAFDC0C93601400: Subscription to service AVTransport succeeded
2021-08-25 19:11:41.595 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3EC5A07B01400: Subscription to service RenderingControl succeeded
2021-08-25 19:11:41.601 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_B8E937E18E0401400: Subscription to service AVTransport succeeded
2021-08-25 19:11:41.619 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3EC5A07B01400: Subscription to service AVTransport succeeded
2021-08-25 19:11:41.630 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_B8E937E18E0401400: Subscription to service AVTransport succeeded
2021-08-25 19:11:41.637 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_B8E937E18E0401400: Subscription to service RenderingControl succeeded
2021-08-25 19:11:41.638 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_5CAAFDC0C93601400: Subscription to service ContentDirectory succeeded
2021-08-25 19:11:41.647 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_48A6B811FCA201400: Subscription to service ContentDirectory succeeded
2021-08-25 19:11:41.661 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3EC5A07B01400: Subscription to service RenderingControl succeeded
2021-08-25 19:11:41.662 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_5CAAFDC0C93601400: Subscription to service RenderingControl succeeded
2021-08-25 19:11:41.663 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_48A6B811FCA201400: Subscription to service AVTransport succeeded
2021-08-25 19:11:41.664 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_48A6B811FCA201400: Subscription to service RenderingControl succeeded
2021-08-25 19:11:41.684 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_5CAAFDC0C93601400: Subscription to service ContentDirectory succeeded
2021-08-25 19:11:41.692 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_B8E937E18E0401400: Subscription to service RenderingControl succeeded
2021-08-25 19:11:41.692 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_5CAAFDC0C93601400: Subscription to service AVTransport succeeded
2021-08-25 19:11:41.699 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_B8E937E18E0401400: Subscription to service ContentDirectory succeeded
2021-08-25 19:11:41.705 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_5CAAFDC0C93601400: Subscription to service RenderingControl succeeded
2021-08-25 19:11:41.709 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_5CAAFDC0C93601400: Subscription to service AVTransport succeeded
SONOS_Fe_Soverom1entDirectory succeeded
2021-08-25 19:12:18.633 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2021-08-25 19:12:18.751 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
..... more pollings jobs ....
2021-08-25 19:26:41.730 [INFO ] [s.internal.handler.ZonePlayerHandler] - UPnP device RINCON_48A6B811FCA201400 is absent (thing sonos:OneSL:SONOS_Fe_Soverom1)
2021-08-25 19:26:41.730 [DEBUG] [overy.ZonePlayerDiscoveryParticipant] - Discovered a Sonos 'sonos:OneSL' thing with UDN 'RINCON_48A6B811FCA201400'
2021-08-25 19:26:41.732 [INFO ] [s.internal.handler.ZonePlayerHandler] - UPnP device RINCON_B8E937E18E0401400 is absent (thing sonos:PLAY1:SONOS_Fe_Soverom2)
2021-08-25 19:26:41.733 [DEBUG] [overy.ZonePlayerDiscoveryParticipant] - Discovered a Sonos 'sonos:PLAY1' thing with UDN 'RINCON_B8E937E18E0401400'
2021-08-25 19:26:41.734 [INFO ] [s.internal.handler.ZonePlayerHandler] - UPnP device RINCON_5CAAFDC0C93601400 is absent (thing sonos:PLAY1:SONOS_Fe_HovedSoverom)
2021-08-25 19:26:41.736 [INFO ] [s.internal.handler.ZonePlayerHandler] - UPnP device RINCON_949F3EC5A07B01400 is absent (thing sonos:Beam:SONOS_Fe_Stue)
2021-08-25 19:26:41.735 [DEBUG] [overy.ZonePlayerDiscoveryParticipant] - Discovered a Sonos 'sonos:PLAY1' thing with UDN 'RINCON_5CAAFDC0C93601400'
2021-08-25 19:26:41.739 [DEBUG] [overy.ZonePlayerDiscoveryParticipant] - Discovered a Sonos 'sonos:Beam' thing with UDN 'RINCON_949F3EC5A07B01400'
2021-08-25 19:27:18.819 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2021-08-25 19:27:18.821 [DEBUG] [s.internal.handler.ZonePlayerHandler] - UPnP device RINCON_949F3EC5A07B01400 not yet registered
2021-08-25 19:27:19.027 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2021-08-25 19:27:19.029 [DEBUG] [s.internal.handler.ZonePlayerHandler] - UPnP device RINCON_48A6B811FCA201400 not yet registered
2021-08-25 19:27:19.382 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2021-08-25 19:27:19.382 [DEBUG] [s.internal.handler.ZonePlayerHandler] - UPnP device RINCON_B8E937E18E0401400 not yet registered
2021-08-25 19:27:19.399 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2021-08-25 19:27:19.400 [DEBUG] [s.internal.handler.ZonePlayerHandler] - UPnP device RINCON_5CAAFDC0C93601400 not yet registered
2021-08-25 19:28:18.823 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2021-08-25 19:28:18.825 [DEBUG] [s.internal.handler.ZonePlayerHandler] - UPnP device RINCON_949F3EC5A07B01400 not yet registered
2021-08-25 19:28:19.032 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2021-08-25 19:28:19.034 [DEBUG] [s.internal.handler.ZonePlayerHandler] - UPnP device RINCON_48A6B811FCA201400 not yet registered
2021-08-25 19:28:19.384 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2021-08-25 19:28:19.385 [DEBUG] [s.internal.handler.ZonePlayerHandler] - UPnP device RINCON_B8E937E18E0401400 not yet registered
2021-08-25 19:28:19.401 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2021-08-25 19:28:19.403 [DEBUG] [s.internal.handler.ZonePlayerHandler] - UPnP device RINCON_5CAAFDC0C93601400 not yet registered

Are your speakers on the same subnet/vlan as your OH setup?

Yes it’s one big flat LAN :slight_smile:

Please open the karaf console and run:

bundle:list -s | grep -i upnp

And post the results.

openhab> bundle:list -s | grep -i upnp
242 x Active x  80 x 2.6.0                 x org.jupnp
244 x Active x  80 x 3.1.0                 x org.openhab.core.config.discovery.upnp
245 x Active x  80 x 3.1.0                 x org.openhab.core.io.transport.upnp

Let’s step back to make sure we’re understanding the issue completely.

When you first start OH, do the Sonos speakers come online or do you have to hit search to get it going?

How many speakers do you have?

How long does it take from first starting OH until the speakers start to fall offline?

@Lolodomo Any other ideas?

Did a clean boot now, here’s how it goes:

2021-08-26 16:08:31.471 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'sonos:Beam:SONOS_Fe_Stue' changed from INITIALIZING to ONLINE
2021-08-26 16:08:31.718 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'SONOS_Volume_Fe_Stue_Vegg' changed from 11 to 9
... 30 minutes ...
2021-08-26 16:37:55.599 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'sonos:Beam:SONOS_Fe_Stue' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR)
2021-08-26 16:38:31.602 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'sonos:Beam:SONOS_Fe_Stue' changed from OFFLINE (COMMUNICATION_ERROR) to OFFLINE (COMMUNICATION_ERROR): The UPnP device RINCON_949F3EC5A07B01400 is not yet registered.

Also the upnp boot log:

2021-08-26 16:07:49.525 [INFO ] [g.jupnp.OSGiUpnpServiceConfiguration] - OSGiUpnpServiceConfiguration createConfiguration threadPoolSize = 20 true
2021-08-26 16:07:49.527 [INFO ] [g.jupnp.OSGiUpnpServiceConfiguration] - OSGiUpnpServiceConfiguration createConfiguration asyncThreadPoolSize = 20 true
2021-08-26 16:07:49.530 [INFO ] [g.jupnp.OSGiUpnpServiceConfiguration] - OSGiUpnpServiceConfiguration retryAfterSeconds = 600
2021-08-26 16:07:49.532 [INFO ] [g.jupnp.OSGiUpnpServiceConfiguration] - OSGiUpnpServiceConfiguration retryIterations = 5
2021-08-26 16:07:49.534 [INFO ] [g.jupnp.OSGiUpnpServiceConfiguration] - OSGiUpnpServiceConfiguration timeoutSeconds = 10

Thanks for helping, appreciated! :slight_smile:

My recent readings in the forum for similar problem were users running OH in docker with a wrong docker network setup (sorry I am not a docker specialist). Are you running docker image?

No, it’s running “dedicated” on a RPI4, Raspbian 10 (buster) with openjdk 11.0.12.

Oh and I have 5 speakers, 4xPlay1’s and 1xBeam. All connected to the same LAN.

In this case, you are in a very common case, similar to mine for example. It always worked for me. So sorry, I have no clever idea except enabling binding DEBUG logs to check if something could help.

I think I’ve figured it out. I had too restrictive iptables rules that blocked LAN broadcast for SSDP (UPNP) to 239.255.255.250. I’ve fixed this and so far everything is working :slight_smile:

1 Like

Yup that will do it. Glad to hear it’s working!

1 Like

I had the same problem. It was literally just a case of going to the router config and enabling uPnP.