Yes. I think they thought there was a good reason to obfuscate the directory name like that. I just find it annoying.
It’s hard to say, especially in the case of a cloud service. Glad you’re not seeing the error any longer.
Thank goodness for tab completion. 
I spoke too soon. 
The error is back. However, it does seem like I’m getting some data from it during startup and then it craps out with the Unable to update data model message.
When I get a chance I’ll turn up debug logging and see if I can find out more.
On a side note, have you looked into Nest Weave?
Thanks, Rich. If you could send some log samples when you have them, I can see better what might be happening. I suspect the HTTP read timeout is sometimes too short to receive a response, but the logs will help confirm that.
No, not yet; hope to.
Below are my logs showing from startup to the first time the error is generated. I put the logging level on TRACE.
My config has
nest:refresh=300000
I did scrub it of anything that looked like a key, token, etc, replacing the random string with XXX.
2015-10-13 08:18:03.023 [TRACE] [veController$WatchDogTimerTask:1595]- Watchdog: Checking Serial threads
2015-10-13 08:18:13.024 [TRACE] [veController$WatchDogTimerTask:1595]- Watchdog: Checking Serial threads
2015-10-13 08:18:23.024 [TRACE] [veController$WatchDogTimerTask:1595]- Watchdog: Checking Serial threads
2015-10-13 08:18:33.025 [TRACE] [veController$WatchDogTimerTask:1595]- Watchdog: Checking Serial threads
2015-10-13 08:18:43.025 [TRACE] [veController$WatchDogTimerTask:1595]- Watchdog: Checking Serial threads
2015-10-13 08:18:53.025 [TRACE] [veController$WatchDogTimerTask:1595]- Watchdog: Checking Serial threads
2015-10-13 08:19:25.128 [DEBUG] [.b.nest.internal.NestActivator:33 ]- Nest binding has been started.
2015-10-13 08:19:25.148 [TRACE] [n.i.NestGenericBindingProvider:148 ]- validateItemType called with bindingConfig=<[thermostats(Entryway).humidity]
2015-10-13 08:19:25.149 [TRACE] [n.i.NestGenericBindingProvider:157 ]- validateItemType called with property=thermostats(Entryway).humidity
2015-10-13 08:19:25.149 [DEBUG] [n.i.NestGenericBindingProvider:111 ]- Processing binding configuration: '<[thermostats(Entryway).humidity]'
2015-10-13 08:19:25.149 [TRACE] [n.i.NestGenericBindingProvider:148 ]- validateItemType called with bindingConfig=<[thermostats(Entryway).ambient_temperature_f]
2015-10-13 08:19:25.150 [TRACE] [n.i.NestGenericBindingProvider:157 ]- validateItemType called with property=thermostats(Entryway).ambient_temperature_f
2015-10-13 08:19:25.150 [DEBUG] [n.i.NestGenericBindingProvider:111 ]- Processing binding configuration: '<[thermostats(Entryway).ambient_temperature_f]'
2015-10-13 08:19:25.150 [TRACE] [n.i.NestGenericBindingProvider:148 ]- validateItemType called with bindingConfig==[thermostats(Entryway).target_temperature_f]
2015-10-13 08:19:25.150 [TRACE] [n.i.NestGenericBindingProvider:157 ]- validateItemType called with property=thermostats(Entryway).target_temperature_f
2015-10-13 08:19:25.151 [DEBUG] [n.i.NestGenericBindingProvider:111 ]- Processing binding configuration: '=[thermostats(Entryway).target_temperature_f]'
2015-10-13 08:19:25.151 [TRACE] [n.i.NestGenericBindingProvider:148 ]- validateItemType called with bindingConfig==[structures(Home).away]
2015-10-13 08:19:25.151 [TRACE] [n.i.NestGenericBindingProvider:157 ]- validateItemType called with property=structures(Home).away
2015-10-13 08:19:25.151 [DEBUG] [n.i.NestGenericBindingProvider:111 ]- Processing binding configuration: '=[structures(Home).away]'
2015-10-13 08:19:25.152 [TRACE] [n.i.NestGenericBindingProvider:148 ]- validateItemType called with bindingConfig==[thermostats(Entryway).fan_timer_active]
2015-10-13 08:19:25.152 [TRACE] [n.i.NestGenericBindingProvider:157 ]- validateItemType called with property=thermostats(Entryway).fan_timer_active
2015-10-13 08:19:25.152 [DEBUG] [n.i.NestGenericBindingProvider:111 ]- Processing binding configuration: '=[thermostats(Entryway).fan_timer_active]'
2015-10-13 08:19:25.153 [TRACE] [n.i.NestGenericBindingProvider:148 ]- validateItemType called with bindingConfig=<[thermostats(Entryway).is_online]
2015-10-13 08:19:25.153 [TRACE] [n.i.NestGenericBindingProvider:157 ]- validateItemType called with property=thermostats(Entryway).is_online
2015-10-13 08:19:25.153 [DEBUG] [n.i.NestGenericBindingProvider:111 ]- Processing binding configuration: '<[thermostats(Entryway).is_online]'
2015-10-13 08:19:26.072 [TRACE] [.o.b.nest.internal.NestBinding:128 ]- Querying Nest API
2015-10-13 08:19:26.321 [TRACE] [b.n.i.messages.AbstractRequest:125 ]- About to execute 'https://developer-api.nest.com/?auth=XXX
2015-10-13 08:19:27.168 [TRACE] [b.n.i.messages.AbstractRequest:166 ]- {"devices":{"thermostats":{"XXX":{"humidity":30,"locale":"en-US","temperature_scale":"F","is_using_emergency_heat":false,"has_fan":true,"software_version":"4.5.1","has_leaf":true,"device_id":"XXX","name":"Entryway","can_heat":true,"can_cool":false,"hvac_mode":"heat","target_temperature_c":16.5,"target_temperature_f":63,"target_temperature_high_c":24.0,"target_temperature_high_f":75,"target_temperature_low_c":20.0,"target_temperature_low_f":68,"ambient_temperature_c":17.0,"ambient_temperature_f":63,"away_temperature_high_c":24.0,"away_temperature_high_f":76,"away_temperature_low_c":10.0,"away_temperature_low_f":50,"structure_id":"XXX","fan_timer_active":false,"name_long":"Entryway Thermostat","is_online":true,"last_connection":"2015-10-13T14:09:37.256Z"}}},"structures":{"XXX":{"name":"XXX","country_code":"US","postal_code":"80921","time_zone":"America/Denver","away":"home","thermostats":["XXX"],"structure_id":"XXX"}},"metadata":{"access_token":"XXX","client_version":1}}
2015-10-13 08:19:27.323 [TRACE] [.o.b.nest.internal.NestBinding:175 ]- Updating itemName 'S_V_NestTargetTemp' with newState '63'
2015-10-13 08:19:27.323 [TRACE] [.o.b.nest.internal.NestBinding:182 ]- Added event (item='S_V_NestTargetTemp', newState='63') to the ignore event list
2015-10-13 08:19:27.323 [TRACE] [.o.b.nest.internal.NestBinding:175 ]- Updating itemName 'S_C_NestFan' with newState 'OFF'
2015-10-13 08:19:27.323 [TRACE] [.o.b.nest.internal.NestBinding:265 ]- Received update (item='S_V_NestTargetTemp', state='63')
2015-10-13 08:19:27.324 [TRACE] [.o.b.nest.internal.NestBinding:182 ]- Added event (item='S_C_NestFan', newState='OFF') to the ignore event list
2015-10-13 08:19:27.324 [DEBUG] [.o.b.nest.internal.NestBinding:288 ]- We received this event (item='S_V_NestTargetTemp', state='63') from Nest, so we don't send it back again -> ignore!
2015-10-13 08:19:27.324 [TRACE] [.o.b.nest.internal.NestBinding:175 ]- Updating itemName 'N_V_NestHumidity' with newState '30'
2015-10-13 08:19:27.324 [TRACE] [.o.b.nest.internal.NestBinding:182 ]- Added event (item='N_V_NestHumidity', newState='30') to the ignore event list
2015-10-13 08:19:27.325 [TRACE] [.o.b.nest.internal.NestBinding:175 ]- Updating itemName 'N_V_NestCurrTemp' with newState '63'
2015-10-13 08:19:27.325 [TRACE] [.o.b.nest.internal.NestBinding:182 ]- Added event (item='N_V_NestCurrTemp', newState='63') to the ignore event list
2015-10-13 08:19:27.325 [TRACE] [.o.b.nest.internal.NestBinding:265 ]- Received update (item='S_C_NestFan', state='OFF')
2015-10-13 08:19:27.326 [DEBUG] [.o.b.nest.internal.NestBinding:288 ]- We received this event (item='S_C_NestFan', state='OFF') from Nest, so we don't send it back again -> ignore!
2015-10-13 08:19:27.327 [TRACE] [.o.b.nest.internal.NestBinding:265 ]- Received update (item='N_V_NestHumidity', state='30')
2015-10-13 08:19:27.328 [DEBUG] [.o.b.nest.internal.NestBinding:288 ]- We received this event (item='N_V_NestHumidity', state='30') from Nest, so we don't send it back again -> ignore!
2015-10-13 08:19:27.329 [TRACE] [.o.b.nest.internal.NestBinding:265 ]- Received update (item='N_V_NestCurrTemp', state='63')
2015-10-13 08:19:27.329 [ERROR] [.o.b.nest.internal.NestBinding:206 ]- Unable to get state from data model
org.apache.commons.beanutils.NestedNullException: Null property value for 'structures(Home).away' on bean class 'class org.openhab.binding.nest.internal.messages.DataModelResponse'
at org.apache.commons.beanutils.PropertyUtilsBean.getNestedProperty(PropertyUtilsBean.java:755) ~[commons-beanutils-1.8.3.jar:1.8.3]
at org.apache.commons.beanutils.PropertyUtilsBean.getProperty(PropertyUtilsBean.java:846) ~[commons-beanutils-1.8.3.jar:1.8.3]
at org.openhab.binding.nest.internal.messages.DataModel.getProperty(DataModel.java:302) ~[bundlefile:na]
at org.openhab.binding.nest.internal.NestBinding.getState(NestBinding.java:204) [bundlefile:na]
at org.openhab.binding.nest.internal.NestBinding.readNest(NestBinding.java:173) [bundlefile:na]
at org.openhab.binding.nest.internal.NestBinding.execute(NestBinding.java:141) [bundlefile:na]
at org.openhab.core.binding.AbstractActiveBinding$BindingActiveService.execute(AbstractActiveBinding.java:156) [org.openhab.core_1.7.1.jar:na]
at org.openhab.core.service.AbstractActiveService$RefreshThread.run(AbstractActiveService.java:173) [org.openhab.core_1.7.1.jar:na]
2015-10-13 08:19:27.330 [DEBUG] [.o.b.nest.internal.NestBinding:288 ]- We received this event (item='N_V_NestCurrTemp', state='63') from Nest, so we don't send it back again -> ignore!
2015-10-13 08:19:27.330 [TRACE] [.o.b.nest.internal.NestBinding:175 ]- Updating itemName 'S_C_NestAway' with newState 'Uninitialized'
2015-10-13 08:19:27.330 [TRACE] [.o.b.nest.internal.NestBinding:182 ]- Added event (item='S_C_NestAway', newState='Uninitialized') to the ignore event list
2015-10-13 08:19:27.331 [TRACE] [.o.b.nest.internal.NestBinding:175 ]- Updating itemName 'N_NestOnline' with newState 'ON'
2015-10-13 08:19:27.331 [TRACE] [.o.b.nest.internal.NestBinding:182 ]- Added event (item='N_NestOnline', newState='ON') to the ignore event list
2015-10-13 08:19:27.331 [TRACE] [.o.b.nest.internal.NestBinding:265 ]- Received update (item='S_C_NestAway', state='Uninitialized')
2015-10-13 08:19:27.332 [DEBUG] [.o.b.nest.internal.NestBinding:288 ]- We received this event (item='S_C_NestAway', state='Uninitialized') from Nest, so we don't send it back again -> ignore!
2015-10-13 08:19:27.334 [TRACE] [.o.b.nest.internal.NestBinding:265 ]- Received update (item='N_NestOnline', state='ON')
2015-10-13 08:19:27.334 [DEBUG] [.o.b.nest.internal.NestBinding:288 ]- We received this event (item='N_NestOnline', state='ON') from Nest, so we don't send it back again -> ignore!Hi Rich,
I would say that either 1) the name of your structure is not “Home” but is set to some other string, or, less likely, 2) your client at developer.nest.com is not authorized for the “Away read/write v1” permission. It looks like the only binding config string that’s not working is "<[structures(Home).away]", and it’s the only one referencing the structure.
Let me know if it’s neither option and I will look some more.
John
Indeed, the structure name was wrong. I while back I installed an update to Nest that went bad and I had to reconfigure everything, including the name. I must have picked a different name at that time and never noticed that it was causing errors in opneHAB until recently.
Thanks!
Rich
Glad there was a fix, Rich!
I’ve got a similar problem to this thread. I’m running openhab 1.8 on a Mac. I’m trying the Nest binding example at https://github.com/openhab/openhab/wiki/Nest-Binding-Example
In openhab.cfg I’ve got:
#
# the Nest Client ID needed to use the API, must be supplied
nest:client_id=2c4c4adb-d90a-4bf6-a480-9002c00a1xxx
# the Nest Client Secret needed to use the API, must be supplied
nest:client_secret=wfBRy8zdAdfWccxTtAusKXxxx
# the PIN code that Nest presented when you authorized the above client, must be supplied
nest:pin_code=V946Txxx
But in the log I see:
2016-03-15 18:23:50.347 [WARN ] [b.n.i.messages.AbstractRequest] - Method failed: HTTP/1.1 400 Bad Request
2016-03-15 18:23:50.347 [ERROR] [.o.b.nest.internal.NestBinding] - Error retrieving access token: AccessTokenResponse[accessToken=,expiresIn=,error=oauth2_error,errorDescription=authorization code not found]'
2016-03-15 18:23:50.348 [WARN ] [.o.b.nest.internal.NestBinding] - Periodic poll skipped.
Any suggestions? The credentials and pin seem right to me but it looks like a login error. In an earlier post someone suggested a persistence issue? I haven’t touched the persistence from the demo code.
Thanks, Jim
Hi Jim, I recommend making sure you exactly copied the client_id, client_secret and pin_code into openhab.cfg. Also make sure that there are no leading or trailing whitespace characters on any lines in openhab.cfg.
If you have verified all of that, then try the step to generate a new pin_code and paste that in place of the previous pin_code value in openhab.cfg, stop and restart openHAB. The binding will get try to get a new access token if it sees that you changed the PIN.
I double checked that there were no spaces, got a new pin, restarted openhab but that didn’t work. I then reread the installation guide which said that on a Mac, put openhab at /opt/openhab. I’d installed mine at ~/openhab. I moved openhab to /opt/openhab, fired it up and the nest binding is mostly working.
Do you suppose it could have been location specific? If not, then when I moved it, something on my system reset itself properly so that it would run.
Most of the items are loading properly but I get the following error on the ‘structures(Home).away’.
2016-03-19 17:03:58.322 [ERROR] [.o.b.nest.internal.NestBinding] - Unable to get state from data model
org.apache.commons.beanutils.NestedNullException: Null property value for 'structures(Home).away' on bean class 'class org.openhab.binding.nest.internal.messages.DataModelResponse'
at org.apache.commons.beanutils.PropertyUtilsBean.getNestedProperty(PropertyUtilsBean.java:755) ~[commons-beanutils-1.8.3.jar:1.8.3]
at org.apache.commons.beanutils.PropertyUtilsBean.getProperty(PropertyUtilsBean.java:846) ~[commons-beanutils-1.8.3.jar:1.8.3]
at org.openhab.binding.nest.internal.messages.DataModel.getProperty(DataModel.java:339) ~[bundlefile:na]
at org.openhab.binding.nest.internal.NestBinding.getState(NestBinding.java:238) [bundlefile:na]
at org.openhab.binding.nest.internal.NestBinding.readNest(NestBinding.java:206) [bundlefile:na]
at org.openhab.binding.nest.internal.NestBinding.execute(NestBinding.java:168) [bundlefile:na]
at org.openhab.core.binding.AbstractActiveBinding$BindingActiveService.execute(AbstractActiveBinding.java:156) [org.openhab.core_1.8.1.jar:na]
at org.openhab.core.service.AbstractActiveService$RefreshThread.run(AbstractActiveService.java:173) [org.openhab.core_1.8.1.jar:na]
My items file has:
String home_away "Home/Away [%s]" <present> { nest="=[structures(Home).away]" }
My best guess is that the name, “Home”, is wrong. This is the default. I don’t remember changing it and it is what I see in the app. Is there some other way to see what the name is? Or another suggestion?
You could enable TRACE logging for the binding (as described here or just add the following to logback.xml):
<logger name="org.openhab.binding.nest" level="TRACE"/>
This should dump the raw JSON to the log, from which we can determine the name for your structure. (If you paste the raw JSON here, make sure to redact out any private information like your access token, personally identifying information, etc.)
Hi a have problem with home_away
Null property value for ‘structures(Home).away’
Where i find logback.xml ??
in nest Api i add away read/write and still not work
I’m having the same problem as the OP, I’m running OpenHAB 2.1.0.
logback.xml is only part of openHAB 1.x. Please see docs.openhab.org for how to enable logging in openHAB 2.x.
http://docs.openhab.org/administration/logging.html#config-file I’ve had a look here and can’t seem to get any trace entries into the openhab.log file.
I added; log:set TRACE org.openhab.binding.nest to the config-file. So either I’ve got the wrong file or the incorrect syntax
Is that special to the NEST binding? Because all other log:set commands (I tried zwave and astro recently) do show up in openhab.log:
2017-06-26 20:32:53.279 [DEBUG] [org.eclipse.smarthome.binding.astro ] - BundleEvent STARTED - org.eclipse.smarthome.binding.astro
2017-06-26 20:32:54.150 [DEBUG] [ding.astro.handler.AstroThingHandler] - Initializing thing astro:sun:shutterlivingroom
2017-06-26 20:32:54.643 [DEBUG] [ding.astro.handler.AstroThingHandler] - AstroThingConfig[thing=astro:sun:shutterlivingroom,geolocation=xx,yy,altitude=2.0,interval=3600,systemTimezone=Europe/Berlin (MEZ +0200),daylightSavings=true]
2017-06-26 20:32:54.691 [DEBUG] [ding.astro.handler.AstroThingHandler] - Restarting jobs for thing astro:sun:shutterlivingroom
The problem was OP was putting log:set into userdata/etc/org.ops4j.pax.logging.cfg when that command is intended to only be issued from inside the Karaf console.
1 Like
Arrgh, did not read the whole thing 