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

Thanks.

You are not running the test version of the binding - you are running the old binding and this is why you see the old messages.

Feeling ashamed now :blush:

This is how this happened:
Today I replaced addons/jar with newest zwave binding version without restarting whole openhab (at that moment I was using development version with old binding installed but inactive), BUT openhab decided that addons/jar file update is a signal to switch to the bundled one, not to the updated file :confused:

Resolved now.

Thank you kindly for your help and patience.

No problem - hopefully it fixes all the problems you mentioned above with converters. This would have been caused by the change in the command class names as the new binding uses the official names from ZWave Standardā€¦

Yep, theyā€™re gone.

Iā€™m observing something new "Not the right scale " message, as below.

This node6 is: http://www.cd-jackson.com/index.php/zwave/zwave-device-database/zwave-device-list/devicesummary/397

2017-04-17 12:54:58.602 [DEBUG] [Handler$ZWaveReceiveThread] - Receive Message = 01 15 00 04 00 06 0F 32 02 21 44 00 00 00 08 01 2D 00 00 00 08 00 9E
2017-04-17 12:54:58.620 [DEBUG] [Handler$ZWaveReceiveThread] - Response SENT 6
2017-04-17 12:54:58.628 [DEBUG] [ZWaveTransactionManager   ] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=6, callback=0, payload=00 06 0F 32 02 21 44 00 00 00 08 01 2D 00 00 00 08 00
2017-04-17 12:54:58.633 [DEBUG] [ZWaveTransactionManager   ] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=6, callback=0, payload=00 06 0F 32 02 21 44 00 00 00 08 01 2D 00 00 00 08 00
2017-04-17 12:54:58.637 [DEBUG] [ZWaveTransactionManager   ] - Received msg Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=6, callback=0, payload=00 06 0F 32 02 21 44 00 00 00 08 01 2D 00 00 00 08 00
2017-04-17 12:54:58.639 [DEBUG] [ZWaveTransactionManager   ] - lastTransaction null
2017-04-17 12:54:58.641 [DEBUG] [ZWaveTransactionManager   ] - NODE 6: Application Command Request (ALIVE:DONE)
2017-04-17 12:54:58.644 [DEBUG] [ZWaveNode                 ] - NODE 6: resetResendCount initComplete=true isDead=false
2017-04-17 12:54:58.646 [DEBUG] [ZWaveNode                 ] - NODE 6: Incoming command class COMMAND_CLASS_METER, endpoint 0
2017-04-17 12:54:58.648 [DEBUG] [ZWaveNode                 ] - NODE 6: SECURITY not supported
2017-04-17 12:54:58.650 [DEBUG] [ZWaveCommandClass         ] - NODE 6: Received COMMAND_CLASS_METER V3 METER_REPORT
2017-04-17 12:54:58.653 [DEBUG] [ZWaveMeterCommandClass    ] - NODE 6: Meter: Type=Electric(1), Scale=kWh(0), Value=0.08
2017-04-17 12:54:58.655 [DEBUG] [ZWaveController           ] - Notifying event listeners: ZWaveMeterValueEvent
2017-04-17 12:54:58.657 [DEBUG] [ZWaveThingHandler         ] - NODE 6: Got an event from Z-Wave network: ZWaveMeterValueEvent
2017-04-17 12:54:58.660 [DEBUG] [ZWaveThingHandler         ] - NODE 6: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_METER, value = 0.08 2017-04-17 12:54:58.662 [DEBUG] [ZWaveMeterConverter       ] - Not the right scale E_A <> E_KWh
2017-04-17 12:54:58.665 [DEBUG] [ZWaveThingHandler         ] - NODE 6: Updating channel state zwave:device:c9b27cea:node6:meter_kwh to 0.08 [DecimalType]
2017-04-17 12:54:58.672 [DEBUG] [ZWaveMeterConverter       ] - Not the right scale E_W <> E_KWh
2017-04-17 12:54:58.674 [DEBUG] [ZWaveMeterConverter       ] - Not the right scale E_V <> E_KWh
2017-04-17 12:54:58.677 [DEBUG] [ZWaveTransactionManager   ] - NODE 6: Commands processed 1.
2017-04-17 12:54:58.679 [DEBUG] [ZWaveTransactionManager   ] - NODE 6: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@e9b867.
2017-04-17 12:54:58.681 [DEBUG] [ZWaveTransactionManager   ] - Transaction completed - outstandingTransactions 0
2017-04-17 12:54:58.684 [DEBUG] [ZWaveTransactionManager   ] - Transaction completed - outstandingTransactions 0
2017-04-17 12:54:58.686 [DEBUG] [ZWaveTransactionManager   ] - ZWaveReceiveThread queue empty
2017-04-17 12:54:58.688 [DEBUG] [ZWaveTransactionManager   ] - Transaction SendNextMessage 0 out at start
2017-04-17 12:54:58.690 [DEBUG] [ZWaveTransactionManager   ] - Transaction from controllerQueue
2017-04-17 12:54:58.692 [DEBUG] [ZWaveTransactionManager   ] - Transaction SendNextMessage nothing
2017-04-17 12:54:59.547 [DEBUG] [Handler$ZWaveReceiveThread] - Receive Message = 01 15 00 04 00 06 0F 32 02 21 54 00 00 08 F9 01 2D 00 00 08 FE 00 89
2017-04-17 12:54:59.553 [DEBUG] [Handler$ZWaveReceiveThread] - Response SENT 6
2017-04-17 12:54:59.557 [DEBUG] [ZWaveTransactionManager   ] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=6, callback=0, payload=00 06 0F 32 02 21 54 00 00 08 F9 01 2D 00 00 08 FE 00
2017-04-17 12:54:59.562 [DEBUG] [ZWaveTransactionManager   ] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=6, callback=0, payload=00 06 0F 32 02 21 54 00 00 08 F9 01 2D 00 00 08 FE 00
2017-04-17 12:54:59.565 [DEBUG] [ZWaveTransactionManager   ] - Received msg Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=6, callback=0, payload=00 06 0F 32 02 21 54 00 00 08 F9 01 2D 00 00 08 FE 00
2017-04-17 12:54:59.568 [DEBUG] [ZWaveTransactionManager   ] - lastTransaction null
2017-04-17 12:54:59.570 [DEBUG] [ZWaveTransactionManager   ] - NODE 6: Application Command Request (ALIVE:DONE)
2017-04-17 12:54:59.572 [DEBUG] [ZWaveNode                 ] - NODE 6: resetResendCount initComplete=true isDead=false
2017-04-17 12:54:59.575 [DEBUG] [ZWaveNode                 ] - NODE 6: Incoming command class COMMAND_CLASS_METER, endpoint 0
2017-04-17 12:54:59.577 [DEBUG] [ZWaveNode                 ] - NODE 6: SECURITY not supported
2017-04-17 12:54:59.579 [DEBUG] [ZWaveCommandClass         ] - NODE 6: Received COMMAND_CLASS_METER V3 METER_REPORT
2017-04-17 12:54:59.582 [DEBUG] [ZWaveMeterCommandClass    ] - NODE 6: Meter: Type=Electric(1), Scale=W(2), Value=22.97
2017-04-17 12:54:59.584 [DEBUG] [ZWaveController           ] - Notifying event listeners: ZWaveMeterValueEvent
2017-04-17 12:54:59.586 [DEBUG] [ZWaveThingHandler         ] - NODE 6: Got an event from Z-Wave network: ZWaveMeterValueEvent
2017-04-17 12:54:59.589 [DEBUG] [ZWaveThingHandler         ] - NODE 6: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_METER, value = 22.97

2017-04-17 12:54:59.591 [DEBUG] [ZWaveMeterConverter       ] - Not the right scale E_A <> E_W
2017-04-17 12:54:59.594 [DEBUG] [ZWaveMeterConverter       ] - Not the right scale E_KWh <> E_W
2017-04-17 12:54:59.596 [DEBUG] [ZWaveThingHandler         ] - NODE 6: Updating channel state zwave:device:c9b27cea:node6:meter_watts to 22.97 [DecimalType]
2017-04-17 12:54:59.608 [DEBUG] [ZWaveMeterConverter       ] - Not the right scale E_V <> E_W
2017-04-17 12:54:59.610 [DEBUG] [ZWaveTransactionManager   ] - NODE 6: Commands processed 1.
2017-04-17 12:54:59.613 [DEBUG] [ZWaveTransactionManager   ] - NODE 6: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@15961f8.
2017-04-17 12:54:59.615 [DEBUG] [ZWaveTransactionManager   ] - Transaction completed - outstandingTransactions 0
2017-04-17 12:54:59.617 [DEBUG] [ZWaveTransactionManager   ] - Transaction completed - outstandingTransactions 0
2017-04-17 12:54:59.619 [DEBUG] [ZWaveTransactionManager   ] - ZWaveReceiveThread queue empty
2017-04-17 12:54:59.621 [DEBUG] [ZWaveTransactionManager   ] - Transaction SendNextMessage 0 out at start
2017-04-17 12:54:59.624 [DEBUG] [ZWaveTransactionManager   ] - Transaction from controllerQueue
2017-04-17 12:54:59.626 [DEBUG] [ZWaveTransactionManager   ] - Transaction SendNextMessage nothing
2017-04-17 12:55:00.547 [DEBUG] [Handler$ZWaveReceiveThread] - Receive Message = 01 11 00 04 00 06 0B 32 02 A1 42 59 B5 01 2D 59 D5 00 78
2017-04-17 12:55:00.551 [DEBUG] [Handler$ZWaveReceiveThread] - Response SENT 6
2017-04-17 12:55:00.555 [DEBUG] [ZWaveTransactionManager   ] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=6, callback=0, payload=00 06 0B 32 02 A1 42 59 B5 01 2D 59 D5 00
2017-04-17 12:55:00.558 [DEBUG] [ZWaveTransactionManager   ] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=6, callback=0, payload=00 06 0B 32 02 A1 42 59 B5 01 2D 59 D5 00
2017-04-17 12:55:00.561 [DEBUG] [ZWaveTransactionManager   ] - Received msg Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=6, callback=0, payload=00 06 0B 32 02 A1 42 59 B5 01 2D 59 D5 00
2017-04-17 12:55:00.571 [DEBUG] [ZWaveTransactionManager   ] - lastTransaction null
2017-04-17 12:55:00.573 [DEBUG] [ZWaveTransactionManager   ] - NODE 6: Application Command Request (ALIVE:DONE)
2017-04-17 12:55:00.576 [DEBUG] [ZWaveNode                 ] - NODE 6: resetResendCount initComplete=true isDead=false
2017-04-17 12:55:00.578 [DEBUG] [ZWaveNode                 ] - NODE 6: Incoming command class COMMAND_CLASS_METER, endpoint 0
2017-04-17 12:55:00.580 [DEBUG] [ZWaveNode                 ] - NODE 6: SECURITY not supported
2017-04-17 12:55:00.583 [DEBUG] [ZWaveCommandClass         ] - NODE 6: Received COMMAND_CLASS_METER V3 METER_REPORT
2017-04-17 12:55:00.585 [DEBUG] [ZWaveMeterCommandClass    ] - NODE 6: Meter: Type=Electric(1), Scale=V(4), Value=229.65
2017-04-17 12:55:00.588 [DEBUG] [ZWaveController           ] - Notifying event listeners: ZWaveMeterValueEvent
2017-04-17 12:55:00.590 [DEBUG] [ZWaveThingHandler         ] - NODE 6: Got an event from Z-Wave network: ZWaveMeterValueEvent
2017-04-17 12:55:00.592 [DEBUG] [ZWaveThingHandler         ] - NODE 6: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_METER, value = 229.65
2017-04-17 12:55:00.595 [DEBUG] [ZWaveMeterConverter       ] - Not the right scale E_A <> E_V
2017-04-17 12:55:00.597 [DEBUG] [ZWaveMeterConverter       ] - Not the right scale E_KWh <> E_V
2017-04-17 12:55:00.599 [DEBUG] [ZWaveMeterConverter       ] - Not the right scale E_W <> E_V
2017-04-17 12:55:00.602 [DEBUG] [ZWaveThingHandler         ] - NODE 6: Updating channel state zwave:device:c9b27cea:node6:meter_voltage to 229.65 [DecimalType]
2017-04-17 12:55:00.605 [DEBUG] [ZWaveTransactionManager   ] - NODE 6: Commands processed 1.
2017-04-17 12:55:00.607 [DEBUG] [ZWaveTransactionManager   ] - NODE 6: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1bf281a.
2017-04-17 12:55:00.609 [DEBUG] [ZWaveTransactionManager   ] - Transaction completed - outstandingTransactions 0
2017-04-17 12:55:00.612 [DEBUG] [ZWaveTransactionManager   ] - Transaction completed - outstandingTransactions 0
2017-04-17 12:55:00.614 [DEBUG] [ZWaveTransactionManager   ] - ZWaveReceiveThread queue empty
2017-04-17 12:55:00.616 [DEBUG] [ZWaveTransactionManager   ] - Transaction SendNextMessage 0 out at start
2017-04-17 12:55:00.618 [DEBUG] [ZWaveTransactionManager   ] - Transaction from controllerQueue
2017-04-17 12:55:00.620 [DEBUG] [ZWaveTransactionManager   ] - Transaction SendNextMessage nothing
2017-04-17 12:55:01.547 [DEBUG] [Handler$ZWaveReceiveThread] - Receive Message = 01 11 00 04 00 06 0B 32 02 A1 4A 00 0B 01 2D 00 0B 00 10
2017-04-17 12:55:01.551 [DEBUG] [Handler$ZWaveReceiveThread] - Response SENT 6
2017-04-17 12:55:01.554 [DEBUG] [ZWaveTransactionManager   ] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=6, callback=0, payload=00 06 0B 32 02 A1 4A 00 0B 01 2D 00 0B 00
2017-04-17 12:55:01.557 [DEBUG] [ZWaveTransactionManager   ] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=6, callback=0, payload=00 06 0B 32 02 A1 4A 00 0B 01 2D 00 0B 00
2017-04-17 12:55:01.561 [DEBUG] [ZWaveTransactionManager   ] - Received msg Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=6, callback=0, payload=00 06 0B 32 02 A1 4A 00 0B 01 2D 00 0B 00
2017-04-17 12:55:01.563 [DEBUG] [ZWaveTransactionManager   ] - lastTransaction null
2017-04-17 12:55:01.565 [DEBUG] [ZWaveTransactionManager   ] - NODE 6: Application Command Request (ALIVE:DONE)
2017-04-17 12:55:01.568 [DEBUG] [ZWaveNode                 ] - NODE 6: resetResendCount initComplete=true isDead=false
2017-04-17 12:55:01.570 [DEBUG] [ZWaveNode                 ] - NODE 6: Incoming command class COMMAND_CLASS_METER, endpoint 0
2017-04-17 12:55:01.572 [DEBUG] [ZWaveNode                 ] - NODE 6: SECURITY not supported
2017-04-17 12:55:01.575 [DEBUG] [ZWaveCommandClass         ] - NODE 6: Received COMMAND_CLASS_METER V3 METER_REPORT
2017-04-17 12:55:01.577 [DEBUG] [ZWaveMeterCommandClass    ] - NODE 6: Meter: Type=Electric(1), Scale=A(5), Value=0.11
2017-04-17 12:55:01.579 [DEBUG] [ZWaveController           ] - Notifying event listeners: ZWaveMeterValueEvent
2017-04-17 12:55:01.582 [DEBUG] [ZWaveThingHandler         ] - NODE 6: Got an event from Z-Wave network: ZWaveMeterValueEvent
2017-04-17 12:55:01.584 [DEBUG] [ZWaveThingHandler         ] - NODE 6: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_METER, value = 0.11 2017-04-17 12:55:01.591 [DEBUG] [ZWaveThingHandler         ] - NODE 6: Updating channel state zwave:device:c9b27cea:node6:meter_current to 0.11 [DecimalType]
2017-04-17 12:55:01.596 [DEBUG] [ZWaveMeterConverter       ] - Not the right scale E_KWh <> E_A
2017-04-17 12:55:01.598 [DEBUG] [ZWaveMeterConverter       ] - Not the right scale E_W <> E_A
2017-04-17 12:55:01.600 [DEBUG] [ZWaveMeterConverter       ] - Not the right scale E_V <> E_A
2017-04-17 12:55:01.603 [DEBUG] [ZWaveTransactionManager   ] - NODE 6: Commands processed 1.
2017-04-17 12:55:01.605 [DEBUG] [ZWaveTransactionManager   ] - NODE 6: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1805508.
2017-04-17 12:55:01.607 [DEBUG] [ZWaveTransactionManager   ] - Transaction completed - outstandingTransactions 0
2017-04-17 12:55:01.609 [DEBUG] [ZWaveTransactionManager   ] - Transaction completed - outstandingTransactions 0
2017-04-17 12:55:01.611 [DEBUG] [ZWaveTransactionManager   ] - ZWaveReceiveThread queue empty
2017-04-17 12:55:01.614 [DEBUG] [ZWaveTransactionManager   ] - Transaction SendNextMessage 0 out at start
2017-04-17 12:55:01.616 [DEBUG] [ZWaveTransactionManager   ] - Transaction from controllerQueue
2017-04-17 12:55:01.618 [DEBUG] [ZWaveTransactionManager   ] - Transaction SendNextMessage nothing

Thatā€™s ok - itā€™s just a debug message. Where you have multiple meter channels in a single class you will see this (although I think Iā€™ll remove this message now).

Remember - this is a test binding - it does have a lot of verbose logging so I wouldnā€™t read too much into the log messages unless youā€™re actually seeing a problem such as exceptions, or channels not updating, commands not working etc.

1 Like

Iā€™ve done an update to add the new devices and change a bit of logging - @rdslw @adb76

Great, thank you. PAD02 is working!

Testing more nowā€¦

Looks good to go. Seems to take a bit of time to push them to the lock, but this morning everything works great!!

One item to add to the endless wishlist would be able to store a string variable with each user code to make it easier to keep track of them, especially once we are able to get the user codes back from the lock when they are entered.

And along @whwkins response here, I did find this document if itā€™s any help and shows how the user codes are included in the alarm notification from the lock.

http://s7d5.scene7.com/is/content/BDHHI/ApplicationNote-UsingASCII-Z-Wave-Locks

Iā€™ll wait for @grizzlyjere to enter in the new alarm_number field to the DB. Iā€™m not quite sure I fully understood how to submit those changes. I look forward to testing out the alarm reports capability, but am fully satisfied now that I can at least get the User Codes entered.

As a side note, I had limited success with the plug my ZStick into a portable compute (Pine64) unit and secure include. I was able to get the Garage Controller in successfully after a bunch of tries. Honestly, I think something in HABmin isnā€™t liking throwing the controller into include. It seemed when I tried from PaperUI that I was able to successfully get it to go.

Feel free to open an issue on the tracker and Iā€™ll take a look at this at some stage.

Thanks, will so.

I did just add the alarm code # / Event Notification message to the 914 database entry so hopefully that will be helpful for others.

@chris - Just trying to revive this post as Iā€™m sure itā€™s been lost in the flood. :wink:

Does this sound like something that could be in the binding and/or the XML somewhere restricting actions taken within OpenHAB? Or should I be hunting down something else that could be wrong here? I believe I even tried using the Karaf console to rename the devices, but it wonā€™t take place, nor do I see any error messages anywhere indicating the problem.

The reason Iā€™m surmising it may be ZWave related, is because only 1 thing is in common for these troublesome devices - theyā€™re all a specific type of switch (HS-WS100+). And because at one point, they didnā€™t have an issue, somewhere along the lines I believe a test binding update (hell if I remember which), caused a lapse in ability to rename them anymore.

Sorry - Iā€™m not sure completely what the issue is - your message references another message which talks about ā€œcoming back to this issueā€ā€¦

Iā€™d suggest to pull out the relevant bits into a separate thread so itā€™s clear what the issue is and Iā€™ll take a lookā€¦

(thanks)

I am in use of a razberry transmitter and have some delays after not interacting with devices for a longer time. For example if i push a remote butten on my NODON or some switch is triggered by a motion detector.

As you can see both the state changes ON to OFF (vice versa) and the received command are logged with nearly the same timestamp. But the device is changing the physical state 5 or more seconds later. The log is written in time when i push the button.

After a few interactions everything is working responsiv. It seems razberry is in sleep mode or something like that. Any experience on that?

Itā€™s hard to comment on this from just the event log - the full debug log would be required.

@chris: of course i will post required info butā€¦

openhab> log:set DEBUG log4j.logger.org.openhab.binding.zwave 

still shows only INFO logs. Im running stable 2.0.

Should be -:

log:set DEBUG org.openhab.binding.zwave

@chris:

openhab> log:get ALL
Logger                                                      | Level
-------------------------------------------------------------------
ROOT                                                        | INFO
javax.jmdns                                                 | ERROR
org.apache.aries.spifly                                     | ERROR
org.apache.karaf.kar.internal.KarServiceImpl                | ERROR
org.eclipse.smarthome                                       | INFO
org.jupnp                                                   | ERROR
org.openhab                                                 | INFO
org.openhab.binding.zwave                                   | DEBUG
org.ops4j.pax.web.service.jetty.internal.JettyServerWrapper | ERROR
smarthome.event                                             | INFO
smarthome.event.InboxUpdatedEvent                           | ERROR
smarthome.event.ItemStateEvent                              | ERROR
smarthome.event.ThingStatusInfoEvent                        | ERROR
openhab>

still get no DEBUG logs for zwave

One thing I noticed with my ct100 thermostats, is that two of the three thermostats are reporting humidity values that donā€™t make sense. That is, the values are greater than 100. Since one humidity value from the three thermostats appears to be correct I tried (and failed) to find a difference in the node xmlā€™s and thing/channel link json definitions from the jsondb. Do you know anything that would cause a ā€œsensor_relhumidityā€ to read > 100?

Here is the device in question: http://www.cd-jackson.com/index.php/zwave/zwave-device-database/zwave-device-list/devicesummary/96

Please provide a debug log - itā€™s really the only way to know if itā€™s the device, the binding, or something else.