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

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

[rgerrans]

@shadowmite

how youd duplicate the key into zensys tools?

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

[shadowmite (Matthew Fogle)]

@rgerrans

@shadowmite

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.

[rgerrans]

@shadowmite

Yea, that means I’d have to reset everything

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.

[shadowmite (Matthew Fogle)]

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