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

Odd. The device seems to stay awake (it keeps blinking yellow).

On a second try I’m now getting this: “NODE 6: SECURITY_ERR No valid NONCE! null”

Here’s a full transaction:

2018-01-07 12:20:36.691 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: Application Command Request (ALIVE:REQUEST_NIF)
2018-01-07 12:20:36.691 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 6: Decapsulating COMMAND_CLASS_SECURITY
2018-01-07 12:20:36.691 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 6: COMMAND_CLASS_SECURITY not found in endpoint 0
2018-01-07 12:20:36.692 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 6: Creating new instance of command class COMMAND_CLASS_SECURITY
2018-01-07 12:20:36.692 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 6: Command class COMMAND_CLASS_SECURITY, endpoint 0 created
2018-01-07 12:20:36.692 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 6: Adding COMMAND_CLASS_SECURITY
2018-01-07 12:20:36.693 [DEBUG] [mmandclass.ZWaveSecurityCommandClass] - NODE 6: Updated networkKey
2018-01-07 12:20:36.693 [DEBUG] [mmandclass.ZWaveSecurityCommandClass] - NODE 6: setupNetworkKey useSchemeZero=false
2018-01-07 12:20:36.694 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 6: Adding command class COMMAND_CLASS_SECURITY to the list of supported command classes.
2018-01-07 12:20:36.694 [DEBUG] [mmandclass.ZWaveSecurityCommandClass] - NODE 6: SECURITY_ERR No valid NONCE! null
2018-01-07 12:20:36.694 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-01-07 12:20:36.694 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
2018-01-07 12:20:36.695 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 6: listening == false, frequentlyListening == false, awake == false
2018-01-07 12:20:36.695 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: Node not awake!

A single entry from the log isn’t so useful - security transactions involve multiple packets.

Fair enough, here’s a more full log: https://www.dropbox.com/s/brrhz2yg66rwbl0/selected_logs_2.log?dl=0

My basic understanding of what is happening is that the inclusion succeeds up to REQUEST_NIF, at which point the binding no longer seems to be able to communicate with the node. Any time I manually re-wake the node, that sequence at the end repeats (ending with the NONCE error), and the binding concludes that the node is asleep.

It’s strange if that is the case as the binding should not request a NIF after a device is included.

The earlier log of yours that I looked at the secure inclusion started fine - the device reported back that it was using key-0 and then it stopped responding. I’ll check this log…

In your latest log the device has securely included ok.

After this the interrogation starts - it looks ok and it will take some time. It’s especially slow with security enabled as every request results in two or three transactions due to the security protocol - it’s all working ok though -:

(this is just an example transaction - the rest also look ok).

The nonce errors can happen occasionally, but this is after the inclusion process completes. I see no issue with the REQUEST_NIF that you mentioned - yes, it’s currently at that point, but it looks like you probably restarted the binding, so now the interrogation has to restart from the beginning as it didn’t complete the first time.

Currently it looks ok from this log and secure inclusion worked fine. The device will currently be asleep after the binding restart - try waking it up and see what happens.

Out of curiosity, what is the tool you use to pretty print the logs?

So I switched back to my old adapter (that last one was me testing on my spare Aeotec Z-Stick). I have yet to get the MultiSensor to securely include at all. It always fails and reverts back to non-secure. So this is still the WallMote (NODE 4 in this file). The initial logs look about the same, except this time it doesn’t even pass identifying the device type. At some point it times out and goes to sleep.

This is the sequence I see when I manually wake it up:


(that is all of the messages I see, nothing else gets logged for at least a full minute).

Curious, why use secure inclusion for these devices? I am only using secure inclusion for entry devices, as per something I was reading before, might have been this thread

I want the WallMote to control an entry-control device :slight_smile:

Besides that, this is mostly academic in nature. I will say the Fibaro has passed secure inclusion every time I’ve reset the controller and re-included it. So this has to be some sort of Aeotec idiosyncrasy. I did successfully secure include the Aeotec devices using Indigo on my Mac with the same stick plugged in to it.

The log viewer on my site.

The secure inclusion isn’t in the log so not much I can comment on.

Does your lock allow basic command class - or maybe the wallmote can send a door lock command?

I think that’s unlikely. As I said before, most (if not all all) zwave devices use the same chipset, and the same basic software. Also, as you’ve shown, the wallmote is including fine, and I’ve also used the ZW100 successfully.

I’ll try to do some more testing on a clean setup later in the week and see if I can derive any trends using your log viewer. Thanks for helping me look today.

The lock is non-zwave. It’s a commercial access control system that answers to HTTP requests (over SSL). The argument for secure inclusion being that any device that can send a command that leads to OpenHAB requesting a door unlock must also be secure.

Not related to your issue, but I’m really really curious about that. Actually, I’m curious if anyone with an HUSBZB-1 could do an

egrep -r "Not initialized" *

in their logs folder to see if there are any messages that come from nodes that do not exist. I’m currently trying to document an issue with the firmware where there are messages coming from the stick with incorrectly reported nodes. I’ve actually seen messages come in from nodes that can’t possibly exist (>232), on two different HUSBZB-1s. Like this…

zwave/zwave.log:2018-01-04 15:04:59.937 [WARN ] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 248: Not initialized (ie node unknown), ignoring message.

The messages I was seeing were along the lines of:

2018-01-06 23:26:59.977 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 27: listening == false, frequentlyListening == false, awake == true
2018-01-06 23:26:59.987 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 27: WakeupTimerTask 1 Messages waiting, state EMPTYNODE

I think Node 27 might have once been a legitimate node that I had excluded. I didn’t have debug logging enabled at the time so I’m not 100% certain. I haven’t seen this type of traffic again today.

1 Like

Dear @chris!

I changed to the current version of this binding due to switching from a raspberry to a NUC. I guess I followed most of the “To Dos” (would be good to put them all in the first post)

In addition I deleted several dead nodes as I never had success with habmin (Remove a ghost Z-Wave Node from HABmin).

A few questions/comments (let me know if I should provide logs or anything else):

  • most probably not related to the binding version - but probably related to the inclusion issue: I updated my heat it thermostat and tried to update the database (my FW-Version is higher i think) - got error messages when uploading the XML ("Manufacturer 7FFFFFFF is not known! Please update the manufacturer database and try again) --> see http://www.cd-jackson.com/index.php/zwave/zwave-device-database/zwave-device-list/devicesummary/247
  • I cannot include further devices (trying to include two fibaro flood sensor GEN5) --> Node 57 is the mentioned thermostat above --> could it be, that the incomplete recognition of Node 57 hinders the inclusion of new devices? Please find attached the log here: https://ufile.io/ppdo3

Regards,
Herbert

I have a quite a few, for the same two devices:

openhab.log.7:2018-01-03 16:18:16.514 [WARN ] [nal.protocol.ZWaveTransactionMana                 ger] - NODE 12: Not initialized (ie node unknown), ignoring message.
openhab.log.7:2018-01-03 16:19:06.370 [WARN ] [nal.protocol.ZWaveTransactionMana                 ger] - NODE 13: Not initialized (ie node unknown), ignoring message.
openhab.log.7:2018-01-03 16:19:08.359 [WARN ] [nal.protocol.ZWaveTransactionMana                 ger] - NODE 13: Not initialized (ie node unknown), ignoring message.

Not sure what a HUSBZB-1 is…

This is a test network I was using to try to get this stuff actually working. 12 doesn’t correspond to any actual device in the network. 13 is an Aeotec Minimote that sometimes eventually works, but most of the time never does. 12 may have been related to it.

I did a hard reset on the network since then in an attempt to get secure associations working, so I don’t have any better data. Previously I was able to switch over to Z-way to see what the controller thought a device was when it mysteriously showed up in OH2.

This is quite common if you have old devices that have been excluded from the controller, but not reset. Normally a device will be reset when excluded, and that stops it sending stuff, but if that doesn’t happen, then it’s common that you get this message.

I know that’s not the case for @5iver, but just thought I’d mention that this message can be generated through reasonably normal operation.

This can occur if the interrogation phase doesn’t complete. It’s most common on battery devices where they haven’t been woken up, and the interrogation doesn’t complete - the 7FFFFFF is a default value.

Probably not - the node above is included ok as best as I can tell, and I think if you wake it up, it will likely complete the interrogation and be recognised. This won’t prevent you from including other devices.

From the log we see the controller is rejecting the include command - I’m not sure why as it doesn’t provide useful feedback like that :wink: . I’d suggest to reset the controller to see if that helps - otherwise, maybe there is something strange with the inclusion of node 57, but I would be surprised.

Good luck :wink:

Yeah I figured it was something like that. Although the close proximity to the two is a little weird – I only have that one device it could be (the remote).

I decided to just wait on messing with this again until the dev merge back to the mainline, reset everything again and try from a know good state and see if I can get the binding working this time.

Interesting I Saw This Message for a device that is actually still included and a valid device that Works. I think only on Startup of openhab that warn Message was there. Maybe Communication before the device was read from the Controller… no clue
Just as Information … dont See any negative side effects.

I guess it’s possible that a message received before the binding is initialised will also cause this. The time window is small, but it could certainly happen if the message comes in before the binding gets the list of known nodes from the controller.