ZWave binding updates

I can’t really see how this is linked to the device loosing its key. The error is in the binding - the device is still sending encrypted data, and if it had a corrupted key, it would just not decrypt, but wouldn’t throw this error.

My guess is that the binding initialisation is corrupt as the report here seems to be that the key in the binding is null, or not initialised in some way.

In my case, the other secure devices still worked. Which reminded me of this occurring with a NGD00Z garage door opener too, but that was after an accidental reinitialization. I had about 5 devices completely drop off the network after reincluding locks the last time they lost their keys. I haven’t had much time to play with Z-Wave lately… but I am due for a network rebuild. Sorry for the lack of empirical data. :wink:

Ok, but the keys are initialised separately for each device, so the fact that they work for some and not others doesn’t mean that it’s not the binding. The error is definitely coming from the binding, and I think the null in the error probably points to an initialisation error.

If it happens again, then I’d like to see the binding initialisation to see if there are any errors during the key initialisation.

1 Like

Yes, coming from 2.3 stable, and the device has just been deleted and then readded in the 2.4 upgrade process, so I don’t know of anything else that has changed than the binding. Do the log messages point anywhere, or should I gather more?

Hi Chris and 5iver,

Thank you for your answers.

Here is the log of the binding initialization (I’ve just quickly removed lots of lines containing nodes other than 2 and 16 that are the one that does not work).

I’m using encryption for many other items and they work correctly.The problem seems to be bound only to the binding and these two special devices (Aeotec Walmote Quad).

openhabStartup.xml (768.2 KB)

I also notice a node 255. What it is ?

It’s the controller.

@chris, I think I was able to catch a “spontaneous” change of the Popp valve setpoint to 1936°C…

See the debug trace…

2018-10-27 10:49:56.708 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 02 03 80 03 43 33 
2018-10-27 10:49:56.715 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 03 80 03 43 
2018-10-27 10:49:56.718 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 03 80 03 43 
2018-10-27 10:49:56.722 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 03 80 03 43 
2018-10-27 10:49:56.725 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2018-10-27 10:49:56.728 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Application Command Request (ALIVE:DONE)
2018-10-27 10:49:56.729 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0C 00 04 00 02 06 43 03 01 02 07 2C 9B 
2018-10-27 10:49:56.731 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: resetResendCount initComplete=true isDead=false
2018-10-27 10:49:56.734 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Incoming command class COMMAND_CLASS_BATTERY, endpoint 0
2018-10-27 10:49:56.736 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 06 43 03 01 02 07 2C 
2018-10-27 10:49:56.737 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: SECURITY not supported
2018-10-27 10:49:56.739 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 06 43 03 01 02 07 2C 
2018-10-27 10:49:56.741 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 2: Received COMMAND_CLASS_BATTERY V1 BATTERY_REPORT
2018-10-27 10:49:56.743 [DEBUG] [ommandclass.ZWaveBatteryCommandClass] - NODE 2: Battery report value = 67
2018-10-27 10:49:56.745 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2018-10-27 10:49:56.747 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_BATTERY, value = 67
2018-10-27 10:49:56.749 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Updating channel state zwave:device:512:node2:battery-level to 67 [DecimalType]
2018-10-27 10:49:56.754 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Commands processed 1.
2018-10-27 10:49:56.756 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@13f240d.
2018-10-27 10:49:56.758 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2018-10-27 10:49:56.760 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2018-10-27 10:49:56.763 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 06 43 03 01 02 07 2C 
2018-10-27 10:49:56.764 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2018-10-27 10:49:56.766 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Application Command Request (ALIVE:DONE)
2018-10-27 10:49:56.768 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: resetResendCount initComplete=true isDead=false
2018-10-27 10:49:56.770 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Incoming command class COMMAND_CLASS_THERMOSTAT_SETPOINT, endpoint 0
2018-10-27 10:49:56.772 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: SECURITY not supported
2018-10-27 10:49:56.774 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 2: Received COMMAND_CLASS_THERMOSTAT_SETPOINT V1 THERMOSTAT_SETPOINT_REPORT
2018-10-27 10:49:56.776 [DEBUG] [.ZWaveThermostatSetpointCommandClass] - NODE 2: Thermostat Setpoint report Scale = 0
2018-10-27 10:49:56.778 [DEBUG] [.ZWaveThermostatSetpointCommandClass] - NODE 2: Thermostat Setpoint Value = 1836
2018-10-27 10:49:56.780 [DEBUG] [.ZWaveThermostatSetpointCommandClass] - NODE 2: Thermostat Setpoint Report, Type Heating (1), value = 1836
2018-10-27 10:49:56.782 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveThermostatSetpointValueEvent
2018-10-27 10:49:56.784 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_THERMOSTAT_SETPOINT, value = 1836
2018-10-27 10:49:56.787 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Updating channel state zwave:device:512:node2:thermostat_setpoint_heating to 1836 °C [QuantityType]
2018-10-27 10:49:56.791 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Commands processed 1.
2018-10-27 10:49:56.793 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@fb9d07.
2018-10-27 10:49:56.798 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2018-10-27 10:49:56.800 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2018-10-27 10:49:56.801 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-10-27 10:49:56.803 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
==> /var/log/openhab2/events.log <==
2018-10-27 10:49:56.804 [vent.ItemStateChangedEvent] - Popp6_Setpoint changed from 19 to 1836
2018-10-27 10:49:56.809 [GroupItemStateChangedEvent] - gThermostatSetpoint changed from 17.4 to 320.3 through Popp6_Setpoint

The device sent incorrect data -:

01: Sensor type
02: Precision / Scale / Size
02 = Precision=0, Scale=0, Size=2
072C: Value = 1836

Because Precision = 0, there is no scaling performed - I guess that this should be 18.36 with a precision of 2, but the data received doesn’t define this. The binding can’t easily know this - I guess it could perform some sort of trending on the data and learn what is correct, but I think that’s a little out of scope :sunglasses:

Hello Chris, thanks a lot for the super fast answer.

I have checked in traces and there are other spontaneous reports from this device with the right value, precision etc… with the right processing by the binding as per traces below.

This would lead to the conclusion that the device is sending “randomly” a badly formatted message?

Or, the other difference could be that in the first case, the initial message contains both battery and setpoint values and the second (where there is no problem) contains only the setpoint value?

Thanks,

2018-10-27 14:17:09.059 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0C 00 04 00 02 06 43 03 01 42 07 6C 9B 
2018-10-27 14:17:09.066 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 06 43 03 01 42 07 6C 
2018-10-27 14:17:09.070 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 06 43 03 01 42 07 6C 
2018-10-27 14:17:09.074 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 06 43 03 01 42 07 6C 
2018-10-27 14:17:09.078 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2018-10-27 14:17:09.081 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Application Command Request (ALIVE:DONE)
2018-10-27 14:17:09.084 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: resetResendCount initComplete=true isDead=false
2018-10-27 14:17:09.088 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Incoming command class COMMAND_CLASS_THERMOSTAT_SETPOINT, endpoint 0
2018-10-27 14:17:09.091 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: SECURITY not supported
2018-10-27 14:17:09.094 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 2: Received COMMAND_CLASS_THERMOSTAT_SETPOINT V1 THERMOSTAT_SETPOINT_REPORT
2018-10-27 14:17:09.097 [DEBUG] [.ZWaveThermostatSetpointCommandClass] - NODE 2: Thermostat Setpoint report Scale = 0
2018-10-27 14:17:09.100 [DEBUG] [.ZWaveThermostatSetpointCommandClass] - NODE 2: Thermostat Setpoint Value = 19
2018-10-27 14:17:09.103 [DEBUG] [.ZWaveThermostatSetpointCommandClass] - NODE 2: Thermostat Setpoint Report, Type Heating (1), value = 19
2018-10-27 14:17:09.107 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveThermostatSetpointValueEvent
2018-10-27 14:17:09.110 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_THERMOSTAT_SETPOINT, value = 19
2018-10-27 14:17:09.114 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Updating channel state zwave:device:512:node2:thermostat_setpoint_heating to 19 °C [QuantityType]

Yes, this is likely - or the message is corrupted when sent which is also possible as ZWave does not use a very strong error detection system by default.

I’m not sure I follow your point? I think that in all cases I saw, the messages are separate - the setpoint is always sent by itself.

In those logs, I notice that during the Node 2 and 16 discovery progress :

2018-10-27 09:53:29.044 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 2: Security = false

Whereas I am sure that the device was included with security enabled.

Shortly after that it comes to the “REQUEST NIF” state and does not advance any more. Could it be related to that, making the binding not decoding the encrypted messages because it thinks security is not used ?

This message is not linked to the secure inclusion, so I wouldn’t worry about this.

OK, I’m definitely not understanding all the underlying stuff :grinning:

Do you have sufficient logs to investigate from your side with those logs ? I can enable TRACE level and post the whole 20MB logs if it helps ?

Ok, understood, I have to say that I don’t distinguish very well between the messages, and in the first trace I posted, the processing of battery level & setpoint are very near each other and almost interleaved.
Going back tothe first block of traces, this would be

2018-10-27 10:49:56.708 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 02 03 80 03 43 33

This one would be the battery info?

2018-10-27 10:49:56.729 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0C 00 04 00 02 06 43 03 01 02 07 2C 9B

And this one would be the setpoint info, which seems to have arrived before the entire processing of the battery info was completed…

Since I did not have this problem when using my super old Zibase and associated openHab binding with this device, I’m not sure I’ll be able to ask the vendor for support, so I guess I’m going to have to filter those “erratic” values (and very temporary as well, because after few seconds there is another message with the right value…
The concrete issue for me is that temperature graphs are “a bit” distorted by the 2000°C reported, even if for a short period of time, so basically I guess I’ll have to filter those values and ensure that they are not saved in database and don’t trigger the various alerts…

Thanks again for your help, Chris.

The first one is the battery level and the second one is the setpoint.

Maybe this device had filtering for such events?

I understand. I could add some filtering, but it’s very complex to get right, and IMHO is something that is not ZWave specific. If someone wants to add such filtering, it would probably be good to add it to the core instead so it is resolved on all bindings.

You’re welcome.

Sure, this shouldn’t be done in the binding, I agree.

1 Like

@sihui, thank you, very convenient;-) I have put this in place and will check how things go…

1 Like

Apologies if this was already covered (I did search, but it’s a long thread) but I have tried to follow the instructions, and kept my old controller.
zwave:serial_zstick:157b8d41438 (Type=Bridge, Status=INITIALIZING, Label=Z-Wave Serial Controller, Bridge=null)

(I have a Zwave plus aeonlabs USB stick in a raspberry pi running the latest snapshot).

However when I look in PaperUI I see " ZWave Plus USB Dongle" and in the log I see:

2018-10-31 13:51:09.281 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'zwave:serial_zstick:512' to inbox.

I tried deleting my old controller, and adding this, but I wasn’t sure how to change the thing id using PaperUI (so I wouldn’t have to update my items files). So in the end I added azwave serial controller again using Habmin, with id=157b8d41438, but then I get back in the original situation: I have a serial controller, but PaperUI (and since I see it in the log, presumably openhab itself) wants me to add another dongle.

What am I missing?

Edit: hmm. This controller doesn’t seem to find any things:
zwave:serial_zstick:157b8d41438 (Type=Bridge, Status=INITIALIZING, Label=Z-Wave Serial Controller, Bridge=null)

Maybe I just need to give in and edit my items files…

There was new core functionality added to auto-detect USB devices. That’s what you’re seeing in the Inbox – the system auto-detecting the zwave USB stick. You can ignore the one that was auto-detected.