Item State not Updating

meingraham · February 27, 2019, 3:25pm

Platform information:

Linux openHABianPi 4.14.98-v7+ #1200 SMP Tue Feb 12 20:27:48 GMT 2019 armv7l
Release = Raspbian GNU/Linux 9 (stretch)
Kernel = Linux 4.14.98-v7+
Platform = Raspberry Pi 3 Model B Rev 1.2
openjdk version "1.8.0_152"
OpenJDK Runtime Environment (Zulu Embedded 8.25.0.76-linux-aarch32hf) (build 1.8.0_152-b76)
OpenJDK Client VM (Zulu Embedded 8.25.0.76-linux-aarch32hf) (build 25.152-b76, mixed mode, Evaluation)
openHAB 2.4.0-1 (Release Build)

// Thermostat Scheduled stored in openHAB Google Calendar - CalDav
Number:Temperature      SPT_house_VT_hallway_wall_sensor_thermostat_TargetTemperatureMin "Target Temperature Min [%.1f %unit%]"
Number:Temperature      SPT_house_VT_hallway_wall_sensor_thermostat_TargetTemperatureMax "Target Temperature Max [%.1f %unit%]"

These Items are set via the CalDav binding (see below as to why I do not believe the problem is with the binding) which retrieves the values from my Google Calendar with multiple changes throughout each day which recur day-to-day, week-to-week.

When I first set this up and got it configured properly, it worked as expected. However, in the last several days, one of the two Item states is no longer being updated. “Min” updates as expected. “Max” is “stuck” and does not update.

At first I thought it might be an issue with the CalDav binding. The log shows that the commands are being sent to the Items on my set schedule.

2019-02-27 06:45:00.009	ItemCommandEvent	Item 'SPT_house_VT_hallway_wall_sensor_thermostat_TargetTemperatureMin' received command 72
2019-02-27 06:45:00.018	ItemCommandEvent	Item 'SPT_house_VT_hallway_wall_sensor_thermostat_TargetTemperatureMax' received command 76
2019-02-27 09:40:18.754	ItemCommandEvent	Item 'SPT_house_VT_hallway_wall_sensor_thermostat_TargetTemperatureMin' received command 72
2019-02-27 09:40:18.764	ItemCommandEvent	Item 'SPT_house_VT_hallway_wall_sensor_thermostat_TargetTemperatureMax' received command 76

However, Max is not being updated to the values in my schedule.

I have stop/started, rebooted, cleared the cache & temp files, etc. None of these have had an effect.

I have been trying to troubleshoot this as a problem somewhere in CalDav or my configuration, or my Item and Sitemap declarations. Nothing appears to be wrong there.

Today I decided to use the REST UI to work my way upward toward the CalDav binding. I used the Item POST to send a value to the Item followed by an Item GET to look at the state.

These log entries are as the result of my interaction with the REST UI.

2019-02-27 09:41:56.366	ItemCommandEvent	Item 'SPT_house_VT_hallway_wall_sensor_thermostat_TargetTemperatureMax' received command 78
2019-02-27 09:45:19.142	ItemCommandEvent	Item 'SPT_house_VT_hallway_wall_sensor_thermostat_TargetTemperatureMin' received command 71

The images below show that the “Max” (name appears truncated due to length of Item name vs. the length of the text box) POST completed successfully (200), yet when I look at the Item state it does not match the value I just set. In fact, it is the value at which the Item has been stuck at since this problem started.

When I perform the same actions for the “Min” Item, it updates as it should. The images show that as well.

REST UI Actions for "Max"

REST UI Actions for "Min"

Any ideas where I can continue to explore to troubleshoot this issue?

Thanks.

Mike

rossko57 · February 27, 2019, 3:57pm

May we see the events.log corresponding to your REST commands?
Note that Item states may not always get updated by commands, unless directed by a binding or by autoupdate. We can’t see the binding part of your Item’s definition that would control that.

I do wonder if the very long names are somehow involved.

rlkoshak · February 27, 2019, 4:23pm

That was my first thought too, but the min Item works and it is just as long as the max Item name.

How are these Items defined?

To test rossko’s theory, can you shorten the names of these two Items?

I also agree, what get’s logged to events.log when you unsuccessfully sendCommand or postUpdate a new state to the max Item?

meingraham · February 27, 2019, 5:02pm

Yeah, I wondered about the names… but they are both the same length as you guys noted.

The Items declarations I included in the post are in an items file.

The log of the sendCommand and of my REST send commands is in the original post (just cleaned up for readability). Is there something further that I need to capture? That’s all that’s in the events log.

Shortening the names… I can give that a try… but it’ll be a headache because it’ll involve changing my Calendar entries. Changing the Items & Sitemap is easy. Only one Rule is impacted. But, if there’s something else to do before that, I would prefer that. Is there a way to turn on debugging for “sendCommand” events? Then I can use REST to capture some more detail… and then turn debugging off.

Mike

rlkoshak · February 27, 2019, 6:17pm

You only need to change the name long enough to load the .items file and exercise it using the REST API. If it works then we have some evidence that the problem is the name length. If it still doesn’t work then we know the problem is elsewhere. The name change need not be permanent.

CalDav is a 1.x binding, right? Where is the binding configs in your Items definitions?

I don’t see any “changed” log entries. When a command results in a change you should see two log entries. Depending on the autoupdate setting you’ll see a third log entry talking about predicting the state. For example:

2019-02-23 14:44:38.574 [ome.event.ItemCommandEvent] - Item 'vHydra_SensorReporter_Uptime' received command 37:22:50:12
2019-02-23 14:44:38.576 [nt.ItemStatePredictedEvent] - vHydra_SensorReporter_Uptime predicted to become 37:22:50:12
2019-02-23 14:44:38.578 [vent.ItemStateChangedEvent] - vHydra_SensorReporter_Uptime changed from 37:22:49:12 to 37:22:50:12

You’ve only posted the received command log entries. Do you not have these other entries?

meingraham · February 27, 2019, 7:52pm

There is no CalDav binding configuration in the Item definition. The binding itself is configured to know what calendar to read. CalDav then reads the events in the Calendar and expects to find the tags it requires (what to do at the beginning of the event, what to do at the end of the event, etc.). It then schedules itself to perform those commands at the time of the Calendar entries. So, for example, this is one of my Calendar events:

BEGIN:SPT_house_VT_hallway_wall_sensor_thermostat_TargetTemperatureMin:72
BEGIN:SPT_house_VT_hallway_wall_sensor_thermostat_TargetTemperatureMax:75

I have never seen messages like these in my log:

And “[ItemStatePredictedEvent] … predicted to become” aren’t always there when a “received command” takes place.

So, I changed the name, saved the .items file and set the new name via the REST UI. I am able to update the value of a shorter named Item. Changing the name created a new Item. I would not have expected differently. While the old Item name was no longer declared, I did try to POST a value to it and it did fail, as expected, because that Item did not exist in the registry. However, when I restore the old name, the old “stuck” value returns due to my persistence settings… and, I still cannot update the Items’ value.

Mike

rossko57 · February 27, 2019, 8:18pm

It’d be helpful to see the events.log for a working caldav-command update of your “min” Item

That’s correct. That comes from autoupdate, and
(a) it only appears if a command is expected to make a change e.g. send command ON to a switch with current state OFF, and
(b) autoupdate can be optionally disabled per Item.

This messaging from autoupdate is new in 2.4

This stuff is important here, because if the caldav binding is sending commands and you are looking at states, you are totally reliant on autoupdate working.

I don’t like the long names, but I’m sure other people would have run into this before if there was an issue? Won’t rule it out though - some localised truncation effect would make both your long names appear to refer to the same Item sometimes.

I don’t like these numeric-only commands being sent to Number:Temperature type Items, because they expect something like 27°C
I’ve little idea of what you are “supposed” to send instead, this UoM stuff seems to be a bit trial and error for me.

No idea why your Items behave differently if its a UoM issue. You seem to be saying there’s persistence involved here as well, restore on startup perhaps?

meingraham · February 27, 2019, 8:34pm

caldav.log (118.4 KB)

The file I uploaded is every events.log entry associated with these Items since I implemented the CalDav binding a few weeks ago.

Yes, the names are long… but this can’t be the reason as Min is the same length.

UOM - yup. I am confused by this as well. But I defined them as Temperatures because my Nest Items are defined accordingly per the Nest binding documentation. I am using these “CalDav” setpoints with my Nest Items. But, again, Min works.

Persistence - correct. I’m using mapdb to restore values on startup. That’s the only way I can explain that the value “returned” to the Item after I had deleted it from the registry (during the name change experiment).

I did stop openHAB and start it again after I had changed the name of the Item. I did not reboot. I did not clear the cache & temp files. I was just trying to ensure that the old Item declaration wasn’t “lost in space” during the name change.

Mike

rossko57 · February 27, 2019, 8:56pm

I guess that’s a filtered log. It contains not a single instance of any openHAB Item state change… Based on that, neither of your Items is working - but I expect its just a filtering thing?

All I wanted was to see the expected events -
command to min Item
autoupdate prediction for min Item
min Item state change
and compare with a failing max example.

We could go at this the brute force way:
Create two plain Number type Items with short names.
Add those to caldav-command. (Can you add, or must it be replace?)
Don’t mess with persistence yet.
Shut down OH.
Find and destroy cached caldavio.config, caldavCommand.config, they will get recreated from caldav.cfg etc.
Reboot.
Test.

When working, restore your long names, temperature type, persistence, etc. until trouble shows up.

meingraham · February 27, 2019, 9:16pm

I didn’t explicitly implement any log filtering myself. Is there somewhere I can look to clear any filters? This “filtering” is system wide as I don’t have any messages of that sort in my log for any Items, regardless of binding.

I think that capturing the information you mention would be a good next step before the steps you outline. Then I’ll start on the “reconfiguration” of this set of Items.

In the interim, regarding CalDav… I had many issues getting CalDav to function properly. I finally found several topics that explained that one had to create caldavio.cfg to prepend caldavio: to each option in the file. I also created caldavCommand.cfg manually… although it is a very simple configuration.

################################### CalDAV IO Binding ###################################
caldavio:openhab:url=https://www.google.com/calendar/dav/<calendarID>@group.calendar.google.com/events
caldavio:openhab:username=<userID>
caldavio:openhab:password=<2FAappPassword>
caldavio:openhab:reloadInterval=720
caldavio:openhab:disableCertificateVerification=true

################################ CalDAV Command Binding ###################################
readCalendars=openhab

Any direction on logging and getting the additional information to be logged? Attached is my org.ops4j.pax.logging.cfg (I changed the extension so that I could upload it).

org.ops4j.pax.logging.cfg.txt (17.4 KB)

Mike

rossko57 · February 27, 2019, 9:39pm

That’s weird then. Beyond my knowledge I’m afraid, hopefully someone else can help. Just to confirm, it is events.log we’re looking at.

As for configuration, yes 1.x bindings require xxx.cfg files.

Also as I understand it, part of the OH2 support of 1.x caches your xxx.cfg in a new file xxx.config, which appears to sometimes catch folk out when changes are made. So as a precaution, if you change xxx.cfg, stop OH and delete xxx.config to enforce changes.

There’s no way this 1.x binding understands UoM, so it’s a case of if a UoM Item supports non-dimensioned number updates and if autoupdate handles the case. I’m not convinced about that

rlkoshak · February 27, 2019, 9:42pm

I don’t think we can be so sure. If the name gets truncated somehow, then it’s possible that only the first long Item matches. What if you made the different part between the two be at the front instead of the end of the file name.

Correct and typically we cannot use UoM willy nilly. It needs to be supported by the binding I think.

meingraham · February 27, 2019, 9:55pm

Yes, events.log. Let’s see if anyone can weigh in on how I can get more detailed logging.

As you can tell, I’m not relishing rolling name changes throughout all the Calendar entries. What we’re not discussing regarding reconfiguring or changing the naming convention is headed in that direction.

CalDav is an “oddball” binding it appears. I think it’s just reading the calendar events and, in essence, generating DSL (I say this in a conceptual terms). What I mean is, caldavCommand reads the Calendar events. It interprets the BEGIN (or END) and sets a cron trigger for the time of each Calendar event. It then looks at the rest of the entry, which in my case is the syntax for setting an Item value. It generates item.sendCommand(value). Thus, the code triggers at the set cron time and runs the setCommand(s). So, the CalDav binding cares less about the data type of each Item. If I have not properly associated the Item and the value, it is the binding associated with the Item that will handle the error, not CalDav. So, the question of sendCommand setting a “plain” value (without any UOM) to an Item that is defined as a Temperature is an issue which should be handled there (i.e., not by CalDav).

Mike

rlkoshak · February 27, 2019, 10:11pm

Have you modified your logging config? The missing lines we are talking about should just appear there as of OH 2.4.

So far it’s the only thing that we can point to as being the problem. You changed the name and it worked. You changed it back and it stopped working again. There is something wrong and changing the name fixed it.

Which leads back to rossko’s statement above. We don’t know that it is handled there. It might require you to append the units in order for it to work.

meingraham · February 27, 2019, 10:26pm

Can someone point me to where I can grab the original logging config file that came with 2.4 (release)?

BTW, I uploaded my customized logging config in this post (Item State not Updating) a couple of posts ago.

The interesting thing is that the Max Item was receiving updates when I first set up CalDav. That’s how that 75 got in there in the first place. I’m not sure what changed (it actually might have been when I installed 2.4 release!).

When I was installing SNAPSHOTs I was being careful to save my modified version and then incorporating my changes to the file that came with the SNAPSHOT. To be honest, I hadn’t installed a new OH version in several weeks and I may not have been careful to go through this process when I grabbed the release version.

My updates only include adding some custom loggers for some of my own logging (power monitoring, temperature) and redirecting Chromecast & Samsung to their own files when I was helping test those bindings.

I’ll start with the “as released” configuration file and once I’m getting all the detailed logging we’re expecting, I’ll go back and add my mods.

Mike

rossko57 · February 28, 2019, 12:04am

Out of curiosity, I used REST API to command plain numbers to an existing Number:Temperature UoM Item. (OH 2.4 release)
Seems to work, accepting the value as being in the “current” dimension, °C in my case.
events.log

2019-02-27 22:33:22.504 [ome.event.ItemCommandEvent] - Item 'nmt_CurrentTemperature' received command 12
2019-02-27 22:33:22.509 [nt.ItemStatePredictedEvent] - nmt_CurrentTemperature predicted to become 12
2019-02-27 22:33:22.530 [vent.ItemStateChangedEvent] - nmt_CurrentTemperature changed from 21.5 °C to 12.0 °C

What’s the current dimension then, if its not specified in the command/update? The UoM framework seems to guess this based on clues from the Items label format [ ]
Mine, like yours, is specified [%.0f %unit%] - no actual clue there.
but -
The Item was previously updated by a 2.x (weather) binding that does understand UoM and populated the Item with e.g. 10 °C, so Item has picked up this, uhm, flavour of °C
also -
°C is the default for Number:Temperature anyway.

I also created a brand new Number:Temperature Item from xxx.items file
with “label [%.0f %unit%]”, so no clues inbuilt.
Used REST API to send plain number, accepted and updated from NULL to 12.0 °C, demonstrating the default in action.
(I would guess your locale defaults °F)

All of which says you can command plain numbers at Number:Temperature Items and expect autoupdate to do something.
I am more convinced about that now

What is not clear from all this is how persistence/restore-on-startup interacts. I would guess it stores/restores plain numbers and lets the UoM sort it out.

rossko57 · February 28, 2019, 12:37am

I think the long names issue is a red herring too, since we have correct looking logs of commands issued by caldav

I created two new Items identical to yours, used REST API to command
events.log

2019-02-28 00:19:58.697 [ome.event.ItemCommandEvent] - Item 'SPT_house_VT_hallway_wall_sensor_thermostat_TargetTemperatureMin' received command 12
2019-02-28 00:19:58.709 [vent.ItemStateChangedEvent] - SPT_house_VT_hallway_wall_sensor_thermostat_TargetTemperatureMin changed from NULL to 12.0 °C
2019-02-28 00:21:20.416 [ome.event.ItemCommandEvent] - Item 'SPT_house_VT_hallway_wall_sensor_thermostat_TargetTemperatureMax' received command 22
2019-02-28 00:21:20.429 [vent.ItemStateChangedEvent] - SPT_house_VT_hallway_wall_sensor_thermostat_TargetTemperatureMax changed from NULL to 22.0 °C
2019-02-28 00:21:47.113 [ome.event.ItemCommandEvent] - Item 'SPT_house_VT_hallway_wall_sensor_thermostat_TargetTemperatureMax' received command 33
2019-02-28 00:21:47.123 [vent.ItemStateChangedEvent] - SPT_house_VT_hallway_wall_sensor_thermostat_TargetTemperatureMax changed from 22.0 °C to 33.0 °C
2019-02-28 00:22:26.724 [ome.event.ItemCommandEvent] - Item 'SPT_house_VT_hallway_wall_sensor_thermostat_TargetTemperatureMin' received command 44
2019-02-28 00:22:26.739 [vent.ItemStateChangedEvent] - SPT_house_VT_hallway_wall_sensor_thermostat_TargetTemperatureMin changed from 12.0 °C to 44.0 °C

I’m pretty sure caldav will use the same REST methods to communicate with openHAB, since there’s no real binding to Items?

meingraham · February 28, 2019, 12:40am

Based on it originally working and what you’ve researched… I’d have to concur.

Does someone have an uncustomized 2.4.0 release logging config file I can use?

rossko57 · February 28, 2019, 12:46am

Here is an unmolested 2.4.0 version of the file you posted earlier, albeit from a Windows system, unknown differences
logging.config.txt (4.9 KB)

meingraham · February 28, 2019, 3:02am

I have increased some of the logging levels from WARN to INFO. I’ll track whether I start seeing additional messages being logged. The Chromecast binding generates so many “update” errors… hopefully this additional logging will generate the information for this issue… and I’ll turn those back off. I’ll report more tomorrow.