All Sonos things flapping every minute

Add-ons Bindings
1

Recently, although I can’t say exactly when, all of my sonos speaker things have started going offline for a brief moment and then coming back online again every minute. The logs for one cycle of one of the speakers look like this

openhab.log (org.openhab.binding.sonos log level DEBUG)

2023-04-02 09:31:56.045 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3E89854601400: Subscription to service RenderingControl succeeded
2023-04-02 09:31:56.056 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3E89854601400: Subscription to service AVTransport succeeded
2023-04-02 09:31:56.075 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3E89854601400: Subscription to service ContentDirectory succeeded
2023-04-02 09:32:08.060 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3E89854601400: Subscription to service RenderingControl succeeded
2023-04-02 09:32:08.067 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3E89854601400: Subscription to service AVTransport succeeded
2023-04-02 09:32:08.069 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3E89854601400: Subscription to service ContentDirectory succeeded
2023-04-02 09:32:18.056 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3E89854601400: Subscription to service ContentDirectory succeeded
2023-04-02 09:32:18.056 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3E89854601400: Subscription to service RenderingControl succeeded
2023-04-02 09:32:19.121 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3E89854601400: Subscription to service AVTransport succeeded
2023-04-02 09:32:28.120 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2023-04-02 09:32:32.051 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3E89854601400: Subscription to service RenderingControl succeeded
2023-04-02 09:32:32.051 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3E89854601400: Subscription to service AVTransport succeeded
2023-04-02 09:32:32.077 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3E89854601400: Subscription to service ContentDirectory succeeded
2023-04-02 09:32:36.943 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2023-04-02 09:32:37.702 [INFO ] [s.internal.handler.ZonePlayerHandler] - UPnP device RINCON_949F3E89854601400 is absent (thing sonos:PLAY1:RINCON_949F3E89854601400)
2023-04-02 09:32:37.703 [DEBUG] [overy.ZonePlayerDiscoveryParticipant] - Discovered a Sonos 'sonos:PLAY1' thing with UDN 'RINCON_949F3E89854601400'
2023-04-02 09:32:39.033 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2023-04-02 09:32:39.120 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2023-04-02 09:32:40.017 [INFO ] [s.internal.handler.ZonePlayerHandler] - UPnP device RINCON_949F3E89854601400 is present (thing sonos:PLAY1:RINCON_949F3E89854601400)
2023-04-02 09:32:40.017 [DEBUG] [overy.ZonePlayerDiscoveryParticipant] - Discovered a Sonos 'sonos:PLAY1' thing with UDN 'RINCON_949F3E89854601400'
2023-04-02 09:32:40.017 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2023-04-02 09:32:40.027 [DEBUG] [s.internal.handler.ZonePlayerHandler] - Polling job
2023-04-02 09:32:41.073 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3E89854601400: Subscription to service ContentDirectory succeeded
2023-04-02 09:32:44.061 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3E89854601400: Subscription to service ContentDirectory succeeded
2023-04-02 09:32:44.065 [DEBUG] [s.internal.handler.ZonePlayerHandler] - RINCON_949F3E89854601400: Subscription to service RenderingControl succeeded

events.log

2023-04-02 09:32:37.702 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'sonos:PLAY1:RINCON_949F3E89854601400' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR)
2023-04-02 09:32:40.019 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'sonos:PLAY1:RINCON_949F3E89854601400' changed from OFFLINE (COMMUNICATION_ERROR) to ONLINE

OH is running in a docker container (network: host) on an ubuntu server. It appears to have started while I was on 4.1M1, but not immediately upon updating to that version. I’ve updated to snapshot #3392 and the problem still persists. I did update the server from 20.04 to 22.04 two weeks ago which might correspond to when the problem started, but I can only say that I know the problem was occurring as of a few days ago when the first obvious symptom of a failed rule involving a sonos thing was reported to me.

I have had adjusted jupnp settings as recommended for sonos speakers for a long time now and the connections have been very solid with these settings:

org.jupnp:threadPoolSize=25
org.jupnp:asyncThreadPoolSize=25
org.jupnp:retryAfterSeconds=300
org.jupnp:retryIterations=8
org.jupnp:timeoutSeconds=15

Anyone seen anything like this?

2

How many speakers do you have? What happens if you set the two pools to -1 (you need to do this with OH stopped)?

3

I’ve got 8 speakers.

That doesn’t appear to change anything. I’m seeing the same flapping still.

4

Are they on the same subnet/vlan?

5

Yes, they always have been. That hasn’t changed.

I also should have mentioned that I do not have automatic updates enabled for the Sonos system and did not run a manual update between the last known working point and now. So, as far as I know, nothing about the speakers themselves has changed.

6

Gotcha. I have about the same setup. My OH is running in a docker on my NAS. I haven’t seen any issues here. I’m on snapshot 3382 currently. It sounds like you’re getting a timeout hit in JuPnP. You may want to enable debug logging on org.jupnp and see if you find anything relevant. Fair warning, it will be a lot of messages.

7

Here’s the section of the jupnp debug that, as far as I can tell, shows the problem:

2023-04-02 18:14:17.033 [DEBUG] [upnp.transport.spi.MulticastReceiver] - UDP datagram received from: 192.168.1.1:42804 on local interface: enp5s0 and address: 192.168.1.105
2023-04-02 18:14:17.034 [DEBUG] [org.jupnp.transport.Router          ] - Received asynchronous message: (IncomingDatagramMessage) NOTIFY
2023-04-02 18:14:17.034 [DEBUG] [upnp.transport.spi.MulticastReceiver] - UDP datagram received from: 192.168.1.1:42804 on local interface: enp5s0 and address: 192.168.1.105
2023-04-02 18:14:17.034 [DEBUG] [org.jupnp.transport.Router          ] - Received asynchronous message: (IncomingDatagramMessage) NOTIFY
2023-04-02 18:14:17.035 [DEBUG] [upnp.transport.spi.MulticastReceiver] - UDP datagram received from: 192.168.1.1:42804 on local interface: enp5s0 and address: 192.168.1.105
2023-04-02 18:14:17.035 [DEBUG] [org.jupnp.transport.Router          ] - Received asynchronous message: (IncomingDatagramMessage) NOTIFY
2023-04-02 18:14:17.036 [DEBUG] [upnp.transport.spi.MulticastReceiver] - UDP datagram received from: 192.168.1.1:42804 on local interface: enp5s0 and address: 192.168.1.105
2023-04-02 18:14:17.036 [DEBUG] [org.jupnp.transport.Router          ] - Received asynchronous message: (IncomingDatagramMessage) NOTIFY
2023-04-02 18:14:17.038 [DEBUG] [upnp.transport.spi.MulticastReceiver] - UDP datagram received from: 192.168.1.1:42804 on local interface: enp5s0 and address: 192.168.1.105
2023-04-02 18:14:17.038 [DEBUG] [org.jupnp.transport.Router          ] - Received asynchronous message: (IncomingDatagramMessage) NOTIFY
2023-04-02 18:14:17.039 [DEBUG] [upnp.transport.spi.MulticastReceiver] - UDP datagram received from: 192.168.1.1:42804 on local interface: enp5s0 and address: 192.168.1.105
2023-04-02 18:14:17.039 [DEBUG] [org.jupnp.transport.Router          ] - Received asynchronous message: (IncomingDatagramMessage) NOTIFY
2023-04-02 18:14:17.046 [DEBUG] [upnp.transport.spi.MulticastReceiver] - UDP datagram received from: 192.168.1.1:42804 on local interface: enp5s0 and address: 192.168.1.105
2023-04-02 18:14:17.046 [DEBUG] [org.jupnp.transport.Router          ] - Received asynchronous message: (IncomingDatagramMessage) NOTIFY
2023-04-02 18:14:17.047 [DEBUG] [upnp.transport.spi.MulticastReceiver] - UDP datagram received from: 192.168.1.1:42804 on local interface: enp5s0 and address: 192.168.1.105
2023-04-02 18:14:17.047 [DEBUG] [org.jupnp.transport.Router          ] - Received asynchronous message: (IncomingDatagramMessage) NOTIFY
2023-04-02 18:14:17.048 [DEBUG] [upnp.transport.spi.MulticastReceiver] - UDP datagram received from: 192.168.1.1:42804 on local interface: enp5s0 and address: 192.168.1.105
2023-04-02 18:14:17.048 [DEBUG] [org.jupnp.transport.Router          ] - Received asynchronous message: (IncomingDatagramMessage) NOTIFY
2023-04-02 18:14:17.048 [DEBUG] [upnp.transport.spi.MulticastReceiver] - UDP datagram received from: 192.168.1.1:42804 on local interface: enp5s0 and address: 192.168.1.105
2023-04-02 18:14:17.048 [DEBUG] [org.jupnp.transport.Router          ] - Received asynchronous message: (IncomingDatagramMessage) NOTIFY
2023-04-02 18:14:17.049 [DEBUG] [upnp.transport.spi.MulticastReceiver] - UDP datagram received from: 192.168.1.1:42804 on local interface: enp5s0 and address: 192.168.1.105
2023-04-02 18:14:17.049 [DEBUG] [org.jupnp.transport.Router          ] - Received asynchronous message: (IncomingDatagramMessage) NOTIFY
2023-04-02 18:14:17.285 [DEBUG] [upnp.transport.spi.MulticastReceiver] - UDP datagram received from: 192.168.1.1:42804 on local interface: enp5s0 and address: 192.168.1.105
2023-04-02 18:14:17.286 [DEBUG] [org.jupnp.transport.Router          ] - Received asynchronous message: (IncomingDatagramMessage) NOTIFY
2023-04-02 18:14:17.286 [DEBUG] [upnp.transport.spi.MulticastReceiver] - UDP datagram received from: 192.168.1.1:42804 on local interface: enp5s0 and address: 192.168.1.105
2023-04-02 18:14:17.286 [DEBUG] [org.jupnp.transport.Router          ] - Received asynchronous message: (IncomingDatagramMessage) NOTIFY
2023-04-02 18:14:17.286 [DEBUG] [upnp.transport.spi.MulticastReceiver] - UDP datagram received from: 192.168.1.1:42804 on local interface: enp5s0 and address: 192.168.1.105
2023-04-02 18:14:17.287 [DEBUG] [org.jupnp.transport.Router          ] - Received asynchronous message: (IncomingDatagramMessage) NOTIFY
2023-04-02 18:14:17.287 [DEBUG] [upnp.transport.spi.MulticastReceiver] - UDP datagram received from: 192.168.1.1:42804 on local interface: enp5s0 and address: 192.168.1.105
2023-04-02 18:14:17.287 [DEBUG] [org.jupnp.transport.Router          ] - Received asynchronous message: (IncomingDatagramMessage) NOTIFY
2023-04-02 18:14:17.287 [DEBUG] [upnp.transport.spi.MulticastReceiver] - UDP datagram received from: 192.168.1.1:42804 on local interface: enp5s0 and address: 192.168.1.105
2023-04-02 18:14:17.287 [DEBUG] [org.jupnp.transport.Router          ] - Received asynchronous message: (IncomingDatagramMessage) NOTIFY
2023-04-02 18:14:17.291 [DEBUG] [upnp.transport.spi.MulticastReceiver] - UDP datagram received from: 192.168.1.1:42804 on local interface: enp5s0 and address: 192.168.1.105
2023-04-02 18:14:17.291 [DEBUG] [org.jupnp.transport.Router          ] - Received asynchronous message: (IncomingDatagramMessage) NOTIFY
2023-04-02 18:14:17.294 [DEBUG] [upnp.transport.spi.MulticastReceiver] - UDP datagram received from: 192.168.1.1:42804 on local interface: enp5s0 and address: 192.168.1.105
2023-04-02 18:14:17.294 [DEBUG] [org.jupnp.transport.Router          ] - Received asynchronous message: (IncomingDatagramMessage) NOTIFY
2023-04-02 18:14:17.295 [DEBUG] [upnp.transport.spi.MulticastReceiver] - UDP datagram received from: 192.168.1.1:42804 on local interface: enp5s0 and address: 192.168.1.105
2023-04-02 18:14:17.295 [DEBUG] [org.jupnp.transport.Router          ] - Received asynchronous message: (IncomingDatagramMessage) NOTIFY
2023-04-02 18:14:17.299 [DEBUG] [upnp.transport.spi.MulticastReceiver] - UDP datagram received from: 192.168.1.1:42804 on local interface: enp5s0 and address: 192.168.1.105
2023-04-02 18:14:17.299 [DEBUG] [org.jupnp.transport.Router          ] - Received asynchronous message: (IncomingDatagramMessage) NOTIFY
2023-04-02 18:14:17.299 [DEBUG] [upnp.transport.spi.MulticastReceiver] - UDP datagram received from: 192.168.1.1:42804 on local interface: enp5s0 and address: 192.168.1.105
2023-04-02 18:14:17.300 [DEBUG] [org.jupnp.transport.Router          ] - Received asynchronous message: (IncomingDatagramMessage) NOTIFY
2023-04-02 18:14:17.300 [DEBUG] [upnp.transport.spi.MulticastReceiver] - UDP datagram received from: 192.168.1.1:42804 on local interface: enp5s0 and address: 192.168.1.105
2023-04-02 18:14:17.300 [DEBUG] [org.jupnp.transport.Router          ] - Received asynchronous message: (IncomingDatagramMessage) NOTIFY
2023-04-02 18:14:17.550 [DEBUG] [org.jupnp.transport.Router          ] - Sending via TCP unicast stream: (OutgoingActionRequestMessage) POST http://192.168.1.18:1400/DeviceProperties/Control
2023-04-02 18:14:18.419 [DEBUG] [org.jupnp.transport.Router          ] - Sending via TCP unicast stream: (OutgoingActionRequestMessage) POST http://192.168.1.41:1400/DeviceProperties/Control
2023-04-02 18:14:18.829 [DEBUG] [org.jupnp.transport.Router          ] - Sending via TCP unicast stream: (OutgoingActionRequestMessage) POST http://192.168.1.132:1400/DeviceProperties/Control
2023-04-02 18:14:23.067 [DEBUG] [org.jupnp.transport.Router          ] - Sending via TCP unicast stream: (OutgoingActionRequestMessage) POST http://192.168.1.17:1400/DeviceProperties/Control
2023-04-02 18:14:24.105 [DEBUG] [upnp.transport.spi.MulticastReceiver] - UDP datagram received from: 169.254.221.238:49361 on local interface: veth0fffc8d and address: 169.254.155.67
2023-04-02 18:14:24.105 [DEBUG] [upnp.transport.spi.MulticastReceiver] - UDP datagram received from: 169.254.85.236:55625 on local interface: vethac53f5d and address: 169.254.155.67
2023-04-02 18:14:24.105 [DEBUG] [upnp.transport.spi.MulticastReceiver] - UDP datagram received from: 169.254.155.67:35740 on local interface: veth66a1bab and address: 169.254.155.67
2023-04-02 18:14:24.105 [DEBUG] [upnp.transport.spi.MulticastReceiver] - UDP datagram received from: 169.254.199.104:54524 on local interface: veth73c8cd2 and address: 169.254.155.67
2023-04-02 18:14:24.105 [DEBUG] [org.jupnp.transport.Router          ] - Received asynchronous message: (IncomingDatagramMessage) M-SEARCH
2023-04-02 18:14:24.105 [DEBUG] [org.jupnp.transport.Router          ] - Received asynchronous message: (IncomingDatagramMessage) M-SEARCH
2023-04-02 18:14:24.105 [DEBUG] [upnp.transport.spi.MulticastReceiver] - UDP datagram received from: 169.254.131.88:52377 on local interface: veth8437ba6 and address: 169.254.155.67
2023-04-02 18:14:24.105 [DEBUG] [org.jupnp.transport.Router          ] - Received asynchronous message: (IncomingDatagramMessage) M-SEARCH
2023-04-02 18:14:24.105 [DEBUG] [upnp.transport.spi.MulticastReceiver] - UDP datagram received from: 192.168.1.105:37788 on local interface: enp5s0 and address: 192.168.1.105
2023-04-02 18:14:24.106 [DEBUG] [org.jupnp.transport.Router          ] - Received asynchronous message: (IncomingDatagramMessage) M-SEARCH
2023-04-02 18:14:24.106 [DEBUG] [org.jupnp.transport.Router          ] - Received asynchronous message: (IncomingDatagramMessage) M-SEARCH
2023-04-02 18:14:24.105 [DEBUG] [org.jupnp.transport.Router          ] - Received asynchronous message: (IncomingDatagramMessage) M-SEARCH
2023-04-02 18:14:24.107 [DEBUG] [upnp.transport.spi.MulticastReceiver] - UDP datagram received from: 169.254.54.176:48093 on local interface: enp5s0 and address: 169.254.155.67
2023-04-02 18:14:24.107 [DEBUG] [org.jupnp.transport.Router          ] - Received asynchronous message: (IncomingDatagramMessage) M-SEARCH
2023-04-02 18:14:26.416 [DEBUG] [org.jupnp.transport.Router          ] - Sending via TCP unicast stream: (OutgoingRenewalRequestMessage) SUBSCRIBE http://192.168.1.41:1400/MediaRenderer/RenderingControl/Event
2023-04-02 18:14:26.416 [DEBUG] [org.jupnp.transport.Router          ] - Sending via TCP unicast stream: (OutgoingRenewalRequestMessage) SUBSCRIBE http://192.168.1.18:1400/MediaRenderer/AVTransport/Event
2023-04-02 18:14:26.416 [DEBUG] [org.jupnp.transport.Router          ] - Sending via TCP unicast stream: (OutgoingRenewalRequestMessage) SUBSCRIBE http://192.168.1.41:1400/MediaRenderer/AVTransport/Event
2023-04-02 18:14:26.423 [DEBUG] [org.jupnp.transport.Router          ] - Sending via TCP unicast stream: (OutgoingSubscribeRequestMessage) SUBSCRIBE http://192.168.1.18:1400/MediaRenderer/AVTransport/Event
2023-04-02 18:14:26.423 [DEBUG] [org.jupnp.transport.Router          ] - Sending via TCP unicast stream: (OutgoingSubscribeRequestMessage) SUBSCRIBE http://192.168.1.41:1400/MediaRenderer/AVTransport/Event
2023-04-02 18:14:26.424 [DEBUG] [org.jupnp.transport.Router          ] - Sending via TCP unicast stream: (OutgoingSubscribeRequestMessage) SUBSCRIBE http://192.168.1.41:1400/MediaRenderer/RenderingControl/Event
2023-04-02 18:14:26.442 [INFO ] [np.transport.impl.async.AsyncServlet] - HttpServlet.service(): id:   0, request URI: /upnpcallback/dev/RINCON_7828CAAEE2FC01400_MR/svc/upnp-org/AVTransport/event/cb
2023-04-02 18:14:26.442 [DEBUG] [np.transport.impl.async.AsyncServlet] - Handling Servlet request asynchronously: org.ops4j.pax.web.service.spi.servlet.OsgiHttpServletRequestWrapper@36dc5017
2023-04-02 18:14:26.442 [DEBUG] [org.jupnp.transport.Router          ] - Received synchronous stream: 855248641
2023-04-02 18:14:26.443 [INFO ] [np.transport.impl.async.AsyncServlet] - HttpServlet.service(): id:   1, request URI: /upnpcallback/dev/RINCON_7828CAABC74601400_MR/svc/upnp-org/AVTransport/event/cb
2023-04-02 18:14:26.443 [DEBUG] [np.transport.impl.async.AsyncServlet] - Handling Servlet request asynchronously: org.ops4j.pax.web.service.spi.servlet.OsgiHttpServletRequestWrapper@6dca47a3
2023-04-02 18:14:26.443 [DEBUG] [np.transport.impl.async.AsyncServlet] - AsyncListener.onComplete(): id:   0, duration:    1, response: HTTP/1.1 200 
Connection: close
Content-Type: text/xml
Date: Mon, 03 Apr 2023 01:14:26 GMT


2023-04-02 18:14:26.444 [DEBUG] [org.jupnp.transport.Router          ] - Received synchronous stream: 1780789212
2023-04-02 18:14:26.455 [DEBUG] [np.transport.impl.async.AsyncServlet] - AsyncListener.onComplete(): id:   1, duration:   12, response: HTTP/1.1 200 
Connection: close
Content-Type: text/xml
Date: Mon, 03 Apr 2023 01:14:26 GMT


2023-04-02 18:14:26.466 [INFO ] [np.transport.impl.async.AsyncServlet] - HttpServlet.service(): id:   2, request URI: /upnpcallback/dev/RINCON_7828CAABC74601400_MR/svc/upnp-org/RenderingControl/event/cb
2023-04-02 18:14:26.466 [DEBUG] [np.transport.impl.async.AsyncServlet] - Handling Servlet request asynchronously: org.ops4j.pax.web.service.spi.servlet.OsgiHttpServletRequestWrapper@d5453f4
2023-04-02 18:14:26.466 [DEBUG] [org.jupnp.transport.Router          ] - Received synchronous stream: 1865733976
2023-04-02 18:14:26.468 [DEBUG] [np.transport.impl.async.AsyncServlet] - AsyncListener.onComplete(): id:   2, duration:    2, response: HTTP/1.1 200 
Connection: close
Content-Type: text/xml
Date: Mon, 03 Apr 2023 01:14:26 GMT


2023-04-02 18:14:27.417 [DEBUG] [org.jupnp.transport.Router          ] - Sending via TCP unicast stream: (OutgoingRenewalRequestMessage) SUBSCRIBE http://192.168.1.18:1400/MediaRenderer/RenderingControl/Event
2023-04-02 18:14:27.417 [DEBUG] [org.jupnp.transport.Router          ] - Sending via TCP unicast stream: (OutgoingRenewalRequestMessage) SUBSCRIBE http://192.168.1.132:1400/MediaServer/ContentDirectory/Event
2023-04-02 18:14:27.417 [DEBUG] [org.jupnp.transport.Router          ] - Sending via TCP unicast stream: (OutgoingRenewalRequestMessage) SUBSCRIBE http://192.168.1.41:1400/MediaServer/ContentDirectory/Event
2023-04-02 18:14:27.418 [DEBUG] [org.jupnp.transport.Router          ] - Sending via TCP unicast stream: (OutgoingRenewalRequestMessage) SUBSCRIBE http://192.168.1.18:1400/MediaServer/ContentDirectory/Event
2023-04-02 18:14:27.418 [DEBUG] [org.jupnp.transport.Router          ] - Sending via TCP unicast stream: (OutgoingRenewalRequestMessage) SUBSCRIBE http://192.168.1.151:1400/MediaServer/ContentDirectory/Event
2023-04-02 18:14:27.418 [DEBUG] [org.jupnp.transport.Router          ] - Sending via TCP unicast stream: (OutgoingRenewalRequestMessage) SUBSCRIBE http://192.168.1.151:1400/MediaRenderer/RenderingControl/Event
2023-04-02 18:14:27.418 [DEBUG] [org.jupnp.transport.Router          ] - Sending via TCP unicast stream: (OutgoingRenewalRequestMessage) SUBSCRIBE http://192.168.1.132:1400/MediaRenderer/RenderingControl/Event
2023-04-02 18:14:27.419 [DEBUG] [org.jupnp.transport.Router          ] - Sending via TCP unicast stream: (OutgoingRenewalRequestMessage) SUBSCRIBE http://192.168.1.132:1400/MediaRenderer/AVTransport/Event
2023-04-02 18:14:27.419 [DEBUG] [org.jupnp.transport.Router          ] - Sending via TCP unicast stream: (OutgoingRenewalRequestMessage) SUBSCRIBE http://192.168.1.151:1400/MediaRenderer/AVTransport/Event
2023-04-02 18:14:27.423 [DEBUG] [org.jupnp.transport.Router          ] - Sending via TCP unicast stream: (OutgoingSubscribeRequestMessage) SUBSCRIBE http://192.168.1.18:1400/MediaRenderer/RenderingControl/Event
2023-04-02 18:14:27.427 [DEBUG] [org.jupnp.transport.Router          ] - Sending via TCP unicast stream: (OutgoingSubscribeRequestMessage) SUBSCRIBE http://192.168.1.132:1400/MediaServer/ContentDirectory/Event
2023-04-02 18:14:27.430 [DEBUG] [org.jupnp.transport.Router          ] - Sending via TCP unicast stream: (OutgoingSubscribeRequestMessage) SUBSCRIBE http://192.168.1.41:1400/MediaServer/ContentDirectory/Event
2023-04-02 18:14:27.431 [DEBUG] [org.jupnp.transport.Router          ] - Sending via TCP unicast stream: (OutgoingSubscribeRequestMessage) SUBSCRIBE http://192.168.1.151:1400/MediaServer/ContentDirectory/Event
2023-04-02 18:14:27.432 [DEBUG] [org.jupnp.transport.Router          ] - Sending via TCP unicast stream: (OutgoingSubscribeRequestMessage) SUBSCRIBE http://192.168.1.151:1400/MediaRenderer/RenderingControl/Event
2023-04-02 18:14:27.433 [DEBUG] [org.jupnp.transport.Router          ] - Sending via TCP unicast stream: (OutgoingSubscribeRequestMessage) SUBSCRIBE http://192.168.1.18:1400/MediaServer/ContentDirectory/Event
2023-04-02 18:14:27.434 [DEBUG] [org.jupnp.transport.Router          ] - Sending via TCP unicast stream: (OutgoingSubscribeRequestMessage) SUBSCRIBE http://192.168.1.132:1400/MediaRenderer/RenderingControl/Event
2023-04-02 18:14:27.446 [DEBUG] [org.jupnp.transport.Router          ] - Sending via TCP unicast stream: (OutgoingSubscribeRequestMessage) SUBSCRIBE http://192.168.1.132:1400/MediaRenderer/AVTransport/Event
2023-04-02 18:14:27.449 [DEBUG] [org.jupnp.transport.Router          ] - Sending via TCP unicast stream: (OutgoingSubscribeRequestMessage) SUBSCRIBE http://192.168.1.151:1400/MediaRenderer/AVTransport/Event
2023-04-02 18:14:27.463 [INFO ] [np.transport.impl.async.AsyncServlet] - HttpServlet.service(): id:   3, request URI: /upnpcallback/dev/RINCON_7828CAABC74601400_MS/svc/upnp-org/ContentDirectory/event/cb
2023-04-02 18:14:27.463 [DEBUG] [np.transport.impl.async.AsyncServlet] - Handling Servlet request asynchronously: org.ops4j.pax.web.service.spi.servlet.OsgiHttpServletRequestWrapper@40f7df0a
2023-04-02 18:14:27.463 [DEBUG] [org.jupnp.transport.Router          ] - Received synchronous stream: 759607854
2023-04-02 18:14:27.464 [DEBUG] [pnp.transport.spi.GENAEventProcessor] - Value RINCON_38420B14A8AC01400,84 for the state variable RadioFavoritesUpdateID ignored: Can't convert string to number or not in range: RINCON_38420B14A8AC01400,84
2023-04-02 18:14:27.464 [DEBUG] [pnp.transport.spi.GENAEventProcessor] - Value RINCON_38420B14A8AC01400,515 for the state variable RadioLocationUpdateID ignored: Can't convert string to number or not in range: RINCON_38420B14A8AC01400,515
2023-04-02 18:14:27.465 [DEBUG] [np.transport.impl.async.AsyncServlet] - AsyncListener.onComplete(): id:   3, duration:    2, response: HTTP/1.1 200 
Connection: close
Content-Type: text/xml
Date: Mon, 03 Apr 2023 01:14:27 GMT


2023-04-02 18:14:27.465 [INFO ] [np.transport.impl.async.AsyncServlet] - HttpServlet.service(): id:   4, request URI: /upnpcallback/dev/RINCON_7828CAAEE2FC01400_MR/svc/upnp-org/RenderingControl/event/cb
2023-04-02 18:14:27.466 [DEBUG] [np.transport.impl.async.AsyncServlet] - Handling Servlet request asynchronously: org.ops4j.pax.web.service.spi.servlet.OsgiHttpServletRequestWrapper@23cf8087
2023-04-02 18:14:27.466 [DEBUG] [org.jupnp.transport.Router          ] - Received synchronous stream: 1778912689
2023-04-02 18:14:27.467 [DEBUG] [np.transport.impl.async.AsyncServlet] - AsyncListener.onComplete(): id:   4, duration:    2, response: HTTP/1.1 200 
Connection: close
Content-Type: text/xml
Date: Mon, 03 Apr 2023 01:14:27 GMT


2023-04-02 18:14:27.468 [INFO ] [np.transport.impl.async.AsyncServlet] - HttpServlet.service(): id:   5, request URI: /upnpcallback/dev/RINCON_949F3E89854601400_MS/svc/upnp-org/ContentDirectory/event/cb
2023-04-02 18:14:27.469 [DEBUG] [np.transport.impl.async.AsyncServlet] - Handling Servlet request asynchronously: org.ops4j.pax.web.service.spi.servlet.OsgiHttpServletRequestWrapper@380febf1
2023-04-02 18:14:27.469 [DEBUG] [org.jupnp.transport.Router          ] - Received synchronous stream: 2006640995
2023-04-02 18:14:27.470 [DEBUG] [pnp.transport.spi.GENAEventProcessor] - Value RINCON_38420B14A8AC01400,84 for the state variable RadioFavoritesUpdateID ignored: Can't convert string to number or not in range: RINCON_38420B14A8AC01400,84
2023-04-02 18:14:27.470 [DEBUG] [pnp.transport.spi.GENAEventProcessor] - Value RINCON_38420B14A8AC01400,515 for the state variable RadioLocationUpdateID ignored: Can't convert string to number or not in range: RINCON_38420B14A8AC01400,515
2023-04-02 18:14:27.470 [DEBUG] [np.transport.impl.async.AsyncServlet] - AsyncListener.onComplete(): id:   5, duration:    2, response: HTTP/1.1 200 
Connection: close
Content-Type: text/xml
Date: Mon, 03 Apr 2023 01:14:27 GMT


2023-04-02 18:14:27.490 [INFO ] [np.transport.impl.async.AsyncServlet] - HttpServlet.service(): id:   6, request URI: /upnpcallback/dev/RINCON_5CAAFD5BA47001400_MS/svc/upnp-org/ContentDirectory/event/cb
2023-04-02 18:14:27.490 [DEBUG] [np.transport.impl.async.AsyncServlet] - Handling Servlet request asynchronously: org.ops4j.pax.web.service.spi.servlet.OsgiHttpServletRequestWrapper@1103dd7f
2023-04-02 18:14:27.491 [DEBUG] [org.jupnp.transport.Router          ] - Received synchronous stream: 1003241323
2023-04-02 18:14:27.491 [DEBUG] [pnp.transport.spi.GENAEventProcessor] - Value RINCON_38420B14A8AC01400,84 for the state variable RadioFavoritesUpdateID ignored: Can't convert string to number or not in range: RINCON_38420B14A8AC01400,84
2023-04-02 18:14:27.492 [DEBUG] [pnp.transport.spi.GENAEventProcessor] - Value RINCON_38420B14A8AC01400,515 for the state variable RadioLocationUpdateID ignored: Can't convert string to number or not in range: RINCON_38420B14A8AC01400,515
2023-04-02 18:14:27.492 [DEBUG] [np.transport.impl.async.AsyncServlet] - AsyncListener.onComplete(): id:   6, duration:    2, response: HTTP/1.1 200 
Connection: close
Content-Type: text/xml
Date: Mon, 03 Apr 2023 01:14:27 GMT


2023-04-02 18:14:27.496 [INFO ] [np.transport.impl.async.AsyncServlet] - HttpServlet.service(): id:   7, request URI: /upnpcallback/dev/RINCON_7828CAAEE2FC01400_MS/svc/upnp-org/ContentDirectory/event/cb
2023-04-02 18:14:27.497 [DEBUG] [np.transport.impl.async.AsyncServlet] - Handling Servlet request asynchronously: org.ops4j.pax.web.service.spi.servlet.OsgiHttpServletRequestWrapper@28377863
2023-04-02 18:14:27.498 [DEBUG] [org.jupnp.transport.Router          ] - Received synchronous stream: 88075216
2023-04-02 18:14:27.499 [DEBUG] [pnp.transport.spi.GENAEventProcessor] - Value RINCON_38420B14A8AC01400,84 for the state variable RadioFavoritesUpdateID ignored: Can't convert string to number or not in range: RINCON_38420B14A8AC01400,84
2023-04-02 18:14:27.499 [DEBUG] [pnp.transport.spi.GENAEventProcessor] - Value RINCON_38420B14A8AC01400,515 for the state variable RadioLocationUpdateID ignored: Can't convert string to number or not in range: RINCON_38420B14A8AC01400,515
2023-04-02 18:14:27.500 [DEBUG] [np.transport.impl.async.AsyncServlet] - AsyncListener.onComplete(): id:   7, duration:    4, response: HTTP/1.1 200 
Connection: close
Content-Type: text/xml
Date: Mon, 03 Apr 2023 01:14:27 GMT


2023-04-02 18:14:27.501 [INFO ] [np.transport.impl.async.AsyncServlet] - HttpServlet.service(): id:   8, request URI: /upnpcallback/dev/RINCON_949F3E89854601400_MR/svc/upnp-org/AVTransport/event/cb
2023-04-02 18:14:27.501 [DEBUG] [np.transport.impl.async.AsyncServlet] - Handling Servlet request asynchronously: org.ops4j.pax.web.service.spi.servlet.OsgiHttpServletRequestWrapper@60297f95
2023-04-02 18:14:27.501 [DEBUG] [org.jupnp.transport.Router          ] - Received synchronous stream: 2028365436
2023-04-02 18:14:27.502 [DEBUG] [np.transport.impl.async.AsyncServlet] - AsyncListener.onComplete(): id:   8, duration:    2, response: HTTP/1.1 200 
Connection: close
Content-Type: text/xml
Date: Mon, 03 Apr 2023 01:14:27 GMT


2023-04-02 18:14:27.514 [INFO ] [np.transport.impl.async.AsyncServlet] - HttpServlet.service(): id:   9, request URI: /upnpcallback/dev/RINCON_949F3E89854601400_MR/svc/upnp-org/RenderingControl/event/cb
2023-04-02 18:14:27.514 [DEBUG] [np.transport.impl.async.AsyncServlet] - Handling Servlet request asynchronously: org.ops4j.pax.web.service.spi.servlet.OsgiHttpServletRequestWrapper@76d4b7b2
2023-04-02 18:14:27.514 [DEBUG] [org.jupnp.transport.Router          ] - Received synchronous stream: 741992804
2023-04-02 18:14:27.515 [DEBUG] [np.transport.impl.async.AsyncServlet] - AsyncListener.onComplete(): id:   9, duration:    1, response: HTTP/1.1 200 
Connection: close
Content-Type: text/xml
Date: Mon, 03 Apr 2023 01:14:27 GMT


2023-04-02 18:14:27.518 [INFO ] [np.transport.impl.async.AsyncServlet] - HttpServlet.service(): id:  10, request URI: /upnpcallback/dev/RINCON_5CAAFD5BA47001400_MR/svc/upnp-org/AVTransport/event/cb
2023-04-02 18:14:27.518 [DEBUG] [np.transport.impl.async.AsyncServlet] - Handling Servlet request asynchronously: org.ops4j.pax.web.service.spi.servlet.OsgiHttpServletRequestWrapper@7abb4ff8
2023-04-02 18:14:27.518 [DEBUG] [org.jupnp.transport.Router          ] - Received synchronous stream: 1523216445
2023-04-02 18:14:27.523 [DEBUG] [np.transport.impl.async.AsyncServlet] - AsyncListener.onComplete(): id:  10, duration:    5, response: HTTP/1.1 200 
Connection: close
Content-Type: text/xml
Date: Mon, 03 Apr 2023 01:14:27 GMT


2023-04-02 18:14:27.538 [INFO ] [np.transport.impl.async.AsyncServlet] - HttpServlet.service(): id:  11, request URI: /upnpcallback/dev/RINCON_5CAAFD5BA47001400_MR/svc/upnp-org/RenderingControl/event/cb
2023-04-02 18:14:27.538 [DEBUG] [np.transport.impl.async.AsyncServlet] - Handling Servlet request asynchronously: org.ops4j.pax.web.service.spi.servlet.OsgiHttpServletRequestWrapper@13b1c285
2023-04-02 18:14:27.539 [DEBUG] [org.jupnp.transport.Router          ] - Received synchronous stream: 1772800584
2023-04-02 18:14:27.540 [DEBUG] [np.transport.impl.async.AsyncServlet] - AsyncListener.onComplete(): id:  11, duration:    2, response: HTTP/1.1 200 
Connection: close
Content-Type: text/xml
Date: Mon, 03 Apr 2023 01:14:27 GMT


2023-04-02 18:14:34.106 [DEBUG] [upnp.transport.spi.MulticastReceiver] - UDP datagram received from: 169.254.85.236:55625 on local interface: vethac53f5d and address: 169.254.155.67
2023-04-02 18:14:34.106 [DEBUG] [upnp.transport.spi.MulticastReceiver] - UDP datagram received from: 192.168.1.105:37788 on local interface: enp5s0 and address: 192.168.1.105
2023-04-02 18:14:34.106 [DEBUG] [upnp.transport.spi.MulticastReceiver] - UDP datagram received from: 169.254.155.67:35740 on local interface: veth66a1bab and address: 169.254.155.67
2023-04-02 18:14:34.106 [DEBUG] [upnp.transport.spi.MulticastReceiver] - UDP datagram received from: 169.254.199.104:54524 on local interface: veth73c8cd2 and address: 169.254.155.67
2023-04-02 18:14:34.106 [DEBUG] [upnp.transport.spi.MulticastReceiver] - UDP datagram received from: 169.254.131.88:52377 on local interface: veth8437ba6 and address: 169.254.155.67
2023-04-02 18:14:34.106 [DEBUG] [upnp.transport.spi.MulticastReceiver] - UDP datagram received from: 169.254.221.238:49361 on local interface: veth0fffc8d and address: 169.254.155.67
2023-04-02 18:14:34.107 [DEBUG] [org.jupnp.transport.Router          ] - Received asynchronous message: (IncomingDatagramMessage) M-SEARCH
2023-04-02 18:14:34.107 [DEBUG] [org.jupnp.transport.Router          ] - Received asynchronous message: (IncomingDatagramMessage) M-SEARCH
2023-04-02 18:14:34.107 [DEBUG] [org.jupnp.transport.Router          ] - Received asynchronous message: (IncomingDatagramMessage) M-SEARCH
2023-04-02 18:14:34.107 [DEBUG] [org.jupnp.transport.Router          ] - Received asynchronous message: (IncomingDatagramMessage) M-SEARCH
2023-04-02 18:14:34.107 [DEBUG] [org.jupnp.transport.Router          ] - Received asynchronous message: (IncomingDatagramMessage) M-SEARCH
2023-04-02 18:14:34.106 [DEBUG] [org.jupnp.transport.Router          ] - Received asynchronous message: (IncomingDatagramMessage) M-SEARCH
2023-04-02 18:14:34.109 [DEBUG] [upnp.transport.spi.MulticastReceiver] - UDP datagram received from: 169.254.54.176:48093 on local interface: enp5s0 and address: 169.254.155.67
2023-04-02 18:14:34.109 [DEBUG] [org.jupnp.transport.Router          ] - Received asynchronous message: (IncomingDatagramMessage) M-SEARCH
2023-04-02 18:14:40.544 [INFO ] [s.internal.handler.ZonePlayerHandler] - UPnP device RINCON_7828CAABC74601400 is absent (thing sonos:PLAY1:RINCON_7828CAABC74601400)
2023-04-02 18:14:40.546 [INFO ] [s.internal.handler.ZonePlayerHandler] - UPnP device RINCON_949F3E89844201400 is absent (thing sonos:PLAY1:RINCON_949F3E89844201400)
2023-04-02 18:14:40.547 [INFO ] [s.internal.handler.ZonePlayerHandler] - UPnP device RINCON_38420B14A8AC01400 is absent (thing sonos:OneSL:RINCON_38420B14A8AC01400)
2023-04-02 18:14:40.551 [INFO ] [s.internal.handler.ZonePlayerHandler] - UPnP device RINCON_7828CAAEE2FC01400 is absent (thing sonos:PLAY1:RINCON_7828CAAEE2FC01400)
2023-04-02 18:14:40.555 [INFO ] [s.internal.handler.ZonePlayerHandler] - UPnP device RINCON_949F3E89854601400 is absent (thing sonos:PLAY1:RINCON_949F3E89854601400)
2023-04-02 18:14:40.556 [INFO ] [s.internal.handler.ZonePlayerHandler] - UPnP device RINCON_7828CAA5029201400 is absent (thing sonos:PLAY1:RINCON_7828CAA5029201400)
2023-04-02 18:14:40.559 [INFO ] [s.internal.handler.ZonePlayerHandler] - UPnP device RINCON_5CAAFD5BA47001400 is absent (thing sonos:PLAY3:RINCON_5CAAFD5BA47001400)
2023-04-02 18:14:40.567 [INFO ] [s.internal.handler.ZonePlayerHandler] - UPnP device RINCON_F0F6C13140DE01400 is absent (thing sonos:RoamSL:RINCON_F0F6C13140DE01400)
2023-04-02 18:14:40.570 [DEBUG] [org.jupnp.transport.Router          ] - Disabling network services...
2023-04-02 18:14:40.571 [DEBUG] [org.jupnp.transport.Router          ] - Stopping stream client connection management/pool
2023-04-02 18:14:40.572 [DEBUG] [org.jupnp.transport.Router          ] - Stopping stream server on address: /169.254.221.238
2023-04-02 18:14:40.573 [DEBUG] [org.jupnp.transport.Router          ] - Stopping stream server on address: /172.17.0.1
2023-04-02 18:14:40.573 [DEBUG] [org.jupnp.transport.Router          ] - Stopping stream server on address: /169.254.226.255
2023-04-02 18:14:40.573 [DEBUG] [org.jupnp.transport.Router          ] - Stopping stream server on address: /192.168.1.105
2023-04-02 18:14:40.573 [DEBUG] [org.jupnp.transport.Router          ] - Stopping stream server on address: /169.254.18.215
2023-04-02 18:14:40.573 [DEBUG] [org.jupnp.transport.Router          ] - Stopping stream server on address: /169.254.117.53
2023-04-02 18:14:40.573 [DEBUG] [org.jupnp.transport.Router          ] - Stopping stream server on address: /169.254.155.67
2023-04-02 18:14:40.573 [DEBUG] [org.jupnp.transport.Router          ] - Stopping stream server on address: /169.254.54.176
2023-04-02 18:14:40.573 [DEBUG] [org.jupnp.transport.Router          ] - Stopping stream server on address: /169.254.242.241
2023-04-02 18:14:40.573 [DEBUG] [org.jupnp.transport.Router          ] - Stopping multicast receiver on interface: enp5s0
2023-04-02 18:14:40.573 [DEBUG] [upnp.transport.spi.MulticastReceiver] - Leaving multicast group
2023-04-02 18:14:40.574 [DEBUG] [org.jupnp.transport.Router          ] - Stopping multicast receiver on interface: veth73c8cd2
2023-04-02 18:14:40.574 [DEBUG] [upnp.transport.spi.MulticastReceiver] - Socket closed
2023-04-02 18:14:40.574 [DEBUG] [upnp.transport.spi.MulticastReceiver] - Leaving multicast group
2023-04-02 18:14:40.574 [DEBUG] [org.jupnp.transport.Router          ] - Stopping multicast receiver on interface: veth0fffc8d
2023-04-02 18:14:40.574 [DEBUG] [upnp.transport.spi.MulticastReceiver] - Leaving multicast group
2023-04-02 18:14:40.574 [DEBUG] [org.jupnp.transport.Router          ] - Stopping multicast receiver on interface: vethac53f5d
2023-04-02 18:14:40.574 [DEBUG] [upnp.transport.spi.MulticastReceiver] - Leaving multicast group
2023-04-02 18:14:40.574 [DEBUG] [upnp.transport.spi.MulticastReceiver] - Socket closed
2023-04-02 18:14:40.574 [DEBUG] [org.jupnp.transport.Router          ] - Stopping multicast receiver on interface: veth66a1bab
2023-04-02 18:14:40.574 [DEBUG] [upnp.transport.spi.MulticastReceiver] - Leaving multicast group
2023-04-02 18:14:40.574 [DEBUG] [org.jupnp.transport.Router          ] - Stopping multicast receiver on interface: veth8437ba6
2023-04-02 18:14:40.574 [DEBUG] [upnp.transport.spi.MulticastReceiver] - Leaving multicast group
2023-04-02 18:14:40.574 [DEBUG] [upnp.transport.spi.MulticastReceiver] - Socket closed
2023-04-02 18:14:40.574 [DEBUG] [org.jupnp.transport.Router          ] - Stopping multicast receiver on interface: docker0
2023-04-02 18:14:40.574 [DEBUG] [upnp.transport.spi.MulticastReceiver] - Leaving multicast group
2023-04-02 18:14:40.574 [DEBUG] [org.jupnp.transport.Router          ] - Stopping datagram I/O on address: /169.254.221.238
2023-04-02 18:14:40.575 [DEBUG] [org.jupnp.transport.Router          ] - Stopping datagram I/O on address: /172.17.0.1
2023-04-02 18:14:40.575 [DEBUG] [upnp.transport.spi.MulticastReceiver] - Socket closed
2023-04-02 18:14:40.575 [DEBUG] [upnp.transport.spi.MulticastReceiver] - Socket closed
2023-04-02 18:14:40.575 [DEBUG] [.jupnp.transport.impl.DatagramIOImpl] - Socket closed
2023-04-02 18:14:40.575 [DEBUG] [upnp.transport.spi.MulticastReceiver] - Socket closed
2023-04-02 18:14:40.575 [DEBUG] [org.jupnp.transport.Router          ] - Stopping datagram I/O on address: /169.254.226.255
2023-04-02 18:14:40.575 [DEBUG] [.jupnp.transport.impl.DatagramIOImpl] - Socket closed
2023-04-02 18:14:40.575 [DEBUG] [org.jupnp.transport.Router          ] - Stopping datagram I/O on address: /192.168.1.105
2023-04-02 18:14:40.575 [DEBUG] [.jupnp.transport.impl.DatagramIOImpl] - Socket closed
2023-04-02 18:14:40.575 [DEBUG] [.jupnp.transport.impl.DatagramIOImpl] - Socket closed
2023-04-02 18:14:40.575 [DEBUG] [org.jupnp.transport.Router          ] - Stopping datagram I/O on address: /169.254.18.215
2023-04-02 18:14:40.575 [DEBUG] [.jupnp.transport.impl.DatagramIOImpl] - Socket closed
2023-04-02 18:14:40.576 [DEBUG] [org.jupnp.transport.Router          ] - Stopping datagram I/O on address: /169.254.117.53
2023-04-02 18:14:40.576 [DEBUG] [.jupnp.transport.impl.DatagramIOImpl] - Socket closed
2023-04-02 18:14:40.576 [DEBUG] [org.jupnp.transport.Router          ] - Stopping datagram I/O on address: /169.254.155.67
2023-04-02 18:14:40.576 [DEBUG] [.jupnp.transport.impl.DatagramIOImpl] - Socket closed
2023-04-02 18:14:40.576 [DEBUG] [org.jupnp.transport.Router          ] - Stopping datagram I/O on address: /169.254.54.176
2023-04-02 18:14:40.576 [DEBUG] [.jupnp.transport.impl.DatagramIOImpl] - Socket closed
2023-04-02 18:14:40.576 [DEBUG] [org.jupnp.transport.Router          ] - Stopping datagram I/O on address: /169.254.242.241
2023-04-02 18:14:40.576 [DEBUG] [.jupnp.transport.impl.DatagramIOImpl] - Socket closed
2023-04-02 18:14:40.576 [DEBUG] [org.jupnp.transport.Router          ] - Starting networking services...
2023-04-02 18:14:40.577 [DEBUG] [upnp.transport.spi.MulticastReceiver] - Socket closed
2023-04-02 18:14:40.577 [DEBUG] [org.jupnp.transport.Router          ] - Init multicast receiver on interface: veth66a1bab
2023-04-02 18:14:40.577 [DEBUG] [upnp.transport.spi.MulticastReceiver] - Creating wildcard socket (for receiving multicast datagrams) on port: 1900
2023-04-02 18:14:40.577 [DEBUG] [upnp.transport.spi.MulticastReceiver] - Joining multicast group: /239.255.255.250:1900 on network interface: veth66a1bab
2023-04-02 18:14:40.577 [DEBUG] [org.jupnp.transport.Router          ] - Init multicast receiver on interface: veth73c8cd2
2023-04-02 18:14:40.577 [DEBUG] [upnp.transport.spi.MulticastReceiver] - Creating wildcard socket (for receiving multicast datagrams) on port: 1900
2023-04-02 18:14:40.577 [DEBUG] [upnp.transport.spi.MulticastReceiver] - Joining multicast group: /239.255.255.250:1900 on network interface: veth73c8cd2
2023-04-02 18:14:40.577 [DEBUG] [org.jupnp.transport.Router          ] - Init multicast receiver on interface: veth8437ba6
2023-04-02 18:14:40.577 [DEBUG] [upnp.transport.spi.MulticastReceiver] - Creating wildcard socket (for receiving multicast datagrams) on port: 1900
2023-04-02 18:14:40.577 [DEBUG] [upnp.transport.spi.MulticastReceiver] - Joining multicast group: /239.255.255.250:1900 on network interface: veth8437ba6
2023-04-02 18:14:40.578 [DEBUG] [org.jupnp.transport.Router          ] - Init multicast receiver on interface: veth0fffc8d
2023-04-02 18:14:40.578 [DEBUG] [upnp.transport.spi.MulticastReceiver] - Creating wildcard socket (for receiving multicast datagrams) on port: 1900
2023-04-02 18:14:40.578 [DEBUG] [upnp.transport.spi.MulticastReceiver] - Joining multicast group: /239.255.255.250:1900 on network interface: veth0fffc8d
2023-04-02 18:14:40.578 [DEBUG] [org.jupnp.transport.Router          ] - Init multicast receiver on interface: vethac53f5d
2023-04-02 18:14:40.578 [DEBUG] [upnp.transport.spi.MulticastReceiver] - Creating wildcard socket (for receiving multicast datagrams) on port: 1900
2023-04-02 18:14:40.578 [DEBUG] [upnp.transport.spi.MulticastReceiver] - Joining multicast group: /239.255.255.250:1900 on network interface: vethac53f5d
2023-04-02 18:14:40.578 [DEBUG] [org.jupnp.transport.Router          ] - Init multicast receiver on interface: docker0
2023-04-02 18:14:40.578 [DEBUG] [upnp.transport.spi.MulticastReceiver] - Creating wildcard socket (for receiving multicast datagrams) on port: 1900
2023-04-02 18:14:40.578 [DEBUG] [upnp.transport.spi.MulticastReceiver] - Joining multicast group: /239.255.255.250:1900 on network interface: docker0
2023-04-02 18:14:40.578 [DEBUG] [org.jupnp.transport.Router          ] - Init multicast receiver on interface: enp5s0
2023-04-02 18:14:40.579 [DEBUG] [upnp.transport.spi.MulticastReceiver] - Creating wildcard socket (for receiving multicast datagrams) on port: 1900
2023-04-02 18:14:40.579 [DEBUG] [upnp.transport.spi.MulticastReceiver] - Joining multicast group: /239.255.255.250:1900 on network interface: enp5s0

Of course, the things go offline when the streams are stopped and come back online as soon as the streams are re-established, so that part is working. I just can’t parse this well enough to know why the streams are being cut off in the first place.

8

Not seeing anything glaring in that. I’d suggest opening an issue on github at this point so the binding maintainer can look into it.

1 Like
9

Issue filed.

10

There were already many topics about difficulties with Sonos due to UPnP when using docker. I believe some of them proposed solutions, you should look at them.

11

In deed, there are quite a few and I have looked through as many as I can find, but none of them (as far as I can tell, not being too familiar with UPnP) are even close to my situation, and none of the solutions are relevant.

I have been running in docker since 3.0 came out and my sonos system has been solidly connected and communicating with dockerized OH ever since the runtime jupnp configs became available.

Even now, the speakers are connected and responsive for ~56 seconds out of every minute except for the few seconds when the connection is stopped by OH because the speaker “absent”. As soon as the connections are restarted the speakers connect quickly and easily and are available again until that same process runs the next minute. Inbox discovery works just fine (unless I try to scan during the few seconds of down time).