Following up on my problems with UPNP. In the openhab log I get lots of these messages:
2025-10-13 13:56:10.450 [DEBUG] [mmon.WrappedScheduledExecutorService] - Scheduled task is taking more than PT5S; it was created here:
java.lang.Exception: null
at org.openhab.core.internal.common.WrappedScheduledExecutorService$TimedAbstractTask.<init>(WrappedScheduledExecutorService.java:68) ~[?:?]
at org.openhab.core.internal.common.WrappedScheduledExecutorService$TimedRunnable.<init>(WrappedScheduledExecutorService.java:98) ~[?:?]
at org.openhab.core.internal.common.WrappedScheduledExecutorService.schedule(WrappedScheduledExecutorService.java:163) ~[?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor.submit(ScheduledThreadPoolExecutor.java:715) ~[?:?]
at org.openhab.core.common.ThreadPoolManager$UnstoppableExecutorService.submit(ThreadPoolManager.java:280) ~[?:?]
at org.openhab.core.config.discovery.sddp.SddpDiscoveryService.startBackgroundDiscovery(SddpDiscoveryService.java:428) ~[?:?]
at org.openhab.core.config.discovery.AbstractDiscoveryService.activate(AbstractDiscoveryService.java:441) ~[?:?]
at org.openhab.core.config.discovery.sddp.SddpDiscoveryService.<init>(SddpDiscoveryService.java:124) ~[?:?]
at jdk.internal.reflect.DirectConstructorHandleAccessor.newInstance(DirectConstructorHandleAccessor.java:62) ~[?:?]
at java.lang.reflect.Constructor.newInstanceWithCaller(Constructor.java:502) ~[?:?]
at java.lang.reflect.Constructor.newInstance(Constructor.java:486) ~[?:?]
at org.apache.felix.scr.impl.inject.internal.ComponentConstructorImpl.newInstance(ComponentConstructorImpl.java:326) ~[?:?]
at org.apache.felix.scr.impl.manager.SingleComponentManager.createImplementationObject(SingleComponentManager.java:286) ~[?:?]
at org.apache.felix.scr.impl.manager.SingleComponentManager.createComponent(SingleComponentManager.java:115) ~[?:?]
at org.apache.felix.scr.impl.manager.SingleComponentManager.getService(SingleComponentManager.java:1002) ~[?:?]
at org.apache.felix.scr.impl.manager.SingleComponentManager.getServiceInternal(SingleComponentManager.java:975) ~[?:?]
at org.apache.felix.scr.impl.manager.SingleComponentManager.getService(SingleComponentManager.java:920) ~[?:?]
at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse$1.run(ServiceFactoryUse.java:220) ~[org.eclipse.osgi-3.18.0.jar:?]
at java.security.AccessController.doPrivileged(AccessController.java:319) ~[?:?]
at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.factoryGetService(ServiceFactoryUse.java:217) ~[org.eclipse.osgi-3.18.0.jar:?]
at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.getService(ServiceFactoryUse.java:118) ~[org.eclipse.osgi-3.18.0.jar:?]
at org.eclipse.osgi.internal.serviceregistry.ServiceConsumer$2.getService(ServiceConsumer.java:48) ~[org.eclipse.osgi-3.18.0.jar:?]
at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.getService(ServiceRegistrationImpl.java:547) ~[org.eclipse.osgi-3.18.0.jar:?]
--
2025-10-13 13:56:13.257 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception:
java.lang.AssertionError: java.net.BindException: Cannot assign requested address (setsockopt failed)
at sun.nio.ch.DatagramChannelImpl.drop(DatagramChannelImpl.java:1727) ~[?:?]
at sun.nio.ch.MembershipKeyImpl.drop(MembershipKeyImpl.java:147) ~[?:?]
at sun.nio.ch.DatagramSocketAdaptor.leaveGroup(DatagramSocketAdaptor.java:512) ~[?:?]
at java.net.DatagramSocket.leaveGroup(DatagramSocket.java:1350) ~[?:?]
at java.net.MulticastSocket.leaveGroup(MulticastSocket.java:386) ~[?:?]
at org.jupnp.transport.impl.MulticastReceiverImpl.stop(MulticastReceiverImpl.java:101) ~[?:?]
at org.jupnp.transport.RouterImpl.disable(RouterImpl.java:171) ~[?:?]
at org.openhab.core.config.discovery.upnp.internal.UpnpDiscoveryService.lambda$1(UpnpDiscoveryService.java:241) ~[?:?]
at org.openhab.core.internal.common.WrappedScheduledExecutorService$TimedRunnable.run(WrappedScheduledExecutorService.java:106) ~[?:?]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:572) ~[?:?]
at java.util.concurrent.FutureTask.run(FutureTask.java:317) ~[?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144) ~[?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642) ~[?:?]
at java.lang.Thread.run(Thread.java:1583) [?:?]
Caused by: java.net.BindException: Cannot assign requested address (setsockopt failed)
at sun.nio.ch.Net.joinOrDrop4(Native Method) ~[?:?]
at sun.nio.ch.Net.drop4(Net.java:717) ~[?:?]
at sun.nio.ch.DatagramChannelImpl.drop(DatagramChannelImpl.java:1722) ~[?:?]
... 14 more
I have tried removing all bindings, restarting and I still continue to get these messages. My openhab installation has ben working fine for several years, and is running in a VM on a server with 16G of RAM and 8 cores allocated (Ubuntu 24.04).
I have to believe that my UPNP discovery and subscription problems are related to these messages. This is causing the samsungtv binding (which I wrote) not to be able to detect the state of the three TV’s I have, as it uses UPNP discovery to be able to tell when the TV’s are on or off.
I finally had to revert to OH 5.0-1. After that, no more messages in the log, and UPNP is back to working as expected.
Something has changed, possibly not specifically with UPNP, but with the WrappedScheduledExecutorService to cause these issues.
I also don’t know what address Cannot assign requested address refers to, as my VM only has one address assigned, but this would also seem to be an issue.
There are similar WrappedScheduledExecutorService messages referring to the mDNS service, and the messages repeat every few seconds.
Does anyone have any idea what these messages mean? or why they would prevent my UPNP discovery/subscriptions from working?
I think there was some change on SddpDiscoveryService recently.
I’m not sure if it can be related, but add @Nadahar to the discussion so it can check if there is something related.
The message you have posted above isn’t a crash, it’s just a warning that the task takes more than 5 seconds to complete. The warning is new in 5.1, but it’s only activated if you have DEBUG logging enabled for org.openhab.core.
I doubt that the log message in itself is a problem, but it might give us some hints about what is the problem. Previously, the same would have happened, but there would be no way to see these delays in the log.
These are signs of general “slowdown” of threads, they queue, waiting for locks, the thread pools are exchausted and things grind more or less to a halt. This was merged two days ago, so it isn’t in 5.1 M1, but it is an attempt to resolve some of this queuing:
There are definitely more issues than just that, but I’ve noticed that the time it took to register a discovery could be many seconds, and the binding threads would then be stuck in a queue waiting to register discoveries, stopping basically everything else they should have been doing.
It’s a bit strange to see where “it is stuck” in your above example, but there have probably been many previous logs that would shed some more light on what’s going on.
Here is the change that was done to WrappedScheduledExecutionService:
What I would be most interested in, is if you’re able to make a thread dump when this is happening. I think that’s necessary to try to figure out what’s causing the blocking/slowdown.
Thanks Laurent. I may have spoken too soon about UPNP working on OH 5.0 - the problem is that UPNP works for a time, then stops working - and I don’t know why.
If I use a third party program, it discovers the TV services with no issue - even if I run a simple discovery script on my OH VM.
OH, however, initially works as expected, but after a period, stops detecting the UPNP services.
The samsungtv binding has been using UPNP for TV state detection for many years, without any problems - but now it has become unreliable.
Here is a log of the UpnpIOServiceImpl where two TV’s are shown as off, but in fact are still on, and 3rd party programs show the services as still discoverable.
2025-10-13 15:29:15.858 [TRACE] [port.upnp.internal.UpnpIOServiceImpl] - Invoking Action 'GetZoneInfo' of service 'DeviceProperties' for participant 'RINCON_542A1BD34E9A01400'
2025-10-13 15:30:04.231 [DEBUG] [port.upnp.internal.UpnpIOServiceImpl] - Device '3bc4a990-d3aa-4f43-a045-26317d32ba92' reachability status changed to 'false'
2025-10-13 15:30:15.865 [TRACE] [port.upnp.internal.UpnpIOServiceImpl] - Invoking Action 'GetZoneInfo' of service 'DeviceProperties' for participant 'RINCON_542A1BD34E9A01400'
2025-10-13 15:30:16.234 [DEBUG] [port.upnp.internal.UpnpIOServiceImpl] - Device 'ea645e34-d3dd-4b9b-a246-e2947f8973d6' reachability status changed to 'false'
I’m just wondering if I have something configured incorrectly, as I just downgraded in-place to 5.0.
That is the ever recurring question. There are several ways, and every time this is up, I’m regretting that we don’t have it documented somewhere. It depends on your setup and knowledge what is the most suitable way. I use VisualVM, but that requires a desktop environment, or some troublesome configuration to allow VisualVM to make a remote connection to another computer.
There is also something called jstack, and there are other options, depending on… Here is a pretty good summary of the most common options:
After some testing on my openHABian, I found this approach quite easy:
sudo ps -ax | grep bin/java
It will list a lot of stuff, what you’re interested in is the PID of the Java process running OH, which should be the very first thing it prints (in my case it was 726).
Then, once you have your PID, run (insert your PID number)
sudo jstack -l 726 > threaddump.txt
The thread dump is then in the file threaddump.txt in the folder you’re in when you run the command.
Yes, I’m all primed with jstack but after clearing the cache, and restarting - after 1/2 hour, UPNP is still working (this is after reverting to 5.0-1). With 5.1, UPNP never worked for more than 5 minutes.
I’ll leave it for a while, I’m hesitant to switch back to 5.1 as then my TV’s likely will stop working and the wife will kill me (no updates after that…).
I decided to bite the bullet, and upgrade back to 5.1 SNAPSHOT.
After 45 minutes, UPNP is still working. I have no idea what is going on, but at least I now know to ignore those WrappedScheduledExecutorService messages.
By the way, I think these are a really bad idea, as they look just like error messages, and when something is wrong, a regular person will waste a lot of time trying to figure out what they mean, and chasing their tails for no reason (like me).
Also, people turn DEBUG on when they are troubleshooting a problem, so that’s not a good toggle for these messages.
Anyway, just my opinion. I will continue to monitor UPNP, which will no doubt stop working 5 seconds after I post this.
That’s why you have to enabled DEBUG for org.openhab.core for them to show up. I wouldn’t expect “a regular person” to have that enabled, it will generate a lot of noise in general. But, I get what you mean, it’s just that it’s very difficult to “find the culprits” that causes these issues, so some way to detect them is needed.
I think maybe they could be tied to TRACE instead, but the options aren’t endless here. There needs to be some “switch” whose status is available where you need to decide if you want to measure the time or not. Making a separate configuration option for this could complicate things, the thread pools are called from “all over the place” and using the logging level just makes sense in that it’s already available and configurable.
That said, I would only enable DEBUG for the bundle I was troubleshooting. Are you saying that you enable it across the board? That would enable a lot of logging I’d imagine.
I feared something like this - it doesn’t seem like dump-create includes monitors/locking information, which is essential to figure this out. I can’t find any arguments that you can use with dump-create to include it either. So, while this thread dump provides some insight, I can’t really figure out what’s blocking what.
Could you try the procedure I listed above instead?
The -l parameter is what makes it include the information I need.
Edit: Your dump shows 18 threads that are considered blocked, but there are another 478 threads waiting for some lock to open. Not all over these are “wrong”, some mechanisms use waiting for a lock as a way to “pause” execution until a task is due, but without doubt, a portion of these should not be waiting, and are in effect stuck.
I’ve already restarted OpenHAB, I will try that method once that happens again. But yes, when I restarted OpenHAB, I’ve also had some problems with OpenHAB not reloading sitemap after change in text file was done - that happened around ~16h after UPNP (symfonisk in this case) stopped to work
Edit 16.10.2025 : Ha, it happened again but I couldn’t run jstack since it requires JDK. I installed JDK but I’ve also stopped OH to be safe when doing it, so I will probably have to wait again till it happens
Issue was, that I was no longer able to control Symfonisk - if understood logs correctly, it was not detected by upnp. Restarting OpenHAB is enough to fix this issue for some time but it sort of random, when it will happen - basically once I had few days of UPNP working fine (like @Nicholas_Waterton has now) but 2 times in a row it failed after around ~12h. Issue is not happening on 5.0 - only on 5.1m1. I haven’t tried snapshot builds.
No other things failed on OpenHAB this time (sitemap editing was fine) but I did that dump shortly after UPNP stopped to work
Maybe you could share part of the logs that seem relevant? I can’t say that there’s no problem with UPnP from the thread dump, it’s just that there’s nothing obvious to see. The UPnP threads aren’t blocked waiting for some other thread, but there are a number of them that are blocking while waiting for response to an HTTP request. That isn’t necessarily uncommon or “wrong” though, it usually means that they have requested information from another device and are waiting for a reply. These waits are almost always with a timeout, so that they will only wait for so long before giving up, so they shouldn’t normally be able to cause a “thread pile-up” where all available threads are consumed and things stop working. But, if the number of such requests is high and the timeout is long, this mechanism could theoretically starve a thread pool so that it can’t do other things, I just don’t find it a very likely scenario.
So, to sum it up: I’m not saying there’s no problem here, but the information in the thread dump isn’t sufficient for me to form a concrete theory of what the problem might be. Maybe corresponding parts of the log can provide enough information.
Your previous thread dump, that lacked the locking information, definitely had a problem. Sadly, I can’t figure out what’s causing it because the locking information isn’t there.
