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

Chri46 · May 30, 2017, 10:58am

Did not remove the things…
With “all things” you refer to the zwave things only.

chris · May 30, 2017, 11:04am

Yes.

Chri46 · May 30, 2017, 11:11am

and working
thanks

bogdanp · May 30, 2017, 2:49pm

@chris
Is the 2.1.0 snapshot using the same database as the one we are able to edit on cd-jackson website? I don’t find the added channel for the ZMNHVD Flush Dimmer 0-10V from qubino …

chris · May 30, 2017, 2:57pm

Yes - the database is the same - it might be slightly different given that updates are made to the different versions at different times so the most recent version of each will include the most recent updates. Fundamentally though, they are the same.

5iver · June 1, 2017, 8:29am

I am experiencing a binding crash (everything else works fine, but nothing zwave responds) every few days (2.1.0-SNAPSHOT Build #908, ZWave Binding 2.1.0.201705281057). This has been occurring with all OH2 and test zwave builds I’ve tried over the last 6 months, so nothing newly introduced. These are from the Karaf console. The first error repeats several times (probably another issue), but the last one is always associated with a zwave binding (maybe serial?) crash:

java.lang.reflect.InvocationTargetException
        at sun.reflect.GeneratedMethodAccessor62.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveCommandClass.handleApplicationCommandRequest(ZWaveCommandClass.java:245)
        at org.openhab.binding.zwave.internal.protocol.ZWaveNode.processCommand(ZWaveNode.java:1284)
        at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager$ZWaveReceiveThread.run(ZWaveTransactionManager.java:413)
Caused by: java.lang.NullPointerException
        at org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveAlarmCommandClass.handleNotificationReport(ZWaveAlarmCommandClass.java:140)
        ... 6 more
Exception in thread "Thread-43" java.lang.ArrayIndexOutOfBoundsException: 0
        at org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload.getCommandClassId(ZWaveCommandClassPayload.java:38)
        at org.openhab.binding.zwave.internal.protocol.ZWaveNode.processCommand(ZWaveNode.java:1243)
        at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager$ZWaveReceiveThread.run(ZWaveTransactionManager.java:413)

I have 3 Aeon HEMs (G1) that report every 10s, and have a rule to alert if they don’t report in 3 minutes:

2017-06-01 00:33:20.599 [Rules                     ] - Alert: SMS notification sent [Warning! Zwave may no longer be responding]

Correlating the time to the zwave log file, there is an error received around the time zwave reportedly stopped responding (I’ll email you a section of the file):

2017-06-01 00:30:11.810 [Handler$ZWaveReceiveThread] - Exception during ZWave thread. 
java.lang.IllegalStateException: Queue full
	at java.util.AbstractQueue.add(AbstractQueue.java:98)[:1.8.0_131]
	at java.util.concurrent.ArrayBlockingQueue.add(ArrayBlockingQueue.java:312)[:1.8.0_131]
	at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.processReceiveMessage(ZWaveTransactionManager.java:345)[9:org.openhab.binding.zwave:2.1.0.201705281057]
	at org.openhab.binding.zwave.internal.protocol.ZWaveController.incomingPacket(ZWaveController.java:1216)[9:org.openhab.binding.zwave:2.1.0.201705281057]
	at org.openhab.binding.zwave.handler.ZWaveControllerHandler.incomingMessage(ZWaveControllerHandler.java:636)[9:org.openhab.binding.zwave:2.1.0.201705281057]
	at org.openhab.binding.zwave.handler.ZWaveSerialHandler$ZWaveReceiveThread.run(ZWaveSerialHandler.java:320)[9:org.openhab.binding.zwave:2.1.0.201705281057]

Stopping serial and zwave, then restarting the bindings restores functionality. Sometimes for hours, sometimes for days (always less than a week). With previous versions of the binding (haven’t tested this recently), removing the HEM items prevented the crash. Please let me know if there are any more details needed to troubleshoot!

chris · June 1, 2017, 9:23am

Please can you provide a debug log around the time that the event happens so we can capture the message causing the problem.

Also, please format logs with the </> button so they are easier to read .

5iver · June 1, 2017, 2:09pm

The formatting was giving me grief! I fiddled with it last night but couldn’t make it look right… a blank line before the preformatted text did the job .

I have some secure devices, so I had emailed the debug logs to you with a link to my post.

sockmeister · June 2, 2017, 3:47am

Hey all. Figured I’d add to the discussion since I didn’t see a similar question already above.

I’ve got the Kwikset door lock in my setup. Everything was working perfectly – that is, until I grabbed the latest build (27 May 2017). After installing, I can lock / unlock the door as normal via Z-Wave, BUT – manual lock/unlock events are not captured, and some investigation showed that it looks like openhab is not getting ANY alarm messages from the door anymore.
Some Z-Wave transaction takes place when the door is locked or unlocked, but no alarm message is passed to my alarm number item as it used to.

I’ve captured the event in the debug log to see if it offers any hints – I can’t quite make sense of what’s going on. Any advice?

23:24:24.818 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 
23:24:24.837 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
23:24:24.852 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=6, callback=0, payload=
23:24:24.866 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=6, callback=0, payload=
23:24:24.881 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=6, callback=0, payload=
23:24:24.892 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
23:24:24.905 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: Application Command Request (ALIVE:DYNAMIC_VALUES)
23:24:24.913 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 6: Incoming command class COMMAND_CLASS_SECURITY, endpoint 0
23:24:24.925 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 6: SECURITY check internal
23:24:24.939 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 6: Received COMMAND_CLASS_SECURITY V1 SECURITY_NONCE_GET
23:24:24.947 [DEBUG] [andclass.impl.CommandClassSecurityV1] - Creating command message SECURITY_NONCE_REPORT version 1
23:24:24.960 [DEBUG] [ommandClassTransactionPayloadBuilder] - At build null
23:24:24.967 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: Added to secure queue - size 1
23:24:24.976 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: Commands processed 1.
23:24:24.988 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@134b45c.
23:24:24.996 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
23:24:25.016 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
23:24:25.023 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
23:24:25.059 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
23:24:25.068 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from secureQueue
23:24:25.085 [DEBUG] [nal.protocol.ZWaveTransactionManager] - getTransactionToSend 6
23:24:25.095 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 
23:24:25.126 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 6: Sending REQUEST Message =
23:24:25.152 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
23:24:25.153 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
23:24:25.166 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 6310: Transaction Start type SendData
23:24:25.181 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
23:24:25.190 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 6310: [WAIT_RESPONSE] requiresResponse=true callback: 79
23:24:25.195 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null
23:24:25.202 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
23:24:25.213 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: 0
23:24:25.222 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
23:24:25.248 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Thu Jun 01 23:24:27 EDT 2017 - 1999ms
23:24:25.243 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 
23:24:25.266 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 6310: [WAIT_RESPONSE] requiresResponse=true callback: 79
23:24:25.272 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
23:24:25.288 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Thu Jun 01 23:24:27 EDT 2017 - 1959ms
23:24:25.292 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
23:24:25.297 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01
23:24:25.305 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
23:24:25.314 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 6310: [WAIT_RESPONSE] requiresResponse=true callback: 79
23:24:25.321 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01
23:24:25.337 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
23:24:25.362 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01
23:24:25.379 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 
23:24:25.382 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 6310: [WAIT_RESPONSE] requiresResponse=true callback: 79
23:24:25.389 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
23:24:25.413 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 6310: [WAIT_RESPONSE] requiresResponse=true callback: 79
23:24:25.436 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
23:24:25.442 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01
23:24:25.461 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=SendData[0x13], type=Request[0x00], dest=0, callback=79, payload=
23:24:25.474 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 6: Sent Data successfully placed on stack.
23:24:25.516 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 6310: TransactionAdvance ST: WAIT_RESPONSE
23:24:25.512 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=SendData[0x13], type=Request[0x00], dest=0, callback=79, payload=
23:24:25.543 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 6310: TransactionAdvance WT: null {}
23:24:25.584 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 6310: TransactionAdvance RX: Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01
23:24:25.593 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 6310: TransactionAdvance TO: WAIT_REQUEST
23:24:25.634 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 6310: Advanced to WAIT_REQUEST
23:24:25.648 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: TID 6310: Transaction not completed
23:24:25.607 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 
23:24:25.682 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg Message: class=SendData[0x13], type=Request[0x00], dest=0, callback=79, payload=
23:24:25.730 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 6310: [WAIT_REQUEST] requiresResponse=true callback: 79
23:24:25.761 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
23:24:25.772 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 6310: [WAIT_REQUEST] requiresResponse=true callback: 79
23:24:25.794 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 6310: (Callback 79)
23:24:25.813 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
23:24:25.834 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 6310: callback 79
23:24:25.839 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
23:24:25.859 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[0x13], type=Request[0x00], dest=0, callback=79, payload=
23:24:25.877 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 6: SendData Request. CallBack ID = 79, Status = Transmission complete and ACK received(0)
23:24:25.891 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 6310: Transaction COMPLETED
23:24:25.882 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=6, callback=0, payload=
23:24:25.905 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 6310: TransactionAdvance ST: DONE
23:24:25.934 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 6310: TransactionAdvance WT: null {}
23:24:25.950 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 6310: TransactionAdvance RX: Message: class=SendData[0x13], type=Request[0x00], dest=0, callback=79, payload=4F 00 00 06
23:24:25.952 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=6, callback=0, payload=
23:24:25.961 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 6310: TransactionAdvance TO: DONE
23:24:25.980 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: Response processed after 815ms
23:24:25.985 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: TID 6310: Transaction completed
23:24:25.992 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: notifyTransactionResponse TID:6310 DONE
23:24:26.011 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
23:24:26.017 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
23:24:26.059 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=6, callback=0, payload=
23:24:26.099 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
23:24:26.110 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: Application Command Request (ALIVE:DYNAMIC_VALUES)
23:24:26.116 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 6: Decapsulating COMMAND_CLASS_SECURITY
23:24:26.143 [DEBUG] [mmandclass.ZWaveSecurityCommandClass] - NODE 6: SECURITY_RXD 
23:24:26.159 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 6: Incoming command class COMMAND_CLASS_ALARM, endpoint 0
23:24:26.166 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 6: Received COMMAND_CLASS_ALARM V1 NOTIFICATION_REPORT
23:24:26.195 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: Commands processed 1.
23:24:26.222 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@f2d34c.
23:24:26.236 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0

chris · June 2, 2017, 6:23am

There is an alarm message received in this log - I don’t see anything wrong, but I don’t really have any context of what was going on so it’s hard to say other than alarms are being transferred.

Very little has changed in the latest build - just database updates I think.

5iver · June 2, 2017, 7:07am

This was another issue I planned to report! I am also experiencing a recent (last build or two, 5/13 was when it started per my persistence db but not sure which zwave build that was) issue where locks (alarm_number) events are no longer reporting. I have BE469s. I can provide logs, if needed.

chris · June 2, 2017, 7:21am

What was the previous version you had? There have been no updates to the code for 1 month so I don’t know why it should change…

5iver · June 2, 2017, 7:56am

Sorry to have not kept better records, but what I have show it stopped working on 5/13 (I stopped taking notes and logging builds on 4/23, darn it). IIRC, at least the previous version had the same issue. I try to monitor this thread for updates almost daily and install new builds whenever available, but have been out of town for a few weeks too. But noted this stopped working before I had left.

I’ve been hoping we would get out of test mode soon so that we could better see the issues submitted/resolved and commits. Wish I could do more to track it down, but think this is the best I can do with the info available to me.

chris · June 2, 2017, 8:00am

Hmmm - ok, so that must mean it only worked for one or two weeks - strange. I’ll check this tonight, but as far as I know the tests are working still .

There is nothing to stop people raising issues or checking the commits now.

5iver · June 2, 2017, 8:13am

O… I’ve been away for a bit and nothing has changed in our environment except zwave binding updtaes. Did you merge into the development branch? https://github.com/openhab/org.openhab.binding.zwave/tree/development

Thought this was still just ‘test’ that you’ve been tracking on your website. If so, glad to see this is moving forward!

chris · June 2, 2017, 8:15am

Yes - it’s been the development branch for a long time (ie always since this development has been ongoing). The binary distribution is still through my website though as there’s no other option, but source etc is always on github.

5iver · June 2, 2017, 8:33am

Excellent! I’d seen some issues reported there (not recently) but hadn’t seen the merge mentioned in this (ginormous) thread. Now I know where I can get the latest! So, the updates I’ve been getting were from this thread. There was one from 5/17ish (applied it while out of town) but the alarm_number issue was occurring before that one. Hopefully that helps to track it down.

chris · June 2, 2017, 9:01am

I’m not really sure what merge you’re talking about - there isn’t any merge . What are you actually looking for?

The JARs are on my website and posted here if that’s what you mean by the updates?

Maybe there’s some confusion (at least I’m confused about your questions now ) so I’ll try and clarify…

There is no “merge” - the source has always been in the development branch on github since well before this discussion started on the forum as other people were testing it before I released it was presented here.

The JAR has always only been distributed through a link on my website and is built manually by me when I make changes to the development branch. It was decided not to set up a CI for this as it was too much effort for a development branch. There are two ways install do this JAR - either through the marketplace, or manually as explained at the top of this thread. Both ways link to the same link on my website.

For issues, either people can report them here and I try and cover them, or there’s the github tracker and if they relate to the development branch, then I mark them with [dev] in the title.

I hope that clarifies how this is managed - if it doesn’t explain things then please can you explain your point about merges and I’ll try and clarify.

5iver · June 2, 2017, 10:12am

That clarifies quite a bit! I had been under the impression (incorrectly) that you were managing the source of a ‘test’ branch on your own and that it would eventually be merged into the development branch. But I am happy to learn that it has always been in the development branch and that I/we can track issues/commits through it. I was most confused by the issue tracking you were doing through your site. I’ve also been confused about how your builds and the development branch were related. I think I’ve now got it all pieced together! Thank you. And thank you for all your effort on this binding (and all the other pieces of OH that you contribute to).

chris · June 2, 2017, 10:23am

Good point…

This was a tracker I added mainly to allow me to manage logfiles (although people are using it for more than this unfortunately). I wanted a way for people to send me logfiles other than through email which is hard for me to track (I get a lot of emails and it’s really hard to keep track logs sent like this). I don’t want to ask people to put logs with secure information on github or on the forum and find someone is using them to break into peoples systems ;).