search

openhab / openhab-core

Core framework of openHAB
https://www.openhab.org/
Eclipse Public License 2.0
898 stars 415 forks source link

Instability with jupnp #3843

Open morph166955 opened 8 months ago

morph166955 commented 8 months ago

I considered putting this under addons but it looks like it's impacting multiple addons and restarting jupnp seems to fix this. This has happened a few times now for reasons I can't explain. It looks like it just crashes from what I can tell. Restarting the bundle seems to make everything come back immediately. Usually my threads graph looks like the far left and right of the one below. As soon as it crashes the entire thing flatlines until the bundle is restarted. To note, in my config neeo and globalcache have the IPs set in the thing config which is why I assume they came back where sonos just has the udn.

To note, I'm on snapshot 3659 currently but this happened a few times on earlier versions as well. I can't remember if this happened prior to the 2.7.1 update. This didn't happen on the 4.0 snapshots or early on in the 4.1.

jupnp

2023-10-09 22:22:48.522 [INFO ] [openhab.core.model.script.THINGSTATE] - State Change For SonosPLAY1RINCON_949F3E129B6001400_ThingState - From: ONLINE To: OFFLINE
2023-10-09 22:22:53.541 [INFO ] [openhab.core.model.script.THINGSTATE] - State Change For SonosPLAY1RINCON_949F3E129B6001400_ThingState - From: OFFLINE To: ONLINE
2023-10-09 22:32:58.740 [INFO ] [openhab.core.model.script.THINGSTATE] - State Change For SonosOneSLRINCON_48A6B858505A01400_ThingState - From: ONLINE To: OFFLINE
2023-10-09 22:33:10.547 [INFO ] [openhab.core.model.script.THINGSTATE] - State Change For SonosOneRINCON_7828CAC278C001400_ThingState - From: ONLINE To: OFFLINE
2023-10-09 22:33:15.562 [INFO ] [openhab.core.model.script.THINGSTATE] - State Change For SonosOneRINCON_7828CAC278C001400_ThingState - From: OFFLINE To: ONLINE
2023-10-09 22:33:25.126 [INFO ] [openhab.core.model.script.THINGSTATE] - State Change For SonosArcRINCON_48A6B8BF040E01400_ThingState - From: ONLINE To: OFFLINE
2023-10-09 22:33:37.064 [INFO ] [openhab.core.model.script.THINGSTATE] - State Change For SonosOneSLRINCON_48A6B858508601400_ThingState - From: ONLINE To: OFFLINE
2023-10-09 22:33:42.082 [INFO ] [openhab.core.model.script.THINGSTATE] - State Change For SonosArcRINCON_48A6B8BF040E01400_ThingState - From: OFFLINE To: ONLINE
2023-10-09 22:33:42.084 [INFO ] [openhab.core.model.script.THINGSTATE] - State Change For SonosOneSLRINCON_48A6B858508601400_ThingState - From: OFFLINE To: ONLINE
2023-10-09 22:33:42.085 [INFO ] [openhab.core.model.script.THINGSTATE] - State Change For SonosOneSLRINCON_48A6B858505A01400_ThingState - From: OFFLINE To: ONLINE
2023-10-09 22:38:05.901 [INFO ] [openhab.core.model.script.THINGSTATE] - State Change For SonosOneSLRINCON_48A6B858505A01400_ThingState - From: ONLINE To: OFFLINE
2023-10-09 22:38:10.916 [INFO ] [openhab.core.model.script.THINGSTATE] - State Change For SonosOneSLRINCON_48A6B858508601400_ThingState - From: ONLINE To: OFFLINE
2023-10-09 22:38:10.918 [INFO ] [openhab.core.model.script.THINGSTATE] - State Change For SonosOneSLRINCON_48A6B858505A01400_ThingState - From: OFFLINE To: ONLINE
2023-10-09 22:38:20.948 [INFO ] [openhab.core.model.script.THINGSTATE] - State Change For SonosOneSLRINCON_48A6B858508601400_ThingState - From: OFFLINE To: ONLINE
2023-10-09 22:38:42.819 [INFO ] [openhab.core.model.script.THINGSTATE] - State Change For NEEO_Brain_713af1e8_ThingState - From: ONLINE To: OFFLINE
2023-10-09 22:38:52.820 [INFO ] [openhab.core.model.script.THINGSTATE] - State Change For NEEO_Brain_713af1e8_ThingState - From: OFFLINE To: ONLINE
2023-10-09 22:53:49.793 [INFO ] [openhab.core.model.script.THINGSTATE] - State Change For SonosOneSLRINCON_48A6B858505A01400_ThingState - From: ONLINE To: OFFLINE
2023-10-09 22:53:54.811 [INFO ] [openhab.core.model.script.THINGSTATE] - State Change For NEEO_Brain_05dbea22_ThingState - From: ONLINE To: OFFLINE
2023-10-09 22:54:05.902 [INFO ] [openhab.core.model.script.THINGSTATE] - State Change For NEEO_Brain_05dbea22_ThingState - From: OFFLINE To: ONLINE
2023-10-09 22:54:10.913 [INFO ] [openhab.core.model.script.THINGSTATE] - State Change For SonosOneSLRINCON_48A6B858508601400_ThingState - From: ONLINE To: OFFLINE
2023-10-09 22:54:15.945 [INFO ] [openhab.core.model.script.THINGSTATE] - State Change For SonosAmpRINCON_F0F6C19B26A701400_ThingState - From: ONLINE To: OFFLINE
2023-10-09 22:54:18.093 [ERROR] [.GlobalCacheHandler$CommandProcessor] - Comm error for thing itachIR:000C1E04A4F7 at 10.255.0.31: Socket closed
2023-10-09 22:54:20.957 [INFO ] [openhab.core.model.script.THINGSTATE] - State Change For GC000C1E04A4F7_ThingState - From: ONLINE To: OFFLINE
2023-10-09 22:54:20.960 [INFO ] [openhab.core.model.script.THINGSTATE] - State Change For SonosOneSLRINCON_48A6B858505A01400_ThingState - From: OFFLINE To: ONLINE
2023-10-09 22:54:20.961 [INFO ] [openhab.core.model.script.THINGSTATE] - State Change For SonosAmpRINCON_F0F6C19B26A701400_ThingState - From: OFFLINE To: ONLINE
2023-10-09 22:54:25.973 [INFO ] [openhab.core.model.script.THINGSTATE] - State Change For SonosOneSLRINCON_48A6B858508601400_ThingState - From: OFFLINE To: ONLINE
2023-10-09 22:54:41.020 [INFO ] [openhab.core.model.script.THINGSTATE] - State Change For SonosOneSLRINCON_48A6B858505A01400_ThingState - From: ONLINE To: OFFLINE
2023-10-09 22:54:51.042 [INFO ] [openhab.core.model.script.THINGSTATE] - State Change For SonosOneSLRINCON_48A6B858508601400_ThingState - From: ONLINE To: OFFLINE
2023-10-09 22:54:51.044 [INFO ] [openhab.core.model.script.THINGSTATE] - State Change For SonosOneSLRINCON_48A6B858505A01400_ThingState - From: OFFLINE To: ONLINE
2023-10-09 22:55:06.084 [INFO ] [openhab.core.model.script.THINGSTATE] - State Change For SonosOneSLRINCON_48A6B858508601400_ThingState - From: OFFLINE To: ONLINE
2023-10-09 22:55:18.063 [INFO ] [GlobalCacheHandler$ConnectionManager] - Got a connection to command port for thing itachIR:000C1E04A4F7 at 10.255.0.31
2023-10-09 22:55:18.065 [INFO ] [openhab.core.model.script.THINGSTATE] - State Change For GC000C1E04A4F7_ThingState - From: OFFLINE To: ONLINE
2023-10-09 22:58:18.566 [INFO ] [openhab.core.model.script.THINGSTATE] - State Change For SonosOneSLRINCON_48A6B858508601400_ThingState - From: ONLINE To: OFFLINE
2023-10-09 22:58:23.580 [INFO ] [openhab.core.model.script.THINGSTATE] - State Change For SonosArcRINCON_48A6B8BF040E01400_ThingState - From: ONLINE To: OFFLINE
2023-10-09 22:58:28.593 [INFO ] [openhab.core.model.script.THINGSTATE] - State Change For SonosArcRINCON_48A6B8BF040E01400_ThingState - From: OFFLINE To: ONLINE
2023-10-09 22:58:33.607 [INFO ] [openhab.core.model.script.THINGSTATE] - State Change For SonosPLAY1RINCON_949F3E129B6001400_ThingState - From: ONLINE To: OFFLINE
2023-10-09 22:58:33.608 [INFO ] [openhab.core.model.script.THINGSTATE] - State Change For SonosOneSLRINCON_48A6B858508601400_ThingState - From: OFFLINE To: ONLINE
2023-10-09 22:58:51.072 [INFO ] [openhab.core.model.script.THINGSTATE] - State Change For SonosPLAY1RINCON_949F3E129B6001400_ThingState - From: OFFLINE To: ONLINE
2023-10-09 22:58:56.086 [INFO ] [openhab.core.model.script.THINGSTATE] - State Change For SonosOneSLRINCON_48A6B858508601400_ThingState - From: ONLINE To: OFFLINE
2023-10-09 22:59:06.217 [INFO ] [openhab.core.model.script.THINGSTATE] - State Change For SonosOneSLRINCON_48A6B858508601400_ThingState - From: OFFLINE To: ONLINE
2023-10-09 23:05:37.953 [INFO ] [openhab.core.model.script.THINGSTATE] - State Change For SonosOneSLRINCON_48A6B858508601400_ThingState - From: ONLINE To: OFFLINE
2023-10-09 23:05:42.968 [INFO ] [openhab.core.model.script.THINGSTATE] - State Change For SonosOneSLRINCON_48A6B858508601400_ThingState - From: OFFLINE To: ONLINE

2023-10-09 23:22:06.378 [INFO ] [s.internal.handler.ZonePlayerHandler] - UPnP device RINCON_48A6B858505A01400 is absent (thing sonos:OneSL:RINCON_48A6B858505A01400)
2023-10-09 23:22:06.383 [INFO ] [openhab.core.model.script.THINGSTATE] - State Change For SonosOneSLRINCON_48A6B858505A01400_ThingState - From: ONLINE To: OFFLINE
2023-10-09 23:22:10.390 [INFO ] [s.internal.handler.ZonePlayerHandler] - UPnP device RINCON_48A6B858508601400 is absent (thing sonos:OneSL:RINCON_48A6B858508601400)
2023-10-09 23:22:11.396 [INFO ] [openhab.core.model.script.THINGSTATE] - State Change For SonosOneSLRINCON_48A6B858508601400_ThingState - From: ONLINE To: OFFLINE
2023-10-09 23:22:15.393 [INFO ] [s.internal.handler.ZonePlayerHandler] - UPnP device RINCON_F0F6C19B26A701400 is absent (thing sonos:Amp:RINCON_F0F6C19B26A701400)
2023-10-09 23:22:16.413 [INFO ] [openhab.core.model.script.THINGSTATE] - State Change For SonosAmpRINCON_F0F6C19B26A701400_ThingState - From: ONLINE To: OFFLINE
2023-10-09 23:22:26.445 [INFO ] [openhab.core.model.script.THINGSTATE] - State Change For SonosPLAY1RINCON_949F3E129B6001400_ThingState - From: ONLINE To: OFFLINE
2023-10-09 23:22:42.407 [INFO ] [openhab.core.model.script.THINGSTATE] - State Change For SonosPLAY1RINCON_949F3E129B6001400_ThingState - From: OFFLINE To: ONLINE
2023-10-09 23:22:55.400 [INFO ] [s.internal.handler.ZonePlayerHandler] - UPnP device RINCON_48A6B8BF04F501400 is absent (thing sonos:Arc:RINCON_48A6B8BF04F501400)
2023-10-09 23:22:55.405 [INFO ] [openhab.core.model.script.THINGSTATE] - State Change For SonosArcRINCON_48A6B8BF04F501400_ThingState - From: ONLINE To: OFFLINE
2023-10-09 23:25:46.346 [INFO ] [openhab.core.model.script.THINGSTATE] - State Change For SonosPLAY1RINCON_949F3E129B6001400_ThingState - From: ONLINE To: OFFLINE
2023-10-09 23:26:07.370 [INFO ] [openhab.core.model.script.THINGSTATE] - State Change For SonosPLAY1RINCON_949F3E129B6001400_ThingState - From: OFFLINE To: ONLINE
2023-10-09 23:28:18.455 [INFO ] [s.internal.handler.ZonePlayerHandler] - UPnP device RINCON_48A6B8BF040E01400 is absent (thing sonos:Arc:RINCON_48A6B8BF040E01400)
2023-10-09 23:28:18.459 [INFO ] [openhab.core.model.script.THINGSTATE] - State Change For SonosArcRINCON_48A6B8BF040E01400_ThingState - From: ONLINE To: OFFLINE
2023-10-09 23:28:26.464 [INFO ] [s.internal.handler.ZonePlayerHandler] - UPnP device RINCON_949F3E129B6001400 is absent (thing sonos:PLAY1:RINCON_949F3E129B6001400)
2023-10-09 23:28:26.465 [INFO ] [s.internal.handler.ZonePlayerHandler] - UPnP device RINCON_7828CA17095601400 is absent (thing sonos:One:RINCON_7828CA17095601400)
2023-10-09 23:28:28.490 [INFO ] [openhab.core.model.script.THINGSTATE] - State Change For SonosOneRINCON_7828CA17095601400_ThingState - From: ONLINE To: OFFLINE
2023-10-09 23:28:28.492 [INFO ] [openhab.core.model.script.THINGSTATE] - State Change For SonosPLAY1RINCON_949F3E129B6001400_ThingState - From: ONLINE To: OFFLINE
2023-10-09 23:52:18.656 [INFO ] [s.internal.handler.ZonePlayerHandler] - UPnP device RINCON_7828CAC278C001400 is absent (thing sonos:One:RINCON_7828CAC278C001400)
2023-10-09 23:52:18.659 [INFO ] [openhab.core.model.script.THINGSTATE] - State Change For SonosOneRINCON_7828CAC278C001400_ThingState - From: ONLINE To: OFFLINE
2023-10-09 23:52:47.661 [INFO ] [s.internal.handler.ZonePlayerHandler] - UPnP device RINCON_F0F6C19B266501400 is absent (thing sonos:Amp:RINCON_F0F6C19B266501400)
2023-10-09 23:52:47.671 [INFO ] [openhab.core.model.script.THINGSTATE] - State Change For SonosAmpRINCON_F0F6C19B266501400_ThingState - From: ONLINE To: OFFLINE
lolodomo commented 1 month ago

Could you please tell us if this is still a problem with JUPnP 3.0.1 which is used by OH 4.2 milestone 2 ?

morph166955 commented 1 month ago

I just updated to snapshot 4092, I'll monitor for this. Updating the big system takes some effort these days so I don't do it as often.

kgoderis commented 1 month ago

+1 @lolodomo

I have the same issue on SNAPSHOT 4082, with a fairly large (>20) Sonos installation. All Sonos devices go into ERROR state, only restarting the jupnp bundle resolves the issue