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

[sloth0815 (Jonas Böhringer)]

Strange, I set logging to DEBUG, did another reboot and now the binding is active. Thanks!

[chris (Chris Jackson)]

@sloth0815

I set logging to DEBUG, did another reboot and now the binding is active.

My guess is it is unrelated…

[rgerrans]

@shawnmix

Sent Data was not placed on stack

@shawnmix Did your errors ever clear up or are you still seeing them. I’ve been getting them for a while as well and seem to be seeing them more and more lately. Given @chris response

@chris

This is an error from the controller itself - a debug log will help, but I think the binding should retry the message.

I’m wondering if I just need to reset my controller or if it’s another issue.

[shawnmix]

@rgerrans - to be honest, I haven’t checked lately. I haven’t done much lately with my OH2 instance, I’ve been working on some other more pressing life matters. But I hope to get back to doing some more with this as I have a second lock I need to get included, and I don’t want to reset my stick to do so.

That said, when I was seeing those errors, they honestly were only a few here and there at times. I think honestly the stick probably over time starts to just get a bit “buggy” and may show more of those errors. Most of the time though, it’s during high traffic periods where a bunch of stuff is happening. Devices being turned on/off, scenes running sending more commands, etc. But I haven’t seen it become an actual issue in function.

Everything for me has been pretty rock solid for awhile, so I would say you could dig in if you’re seeing constant errors of this type. But a few every hour isn’t concerning to me as long as everything still functions properly.

[rgerrans]

Thanks @shawnmix. For me I see the errors quite a bit but do see occasional glitches so now that I have my core system stable trying to knock out the few issues that are showing up.

[OMR (Ole Morten Rønning)]

@shawnmix

That said, when I was seeing those errors, they honestly were only a few here and there at times. I think honestly the stick probably over time starts to just get a bit “buggy” and may show more of those errors. Most of the time though, it’s during high traffic periods where a bunch of stuff is happening. Devices being turned on/off, scenes running sending more commands, etc. But I haven’t seen it become an actual issue in function.

My gut feeling is that my system starting logging these errors when my number of nodes turned grater than ~45 (currently 53)
My openhap.log goes back to 15.08 and there has been quite a few:

omr@shs2:/var/log/openhab2$ egrep -c 'not placed on stack' openhab.log
4704

It could also be that the issue was caused by an upgrade, but the issue sort of snuck up on me as everything is working OK despite of these log entries.
I tried @chris’s advice to un/re-plug the Z-Wave stick (Aeon 5.gen), but that did not help.

[shawnmix]

That might be a valid observation. I think I have around 35 or so actual ZWave devices reporting in. More in OH of course from other bindings, but actual nodes is safely around 35-40 which could be the tipping point as you indicated. I’m close to that lower number, and I don’t see those as often. You’re getting higher and seeing more. It could simply just be a matter of how quick the device can really react to the current transmissions on the wire at the time.

One suggestion I’d give, is to make sure you let the system settle first. If you restart the system, you’re likely to see more of this if it is indeed from activity. Once it’s settled for about an hour, you should be in a steady state. Maybe check on the frequency of reports setup for the devices as well? Perhaps you’ve tuned it a bit high and in return tuned up the frequency of communication from the devices.

[chris (Chris Jackson)]

Fundamentally, this means that the transmitter queue is full in the stick, so it possibly means that there’s too many things happening on the network and the controller is busy. I don’t think the binding retries commands that are rejected in this way, so this should be added and I’ll take a look at doing this.

[sihui]

@chris

The latest version of the test binding dated 29th August 2017 is

@chris, I have a PR for you:

The latest version of the test binding dated 11th September 2017 is

diff:
- 29th August
+ 11th September

[chris (Chris Jackson)]

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 -:

Z-Wave security testing ZW100 and MT02648

There was a bug processing multiple encapsulations. Please try the latest version and see if it’s any better.

[vespaman (Micael)]

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.

[chris (Chris Jackson)]

@vespaman

I also see these errors

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.

[OMR (Ole Morten Rønning)]

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 .

[chris (Chris Jackson)]

@OMR

logging ERROR:

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.

[shadowmite (Matthew Fogle)]

@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?

[rgerrans]

@shadowmite

If not, what is the suggested workaround,

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

[shadowmite (Matthew Fogle)]

@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?

[rgerrans]

@shadowmite

Can you explain how you did this?

Here you go:

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

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.

[5iver (Scott Rushworth)]

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

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

I haven’t had to do a secure inclusion for a while. When I was setting up my secure devices, I tried everything over and over without any success. I had even put OH on my laptop so that I could walk around with my zstick attached (same security settings) and pair my locks without taking them off the door and garage openers off the ceiling. Nothing worked, literally, for weeks. I was very frustrated, so I finally setup Domoticz (uses OpenZwave) on my laptop and BAM had three locks paired on their…

[shadowmite (Matthew Fogle)]

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?