[http] refresh and delay

Ah, okay, so you trigger the releases manually (no nightly build or the like) - that’s what I needed to know :wink:

Thanks and don’t feel stressed! :sweat_smile:

Hi again,

I think it’s been a while :slight_smile: and of course there was the release of v4.1 (although I must admit I did not upgrade yet :wink: )

Anyhow, timing is still critical for my Homepilot - it runs into errors due to overload timeout sporadically. From what I tested so far, having a delay between the two main HTTP requests would eliminate these errors.

Therefore, I am still very interested in the fixed HTTP binding in the Smarthome/J package, but the latest release still looks to be June 11 2023. Is there some hope for a new release meanwhile…? :innocent:

The release is available, I just forgot to add the Releases to GitHub.

1 Like

Hi, thanks again, - I just tested the new release.

As I am still using OpenHAB 4.0.4, I got version 4.0.2 of SmartHome/J / HTTP Binding installed automatically (updated from 4.0.0 previously)

Anyhow, I have the impression that the issue still exists…
Nothing fundamental has changed with my config so far, except from some channels added - but all of them belonging to only two stateExtensions.

So I set the delay time to 1000ms and the refresh time to 2s, as I planned before… and still got this message in the log:

2024-01-14 17:42:51.135 [WARN ] [nding.http.internal.HttpThingHandler] - 173 channels in thing http:url:HomePilot with a delay of 1000 incompatible with the configured refresh time. Refresh-Time increased to the minimum of 174

So, it still regards every channel as a separate request for computing the refresh time, although two cached requests would be sufficient… did I miss something?

Can you please send the thing config to me at github@klug.nrw? YAML code view preferred.

Thanks - I just sent the file.

It’s the full config which I am currently using as working.

If I simply change delay: 0 to delay: 100 (or higher, my goal would be 1000ms), I already get the warning mentioned before, and of course the actual refresh rate is overwritten as said.

Much thanks already!

I can’t reproduce that, can you show the output of list -s | grep http on the console?

Uhm… I’m a bit confused. Is list some alias or script you are using? At least, my console does not know that command, Google is not really helpful (only Python stuff) and as you are using grep I’m pretty sure you meant the bash console :upside_down_face: :wink:

By the way - I upgraded the SmarthomeJ package by uninstalling and re-installing it in the addons section. And nothing more than that - as I saw the version number changing from 4.0.0 to 4.0.2 and my Thing starting up again without errors I supposed everything was done.
I did not clear any caches or the like, nor did I restart the OH service or reboot. Is something like this required?

It has to be entered in openHABs console, not your shell…

Oh no, Complete Console Confusion! :sweat_smile:

Sorry - and thanks @hmerk for the hint!

Now, here we go:

openhab> list -s | grep http
 71 │ Active │  80 │ 3.4.5                  │ org.apache.cxf.cxf-rt-transports-http
110 │ Active │  80 │ 9.4.50.v20221201       │ org.eclipse.jetty.http2.client
170 │ Active │  80 │ 4.0.4                  │ org.openhab.core.io.http
171 │ Active │  80 │ 4.0.4                  │ org.openhab.core.io.http.auth
238 │ Active │  80 │ 4.0.0                  │ org.smarthomej.binding.http
245 │ Active │  80 │ 4.1.92.Final           │ io.netty.codec-http
260 │ Active │  80 │                │ org.apache.servicemix.bundles.okhttp
312 │ Active │  80 │ 4.0.2                  │ org.smarthomej.binding.http

somewhat interesting that there seems to be a SmarthomeJ HTTP binding 4.0.0 and 4.0.2 in parallel… Very suspicious that this might be the reason for the error, but I uninstalled 4.0.0 before successfully!

If I uninstall the binding in the GUI, the 4.0.2 entry disappears but the 4.0.0 remains… I can’t uninstall it - it tells me:

openhab> feature:uninstall org.smarthomej.binding.http
Error executing command: Feature named 'org.smarthomej.binding.http/0' is not installed

I already checked /usr/share/openhab/addons, nothing there except the system addons. What else could I do?

Do you have anything inside openhab/addons folder? If not, try typing bundle:uninstall 238 i.e using the actual listed id

That worked, great, thanks! :slight_smile:

So now back with only HTTP Binding 4.0.2 installed, the error message is finally gone. :tada:

Nevertheless, I observed something unexpected when experimenting - remember, I came to this topic with the goal of relaxing the HTTP requests to the HomePilot, and the core idea is that the two stateExtensions are queried with some delay.

For testing, I set the timing values quite long:

  • refresh=10
  • timeout=10000
  • delay=5000

These are values which do not stress the HomePilot at all, it can easily answer at these rates; usually it takes between 1 and 2 seconds to send a reply.
What I actually expected was that I can see the lastSuccess channel of the HTTP binding updating every 5 seconds, for each query.

What I saw was this:

2024-01-15 12:26:06.614 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'http:url:HomePilot' changed from ONLINE to UNKNOWN
2024-01-15 12:26:19.500 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'http:url:HomePilot' changed from UNKNOWN to ONLINE

2024-01-15 12:26:19.502 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'HomePilot_Last_Success' changed from 2024-01-15T12:26:04.539207959+0100 to 2024-01-15T12:26:19.498724842+0100
2024-01-15 12:26:21.849 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'HomePilot_Last_Success' changed from 2024-01-15T12:26:19.498724842+0100 to 2024-01-15T12:26:21.847259359+0100

2024-01-15 12:26:29.742 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'HomePilot_Last_Success' changed from 2024-01-15T12:26:21.847259359+0100 to 2024-01-15T12:26:29.739424871+0100
2024-01-15 12:26:31.822 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'HomePilot_Last_Success' changed from 2024-01-15T12:26:29.739424871+0100 to 2024-01-15T12:26:31.820346286+0100

2024-01-15 12:26:39.382 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'HomePilot_Last_Success' changed from 2024-01-15T12:26:31.820346286+0100 to 2024-01-15T12:26:39.379214539+0100
2024-01-15 12:26:41.842 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'HomePilot_Last_Success' changed from 2024-01-15T12:26:39.379214539+0100 to 2024-01-15T12:26:41.838588237+0100

The replies to the two queries are quite close, between 1 and 2 seconds, and then between 8 and 10 seconds of pause.
Which is, actually, exactly the same behavior I get when I set delay=0 (with all other settings unchanged), I just tested this.

Yet another strange behavior - If I set refresh=2 and delay=10000, I would have expected that the binding now correctly complains about an unreasonable timing setting and overwrites the refresh rate. But there is no warning or message at all, it just turns to “online” but behaves erratically…

So maybe you could have another look at this…? :pray:

I found the issue with the missing warning, that is the result of a wrong position for the calculation of the minimum refresh time.

Regarding the timing: can you please set the binding to TRACE level and see at what time the refresh is actually done?

Hi, thanks for the quick reply!

For not having to wait for ages, I took some slightly faster settings:

UID: http:url:HomePilot
label: HomePilot
thingTypeUID: http:url
  authMode: BASIC
  ignoreSSLErrors: true
  delay: 3000
  stateMethod: GET
  refresh: 5
  commandMethod: PUT
  contentType: application/json
  timeout: 5000
  bufferSize: 2048

With this, the requests should have been sent with 3sec inbetween. Here is what the trace showed:

2024-01-15 19:12:03.729 [TRACE] [ttp.internal.http.RefreshingUrlCache] - Sending to '': Method = {GET}, Headers = {Accept-Encoding: gzip, User-Agent: Jetty/9.4.50.v20221201}, Content = {null}
2024-01-15 19:12:04.729 [TRACE] [ttp.internal.http.RefreshingUrlCache] - Requesting refresh (retry=false) from '' with timeout 5000ms
2024-01-15 19:12:04.746 [TRACE] [ttp.internal.http.RefreshingUrlCache] - Requesting refresh (retry=false) from '' with timeout 5000ms
2024-01-15 19:12:06.103 [TRACE] [p.internal.http.HttpResponseListener] - Received from '': [...]
2024-01-15 19:12:06.772 [TRACE] [p.internal.http.HttpResponseListener] - Received from '': [...]

I shortened the responses, they are very long :wink:

But as far as I can see, the “Requesting refresh” from the two stateExtensions are only 17ms apart, instead of expected 3000ms…

Please let me know if I can supply you with more logs or test something! :slight_smile:

“Requesting refresh” is only queuing the request, it is send when the “Sending to …” message is logged. Did you omit one of those?

EDIT: I checked again, seems like I overlooked the “Sending To” and deleted them, as they were somewhat mixed up with the pages-long responses. I took it from the logfiles now and it looks way better:

2024-01-15 19:18:49.823 [TRACE] [ttp.internal.http.RefreshingUrlCache] - Requesting refresh (retry=false) from '' with timeout 5000ms
2024-01-15 19:18:49.824 [TRACE] [ttp.internal.http.RefreshingUrlCache] - Requesting refresh (retry=false) from '' with timeout 5000ms
2024-01-15 19:18:51.913 [TRACE] [ttp.internal.http.RefreshingUrlCache] - Sending to '': Method = {GET}, Headers = {Accept-Encoding: gzip, User-Agent: Jetty/9.4.50.v20221201}, Content = {null}
2024-01-15 19:18:51.953 [TRACE] [p.internal.http.HttpResponseListener] - Received from '': [...]
2024-01-15 19:18:54.824 [TRACE] [ttp.internal.http.RefreshingUrlCache] - Requesting refresh (retry=false) from '' with timeout 5000ms
2024-01-15 19:18:54.826 [TRACE] [ttp.internal.http.RefreshingUrlCache] - Requesting refresh (retry=false) from '' with timeout 5000ms
2024-01-15 19:18:54.915 [TRACE] [ttp.internal.http.RefreshingUrlCache] - Sending to '': Method = {GET}, Headers = {Accept-Encoding: gzip, User-Agent: Jetty/9.4.50.v20221201}, Content = {null}
2024-01-15 19:18:57.263 [TRACE] [p.internal.http.HttpResponseListener] - Received from '': [...]
2024-01-15 19:18:57.917 [TRACE] [ttp.internal.http.RefreshingUrlCache] - Sending to '': Method = {GET}, Headers = {Accept-Encoding: gzip, User-Agent: Jetty/9.4.50.v20221201}, Content = {null}
2024-01-15 19:18:59.826 [TRACE] [ttp.internal.http.RefreshingUrlCache] - Requesting refresh (retry=false) from '' with timeout 5000ms
2024-01-15 19:18:59.827 [TRACE] [ttp.internal.http.RefreshingUrlCache] - Requesting refresh (retry=false) from '' with timeout 5000ms
2024-01-15 19:19:00.293 [TRACE] [p.internal.http.HttpResponseListener] - Received from '': [...]
2024-01-15 19:19:00.918 [TRACE] [ttp.internal.http.RefreshingUrlCache] - Sending to '': Method = {GET}, Headers = {Accept-Encoding: gzip, User-Agent: Jetty/9.4.50.v20221201}, Content = {null}
2024-01-15 19:19:00.960 [TRACE] [p.internal.http.HttpResponseListener] - Received from '': [...]

Anyway, something which I find interesting:

  • Do I understand correctly that the “lastSuccess” variable is updated for each stateExtension address (which I currently think it is), or is it only updated when all requests of one refresh period were answered?
  • If the requests are actually sent with the configured delay, and if the responses are coming in with according delays, why are the lastSuccess times updated in a fashion that they look like occuring at the same time?
    I want to use the success and failure times for fault detection and handling, so this is important for me to know - there is no “good or bad way” how it’s done, I just need to know to implement a proper interpretation :slight_smile: