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

Woohoo! It’s not just me anymore. :smile:

Agreed - thanks as always @chris for the continued hard work, especially over a holiday weekend!

I’ll look to gather some more logs and get back to you ticket as well since I’ve confirmed the SET is still not working, and still not receiving the code that is there in HABmin.

Hey - not so chearful! :wink:

I’ve just reinstalled my lock so can also confirm this here as well. I don’t think it’s a HABmin problem - it’s probably a problem in the binding since the binding isn’t serving up the configuration via REST.

New binding available - hopefully with user codes working.

I found that most configuration data wasn’t being secured - this is why the user codes weren’t working, but also why things like configuration weren’t working (which explains why I couldn’t set the volume on my door to low! my partner will be happy now ;)).

There are still a few things to look at here, but this should be a big improvement.

Sweet! Didn’t even need to send those pesky logs. :smile: confirmed working for me. Now I can install the lock, my partner will be excited!! :wink:

I do look forward to future testing involving the time restrictions, and advancement of the alarm functions. I’ll be looking at those when I have some time, but for now this is fantastic and really the missing piece for me to get it running full force here. Thanks so much for the work Chris, this really is phenomenal.

All of the exceptions seem to be related to logging issues - I don’t know why, but given that the only change (other than database updates) is the change of the logger, I’m guessing it’s that.

I’ll try and revert this change, but it’s not so easy :frowning:

Ok - I’ve reverted back to using the static logger - lets see if that helps.

@chris, sorry if I’m dense but could you give me guidance on what updates need to be made to the website database for a lock to support the raw error code and the user code? Or perhaps share an example to copy from?

I’m using a YRD220 lock with the latest binding.

Thanks!

Do I need to delete and readd the Lock to get this to work or should they work with just the binding change?

You just need to update the binding - you shouldn’t need to do anything else.

Simply add a new channel into the ALARM command class called alarm_number. That should be all (and give it a label obviously :wink: ).

@chris , few questions:

  1. is PAD02 I entered yesterdey compiled into latest jar (from APR 16, 21h57m CET) ?
    I’m asking as it’s still ‘Device Unknown’ after discovery, although zwave.log shows more information. This is BTW device ‘node5’ from the log below.

  2. I’m seeing today messages ‘NODE 255: Transaction not completed: node address inconsistent. lastSent=255, incoming=255’ - it MAY be related to binding updated from Apr15 to Apr16, but not necessarily - any suggestions?

  3. I’m seeing today a lot of ‘NODE 6: Polling aborted as no converter found for zwave:device:c9b27cea:node6:meter_current’ messages. They did not happened yesterday.

EDIT:
ad 3: This happens with a lot of nodes today, also for switch channels:
2017-04-17 10:52:35.633 [DEBUG] [ZWaveThingHandler ] - NODE 2: Command received zwave:device:c9b27cea:node2:switch_binary --> ON
2017-04-17 10:52:35.650 [DEBUG] [ZWaveThingHandler ] - NODE 2: No converter set for command zwave:device:c9b27cea:node2:switch_binary type OnOffType

Log exempt:


    2017-04-17 10:33:37.271 [DEBUG] [zwave                     ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=323, service.bundleid=191, service.scope=singleton} - org.openhab.binding.zwave
    2017-04-17 10:33:37.293 [DEBUG] [ZWaveThingHandler         ] - Initializing ZWave thing handler.
    2017-04-17 10:33:37.323 [DEBUG] [ZWaveThingHandler         ] - NODE 5: Controller status changed to ONLINE.
    2017-04-17 10:33:37.331 [DEBUG] [ZWaveThingHandler         ] - NODE 5: Controller is ONLINE. Starting device initialisation.
    2017-04-17 10:33:37.342 [DEBUG] [ZWaveThingHandler         ] - NODE 5: Updating node properties.
    2017-04-17 10:33:37.344 [DEBUG] [ZWaveThingHandler         ] - NODE 5: Updating node properties. MAN=316
    2017-04-17 10:33:37.346 [DEBUG] [ZWaveThingHandler         ] - NODE 5: Updating node properties. MAN=316. SET. Was 316
    2017-04-17 10:33:37.349 [DEBUG] [ZWaveThingHandler         ] - NODE 5: Properties synchronised
    2017-04-17 10:33:37.360 [DEBUG] [ZWaveThingHandler         ] - NODE 5: Configuration synchronised
    2017-04-17 10:33:37.429 [DEBUG] [ZWaveThingHandler         ] - NODE 5: Initialising Thing Node...
    2017-04-17 10:33:37.430 [DEBUG] [ZWaveThingHandler         ] - NODE 5: Polling intialised at 1800 seconds - start in 1800000 milliseconds.
    2017-04-17 10:34:36.113 [DEBUG] [Handler$ZWaveReceiveThread] - Receive Message = 01 15 00 04 00 06 0F 32 02 21 44 00 00 00 04 01 2D 00 00 00 03 00 99
    2017-04-17 10:34:36.133 [DEBUG] [ZWaveController           ] - Receive queue TAKE: Length=0
    2017-04-17 10:34:36.135 [DEBUG] [SerialMessage             ] - Assembled message buffer = 01 15 00 04 00 06 0F 32 02 21 44 00 00 00 04 01 2D 00 00 00 03 00 99
    2017-04-17 10:34:36.137 [DEBUG] [ZWaveController           ] - Process Message = 01 15 00 04 00 06 0F 32 02 21 44 00 00 00 04 01 2D 00 00 00 03 00 99
    2017-04-17 10:34:36.139 [DEBUG] [ZWaveController           ] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 06 0F 32 02 21 44 00 00 00 04 01 2D 00 00 00 03 00
    2017-04-17 10:34:36.142 [DEBUG] [icationCommandMessageClass] - NODE 6: Application Command Request (ALIVE:DONE)
    2017-04-17 10:34:36.145 [DEBUG] [ZWaveNodeInitStageAdvancer] - NODE 6: Starting initialisation from DONE
    2017-04-17 10:34:36.147 [DEBUG] [ZWaveController           ] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@1b270bb already registered
    2017-04-17 10:34:36.150 [DEBUG] [icationCommandMessageClass] - NODE 6: Incoming command class METER
    2017-04-17 10:34:36.152 [DEBUG] [ZWaveMeterCommandClass    ] - NODE 6: Received METER command V3
    2017-04-17 10:34:36.155 [DEBUG] [ZWaveMeterCommandClass    ] - NODE 6: Meter: Type=Electric(1), Scale=kWh(0), Value=0.04
    2017-04-17 10:34:36.157 [DEBUG] [ZWaveController           ] - Notifying event listeners: ZWaveMeterValueEvent
    2017-04-17 10:34:36.159 [DEBUG] [ZWaveThingHandler         ] - NODE 6: Got an event from Z-Wave network: ZWaveMeterValueEvent
    2017-04-17 10:34:36.161 [DEBUG] [ZWaveThingHandler         ] - NODE 6: Got a value event from Z-Wave network, endpoint = 0, command class = METER, value = 0.04
    2017-04-17 10:34:36.164 [DEBUG] [icationCommandMessageClass] - NODE 255: Transaction not completed: node address inconsistent.  lastSent=255, incoming=255
    2017-04-17 10:34:37.092 [DEBUG] [Handler$ZWaveReceiveThread] - Receive Message = 01 15 00 04 00 06 0F 32 02 21 54 00 00 09 01 01 2D 00 00 09 15 00 9A
    2017-04-17 10:34:37.120 [DEBUG] [ZWaveController           ] - Receive queue TAKE: Length=0
    2017-04-17 10:34:37.122 [DEBUG] [SerialMessage             ] - Assembled message buffer = 01 15 00 04 00 06 0F 32 02 21 54 00 00 09 01 01 2D 00 00 09 15 00 9A
    2017-04-17 10:34:37.125 [DEBUG] [ZWaveController           ] - Process Message = 01 15 00 04 00 06 0F 32 02 21 54 00 00 09 01 01 2D 00 00 09 15 00 9A
    2017-04-17 10:34:37.129 [DEBUG] [ZWaveController           ] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 06 0F 32 02 21 54 00 00 09 01 01 2D 00 00 09 15 00
    2017-04-17 10:34:37.131 [DEBUG] [icationCommandMessageClass] - NODE 6: Application Command Request (ALIVE:DONE)
    2017-04-17 10:34:37.142 [DEBUG] [ZWaveNodeInitStageAdvancer] - NODE 6: Starting initialisation from DONE
    2017-04-17 10:34:37.144 [DEBUG] [ZWaveController           ] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@1b270bb already registered
    2017-04-17 10:34:37.147 [DEBUG] [icationCommandMessageClass] - NODE 6: Incoming command class METER
    2017-04-17 10:34:37.151 [DEBUG] [ZWaveMeterCommandClass    ] - NODE 6: Received METER command V3
    2017-04-17 10:34:37.154 [DEBUG] [ZWaveMeterCommandClass    ] - NODE 6: Meter: Type=Electric(1), Scale=W(2), Value=23.05
    2017-04-17 10:34:37.157 [DEBUG] [ZWaveController           ] - Notifying event listeners: ZWaveMeterValueEvent
    2017-04-17 10:34:37.162 [DEBUG] [ZWaveThingHandler         ] - NODE 6: Got an event from Z-Wave network: ZWaveMeterValueEvent
    2017-04-17 10:34:37.164 [DEBUG] [ZWaveThingHandler         ] - NODE 6: Got a value event from Z-Wave network, endpoint = 0, command class = METER, value = 23.05
    2017-04-17 10:34:37.166 [DEBUG] [icationCommandMessageClass] - NODE 255: Transaction not completed: node address inconsistent.  lastSent=255, incoming=255
    2017-04-17 10:34:38.106 [DEBUG] [Handler$ZWaveReceiveThread] - Receive Message = 01 11 00 04 00 06 0B 32 02 A1 42 59 39 01 2D 59 8E 00 AF
    2017-04-17 10:34:38.111 [DEBUG] [ZWaveController           ] - Receive queue TAKE: Length=0
    2017-04-17 10:34:38.116 [DEBUG] [SerialMessage             ] - Assembled message buffer = 01 11 00 04 00 06 0B 32 02 A1 42 59 39 01 2D 59 8E 00 AF
    2017-04-17 10:34:38.119 [DEBUG] [ZWaveController           ] - Process Message = 01 11 00 04 00 06 0B 32 02 A1 42 59 39 01 2D 59 8E 00 AF
    2017-04-17 10:34:38.123 [DEBUG] [ZWaveController           ] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 06 0B 32 02 A1 42 59 39 01 2D 59 8E 00
    2017-04-17 10:34:38.126 [DEBUG] [icationCommandMessageClass] - NODE 6: Application Command Request (ALIVE:DONE)
    2017-04-17 10:34:38.128 [DEBUG] [ZWaveNodeInitStageAdvancer] - NODE 6: Starting initialisation from DONE
    2017-04-17 10:34:38.130 [DEBUG] [ZWaveController           ] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@1b270bb already registered
    2017-04-17 10:34:38.133 [DEBUG] [icationCommandMessageClass] - NODE 6: Incoming command class METER
    2017-04-17 10:34:38.135 [DEBUG] [ZWaveMeterCommandClass    ] - NODE 6: Received METER command V3
    2017-04-17 10:34:38.138 [DEBUG] [ZWaveMeterCommandClass    ] - NODE 6: Meter: Type=Electric(1), Scale=V(4), Value=228.41
    2017-04-17 10:34:38.140 [DEBUG] [ZWaveController           ] - Notifying event listeners: ZWaveMeterValueEvent
    2017-04-17 10:34:38.142 [DEBUG] [ZWaveThingHandler         ] - NODE 6: Got an event from Z-Wave network: ZWaveMeterValueEvent
    2017-04-17 10:34:38.144 [DEBUG] [ZWaveThingHandler         ] - NODE 6: Got a value event from Z-Wave network, endpoint = 0, command class = METER, value = 228.41
    2017-04-17 10:34:38.147 [DEBUG] [icationCommandMessageClass] - NODE 255: Transaction not completed: node address inconsistent.  lastSent=255, incoming=255
    2017-04-17 10:34:39.097 [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 10:34:39.117 [DEBUG] [ZWaveController           ] - Receive queue TAKE: Length=0
    2017-04-17 10:34:39.119 [DEBUG] [SerialMessage             ] - Assembled message buffer = 01 11 00 04 00 06 0B 32 02 A1 4A 00 0B 01 2D 00 0B 00 10
    2017-04-17 10:34:39.122 [DEBUG] [ZWaveController           ] - Process Message = 01 11 00 04 00 06 0B 32 02 A1 4A 00 0B 01 2D 00 0B 00 10
    2017-04-17 10:34:39.125 [DEBUG] [ZWaveController           ] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 06 0B 32 02 A1 4A 00 0B 01 2D 00 0B 00
    2017-04-17 10:34:39.128 [DEBUG] [icationCommandMessageClass] - NODE 6: Application Command Request (ALIVE:DONE)
    2017-04-17 10:34:39.130 [DEBUG] [ZWaveNodeInitStageAdvancer] - NODE 6: Starting initialisation from DONE
    2017-04-17 10:34:39.132 [DEBUG] [ZWaveController           ] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@1b270bb already registered
    2017-04-17 10:34:39.135 [DEBUG] [icationCommandMessageClass] - NODE 6: Incoming command class METER
    2017-04-17 10:34:39.137 [DEBUG] [ZWaveMeterCommandClass    ] - NODE 6: Received METER command V3
    2017-04-17 10:34:39.139 [DEBUG] [ZWaveMeterCommandClass    ] - NODE 6: Meter: Type=Electric(1), Scale=A(5), Value=0.11
    2017-04-17 10:34:39.142 [DEBUG] [ZWaveController           ] - Notifying event listeners: ZWaveMeterValueEvent
    2017-04-17 10:34:39.144 [DEBUG] [ZWaveThingHandler         ] - NODE 6: Got an event from Z-Wave network: ZWaveMeterValueEvent
    2017-04-17 10:34:39.146 [DEBUG] [ZWaveThingHandler         ] - NODE 6: Got a value event from Z-Wave network, endpoint = 0, command class = METER, value = 0.11
    2017-04-17 10:34:39.149 [DEBUG] [icationCommandMessageClass] - NODE 255: Transaction not completed: node address inconsistent.  lastSent=255, incoming=255
    2017-04-17 10:35:31.384 [DEBUG] [ZWaveThingHandler         ] - NODE 6: Command received zwave:device:c9b27cea:node6:switch_binary --> REFRESH
    2017-04-17 10:35:31.392 [DEBUG] [ZWaveThingHandler         ] - NODE 6: Polling intialised at 1800 seconds - start in 50 milliseconds.
    2017-04-17 10:35:31.397 [DEBUG] [ZWaveThingHandler         ] - NODE 6: Command received zwave:device:c9b27cea:node6:switch_binary --> REFRESH
    2017-04-17 10:35:31.400 [DEBUG] [ZWaveThingHandler         ] - NODE 6: Polling intialised at 1800 seconds - start in 50 milliseconds.
    2017-04-17 10:35:31.449 [DEBUG] [ZWaveThingHandler         ] - NODE 2: Polling...
    2017-04-17 10:35:31.450 [DEBUG] [ZWaveThingHandler         ] - NODE 2: Polling zwave:device:c9b27cea:node2:switch_binary
    2017-04-17 10:35:31.451 [DEBUG] [ZWaveThingHandler         ] - NODE 2: Polling aborted as no converter found for zwave:device:c9b27cea:node2:switch_binary
    2017-04-17 10:35:31.451 [DEBUG] [ZWaveThingHandler         ] - NODE 2: Polling zwave:device:c9b27cea:node2:sensor_power
    2017-04-17 10:35:31.452 [DEBUG] [ZWaveThingHandler         ] - NODE 2: Polling aborted as no converter found for zwave:device:c9b27cea:node2:sensor_power
    2017-04-17 10:35:31.452 [DEBUG] [ZWaveThingHandler         ] - NODE 2: Polling zwave:device:c9b27cea:node2:meter_kwh
    2017-04-17 10:35:31.453 [DEBUG] [ZWaveThingHandler         ] - NODE 2: Polling aborted as no converter found for zwave:device:c9b27cea:node2:meter_kwh
    2017-04-17 10:35:31.454 [DEBUG] [ZWaveThingHandler         ] - NODE 2: Polling zwave:device:c9b27cea:node2:meter_watts
    2017-04-17 10:35:31.454 [DEBUG] [ZWaveThingHandler         ] - NODE 2: Polling aborted as no converter found for zwave:device:c9b27cea:node2:meter_watts
    2017-04-17 10:35:31.455 [DEBUG] [ZWaveThingHandler         ] - NODE 2: Polling zwave:device:c9b27cea:node2:meter_reset
    2017-04-17 10:35:31.455 [DEBUG] [ZWaveThingHandler         ] - NODE 2: Polling aborted as no converter found for zwave:device:c9b27cea:node2:meter_reset
    2017-04-17 10:35:31.456 [DEBUG] [ZWaveThingHandler         ] - NODE 2: Polling zwave:device:c9b27cea:node2:config_decimal_param61
    2017-04-17 10:35:31.456 [DEBUG] [ZWaveThingHandler         ] - NODE 2: Polling aborted as no converter found for zwave:device:c9b27cea:node2:config_decimal_param61
    2017-04-17 10:35:31.457 [DEBUG] [ZWaveThingHandler         ] - NODE 2: Polling zwave:device:c9b27cea:node2:config_decimal_param62
    2017-04-17 10:35:31.457 [DEBUG] [ZWaveThingHandler         ] - NODE 2: Polling aborted as no converter found for zwave:device:c9b27cea:node2:config_decimal_param62
    2017-04-17 10:35:31.458 [DEBUG] [ZWaveThingHandler         ] - NODE 2: Polling zwave:device:c9b27cea:node2:notification_send
    2017-04-17 10:35:31.458 [DEBUG] [ZWaveThingHandler         ] - NODE 2: Polling aborted as no converter found for zwave:device:c9b27cea:node2:notification_send
    2017-04-17 10:35:31.459 [DEBUG] [ZWaveThingHandler         ] - NODE 6: Polling...
    2017-04-17 10:35:31.472 [DEBUG] [ZWaveThingHandler         ] - NODE 6: Polling zwave:device:c9b27cea:node6:switch_binary
    2017-04-17 10:35:31.474 [DEBUG] [ZWaveThingHandler         ] - NODE 6: Polling aborted as no converter found for zwave:device:c9b27cea:node6:switch_binary
    2017-04-17 10:35:31.481 [DEBUG] [ZWaveThingHandler         ] - NODE 6: Polling zwave:device:c9b27cea:node6:meter_current
    2017-04-17 10:35:31.483 [DEBUG] [ZWaveThingHandler         ] - NODE 6: Polling aborted as no converter found for zwave:device:c9b27cea:node6:meter_current
    2017-04-17 10:35:31.485 [DEBUG] [ZWaveThingHandler         ] - NODE 6: Polling zwave:device:c9b27cea:node6:meter_kwh
    2017-04-17 10:35:31.487 [DEBUG] [ZWaveThingHandler         ] - NODE 6: Polling aborted as no converter found for zwave:device:c9b27cea:node6:meter_kwh
    2017-04-17 10:35:31.491 [DEBUG] [ZWaveThingHandler         ] - NODE 6: Polling zwave:device:c9b27cea:node6:meter_watts
    2017-04-17 10:35:31.494 [DEBUG] [ZWaveThingHandler         ] - NODE 6: Polling aborted as no converter found for zwave:device:c9b27cea:node6:meter_watts
    2017-04-17 10:35:31.511 [DEBUG] [ZWaveThingHandler         ] - NODE 6: Polling zwave:device:c9b27cea:node6:meter_voltage
    2017-04-17 10:35:31.514 [DEBUG] [ZWaveThingHandler         ] - NODE 6: Polling aborted as no converter found for zwave:device:c9b27cea:node6:meter_voltage
    2017-04-17 10:35:31.516 [DEBUG] [ZWaveThingHandler         ] - NODE 6: Polling zwave:device:c9b27cea:node6:alarm_power
    2017-04-17 10:35:31.518 [DEBUG] [ZWaveThingHandler         ] - NODE 6: Polling aborted as no converter found for zwave:device:c9b27cea:node6:alarm_power

No, not yet.

This is a normal message from the old binding - it’s not an error in any case - it’s perfectly normal.

I’m not sure what node 6 is? Please can you provide a link to the database for this device.

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

IMPORTANT: I’m seeing ‘no converter’ messages from few others nodes of different types as well. For metered channels, but also from on/off channels.

Node 2: http://www.cd-jackson.com/index.php/zwave/zwave-device-database/zwave-device-list/devicesummary/130

Currently I’m not able to control them from paperUI - didnt try any kind of reset of openhab nor nodes.

Hi @chris,

many thanks for the latest updates of the binding. The error regarding the UPDATE_DATABASE issue for the Fibaro Wall Plugs is gone. Great!

On your homepage I saw that my ticket “Poll issue with “BATTERY_REPORT” / “METER_REPORT ELECTRIC_KWH”” is closed. So I tested my NorthQ power meter also with the latest update. Unfortunately this bug is still there. So should it work? If so I can provide new debug logs…

Regards.

When you say -:

What do you mean? What binding version is that with?

Also, what is node 2.

Can you provide the full log for startup - if easier open a ticket on my website as you can upload log files there.

By saying ‘they did not happened yesterday’ I meant, that I did not observe messages yesterday.
Important thing is, that yesterday, I was using binding version from April 15th, while today I’m using version from April 16th.

So too summarize: it looks (of course I may be wrong), that the ‘no converter’ messages started after upgrading binding to the version 16th.

Node 2 is: http://www.cd-jackson.com/index.php/zwave/zwave-device-database/zwave-device-list/devicesummary/130

I’ll do full network restart and if the problem persist, I’ll create a ticket.

p.s. The message “NODE 255: Transaction not completed: node address inconsistent.” you said is fine also did not appeared on Apr 15th version. Here the word ‘inconsistent’ is probably too strongly suggesting something bad is happening.

Yes - the version is what’s important - that’s what I meant. Again though - when you say the version from the 15th - is that the old binding or the new binding? I think you only changed to the new version recently and you ask some questions here relating to the old binding (ie the inconsistent id message) - I want to understand what version you were running.

Sure, no problem.

I’m currently using only new (development) version of the binding.

When I say version from April15, it’s a development version you uploaded on April 15th.
When I say version from April16, it’s a development version you uploaded on April 16h (just a day newer).
I’m using date modification time of YOUR upload to http://www.cd-jackson.com/downloads/openhab2/org.openhab.binding.zwave-2.1.0-SNAPSHOT.jar

As to the ‘NODE 255: Transaction not completed: node address inconsistent’ I did not see this message in my zwave.log while using version April15 (to be sure, this means development version of binding), but I do see it after upgrading to version from April16. This may be strange, but to be sure I did just now:
“grep ‘NODE 255: Transa’ /var/log/openhab2/zwave.log” and I get messages ONLY today, starting after I updated binding to the Apr16version.

Strange indeed - please can you provide part of a logfile with this.

Ticket created with logs.

I’ll do some more testing on my side with openhab restarts.