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

Can you provide the log showing this please (just this command, and a little before it will be fine) and I’ll have a look…

I got this error when the binding is stopped:

2018-08-22 11:57:54.589 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Stopped ZWave serial handler
2018-08-22 11:57:54.606 [ERROR] [nal.common.AbstractInvocationHandler] - An error occurred while calling method 'ThingHandler.dispose()' on 'org.openhab.binding.zwave.handler.ZWaveSerialHandler@1e3badc': null
java.lang.IllegalMonitorStateException: null
        at java.lang.Object.notify(Native Method) ~[?:?]
        at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.shutdown(ZWaveTransactionManager.java:207) [218:org.openhab.binding.zwave:2.4.0.201808200952]
        at org.openhab.binding.zwave.internal.protocol.ZWaveController.shutdown(ZWaveController.java:118) [218:org.openhab.binding.zwave:2.4.0.201808200952]
        at org.openhab.binding.zwave.handler.ZWaveControllerHandler.dispose(ZWaveControllerHandler.java:247) [218:org.openhab.binding.zwave:2.4.0.201808200952]
        at org.openhab.binding.zwave.handler.ZWaveSerialHandler.dispose(ZWaveSerialHandler.java:133) [218:org.openhab.binding.zwave:2.4.0.201808200952]
        at sun.reflect.GeneratedMethodAccessor116.invoke(Unknown Source) ~[?:?]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
        at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
        at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:153) [94:org.eclipse.smarthome.core:0.10.0.201808211930]
        at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [94:org.eclipse.smarthome.core:0.10.0.201808211930]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:?]
        at java.lang.Thread.run(Thread.java:745) [?:?]
2018-08-22 11:57:54.633 [ERROR] [ome.core.thing.internal.ThingManager] - Exception occurred while disposing handler of thing 'zwave:serial_zstick:controller': null
java.lang.IllegalMonitorStateException: null
        at java.lang.Object.notify(Native Method) ~[?:?]
        at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.shutdown(ZWaveTransactionManager.java:207) [218:org.openhab.binding.zwave:2.4.0.201808200952]
        at org.openhab.binding.zwave.internal.protocol.ZWaveController.shutdown(ZWaveController.java:118) [218:org.openhab.binding.zwave:2.4.0.201808200952]
        at org.openhab.binding.zwave.handler.ZWaveControllerHandler.dispose(ZWaveControllerHandler.java:247) [218:org.openhab.binding.zwave:2.4.0.201808200952]
        at org.openhab.binding.zwave.handler.ZWaveSerialHandler.dispose(ZWaveSerialHandler.java:133) [218:org.openhab.binding.zwave:2.4.0.201808200952]
        at sun.reflect.GeneratedMethodAccessor116.invoke(Unknown Source) ~[?:?]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
        at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
        at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:153) [94:org.eclipse.smarthome.core:0.10.0.201808211930]
        at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [94:org.eclipse.smarthome.core:0.10.0.201808211930]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:?]
        at java.lang.Thread.run(Thread.java:745) [?:?]

I get the exact same since about a week back. Just haven’t got around to reporting it :blush:

To be more precise, the first time I got it was 2018-08-15. That day I upgraded the binding from an old (months back) version though, so this could have been introduced quite some time before that.

One thing I notice is that both me and @Lolodomo are on Z-sticks, don’t know if that’s relevant?

I stood on a ladder last night for an hour excluding and reincluding an NGD00Z that had “lost” it’s secure inclusion. Hold offs were not always involved, but it’s looking like the failure was always the same:

2018-08-21 21:50:48.820 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Holdoff Timer started...
2018-08-21 21:50:48.821 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Holdoff Timer finishing in 250ms
2018-08-21 21:50:48.821 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 129: Retry count exceeded. Discarding message: TID 1260: [CANCELLED] priority=Immediate, requiresResponse=true, callback: 29
2018-08-21 21:50:48.821 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 129: TID 1260: Transaction completed
2018-08-21 21:50:48.821 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 129: notifyTransactionResponse TID:1260 CANCELLED
2018-08-21 21:50:48.821 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-08-21 21:50:48.821 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff true.
2018-08-21 21:50:48.821 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - TID 1260: Transaction event listener: DONE: CANCELLED -> 
2018-08-21 21:50:48.821 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Holdoff Timer active - no send...
2018-08-21 21:50:48.821 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Holdoff Timer finishing in 250ms
2018-08-21 21:50:48.821 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 129: -- To notify -- TIMEOUT_WAITING_FOR_CONTROLLER
2018-08-21 21:50:48.821 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ********* Transaction Response Complete -- 1260 --
2018-08-21 21:50:48.821 [DEBUG] [protocol.initialization.ZWaveNodeInitStageAdvancer] - NODE 129: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@20b4047e
2018-08-21 21:50:48.821 [DEBUG] [protocol.initialization.ZWaveNodeInitStageAdvancer] - NODE 129: timed out after 20455128398 / 20000000000
2018-08-21 21:50:48.821 [INFO ] [protocol.initialization.ZWaveNodeInitStageAdvancer] - NODE 129: SECURITY_INC State=FAILED, Reason=GET_SCHEME

I’m going to test secure inclusion with some other devices. Hopefully, this is just a hardware failure and not a regression in secure inclusion. On second thought…

Hello!

I am having trouble including/excluding devices with an everspring zwave plus stick and while searching how to find the issue I saw weird logs trying to go to exclusion mode in habmin, binding log as debug:
(I am using version 2.4.0.201808191228 of the binding)

2018-08-22 16:30:15.063 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - No bridgeUID found in getConfigDescription thing:zwave:serial_zstick:512

2018-08-22 16:30:15.066 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update received

2018-08-22 16:30:15.068 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update controller_exclude to true

2018-08-22 16:30:15.069 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWave inclusion process already running - aborted

Is something stuck in my controller preventing it from excluding/including devices ?

Thanks for your help !

It’s really hard to tell - you’ve only provide 6 milliseconds of logging and there’s nothing really wrong here in itself. It needs more context to understand what is happening, so please provide a minute or so of the log from prior to this.

Did you also bring the controller up the ladder ?
I have just had to move mine really close to my door lock to get that securely included.
Routing, “network wide” inclusion they all don’t seem to work with secure inclusion.
Someone a couple of posts up posted this hint, and I can confirm.

Maybe this is necessary for old locks that may use low power mode for inclusion, but this is definitely not the recommendation these days. Most devices should use high power inclusion (note that network wide inclusion is another issue again) and you should be able to include most devices up to 10 to 15 meters away (ie within standard, but direct range of the controller).

As I say though, some devices may not respect this - I think in the past the recommendation from ZWA was to use low power inclusion for locks, but it’s not the case now.

@chris Is there anyway to force a wakeup from a battery device (except for opening the device/push its button).
I just installed the snapshot build from the 18th august. All my battery devices were rediscovered, but unknown… I suspect this is due to they´re not wake.

A shot side matter on the upgrade…
When I removed the 2.3.0 Z-wave binding via PaperUI, I suddenly got tons of Zigbee errors… is there a connection somewhere??

No - if a device is asleep, then it can only wake up by itself. Either by pressing the button, or through the regular timer.

Probably - you need to wait for them to wake up, or manually wake them up.

No - there’s no link at all (other than the serial driver of course, but that’s not related to the binding).

When i restart openhab the following IllegalMonitorStateException is shown. I’m not sure when this exception first occured and what the cause is, using 2018-08-20 binding version.

2018-08-22 22:08:15.130 [INFO ] [basic.internal.servlet.WebAppServlet] - Started Basic UI at /basicui/app
2018-08-22 22:08:15.189 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui
2018-08-22 22:08:54.374 [INFO ] [ui.habmin.internal.servlet.HABminApp] - Started HABmin servlet at /habmin
2018-08-22 22:15:45.388 [INFO ] [basic.internal.servlet.WebAppServlet] - Stopped Basic UI
2018-08-22 22:15:57.508 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Stopped ZWave serial handler
2018-08-22 22:15:57.520 [ERROR] [nal.common.AbstractInvocationHandler] - An error occurred while calling method 'ThingHandler.dispose()' on 'org.openhab.binding.zwave.handler.ZWaveSerialHandler@3759ed': null
java.lang.IllegalMonitorStateException: null
	at java.lang.Object.notify(Native Method) ~[?:?]
	at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.shutdown(ZWaveTransactionManager.java:207) [180:org.openhab.binding.zwave:2.4.0.201808200952]
	at org.openhab.binding.zwave.internal.protocol.ZWaveController.shutdown(ZWaveController.java:118) [180:org.openhab.binding.zwave:2.4.0.201808200952]
	at org.openhab.binding.zwave.handler.ZWaveControllerHandler.dispose(ZWaveControllerHandler.java:247) [180:org.openhab.binding.zwave:2.4.0.201808200952]
	at org.openhab.binding.zwave.handler.ZWaveSerialHandler.dispose(ZWaveSerialHandler.java:133) [180:org.openhab.binding.zwave:2.4.0.201808200952]
	at sun.reflect.GeneratedMethodAccessor141.invoke(Unknown Source) ~[?:?]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
	at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:153) [94:org.eclipse.smarthome.core:0.10.0.201808211930]
	at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [94:org.eclipse.smarthome.core:0.10.0.201808211930]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
	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-08-22 22:15:57.541 [ERROR] [ome.core.thing.internal.ThingManager] - Exception occurred while disposing handler of thing 'zwave:serial_zstick:512': null
java.lang.IllegalMonitorStateException: null
	at java.lang.Object.notify(Native Method) ~[?:?]
	at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.shutdown(ZWaveTransactionManager.java:207) [180:org.openhab.binding.zwave:2.4.0.201808200952]
	at org.openhab.binding.zwave.internal.protocol.ZWaveController.shutdown(ZWaveController.java:118) [180:org.openhab.binding.zwave:2.4.0.201808200952]
	at org.openhab.binding.zwave.handler.ZWaveControllerHandler.dispose(ZWaveControllerHandler.java:247) [180:org.openhab.binding.zwave:2.4.0.201808200952]
	at org.openhab.binding.zwave.handler.ZWaveSerialHandler.dispose(ZWaveSerialHandler.java:133) [180:org.openhab.binding.zwave:2.4.0.201808200952]
	at sun.reflect.GeneratedMethodAccessor141.invoke(Unknown Source) ~[?:?]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
	at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:153) [94:org.eclipse.smarthome.core:0.10.0.201808211930]
	at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [94:org.eclipse.smarthome.core:0.10.0.201808211930]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
	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-08-22 22:15:59.522 [INFO ] [ui.habmin.internal.servlet.HABminApp] - Stopped HABmin servlet
2018-08-22 22:16:03.148 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Stopped Paper UI
2018-08-22 22:16:03.186 [INFO ] [panel.internal.HABPanelDashboardTile] - Stopped HABPanel
2018-08-22 22:16:03.218 [INFO ] [.dashboard.internal.DashboardService] - Stopped Dashboard

Hmm. After updating to the snapshot binding, I have a problem with a Vision PIR (model ZP3102).
I can not get it to report Alarm. Binary works fine though…

In the settings under wakeup configuration, I can not choose Controller (or OpenHab). I can however choose Node 1 (or any other number). Is Node 1 equal to OpenHab?
Under associate I can choose Controller, which I believe is correct, right?

Node 1 in a standard setup should be the zwave controller.

I am a bit confused here.
For the ZP3102 Vision Motion and temperatur sensor. I´m not able to choose OpenHab.
EDIT - Correction, I can choose Controller or Node under Association. I can not choose OpenHab.

See screenshot:

It appears to be added, but it is incomplete. I added comments to the device, but I am unable to edit it. It is identical to DZ6HD just the wattage is different. Is there any way to force the device to use the same profile?

I can not get the Alarm channel to trigger for both my zwave sensors. They worked fine with binding 2.3.0. After updating to latest snapshot, Alarm channel no longer trigger. Binary channel works fine though.
This applies to Vision PIR ZP3102 as well as Neo Coolcam (the one without temperature sensor).

That is fine. you need to choose your controller, in a standard setup that is node 1 or sometimes it is called “Controller”. That means your devices are reporting to the controller connected to openHAB.

Which one? The snapshot or the development version on top of this thread? If the latter, you need to delete your things and readd them. Some channels may have changed, so please check if you have to change your items (linked to channels of your things) too.

Yes, you are. Just follow the guide and email Chris:

https://www.cd-jackson.com/index.php/zwave/zwave-device-database/zwave-device-database-guide

To use the database you must first register on the site, then email, or open a ticket to have your access updated to allow you to edit the information.

That is a lot faster than to wait for someone doing it for you :grinning:

Edit: Btw, if this is your problem

you may need to switch to a recent snapshot or development version of the zwave binding.

I saw this once after upgrading to a recent dev snapshot and the binding restarted by itself and the error was gone.
After deleting content of tmp and cache folders I did not see that error again.