Possible auth bug in HTTP 3.0 binding

karlfife · January 2, 2021, 9:52pm

I have a new installation of OH3 (openhabian).
I have the HTTP binding installed with 3 identical Things defined (three identical Proliphix IMT550c Ethernet Thermostats). I have created Channels, Links and Items, and can successfully get thermostat properties using the devices’ REST API. However every time that I reboot Openhab, the logs show an auth problem for each of the three things. e.g.:
… [DEBUG] [p.internal.http.HttpResponseListener]… failed: Authorization error

The configured auth parameters are correct, and if I simply view the config in the GUI and re-save (without changes), the things’ auth starts working again. e.g. the following is logged:
… [DEBUG] [nding.http.internal.HttpThingHandler] - Digest Authentication configured for thing ‘http:url:49422d1796’
… [INFO ] [nding.http.internal.HttpThingHandler] - Using the insecure client for thing ‘http:url:49422d1796’.

Curiously, very early in the boot process, the auth seems to succeed. OH logs the same two messages above ( “Digest Auth Configured” and “Using the insecure client”) for each of the three things/endpoints. However, shortly thereafter in the logs I get (for all 3 endpoints):
… [DEBUG] [p.internal.http.HttpResponseListener] - Requesting ‘http://thermostat1.6w.kfife.com/get?OID4.1.13’ (method=‘GET’, content=‘null’) failed: Authorization error
and
[WARN ] [ttp.internal.http.RefreshingUrlCache] - Could not find authentication result for ‘http://thermostat1.6w.kfife.com/get?OID4.1.13’, failing here

Given the characteristics of this failure, and the newness of OH3, I suspect this could be a regression, rather than a problem with my config. I’m happy to post examples/code/how-to-reproduce in the right place with some guidance from the community.

Klaus_Schuster · January 7, 2021, 3:55pm

hi! same problem under Windows10 using zulu (java for windows openjdk 11.0.9.1).
boot in debug shows:
Using the insecure client for thing ‘http:url:9670a3c5b5’

using my items, it shows warning:
Could not find authentication result for https://192.168.1.50/..../post.php, failing here

sometimes it works, if I restart a few times… or saving the http Binding Thing again…

Klaus_Schuster · January 8, 2021, 7:01am

has anyone any suggestion concering this bug ?

karlfife · January 8, 2021, 7:57pm

Is anyone NOT seeing this behavior in OH3? If so, would be helpful to know so the behavior can be narrowed down to a particular condition (e.g. network/transport/auth idiosyncrasies).

karlfife · January 29, 2021, 1:52am

For what it’s worth, after the openhab 3.0.1 update, I am still seeing this HTTP binding Authorization error problem.
It occurs 100% of the time after reboot.
The error stops 100% if I view the ‘thing’ in gui, and then hit ‘save’.
Does anyone have an idea of where I might look for a solution?

rpwong · January 29, 2021, 2:08am

I think you probably need to post a bug report on GitHub, specific to the HTTP binding. That’s the only way to guarantee that developers will see it.

HaKuNa · January 29, 2021, 4:41am

Just to mention. I have 7 things for the HTTP binding and do not have any issue. Also restart/boot is absolutely no problem. But there‘s one slight difference. My things are all using the secure client.
Probably because I have either a token or an auth header configured in all my things.

2021-01-27 19:19:27.145 [INFO ] [nding.http.internal.HttpThingHandler] - Using the secure client for thing ‘http:url:dingzWZ’.

karlfife · January 29, 2021, 4:57am

Thank you @rpwong for the suggestion. I will do that. I wireshark’ed the conversation and correlated it to the OH trace debug log. It appears that after every reboot (or OH service restart), the http binding ‘thing’ does not attempt to authenticate (Digest) when it sends its http GET. When the endpoint replies with 401 “authorization required”, the OH binding does not re-try with an authenticated request. Instead it gives up and waits for the refresh interval (60 sec), and tries again, also unauthenticated.

By contrast, after one ‘re-saves’ of the http binding thing, the behavior is different. In the post-save scenario, when OH receives the 401 from the endpoint, OH immediately retries (i.e. ~25ms) with an appropriate authenticated GET, and the endpoint replies appropriately (200 OK).

Subsequent GET requests from OH (made on its 60-second interval) are properly pre-authenticated without needing to respond to a failed GET ending in 401 (until the next restart). I will mention @J-N-K here for good measure.

@HaKuNa thank for the datapoint. Yes, it appears you’re using a different kind of auth and of course, TLS.

J-N-K · January 30, 2021, 8:31am

Please provide a TRACE log when the thing is initialized.

karlfife · January 31, 2021, 3:33am

Clean system restart:

2021-01-28 21:14:18.442 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Time zone set to ‘America/Chicago’.
2021-01-28 21:14:18.502 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Location set to ‘41.68568475971216,-86.99541091918945’.
2021-01-28 21:14:18.507 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Locale set to ‘en_US’.
2021-01-28 21:14:18.511 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Measurement system set to ‘US’.
2021-01-28 21:14:39.797 [INFO ] [.core.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
2021-01-28 21:14:46.845 [INFO ] [org.openhab.ui.internal.UIService ] - Started UI on port 8080
2021-01-28 21:14:48.950 [INFO ] [e.automation.internal.RuleEngineImpl] - Rule engine started.
2021-01-28 21:14:50.241 [INFO ] [ab.ui.habpanel.internal.HABPanelTile] - Started HABPanel at /habpanel
2021-01-28 21:14:50.698 [DEBUG] [nding.http.internal.HttpThingHandler] - Digest Authentication configured for thing ‘http:url:49422d1796’
2021-01-28 21:14:50.702 [INFO ] [nding.http.internal.HttpThingHandler] - Using the insecure client for thing ‘http:url:49422d1796’.
2021-01-28 21:14:50.742 [TRACE] [ttp.internal.http.RefreshingUrlCache] - Started refresh task for URL ‘http://thermostat1.6w.kfife.com/get?OID4.1.13’ with interval 60s
2021-01-28 21:14:50.749 [TRACE] [.HttpDynamicStateDescriptionProvider] - adding state description for channel http:url:49422d1796:GetZoneTemp
2021-01-28 21:14:57.904 [INFO ] [zwave.handler.ZWaveControllerHandler] - Attempting to add listener when controller is null
2021-01-28 21:15:01.034 [TRACE] [.HttpDynamicStateDescriptionProvider] - returning new stateDescription for http:url:49422d1796:GetZoneTemp
2021-01-28 21:15:03.388 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
2021-01-28 21:15:03.391 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.

First GET after START:

2021-01-28 21:15:50.743 [TRACE] [ttp.internal.http.RefreshingUrlCache] - Requesting refresh (retry=false) from ‘http://thermostat1.6w.kfife.com/get?OID4.1.13’ with timeout 3000ms
2021-01-28 21:15:50.800 [TRACE] [ttp.internal.http.RefreshingUrlCache] - Sending to ‘http://thermostat1.6w.kfife.com/get?OID4.1.13’: Method = {GET}, Headers = {Accept-Encoding: gzip, User-Agent: Jetty/9.4.20.v20190813}, Content = {null}
2021-01-28 21:15:51.077 [TRACE] [p.internal.http.HttpResponseListener] - Received from ‘http://thermostat1.6w.kfife.com/get?OID4.1.13’: Code = {401}, Headers = {Connection: close, Date: Fri, 29 Jan 2021 03:15:51 GMT, Server: Cherokee, WWW-Authenticate: Digest realm=“proliphixrealm”, nonce=“f719a91aa0f66cb6d5319a439acd539d”, qop="$

401 Authorization Required

This server could not verify that you are authorized to access the requested URL. Either you supplied the wrong credentials (e.g., bad password), or your browser doesn't know how to supply the credentials required.

Cherokee web server, Port 80 }

2021-01-28 21:15:51.080 [DEBUG] [p.internal.http.HttpResponseListener] - Requesting ‘http://thermostat1.6w.kfife.com/get?OID4.1.13’ (method=‘GET’, content=‘null’) failed: Authorization error
2021-01-28 21:15:51.082 [WARN ] [ttp.internal.http.RefreshingUrlCache] - Could not find authentication result for ‘http://thermostat1.6w.kfife.com/get?OID4.1.13’, failing here
2021-01-28 21:16:00.117 [TRACE] [.HttpDynamicStateDescriptionProvider] - returning new stateDescription for http:url:49422d1796:GetZoneTemp

Opened, re-SAVED thing in GUI (with no changes):

2021-01-28 21:16:35.911 [TRACE] [ttp.internal.http.RefreshingUrlCache] - Stopped refresh task for URL ‘http://thermostat1.6w.kfife.com/get?OID4.1.13’
2021-01-28 21:16:35.913 [TRACE] [.HttpDynamicStateDescriptionProvider] - removing state description for thing http:url:49422d1796
2021-01-28 21:16:35.920 [DEBUG] [nding.http.internal.HttpThingHandler] - Digest Authentication configured for thing ‘http:url:49422d1796’
2021-01-28 21:16:35.922 [INFO ] [nding.http.internal.HttpThingHandler] - Using the insecure client for thing ‘http:url:49422d1796’.
2021-01-28 21:16:35.927 [TRACE] [ttp.internal.http.RefreshingUrlCache] - Started refresh task for URL ‘http://thermostat1.6w.kfife.com/get?OID4.1.13’ with interval 60s
2021-01-28 21:16:35.928 [TRACE] [.HttpDynamicStateDescriptionProvider] - adding state description for channel http:url:49422d1796:GetZoneTemp

Successful GET after SAVE:

2021-01-28 21:17:00.180 [TRACE] [.HttpDynamicStateDescriptionProvider] - returning new stateDescription for http:url:49422d1796:GetZoneTemp
2021-01-28 21:17:35.927 [TRACE] [ttp.internal.http.RefreshingUrlCache] - Requesting refresh (retry=false) from ‘http://thermostat1.6w.kfife.com/get?OID4.1.13’ with timeout 3000ms
2021-01-28 21:17:35.929 [TRACE] [ttp.internal.http.RefreshingUrlCache] - Sending to ‘http://thermostat1.6w.kfife.com/get?OID4.1.13’: Method = {GET}, Headers = {Accept-Encoding: gzip, User-Agent: Jetty/9.4.20.v20190813}, Content = {null}
2021-01-28 21:17:36.070 [TRACE] [p.internal.http.HttpResponseListener] - Received from ‘http://thermostat1.6w.kfife.com/get?OID4.1.13’: Code = {200}, Headers = {Transfer-Encoding: chunked, Date: Fri, 29 Jan 2021 03:17:35 GMT, Server: Cherokee, Content-Encoding: gzip, Vary: Accept-Encoding, Content-Type: text/plain}, Content = {
OID4.1.13=683}

Please let me know if you want the PCAP from this same conversation between OH and Thermostat1

J-N-K · January 31, 2021, 10:47am

I can’t reproduce that:

11:45:10.785 [INFO ] [b.core.internal.i18n.I18nProviderImpl] - Time zone set to 'Europe/Berlin'.
11:45:10.817 [INFO ] [b.core.internal.i18n.I18nProviderImpl] - Location set to '51.4987,7.1201'.
11:45:10.817 [INFO ] [b.core.internal.i18n.I18nProviderImpl] - Locale set to 'de_DE'.
11:45:14.524 [WARN ] [org.openhab.core.net.NetUtil         ] - Found multiple local interfaces - ignoring 192.168.0.181
11:45:27.946 [INFO ] [b.core.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
11:45:30.466 [INFO ] [org.openhab.ui.internal.UIService    ] - Started UI on port 8080
11:45:32.279 [INFO ] [hab.ui.habpanel.internal.HABPanelTile] - Started HABPanel at /habpanel
11:45:32.704 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'http:url:9f2003a3e9' changed from UNINITIALIZED to INITIALIZING
11:45:32.759 [INFO ] [inding.http.internal.HttpThingHandler] - Using the insecure client for thing 'http:url:9f2003a3e9'.
11:45:32.952 [DEBUG] [inding.http.internal.HttpThingHandler] - Digest Authentication configured for thing 'http:url:9f2003a3e9'
11:45:32.987 [TRACE] [http.internal.http.RefreshingUrlCache] - Started refresh task for URL 'https://jigsaw.w3.org/HTTP/Digest/' with interval 30s
11:45:33.018 [TRACE] [l.HttpDynamicStateDescriptionProvider] - adding state description for channel http:url:9f2003a3e9:str
11:45:33.037 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'http:url:9f2003a3e9' changed from INITIALIZING to ONLINE
11:45:34.002 [TRACE] [http.internal.http.RefreshingUrlCache] - Requesting refresh (retry=false) from 'https://jigsaw.w3.org/HTTP/Digest/' with timeout 3000ms
11:45:34.006 [TRACE] [http.internal.http.RefreshingUrlCache] - Sending to 'https://jigsaw.w3.org/HTTP/Digest/': Method = {GET}, Headers = {Accept-Encoding: gzip, User-Agent: Jetty/9.4.20.v20190813}, Content = {null}
11:45:34.756 [TRACE] [tp.internal.http.HttpResponseListener] - Received from 'https://jigsaw.w3.org/HTTP/Digest/': Code = {200}, Headers = {Date: Sun, 31 Jan 2021 10:45:34 GMT, Content-Length: 459, Content-Location: https://jigsaw.w3.org/HTTP/Digest/ok.html, Content-Type: text/html, ETag: "6km9jn:qogunjao", Last-Modified: Thu, 01 Jun 2000 22:07:10 GMT, Server: Jigsaw/2.3.0-beta2, Strict-Transport-Security: max-age=15552015; includeSubDomains; preload, public-key-pins: pin-sha256="cN0QSpPIkuwpT6iP2YjEo1bEwGpH/yiUn6yhdy+HNto="; pin-sha256="WGJkyYjx1QMdMe0UqlyOKXtydPDVrk7sl2fV+nNm1r4="; pin-sha256="LrKdTxZLRTvyHM4/atX2nquX9BeHRZMCxg3cf4rhc2I="; max-age=864000, x-frame-options: deny, x-xss-protection: 1; mode=block}, Content = {<!DOCTYPE HTML PUBLIC "-//IETF//DTD HTML//EN">
<html>
  <head>
    <title>Digest Authentication test page</title>
<!-- Changed by: Yves Lafon, 22-Feb-1999 -->
  </head>

<BODY BGCOLOR="white">
<P>
      <A HREF=".."><IMG SRC="/icons/jigsaw" ALT="Jigsaw" BORDER="0" WIDTH="212"
          HEIGHT="49"></A><IMG SRC="/icons/jigpower.gif" WIDTH="94" HEIGHT="52" ALT="Jigsaw Powered !"
        BORDER="0" ALIGN="Right">

<P>
<HR>
<P>Your browser made it!
  </body>
</html>
}
11:45:34.767 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'HTTPURLThing_str' changed from NULL to <!DOCTYPE HTML PUBLIC "-//IETF//DTD HTML//EN">
<html>
  <head>
    <title>Digest Authentication test page</title>
<!-- Changed by: Yves Lafon, 22-Feb-1999 -->
  </head>

<BODY BGCOLOR="white">
<P>
      <A HREF=".."><IMG SRC="/icons/jigsaw" ALT="Jigsaw" BORDER="0" WIDTH="212"
          HEIGHT="49"></A><IMG SRC="/icons/jigpower.gif" WIDTH="94" HEIGHT="52" ALT="Jigsaw Powered !"
        BORDER="0" ALIGN="Right">

<P>
<HR>
<P>Your browser made it!
  </body>
</html>

UID: http:url:9f2003a3e9
label: HTTP URL Thing
thingTypeUID: http:url
configuration:
  authMode: DIGEST
  ignoreSSLErrors: true
  baseURL: https://jigsaw.w3.org/HTTP/Digest/
  password: guest
  delay: 0
  refresh: 30
  commandMethod: GET
  timeout: 3000
  bufferSize: 2048
  username: guest
channels:
  - id: str
    channelTypeUID: http:string
    label: str
    description: ""
    configuration:
      mode: READONLY

karlfife · February 2, 2021, 8:41pm

Would it be helpful to see a .pcap of the traced conversation? Would it be helpful to bump up the debug level and repeat?

Would it be helpful if I were to NAT you to this particular endpoint? (e.g. with your source IP address and a time window).

The only significant difference I see in configs is state extension.
I’m happy to help in any way I can.

UID: http:url:f4ae30deb5
label: Thermostat3
thingTypeUID: http:url
configuration:
authMode: DIGEST
ignoreSSLErrors: true
baseURL: http://thermostat3.6w.kfife.com
password: notmyrealpassword
refresh: 60
commandMethod: GET
contentType: text/plain
timeout: 3000
username: admin
bufferSize: 2048
channels:
- id: GetZoneTemp
channelTypeUID: http:string
label: Zone 3 Temperature
description: “”
configuration:
mode: READONLY
stateExtension: get?OID4.1.13&OID4.3.2.3&OID4.3.2.4&OID4.3.2.5

J-N-K · February 2, 2021, 9:05pm

Good point, could be the stateExtension. I‘ll try that tomorrow.

J-N-K · February 3, 2021, 5:24pm

Still works for me. The question is why no authentication result is found even though it has been configured before (according to the log). I have no idea how to debug that.

karlfife · February 3, 2021, 5:35pm

Would it be helpful if I share the pcap of that conversation? Alternatively if you want to share yours I could compare the the two.

This install was migrated from v 2.5. I’ve seen some examples of configuration cruft (configs pointing to non-existent 2.x directories etc. that I’ve had to clean up manually). I wonder if there’s some kind of persistence problem related to migration, and magically ‘fixed’ when the thing is re-saved, essentially to a ramdisk that lacks persistence due to impropper mapping/zram? Just a thought.

I can Nat you to this device to rule in/out this install.

J-N-K · February 3, 2021, 7:19pm

No, I think it‘s an internal issue in Jetty. No idea what the difference between your setup and mine is.

What happens if you wait for the next refresh instead of editing the thing? Is that succeeding?

karlfife · February 4, 2021, 4:20am

It appears to fail forever until re-saved.

karlfife · February 9, 2021, 6:34am

When I save the HTTP thing, where is the file written to the filesystem?

I’d really like to figure this out. Can you share a PCAP file of your conversation, or conversely I can share mine for the period of service restart, fail, save, succeed. It’s only a few dozen packets.

Would you like to hit my HTTP endpoint? I can whitelist NAT your IP in to the device.

J-N-K · February 9, 2021, 6:50am

I am no longer involved in the development of openHAB. Maybe someone will investigate and fix if you enter an issue on GitHub. You should reference this thread here.

karlfife · February 10, 2021, 3:25am

This issue appears to be resolved. After updating from 3.0.1 to 3.1 Milestone 3 the problem no longer occurs. Thank you to everyone involved!