search

openhab / openhab-addons

Add-ons for openHAB
https://www.openhab.org/
Eclipse Public License 2.0
1.88k stars 3.59k forks source link

[Sonos] all speaker things flapping every minute (OH in docker) #14742

Closed JustinGeorgi closed 3 months ago

JustinGeorgi commented 1 year ago

I have 8 sonos speakers. My sonos system has been reliably connected to OH for several years, but I have noticed in the last week now that the things for all 8 speakers go offline for a second or two and then come back online again once every minute.

A forum discussion about the issue can be seen here: https://community.openhab.org/t/all-sonos-things-flapping-every-minute/145765 but no resolution has been found.

System: OH 4.0 snapshot Build #3392 (also occurs on 4.0M1) Docker container network: host Docker running on ubuntu 22.04 All sonos speakers on same lan as OH Sonos system fully up-to-date

JUPnP settings in runtime.cfg

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

Have also tried org.jupnp:threadPoolSize and org.jupnp:asyncThreadPoolSize set to -1 but this does not fix the issue.

Logs: events.log (example of one speaker)

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

openhab.log (org.openhab.binding.sonos log level DEBUG, example of one speaker)

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

openhab.log (org.jupnp log level DEBUG)

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
openhab-bot commented 1 year ago

This issue has been mentioned on openHAB Community. There might be relevant details there:

https://community.openhab.org/t/all-sonos-things-flapping-every-minute/145765/9

lsiepel commented 8 months ago

Not sure if you still experience this issue, but the last snapshot build's have an upgraded jUPnP library. Maybe worth a while to test if that improves on the matter. From the binding perspective, i don't think there is anything that can be done to fix this issue. Docker / network / uPnP that is all sort of transparant to the binding.

JustinGeorgi commented 8 months ago

the last snapshot build's have an upgraded jUPnP library

That very interesting news, thank you. I have been able to manage the issue, but that's not the same as fixing it, so I will definitely take a look at the new snapshots when I have a chance.

lolodomo commented 8 months ago

You can find answers on the community forum or in documentation: https://next.openhab.org/docs/installation/docker.html#universal-plug-and-play-upnp

JustinGeorgi commented 8 months ago

You can find answers on the community forum or in documentation:

I've followed all the forum threads about this. Every time I try the Dorg.jupnp.network.useInterfaces Dorg.jupnp.network.useAddresses suggestions (and I've done it three or four times), far from fixing the problem, my container looses all connection to the internet. I don't know what I'm doing wrong or is different about my setup that causes this problem. I'll have time to try again soon and report back if the new update changes anything.

lsiepel commented 3 months ago

Unfortunately this seems to be specific to your docker installation and/or configuration. As the network layer is transparant to the binding, and no other cases have been reported, i guess this is something that can't be fixed in the binding. If you think otherwise, or have a lead how this cvan be fixed, feel free te re-open. For docker config the community forums are the best place to get assistance.

JustinGeorgi commented 3 months ago

I migrated my OH system to a new environment and initially, I had the same problem (so at least it wasn't specific to the system OH was running on). I then reconfigured my docker containers on the new system so that all of them were using the host network and I haven't had the issue since.

Thank you for checking back in. Closing this issue is fine.