Re-occurring "valueChanged" log messages every minute even though lights are same state

Mozilla IoT
#1

I’ve installed an Ubuntu docker config with a Gen 5 Z-Stick & 3 GE Smart Dimming switches. The install works as expected. When viewing the logfile, there are periodic “valueChanged” log entries every minute even though the lights remain off. This is not critical by any means but I wanted to verify if this was a normal (mis-worded) polling event or an actual nit-of-a-problem.

2019-10-17 17:28:58.198 INFO   : zwave: node4 valueChanged: 4-38-1-0:Level property: on = false
2019-10-17 17:28:58.198 INFO   : zwave: node4 valueChanged: 4-38-1-0:Level property: level = 0.0% (zw: 0)
2019-10-17 17:29:08.246 INFO   : zwave: node2 valueChanged: 2-38-1-0:Level property: on = false
2019-10-17 17:29:08.247 INFO   : zwave: node2 valueChanged: 2-38-1-0:Level property: level = 0.0% (zw: 0)
2019-10-17 17:29:18.289 INFO   : zwave: node3 valueChanged: 3-38-1-0:Level property: on = false
2019-10-17 17:29:18.290 INFO   : zwave: node3 valueChanged: 3-38-1-0:Level property: level = 0.0% (zw: 0)
2019-10-17 17:29:28.331 INFO   : zwave: node4 valueChanged: 4-38-1-0:Level property: on = false
2019-10-17 17:29:28.331 INFO   : zwave: node4 valueChanged: 4-38-1-0:Level property: level = 0.0% (zw: 0)
2019-10-17 17:29:38.378 INFO   : zwave: node2 valueChanged: 2-38-1-0:Level property: on = false
2019-10-17 17:29:38.378 INFO   : zwave: node2 valueChanged: 2-38-1-0:Level property: level = 0.0% (zw: 0)
2019-10-17 17:29:48.423 INFO   : zwave: node3 valueChanged: 3-38-1-0:Level property: on = false
2019-10-17 17:29:48.424 INFO   : zwave: node3 valueChanged: 3-38-1-0:Level property: level = 0.0% (zw: 0)
2019-10-17 17:29:58.464 INFO   : zwave: node4 valueChanged: 4-38-1-0:Level property: on = false
2019-10-17 17:29:58.464 INFO   : zwave: node4 valueChanged: 4-38-1-0:Level property: level = 0.0% (zw: 0)
2019-10-17 17:30:08.512 INFO   : zwave: node2 valueChanged: 2-38-1-0:Level property: on = false
2019-10-17 17:30:08.513 INFO   : zwave: node2 valueChanged: 2-38-1-0:Level property: level = 0.0% (zw: 0)
2019-10-17 17:30:18.556 INFO   : zwave: node3 valueChanged: 3-38-1-0:Level property: on = false
2019-10-17 17:30:18.557 INFO   : zwave: node3 valueChanged: 3-38-1-0:Level property: level = 0.0% (zw: 0)
#2

By default, the zwave adapter sets up COMMAND_CLASS_SWITCH_BINARY and COMMAND_CLASS_SWITCH_MULTILEVEL to poll. This is for devices which don’t advertise changes.

Some devices (like the Aeotect ones) don’t need to be polled since they send changes right away. So there are “quirks” in the code where I can turn off polling for devices which I know don’t need it.

Currently, the gateway doesn’t support per-device configuration, which would allow polling to be configured or disabled on a per-device basis.

Do you know the exact model of device you’re using? If I have one I can test it and see if needs polling, and if it doesn’t we can update the adapter.

#3

The lights switches are: Jasco GE Z-Wave Plus Smart Dimmer SKU: 28167 purchased from Lowes. This Jasco switch does not contain all features in similar switches from Jasco (Power Sense for one) so they must be cost-reduced for big-box stores.

See:


https://products.z-wavealliance.org/products/2100/configs

I am new to Z-Wave and have 2 months testing and monitoring my configuration. I guess that polling devices, even when they send state transitions to the controller, may self-heal if/when spurious errors transmission errors. You probably know better if/when polling is a better choice. Adding supporting to poll devices would be a great addition and help self-heal state.

When I manually pressed the “on” button on the switch the log file showed this output for NODE2 (the one I pressed).

2019-10-18 21:19:34.468 INFO   : zwave: node3 valueChanged: 3-38-1-0:Level property: on = false
2019-10-18 21:19:34.468 INFO   : zwave: node3 valueChanged: 3-38-1-0:Level property: level = 0.0% (zw: 0)
2019-10-18 21:19:42.457 INFO   : zwave: node2 valueChanged: 2-38-1-0:Level property: on = true
2019-10-18 21:19:42.457 INFO   : zwave: node2 valueChanged: 2-38-1-0:Level property: level = 3.0% (zw: 3)
2019-10-18 21:19:44.509 INFO   : zwave: node4 valueChanged: 4-38-1-0:Level property: on = false
2019-10-18 21:19:44.510 INFO   : zwave: node4 valueChanged: 4-38-1-0:Level property: level = 0.0% (zw: 0)
2019-10-18 21:19:45.318 INFO   : zwave: node2 valueChanged: 2-38-1-0:Level property: on = true
2019-10-18 21:19:45.318 INFO   : zwave: node2 valueChanged: 2-38-1-0:Level property: level = 100.0% (zw: 99)
2019-10-18 21:19:54.557 INFO   : zwave: node2 valueChanged: 2-38-1-0:Level property: on = true
2019-10-18 21:19:54.557 INFO   : zwave: node2 valueChanged: 2-38-1-0:Level property: level = 100.0% (zw: 99)
2019-10-18 21:20:04.601 INFO   : zwave: node3 valueChanged: 3-38-1-0:Level property: on = false
2019-10-18 21:20:04.601 INFO   : zwave: node3 valueChanged: 3-38-1-0:Level property: level = 0.0% (zw: 0)
2019-10-18 21:20:14.641 INFO   : zwave: node4 valueChanged: 4-38-1-0:Level property: on = false
2019-10-18 21:20:14.642 INFO   : zwave: node4 valueChanged: 4-38-1-0:Level property: level = 0.0% (zw: 0)
2019-10-18 21:20:24.690 INFO   : zwave: node2 valueChanged: 2-38-1-0:Level property: on = true
2019-10-18 21:20:24.691 INFO   : zwave: node2 valueChanged: 2-38-1-0:Level property: level = 100.0% (zw: 99)

I pressed the button and looked at the logfile a few seconds later and power was TRUE, along with other nodes reporting so I could not tell if node2 sent an asynchronous transaction or polling occured. I guess that polling did not occur since the sequence of events for nodes: 4,2,3 were repeated. I would have expected to see a spurious node2 change event in there somewhere.

Let me know if you need other information.

I think that polling is a good thing to keep devices and the controller in sync. Would rather have accurate state using some type of polling scheme rather loosing state. Keeping accurate state is a priority…

Eric Edberg

#4

It’s probably worthwhile to add some logic so that if the values don’t change then it will suppress the logging.

#5

I had a GE Enbrighten Z-Wave Plus Dual Smart Plug (14282 ) and a Z-Wave Jasco Zigbee Plug-in Smart Dimmer (45852 ) that both behaved the same way. I returned them both because of the logging issue (I hadn’t registered on this forum so I didn’t report it then.)

Yes, if the repetitive logging could be suppressed it would be very good. I had a lot of problems getting any Z-Wave devices to connect at all, so I gave up on Z-Wave for now and disconnected my Aeotec Z-Stick. Now that my Zigbee errors have have stopped (and I’m not running Onvif), I’ll take another whack at seeing what is going on with Z-Wave. It helps to have better control of log filtering.

#6

I’ve read that when adding a Z-Wave device to the controller it’s best to locate the Z-Wave stick close to the device. Some have reported problems discovering remotely-located devices. I co-located my controller and device during discovery and then moved it to it’s final location.

I have no issue with logging every polling event. It does add many more entries to the log, but it correctly documents each event that is happening. Minimally: “valueChanged”, could be changed to: “devicePolled”, with an additional log record printed: “valueChanged”, when the value actually changes. Being able to know exactly what and when polling occurs is a good thing.

Note: logfiles are rotated so there is practically no worry about space usage. Logfiles, documenting 3 polled devices, are about 2MB each.

-rw-r--r-- 1 ele ele 1919914 Oct 21 18:59 run-app.log.2019-10-21

Q: Are there different logfile “levels”? When writing logging tools, often logging is enabled based on a provisioned numeric level. More info is then logged based on the currently-provisioned level. Assigning “eventPolled” log entries at a higher level is an option.

#7

There are additional debug logging levels which can be enabled.

Unfortunately, I don’t think that there is anyway to determine devicePolled versus valueChanged. We’re using the OpenZWave library, and it does the actual polling and we get notified via the valueChanged callback.

#8

There is an issue with excessive log writes for those of us using a Raspberry Pi with the “hard drive” being an SD card . Excessive writes cause SD cards to fail.

I’d prefer to have more granularity so I could better control what is being logged. This would help constrain log writes to my SD card.