OH2 Z-Wave refactoring and testing... and SECURITY

@digitaldan You got luck. I’ve also used the Aug 3rd version but ran into ‘queue full’ occurences two or three times since. @chris I’ve uploaded the log of the first occurence with my ticket on your site. If you want another one let me know.

Chris, I can confirm that state update delay with all DZMX1 devices is 8 (exactly) seconds instead of 2, as it use to be. Not a big deal, just to let you know. New version of these dimmers push updates immediately.

I think it’s an issue if you have OH2 set to “automatically accept” new items in the inbox. In my case anyway, it starts to attempt to open the same /dev/tty serial port and then both z-stick controllers show offline at that point.

I tried changing the port on the “dongle” to /dev/null or another port, but somehow it keeps coming back to /dev/ttyACM0 which conflicts.

Can you provide a log please. The binding is only setting a 2 second delay - maybe something else is blocking in the binding and I’d like to understand why it’s not 2 seconds.

Thanks
Chris

Yes, please @chris would you mind to prepare a jar of the code right before you added holdoff changes, but to include the current database ? Or current code with the holdoff stuff disabled if that’s easy to do.

I will see what I can do. I fear though if we go down this route, it will not be possible to find the problem now and I will have to remove this :frowning: .

Thanks. I’ll be volunteering to keep testing latest bindings to include holdoff, but I really need a stable jar to fall back to, else my wife won’t allow me to :slight_smile:
No idea how you laid out the code so no idea if that can be done easily, but maybe you could instead introduce a config option (?) or other parameter that can be changed at runtime to enable/disable holdoff ?
If another log of a run to end in ‘queue full’ would be of help, let me know. I can also include TRACE level if you like.

Thank you for your reply !! This stuff has got me all excited and am learning a lot!

Here is log, node 6 is one of the dimmers with 8 sec timeout - https://paste.ee/p/UphQZ

Thanks for this.

From a quick look, I think the issue is that the initial GET request, which results in the “try again later” response, doesn’t actually complete as a result of the “try again later” message. It times out 5 seconds later (5 seconds is the standard transaction timeout). This gives us the 6 second delay (At least in this log, it’s 6 seconds rather than 8).

I will take a look at how this can be fixed, but at least it is understood why it’s not the 2 seconds which was my main concern.

1 Like

Seems like these APPLICATION_BUSY responses are a fact of life with Leviton devices. FWIW, I see several of these a day from a variety of nodes with no obvious reason why they happen.

zwave.log.20180730170811:2018-07-30 16:51:38.247 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 73: Received COMMAND_CLASS_APPLICATION_STATUS V0 APPLICATION_BUSY
zwave.log.20180731021619:2018-07-30 19:51:03.757 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 21: Received COMMAND_CLASS_APPLICATION_STATUS V0 APPLICATION_BUSY
zwave.log.20180731133958:2018-07-31 09:54:32.742 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 78: Received COMMAND_CLASS_APPLICATION_STATUS V0 APPLICATION_BUSY
zwave.log.20180731215103:2018-07-31 19:30:12.035 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 50: Received COMMAND_CLASS_APPLICATION_STATUS V0 APPLICATION_BUSY
zwave.log.20180801215422:2018-08-01 13:30:11.138 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 50: Received COMMAND_CLASS_APPLICATION_STATUS V0 APPLICATION_BUSY
zwave.log.20180801215422:2018-08-01 13:30:11.200 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 50: Received COMMAND_CLASS_APPLICATION_STATUS V0 APPLICATION_BUSY
zwave.log.20180801215422:2018-08-01 17:59:55.535 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 48: Received COMMAND_CLASS_APPLICATION_STATUS V0 APPLICATION_BUSY
zwave.log.20180801215422:2018-08-01 19:07:11.521 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 54: Received COMMAND_CLASS_APPLICATION_STATUS V0 APPLICATION_BUSY
zwave.log.20180802140605:2018-08-02 06:15:58.673 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 56: Received COMMAND_CLASS_APPLICATION_STATUS V0 APPLICATION_BUSY
zwave.log.20180802230700:2018-08-02 15:15:59.967 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 57: Received COMMAND_CLASS_APPLICATION_STATUS V0 APPLICATION_BUSY
zwave.log.20180802230700:2018-08-02 15:16:04.317 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 57: Received COMMAND_CLASS_APPLICATION_STATUS V0 APPLICATION_BUSY
zwave.log.20180802230700:2018-08-02 16:30:11.059 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 50: Received COMMAND_CLASS_APPLICATION_STATUS V0 APPLICATION_BUSY
zwave.log.20180802230700:2018-08-02 17:50:51.325 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 51: Received COMMAND_CLASS_APPLICATION_STATUS V0 APPLICATION_BUSY
zwave.log.20180803154608:2018-08-03 09:09:14.631 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 56: Received COMMAND_CLASS_APPLICATION_STATUS V0 APPLICATION_BUSY
zwave.log.20180803154608:2018-08-03 10:59:16.131 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 45: Received COMMAND_CLASS_APPLICATION_STATUS V0 APPLICATION_BUSY
zwave.log.20180803154608:2018-08-03 12:17:57.290 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 73: Received COMMAND_CLASS_APPLICATION_STATUS V0 APPLICATION_BUSY
zwave.log.20180803154608:2018-08-03 13:07:15.333 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 54: Received COMMAND_CLASS_APPLICATION_STATUS V0 APPLICATION_BUSY
zwave.log.20180804003918:2018-08-03 16:07:18.692 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 54: Received COMMAND_CLASS_APPLICATION_STATUS V0 APPLICATION_BUSY
zwave.log.20180804003918:2018-08-03 19:07:21.489 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 54: Received COMMAND_CLASS_APPLICATION_STATUS V0 APPLICATION_BUSY
zwave.log.20180804003918:2018-08-03 19:59:18.503 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 45: Received COMMAND_CLASS_APPLICATION_STATUS V0 APPLICATION_BUSY
zwave.log.20180805174619:2018-08-05 09:31:55.070 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 73: Received COMMAND_CLASS_APPLICATION_STATUS V0 APPLICATION_BUSY
zwave.log.20180805174619:2018-08-05 09:31:55.118 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 73: Received COMMAND_CLASS_APPLICATION_STATUS V0 APPLICATION_BUSY
zwave.log.20180805174619:2018-08-05 12:31:53.147 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 78: Received COMMAND_CLASS_APPLICATION_STATUS V0 APPLICATION_BUSY
zwave.log.20180805174619:2018-08-05 12:31:55.805 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 78: Received COMMAND_CLASS_APPLICATION_STATUS V0 APPLICATION_BUSY
zwave.log.20180806014458:2018-08-05 19:03:38.512 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 51: Received COMMAND_CLASS_APPLICATION_STATUS V0 APPLICATION_BUSY
zwave.log.20180806014458:2018-08-05 20:10:45.290 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 51: Received COMMAND_CLASS_APPLICATION_STATUS V0 APPLICATION_BUSY
zwave.log.20180806081510:2018-08-06 04:59:20.671 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 45: Received COMMAND_CLASS_APPLICATION_STATUS V0 APPLICATION_BUSY
zwave.log.20180806081510:2018-08-06 04:59:22.899 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 45: Received COMMAND_CLASS_APPLICATION_STATUS V0 APPLICATION_BUSY
zwave.log.20180806081510:2018-08-06 07:59:25.683 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 45: Received COMMAND_CLASS_APPLICATION_STATUS V0 APPLICATION_BUSY
zwave.log.20180806231500:2018-08-06 21:09:16.844 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 56: Received COMMAND_CLASS_APPLICATION_STATUS V0 APPLICATION_BUSY
zwave.log.20180807151457:2018-08-07 06:30:02.533 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 78: Received COMMAND_CLASS_APPLICATION_STATUS V0 APPLICATION_BUSY
zwave.log.20180807151457:2018-08-07 06:30:46.224 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 46: Received COMMAND_CLASS_APPLICATION_STATUS V0 APPLICATION_BUSY
zwave.log.20180808002630:2018-08-07 22:59:28.248 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 45: Received COMMAND_CLASS_APPLICATION_STATUS V0 APPLICATION_BUSY
zwave.log.20180808074812:2018-08-08 03:17:27.770 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 56: Received COMMAND_CLASS_APPLICATION_STATUS V0 APPLICATION_BUSY
zwave.log.20180808171539:2018-08-08 09:59:22.353 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 46: Received COMMAND_CLASS_APPLICATION_STATUS V0 APPLICATION_BUSY
zwave.log.20180808171539:2018-08-08 12:29:37.269 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 73: Received COMMAND_CLASS_APPLICATION_STATUS V0 APPLICATION_BUSY
zwave.log.20180808171539:2018-08-08 15:29:39.817 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 73: Received COMMAND_CLASS_APPLICATION_STATUS V0 APPLICATION_BUSY
zwave.log.20180809095525:2018-08-09 06:34:40.264 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 51: Received COMMAND_CLASS_APPLICATION_STATUS V0 APPLICATION_BUSY
zwave.log.20180809095525:2018-08-09 06:34:41.026 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 51: Received COMMAND_CLASS_APPLICATION_STATUS V0 APPLICATION_BUSY
zwave.log.20180809095525:2018-08-09 09:34:45.205 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 51: Received COMMAND_CLASS_APPLICATION_STATUS V0 APPLICATION_BUSY

Is there a Lifeline issue currently?

I freshly included some new devices. Whenever I mess around manually in the “Association” in Habmin those devices dont get any lifeline updates anymore. Even if I restore the same state as the default.

only deleting the thing + xml and rediscover it solves my issues

I did not follow the discussion for a while… after updating to the latest build I see quite some queuing and therefore bad reaction times for devices. whats the background for holdoff function?

Also on current build I have a device that is sending temperature that is randomly interpreted in Celsius OR Fahrenheit. Is there something known yet?

When the item goes from 25 to 74 … my fire alarm rule triggers :wink:

Have you defined the item using the UoM syntax.

Number:Temperature

uhm thats new to me.
but from maaaaaany devices only one has that behaviour

thanks for the hint… will try

It was implemented to avoid retransmitting a message immediately after getting a busy response from the controller. Without the holdoff (250 ms, I think), it’s almost guaranteed to get another busy response.

Yeah, I saw that behavior from one of my devices (I forget which one). Using Number:Temperature resolved the issue for me.

Hi Chris

I am running:

openhab> bundle:list | grep Z
223 │ Active │ 80 │ 2.4.0.201807071112 │ ZWave Binding
openhab>

Is it worth upgrading if I use FIbaro devices? I get alot off odd behaviour now and then (lights going on off) need to reboot the whole system and reinitialise the Motion Sensor as an example. And updates taking AGES for lux/temp

Cheers