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

Add-ons Bindings
,
1488

Didn’t help.

These are my nodes:

2017-08-21 19:42:01.263 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 1: Node found
2017-08-21 19:42:01.263 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 3: Node found
2017-08-21 19:42:01.264 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 4: Node found
2017-08-21 19:42:01.264 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 5: Node found
2017-08-21 19:42:01.264 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 6: Node found
2017-08-21 19:42:01.265 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 7: Node found
2017-08-21 19:42:01.265 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 8: Node found
2017-08-21 19:42:01.265 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 9: Node found
2017-08-21 19:42:01.265 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 10: Node found
2017-08-21 19:42:01.266 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 11: Node found
2017-08-21 19:42:01.266 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 12: Node found
2017-08-21 19:42:01.266 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 13: Node found
2017-08-21 19:42:01.267 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 14: Node found
2017-08-21 19:42:01.267 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 15: Node found
2017-08-21 19:42:01.267 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 16: Node found
2017-08-21 19:42:01.267 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 17: Node found
2017-08-21 19:42:01.268 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 18: Node found
2017-08-21 19:42:01.268 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 20: Node found
2017-08-21 19:42:01.268 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 21: Node found
2017-08-21 19:42:01.268 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 22: Node found
2017-08-21 19:42:01.269 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 24: Node found
2017-08-21 19:42:01.273 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 25: Node found
2017-08-21 19:42:01.273 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 26: Node found
2017-08-21 19:42:01.274 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 27: Node found
2017-08-21 19:42:01.277 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 28: Node found
2017-08-21 19:42:01.277 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 29: Node found
2017-08-21 19:42:01.278 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 30: Node found
2017-08-21 19:42:01.278 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 31: Node found
2017-08-21 19:42:01.278 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 32: Node found
2017-08-21 19:42:01.279 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 34: Node found
2017-08-21 19:42:01.279 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 35: Node found
2017-08-21 19:42:01.279 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 36: Node found
2017-08-21 19:42:01.280 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 37: Node found
2017-08-21 19:42:01.284 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 38: Node found
2017-08-21 19:42:01.285 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 40: Node found
2017-08-21 19:42:01.285 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 41: Node found
2017-08-21 19:42:01.286 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 42: Node found
2017-08-21 19:42:01.286 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 43: Node found
2017-08-21 19:42:01.293 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 44: Node found
2017-08-21 19:42:01.297 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 45: Node found
2017-08-21 19:42:01.297 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 46: Node found
2017-08-21 19:42:01.298 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 47: Node found
2017-08-21 19:42:01.298 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 48: Node found
2017-08-21 19:42:01.298 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 49: Node found
2017-08-21 19:42:01.299 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 50: Node found
2017-08-21 19:42:01.299 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 51: Node found
2017-08-21 19:42:01.299 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 52: Node found
2017-08-21 19:42:01.299 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 53: Node found
2017-08-21 19:42:01.305 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 54: Node found
2017-08-21 19:42:01.305 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 55: Node found
2017-08-21 19:42:01.306 [INFO ] [age.SerialApiGetInitDataMessageClass] - ZWave Controller using Controller API
2017-08-21 19:42:01.306 [INFO ] [age.SerialApiGetInitDataMessageClass] - ZWave Controller is Primary Controller
2017-08-21 19:42:01.312 [INFO ] [age.SerialApiGetInitDataMessageClass] - ------------Number of Nodes Found Registered to ZWave Controller------------
2017-08-21 19:42:01.317 [INFO ] [age.SerialApiGetInitDataMessageClass] - # Nodes = 50
2017-08-21 19:42:01.318 [INFO ] [age.SerialApiGetInitDataMessageClass] - ----------------------------------------------------------------------------

Error messages (node 59 not even part of network)

2017-08-21 20:13:08.156 [ERROR] [lmessage.RequestNodeInfoMessageClass] - Request node info not placed on stack due to error.
2017-08-21 20:13:08.168 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 51: Sent Data was not placed on stack.
2017-08-21 20:13:08.178 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 51: Sent Data was not placed on stack.
2017-08-21 20:13:08.188 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 51: Sent Data was not placed on stack.
2017-08-21 20:13:15.878 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 49: Sent Data was not placed on stack.
2017-08-21 20:13:22.389 [INFO ] [clipse.smarthome.model.script.Motion] - BedroomMovement.state=OFF
2017-08-21 20:13:22.396 [INFO ] [lipse.smarthome.model.script.Bedroom] - BuildInBedroomRoof.state=0
2017-08-21 20:13:27.189 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 59: Not initialized (ie node unknown), ignoring message.
2017-08-21 20:13:27.861 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 59: Not initialized (ie node unknown), ignoring message.
2017-08-21 20:13:27.877 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 59: Not initialized (ie node unknown), ignoring message.
2017-08-21 20:13:27.930 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 59: Not initialized (ie node unknown), ignoring message.
2017-08-21 20:13:27.994 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 59: Not initialized (ie node unknown), ignoring message.
2017-08-21 20:13:28.207 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 59: Not initialized (ie node unknown), ignoring message.
2017-08-21 20:13:28.231 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 59: Not initialized (ie node unknown), ignoring message.
2017-08-21 20:13:28.241 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 59: Not initialized (ie node unknown), ignoring message.
2017-08-21 20:13:28.282 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 59: Not initialized (ie node unknown), ignoring message.
2017-08-21 20:13:28.327 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 59: Not initialized (ie node unknown), ignoring message.

No big deal, because everything is working fine …

1489

Clearly it’s not :wink: .

These errors come from the stick. They mean that it hasn’t sent a message that the binding wants to send. The binding will retry the message, but it’s going to cause problems if it happens very often.

This means the binding received a message from a node it doesn’t know about. Normally this happens when you reset your controller, and add nodes back again, but one node still hasn’t been reset.

1490

Do you know why I would have trouble entering inclusion mode? Maybe at least 75% of the time when I try to add a device via openhab the controller does not actually enter inclusion mode. I can tell by the toasts that are displayed and the fact that I can’t get my device to include. I’ve resorted to pulling the stick and including manually by the button on the stick.

1491

There might be something to this. I hadn’t updated the binding in a few weeks, but since updating to 2.1.0.201708182242, I’ve had missed events (lights not turning on/off, motion sensors reporting the wrong state, etc.). When I saw the posts by @OMR, I stopped OH, reset my controller, searched my log, and found LOTS of:

2017-08-21 15:01:02.395 [SendDataMessageClass      ] - NODE 41: Sent Data was not placed on stack.
2017-08-21 15:01:02.451 [SendDataMessageClass      ] - NODE 42: Sent Data was not placed on stack.
2017-08-21 15:01:04.167 [SendDataMessageClass      ] - NODE 52: Sent Data was not placed on stack.
2017-08-21 15:01:15.882 [SendDataMessageClass      ] - NODE 73: Sent Data was not placed on stack.
2017-08-21 15:02:01.210 [SendDataMessageClass      ] - NODE 50: Sent Data was not placed on stack.

And there are a lot of CAN messages too, when put into the Log Viewer. I’m going to go back to 2.1.0.201708041056 to see if the same occurs.

1492

Well, these errors mean that the stick did not accept the request. Possibly due to it being busy. Nothing has changed in the serial manager for a long time (couple of months).

These are typically caused by clashes when the stick sends data at the same time the binding does. Again, this hasn’t changed in around 2 months.

1493

Not from where I’m sitting :wink:

So you should have more information then? What messages are you getting?

You can’t include secure devices like this - it simply won’t work.

Please provide a log, or error messages, or something that can help - I’m afraid I lost my crystal ball :wink: .

1494

Is this the serial manager we have to re-install after every upgrade?

feature:install openhab-transport-serial

If not, something could have changed there …

1495

No - it’s part of the zwave binding - the part that manages the serial API. You are right though that the serial drivers might have changed, but I would be surprised if it caused the stick to report these errors.

1496

@chris Would it work for me to securely include a lock with a 3rd party tool (Zensys or OpenZwave) and then add it with OpenHab?

I have no problems bringing in my Kwikset 910, but I have two 914’s. I manged to get one to come in relatively straightforward (wish I can remember exactly what I did to get it to work) but can’t get the 2nd one to come in. So thought I might try a different approach, but thought I’d ask first to save myself unnecessary work if it won’t work.

1497

Yes - this should work. Just make sure the same key is used in both cases.

1498

Thanks. I’ll report back if it works (I noticed I was getting secure inclusion errors popping up in HABmin when trying from OpenHAB so that might be my issue).

Edit: Would a sign that I didn’t get a compete security inclusion be if I send a command to the lock, see the communication light on the lock come on and nothing happens (I’m not seeing any errors in my log, thought I don’t have it in full debug mode)?

1499

I don’t know - what does the device manual say? On my Yale lock, if it doesn’t include securely, it says so (I forget what it says - “failed” or something). I think on the Schlage I have it flashes a red cross.

1500

I’ll look. I did see a popup message in HABmin that looked like it failed.

Edit: This is what I see in HABMin when I try to include these locks:
image

Here’s my log for the lock (node 103).

https://drive.google.com/open?id=0B77VHtwPft8eMTRUYWRKQzNFWkU

1501

From the log, it does look like it’s working - it’s responding to NONCE requests which I don’t think it should if it wasn’t included.

1502

hmmm…it doesn’t actually physically lock / unlock or report back any information?

1503

So, one thing that’s strange - there are multiple commands in the log -:

image
image.png862×960 170 KB

This shows you sent an OFF, and the binding started to send the command to the door - it requested the NONCE. By the time the NONCE was received, and the real command sent there’s another command come in from the UI. Both commands get sent in quick succession - they both appear to have worked although I’m only going on the ACKs and the fact that NONCEs are being received.

1504

Now you are above my paygrade. What are some specific things I can do to try to troubleshoot?

Edit1: So in trying different things, I did grab the xml file for Node 103 by copying it from 101 (I thought that might have been what I did last time to get it to work…) Is there anything in the xml file that would be causing it to think it’s working when it’s not?

I also installed my 2nd lock using OpenZwave and am now trying to get it to include into OpenHAB (so far it shows up in the inbox as a generic node and not generating an xml file or being recognized). Just doing a system restart now.

Edit2: So this didn’t seem to work. I couldn’t get it to generate an xml file. I tried copying over the working file from my 910 (this is a 914 but seems both are using the TRL914) and now it’s in the same place as my other lock where it looks in OpenHAB like it’s working but the locks aren’t physically working.

Would appreciate any suggestions on what to try with either lock to get them online?

1505

Success!!!

I must have had something wrong in my OpenZwave configuration. I switched back to Zensys Tools. Excluded the lock, then using Network Wide Inclusion included the lock back in. Then I moved my zwave stick back to OpenHAB and the lock nodes added with the correct configuration file from the PaperUI (they weren’t showing up in HABmin’s Inbox.

1506

How did you configure the security key in Zensys Tools?

1507

The controller reported back to me in the logs when I first plugged it in it’s security key