[snapshot] Can't change to customer function: binary report

[thopiekar]

When trying to change my DCH-Z510's operation mode to "binary report", I get a "HTTP Error -1" popping up and nothing changes. It doesn't matter which UI (Paper UI and HABmin2) I use. I readded (excluded, resetted the DCH-Z510 and included it again), without any changes.

2016-08-08 09:48:52.402 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 17: Timeout while sending message. Requeueing - 1 attempts left!
2016-08-08 09:48:52.403 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 17: Got an error while sending data. Resending message.
2016-08-08 09:48:52.414 [INFO ] [marthome.event.ItemStateChangedEvent] - zwave_serial_zstick_8d1481bf_serial_ack changed from 167 to 168
2016-08-08 09:48:52.424 [INFO ] [marthome.event.ItemStateChangedEvent] - zwave_serial_zstick_8d1481bf_serial_sof changed from 333 to 334
2016-08-08 09:48:52.439 [INFO ] [marthome.event.ItemStateChangedEvent] - zwave_serial_zstick_8d1481bf_serial_sof changed from 334 to 335
2016-08-08 09:48:54.648 [INFO ] [marthome.event.ItemStateChangedEvent] - ipp_printer_Drucker_Airprint__waitingJobs changed from NULL to 0
2016-08-08 09:48:57.406 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 17: Timeout while sending message. Requeueing - 0 attempts left!
2016-08-08 09:48:57.407 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 17: Got an error while sending data. Resending message.
2016-08-08 09:48:57.418 [INFO ] [marthome.event.ItemStateChangedEvent] - zwave_serial_zstick_8d1481bf_serial_ack changed from 168 to 169
2016-08-08 09:48:57.438 [INFO ] [marthome.event.ItemStateChangedEvent] - zwave_serial_zstick_8d1481bf_serial_sof changed from 335 to 336
2016-08-08 09:48:57.449 [INFO ] [marthome.event.ItemStateChangedEvent] - zwave_serial_zstick_8d1481bf_serial_sof changed from 336 to 337
2016-08-08 09:49:02.411 [WARN ] [ocol.ZWaveController$ZWaveSendThread] - NODE 17: Too many retries. Discarding message: Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=17, callback=122, payload=11 02 25 02

[cdjackson]

I don't know what the http error is or what the relevance is to the log? I would suggest to upgrade the a more recent runtime than beta 3 and if the problem still exists then provide a debug log.

Sent from my iPhone

On 8 Aug 2016, at 10:55, Thomas Karl Pietrowski notifications@github.com wrote:

When trying to change my DCH-Z510's operation mode to "binary report", I get a "HTTP Error -1" popping up and nothing changes. It doesn't matter which UI (Paper UI and HABmin2) I use. I readded (excluded, resetted the DCH-Z510 and included it again), without any changes.

2016-08-08 09:48:52.402 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 17: Timeout while sending message. Requeueing - 1 attempts left! 2016-08-08 09:48:52.403 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 17: Got an error while sending data. Resending message. 2016-08-08 09:48:52.414 [INFO ] [marthome.event.ItemStateChangedEvent] - zwave_serial_zstick_8d1481bf_serial_ack changed from 167 to 168 2016-08-08 09:48:52.424 [INFO ] [marthome.event.ItemStateChangedEvent] - zwave_serial_zstick_8d1481bf_serial_sof changed from 333 to 334 2016-08-08 09:48:52.439 [INFO ] [marthome.event.ItemStateChangedEvent] - zwave_serial_zstick_8d1481bf_serial_sof changed from 334 to 335 2016-08-08 09:48:54.648 [INFO ] [marthome.event.ItemStateChangedEvent] - ipp_printer_Drucker_Airprint__waitingJobs changed from NULL to 0 2016-08-08 09:48:57.406 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 17: Timeout while sending message. Requeueing - 0 attempts left! 2016-08-08 09:48:57.407 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 17: Got an error while sending data. Resending message. 2016-08-08 09:48:57.418 [INFO ] [marthome.event.ItemStateChangedEvent] - zwave_serial_zstick_8d1481bf_serial_ack changed from 168 to 169 2016-08-08 09:48:57.438 [INFO ] [marthome.event.ItemStateChangedEvent] - zwave_serial_zstick_8d1481bf_serial_sof changed from 335 to 336 2016-08-08 09:48:57.449 [INFO ] [marthome.event.ItemStateChangedEvent] - zwave_serial_zstick_8d1481bf_serial_sof changed from 336 to 337 2016-08-08 09:49:02.411 [WARN ] [ocol.ZWaveController$ZWaveSendThread] - NODE 17: Too many retries. Discarding message: Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=17, callback=122, payload=11 02 25 02 — You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub, or mute the thread.

[thopiekar]

Sorry, but https://github.com/openhab/openhab-distro/issues/264 is blocking here.

[thopiekar]

I updated to the recent snapshot, updated the binding and readded the controller and the siren. This is what I get here:

2016-08-20 16:52:54.399 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyACM0'
2016-08-20 16:52:54.594 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Serial port is initialized
2016-08-20 16:52:54.595 [INFO ] [mmandclass.ZWaveSecurityCommandClass] - Update networkKey
2016-08-20 16:52:54.607 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
2016-08-20 16:52:54.608 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.
2016-08-20 16:52:57.998 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 1: Node found
2016-08-20 16:52:58.015 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 4: Node found
2016-08-20 16:52:58.018 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 6: Node found
2016-08-20 16:52:58.026 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 7: Node found
2016-08-20 16:52:58.036 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 9: Node found
2016-08-20 16:52:58.039 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 10: Node found
2016-08-20 16:52:58.044 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 11: Node found
2016-08-20 16:52:58.048 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 12: Node found
2016-08-20 16:52:58.056 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 13: Node found
2016-08-20 16:52:58.057 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 15: Node found
2016-08-20 16:52:58.061 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 17: Node found
2016-08-20 16:52:58.070 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 18: Node found
2016-08-20 16:52:58.072 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 19: Node found
2016-08-20 16:52:58.074 [INFO ] [age.SerialApiGetInitDataMessageClass] - ZWave Controller using Controller API
2016-08-20 16:52:58.075 [INFO ] [age.SerialApiGetInitDataMessageClass] - ZWave Controller is Primary Controller
2016-08-20 16:52:58.076 [INFO ] [age.SerialApiGetInitDataMessageClass] - ------------Number of Nodes Found Registered to ZWave Controller------------
2016-08-20 16:52:58.078 [INFO ] [age.SerialApiGetInitDataMessageClass] - # Nodes = 13
2016-08-20 16:52:58.079 [INFO ] [age.SerialApiGetInitDataMessageClass] - ----------------------------------------------------------------------------
2016-08-20 16:53:00.682 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'zwave:device:f9088262:node17' to inbox.
2016-08-20 16:53:01.073 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'zwave:device:f9088262:node11' to inbox.
2016-08-20 16:53:02.040 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'zwave:device:f9088262:node9' to inbox.
2016-08-20 16:53:02.553 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'zwave:device:f9088262:node7' to inbox.
2016-08-20 16:53:03.087 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Timeout while sending message. Requeueing - 2 attempts left!
2016-08-20 16:53:03.622 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'zwave:device:f9088262:node13' to inbox.
2016-08-20 16:53:04.363 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'zwave:device:f9088262:node19' to inbox.
2016-08-20 16:53:04.886 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'zwave:device:f9088262:node18' to inbox.
2016-08-20 16:53:05.603 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'zwave:device:f9088262:node10' to inbox.
2016-08-20 16:53:06.073 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'zwave:device:f9088262:node12' to inbox.
2016-08-20 16:53:06.735 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'zwave:device:f9088262:node4' to inbox.
2016-08-20 16:53:08.214 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Timeout while sending message. Requeueing - 1 attempts left!
2016-08-20 16:53:13.216 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Timeout while sending message. Requeueing - 0 attempts left!
2016-08-20 16:53:18.219 [WARN ] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Too many retries. Discarding message: Message: class=EnableSuc[0x52], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 00 
2016-08-20 16:53:23.222 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Timeout while sending message. Requeueing - 2 attempts left!
2016-08-20 16:53:28.225 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Timeout while sending message. Requeueing - 1 attempts left!
2016-08-20 16:53:33.228 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Timeout while sending message. Requeueing - 0 attempts left!
2016-08-20 16:53:38.231 [WARN ] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Too many retries. Discarding message: Message: class=SetSucNodeID[0x54], type=Request[0x00], priority=High, dest=255, callback=0, payload=01 00 00 00 01 
2016-08-20 16:53:45.388 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 4: Timeout while sending message. Requeueing - 0 attempts left!
2016-08-20 16:53:45.392 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 4: Got an error while sending data. Resending message.
2016-08-20 16:53:46.609 [ERROR] [alization.ZWaveNodeInitStageAdvancer] - NODE 4: Node advancer: Retries exceeded at DYNAMIC_VALUES
2016-08-20 16:53:52.117 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 17: Initialising Thing Node...
2016-08-20 16:53:53.260 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 17: Initialising Thing Node...
2016-08-20 16:53:53.338 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 17: Timeout while sending message. Requeueing - 2 attempts left!
2016-08-20 16:53:53.338 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 17: Got an error while sending data. Resending message.
2016-08-20 16:53:58.340 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 17: Timeout while sending message. Requeueing - 1 attempts left!
2016-08-20 16:53:58.342 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 17: Got an error while sending data. Resending message.
2016-08-20 16:54:03.347 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 17: Timeout while sending message. Requeueing - 0 attempts left!
2016-08-20 16:54:03.348 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 17: Got an error while sending data. Resending message.
2016-08-20 16:54:08.351 [WARN ] [ocol.ZWaveController$ZWaveSendThread] - NODE 17: Too many retries. Discarding message: Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=17, callback=32, payload=11 02 25 02 
2016-08-20 16:54:10.680 [ERROR] [ding.zwave.handler.ZWaveThingHandler] - NODE 17: Error getting configurationCommandClass
2016-08-20 16:54:10.687 [ERROR] [ding.zwave.handler.ZWaveThingHandler] - NODE 17: Error getting configurationCommandClass
2016-08-20 16:54:10.700 [ERROR] [ding.zwave.handler.ZWaveThingHandler] - NODE 17: Error getting configurationCommandClass
2016-08-20 16:54:11.009 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 17: Initialising Thing Node...
2016-08-20 16:54:13.354 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 17: Timeout while sending message. Requeueing - 2 attempts left!
2016-08-20 16:54:13.355 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 17: Got an error while sending data. Resending message.
2016-08-20 16:54:18.362 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 17: Timeout while sending message. Requeueing - 1 attempts left!
2016-08-20 16:54:18.364 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 17: Got an error while sending data. Resending message.

2016-08-20 16:56:28.340 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 17: Timeout while sending message. Requeueing - 2 attempts left!
2016-08-20 16:56:28.341 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 17: Got an error while sending data. Resending message.
2016-08-20 16:56:33.343 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 17: Timeout while sending message. Requeueing - 1 attempts left!
2016-08-20 16:56:33.344 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 17: Got an error while sending data. Resending message.
2016-08-20 16:56:38.346 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 17: Timeout while sending message. Requeueing - 0 attempts left!
2016-08-20 16:56:38.347 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 17: Got an error while sending data. Resending message.
2016-08-20 16:56:43.350 [WARN ] [ocol.ZWaveController$ZWaveSendThread] - NODE 17: Too many retries. Discarding message: Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=17, callback=66, payload=11 02 25 02 
2016-08-20 16:59:03.337 [ERROR] [alization.ZWaveNodeInitStageAdvancer] - NODE 17: Node advancer: Retries exceeded at DYNAMIC_VALUES
2016-08-20 16:59:03.448 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 17: Initialising Thing Node...
2016-08-20 16:59:03.506 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 17: Initialising Thing Node...
2016-08-20 17:01:16.861 [ERROR] [ding.zwave.handler.ZWaveThingHandler] - NODE 17: Error getting configurationCommandClass
2016-08-20 17:01:16.923 [ERROR] [ding.zwave.handler.ZWaveThingHandler] - NODE 17: Error getting configurationCommandClass
2016-08-20 17:01:16.927 [ERROR] [ding.zwave.handler.ZWaveThingHandler] - NODE 17: Error getting configurationCommandClass
2016-08-20 17:01:17.703 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 17: Initialising Thing Node...
2016-08-20 17:01:27.644 [ERROR] [ding.zwave.handler.ZWaveThingHandler] - NODE 17: Error getting configurationCommandClass
2016-08-20 17:01:27.721 [ERROR] [ding.zwave.handler.ZWaveThingHandler] - NODE 17: Error getting configurationCommandClass
2016-08-20 17:01:27.722 [ERROR] [ding.zwave.handler.ZWaveThingHandler] - NODE 17: Error getting configurationCommandClass
2016-08-20 17:01:28.277 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 17: Initialising Thing Node...

2016-08-20 16:50:42.049 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 17: Initialising Thing Node...
2016-08-20 16:50:42.642 [ERROR] [ome.core.thing.internal.ThingManager] - Exception occured while initializing handler of thing 'zwave:device:8d1481bf:node17': java.lang.IllegalStateException: Could not update status, because callback is missing
java.util.concurrent.ExecutionException: java.lang.IllegalStateException: Could not update status, because callback is missing
    at java.util.concurrent.FutureTask.report(FutureTask.java:122)[:1.8.0_65]
    at java.util.concurrent.FutureTask.get(FutureTask.java:206)[:1.8.0_65]
    at org.eclipse.smarthome.core.common.SafeMethodCaller.callAsynchronous(SafeMethodCaller.java:186)[96:org.eclipse.smarthome.core:0.9.0.201608031951]
    at org.eclipse.smarthome.core.common.SafeMethodCaller.call(SafeMethodCaller.java:79)[96:org.eclipse.smarthome.core:0.9.0.201608031951]
    at org.eclipse.smarthome.core.common.SafeMethodCaller.call(SafeMethodCaller.java:63)[96:org.eclipse.smarthome.core:0.9.0.201608031951]
    at org.eclipse.smarthome.core.thing.internal.ThingManager$8.run(ThingManager.java:736)[102:org.eclipse.smarthome.core.thing:0.9.0.201608031951]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)[:1.8.0_65]
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)[:1.8.0_65]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)[:1.8.0_65]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)[:1.8.0_65]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)[:1.8.0_65]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)[:1.8.0_65]
    at java.lang.Thread.run(Thread.java:745)[:1.8.0_65]
Caused by: java.lang.IllegalStateException: Could not update status, because callback is missing
    at org.eclipse.smarthome.core.thing.binding.BaseThingHandler.updateStatus(BaseThingHandler.java:332)[102:org.eclipse.smarthome.core.thing:0.9.0.201608031951]
    at org.openhab.binding.zwave.handler.ZWaveThingHandler.bridgeStatusChanged(ZWaveThingHandler.java:423)[188:org.openhab.binding.zwave:2.0.0.201608190102]
    at org.openhab.binding.zwave.handler.ZWaveThingHandler.initialize(ZWaveThingHandler.java:146)[188:org.openhab.binding.zwave:2.0.0.201608190102]
    at org.eclipse.smarthome.core.thing.internal.ThingManager$8$1.call(ThingManager.java:739)[102:org.eclipse.smarthome.core.thing:0.9.0.201608031951]
    at org.eclipse.smarthome.core.thing.internal.ThingManager$8$1.call(ThingManager.java:1)[102:org.eclipse.smarthome.core.thing:0.9.0.201608031951]
    at org.eclipse.smarthome.core.common.SafeMethodCaller$CallableWrapper.call(SafeMethodCaller.java:177)[96:org.eclipse.smarthome.core:0.9.0.201608031951]
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)[:1.8.0_65]
    ... 3 more
2016-08-20 16:50:43.009 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - Controller handler not found. Cannot handle command without ZWave controller.
2016-08-20 16:50:43.033 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 17: Initialising Thing Node...

[thopiekar]

Also appended more messages I found in the logs.

[cdjackson]

Other than a few timeouts (which are quite common) I don’t see much of a problem. The configCommandClass message might be an issue, but without a debug log it’s impossible to say (and even with the debug log, it might not be obvious).

How does this relate to your reported problem of not changing the binary report?

Regarding the exception, I had hoped that this had been fixed in recent ESH versions, but if not I’m not sure how to resolve it. I don’t think it’s an issue with the binding, but again, without a log I’m afraid it’s hard to say.

[thopiekar]

Followed your instructions at http://www.cd-jackson.com/index.php/openhab/5-zwave-debugging-openhab and ran log:set debug org.openhab.binding.zwave . After that it got a bit more verbose. Did I miss a command? Would be great if you could add it to the instructions on your website, so we (at least I) don't need to ask again.

[cdjackson]

That should be all that's required to get debug level messages from the zwave binding.

[thopiekar]

There are DEBUG messages on other nodes, but not on the relevant one. However, I give you now full access to my openhab.log* files. (openHAB2 is running on my NAS if it matters.)

https://www.myqnapcloud.com/smartshare/69237gkn4l6p7008uv2z1x3c_65YSKfC

[cdjackson]

Ah - I didn't realise you'd filtered the logs. This is always a bad idea as it filters information that is needed. If you only show lines that start with NODE x:, then it will filter out all received data and this is mandatory for debugging.

I'll have a look at the log...

[thopiekar]

Ok, sorry about this.

Thanks!

Mit freundlichen Grüßen/With kind regards

• Thomas Karl Pietrowski

Am 20.08.2016 10:17 nachm. schrieb "Chris Jackson" <notifications@github.com

:

Ah - I didn't realise you'd filtered the logs. This is always a bad idea as it filters information that is needed. If you only show lines that start with NODE x:, then it will filter out all received data and this is mandatory for debugging.

I'll have a look at the log...

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub https://github.com/openhab/org.openhab.binding.zwave/issues/17#issuecomment-241221462, or mute the thread https://github.com/notifications/unsubscribe-auth/ABwwjQi24Ddr3qTMzfMZCIBcNlPuypjyks5qh2DugaJpZM4Je4aV .

[cdjackson]

Im trying to work out what your problem actually is. The title of this is "can't change to customer function: binary report" which I assume means that you can't set parameter 7 to 16?

What I need to see is a log that shows what happens when you try and do this - I can't really search through 100MB of logs to find this ;)

[thopiekar]

No problem. Correct, otherwise it is not possible to make the "switch" of the siren work. It will wait for a notification per default (Got no idea how to implement this. But, I'm interested, as the siren can play sounds, eg. like a "door bell", too.).

The last time stamp was 2016-08-20 21:11:01.499 before I was on the page of my thing via paper ui ( Configuration > Things > {Thing_name} )and did the following 3 times:

1. Went to the parameter settings
2. Changed parameter 7 to "sensor binary report"
3. Applied the change and got back to the first page
4. Reloaded the page (as it seemed to hang)
5. Waited until all channels were listed

Reloaded the log and the last time stamp is: 2016-08-20 21:18:17.598

[cdjackson]

The logs don't appear to be very useful as there's still no debug for some reason. Can you post the node17.xml file please? I'm wondering if there was some sort of problem during the discovery that means it's not properly discovered the device and there's no config class...

[thopiekar]

distribution/userdata/zwave/node17.xml:

https://www.myqnapcloud.com/smartshare/69237gkn4l6p7008uv2z1x3c_6o823Gs

[cdjackson]

Ok - so as I thought - there’s no config class showing. Try deleting the XML and restarting OH and see if it regenerates with configuration this time. If not, we’ll need to look at why not (which will require a full log file during startup, and DEBUG logging will definitely be needed).

[thopiekar]

Already removed the xml before resuming our conversation here today.

I saw messages in the log that said that the binding wasn't able to deserialize the XML. So I thought mine has an old layout and I remembered that the XMLs are only 'caches', so I deleted it.

But can give it another try if you want. On startup it will generate a new openhab.log isn't it?

My link above should show the recent openhab.log* files of my userdata/logs/ ( actually it is directly linked to these files ) or is it needed to get the log from the OH2 console?

[thopiekar]

This is the XML I had since beta3 (backed it up):

https://www.myqnapcloud.com/smartshare/69237gkn4l6p7008uv2z1x3c_6E752nt

[cdjackson]

One other thing to try then is to make sure that the network secure inclusion setting in the controller is set to either door locks. Or none. You need to enable advanced settings if using Habmin to see this.

The log will be appended to when you restart - it's fine I can process this out. You shouldn't in theory need to look at the console log - the files should be fine.

And yes the xml files are just a coach so deleting them is fine - since you've already done this id definitely try the secure setting (I saw some strange secure messages in your log which is why I mention this).

On 20 Aug 2016, at 23:10, Thomas Karl Pietrowski notifications@github.com wrote:

Already removed the xml before resuming our conversation here today.

I saw messages in the log that said that the binding wasn't able to deserialize the XML. So I thought mine has an old layout and I remembered that the XMLs are only 'caches', so I deleted it.

But can give it another try if you want. On startup it will generate a new openhab.log isn't it?

My link above should show the recent openhab.log* files of my userdata/logs/ ( actually it is directly linked to these files ) or is it needed to get the log from the OH2 console? — You are receiving this because you commented. Reply to this email directly, view it on GitHub, or mute the thread.

[thopiekar]

It was set to: Entry Control Devices. Can see it here from Paper UI. Additionally, I saw that my controller is not set as "SUC", but it was in the past. So I enabled it again and set network secure inclusion setting to None. Now, I get OFFLINE Node not found in Z-Wave network on every thing. I guess it was a bad idea making it a SUC again :eyes: Disabled the SUC setting after that.

Ok, I'll try go for it...

1. Shutting down OH2
2. Removing the node17.xml
3. Restarted OH2. The now it is: 00:44 (+02:00 timezone, so 22:44 in the logs)

[thopiekar]

Retried to change to "sensor binary report" (parameter 7) at approx 0:59 after node17.xml was found again. The old link also works again: https://www.myqnapcloud.com/smartshare/69237gkn4l6p7008uv2z1x3c_6o823Gs

(Going to bed now. Thank you Chris for taking time :+1: )

[cdjackson]

I don’t think enabling SUC should make any problem, so maybe something else caused the devices to go offline. Also, when you do this, the binding will effectively restart, so everything will go offline for a little while.

Anyway, looking at the XML, it still doesn’t show CONFIG class. As it’s not in the NIF either, I guess the device is not reporting it. I have added a setting in the database for force this so let’s see if that solves this - I’ll do an update tonight, so please take another look with tomorrows binding. You will need to delete the XML and restart after updating the binding.

[thopiekar]

Hmm, I've set it again to SUC more than 6 hours ago (approx) and all things are still OFFLINE? Sounds like a bug?

As I had problems jumping to the beta3 from an old snapshot, I resetted my siren. Is it possible that I've done it wrong? Or is there any other reason which could case my problem here?

[cdjackson]

Ok - I’ll need to see a log. Probably best to get a debug log during startup period.

SUC shouldn’t make much/any difference to the network, so there’s probably a bug in the binding…

[thopiekar]

So shutdown openHAB, rm userdata/logs/openhab.log and restart? Done that...

[cdjackson]

Yep.

[thopiekar]

Ok, the new log should be accessible via old link.

[cdjackson]

The log has no debug so it’s not especially useful.

I did find one bug as there’s an exception in the log and I can track this down - not sure that it’s actually the problem or not though. Any chance of getting debug logging turned on and redoing this?

[thopiekar]

That's strange.. I'm sure I've set the zwave binding to debug. Also other extras don't appear just ROOT. Don't know what happened here:

openhab> log:get log:get

Logger | Level

ROOT | WARN openhab> log:set DEBUG log:set DEBUG openhab> log:get log:get

Logger | Level

ROOT | DEBUG

Is DEBUG globally to noisy?

[cdjackson]

Global is ok for me - I’ll process this with the log viewer and it will tell me most of what I need to know. If I need to actually read the log, then I use the log viewer to tell me the exact time…

If that’s the only way to get debug, then go for it...

[thopiekar]

Done. Log with global debugging is on since 18:51. So 16:51 in the logs. (Hopefully nothing got resetted again...)

[cdjackson]

Well, I’m confused… This log still doesn’t have any zwave debug messages. It has debug for other bindings/core bundles, just not ZWave. I don’t know why that is - you don’t have any other configuration files have you - e.g. you haven’t edited the logbook file. I guess not, but something is stopping this from logging correctly...

[thopiekar]

Noticed that my openHAB just stopped yesterday. I waited for a new build from today, but had to start openHAB so I made a update to a yesterdays build.

As you can see there are DEBUG messages from yesterday:

2016-08-21 16:51:07.602 [DEBUG] [ell.impl.action.osgi.CommandExtender] - org.openhab.binding.zwave (188): Starting destruction process
2016-08-21 16:51:07.603 [DEBUG] [ell.impl.action.osgi.CommandExtender] - org.openhab.binding.zwave (188): Not an extended bundle or destruction of extension already finished
2016-08-21 16:51:07.604 [DEBUG] [ell.impl.action.osgi.CommandExtender] - org.openhab.binding.zwave (188): Starting destruction process
2016-08-21 16:51:07.604 [DEBUG] [ell.impl.action.osgi.CommandExtender] - org.openhab.binding.zwave (188): Not an extended bundle or destruction of extension already finished

Now restarted into console and found that my kind of "updating" (https://github.com/openhab/openhab-qnap-qpkg/blob/master/shared/openHAB.sh#L111) removes these settings:

openhab> log:get
log:get
Logger | Level
--------------
ROOT   | WARN

Made a log:set DEBUG and restarted it as a service, while writing this comment.

[cdjackson]

Good luck - but as said earlier, while there were debug messages in the log there are no debug message from the zwave binding.

[thopiekar]

Hmm, but it seems to work now...

2016-08-22 21:16:44.699 [DEBUG] [ell.impl.action.osgi.CommandExtender] - org.openhab.binding.zwave (198): Starting destruction process
2016-08-22 21:16:44.699 [DEBUG] [ell.impl.action.osgi.CommandExtender] - org.openhab.binding.zwave (198): Not an extended bundle or destruction of extension already finished
2016-08-22 21:16:44.700 [DEBUG] [ell.impl.action.osgi.CommandExtender] - org.openhab.binding.zwave (198): Starting destruction process
2016-08-22 21:16:44.701 [DEBUG] [ell.impl.action.osgi.CommandExtender] - org.openhab.binding.zwave (198): Not an extended bundle or destruction of extension already finished
2016-08-22 21:16:47.998 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Stopped ZWave serial handler
2016-08-22 21:16:48.127 [DEBUG] [ell.impl.action.osgi.CommandExtender] - org.openhab.binding.zwave (198): Starting destruction process
2016-08-22 21:16:48.128 [DEBUG] [ell.impl.action.osgi.CommandExtender] - org.openhab.binding.zwave (198): Not an extended bundle or destruction of extension already finished

[cdjackson]

On 22 Aug 2016, at 22:21, Thomas Karl Pietrowski notifications@github.com wrote:

Hmm, but it seems to work now...

No - there’s only INFO logging showing.

[thopiekar]

Oops, yes, you are right.

[thopiekar]

I reran log:set debug org.openhab.binding.zwave and now I have:

2016-08-22 21:27:35.662 [WARN ] [ore.internal.events.OSGiEventManager] - Dispatching event to subscriber 'org.eclipse.smarthome.core.thing.link.ThingLinkManager@132b7ca' takes more than 5000ms.
2016-08-22 21:27:35.850 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandler}={thing.type=zwave:dlink_dchz110_00_000, thing.id=zwave:device:f9088262:node13, service.id=342, service.bundleid=198, service.scope=singleton} - org.openhab.binding.zwave
2016-08-22 21:27:35.867 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=343, service.bundleid=198, service.scope=singleton} - org.openhab.binding.zwave

[thopiekar]

It was truly a bug. Looks like log:get returns something completely wrong..

I'm just restarting openHAB as an service now, so I can close the SSH session.

[thopiekar]

Hey @cdjackson, can we take another look on this?

Thanks!

[cdjackson]

Sure. Just let me know...

[thopiekar]

Hey @cdjackson made an update of my snapshot today, set the logger to debug again and restarted OH2.

I also created a new link, so you can access /zwave and /log* under userdata. https://www.myqnapcloud.com/smartshare/69237gkn4l6p7008uv2z1x3c_6j9o21i

I retried to change the customer function 3 times around 11:38.

PS: Made a copy of openhab.log called openhab_zwave.log after trying to change the customer function.

[thopiekar]

Any news? :confused:

[cdjackson]

Sorry - I could find the point in the log. I only looked just now though and the only log around this time is the openhab_zwave.log file, but it stops at 11:37.

[thopiekar]

Ok, that's strange :confused:

[cdjackson]

I probably left it too long to download - it looks like the logs are live, and they have overwritten everything from yesterday other than the one that was renamed...

[thopiekar]

No problem. OH2 is running all the time - that's why I made the copy. I just didn't noticed the delay in the copied file.

Would it help if I remove all logs, start OH2, try to set the correct mode and shut OH2 down again (eg. after 10minutes), so you can look for the error messages without any stress?

[cdjackson]

A clean log would be good - so starting OH2, setting the parameter that doesn’t work, then copying the log somewhere so we know exactly what we’re looking at...

[thopiekar]

Removed all logs, restarted OH2, retried (17:23), waited for 5 minutes and turned it off.

[thopiekar]

Was there anything useful for you?

[cdjackson]

Sorry - I’ve not had a chance to look yet. I’m also trying to do a number of other things at the same time… I’ll try and look later this evening.