HTTP binding data refresh interval extending itslef

Tomas_Vrana · June 12, 2024, 7:35pm

Hi,
it seems to me that after OH restart, the HTTP binding refresh interval extends itself until the thing valued does not change at all (after 4 or 5 days).
The refresh interval is set 5 seconds and few hours after restart it really gets updated that often:

On the second day the refresh interval seems to be already 5 minutes or so:

Third day 20 minutes:

I can see this behaviour on more than one thing a it does not matter if I use oh-http binding or SmartHomeJ http binding. Turning debuggin on has not provided me any hints sofar. Having to periadically resatart OH is very annoying, I would appreciate any hints on what might be wrong.
Tom

rlkoshak · June 12, 2024, 8:03pm

What is the system load and swap usage on the machine running openHAB?

Tomas_Vrana · June 13, 2024, 2:35pm

As far as I understand it, the system load is fine, and no swap is used…

##   Release = Debian GNU/Linux 12 (bookworm)
##    Kernel = Linux 6.6.20+rpt-rpi-v8
##  Platform = BCM43455 37.4MHz Raspberry Pi 3+-0190
##    Uptime = 10 day(s). 04:11:57
## CPU Usage = 1.93% avg over 4 cpu(s) ( core(s) x - socket(s))
##  CPU Load = 1m: 0.36, 5m: 0.27, 15m: 0.26
##    Memory = Free: 5.35GB (70%), Used: 2.44GB (30%), Total: 7.67GB
##      Swap = Free: 2.99GB (100%), Used: 0.00GB (0%), Total: 2.99GB
##      Root = Free: 97.96GB (94%), Used: 5.96GB (6%), Total: 109.51GB
##   Updates = 28 apt updates available.
##  Sessions = 1 session(s)
## Processes = 139 running processes of 4194304 maximum processes

rlkoshak · June 13, 2024, 3:35pm

Yes, those stats look good. Double check when the delays start to become more pronounced just to make sure that the problem isn’t lack of resources.

I’ve never seen anything like this reported before that wasn’t caused by a high system load and/or high usage of swap. So it’s a bit of a mystery what could cause this behavior.

Tomas_Vrana · June 13, 2024, 3:54pm

I definitely agree on the mystery part. It is basically happening online, at the moment

2024-06-13 16:10:10.383 [TRACE] [ttp.internal.http.RefreshingUrlCache] - Requesting refresh (retry=false) from 'http://192.168.99.19/123solar/programs/power.php?invtnum=1' with timeout 100ms
2024-06-13 16:10:10.383 [TRACE] [ttp.internal.http.RefreshingUrlCache] - Requesting refresh (retry=false) from 'http://192.168.99.19/123solar/programs/power.php?invtnum=1' with timeout 100ms
2024-06-13 16:10:10.384 [TRACE] [ttp.internal.http.RefreshingUrlCache] - Sending to 'http://192.168.99.19/123solar/programs/power.php?invtnum=1': Method = {GET}, Headers = {Accept-Encoding: gzip, User-Agent: Jetty/9.4.52.v20230823}, Content = {null}
2024-06-13 16:10:10.384 [TRACE] [ttp.internal.http.RefreshingUrlCache] - Sending to 'http://192.168.99.19/123solar/programs/power.php?invtnum=1': Method = {GET}, Headers = {Accept-Encoding: gzip, User-Agent: Jetty/9.4.52.v20230823}, Content = {null}
2024-06-13 16:10:10.395 [TRACE] [p.internal.http.HttpResponseListener] - Received from 'http://192.168.99.19/123solar/programs/power.php?invtnum=1': Code = {200}, Headers = {Server: nginx/1.16.1, Date: Thu, 13 Jun 2024 15:10:10 GMT, Content-Type: application/json, Transfer-Encoding: chunked, Connection: keep-alive, Keep-Alive: timeout=5, X-Powered-By: PHP/7.4.5}, Content = {{"POWER":9669}}
2024-06-13 16:10:10.395 [TRACE] [p.internal.http.HttpResponseListener] - Received from 'http://192.168.99.19/123solar/programs/power.php?invtnum=1': Code = {200}, Headers = {Server: nginx/1.16.1, Date: Thu, 13 Jun 2024 15:10:10 GMT, Content-Type: application/json, Transfer-Encoding: chunked, Connection: keep-alive, Keep-Alive: timeout=5, X-Powered-By: PHP/7.4.5}, Content = {{"POWER":9669}}
2024-06-13 16:10:10.399 [TRACE] [.HttpDynamicStateDescriptionProvider] - returning new stateDescription for http:url:977309dc35:fve_vykon_httpj
2024-06-13 16:37:12.398 [TRACE] [ttp.internal.http.RefreshingUrlCache] - Requesting refresh (retry=false) from 'http://192.168.99.19/123solar/programs/power.php?invtnum=1' with timeout 100ms
2024-06-13 16:37:12.399 [TRACE] [ttp.internal.http.RefreshingUrlCache] - Requesting refresh (retry=false) from 'http://192.168.99.19/123solar/programs/power.php?invtnum=1' with timeout 100ms
2024-06-13 16:37:12.399 [TRACE] [ttp.internal.http.RefreshingUrlCache] - Sending to 'http://192.168.99.19/123solar/programs/power.php?invtnum=1': Method = {GET}, Headers = {Accept-Encoding: gzip, User-Agent: Jetty/9.4.52.v20230823}, Content = {null}
2024-06-13 16:37:12.400 [TRACE] [ttp.internal.http.RefreshingUrlCache] - Sending to 'http://192.168.99.19/123solar/programs/power.php?invtnum=1': Method = {GET}, Headers = {Accept-Encoding: gzip, User-Agent: Jetty/9.4.52.v20230823}, Content = {null}
2024-06-13 16:37:12.408 [TRACE] [p.internal.http.HttpResponseListener] - Received from 'http://192.168.99.19/123solar/programs/power.php?invtnum=1': Code = {200}, Headers = {Server: nginx/1.16.1, Date: Thu, 13 Jun 2024 15:37:12 GMT, Content-Type: application/json, Transfer-Encoding: chunked, Connection: keep-alive, Keep-Alive: timeout=5, X-Powered-By: PHP/7.4.5}, Content = {{"POWER":2748}}
2024-06-13 16:37:12.409 [TRACE] [p.internal.http.HttpResponseListener] - Received from 'http://192.168.99.19/123solar/programs/power.php?invtnum=1': Code = {200}, Headers = {Server: nginx/1.16.1, Date: Thu, 13 Jun 2024 15:37:12 GMT, Content-Type: application/json, Transfer-Encoding: chunked, Connection: keep-alive, Keep-Alive: timeout=5, X-Powered-By: PHP/7.4.5}, Content = {{"POWER":2748}}

the refresh interval is about 26 minutes… Oh and the server in question is another RPi connected via a gigabit ethernet switch. On the other hand, this piece of log might be related and looks suspicious to me:

2024-06-10 18:50:21.990 [DEBUG] [.HttpDynamicStateDescriptionProvider] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpDynamicStateDescriptionProvider] : Component created: DS=DS13, implementation=org.openhab.binding.http.internal.HttpDynamicStateDescriptionProvider, immediate=true, default-enabled=true, factory=null, configuration-policy=optional, activate=activate, deactivate=deactivate, modified=null configuration-pid=[org.openhab.binding.http.internal.HttpDynamicStateDescriptionProvider]
2024-06-10 18:50:21.991 [DEBUG] [.HttpDynamicStateDescriptionProvider] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpDynamicStateDescriptionProvider] : Component Services: scope=singleton, services=[org.openhab.core.thing.type.DynamicStateDescriptionProvider, org.openhab.binding.http.internal.HttpDynamicStateDescriptionProvider]
2024-06-10 18:50:21.993 [DEBUG] [.HttpDynamicStateDescriptionProvider] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpDynamicStateDescriptionProvider] : Component Properties: {osgi.ds.satisfying.condition.target=(osgi.condition.id=true)}
2024-06-10 18:50:21.996 [DEBUG] [.HttpDynamicStateDescriptionProvider] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpDynamicStateDescriptionProvider] : Querying state disabled
2024-06-10 18:50:21.998 [DEBUG] [.HttpDynamicStateDescriptionProvider] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpDynamicStateDescriptionProvider] : Querying state disabled
2024-06-10 18:50:21.999 [DEBUG] [.HttpDynamicStateDescriptionProvider] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpDynamicStateDescriptionProvider] : Component can not be activated since it is in state disabled
2024-06-10 18:50:22.001 [DEBUG] [.HttpDynamicStateDescriptionProvider] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpDynamicStateDescriptionProvider] : Querying state disabled
2024-06-10 18:50:22.003 [DEBUG] [.HttpDynamicStateDescriptionProvider] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpDynamicStateDescriptionProvider(346)] : Updating target filters
2024-06-10 18:50:22.004 [DEBUG] [.HttpDynamicStateDescriptionProvider] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpDynamicStateDescriptionProvider(346)] :  No existing service listener to unregister for dependency osgi.ds.satisfying.condition
2024-06-10 18:50:22.006 [DEBUG] [.HttpDynamicStateDescriptionProvider] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpDynamicStateDescriptionProvider(346)] : Setting target property for dependency osgi.ds.satisfying.condition to (osgi.condition.id=true)
2024-06-10 18:50:22.008 [DEBUG] [.HttpDynamicStateDescriptionProvider] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpDynamicStateDescriptionProvider(346)] : New service tracker for osgi.ds.satisfying.condition, initial active: false, previous references: {}, classFilter: (objectClass=org.osgi.service.condition.Condition), initialReferenceFilter (&(objectClass=org.osgi.service.condition.Condition)(osgi.condition.id=true))
2024-06-10 18:50:22.009 [DEBUG] [.HttpDynamicStateDescriptionProvider] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpDynamicStateDescriptionProvider(346)] : dm osgi.ds.satisfying.condition tracker reset (closed)
2024-06-10 18:50:22.011 [DEBUG] [.HttpDynamicStateDescriptionProvider] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpDynamicStateDescriptionProvider(346)] : dm osgi.ds.satisfying.condition tracking 1 SingleDynamic added {org.osgi.service.condition.Condition}={service.id=6, service.bundleid=0, service.scope=singleton, service.pid=0.org.osgi.service.condition.ConditionImpl, osgi.condition.id=true} (enter)
2024-06-10 18:50:22.013 [DEBUG] [.HttpDynamicStateDescriptionProvider] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpDynamicStateDescriptionProvider(346)] : dm osgi.ds.satisfying.condition tracking 1 SingleDynamic added {org.osgi.service.condition.Condition}={service.id=6, service.bundleid=0, service.scope=singleton, service.pid=0.org.osgi.service.condition.ConditionImpl, osgi.condition.id=true} (exit)
2024-06-10 18:50:22.015 [DEBUG] [.HttpDynamicStateDescriptionProvider] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpDynamicStateDescriptionProvider(346)] : dm osgi.ds.satisfying.condition tracker opened
2024-06-10 18:50:22.016 [DEBUG] [.HttpDynamicStateDescriptionProvider] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpDynamicStateDescriptionProvider(346)] : registering service listener for dependency osgi.ds.satisfying.condition
2024-06-10 18:50:22.018 [DEBUG] [.HttpDynamicStateDescriptionProvider] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpDynamicStateDescriptionProvider(346)] : Changed state from disabled to unsatisfiedReference
2024-06-10 18:50:22.020 [DEBUG] [.HttpDynamicStateDescriptionProvider] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpDynamicStateDescriptionProvider(346)] : Component enabled
2024-06-10 18:50:22.021 [DEBUG] [.HttpDynamicStateDescriptionProvider] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpDynamicStateDescriptionProvider(346)] : ActivateInternal
2024-06-10 18:50:22.022 [DEBUG] [.HttpDynamicStateDescriptionProvider] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpDynamicStateDescriptionProvider(346)] : Querying state unsatisfiedReference
2024-06-10 18:50:22.024 [DEBUG] [.HttpDynamicStateDescriptionProvider] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpDynamicStateDescriptionProvider(346)] : Querying state unsatisfiedReference
2024-06-10 18:50:22.025 [DEBUG] [.HttpDynamicStateDescriptionProvider] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpDynamicStateDescriptionProvider(346)] : Activating component from state unsatisfiedReference
2024-06-10 18:50:22.027 [DEBUG] [.HttpDynamicStateDescriptionProvider] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpDynamicStateDescriptionProvider(346)] : Querying state unsatisfiedReference
2024-06-10 18:50:22.028 [DEBUG] [.HttpDynamicStateDescriptionProvider] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpDynamicStateDescriptionProvider(346)] : Querying state unsatisfiedReference
2024-06-10 18:50:22.030 [DEBUG] [.HttpDynamicStateDescriptionProvider] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpDynamicStateDescriptionProvider(346)] : Changed state from unsatisfiedReference to satisfied
2024-06-10 18:50:22.032 [DEBUG] [.HttpDynamicStateDescriptionProvider] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpDynamicStateDescriptionProvider(346)] : registration change queue [registered]
2024-06-10 18:50:22.038 [DEBUG] [.HttpDynamicStateDescriptionProvider] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpDynamicStateDescriptionProvider(346)] : Checking constructor public org.openhab.binding.http.internal.HttpDynamicStateDescriptionProvider()
2024-06-10 18:50:22.046 [DEBUG] [.HttpDynamicStateDescriptionProvider] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpDynamicStateDescriptionProvider(346)] : Found constructor with 0 arguments : public org.openhab.binding.http.internal.HttpDynamicStateDescriptionProvider()
2024-06-10 18:50:22.048 [DEBUG] [.HttpDynamicStateDescriptionProvider] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpDynamicStateDescriptionProvider(346)] : This thread collected dependencies
2024-06-10 18:50:22.049 [DEBUG] [.HttpDynamicStateDescriptionProvider] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpDynamicStateDescriptionProvider(346)] : getService (single component manager) dependencies collected.
2024-06-10 18:50:22.051 [DEBUG] [.HttpDynamicStateDescriptionProvider] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpDynamicStateDescriptionProvider(346)] : Querying state satisfied
2024-06-10 18:50:22.053 [DEBUG] [.HttpDynamicStateDescriptionProvider] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpDynamicStateDescriptionProvider(346)] : Querying state satisfied
2024-06-10 18:50:22.054 [DEBUG] [.HttpDynamicStateDescriptionProvider] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpDynamicStateDescriptionProvider(346)] : For dependency osgi.ds.satisfying.condition, optional: false; to bind: [[RefPair: ref: [{org.osgi.service.condition.Condition}={service.id=6, service.bundleid=0, service.scope=singleton, service.pid=0.org.osgi.service.condition.ConditionImpl, osgi.condition.id=true}] service: [null]]]
2024-06-10 18:50:22.057 [DEBUG] [.HttpDynamicStateDescriptionProvider] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpDynamicStateDescriptionProvider(346)] : getting activate: activate
2024-06-10 18:50:22.059 [DEBUG] [.HttpDynamicStateDescriptionProvider] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpDynamicStateDescriptionProvider(346)] : Locating method activate in class org.openhab.binding.http.internal.HttpDynamicStateDescriptionProvider
2024-06-10 18:50:22.062 [DEBUG] [.HttpDynamicStateDescriptionProvider] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpDynamicStateDescriptionProvider(346)] : Declared Method org.openhab.binding.http.internal.HttpDynamicStateDescriptionProvider.activate([interface org.osgi.service.component.ComponentContext]) not found
2024-06-10 18:50:22.064 [DEBUG] [.HttpDynamicStateDescriptionProvider] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpDynamicStateDescriptionProvider(346)] : Locating method activate in class java.lang.Object
2024-06-10 18:50:22.066 [DEBUG] [.HttpDynamicStateDescriptionProvider] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpDynamicStateDescriptionProvider(346)] : Declared Method java.lang.Object.activate([interface org.osgi.service.component.ComponentContext]) not found
2024-06-10 18:50:22.068 [DEBUG] [.HttpDynamicStateDescriptionProvider] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpDynamicStateDescriptionProvider(346)] : activate method [activate] not found, ignoring
2024-06-10 18:50:22.070 [DEBUG] [.HttpDynamicStateDescriptionProvider] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpDynamicStateDescriptionProvider(346)] : Set implementation object for component
2024-06-10 18:50:22.072 [DEBUG] [.HttpDynamicStateDescriptionProvider] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpDynamicStateDescriptionProvider(346)] : Changed state from satisfied to active
2024-06-10 18:50:22.076 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory] : Dependency Manager created $000interface=org.openhab.core.io.net.http.HttpClientFactory, filter=null, policy=static, cardinality=1..1, bind=null, unbind=null, updated=null, field=null, field-option=null, collection-type=service, parameter=0
2024-06-10 18:50:22.078 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory] : Dependency Manager created $001interface=org.openhab.binding.http.internal.HttpDynamicStateDescriptionProvider, filter=null, policy=static, cardinality=1..1, bind=null, unbind=null, updated=null, field=null, field-option=null, collection-type=service, parameter=1
2024-06-10 18:50:22.080 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory] : Dependency Manager created osgi.ds.satisfying.conditioninterface=org.osgi.service.condition.Condition, filter=(osgi.condition.id=true), policy=dynamic, cardinality=1..1, bind=null, unbind=null, updated=null, field=null, field-option=null, collection-type=null, parameter=null
2024-06-10 18:50:22.082 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory] : Component created: DS=DS14, implementation=org.openhab.binding.http.internal.HttpHandlerFactory, immediate=false, default-enabled=true, factory=null, configuration-policy=optional, activate=activate, deactivate=deactivate, modified=null configuration-pid=[binding.http]
2024-06-10 18:50:22.084 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory] : Component Services: scope=singleton, services=[org.openhab.core.thing.binding.ThingHandlerFactory]
2024-06-10 18:50:22.086 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory] : Component Properties: {osgi.ds.satisfying.condition.target=(osgi.condition.id=true)}
2024-06-10 18:50:22.088 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory] : Querying state disabled
2024-06-10 18:50:22.089 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory] : Querying state disabled
2024-06-10 18:50:22.091 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory] : Component can not be activated since it is in state disabled
2024-06-10 18:50:22.093 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory] : Querying state disabled
2024-06-10 18:50:22.095 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory(347)] : Updating target filters
2024-06-10 18:50:22.096 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory(347)] : No change in target property for dependency $000: currently registered: false
2024-06-10 18:50:22.099 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory(347)] :  No existing service listener to unregister for dependency $000
2024-06-10 18:50:22.100 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory(347)] : Setting target property for dependency $000 to null
2024-06-10 18:50:22.102 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory(347)] : New service tracker for $000, initial active: false, previous references: {}, classFilter: (objectClass=org.openhab.core.io.net.http.HttpClientFactory), initialReferenceFilter (objectClass=org.openhab.core.io.net.http.HttpClientFactory)
2024-06-10 18:50:22.104 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory(347)] : dm $000 tracker reset (closed)
2024-06-10 18:50:22.107 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory(347)] : dm $000 tracking 1 SingleStatic added {org.openhab.core.io.net.http.HttpClientFactory, org.openhab.core.io.net.http.WebSocketFactory}={service.id=294, service.bundleid=180, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), component.name=org.openhab.core.io.net.http.internal.WebClientFactoryImpl, component.id=161} (enter)
2024-06-10 18:50:22.109 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory(347)] : dm $000 tracking 1 SingleStatic active: false trackerOpened: false optional: false
2024-06-10 18:50:22.112 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory(347)] : dm $000 tracking 1 SingleStatic added {org.openhab.core.io.net.http.HttpClientFactory, org.openhab.core.io.net.http.WebSocketFactory}={service.id=294, service.bundleid=180, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), component.name=org.openhab.core.io.net.http.internal.WebClientFactoryImpl, component.id=161} (exit)
2024-06-10 18:50:22.114 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory(347)] : dm $000 tracker opened
2024-06-10 18:50:22.116 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory(347)] : registering service listener for dependency $000
2024-06-10 18:50:22.118 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory(347)] : No change in target property for dependency $001: currently registered: false
2024-06-10 18:50:22.119 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory(347)] :  No existing service listener to unregister for dependency $001
2024-06-10 18:50:22.121 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory(347)] : Setting target property for dependency $001 to null
2024-06-10 18:50:22.123 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory(347)] : New service tracker for $001, initial active: false, previous references: {}, classFilter: (objectClass=org.openhab.binding.http.internal.HttpDynamicStateDescriptionProvider), initialReferenceFilter (objectClass=org.openhab.binding.http.internal.HttpDynamicStateDescriptionProvider)
2024-06-10 18:50:22.125 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory(347)] : dm $001 tracker reset (closed)
2024-06-10 18:50:22.129 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory(347)] : dm $001 tracking 2 SingleStatic added {org.openhab.core.thing.type.DynamicStateDescriptionProvider, org.openhab.binding.http.internal.HttpDynamicStateDescriptionProvider}={service.id=548, service.bundleid=292, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), component.name=org.openhab.binding.http.internal.HttpDynamicStateDescriptionProvider, component.id=346} (enter)
2024-06-10 18:50:22.131 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory(347)] : dm $001 tracking 2 SingleStatic active: false trackerOpened: false optional: false
2024-06-10 18:50:22.134 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory(347)] : dm $001 tracking 2 SingleStatic added {org.openhab.core.thing.type.DynamicStateDescriptionProvider, org.openhab.binding.http.internal.HttpDynamicStateDescriptionProvider}={service.id=548, service.bundleid=292, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), component.name=org.openhab.binding.http.internal.HttpDynamicStateDescriptionProvider, component.id=346} (exit)
2024-06-10 18:50:22.136 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory(347)] : dm $001 tracker opened
2024-06-10 18:50:22.138 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory(347)] : registering service listener for dependency $001
2024-06-10 18:50:22.140 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory(347)] :  No existing service listener to unregister for dependency osgi.ds.satisfying.condition
2024-06-10 18:50:22.142 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory(347)] : Setting target property for dependency osgi.ds.satisfying.condition to (osgi.condition.id=true)
2024-06-10 18:50:22.144 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory(347)] : New service tracker for osgi.ds.satisfying.condition, initial active: false, previous references: {}, classFilter: (objectClass=org.osgi.service.condition.Condition), initialReferenceFilter (&(objectClass=org.osgi.service.condition.Condition)(osgi.condition.id=true))
2024-06-10 18:50:22.146 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory(347)] : dm osgi.ds.satisfying.condition tracker reset (closed)
2024-06-10 18:50:22.149 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory(347)] : dm osgi.ds.satisfying.condition tracking 3 SingleDynamic added {org.osgi.service.condition.Condition}={service.id=6, service.bundleid=0, service.scope=singleton, service.pid=0.org.osgi.service.condition.ConditionImpl, osgi.condition.id=true} (enter)
2024-06-10 18:50:22.151 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory(347)] : dm osgi.ds.satisfying.condition tracking 3 SingleDynamic added {org.osgi.service.condition.Condition}={service.id=6, service.bundleid=0, service.scope=singleton, service.pid=0.org.osgi.service.condition.ConditionImpl, osgi.condition.id=true} (exit)
2024-06-10 18:50:22.152 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory(347)] : dm osgi.ds.satisfying.condition tracker opened
2024-06-10 18:50:22.154 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory(347)] : registering service listener for dependency osgi.ds.satisfying.condition
2024-06-10 18:50:22.156 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory(347)] : Changed state from disabled to unsatisfiedReference
2024-06-10 18:50:22.159 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory(347)] : Component enabled
2024-06-10 18:50:22.160 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory(347)] : ActivateInternal
2024-06-10 18:50:22.162 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory(347)] : Querying state unsatisfiedReference
2024-06-10 18:50:22.164 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory(347)] : Querying state unsatisfiedReference
2024-06-10 18:50:22.165 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory(347)] : Activating component from state unsatisfiedReference
2024-06-10 18:50:22.167 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory(347)] : Querying state unsatisfiedReference
2024-06-10 18:50:22.169 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory(347)] : Querying state unsatisfiedReference
2024-06-10 18:50:22.171 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory(347)] : Changed state from unsatisfiedReference to satisfied
2024-06-10 18:50:22.172 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory(347)] : registration change queue [registered]
2024-06-10 18:50:22.184 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory(347)] : Checking constructor public org.openhab.binding.http.internal.HttpHandlerFactory(org.openhab.core.io.net.http.HttpClientFactory,org.openhab.binding.http.internal.HttpDynamicStateDescriptionProvider)
2024-06-10 18:50:22.186 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory(347)] : getClassFromComponentClassLoader: Looking for interface class org.openhab.core.io.net.http.HttpClientFactory through loader of org.openhab.binding.http.internal.HttpHandlerFactory
2024-06-10 18:50:22.188 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory(347)] : getClassFromComponentClassLoader: Found class org.openhab.core.io.net.http.HttpClientFactory
2024-06-10 18:50:22.190 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory(347)] : getClassFromComponentClassLoader: Looking for interface class org.openhab.binding.http.internal.HttpDynamicStateDescriptionProvider through loader of org.openhab.binding.http.internal.HttpHandlerFactory
2024-06-10 18:50:22.192 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory(347)] : getClassFromComponentClassLoader: Found class org.openhab.binding.http.internal.HttpDynamicStateDescriptionProvider
2024-06-10 18:50:22.194 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory(347)] : Found constructor with 2 arguments : public org.openhab.binding.http.internal.HttpHandlerFactory(org.openhab.core.io.net.http.HttpClientFactory,org.openhab.binding.http.internal.HttpDynamicStateDescriptionProvider)
2024-06-10 18:50:22.196 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory(347)] : This thread collected dependencies
2024-06-10 18:50:22.198 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory(347)] : getService (single component manager) dependencies collected.
2024-06-10 18:50:22.200 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory(347)] : Querying state satisfied
2024-06-10 18:50:22.202 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory(347)] : Querying state satisfied
2024-06-10 18:50:22.204 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory(347)] : For dependency $000, optional: false; to bind: [[RefPair: ref: [{org.openhab.core.io.net.http.HttpClientFactory, org.openhab.core.io.net.http.WebSocketFactory}={service.id=294, service.bundleid=180, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), component.name=org.openhab.core.io.net.http.internal.WebClientFactoryImpl, component.id=161}] service: [null]]]
2024-06-10 18:50:22.205 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory(347)] : For dependency $001, optional: false; to bind: [[RefPair: ref: [{org.openhab.core.thing.type.DynamicStateDescriptionProvider, org.openhab.binding.http.internal.HttpDynamicStateDescriptionProvider}={service.id=548, service.bundleid=292, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), component.name=org.openhab.binding.http.internal.HttpDynamicStateDescriptionProvider, component.id=346}] service: [null]]]
2024-06-10 18:50:22.208 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory(347)] : For dependency osgi.ds.satisfying.condition, optional: false; to bind: [[RefPair: ref: [{org.osgi.service.condition.Condition}={service.id=6, service.bundleid=0, service.scope=singleton, service.pid=0.org.osgi.service.condition.ConditionImpl, osgi.condition.id=true}] service: [null]]]
2024-06-10 18:50:22.257 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory(347)] : getting activate: activate
2024-06-10 18:50:22.259 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory(347)] : Locating method activate in class org.openhab.binding.http.internal.HttpHandlerFactory
2024-06-10 18:50:22.262 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory(347)] : Declared Method org.openhab.binding.http.internal.HttpHandlerFactory.activate([interface org.osgi.service.component.ComponentContext]) not found
2024-06-10 18:50:22.263 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory(347)] : Locating method activate in class org.openhab.core.thing.binding.BaseThingHandlerFactory
2024-06-10 18:50:22.269 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory(347)] : Found activate method: protected void org.openhab.core.thing.binding.BaseThingHandlerFactory.activate(org.osgi.service.component.ComponentContext)
2024-06-10 18:50:22.271 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory(347)] : invoking activate: activate: parameters [org.apache.felix.scr.impl.manager.ComponentContextImpl]
2024-06-10 18:50:22.273 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory(347)] : invoked activate: activate
2024-06-10 18:50:22.275 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory(347)] : Set implementation object for component
2024-06-10 18:50:22.277 [DEBUG] [ing.http.internal.HttpHandlerFactory] - bundle org.openhab.binding.http:4.1.2 (292)[org.openhab.binding.http.internal.HttpHandlerFactory(347)] : Changed state from satisfied to active
2024-06-10 18:50:25.127 [DEBUG] [nding.http.internal.HttpThingHandler] - No authentication configured for thing 'http:url:solax'
2024-06-10 18:50:27.364 [DEBUG] [nding.http.internal.HttpThingHandler] - No authentication configured for thing 'http:url:b4ab08876b'
2024-06-10 18:50:27.445 [DEBUG] [nding.http.internal.HttpThingHandler] - No authentication configured for thing 'http:url:977309dc35'

Does it mean the binding is reloading itself ? The block seems to repeat itself every 5 seconds for a minute or two.

rlkoshak · June 13, 2024, 5:18pm

Those logs look like the web site being queried is responding right away so it’s not timing out. The requests that start at 16:10:10.383 and the response arrive by 16:10:10.395 (then again at 37:12).

I don’t think so. If the bundle were reloading itself over and over we’d see some logs from openHAB and karaf. All these logs are internal to the HTTP binding.

Tomas_Vrana · July 17, 2024, 11:07am

Well, whatever the problem was, it seems to be gone with upgrading to 4.2.0