Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Open
jeremias-jordan opened this issue Nov 9, 2022 · 12 comments
Labels
awaiting feedback bug An unexpected problem or unintended behavior of an add-on

Comments

@jeremias-jordan
Copy link

jeremias-jordan commented Nov 9, 2022

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)

  1. 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
@jeremias-jordan jeremias-jordan added the bug An unexpected problem or unintended behavior of an add-on label Nov 9, 2022
@MHerbst
Copy link
Contributor

MHerbst commented Nov 10, 2022

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
Copy link
Author

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
Copy link
Author

jeremias-jordan commented Nov 10, 2022

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
Copy link
Contributor

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
Copy link
Author

@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
Copy link
Contributor

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
Copy link
Contributor

lolodomo commented Nov 11, 2022

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

@jeremias-jordan
Copy link
Author

@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
Copy link
Contributor

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

@lolodomo lolodomo changed the title [homematic] binding hangs on Waiting [homematic] binding hangs on Waiting (OH run by processor with 10 cores) Nov 12, 2022
@MHerbst
Copy link
Contributor

MHerbst commented Nov 14, 2022

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

@jeremias-jordan jeremias-jordan changed the title [homematic] binding hangs on Waiting (OH run by processor with 10 cores) [OH-httpClient-common] binding hangs on Waiting (OH run by processor with 10 cores) Nov 14, 2022
@lsiepel
Copy link
Contributor

lsiepel commented Jul 23, 2024

@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?

@lsiepel
Copy link
Contributor

lsiepel commented Aug 30, 2024

@jeremias-jordan are you able to confirm this still exists on openHAB 4.2.x ? As many changes (java17, jetty version and others) have been merged it might already be fixed. I also remember something about spawning threads on demand has changed. but can't remember the details anymore.

If the solution is to change the runtime config, this issue should be transferred to the distro repostitory

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
awaiting feedback bug An unexpected problem or unintended behavior of an add-on
Projects
None yet
Development

No branches or pull requests

4 participants