ZWave binding updates

zwave
Tags: #<Tag:0x00007f0141e0e1d0>

(Chris Jackson) #258

Please provide a logfile so I can see what is causing this.


(SiHui) #259

At least for this one you are on the wrong track :sunglasses:

You are showing your org.eclipse.smarthome.core.thing.Thing.json definition. That file (actually a JsonDB entry) does not get populated via things file, only via UI.
So you must have set that outside of your flat text file.


(Ulrich) #260

zwave.log:

25-Nov-2018 18:49:07.130 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Handler disposed. Unregistering listener.
25-Nov-2018 18:49:07.312 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 13: Serialise aborted as static stages not complete
25-Nov-2018 18:49:07.365 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=438, service.bundleid=241, service.scope=singleton} - org.openhab.binding.zwave
25-Nov-2018 18:49:50.830 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Stop zwave:serial_zstick:gehirn
25-Nov-2018 18:49:50.886 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWave inclusion process not running - nothing to do
25-Nov-2018 18:49:50.963 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Start zwave:serial_zstick:gehirn
25-Nov-2018 18:49:51.019 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWave controller start inclusion - mode 2
25-Nov-2018 18:49:51.053 [DEBUG] [ve.internal.protocol.ZWaveController] - Event listener added.
25-Nov-2018 18:49:51.086 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave controller start inclusion
25-Nov-2018 18:49:51.120 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Setting controller into INCLUSION mode, highPower:true networkWide:true.
25-Nov-2018 18:49:51.153 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 201 to queue - size 1
25-Nov-2018 18:49:51.187 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
25-Nov-2018 18:49:51.277 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A C1 92 E3 
25-Nov-2018 18:49:51.345 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A C1 92 E3 
25-Nov-2018 18:49:51.424 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
25-Nov-2018 18:49:51.443 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
25-Nov-2018 18:49:51.478 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
25-Nov-2018 18:49:51.523 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 201: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 146
25-Nov-2018 18:49:51.569 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 92 01 00 00 21 
25-Nov-2018 18:49:51.566 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
25-Nov-2018 18:49:51.684 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=1, callback=146, payload=92 01 00 00 
25-Nov-2018 18:49:51.700 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 201: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 146
25-Nov-2018 18:49:51.789 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
25-Nov-2018 18:49:51.834 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=1, callback=146, payload=92 01 00 00 
25-Nov-2018 18:49:51.878 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 201: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 146
25-Nov-2018 18:49:51.923 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
25-Nov-2018 18:49:51.967 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 201: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 146
25-Nov-2018 18:49:52.012 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 201: (Callback 146)
25-Nov-2018 18:49:52.056 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
25-Nov-2018 18:49:52.101 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 201: callback 146
25-Nov-2018 18:49:52.146 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=1, callback=146, payload=92 01 00 00 
25-Nov-2018 18:49:52.190 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: Learn ready.
25-Nov-2018 18:49:52.279 [DEBUG] [al.protocol.ZWaveInclusionController] - Inclusion event: Current state IncludeSent, new event IncludeStart
25-Nov-2018 18:49:52.335 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 201: Transaction COMPLETED
25-Nov-2018 18:49:52.402 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 879ms
25-Nov-2018 18:49:52.513 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 201: Transaction completed
25-Nov-2018 18:49:52.626 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:201 DONE
25-Nov-2018 18:49:52.669 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
25-Nov-2018 18:49:52.713 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
25-Nov-2018 18:49:53.613 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 16: Device discovery completed
...
25-Nov-2018 18:49:55.075 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 13: Device discovery completed
25-Nov-2018 18:49:55.119 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 13: Device discovery resolved to thingType zwave:vision_zd2102plus_00_000
25-Nov-2018 18:49:55.228 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 14: Device discovery completed
25-Nov-2018 18:49:55.276 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 14: Device discovery resolved to thingType zwave:vision_zg8101_00_000
25-Nov-2018 18:50:20.963 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Stop zwave:serial_zstick:gehirn
25-Nov-2018 18:50:21.010 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave controller stopping inclusion at IncludeStart
25-Nov-2018 18:50:21.044 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.
25-Nov-2018 18:50:21.077 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 202 to queue - size 1
25-Nov-2018 18:50:21.166 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
25-Nov-2018 18:50:21.223 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A 05 93 26 
25-Nov-2018 18:50:21.256 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A 05 93 26 
25-Nov-2018 18:50:21.290 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
25-Nov-2018 18:50:21.313 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
25-Nov-2018 18:50:21.334 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
25-Nov-2018 18:50:21.367 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 202: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 147
25-Nov-2018 18:50:21.400 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
25-Nov-2018 18:50:21.403 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 93 06 00 00 27 
25-Nov-2018 18:50:21.467 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 202: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 147
25-Nov-2018 18:50:21.534 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=147, payload=93 06 00 00 
25-Nov-2018 18:50:21.534 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
25-Nov-2018 18:50:21.581 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=147, payload=93 06 00 00 
25-Nov-2018 18:50:21.624 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 202: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 147
25-Nov-2018 18:50:21.668 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
25-Nov-2018 18:50:21.713 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 202: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 147
25-Nov-2018 18:50:21.757 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 202: (Callback 147)
25-Nov-2018 18:50:21.802 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
25-Nov-2018 18:50:21.846 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 202: callback 147
25-Nov-2018 18:50:21.904 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=147, payload=93 06 00 00 
25-Nov-2018 18:50:21.982 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: Done.
25-Nov-2018 18:50:22.036 [DEBUG] [al.protocol.ZWaveInclusionController] - Inclusion event: Current state IncludeDone, new event IncludeDone
25-Nov-2018 18:50:22.082 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.
25-Nov-2018 18:50:22.126 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 203 to queue - size 1
25-Nov-2018 18:50:22.172 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
25-Nov-2018 18:50:22.215 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave controller end exclusion
25-Nov-2018 18:50:22.258 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWaveController include done
25-Nov-2018 18:50:22.304 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 202: Advanced to DONE
25-Nov-2018 18:50:22.347 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 980ms
25-Nov-2018 18:50:22.393 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 202: Transaction completed
25-Nov-2018 18:50:22.436 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:202 DONE
25-Nov-2018 18:50:22.481 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
25-Nov-2018 18:50:22.525 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
25-Nov-2018 18:50:22.572 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A 05 00 B5 
25-Nov-2018 18:50:22.616 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A 05 00 B5 
25-Nov-2018 18:50:22.662 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
25-Nov-2018 18:50:22.683 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
25-Nov-2018 18:50:22.706 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
25-Nov-2018 18:50:22.748 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 203: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 0
25-Nov-2018 18:50:22.838 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
25-Nov-2018 18:50:22.906 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 203: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 0
25-Nov-2018 18:50:22.950 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
25-Nov-2018 18:50:22.995 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
25-Nov-2018 18:50:23.039 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
25-Nov-2018 18:50:27.838 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 255: TID 203: Timeout at state WAIT_REQUEST. 3 retries remaining.
25-Nov-2018 18:50:27.886 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 203: Transaction is current transaction, so clearing!!!!!
25-Nov-2018 18:50:27.931 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 203: Transaction CANCELLED
25-Nov-2018 18:50:27.975 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:203 CANCELLED
25-Nov-2018 18:50:28.021 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
25-Nov-2018 18:51:23.847 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=439, service.bundleid=241, service.scope=singleton} - org.openhab.binding.zwave
25-Nov-2018 18:51:23.937 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:gehirn:node13.
25-Nov-2018 18:51:24.030 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Controller status changed to ONLINE.
25-Nov-2018 18:51:24.030 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Channel zwave:device:gehirn:node13:sensor_door linked - polling started.
25-Nov-2018 18:51:24.109 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Controller is ONLINE. Starting device initialisation.
25-Nov-2018 18:51:24.032 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Channel zwave:device:gehirn:node13:battery-level linked - polling started.
25-Nov-2018 18:51:24.298 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Updating node properties.
25-Nov-2018 18:51:24.387 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Updating node properties. MAN=265
25-Nov-2018 18:51:24.443 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Updating node properties. MAN=265. SET. Was 265
25-Nov-2018 18:51:24.510 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Properties synchronised
25-Nov-2018 18:51:24.610 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Update ASSOCIATION group_ZWaveAssociationGroup [index=1, name=null, profile1=null, profile2=null, associations=[node_1]]: Adding node_1
25-Nov-2018 18:51:24.665 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Configuration synchronised
25-Nov-2018 18:51:24.762 [DEBUG] [ve.internal.protocol.ZWaveController] - Event listener added.
25-Nov-2018 18:51:24.823 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Initialising Thing Node...
25-Nov-2018 18:51:24.900 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Initialising cmd channel zwave:device:gehirn:node13:sensor_door for OpenClosedType
25-Nov-2018 18:51:24.944 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Initialising state channel zwave:device:gehirn:node13:sensor_door for OpenClosedType
25-Nov-2018 18:51:29.965 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 00 04 00 11 0A 56 01 31 05 04 22 00 1B DA 81 F5 
25-Nov-2018 18:51:30.074 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=17, callback=0, payload=00 11 0A 56 01 31 05 04 22 00 1B DA 81 
25-Nov-2018 18:51:30.139 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=17, callback=0, payload=00 11 0A 56 01 31 05 04 22 00 1B DA 81 
25-Nov-2018 18:51:30.193 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
25-Nov-2018 18:51:30.227 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 17: Application Command Request (ALIVE:DONE)
25-Nov-2018 18:51:30.271 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 17: resetResendCount initComplete=true isDead=false
25-Nov-2018 18:51:30.305 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 17: Decapsulating COMMAND_CLASS_CRC_16_ENCAP
25-Nov-2018 18:51:30.338 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 17: Incoming command class COMMAND_CLASS_SENSOR_MULTILEVEL, endpoint 0
25-Nov-2018 18:51:30.371 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 17: SECURITY NOT required on COMMAND_CLASS_SENSOR_MULTILEVEL
25-Nov-2018 18:51:30.405 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 17: Received COMMAND_CLASS_SENSOR_MULTILEVEL V5 SENSOR_MULTILEVEL_REPORT
25-Nov-2018 18:51:30.438 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 17: Sensor Type = Power(4), Scale = 0
25-Nov-2018 18:51:30.472 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 17: Sensor Value = 2.7
25-Nov-2018 18:51:30.506 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 17: Got an event from Z-Wave network: ZWaveMultiLevelSensorValueEvent
25-Nov-2018 18:51:30.539 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 17: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_SENSOR_MULTILEVEL, value = 2.7
25-Nov-2018 18:51:30.573 [DEBUG] [erter.ZWaveMultiLevelSensorConverter] - NODE 17: Sensor conversion not performed for POWER.
25-Nov-2018 18:51:30.605 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 17: Updating channel state zwave:device:gehirn:node17:sensor_power to 2.7 [DecimalType]
25-Nov-2018 18:51:30.639 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 17: Commands processed 1.
25-Nov-2018 18:51:30.672 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 17: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@b0ea21.
25-Nov-2018 18:51:30.706 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
25-Nov-2018 18:51:30.739 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
25-Nov-2018 18:51:30.773 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
25-Nov-2018 18:51:30.806 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

openhab.log:

2018-11-25 18:55:33.740 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'zwave:device:gehirn:node13' to inbox.
2018-11-25 18:55:39.361 [ERROR] [nal.common.AbstractInvocationHandler] - An error occurred while calling method 'ThingHandler.initialize()' on 'org.openhab.binding.zwave.handler.ZWaveThingHandler@36b30f': 1
java.lang.ArrayIndexOutOfBoundsException: 1
	at org.openhab.binding.zwave.handler.ZWaveThingHandler.initialiseNode(ZWaveThingHandler.java:226) ~[?:?]
	at org.openhab.binding.zwave.handler.ZWaveThingHandler.bridgeStatusChanged(ZWaveThingHandler.java:512) ~[?:?]
	at org.openhab.binding.zwave.handler.ZWaveThingHandler.initialize(ZWaveThingHandler.java:164) ~[?:?]
	at sun.reflect.GeneratedMethodAccessor95.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) [101:org.eclipse.smarthome.core:0.10.0.oh240M6]
	at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [101:org.eclipse.smarthome.core:0.10.0.oh240M6]
	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-11-25 18:55:39.424 [ERROR] [core.thing.internal.ThingManagerImpl] - Exception occurred while initializing handler of thing 'zwave:device:gehirn:node13': 1
java.lang.ArrayIndexOutOfBoundsException: 1
	at org.openhab.binding.zwave.handler.ZWaveThingHandler.initialiseNode(ZWaveThingHandler.java:226) ~[?:?]
	at org.openhab.binding.zwave.handler.ZWaveThingHandler.bridgeStatusChanged(ZWaveThingHandler.java:512) ~[?:?]
	at org.openhab.binding.zwave.handler.ZWaveThingHandler.initialize(ZWaveThingHandler.java:164) ~[?:?]
	at sun.reflect.GeneratedMethodAccessor95.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) [101:org.eclipse.smarthome.core:0.10.0.oh240M6]
	at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [101:org.eclipse.smarthome.core:0.10.0.oh240M6]
	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) [?:?]

(Chris Jackson) #261

There are 4 minutes between the logs :confused:. I assume that the two logs aren’t linked - I need to see the data that is received, and the exception that is fired…

Or maybe I’m missing something? Can you maybe explain what the logs are showing?


(Ulrich) #262

Sorry, I retried it and have sent the wrong log…

2018-11-25 18:49:55.176 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'zwave:device:gehirn:node13' to inbox.
2018-11-25 18:50:04.106 [INFO ] [.model.script.OpenHAB system started] - System läuft bereits
2018-11-25 18:51:24.989 [ERROR] [nal.common.AbstractInvocationHandler] - An error occurred while calling method 'ThingHandler.initialize()' on 'org.openhab.binding.zwave.handler.ZWaveThingHandler@65230b': 1
java.lang.ArrayIndexOutOfBoundsException: 1
	at org.openhab.binding.zwave.handler.ZWaveThingHandler.initialiseNode(ZWaveThingHandler.java:226) ~[?:?]
	at org.openhab.binding.zwave.handler.ZWaveThingHandler.bridgeStatusChanged(ZWaveThingHandler.java:512) ~[?:?]
	at org.openhab.binding.zwave.handler.ZWaveThingHandler.initialize(ZWaveThingHandler.java:164) ~[?:?]
	at sun.reflect.GeneratedMethodAccessor95.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) [101:org.eclipse.smarthome.core:0.10.0.oh240M6]
	at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [101:org.eclipse.smarthome.core:0.10.0.oh240M6]
	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-11-25 18:51:25.045 [ERROR] [core.thing.internal.ThingManagerImpl] - Exception occurred while initializing handler of thing 'zwave:device:gehirn:node13': 1
java.lang.ArrayIndexOutOfBoundsException: 1
	at org.openhab.binding.zwave.handler.ZWaveThingHandler.initialiseNode(ZWaveThingHandler.java:226) ~[?:?]
	at org.openhab.binding.zwave.handler.ZWaveThingHandler.bridgeStatusChanged(ZWaveThingHandler.java:512) ~[?:?]
	at org.openhab.binding.zwave.handler.ZWaveThingHandler.initialize(ZWaveThingHandler.java:164) ~[?:?]
	at sun.reflect.GeneratedMethodAccessor95.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) [101:org.eclipse.smarthome.core:0.10.0.oh240M6]
	at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [101:org.eclipse.smarthome.core:0.10.0.oh240M6]
	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) [?:?]


(Chris Jackson) #263

It needs to be a debug log like the one you provided above - otherwise it doesn’t log the data that is causing the problem.


(Ulrich) #264

I added the debug log for org.eclipse.smarthome.core.
I hope that it is sufficient. Otherwise please provide information, which package should be set to DEBUG.

25-Nov-2018 21:14:19.900 [DEBUG] [core.thing.internal.ThingManagerImpl] - Removal handling of thing 'zwave:device:gehirn:node13' completed. Going to remove it now.
25-Nov-2018 21:14:20.118 [DEBUG] [core.thing.internal.ThingManagerImpl] - Thing 'zwave:device:gehirn:node13' is no longer tracked by ThingManager.
25-Nov-2018 21:14:20.203 [DEBUG] [core.thing.internal.ThingManagerImpl] - Calling dispose handler for thing 'zwave:device:gehirn:node13' at 'org.openhab.binding.zwave.handler.ZWaveThingHandler@e0f996'.
25-Nov-2018 21:14:20.296 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Handler disposed. Unregistering listener.
25-Nov-2018 21:14:20.411 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 13: Serialise aborted as static stages not complete
25-Nov-2018 21:14:20.460 [DEBUG] [core.thing.internal.ThingManagerImpl] - Calling unregisterHandler handler for thing 'zwave:device:gehirn:node13' at 'org.openhab.binding.zwave.internal.ZWaveHandlerFactory@522d7d'.
25-Nov-2018 21:14:20.557 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=441, service.bundleid=241, service.scope=singleton} - org.openhab.binding.zwave
25-Nov-2018 21:14:20.640 [DEBUG] [mon.registry.AbstractManagedProvider] - Removed element zwave:device:gehirn:node13 from ManagedThingProvider.
25-Nov-2018 21:14:28.881 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Stop zwave:serial_zstick:gehirn
25-Nov-2018 21:14:28.950 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWave inclusion process not running - nothing to do
25-Nov-2018 21:14:28.988 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Start zwave:serial_zstick:gehirn
25-Nov-2018 21:14:29.074 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWave controller start inclusion - mode 2
25-Nov-2018 21:14:29.176 [DEBUG] [ve.internal.protocol.ZWaveController] - Event listener added.
25-Nov-2018 21:14:29.241 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave controller start inclusion
25-Nov-2018 21:14:29.319 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Setting controller into INCLUSION mode, highPower:true networkWide:true.
25-Nov-2018 21:14:29.386 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 250 to queue - size 1
25-Nov-2018 21:14:29.452 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
25-Nov-2018 21:14:29.523 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A C1 BA CB 
25-Nov-2018 21:14:29.600 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A C1 BA CB 
25-Nov-2018 21:14:29.680 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
25-Nov-2018 21:14:29.703 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
25-Nov-2018 21:14:29.768 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
25-Nov-2018 21:14:29.845 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 250: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 186
25-Nov-2018 21:14:29.936 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A BA 01 00 00 09 
25-Nov-2018 21:14:29.934 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
25-Nov-2018 21:14:30.073 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=1, callback=186, payload=BA 01 00 00 
25-Nov-2018 21:14:30.089 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 250: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 186
25-Nov-2018 21:14:30.178 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
25-Nov-2018 21:14:30.224 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=1, callback=186, payload=BA 01 00 00 
25-Nov-2018 21:14:30.268 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 250: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 186
25-Nov-2018 21:14:30.324 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
25-Nov-2018 21:14:30.390 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 250: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 186
25-Nov-2018 21:14:30.435 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 250: (Callback 186)
25-Nov-2018 21:14:30.479 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
25-Nov-2018 21:14:30.524 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 250: callback 186
25-Nov-2018 21:14:30.570 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=1, callback=186, payload=BA 01 00 00 
25-Nov-2018 21:14:30.614 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: Learn ready.
25-Nov-2018 21:14:30.659 [DEBUG] [al.protocol.ZWaveInclusionController] - Inclusion event: Current state IncludeSent, new event IncludeStart
25-Nov-2018 21:14:30.713 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 250: Transaction COMPLETED
25-Nov-2018 21:14:30.781 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 935ms
25-Nov-2018 21:14:30.924 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 250: Transaction completed
25-Nov-2018 21:14:31.199 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:250 DONE
25-Nov-2018 21:14:31.307 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
25-Nov-2018 21:14:31.359 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
...
25-Nov-2018 21:14:33.766 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 13: Device discovery completed
25-Nov-2018 21:14:33.810 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 13: Device discovery resolved to thingType zwave:vision_zd2102plus_00_000
25-Nov-2018 21:14:33.954 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 14: Device discovery completed
25-Nov-2018 21:14:34.011 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 14: Device discovery resolved to thingType zwave:vision_zg8101_00_000
25-Nov-2018 21:14:44.518 [DEBUG] [core.thing.internal.ThingManagerImpl] - Thing 'zwave:device:gehirn:node13' is tracked by ThingManager.
25-Nov-2018 21:14:44.636 [DEBUG] [core.thing.internal.ThingManagerImpl] - Calling 'ZWaveHandlerFactory.registerHandler()' for thing 'zwave:device:gehirn:node13'.
25-Nov-2018 21:14:44.710 [DEBUG] [hing.binding.BaseThingHandlerFactory] - Creating thing zwave:device:gehirn:node13
25-Nov-2018 21:14:44.848 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=442, service.bundleid=241, service.scope=singleton} - org.openhab.binding.zwave
25-Nov-2018 21:14:44.910 [DEBUG] [core.thing.internal.ThingManagerImpl] - Configuration of 'zwave:device:gehirn:node13' needs [node_id, node_id], has [config_1_1, node_id].
25-Nov-2018 21:14:44.978 [DEBUG] [core.thing.internal.ThingManagerImpl] - Config description for 'zwave:sensor_door' is not resolvable, assuming 'zwave:device:gehirn:node13:sensor_door' is initializable
25-Nov-2018 21:14:45.067 [DEBUG] [core.thing.internal.ThingManagerImpl] - Config description for 'zwave:alarm_tamper' is not resolvable, assuming 'zwave:device:gehirn:node13:alarm_tamper' is initializable
25-Nov-2018 21:14:45.130 [DEBUG] [home.core.internal.items.ItemUpdater] - Received update of a not accepted type (DecimalType) for item str_Heiz_BLNetRawExit
25-Nov-2018 21:14:45.165 [DEBUG] [core.thing.internal.ThingManagerImpl] - Config description for 'system:battery-level' is not resolvable, assuming 'zwave:device:gehirn:node13:battery-level' is initializable
25-Nov-2018 21:14:45.337 [DEBUG] [core.thing.internal.ThingManagerImpl] - Calling initialize handler for thing 'zwave:device:gehirn:node13' at 'org.openhab.binding.zwave.handler.ZWaveThingHandler@a225c'.
25-Nov-2018 21:14:45.493 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:gehirn:node13.
25-Nov-2018 21:14:45.561 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Controller status changed to ONLINE.
25-Nov-2018 21:14:45.567 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Channel zwave:device:gehirn:node13:battery-level linked - polling started.
25-Nov-2018 21:14:45.614 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Controller is ONLINE. Starting device initialisation.
25-Nov-2018 21:14:45.567 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Channel zwave:device:gehirn:node13:sensor_door linked - polling started.
25-Nov-2018 21:14:45.716 [DEBUG] [mon.registry.AbstractManagedProvider] - Updated element zwave:device:gehirn:node13 in ManagedThingProvider.
25-Nov-2018 21:14:45.904 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Updating node properties.
25-Nov-2018 21:14:45.978 [DEBUG] [mon.registry.AbstractManagedProvider] - Updated element zwave:device:gehirn:node13 in ManagedThingProvider.
25-Nov-2018 21:14:46.104 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Updating node properties. MAN=265
25-Nov-2018 21:14:46.149 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Updating node properties. MAN=265. SET. Was 265
25-Nov-2018 21:14:46.193 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Properties synchronised
25-Nov-2018 21:14:46.266 [DEBUG] [mon.registry.AbstractManagedProvider] - Updated element zwave:device:gehirn:node13 in ManagedThingProvider.
25-Nov-2018 21:14:46.428 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Update ASSOCIATION group_ZWaveAssociationGroup [index=1, name=null, profile1=null, profile2=null, associations=[node_1]]: Adding node_1
25-Nov-2018 21:14:46.472 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Configuration synchronised
25-Nov-2018 21:14:46.561 [DEBUG] [mon.registry.AbstractManagedProvider] - Updated element zwave:device:gehirn:node13 in ManagedThingProvider.
25-Nov-2018 21:14:46.762 [DEBUG] [ve.internal.protocol.ZWaveController] - Event listener added.
25-Nov-2018 21:14:46.840 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Initialising Thing Node...
25-Nov-2018 21:14:46.884 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Initialising cmd channel zwave:device:gehirn:node13:sensor_door for OpenClosedType
25-Nov-2018 21:14:46.928 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Initialising state channel zwave:device:gehirn:node13:sensor_door for OpenClosedType
25-Nov-2018 21:14:46.974 [ERROR] [nal.common.AbstractInvocationHandler] - An error occurred while calling method 'ThingHandler.initialize()' on 'org.openhab.binding.zwave.handler.ZWaveThingHandler@a225c': 1
java.lang.ArrayIndexOutOfBoundsException: 1
	at org.openhab.binding.zwave.handler.ZWaveThingHandler.initialiseNode(ZWaveThingHandler.java:226) ~[?:?]
	at org.openhab.binding.zwave.handler.ZWaveThingHandler.bridgeStatusChanged(ZWaveThingHandler.java:512) ~[?:?]
	at org.openhab.binding.zwave.handler.ZWaveThingHandler.initialize(ZWaveThingHandler.java:164) ~[?:?]
	at sun.reflect.GeneratedMethodAccessor95.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) [101:org.eclipse.smarthome.core:0.10.0.oh240M6]
	at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [101:org.eclipse.smarthome.core:0.10.0.oh240M6]
	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) [?:?]
25-Nov-2018 21:14:47.086 [ERROR] [core.thing.internal.ThingManagerImpl] - Exception occurred while initializing handler of thing 'zwave:device:gehirn:node13': 1
java.lang.ArrayIndexOutOfBoundsException: 1
	at org.openhab.binding.zwave.handler.ZWaveThingHandler.initialiseNode(ZWaveThingHandler.java:226) ~[?:?]
	at org.openhab.binding.zwave.handler.ZWaveThingHandler.bridgeStatusChanged(ZWaveThingHandler.java:512) ~[?:?]
	at org.openhab.binding.zwave.handler.ZWaveThingHandler.initialize(ZWaveThingHandler.java:164) ~[?:?]
	at sun.reflect.GeneratedMethodAccessor95.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) [101:org.eclipse.smarthome.core:0.10.0.oh240M6]
	at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [101:org.eclipse.smarthome.core:0.10.0.oh240M6]
	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) [?:?]
25-Nov-2018 21:14:47.274 [DEBUG] [mon.registry.AbstractManagedProvider] - Added new element zwave:device:gehirn:node13 to ManagedThingProvider.
25-Nov-2018 21:14:58.988 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Stop zwave:serial_zstick:gehirn
25-Nov-2018 21:14:59.045 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave controller stopping inclusion at IncludeStart
25-Nov-2018 21:14:59.078 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.
25-Nov-2018 21:14:59.124 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 251 to queue - size 1
25-Nov-2018 21:14:59.168 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
25-Nov-2018 21:14:59.214 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A 05 BB 0E 
25-Nov-2018 21:14:59.258 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A 05 BB 0E 
25-Nov-2018 21:14:59.303 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
25-Nov-2018 21:14:59.323 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
25-Nov-2018 21:14:59.346 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
25-Nov-2018 21:14:59.391 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 251: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 187
25-Nov-2018 21:14:59.424 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
25-Nov-2018 21:14:59.426 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A BB 06 00 00 0F 
25-Nov-2018 21:14:59.513 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 251: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 187
25-Nov-2018 21:14:59.543 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=187, payload=BB 06 00 00 
25-Nov-2018 21:14:59.557 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
25-Nov-2018 21:14:59.647 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=187, payload=BB 06 00 00 
25-Nov-2018 21:14:59.733 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 251: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 187
25-Nov-2018 21:14:59.769 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
25-Nov-2018 21:14:59.813 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 251: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 187
25-Nov-2018 21:14:59.858 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 251: (Callback 187)
25-Nov-2018 21:14:59.903 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
25-Nov-2018 21:14:59.947 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 251: callback 187
25-Nov-2018 21:14:59.993 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=187, payload=BB 06 00 00 
25-Nov-2018 21:15:00.037 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: Done.
25-Nov-2018 21:15:00.081 [DEBUG] [al.protocol.ZWaveInclusionController] - Inclusion event: Current state IncludeDone, new event IncludeDone
25-Nov-2018 21:15:00.088 [DEBUG] [cheduler.ExpressionThreadPoolManager] - Scheduling the task 'org.eclipse.smarthome.core.scheduler.RunnableWrapper@165c2b0' to execute in 60000 ms
25-Nov-2018 21:15:00.125 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.
25-Nov-2018 21:15:00.279 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 252 to queue - size 1
25-Nov-2018 21:15:00.348 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
25-Nov-2018 21:15:00.393 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave controller end exclusion
25-Nov-2018 21:15:00.437 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWaveController include done


(Mike Anderson) #265

Hello!

I’m using openhabian in a RPI running “Stable 2.3”. I would like to use my z-wave garage door opener and my Telegesis Zigbee controller has all of the problems mentioned in other posts. Am I correct that switching to the latest snapshot using openhabian-config will include the secure z-wave binding and the repairs made to the Zigbee binding? I understand the process for updating the z-wave binding from your description in your post, but do I need to do the same process to fix the Zigbee Telegesis “init transport layer” problem or does just up-grading to the latest snapshot fix that?

Thank you! Mike


(Elser Marc) #266

Hi Mechd, I think your mixing up things here. This binding is purely about zwave. You’re talking about a zwave garaqe opener, ok that’s fine that’s what the binding (or the underlying controller) will work. Then you’re talking about a “Zigbee Telegesis”, but Zigbee has nothing to do with ZWave. These are 2 totally different protocols. Each network needs a specific controller. So to control ZWave devices like you’re Garage opener you need a ZWave controller. To control Zigbee devices like this Telegesis you need a zigbee controller and probably a zigbee binding for openhab. Don’t know if this exists though. But Zigbee & ZWave are in noway compatible.and can not talk to each other nor does the zwave binding discussed here control Zigbee devices


(Mike Anderson) #267

Hi Again!

A big thank you to all the brains and effort to the maintainers put in to keep openHAB up to date! I updated my openhabian RPi truough the openhabian-config tool to the new 2.4 snapshot. The upgrade seems to have fixes the security issues with zwave and the Telegesis zigbee controller initialized immediately. I followed Chris Jackson’s directions to the letter and the zwave worked great and my garage door showed that it was using “security” in Habmin. The only issue was with the zigbee whereas I had to delete and re-install my zigbee devices because the looked like they were on-line but would not communicate with the controller after the upgrade. list -s | grep zigbee and list -s | grep zwave showed that both were using the 2.4xxx binding that were included in the 2.4 snapshot. Upon upgrade these bindings were installed automatically.

Thank you!
Mike


(Mr. Wiseman) #268

Hi Dim,

I finally purchased one and used your settings and everything is working with the USB power now and updating more often than using the battery mode.

Thanks again for your help!

Best, Jay


(Neil C) #269

Hi,

I am pretty new to OpenHAB, and I have been setting things up mostly with the Z-Wave controller for now. I have 7 light switches which I had previously paired to our alarm system, but they weren’t working reliably or quickly, which is why I looked into a home automation system instead. The lights are working very well, much more reliably than the alarm system ever was able to control them.

I had an old Z-Wave lock, Schlage BE469, lying around which I had bought on Amazon 2 years ago. I wasn’t able to pair it to the alarm system at the time, even after exchanging it for a replacement, so I bought another lock from the alarm vendor, and this one sat in a box, determined not to be compatible with the alarm system, which was notably picky.

I wasn’t originally planning on pairing this lock with OpenHAB, but after my success with the Z-Wave switches, I got ambitious. I was previously using 2.3 of the Z-Wave binding, but when I couldn’t get it to pair with the lock, I found version 2.4 and did the update in the addons folder. I had a couple bad attempts at performing this upgrade, but I have since deleted all my Z-Wave things, including the controller, and re-added all of them, reconnecting to the switch Items, and re-associating with my rules.

The response is always the same, regardless of how many times I do it. I go to the inbox in PaperUI, hit the plus button, and while the pinwheel is spinning, I hit the Schlage button, type the programming code plus “0”. After a few seconds, the X on the lock appears instead of the checkmark. Nothing is presented in the inbox on PaperUI. I’ve also tried it in HABmin, and the response is the same. The log on the console acknowledges binding mode, but doesn’t report anything else.

I know the lock is compatible, since it appears in the Z-Wave list under BE496 Touchscreen Deadbolt (zwave:schlage_be469_00_000).

Does anyone have any ideas of what else I can try?

Thanks,
Neil


(Scott Rushworth) #270

Exclude the lock and reset it. Also, get it as close to the controller as you can. <10 ft but closer is better.


(Neil C) #271

I’ve done factory resets on the lock twice. It was never successfully joined to a system, so there’s nothing to exclude. I’ve had the lock as close as 1 foot to the Z-Wave controller (the lock isn’t installed, it’s sitting on my desk).


(Scott Rushworth) #272

Try actually touching the lock to the controller when doing the inclusion. Start inclusion first, then put the lock in include mode. Which controller are you using, are you doing the inclusion through OH, and is the binding configured to use security? And just to be sure, which versions of OH (bottom of dashboard or Karaf) and the binding (list -s |grep zwave in Karaf) are you using? Lastly, try fresh batteries. My locks get flaky when the batteries are low. If I let the batteries go to zero, sometimes I even need to reinclude them… they’ll still be included but it’s like they lose their security key.

Afterthought… are the lock and controller using the same zwave frequency? I think Schlage only released the lock in the US.


(SiHui) #273

And don’t forget that

:sunglasses:


(Frank Edgley) #274

“4. Ensure that your default region is set so that temperates etc are properly configured. Note that thermostats will not work if this is not set.”

I’m curious about the “default region” mentioned in step #4… I live in Windsor, Ontario. Since I live right across the river from downtown Detroit (and watched their weather forecasts on TV growing up) I tend to set/read my thermostat in Fahrenheit, despite living in Canada where the official unit of measure is Celsius. Since upgrading my zwave binding and setting my location, my zwave thermostat is now cranking the temperature to 90 degrees (the maximum heating setpoint) whenever my custom climate rule executes. This is a new problem, so I suspect this new location configuration is to blame. How does this setting work exactly and why is it now necessary where it wasn’t before? Trying to diagnose the issue. Thanks in advance!


(Neil C) #275

Ok, I got it to recognize. I had to put secure inclusion mode to “All Devices” instead of “Entry Control Devices”, and it recognized it right away. Thanks for the suggestions, I didn’t think to go looking for secure inclusion mode.


(Chris Jackson) #276

With the UoM system, ESH will convert your data to/from the units relevant for your locale. When the commands are sent to the binding, they also now have the units attached, so the binding knows what to do with them. This was not the case in the past, and the binding now needs to know this or it won’t be able to send the right command to the device.


(Frank Edgley) #277

Heh. OK, so even though I have my thermostat set to display the temperature in Fahrenheit, because I live in Canada I have to pass the setpoint temp to the thermostat (via zWave) in Celsius… Either that or I guess I could always tell it that I live in Detroit (1 km away)… LOLz! Anyhow, that’s fine I guess, so long as I know what it’s doin and can compensate… Thanks so much for the info! :smiley: