[OH-httpClient-common] binding hangs on Waiting (OH run by processor with 10 cores)

jeremias-jordan commented 1 year ago

Expected Behavior

Should be possible to add things to binding, Binding should start up correctly on OpenHab Startup

Current Behavior

No matter which installation method i choose, the bundle hangs on "waiting" in the console

237 │ Waiting │  80 │ 3.3.0                  │ openHAB Add-ons :: Bundles :: Homematic Binding

I tried restarting, uninstalling and reinstalling, different installations methods (UI, console), cleaning the cache, basically everything i can do (even a complete reinstall of docker and openhab) but nothing helped. Here is a log excerpt after setting the log level to TRACE. Most of it keeps repeating, i hope i have included the important parts.

00:09:45.638 [ERROR] [.handler.HomematicThingHandlerFactory] - bundle org.openhab.binding.homematic:3.3.0 (237)[org.openhab.binding.homematic.internal.handler.HomematicThingHandlerFactory(347)] : Error during instantiation of the implementation object

00:09:45.648 [DEBUG] [.handler.HomematicThingHandlerFactory] - bundle org.openhab.binding.homematic:3.3.0 (237)[org.openhab.binding.homematic.internal.handler.HomematicThingHandlerFactory(347)] : Failed creating the component instance; see log for reason
00:09:45.649 [DEBUG] [.handler.HomematicThingHandlerFactory] - bundle org.openhab.binding.homematic:3.3.0 (237)[org.openhab.binding.homematic.internal.handler.HomematicThingHandlerFactory(347)] : Querying state satisfied
00:09:45.649 [DEBUG] [.handler.HomematicThingHandlerFactory] - bundle org.openhab.binding.homematic:3.3.0 (237)[org.openhab.binding.homematic.internal.handler.HomematicThingHandlerFactory(347)] : Changed state from satisfied to satisfied
00:09:45.649 [WARN ] [ig.discovery.internal.PersistentInbox] - bundle org.openhab.core.config.discovery:3.3.0 (161)[org.openhab.core.config.discovery.internal.PersistentInbox(105)] : Could not get service from ref {org.openhab.core.thing.binding.ThingHandlerFactory}={service.id=527, service.bundleid=237, service.scope=bundle, component.name=org.openhab.binding.homematic.internal.handler.HomematicThingHandlerFactory, component.id=347}
00:09:45.650 [WARN ] [ig.discovery.internal.PersistentInbox] - bundle org.openhab.core.config.discovery:3.3.0 (161)[org.openhab.core.config.discovery.internal.PersistentInbox(105)] : DependencyManager : invokeBindMethod : Service not available from service registry for ServiceReference {org.openhab.core.thing.binding.ThingHandlerFactory}={service.id=527, service.bundleid=237, service.scope=bundle, component.name=org.openhab.binding.homematic.internal.handler.HomematicThingHandlerFactory, component.id=347} for reference ThingHandlerFactory
00:09:45.650 [DEBUG] [.handler.HomematicThingHandlerFactory] - bundle org.openhab.binding.homematic:3.3.0 (237)[org.openhab.binding.homematic.internal.handler.HomematicThingHandlerFactory(347)] : dm $000 tracking 4 SingleStatic added {org.openhab.binding.homematic.internal.type.HomematicTypeGenerator}={service.id=526, service.bundleid=237, service.scope=bundle, component.name=org.openhab.binding.homematic.internal.type.HomematicTypeGeneratorImpl, component.id=352} (exit)
00:10:34.823 [DEBUG] [HomematicChannelGroupTypeProviderImpl] - bundle org.openhab.binding.homematic:3.3.0 (237)[org.openhab.binding.homematic.internal.type.HomematicChannelGroupTypeProviderImpl(348)] : Querying state active
00:10:34.824 [DEBUG] [iscovery.HomegearDiscoveryParticipant] - bundle org.openhab.binding.homematic:3.3.0 (237)[org.openhab.binding.homematic.internal.discovery.HomegearDiscoveryParticipant(346)] : Querying state active
00:10:34.824 [DEBUG] [nternal.discovery.CcuDiscoveryService] - bundle org.openhab.binding.homematic:3.3.0 (237)[org.openhab.binding.homematic.internal.discovery.CcuDiscoveryService(345)] : Querying state active
00:10:34.824 [DEBUG] [omematicConfigDescriptionProviderImpl] - bundle org.openhab.binding.homematic:3.3.0 (237)[org.openhab.binding.homematic.internal.type.HomematicConfigDescriptionProviderImpl(350)] : Querying state active
00:10:34.825 [DEBUG] [l.type.HomematicThingTypeProviderImpl] - bundle org.openhab.binding.homematic:3.3.0 (237)[org.openhab.binding.homematic.internal.type.HomematicThingTypeProviderImpl(351)] : Querying state active
00:10:34.825 [DEBUG] [.handler.HomematicThingHandlerFactory] - bundle org.openhab.binding.homematic:3.3.0 (237)[org.openhab.binding.homematic.internal.handler.HomematicThingHandlerFactory(347)] : Querying state satisfied

And here is the bundle:diag

openhab> bundle:diag 237
openHAB Add-ons :: Bundles :: Homematic Binding (237)
-----------------------------------------------------
Status: Waiting
Declarative Services
org.openhab.binding.homematic.internal.type.HomematicChannelGroupTypeProviderImpl (307)
org.openhab.binding.homematic.internal.discovery.HomegearDiscoveryParticipant (305)
org.openhab.binding.homematic.internal.discovery.CcuDiscoveryService (304)
org.openhab.binding.homematic.internal.type.HomematicConfigDescriptionProviderImpl (309)
org.openhab.binding.homematic.internal.type.HomematicThingTypeProviderImpl (310)
org.openhab.binding.homematic.internal.handler.HomematicThingHandlerFactory (306)
org.openhab.binding.homematic.internal.type.HomematicTypeGeneratorImpl (311)
org.openhab.binding.homematic.internal.type.HomematicChannelTypeProviderImpl (308)

Furthermore there are some issues with the UI. For example i can't add things to the binding, if i do it manually, it stays on Uninitialized.

Steps to Reproduce (for Bugs)

Fresh install of openhab docker container on ubuntu server following the instructions on https://hub.docker.com/r/openhab/openhab/ for local directory mount. In short:

cd /opt/openhab
mkdir conf addons userdata
chown -R openhab:openhab conf addons userdata

Copy the following docker-compose file to /opt/openhab

services:
  openhab:
    image: "openhab/openhab:3.3.0"
    restart: always
    network_mode: host
    volumes:
      - "/etc/localtime:/etc/localtime:ro"
      - "/etc/timezone:/etc/timezone:ro"
      - "/opt/openhab/addons:/openhab/addons"
      - "/opt/openhab/conf:/openhab/conf"
      - "/opt/openhab/userdata:/openhab/userdata"
    environment:
      CRYPTO_POLICY: "unlimited"
      EXTRA_JAVA_OPTS: "-Duser.timezone=Europe/Berlin"
      OPENHAB_HTTP_PORT: "9081"
      OPENHAB_HTTPS_PORT: "9082"

then

docker-compose up -d

and install the Homematic Binding via UI, console (with feature:install) addons.cfg, etc.

My Environment

Version used: Openhab 3.3.0 / Docker version 20.10.18
Operating System: Ubuntu Server 20.04 LTS

MHerbst commented 1 year ago

I don't think that this is a bug in the binding. It looks like there are some port mappings missing in your Docker configuration. The binding listens on several ports and is wating for events from the CCU. See the binding's documentation for the list of ports.

BTW: The forum is much better place if you are looking for help with problems like this. There are several users of the Homematic binding within a docker container and there are several thread in the forum.

jeremias-jordan commented 1 year ago

But as long as i understand the docker configuration correctly, there should be no port mappings necessary because i've used the host network instead of a bridge so the container should have access to all ports on the host system. That's also the official recommendation on docker hub.

I also checked on the host system if any of the ports are blocked by the firewall or other processes and there were no issues. I've also searched in forums and at least with older versions, this configuration should technically work. If i have overlooked anything obvious, i would be thankful for hints where to start debugging this issue.

Anyway, sorry if this isn't a bug. I'll post my issue in openhab forums.

jeremias-jordan commented 1 year ago

Update:

The Problem was in the ThreadPool of jetty. This was an additional part of my openhab.log;

2022-11-10 22:56:25.684 [DEBUG] [handler.HomematicThingHandlerFactory] - bundle org.openhab.binding.homematic:3.3.0 (252)[org.openhab.binding.homematic.internal.handler.HomematicThingHandlerFactory(318)] : For dependency $003, optional: false; to bind: [[RefPair: ref: [{org.openhab.core.io.net.http.HttpClientFactory, org.openhab.core.io.net.http.WebSocketFactory}={service.id=183, maxThreadsShared=44, service.bundleid=173, service.scope=bundle, maxThreadsCustom=44, minThreadsCustom=10, minThreadsShared=10, service.pid=org.openhab.webclient, component.name=org.openhab.core.io.net.http.internal.WebClientFactoryImpl, component.id=73}] service: [org.openhab.core.io.net.http.internal.WebClientFactoryImpl@6c794702]]]
java.lang.IllegalStateException: Insufficient configured threads: required=44 < max=44 for QueuedThreadPool[OH-httpClient-common]@165618a4{STARTED,10<=20<=44,i=0,r=-1,q=0}[ReservedThreadExecutor@ec8b27e{reserved=0/4,pending=0}]
        at org.eclipse.jetty.util.thread.ThreadPoolBudget.check(ThreadPoolBudget.java:165) ~[?:?]
        at org.eclipse.jetty.util.thread.ThreadPoolBudget.leaseTo(ThreadPoolBudget.java:141) ~[?:?]
        at org.eclipse.jetty.util.thread.ThreadPoolBudget.leaseFrom(ThreadPoolBudget.java:191) ~[?:?]
        at org.apache.karaf.features.internal.service.FeaturesServiceImpl.lambda$doProvisionInThread$13(FeaturesServiceImpl.java:1004) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
        at java.lang.Thread.run(Thread.java:829) [?:?]
        at org.apache.karaf.features.internal.service.FeaturesServiceImpl.lambda$doProvisionInThread$13(FeaturesServiceImpl.java:1004) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
        at java.lang.Thread.run(Thread.java:829) [?:?]
Caused by: java.lang.IllegalStateException: Insufficient configured threads: required=44 < max=44 for QueuedThreadPool[OH-httpClient-common]@165618a4{STARTED,10<=20<=44,i=0,r=-1,q=0}[ReservedThreadExecutor@ec8b27e{reserved=0/4,pending=0}]
        at org.eclipse.jetty.util.thread.ThreadPoolBudget.check(ThreadPoolBudget.java:165) ~[?:?]
        at org.eclipse.jetty.util.thread.ThreadPoolBudget.leaseTo(ThreadPoolBudget.java:141) ~[?:?]
        at org.eclipse.jetty.util.thread.ThreadPoolBudget.leaseFrom(ThreadPoolBudget.java:191) ~[?:?]

Got the solution from here: https://community.openhab.org/t/fix-for-jetty-error-when-running-on-host-with-many-cores/57449/7

I just added these lines to the runtime.cfg:

org.eclipse.smarthome.webclient:minThreadsShared=10
org.eclipse.smarthome.webclient:maxThreadsShared=45
org.eclipse.smarthome.webclient:minThreadsCustom=5
org.eclipse.smarthome.webclient:maxThreadsCustom=45

org.openhab.webclient:minThreadsShared = 10
org.openhab.webclient:maxThreadsShared = 45
org.openhab.webclient:minThreadsCustom = 10
org.openhab.webclient:maxThreadsCustom = 45

Honestly, still seems like a bug to me or is it intended to change the ThreadPooling manually as end user?

lolodomo commented 1 year ago

Honestly, still seems like a bug to me or is it intended to change the ThreadPooling manually as end user?

You are probably in a very unusual setup if so many threads are required for HTTP requests in OH. What are the bindings installed in your OH system ? Maybe some are badly implemented.

I guess the default settings are OK for 99% of users. We cannot set the pool too much high by default as most of users are using small machines with limited resources like RPI. So I believe only users with a very unusual setup should have to change these settings.

jeremias-jordan commented 1 year ago

@lolodomo i guess the only way my setup could be unusual is the hardware itself, i have a server with a Xenon E5-2650L v2 processor with 10 Cores. Besides that, the setup is pretty common. Does a CPU with many Cores pump up the required thread count? Or which instance is responsible for calculating the required threads?

Currently i have the MQTT and modbus Binding installed. But as i wrote in Steps to Reproduce the issue occurred even on a fresh install of everything with nothing but the homematic binding installed. Other Bindings did work well.

lolodomo commented 1 year ago

Does a CPU with many Cores pump up the required thread count?

I am not enough expert to answer to that question but looks like a good question.

lolodomo commented 1 year ago

... but @mhilbush was mentioning a problem with many cores in that issue: https://github.com/eclipse-archived/smarthome/issues/6574

jeremias-jordan commented 1 year ago

@lolodomo Thanks, seems to really be an hardware issue then and probably not relevant for most users on small machines. However on a more powerful server the thread management seems to be badly implemented. I don't think it's that efficient to have 45 (idle) threads just to deal with http on one openhab binding.

Unfortunately i'm also not an expert and i still don't understand how the required Threads are calculated even after reading the issue you mentioned and parts of the source code. It would be great if someone, who understands it could just set a fixed limit for Thread creation so that there aren't that many threads running on idle.

lolodomo commented 1 year ago

Maybe @mhilbush can explain the link between the required threads and the number of cores?

MHerbst commented 1 year ago

In my opinion this issue is not Homematic specific. I think similar problems can happen with other binding, too. Can you change the subject?

lsiepel commented 3 weeks ago

@J-N-K i think this should be moved to core as these webclient thread count is not something that is controlled by the addons repo is it?

openhab / openhab-addons