Doesn't find matching binding provider

Hello all!

OpenHAB has been running the thermostat for a while and it works fairly well. But periodically I’ll notice that it has quit communicating with the thermostat.

When I see this I’ll check to make sure the thermostat is still visible on the network, and it is.

Then open Putty and SSH to the RaspberryPi and issue various Curl commands to make sure I can interact with the thermostat from a command prompt, and I can.

All the while OpenHAB is reporting it hasn’t interacted with the thermostat for hours or a day or two… I track every update received with a timestamp to verify they are communicating.

This morning I enabled logging all http activity and first thing I noticed were lines with “doesn’t find matching binding provider” when the thermostat would update. What are these telling me? Because the items they are talking about do exist and are updated. You can see the results in the events file entries below.

Here is everything relative to the thermostat in my setup. And help greatly appreciated.

Thanks!

command prompt:
curl http://192.168.224.50/tstat/
{“temp”:66.50,“tmode”:1,“fmode”:0,“override”:0,“hold”:1,“t_heat”:67.00,“tstate”:0,“fstate”:0,“time”:{“day”:6,“hour”:9,“minute”:8},“t_type_post”:0}

http binding:

3M/Filtrete 50 Thermostat - heating/cooling info

http:tstat.url=http://192.168.224.50/tstat

refresh every 2 minutes

http:tstat.updateInterval=120000

items:
Number Tstat_mode “System Status” { http="<[tstat:120000:JSONPATH($.tmode)]" }
Number Tstat_temp “Indoor Temp [%.1f °F]” { http="<[tstat:120000:JSONPATH($.temp)]" }
Number Tstat_SetpointH “Set Heat Temperature [%.1f °F]” { http="<[tstat:120000:JSONPATH($.t_heat)]" }
Number Tstat_SetpointC “Set A/C Temperature [%.1f °F]” { http="<[tstat:120000:JSONPATH($.t_cool)]" }
Number Tstat_Setpoint “Set Temperature [%.1f °F]”
Number Tstat_hold “Hold Status” { http="<[tstat:120000:JSONPATH($.hold)]" }
Number Tstat_fan “Fan Mode” { http="<[tstat:120000:JSONPATH($.fmode)]" }
DateTime Tstat_LastUpdate “Last contact [%1$tm-%1$td @ %1$tH:%1$tM]”

rules:
// Get Current Heat/AC Target Temperature - load Setpoint
rule “New Target Temperature”
when
Item Tstat_mode received update
then
if (Tstat_mode.state == 1) {
Tstat_Setpoint.state = Tstat_SetpointH.state
}
if (Tstat_mode.state == 2) {
Tstat_Setpoint.state = Tstat_SetpointC.state
}
end

***there are other rules to set temp, heat/cool mode etc but the above rule is the only one that triggers querying the thermostat

sitemap:
Switch item=Tstat_mode mappings=[0=“Off”, 1=“Heat”, 2=“Cool”] icon=“thermometer”
Setpoint item=Tstat_Setpoint minValue=60 maxValue=80 step=1.0
Switch item=Tstat_hold mappings=[0=“No”, 1=“Yes”]
Switch item=Tstat_fan mappings=[0=“Auto”, 2=“On”] icon=“fan”
Text item=Tstat_LastUpdate

openhab.log:
2015-11-15 09:14:28.486 [DEBUG] [.o.b.http.internal.HttpBinding] - item ‘Tstat_mode’ is fetched from cache
2015-11-15 09:14:28.489 [DEBUG] [.o.b.http.internal.HttpBinding] - transformed response is ‘1’
2015-11-15 09:14:28.491 [TRACE] [.o.b.http.internal.HttpBinding] - doesn’t find matching binding provider [itemName=Tstat_mode, command=CHANGED]
2015-11-15 09:14:35.497 [DEBUG] [.o.b.http.internal.HttpBinding] - item ‘Tstat_temp’ is fetched from cache
2015-11-15 09:14:35.500 [DEBUG] [.o.b.http.internal.HttpBinding] - transformed response is ‘67.0’
2015-11-15 09:14:35.503 [TRACE] [.o.b.http.internal.HttpBinding] - doesn’t find matching binding provider [itemName=Tstat_temp, command=CHANGED]
2015-11-15 09:14:35.503 [DEBUG] [.o.b.http.internal.HttpBinding] - item ‘Tstat_SetpointH’ is fetched from cache
2015-11-15 09:14:35.506 [DEBUG] [.o.b.http.internal.HttpBinding] - transformed response is ‘67.0’
2015-11-15 09:14:35.508 [DEBUG] [.o.b.http.internal.HttpBinding] - item ‘Tstat_SetpointC’ is fetched from cache
2015-11-15 09:14:35.512 [DEBUG] [.o.b.http.internal.HttpBinding] - transformed response is ‘null’
2015-11-15 09:14:35.515 [DEBUG] [.o.b.http.internal.HttpBinding] - Couldn’t create state of type ‘class org.openhab.core.library.items.NumberItem’ for value ‘null’
2015-11-15 09:14:35.517 [DEBUG] [.o.b.http.internal.HttpBinding] - item ‘Tstat_hold’ is fetched from cache
2015-11-15 09:14:35.520 [DEBUG] [.o.b.http.internal.HttpBinding] - transformed response is ‘1’
2015-11-15 09:14:35.523 [DEBUG] [.o.b.http.internal.HttpBinding] - item ‘Tstat_fan’ is fetched from cache
2015-11-15 09:14:35.527 [DEBUG] [.o.b.http.internal.HttpBinding] - transformed response is ‘0’
2015-11-15 09:14:35.530 [TRACE] [.o.b.http.internal.HttpBinding] - doesn’t find matching binding provider [itemName=Tstat_SetpointH, command=CHANGED]
2015-11-15 09:14:35.537 [TRACE] [.o.b.http.internal.HttpBinding] - doesn’t find matching binding provider [itemName=Tstat_SetpointC, command=CHANGED]
2015-11-15 09:14:35.552 [TRACE] [.o.b.http.internal.HttpBinding] - doesn’t find matching binding provider [itemName=Tstat_hold, command=CHANGED]
2015-11-15 09:14:35.559 [TRACE] [.o.b.http.internal.HttpBinding] - doesn’t find matching binding provider [itemName=Tstat_fan, command=CHANGED]

events.log:
2015-11-15 09:14:28 - Tstat_mode state updated to 1
2015-11-15 09:14:35 - Tstat_temp state updated to 67.0
2015-11-15 09:14:35 - Tstat_SetpointH state updated to 67.0
2015-11-15 09:14:35 - Tstat_SetpointC state updated to null
2015-11-15 09:14:35 - Tstat_hold state updated to 1
2015-11-15 09:14:35 - Tstat_fan state updated to 0
2015-11-15 09:14:35 - Tstat_LastUpdate state updated to 2015-11-15T09:14:35

Looking at the source code of the http binding, it appears that the log entries don’t necessarily indicate a problem. The “is fetched from cache” message is logged when the periodic item update happens and the value is loaded from the configured cache (“tstat”, in this case). The “transformed response” message is logged when the cached value is successfully transformed. The item update is published after after the transformation.

When the item is updated, the update event on the bus also triggers the http binding. However, it seems that the binding information is not in the list that’s checked when an update event occurs. It’s probably only checked periodically because of the cache. If so, that’s the reason for not finding the matching binding provider. This is logged at TRACE level so that’s more evidence that it’s not an error.

My guess is that there may be some issue with the cache updates. I’d look earlier in the log file for any potential warnings or error messages related to that. Good luck.