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

paulfaure · February 27, 2018, 10:47pm

In case you want to know about my ZStick due to this:
2018-02-27 17:33:06.080 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - NO callback match! (52 <> 1)

T: Bus=02 Lev=01 Prnt=01 Port=00 Cnt=01 Dev#= 3 Spd=12 MxCh= 0
D: Ver= 1.10 Cls=00(>ifc ) Sub=00 Prot=00 MxPS=64 #Cfgs= 1
P: Vendor=10c4 ProdID=ea60 Rev=01.00
S: Manufacturer=Silicon Labs
S: Product=CP2102 USB to UART Bridge Controller
S: SerialNumber=0001
C: #Ifs= 1 Cfg#= 1 Atr=80 MxPwr=100mA
I: If#= 0 Alt= 0 #EPs= 2 Cls=ff(vend.) Sub=00 Prot=00 Driver=cp210x

stratt · February 28, 2018, 1:25am

Thanks, Chris

finahmenal · February 28, 2018, 5:38am

Having a hard time getting my secure node (Kwikset 912) to work with my secondary controller. Can secure nodes be controlled by secondary controllers?

chris · February 28, 2018, 9:38am

This message is perfectly normal. It’s nothing to do with the stick and is just a debug message from the transaction processor.

I’ll take a look at the log…

chris · February 28, 2018, 9:39am

Probably not - I don’t know what controller you’re talking about - if you’ve transferred the key to the other controller, then it should be possible, but if the controller is a keyfob or something similar, then no, it won’t work.

chris · February 28, 2018, 9:43am

In this log, as you said the controller is responding with an error and isn’t going in to inclusion mode. I’m not sure why this would happen.

I’ll see if I can find out what might cause this, but from memory the ZWave docs don’t provide any information about possible causes.

finahmenal · February 28, 2018, 3:23pm

I have a Honeywell Tuxedo touch, OH 2.2 on RaspberryPi with your Z-wave binding 2.3 (Feb 25) and Aeon Gen 5 Z Stick. Honeywell works well controlling other non secure nodes. I doubt ill be able to change the Key on the Tuxedo. Honeywell seems to lock the unit down pretty well. Can I try to change the key to in OH2 to match what the tuxedo has? Of course i would have to look to see if i can find the Key in the tuxedo.

Also interesting note when I sync the devices on the tuxedo by making it a secondary and manually hitting the inclusion button on the aeon stick it adds in the “static controller” Node and I can see it on the network and in Things. However, if I do the inclusion process via OH2 the devices sync to the Tuxedo, but I get a “Node not found in Z-Wave network”. Only reason I thought syncing it from OH2 was maybe during the process of sending devices to the secondary controller, maybe it passes the Key as well…If thats not the case then it wont matter much to debug this.

hl_at · February 28, 2018, 6:49pm

Dear @chris

I also recognize the behaviour mentioned here ZWave device association/physical switches not registering

Regards,
Herbert

5iver · February 28, 2018, 7:10pm

I occasionally see the same behavior. Clearing and resetting the association didn’t help. But deleting the Thing and rediscovering resolves it for me. I find it best to delete all Things and rediscover after each binding update. I have a rule for this and will create a post to share it. Saves a lot of time if you have more than a couple devices. But still a huge PITA to have to change 30+ temperature scales from Celsius to Fahrenheit. I know it can be done in the rule, but haven’t quite figured it out yet. Sure wish there was a default setting for that…

romain · February 28, 2018, 10:26pm

No more hints for me @chris, provided the new logs after deleting the xml ?

Regards

Romain

paulfaure · February 28, 2018, 11:29pm

Here are some clean logs from a fresh start of OH:
http://www.faure.ca/~paul/openhab.clean.start.log
Hope it helps.

FYI, I seemed to have an old 2.1 version of the other bindings. I have not updated them to the latest 2.2 and refreshed the log above.

I now see these message in the logs:

2018-02-28 19:02:03.932 [WARN ] [ig.xml.osgi.XmlDocumentBundleTracker] - The XML document '/ESH-INF/binding/binding.xml' in module 'org.openhab.binding.zwave' could not         be parsed: The XmlConfigDescriptionProvider must not be null!
java.lang.IllegalArgumentException: The XmlConfigDescriptionProvider must not be null!
        at org.eclipse.smarthome.core.binding.xml.internal.BindingInfoXmlProvider.<init>(BindingInfoXmlProvider.java:60) [112:org.eclipse.smarthome.core.binding.xml:0.1        0.0.b1]
        at org.eclipse.smarthome.core.binding.xml.internal.XmlBindingInfoProvider.createDocumentProvider(XmlBindingInfoProvider.java:141) [112:org.eclipse.smarthome.cor        e.binding.xml:0.10.0.b1]
        at org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker.acquireXmlDocumentProvider(XmlDocumentBundleTracker.java:181) [108:org.eclipse.smarthome.confi        g.xml:0.10.0.b1]
        at org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker.addingObject(XmlDocumentBundleTracker.java:206) [108:org.eclipse.smarthome.config.xml:0.10.0.b        1]
        at org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker.parseDocuments(XmlDocumentBundleTracker.java:350) [108:org.eclipse.smarthome.config.xml:0.10.0        .b1]
        at org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker.processBundle(XmlDocumentBundleTracker.java:336) [108:org.eclipse.smarthome.config.xml:0.10.0.        b1]
        at org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker.access$3(XmlDocumentBundleTracker.java:331) [108:org.eclipse.smarthome.config.xml:0.10.0.b1]
        at org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker$2.run(XmlDocumentBundleTracker.java:307) [108:org.eclipse.smarthome.config.xml:0.10.0.b1]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
        at java.lang.Thread.run(Thread.java:748) [?:?]

2018-02-28 19:02:26.023 [ERROR] [ding.zwave.handler.ZWaveThingHandler] - NodeID is not set in zwave:device:cont:node5
2018-02-28 19:02:26.023 [ERROR] [ding.zwave.handler.ZWaveThingHandler] - NodeID is not set in zwave:device:cont:node3
2018-02-28 19:02:26.024 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:cont:node8.
2018-02-28 19:02:26.026 [ERROR] [ding.zwave.handler.ZWaveThingHandler] - NodeID is not set in zwave:device:cont:node8
2018-02-28 19:02:26.026 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:cont:node6.
2018-02-28 19:02:26.026 [ERROR] [ding.zwave.handler.ZWaveThingHandler] - NodeID is not set in zwave:device:cont:node6
2018-02-28 19:02:26.028 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:cont:node4.
2018-02-28 19:02:26.031 [ERROR] [ding.zwave.handler.ZWaveThingHandler] - NodeID is not set in zwave:device:cont:node4


2018-02-28 19:02:31.679 [ERROR] [.serialmessage.EnableSucMessageClass] - Unable to disable a running SUC!

paulfaure · February 28, 2018, 11:36pm

FYI, this version worked for inclusion: 2.3.0.201802081624
It didn’t error out and the door lock got included successfully. But controlling the device didn’t work at all.

I am now running: 2.3.0.201802082157

chris · March 1, 2018, 7:41am

I’m not sure what is causing this - it seems to indicate something wrong with the runtime. Also, are you configuring your things through text files or the UI? Some people seem to have problems configuring through text files recently - I don’t think it’s a binding issue, but it’s what normally causes the NodeID not set error. If you use the UI, this really should not happen.

chris · March 1, 2018, 7:46am

Can you provide a log when it doesn’t work?

5iver · March 1, 2018, 8:49am

I added the log to an existing ticket on your website for the same issue.

romain · March 1, 2018, 7:58pm

Finally, after a lot of trials, reboots, resets, reinclude, re-awake… it works !

I do not really understand what finally made the things up.

Thank you for your help.

Regards,

Romain

paulfaure · March 1, 2018, 10:57pm

I am using the UI to configure my things. Could never get the text files to
work.

paulfaure · March 2, 2018, 2:23am

Hi @chris
Sorry for the all the messages. I installed a fresh copy of OH 2.3 snapshot, enabled only your latest zwave binding and tested the inclusion. This is the result:
http://www.faure.ca/~paul/openhab.mar1.log

Inclusion doesn’t error out right away, but I still can’t add my lock.

paulfaure · March 2, 2018, 3:45am

When I downgraded to a fresh 2.2.0 stable with no other binding or configuration other than zwave, i got the immediate error upon starting zwave inclusion.

chris · March 2, 2018, 7:42am

Yes, unfortunately the stick is returning an error immediately when put into inclusion.

While the logs don’t show any other activity, I’m a little suspicious that you are doing this too quickly after starting the binding. While it should (probably) work, there’s often a lot of activity after startup and this might have an impact. Maybe I’m wrong about this and you’re not doing it at startup, but I see the thing types being set, and this normally only happens immediately after start.