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

I’ve asked someone to test something before I commit the changes - this is why there is a small difference. I will commit this as soon as we confirm the following issue is working -:

I have about 65 nodes up, also with Aeon Gen5, and I also see these errors, about 20 of them the last seven hours (I only have logs from midnight until now (0800)). Maybe it is more during the day, when the system is exercised more.
I’ll keep my eye open.

This isn’t an error - it’s a debug message as explained above. I will add a retry of messages that get dropped here - I think that’s all that is needed.

Two samples of a grep since yesterday. They all look the same, but different nodes logging ERROR:

omr@shs2:/var/log/openhab2$ tail -F openhab.log | grep -C 8 ‘not placed on stack’

--
2017-09-13 15:53:26.655 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (1): Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
2017-09-13 15:53:26.655 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 24901: [WAIT_RESPONSE] requiresResponse=false callback: 106
2017-09-13 15:53:26.655 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2017-09-13 15:53:26.656 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=00 
2017-09-13 15:53:26.656 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 24901: [WAIT_RESPONSE] requiresResponse=false callback: 106
2017-09-13 15:53:26.656 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2017-09-13 15:53:26.656 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 24901: [WAIT_RESPONSE] requiresResponse=false callback: 106
2017-09-13 15:53:26.656 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=00 
2017-09-13 15:53:26.656 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 12: Sent Data was not placed on stack.
2017-09-13 15:53:26.656 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 24901: Transaction CANCELLED
2017-09-13 15:53:26.656 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 24901: TransactionAdvance ST: CANCELLED
2017-09-13 15:53:26.656 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 24901: TransactionAdvance WT: ApplicationCommandHandler {}
2017-09-13 15:53:26.656 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 24901: TransactionAdvance RX: Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=00 
2017-09-13 15:53:26.656 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 24901: TransactionAdvance TO: CANCELLED
2017-09-13 15:53:26.657 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2017-09-13 15:53:26.657 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2017-09-13 15:53:26.657 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: TID 24901: Transaction completed
--
2017-09-13 15:53:26.663 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
2017-09-13 15:53:26.664 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 24903: [WAIT_RESPONSE] requiresResponse=false callback: 104
2017-09-13 15:53:26.664 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2017-09-13 15:53:26.664 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=00 
2017-09-13 15:53:26.664 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 24903: [WAIT_RESPONSE] requiresResponse=false callback: 104
2017-09-13 15:53:26.664 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2017-09-13 15:53:26.664 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 24903: [WAIT_RESPONSE] requiresResponse=false callback: 104
2017-09-13 15:53:26.664 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=00 
2017-09-13 15:53:26.664 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 12: Sent Data was not placed on stack.
2017-09-13 15:53:26.664 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 24903: Transaction CANCELLED
2017-09-13 15:53:26.665 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 24903: TransactionAdvance ST: CANCELLED
2017-09-13 15:53:26.665 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 24903: TransactionAdvance WT: ApplicationCommandHandler {}
2017-09-13 15:53:26.665 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 24903: TransactionAdvance RX: Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=00 
2017-09-13 15:53:26.665 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 24903: TransactionAdvance TO: CANCELLED
2017-09-13 15:53:26.665 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2017-09-13 15:53:26.665 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2017-09-13 15:53:26.665 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: TID 24903: Transaction completed

Tell me if a wider context than 8 is interesting .

Hmmm - for some reason this got changed to ERROR - not sure why I did that as in the old binding it’s definitely DEBUG… Actually, it was probably ERROR in master and I changed it there to DEBUG, but forgot to change it in the dev version…

Anyway - the point is still the same. It’s not really an error, and it should be retried if it fails.

@chris, has there been any progress toward the secure inclusion issue on some devices? I haven’t been able to add my BE469 yet due to this issue. If not, what is the suggested workaround, to nuke my entire setup and start over?

What are you using for Zwave? I have the Aeotec stick and was able to use zensys tools to include a device and then add it in to OpenHAB for one that was giving me issues

@rgerrans: I use a Aeotec Z-Stick Gen5. Can you explain how you did this? I imagine you’d somehow have to transfer the secure key?

Here you go:

Another option is OpenZwave (included with Domoticz). Just configure it with the same key used in OH.

1 Like

I tried with zensys tools, I don’t see how this is possible as I don’t see a way to enter the network security key. I’ll try 5iver’s option next. Please in the mean time let me know if I’m missing how youd duplicate the key into zensys tools?

I did it the other way and copied the key from zensys to OH

Yea, that means I’d have to reset everything. Back to square one. :slight_smile:

I don’t remember that being an issue but I may have gotten my orginal key before I started my locks. I’d go with @5iver’s approach of OpenZwave then since you can copy your key from OH.

From what I read zensys tools doesn’t allow you to set a key, but it does expose the key so you could copy it over to open hab. So the way you did it is the only way that would work.

With domoticz I tried to remove and then secure include the lock. Everything seemed to work but alas openhab shows secure=false. :frowning: I’m not sure how you pulled this off @5iver? I added the openzwave usb hardware on com3, went into setup and set the network security key identically to openhab. Then secure included. Did I miss something?

Everything you did looks OK to me. If you select the controller in Domiticz, does it show the actual Security Network Key as the key you entered? You have a BE469, so did it give you a green checkmark after inclusion? I don’t recall if I did this when I paired through Domoticz, but I know at times I had to completely reset the lock to get it to work. Were all your devices, including the lock, showing up in Domoticz and did the lock show up as using security? If that was all good, and you used the same key, then it may take a few resets in OH for the security checks to pass. I think I was reinitializing, but I may have deleted and rediscovered.

I did it a second time, exactly the same way and it appears to be semi-working. Thanks, will be a headache for sure until the binding supports this properly.

If you’re asking the question, then I assume not :wink: . I’ve tried a number of things, but if it’s not working, then there’s the answer… I’ve checked what I’m doing against the Sigma code and it looks fundamentally the same from the quick check I did.

This is an area that needs to be resolved, but at the moment I’m looking at a bit of binding restructuring to allow adding a load of new features.

Oh, new features? Like what?

Could you also give us some expectations / guestimates on the long term future of this testing version? I mean … could this make it into openhab 2.2 eventually? Or do you expect the test version to remain with its parallel life for several versions / years … ?

Thanks for everything!

Mostly maintenance, backup, heal, routing information, link quality related functions at the moment.

I’m trying to avoid making multiple sets of breaking changes that require people to re-install their system. My plan had been to merge this into 2.2, but given I want to do a bit more restructuring to incorporate some other features, it’s probably better to make it 2.3. (that’s my thinking at the moment anyway).

It might be ok for people who are active on the forum if the binding completely changes, but there are a LOT of people using OH that aren’t active here, and breaking their systems isn’t really something I want to do (too often anyway :wink: ).

1 Like