Z-Wave Locks Switching Randomly

rpwong · February 13, 2022, 10:19pm

I wondered about that too, but it seems awfully weird that a corrupt SD card would fire off all of the Z-Wave devices at once and then not do it again. I suppose there are stranger things, though…

rossko57 · February 13, 2022, 10:49pm

I don’t suppose it’s quite like that. I do have a feeling in my water that something like all Items or all Things “reset” in some way, and the recovery from that as Items get repopulated is firing off a flurry of rules.

EDIT -

PeteC:

2022-02-09 12:16:10.893 [vent.ItemStateChangedEvent] - Basement_Tstat_CoolSetPoint changed from NULL to 7E+1 °F
2022-02-09 12:16:11.185 [vent.ItemStateChangedEvent] - ThermostatBattery changed from NULL to 100

Still homing in on this NULL anomaly. I’ll bet if you search preceding events.log there is no “some valid value → NULL” change logged?
Talking of Things reset reminded me … oh yeah, in OH2 zwave could throw a wobbly somehow and silently set linked Items to NULL - that isn’t something bindings should do, but this was associated with the Thing being “reset”
Check your events.log for events like

2020-08-20 02:58:25.352 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:5204811e:node4' has been updated.

PeteC · February 14, 2022, 8:08pm

rossko57:

PeteC:

However, openHAB.log doesn't show any commands to the HVAC

You sure?

Yes, the HVAC entries are from events.log.
I also intended to include openhab.log in that post but it seems to be missing.
I should have reviewed it better, sorry.
Here is the contents of openhab.log at the point of interest
2022-02-09 12:16:01.344 [DEBUG] [e.smarthome.model.script.RULE_SYSTEM] - FrontLock Lock Un-Secured by Controller – Successful (Fully retracted)
2022-02-09 12:16:03.911 [DEBUG] [e.smarthome.model.script.RULE_SYSTEM] - Porch Lock: Alarm events: TFormed State: 25, StateValue: 1
2022-02-09 12:16:03.926 [DEBUG] [e.smarthome.model.script.RULE_SYSTEM] - PorchLock RF unlock
2022-02-09 12:16:10.875 [WARN ] [al.profiles.MapTransformationProfile] - Please specify a function and a source format for this Profile in the 'function' and 'sourceFormat' parameters, e.g "translation.map" and "%s". Returning the original state now.
2022-02-09 12:16:11.176 [WARN ] [al.profiles.MapTransformationProfile] - Please specify a function and a source format for this Profile in the 'function' and 'sourceFormat' parameters, e.g "translation.map" and "%s". Returning the original state now.
2022-02-09 12:16:33.377 [WARN ] [al.profiles.MapTransformationProfile] - Please specify a function and a source format for this Profile in the 'function' and 'sourceFormat' parameters, e.g "translation.map" and "%s". Returning the original state now.
2022-02-09 12:16:33.824 [WARN ] [al.profiles.MapTransformationProfile] - Please specify a function and a source format for this Profile in the 'function' and 'sourceFormat' parameters, e.g "translation.map" and "%s". Returning the original state now.
2022-02-09 12:16:37.895 [WARN ] [al.profiles.MapTransformationProfile] - Please specify a function and a source format for this Profile in the 'function' and 'sourceFormat' parameters, e.g "translation.map" and "%s". Returning the original state now.
2022-02-09 12:16:38.290 [WARN ] [al.profiles.MapTransformationProfile] - Please specify a function and a source format for this Profile in the 'function' and 'sourceFormat' parameters, e.g "translation.map" and "%s". Returning the original state now.
2022-02-09 12:16:58.036 [DEBUG] [e.smarthome.model.script.RULE_SYSTEM] - Garage Lock: Alarm events: TFormed State: 0, StateValue: 0
2022-02-09 12:16:59.067 [DEBUG] [e.smarthome.model.script.RULE_SYSTEM] - Garage Lock: Alarm events: TFormed State: 25, StateValue: 1
2022-02-09 12:16:59.095 [DEBUG] [e.smarthome.model.script.RULE_SYSTEM] - GarageLock RF unlock
PeteC:
2022-02-09 12:16:08.792 [ome.event.ItemCommandEvent] - Item 'HVAC_Mode' received command 1
...
2022-02-09 12:16:31.394 [ome.event.ItemCommandEvent] - Item 'HVAC_Fan_State' received command 1
PeteC:

2/9 at 12:13:39.026 all hell breaks loose.
“An I/O error has occurred while writing a response message entity to the container output stream.”

Looks UI related; don’t leap on that as cause though, just as likely a symptom.

Need to ask again - do you have a permanent tablet display or such, a browser window in the background, cat on the keyboard?

Sorry I didn’t answer before. I didn’t fully understand the question and never returned to it.

My RPi has a monitor, and keyboard/mouse (connected by a USB dongle) and a AEOTEC Z-Wave interface.

Still don’t really see the source as UI though - would not explain NULL states. Just as an xxx.items file glitch alone does not explain commands.

Have you rules that might activate locks and HVAC, based off of say time-of-day?

No rules for the HVAC. Each lock has a rule instructing it to “lock” at 10:00 PM.
Also each lock has a “rule” that converts the TFormed State,and StateValue: from a numerical code to human readable text for display.

PeteC:

I built my system a few years ago

So, Pi hardware. Is this running off an SD card of some vintage?

The “vintage” is a little uncertain. After I do a Linux upgrade I make five or six copies and test them all so the one being used is random and of random vintage.

rossko57 · February 14, 2022, 9:02pm

rossko57:

2022-02-09 12:16:10.875 [WARN ] [al.profiles.MapTransformationProfile] - Please specify a function and a source format for this Profile in the 'function' and 'sourceFormat' parameters, e.g "translation.map" and "%s". Returning the original state now.

That one is an unrelated little sideshow. One or more of your Item-to-channel links has a faulty profile configured on it. If you configure your Items from xxx.items files, you’ll probably see it/them with a visual scan.

PeteC · February 14, 2022, 9:53pm

rossko57:

rpwong:

weird that a corrupt SD card would fire off all of the Z-Wave devices at once

I don’t suppose it’s quite like that. I do have a feeling in my water that something like all Items or all Things “reset” in some way, and the recovery from that as Items get repopulated is firing off a flurry of rules.

EDIT -
PeteC:
2022-02-09 12:16:10.893 [vent.ItemStateChangedEvent] - Basement_Tstat_CoolSetPoint changed from NULL to 7E+1 °F
2022-02-09 12:16:11.185 [vent.ItemStateChangedEvent] - ThermostatBattery changed from NULL to 100
Still homing in on this NULL anomaly. I’ll bet if you search preceding events.log there is no “some valid value → NULL” change logged?

You are correct. The word “NULL” appears 51 times but always from “NULL to some valid value or state”

Talking of Things reset reminded me … oh yeah, in OH2 zwave could throw a wobbly somehow and silently set linked Items to NULL - that isn’t something bindings should do, but this was associated with the Thing being “reset”
Check your events.log for events like
2020-08-20 02:58:25.352 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:5204811e:node4' has been updated.

The word “updated” appears 508 times (actually 254 events, the word appears twice per event)
At 2 in the morning the four Z-Wave devices “has been updated”.
Then just before 11PM it begins of updating each of the locks at about 200 milliseconds. intervals. Each update event is followed by a “ConfigStatusInfo” event two milliseconds later.
This 200 millisecond cycle repeats for about a minute then things seem to settle down.
Note, this burst just before 11PM is preceded by about 20 events of:
UNINITIALIZED to INITIALIZING
INITIALIZING to OFFLINE (BRIDGE_OFFLINE)
For various Z-Wave devices, some of which no longer exist
I hate do do this but here is the whole gory event,log
I wish I could find an explanation for what these entries mean. It would save you folks a lot.


2022-02-09 01:43:10.258 [vent.ItemStateChangedEvent] - Temperature_HVAC changed from 71 °F to 7E+1 °F
2022-02-09 02:24:40.957 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:fe40ab17:node32' has been updated.
2022-02-09 02:24:41.647 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:fe40ab17:node26' has been updated.
2022-02-09 02:25:08.452 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:fe40ab17:node28' has been updated.
2022-02-09 02:25:08.797 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:fe40ab17:node5' has been updated.
2022-02-09 02:26:49.003 [vent.ItemStateChangedEvent] - WatchDogBurp changed from BurpDown to BurpUp
2022-02-09 02:26:49.211 [vent.ItemStateChangedEvent] - When_Bumped changed from 2022-02-09T01:24:18.772-0600 to 2022-02-09T02:26:49.201-0600
*XXXXX I had to remove some lines here to stay below the 48000 character limit XXXXX*
2022-02-09 09:44:23.347 [vent.ItemStateChangedEvent] - When_Bumped changed from 2022-02-09T08:41:52.549-0600 to 2022-02-09T09:44:23.322-0600
2022-02-09 09:53:21.919 [vent.ItemStateChangedEvent] - BackLeftWindow changed from N0_RPT to StillClosed
2022-02-09 10:11:06.382 [vent.ItemStateChangedEvent] - Garage_Alarm_Raw changed from {"type":"0","value":"0"} to {"type":"22","value":"1"}
2022-02-09 10:11:07.245 [vent.ItemStateChangedEvent] - GarageDoor changed from StillClosed to Opening
2022-02-09 10:11:09.025 [vent.ItemStateChangedEvent] - Garage_Alarm_Virtual changed from RF lock to Manual unlock
2022-02-09 10:11:09.029 [vent.ItemStateChangedEvent] - Garage_Alarm_Virtual_Short changed from Secured to Un-Secured
2022-02-09 10:11:13.485 [vent.ItemStateChangedEvent] - GarageDoor changed from Opening to Closing
2022-02-09 10:11:25.062 [vent.ItemStateChangedEvent] - GarageDoor changed from Closing to Opening
2022-02-09 10:11:30.696 [vent.ItemStateChangedEvent] - GarageDoor changed from Opening to Closing
2022-02-09 10:12:30.081 [vent.ItemStateChangedEvent] - GarageDoor changed from Closing to Opening
2022-02-09 10:12:32.299 [vent.ItemStateChangedEvent] - GarageLightState changed from Off to On
2022-02-09 10:12:35.866 [vent.ItemStateChangedEvent] - GarageDoor changed from Opening to Closing
2022-02-09 10:13:03.615 [vent.ItemStateChangedEvent] - GarageDoor changed from Closing to Opening
2022-02-09 10:13:04.361 [vent.ItemStateChangedEvent] - GarageLightState changed from On to Off
2022-02-09 10:13:09.850 [vent.ItemStateChangedEvent] - GarageDoor changed from Opening to Closing
2022-02-09 10:14:03.874 [vent.ItemStateChangedEvent] - GarageDoor changed from Closing to StillClosed
2022-02-09 10:15:48.788 [vent.ItemStateChangedEvent] - GarageDoor changed from StillClosed to Opening
2022-02-09 10:15:50.647 [vent.ItemStateChangedEvent] - GarageLightState changed from Off to On
2022-02-09 10:15:53.546 [vent.ItemStateChangedEvent] - GarageDoor changed from Opening to Closing
2022-02-09 10:20:01.924 [vent.ItemStateChangedEvent] - GarageDoor changed from Closing to Opening
2022-02-09 10:20:07.776 [vent.ItemStateChangedEvent] - GarageDoor changed from Opening to Closing
2022-02-09 10:22:19.913 [vent.ItemStateChangedEvent] - GarageDoor changed from Closing to Opening
2022-02-09 10:22:24.600 [vent.ItemStateChangedEvent] - GarageDoor changed from Opening to Closing
2022-02-09 10:23:38.080 [vent.ItemStateChangedEvent] - GarageDoor changed from Closing to Opening
2022-02-09 10:23:43.770 [vent.ItemStateChangedEvent] - GarageDoor changed from Opening to Closing
2022-02-09 10:32:04.497 [vent.ItemStateChangedEvent] - GarageDoor changed from Closing to Opening
2022-02-09 10:32:09.143 [vent.ItemStateChangedEvent] - GarageDoor changed from Opening to Closing
2022-02-09 10:32:30.182 [vent.ItemStateChangedEvent] - GarageDoor changed from Closing to Opening
2022-02-09 10:32:36.359 [vent.ItemStateChangedEvent] - GarageDoor changed from Opening to Closing
2022-02-09 10:35:21.688 [vent.ItemStateChangedEvent] - Front_Alarm_Raw changed from {"type":"18","value":"0"} to {"type":"22","value":"1"}
2022-02-09 10:35:23.171 [vent.ItemStateChangedEvent] - FrontDoor changed from StillClosed to Opening
2022-02-09 10:35:23.821 [vent.ItemStateChangedEvent] - Front_Alarm_Virtual changed from Lock Secured using Keyed cylinder or inside thumb-turn to Lock Un-Secured using Keyed cylinder or inside thumb-turn
2022-02-09 10:35:23.824 [vent.ItemStateChangedEvent] - Front_Alarm_Virtual_Short changed from Secured to Un-Secured
2022-02-09 10:35:31.450 [vent.ItemStateChangedEvent] - FrontDoor changed from Opening to Closing
2022-02-09 10:46:59.297 [vent.ItemStateChangedEvent] - WatchDogBurp changed from BurpDown to BurpUp
2022-02-09 10:46:59.315 [vent.ItemStateChangedEvent] - When_Bumped changed from 2022-02-09T09:44:23.322-0600 to 2022-02-09T10:46:59.304-0600
2022-02-09 10:51:12.700 [vent.ItemStateChangedEvent] - GarageDoor changed from Closing to Opening
2022-02-09 10:51:17.774 [vent.ItemStateChangedEvent] - GarageDoor changed from Opening to Closing
2022-02-09 10:51:42.537 [vent.ItemStateChangedEvent] - GarageDoor changed from Closing to Opening
2022-02-09 10:51:44.306 [vent.ItemStateChangedEvent] - GarageLightState changed from On to Off
2022-02-09 10:51:49.277 [vent.ItemStateChangedEvent] - GarageDoor changed from Opening to Closing
2022-02-09 10:58:55.631 [vent.ItemStateChangedEvent] - Front_Lock_Door changed from ON to OFF
2022-02-09 10:58:55.781 [vent.ItemStateChangedEvent] - Front_Alarm_Raw changed from {"type":"22","value":"1"} to {"type":"18","value":"0"}
2022-02-09 11:16:57.631 [vent.ItemStateChangedEvent] - GarageDoor changed from Closing to StillClosed
2022-02-09 11:22:46.845 [vent.ItemStateChangedEvent] - FrontDoor changed from Closing to StillClosed
2022-02-09 11:23:22.172 [vent.ItemStateChangedEvent] - BackLeftWindow changed from StillClosed to N0_RPT
2022-02-09 11:49:29.547 [vent.ItemStateChangedEvent] - WatchDogBurp changed from BurpUp to BurpDown
2022-02-09 11:49:29.583 [vent.ItemStateChangedEvent] - When_Bumped changed from 2022-02-09T10:46:59.304-0600 to 2022-02-09T11:49:29.565-0600
2022-02-09 11:55:35.173 [vent.ItemStateChangedEvent] - Temperature_HVAC changed from 69 °F to 7E+1 °F
2022-02-09 12:07:10.342 [vent.ItemStateChangedEvent] - BackLeftWindow changed from N0_RPT to StillClosed
2022-02-09 12:13:06.733 [ome.event.ItemCommandEvent] - Item 'Bump_Time' received command ON
2022-02-09 12:13:06.750 [vent.ItemStateChangedEvent] - Bump_Time changed from NULL to ON
2022-02-09 12:15:43.588 [ome.event.ItemCommandEvent] - Item 'Garage_Lock_Door' received command OFF
2022-02-09 12:15:43.603 [nt.ItemStatePredictedEvent] - Garage_Lock_Door predicted to become OFF
2022-02-09 12:15:43.646 [vent.ItemStateChangedEvent] - Garage_Lock_Door changed from ON to OFF
2022-02-09 12:15:44.970 [ome.event.ItemCommandEvent] - Item 'Garage_Lock_Door' received command ON
2022-02-09 12:15:44.973 [nt.ItemStatePredictedEvent] - Garage_Lock_Door predicted to become ON
2022-02-09 12:15:44.986 [vent.ItemStateChangedEvent] - Garage_Lock_Door changed from OFF to ON
2022-02-09 12:15:45.752 [ome.event.ItemCommandEvent] - Item 'Garage_Lock_Door' received command OFF
2022-02-09 12:15:45.758 [nt.ItemStatePredictedEvent] - Garage_Lock_Door predicted to become OFF
2022-02-09 12:15:45.770 [vent.ItemStateChangedEvent] - Garage_Lock_Door changed from ON to OFF
2022-02-09 12:15:46.548 [vent.ItemStateChangedEvent] - Garage_Alarm_Raw changed from {"type":"22","value":"1"} to {"type":"25","value":"1"}
2022-02-09 12:15:46.595 [vent.ItemStateChangedEvent] - Garage_Alarm_Virtual changed from Manual unlock to RF unlock
2022-02-09 12:15:46.687 [vent.ItemStateChangedEvent] - Garage_Alarm_Raw changed from {"type":"25","value":"1"} to {"type":"24","value":"1"}
2022-02-09 12:15:46.721 [vent.ItemStateChangedEvent] - Garage_Alarm_Virtual changed from RF unlock to RF lock
2022-02-09 12:15:46.724 [vent.ItemStateChangedEvent] - Garage_Alarm_Virtual_Short changed from Un-Secured to Secured
2022-02-09 12:15:47.464 [vent.ItemStateChangedEvent] - Garage_Lock_Door changed from OFF to ON
2022-02-09 12:15:51.916 [ome.event.ItemCommandEvent] - Item 'Front_Lock_Door' received command ON
2022-02-09 12:15:51.920 [nt.ItemStatePredictedEvent] - Front_Lock_Door predicted to become ON
2022-02-09 12:15:51.939 [vent.ItemStateChangedEvent] - Front_Lock_Door changed from OFF to ON
2022-02-09 12:15:53.795 [ome.event.ItemCommandEvent] - Item 'Front_Lock_Door' received command OFF
2022-02-09 12:15:53.800 [nt.ItemStatePredictedEvent] - Front_Lock_Door predicted to become OFF
2022-02-09 12:15:53.820 [vent.ItemStateChangedEvent] - Front_Lock_Door changed from ON to OFF
2022-02-09 12:15:57.206 [ome.event.ItemCommandEvent] - Item 'Porch_Lock_Door' received command OFF
2022-02-09 12:15:57.211 [nt.ItemStatePredictedEvent] - Porch_Lock_Door predicted to become OFF
2022-02-09 12:15:57.223 [vent.ItemStateChangedEvent] - Porch_Lock_Door changed from ON to OFF
2022-02-09 12:16:00.244 [vent.ItemStateChangedEvent] - Porch_Lock_Door changed from OFF to ON
2022-02-09 12:16:01.315 [vent.ItemStateChangedEvent] - Front_Alarm_Raw changed from {"type":"18","value":"0"} to {"type":"25","value":"1"}
2022-02-09 12:16:01.347 [vent.ItemStateChangedEvent] - Front_Alarm_Virtual changed from Lock Un-Secured using Keyed cylinder or inside thumb-turn to Lock Un-Secured by Controller – Successful (Fully retracted)
2022-02-09 12:16:01.468 [vent.ItemStateChangedEvent] - Porch_Alarm_Raw changed from {"type":"0","value":"0"} to {"type":"25","value":"1"}
2022-02-09 12:16:03.924 [vent.ItemStateChangedEvent] - Porch_Alarm_Virtual changed from RF lock to RF unlock
2022-02-09 12:16:03.935 [vent.ItemStateChangedEvent] - Porch_Alarm_Virtual_Short changed from Secured to Un-Secured
2022-02-09 12:16:08.792 [ome.event.ItemCommandEvent] - Item 'HVAC_Mode' received command 1
2022-02-09 12:16:08.797 [nt.ItemStatePredictedEvent] - HVAC_Mode predicted to become 1
2022-02-09 12:16:08.812 [vent.ItemStateChangedEvent] - HVAC_Mode changed from 0 to 1
2022-02-09 12:16:10.689 [vent.ItemStateChangedEvent] - HVAC_Operating_State changed from 0 to 1
2022-02-09 12:16:10.893 [vent.ItemStateChangedEvent] - Basement_Tstat_CoolSetPoint changed from NULL to 7E+1 °F
2022-02-09 12:16:11.185 [vent.ItemStateChangedEvent] - ThermostatBattery changed from NULL to 100
2022-02-09 12:16:31.394 [ome.event.ItemCommandEvent] - Item 'HVAC_Fan_State' received command 1
2022-02-09 12:16:31.396 [nt.ItemStatePredictedEvent] - HVAC_Fan_State predicted to become 1
2022-02-09 12:16:31.408 [vent.ItemStateChangedEvent] - HVAC_Fan_State changed from 0 to 1
2022-02-09 12:16:33.699 [vent.ItemStateChangedEvent] - HVAC_Fan_State changed from 1 to 0
2022-02-09 12:16:35.769 [ome.event.ItemCommandEvent] - Item 'HVAC_Fan_State' received command 1
2022-02-09 12:16:35.772 [nt.ItemStatePredictedEvent] - HVAC_Fan_State predicted to become 1
2022-02-09 12:16:35.788 [vent.ItemStateChangedEvent] - HVAC_Fan_State changed from 0 to 1
2022-02-09 12:16:38.134 [vent.ItemStateChangedEvent] - HVAC_Fan_State changed from 1 to 0
2022-02-09 12:16:56.172 [ome.event.ItemCommandEvent] - Item 'Garage_Lock_Door' received command OFF
2022-02-09 12:16:56.176 [nt.ItemStatePredictedEvent] - Garage_Lock_Door predicted to become OFF
2022-02-09 12:16:56.191 [vent.ItemStateChangedEvent] - Garage_Lock_Door changed from ON to OFF
2022-02-09 12:16:57.879 [vent.ItemStateChangedEvent] - Garage_Lock_Door changed from OFF to ON
2022-02-09 12:16:58.028 [vent.ItemStateChangedEvent] - Garage_Alarm_Raw changed from {"type":"24","value":"1"} to {"type":"0","value":"0"}
2022-02-09 12:16:59.059 [vent.ItemStateChangedEvent] - Garage_Alarm_Raw changed from {"type":"0","value":"0"} to {"type":"25","value":"1"}
2022-02-09 12:16:59.090 [vent.ItemStateChangedEvent] - Garage_Alarm_Virtual changed from RF lock to RF unlock
2022-02-09 12:16:59.095 [vent.ItemStateChangedEvent] - Garage_Alarm_Virtual_Short changed from Secured to Un-Secured
2022-02-09 12:17:02.944 [ome.event.ItemCommandEvent] - Item 'Porch_Lock_Door' received command OFF
2022-02-09 12:17:02.948 [nt.ItemStatePredictedEvent] - Porch_Lock_Door predicted to become OFF
2022-02-09 12:17:02.962 [vent.ItemStateChangedEvent] - Porch_Lock_Door changed from ON to OFF
2022-02-09 12:17:04.815 [vent.ItemStateChangedEvent] - Porch_Alarm_Raw changed from {"type":"25","value":"1"} to {"type":"0","value":"0"}
2022-02-09 12:17:05.358 [vent.ItemStateChangedEvent] - Porch_Alarm_Raw changed from {"type":"0","value":"0"} to {"type":"25","value":"1"}
2022-02-09 12:17:10.850 [ome.event.ItemCommandEvent] - Item 'Porch_Lock_Door' received command ON
2022-02-09 12:17:10.862 [nt.ItemStatePredictedEvent] - Porch_Lock_Door predicted to become ON
2022-02-09 12:17:10.887 [vent.ItemStateChangedEvent] - Porch_Lock_Door changed from OFF to ON
2022-02-09 12:17:12.571 [vent.ItemStateChangedEvent] - Porch_Lock_Door changed from ON to OFF
2022-02-09 12:17:12.728 [vent.ItemStateChangedEvent] - Porch_Alarm_Raw changed from {"type":"25","value":"1"} to {"type":"0","value":"0"}
2022-02-09 12:17:13.534 [vent.ItemStateChangedEvent] - Porch_Alarm_Raw changed from {"type":"0","value":"0"} to {"type":"24","value":"1"}
2022-02-09 12:17:13.563 [vent.ItemStateChangedEvent] - Porch_Alarm_Virtual changed from RF unlock to RF lock
2022-02-09 12:17:13.574 [vent.ItemStateChangedEvent] - Porch_Alarm_Virtual_Short changed from Un-Secured to Secured
2022-02-09 12:17:14.678 [ome.event.ItemCommandEvent] - Item 'Porch_Lock_Door' received command OFF
2022-02-09 12:17:14.682 [nt.ItemStatePredictedEvent] - Porch_Lock_Door predicted to become OFF
2022-02-09 12:17:16.190 [vent.ItemStateChangedEvent] - Porch_Alarm_Raw changed from {"type":"24","value":"1"} to {"type":"25","value":"1"}
2022-02-09 12:17:16.206 [vent.ItemStateChangedEvent] - Porch_Alarm_Virtual changed from RF lock to RF unlock
2022-02-09 12:17:16.214 [vent.ItemStateChangedEvent] - Porch_Alarm_Virtual_Short changed from Secured to Un-Secured
2022-02-09 12:17:23.788 [ome.event.ItemCommandEvent] - Item 'Front_Lock_Door' received command ON
2022-02-09 12:17:23.791 [nt.ItemStatePredictedEvent] - Front_Lock_Door predicted to become ON
2022-02-09 12:17:23.803 [vent.ItemStateChangedEvent] - Front_Lock_Door changed from OFF to ON
2022-02-09 12:17:27.753 [vent.ItemStateChangedEvent] - Front_Alarm_Raw changed from {"type":"25","value":"1"} to {"type":"24","value":"1"}
2022-02-09 12:17:27.780 [vent.ItemStateChangedEvent] - Front_Alarm_Virtual changed from Lock Un-Secured by Controller – Successful (Fully retracted) to Lock Secured by Controller – Successful (Fully extended)
2022-02-09 12:17:27.801 [vent.ItemStateChangedEvent] - Front_Alarm_Virtual_Short changed from Un-Secured to Secured
2022-02-09 12:17:30.237 [ome.event.ItemCommandEvent] - Item 'Front_Lock_Door' received command OFF
2022-02-09 12:17:30.241 [nt.ItemStatePredictedEvent] - Front_Lock_Door predicted to become OFF
2022-02-09 12:17:30.260 [vent.ItemStateChangedEvent] - Front_Lock_Door changed from ON to OFF
2022-02-09 12:17:32.939 [ome.event.ItemCommandEvent] - Item 'Garage_Lock_Door' received command OFF
2022-02-09 12:17:32.943 [nt.ItemStatePredictedEvent] - Garage_Lock_Door predicted to become OFF
2022-02-09 12:17:32.963 [vent.ItemStateChangedEvent] - Garage_Lock_Door changed from ON to OFF
2022-02-09 12:17:34.797 [vent.ItemStateChangedEvent] - Garage_Alarm_Raw changed from {"type":"25","value":"1"} to {"type":"0","value":"0"}
2022-02-09 12:17:35.314 [vent.ItemStateChangedEvent] - Front_Alarm_Raw changed from {"type":"24","value":"1"} to {"type":"25","value":"1"}
2022-02-09 12:17:35.337 [vent.ItemStateChangedEvent] - Front_Alarm_Virtual changed from Lock Secured by Controller – Successful (Fully extended) to Lock Un-Secured by Controller – Successful (Fully retracted)
2022-02-09 12:17:35.345 [vent.ItemStateChangedEvent] - Front_Alarm_Virtual_Short changed from Secured to Un-Secured
2022-02-09 12:17:35.435 [vent.ItemStateChangedEvent] - Garage_Alarm_Raw changed from {"type":"0","value":"0"} to {"type":"25","value":"1"}
2022-02-09 12:17:42.965 [ome.event.ItemCommandEvent] - Item 'HVAC_Fan_State' received command 1
2022-02-09 12:17:42.969 [nt.ItemStatePredictedEvent] - HVAC_Fan_State predicted to become 1
2022-02-09 12:17:42.997 [vent.ItemStateChangedEvent] - HVAC_Fan_State changed from 0 to 1
2022-02-09 12:17:45.382 [vent.ItemStateChangedEvent] - HVAC_Fan_State changed from 1 to 0
2022-02-09 12:22:39.595 [vent.ItemStateChangedEvent] - GarageLightState changed from Off to On
2022-02-09 12:22:41.022 [vent.ItemStateChangedEvent] - GarageDoor changed from StillClosed to Opening
2022-02-09 12:22:46.611 [vent.ItemStateChangedEvent] - GarageDoor changed from Opening to Closing
2022-02-09 12:27:04.077 [vent.ItemStateChangedEvent] - GarageOverheadState changed from closed to open
2022-02-09 12:27:58.192 [vent.ItemStateChangedEvent] - Temperature_HVAC changed from 7E+1 °F to 71 °F
2022-02-09 12:28:54.559 [vent.ItemStateChangedEvent] - Front_Alarm_Raw changed from {"type":"25","value":"1"} to {"type":"18","value":"0"}
2022-02-09 12:29:56.006 [vent.ItemStateChangedEvent] - GarageDoor changed from Closing to Opening
2022-02-09 12:32:25.531 [vent.ItemStateChangedEvent] - GarageDoor changed from Opening to Closing
2022-02-09 12:34:02.421 [vent.ItemStateChangedEvent] - GarageDoor changed from Closing to Opening
2022-02-09 12:34:06.710 [vent.ItemStateChangedEvent] - GarageDoor changed from Opening to Closing
2022-02-09 12:35:11.192 [vent.ItemStateChangedEvent] - Temperature_HVAC changed from 71 °F to 72 °F
2022-02-09 12:37:27.081 [vent.ItemStateChangedEvent] - GarageDoor changed from Closing to Opening
2022-02-09 12:37:33.291 [vent.ItemStateChangedEvent] - GarageDoor changed from Opening to Closing
2022-02-09 12:48:11.255 [vent.ItemStateChangedEvent] - Temperature_HVAC changed from 72 °F to 73 °F
2022-02-09 12:52:06.074 [vent.ItemStateChangedEvent] - WatchDogBurp changed from BurpDown to BurpUp
2022-02-09 12:52:06.119 [vent.ItemStateChangedEvent] - When_Bumped changed from 2022-02-09T11:49:29.565-0600 to 2022-02-09T12:52:06.083-0600
2022-02-09 13:01:11.244 [vent.ItemStateChangedEvent] - Temperature_HVAC changed from 73 °F to 74 °F
2022-02-09 13:01:41.454 [ome.event.ItemCommandEvent] - Item 'Porch_Lock_Door' received command ON
2022-02-09 13:01:41.457 [nt.ItemStatePredictedEvent] - Porch_Lock_Door predicted to become ON
2022-02-09 13:01:41.478 [vent.ItemStateChangedEvent] - Porch_Lock_Door changed from OFF to ON
2022-02-09 13:01:43.182 [vent.ItemStateChangedEvent] - Porch_Lock_Door changed from ON to OFF
2022-02-09 13:01:43.342 [vent.ItemStateChangedEvent] - Porch_Alarm_Raw changed from {"type":"25","value":"1"} to {"type":"0","value":"0"}
2022-02-09 13:01:44.192 [vent.ItemStateChangedEvent] - Porch_Alarm_Raw changed from {"type":"0","value":"0"} to {"type":"24","value":"1"}
2022-02-09 13:01:44.239 [vent.ItemStateChangedEvent] - Porch_Alarm_Virtual changed from RF unlock to RF lock
2022-02-09 13:01:44.250 [vent.ItemStateChangedEvent] - Porch_Alarm_Virtual_Short changed from Un-Secured to Secured
2022-02-09 13:01:49.275 [ome.event.ItemCommandEvent] - Item 'Garage_Lock_Door' received command ON
2022-02-09 13:01:49.280 [nt.ItemStatePredictedEvent] - Garage_Lock_Door predicted to become ON
2022-02-09 13:01:49.296 [vent.ItemStateChangedEvent] - Garage_Lock_Door changed from OFF to ON
2022-02-09 13:01:50.982 [vent.ItemStateChangedEvent] - Garage_Lock_Door changed from ON to OFF
2022-02-09 13:01:51.136 [vent.ItemStateChangedEvent] - Garage_Alarm_Raw changed from {"type":"25","value":"1"} to {"type":"0","value":"0"}
2022-02-09 13:01:51.993 [vent.ItemStateChangedEvent] - Garage_Alarm_Raw changed from {"type":"0","value":"0"} to {"type":"24","value":"1"}
2022-02-09 13:01:52.028 [vent.ItemStateChangedEvent] - Garage_Alarm_Virtual changed from RF unlock to RF lock
2022-02-09 13:01:52.034 [vent.ItemStateChangedEvent] - Garage_Alarm_Virtual_Short changed from Un-Secured to Secured
2022-02-09 13:09:07.752 [vent.ItemStateChangedEvent] - BackRightWindow changed from StillClosed to N0_RPT
2022-02-09 13:10:43.751 [vent.ItemStateChangedEvent] - Garage_Alarm_Raw changed from {"type":"24","value":"1"} to {"type":"22","value":"1"}
2022-02-09 13:10:43.791 [vent.ItemStateChangedEvent] - Garage_Alarm_Virtual changed from RF lock to Manual unlock

*XXXX I had to remove some events here to get below the 48000 character max XXXXX*
2022-02-09 20:09:43.512 [vent.ItemStateChangedEvent] - WatchDogBurp changed from BurpUp to BurpDown
2022-02-09 20:09:43.548 [vent.ItemStateChangedEvent] - When_Bumped changed from 2022-02-09T19:07:16.960-0600 to 2022-02-09T20:09:43.530-0600
2022-02-09 20:09:46.917 [vent.ItemStateChangedEvent] - Temperature_HVAC changed from 73 °F to 74 °F
2022-02-09 20:18:29.464 [vent.ItemStateChangedEvent] - BackLeftWindow changed from StillClosed to N0_RPT
2022-02-09 20:40:52.435 [vent.ItemStateChangedEvent] - Temperature_HVAC changed from 74 °F to 73 °F
2022-02-09 20:45:45.573 [vent.ItemStateChangedEvent] - FrontDoor changed from Closing to StillClosed
2022-02-09 20:18:16.125 [hingStatusInfoChangedEvent] - 'ntp:ntp:local' changed from UNINITIALIZED to INITIALIZING
2022-02-09 20:18:16.290 [hingStatusInfoChangedEvent] - 'ntp:ntp:local' changed from INITIALIZING to ONLINE
2022-02-09 20:18:17.491 [vent.ItemStateChangedEvent] - GPIO_BUTTON changed from NULL to OPEN
2022-02-09 20:18:18.005 [vent.ItemStateChangedEvent] - LED changed from NULL to OFF
2022-02-09 20:55:32.460 [hingStatusInfoChangedEvent] - 'zwave:serial_zstick:fe40ab17' changed from UNINITIALIZED to INITIALIZING
2022-02-09 20:55:32.482 [hingStatusInfoChangedEvent] - 'zwave:serial_zstick:fe40ab17' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2022-02-09 20:55:32.542 [hingStatusInfoChangedEvent] - 'zwave:device:fe40ab17:node8' changed from UNINITIALIZED to UNINITIALIZED (DISABLED)
2022-02-09 20:55:32.609 [hingStatusInfoChangedEvent] - 'zwave:device:fe40ab17:node9' changed from UNINITIALIZED to UNINITIALIZED (DISABLED)
2022-02-09 20:55:32.612 [hingStatusInfoChangedEvent] - 'zwave:device:fe40ab17:node10' changed from UNINITIALIZED to UNINITIALIZED (DISABLED)
2022-02-09 20:55:32.741 [hingStatusInfoChangedEvent] - 'zwave:device:fe40ab17:node20' changed from UNINITIALIZED to INITIALIZING
2022-02-09 20:55:32.744 [hingStatusInfoChangedEvent] - 'zwave:device:fe40ab17:node32' changed from UNINITIALIZED to INITIALIZING
2022-02-09 20:55:32.783 [hingStatusInfoChangedEvent] - 'zwave:device:fe40ab17:node20' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2022-02-09 20:55:32.810 [hingStatusInfoChangedEvent] - 'zwave:device:fe40ab17:node32' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2022-02-09 20:55:32.833 [hingStatusInfoChangedEvent] - 'zwave:device:fe40ab17:node26' changed from UNINITIALIZED to INITIALIZING
2022-02-09 20:55:32.840 [hingStatusInfoChangedEvent] - 'zwave:device:fe40ab17:node16' changed from UNINITIALIZED to UNINITIALIZED (DISABLED)
2022-02-09 20:55:32.845 [hingStatusInfoChangedEvent] - 'zwave:device:fe40ab17:node17' changed from UNINITIALIZED to UNINITIALIZED (DISABLED)
2022-02-09 20:55:32.848 [hingStatusInfoChangedEvent] - 'zwave:device:fe40ab17:node5' changed from UNINITIALIZED to INITIALIZING
2022-02-09 20:55:32.853 [hingStatusInfoChangedEvent] - 'zwave:device:fe40ab17:node28' changed from UNINITIALIZED to INITIALIZING
2022-02-09 20:55:32.861 [hingStatusInfoChangedEvent] - 'zwave:device:fe40ab17:node26' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2022-02-09 20:55:32.867 [hingStatusInfoChangedEvent] - 'zwave:device:fe40ab17:node19' changed from UNINITIALIZED to INITIALIZING
2022-02-09 20:55:32.875 [hingStatusInfoChangedEvent] - 'zwave:device:fe40ab17:node28' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2022-02-09 20:55:32.880 [hingStatusInfoChangedEvent] - 'zwave:device:fe40ab17:node5' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2022-02-09 20:55:32.893 [hingStatusInfoChangedEvent] - 'zwave:device:fe40ab17:node19' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2022-02-09 20:55:58.121 [hingStatusInfoChangedEvent] - 'zwave:serial_zstick:fe40ab17' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE
2022-02-09 20:55:58.132 [hingStatusInfoChangedEvent] - 'zwave:device:fe40ab17:node26' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE
2022-02-09 20:55:58.135 [hingStatusInfoChangedEvent] - 'zwave:device:fe40ab17:node32' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE
2022-02-09 20:55:58.144 [hingStatusInfoChangedEvent] - 'zwave:device:fe40ab17:node5' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE
2022-02-09 20:55:58.148 [hingStatusInfoChangedEvent] - 'zwave:device:fe40ab17:node28' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE
2022-02-09 20:55:58.150 [hingStatusInfoChangedEvent] - 'zwave:device:fe40ab17:node20' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE
2022-02-09 20:55:58.187 [hingStatusInfoChangedEvent] - 'zwave:device:fe40ab17:node5' changed from ONLINE to ONLINE: Node initialising: REQUEST_NIF
2022-02-09 20:55:58.238 [me.event.ThingUpdatedEvent] - Thing 'zwave:serial_zstick:fe40ab17' has been updated.
2022-02-09 20:55:58.247 [hingStatusInfoChangedEvent] - 'zwave:device:fe40ab17:node28' changed from ONLINE to ONLINE: Node initialising: REQUEST_NIF
2022-02-09 20:55:58.259 [hingStatusInfoChangedEvent] - 'zwave:device:fe40ab17:node26' changed from ONLINE to ONLINE: Node initialising: REQUEST_NIF
2022-02-09 20:55:58.357 [hingStatusInfoChangedEvent] - 'zwave:device:fe40ab17:node19' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE
2022-02-09 20:56:02.385 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:fe40ab17:node32' has been updated.
2022-02-09 20:56:02.407 [vent.ConfigStatusInfoEvent] - ConfigStatusInfo [configStatusMessages=[]]
2022-02-09 20:56:02.637 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:fe40ab17:node28' has been updated.
2022-02-09 20:56:02.640 [vent.ConfigStatusInfoEvent] - ConfigStatusInfo [configStatusMessages=[]]
2022-02-09 20:56:02.825 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:fe40ab17:node26' has been updated.
2022-02-09 20:56:02.829 [vent.ConfigStatusInfoEvent] - ConfigStatusInfo [configStatusMessages=[]]
2022-02-09 20:56:03.040 [vent.ItemStateChangedEvent] - Front_Lock_Door changed from NULL to ON
2022-02-09 20:56:03.224 [vent.ItemStateChangedEvent] - Garage_Lock_Door changed from NULL to OFF
2022-02-09 20:56:03.411 [vent.ItemStateChangedEvent] - Porch_Lock_Door changed from NULL to ON
2022-02-09 20:56:03.573 [vent.ItemStateChangedEvent] - Front_Alarm_Raw changed from NULL to {"type":"19","value":"0"}
2022-02-09 20:56:03.741 [vent.ItemStateChangedEvent] - Garage_Alarm_Raw changed from NULL to {"type":"0","value":"0"}
2022-02-09 20:56:03.890 [vent.ItemStateChangedEvent] - Porch_Alarm_Raw changed from NULL to {"type":"0","value":"0"}
2022-02-09 20:56:04.118 [vent.ItemStateChangedEvent] - Front_Alarm_Raw changed from {"type":"19","value":"0"} to {"type":"0","value":"0"}
2022-02-09 20:56:04.627 [vent.ItemStateChangedEvent] - Front_Alarm_Raw changed from {"type":"0","value":"0"} to {"type":"18","value":"0"}
2022-02-09 20:56:05.101 [vent.ItemStateChangedEvent] - Front_Alarm_Raw changed from {"type":"18","value":"0"} to {"type":"22","value":"0"}
2022-02-09 20:56:05.702 [vent.ItemStateChangedEvent] - Front_Alarm_Raw changed from {"type":"22","value":"0"} to {"type":"21","value":"0"}
2022-02-09 20:56:06.220 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:fe40ab17:node32' has been updated.
2022-02-09 20:56:06.225 [vent.ConfigStatusInfoEvent] - ConfigStatusInfo [configStatusMessages=[]]
2022-02-09 20:56:06.480 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:fe40ab17:node28' has been updated.
2022-02-09 20:56:06.485 [vent.ConfigStatusInfoEvent] - ConfigStatusInfo [configStatusMessages=[]]
2022-02-09 20:56:06.696 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:fe40ab17:node26' has been updated.
2022-02-09 20:56:06.701 [vent.ConfigStatusInfoEvent] - ConfigStatusInfo [configStatusMessages=[]]
2022-02-09 20:56:06.953 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:fe40ab17:node32' has been updated.
2022-02-09 20:56:06.957 [vent.ConfigStatusInfoEvent] - ConfigStatusInfo [configStatusMessages=[]]
2022-02-09 20:56:07.172 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:fe40ab17:node28' has been updated.
2022-02-09 20:56:07.176 [vent.ConfigStatusInfoEvent] - ConfigStatusInfo [configStatusMessages=[]]
2022-02*-09 20:56:07.410 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:fe40ab17:node26' has been updated.*
*2022-02-09 20:56:07.413 [vent.ConfigStatusInfoEvent] - ConfigStatusInfo [configStatusMessages=[]]*

*XXXXX The pattern above is repeated for about 449 lines.  I deleted them XXXX*



2022-02-09 20:56:58.255 [hingStatusInfoChangedEvent] - 'zwave:device:fe40ab17:node28' changed from ONLINE: Node initialising: REQUEST_NIF to ONLINE
2022-02-09 20:56:58.387 [hingStatusInfoChangedEvent] - 'zwave:device:fe40ab17:node26' changed from ONLINE: Node initialising: REQUEST_NIF to ONLINE
2022-02-09 20:56:58.650 [vent.ItemStateChangedEvent] - Temperature_HVAC changed from NULL to 73 °F
2022-02-09 20:56:58.770 [vent.ItemStateChangedEvent] - HVAC_Operating_State changed from NULL to 0
2022-02-09 20:56:58.886 [vent.ItemStateChangedEvent] - HVAC_HeatSetPoint changed from NULL to 75 °F
2022-02-09 20:56:59.023 [vent.ItemStateChangedEvent] - Basement_Tstat_CoolSetPoint changed from NULL to 7E+1 °F
2022-02-09 20:56:59.027 [vent.ItemStateChangedEvent] - HVAC_CoolSetPoint changed from NULL to 7E+1 °F
2022-02-09 20:56:59.145 [vent.ItemStateChangedEvent] - HVAC_Fan_Mode changed from NULL to 0
2022-02-09 20:56:59.257 [vent.ItemStateChangedEvent] - HVAC_Mode changed from NULL to 0
2022-02-09 20:56:59.464 [vent.ItemStateChangedEvent] - HVAC_Fan_State changed from NULL to 0
2022-02-09 20:56:59.839 [vent.ItemStateChangedEvent] - HVAC_Battery changed from NULL to 100
2022-02-09 20:56:59.846 [vent.ItemStateChangedEvent] - ThermostatBattery changed from NULL to 100
2022-02-09 20:57:00.049 [vent.ItemStateChangedEvent] - Humidity_HVAC changed from NULL to 34
2022-02-09 20:57:00.075 [hingStatusInfoChangedEvent] - 'zwave:device:fe40ab17:node5' changed from ONLINE: Node initialising: REQUEST_NIF to ONLINE

rossko57 · February 15, 2022, 1:37am

PeteC:

2022-02-09 02:24:40.957 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:fe40ab17:node32' has been updated.
2022-02-09 02:24:41.647 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:fe40ab17:node26' has been updated.
2022-02-09 02:25:08.452 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:fe40ab17:node28' has been updated.
2022-02-09 02:25:08.797 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:fe40ab17:node5' has been updated.

Those were what I was looking for.
Thing updates are abnormal in ordinary service; they are about configuration, not online/offline status etc.
My understanding is incomplete, but from observation of people’s previous troubles, the Thing update will also reinitialize linked Items.
Hurrah, the culprit for the NULL states!! My curiosity is satisfied now

So why a Thing update? Again, my understanding is incomplete, but from observation of people’s previous troubles it is directly linked to the zwave “nightly heal” feature.
Roughly, zwave goes around and re-learns its mesh network every night at around 02:30. It does that by calling devices to reinitialize, and when they do we may get Thing updates.

Note that battery devices may be asleep at this time, but the re-init is queued for them and may kick in many hours later when they wake up for a periodic check-in.

It’s a pointless exercise really, unless you have added, removed, or relocated zwave devices. Many people disable the nightly heal on their zwave network - but remember to run it manually if/when you do make changes.

I’d recommend a different approach in the first place though.
I have a theory that the Thing update is triggered when the zwave node re-inits AND the existing Thing definition is not a perfect match for the Thing definition in the currently active zwave binding device database.
That can happen if the Thing was created under an old binding version, and the binding has since been updated.
That can be fixed by taking note of the affected Thing UID; deleting Thing from openHAB (not removing from zwave); re-discovering the node and creating a new Thing, making sure to give it the same UID (so that it hooks up to existing Items etc.)
Try that on one of the four nodes above, and see if it stops complaining in the night.

Note, that none of this causes spontaneous commands of itself. There is a lot of wood obscuring trees here.

Separate business -

PeteC:

2022-02-09 20:18:29.464 [vent.ItemStateChangedEvent] - BackLeftWindow changed from StillClosed to N0_RPT
2022-02-09 20:40:52.435 [vent.ItemStateChangedEvent] - Temperature_HVAC changed from 74 °F to 73 °F
2022-02-09 20:45:45.573 [vent.ItemStateChangedEvent] - FrontDoor changed from Closing to StillClosed
2022-02-09 20:18:16.125 [hingStatusInfoChangedEvent] - 'ntp:ntp:local' changed from UNINITIALIZED to INITIALIZING
2022-02-09 20:18:16.290 [hingStatusInfoChangedEvent] - 'ntp:ntp:local' changed from

What’s gone on here? Never mind the subjects, look at the log timestamps.
It does sometimes happen that events get written to the log out of order by a millisecond or two. I guess they get timestamped as the logger picks them up and put in a queue for writing that is not necessarily strictly sequential.
But twenty minute discrepancy? A serious clock glitch (logger uses Java system time) or a major filestore I/O problem.

Wait … system clock glitch?

PeteC:

2022-02-09 20:18:16.125 [hingStatusInfoChangedEvent] - 'ntp:ntp:local' changed from UNINITIALIZED to INITIALIZING
2022-02-09 20:18:16.290 [hingStatusInfoChangedEvent] - 'ntp:ntp:local' changed from INITIALIZING to ONLINE

Far too much of a coincidence. NTP is the service that fetches the date-time from a remote server, and adjust the system clock to the new time. Usually by a couple of seconds … but I reckon your clock has slipped significantly, and been adjusted by twenty minutes or more.

Separate business again -

PeteC:

2022-02-09 20:55:32.460 [hingStatusInfoChangedEvent] - 'zwave:serial_zstick:fe40ab17' changed from UNINITIALIZED to INITIALIZING
2022-02-09 20:55:32.482 [hingStatusInfoChangedEvent] - 'zwave:serial_zstick:fe40ab17' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
etc.

zwave controller crashed and starting out fresh.
Seriously nasty glitch.

But is it really separate … this looks like it comes within a few minutes of the NTP business, surely not a coincidence. If there’s some kind of watchdog in the binding it’s going to think the controller stick has been asleep for 20 minutes and give it a kick in the pants.
I think the clock is likely real root cause here.

Again, none of this cause spontaneous commands, but there’s way too much going on to discount those as some obscure knock-on effect.

Andrew_Rowe · February 15, 2022, 3:58am

Ross is expressing something very succinctly here… the nightly heal causes more problems then it fixes if you haven’t physically moved any of the nodes

PeteC · February 17, 2022, 1:26am

Well, I don’t know where to go with this now. It has gotten beyond my knowledge. I tend to think I should collect what data I can get from this episode and see if it happens again.

However, if perusing this helps the community I will be more then happy to do what ever you folks want.

Please advise.

Pete

rpwong · February 17, 2022, 2:36am

I can’t really add anything, unfortunately. We’ve no reason to think that you were hacked, but no explanation for your Z-Wave devices all firing off at once (with your doors both locking and unlocking) and then going back to normal.

If you run into any other weird issues then I’d suspect SD corruption.

Did we have a full moon on February 9?

rossko57 · February 17, 2022, 9:46am

There’s a lot going on. Some is likely unrelated to the locks issue. How about taking some easy wins to clear some away ?

First - make sure you have full backup. Before anything else.

Only after that -

rossko57:

2022-02-09 12:16:10.875 [WARN ] [al.profiles.MapTransformationProfile] - Please specify a function and a source format for this Profile in the 'function' and 'sourceFormat' parameters, e.g "translation.map" and "%s". Returning the original state now.

Here’s an annoyance we can get rid of.
Somewhere, one or more of your Items has a broken configuration - it has a transformation profile specified on an Item-to-channel link, but rubbish parameters for the profile. Likely a simple mistake from long ago.
It doesn’t tell you which Item(s). You must inspect your configuration, by eye.

How do you configure your Items, from xxx.items file or PaperUI?
For xxx.items files, look for Item lines with config like
... { channel="..blah.." [profile="bleh"] }

PeteC · February 19, 2022, 1:14am

Yes, I know (sheepishly). Everything was fine. Then I would make a tweak here and there. Then this transformation started showing up but I don’t remember all the tweaks I made and don’t know the troublemaker. I keep telling myself it will come to me but it never does.

But it has been so long since I messed with OH I have a lot to relearn.

Thanks to all.

Pete

system · April 1, 2022, 5:14pm

This topic was automatically closed 41 days after the last reply. New replies are no longer allowed.