Ok - I’ll take a look at this tonight… Thanks.
perfect … this also killed the working LED options for the “Configuration” channel :-/
strange
did you find some time for a look? 
Of course ;).
I made a change - I’m not sure if it will help, but if not the logging is changed, and hopefully the exception is gone at least.
ok Comet Thermostat is working 
time to change the thread…
Not sure what change that was… the device still creates no XML anymore and also the LED from Configuration Channel stopped working…
that behaviour startet after ADD was added to the the Config … is that possible?
I guess you want a debug log?
remove device and readd ?
Yes, but it’s not directly. I also changed something in the binding to try and solve an issue - not with ADD, but with REMOVE (on another device - the code is the same so it affected this as well).
Can you provide a log - maybe not the full log, but around the point at which it does the database update.
not sure if this is the correct part of the log …
and before you look at the log I need to make my findings more complicated…
When I delete and readd the device it seems to be ok in Habmin and it does not show the DATABASE UPDATE entry
however no XML is created… when I restart openhab that device stops at DATABASE UPDATE
here is the log when deleting and readding
2016-10-14 19:53:12.399 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=05 00 00 03
2016-10-14 19:53:12.402 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 7: SendData Request. CallBack ID = 5, Status = Transmission complete and ACK received(0)
2016-10-14 19:53:12.406 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Set, dest=7, callback=5, payload=07 03 25 01 FF
2016-10-14 19:53:12.409 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=05 00 00 03
2016-10-14 19:53:12.411 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=5, expected=SendData, cancelled=false transaction complete!
2016-10-14 19:53:12.412 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2016-10-14 19:53:12.413 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 7: Node advancer - UPDATE_DATABASE: Transaction complete (SendData:Request) success(true)
2016-10-14 19:53:12.414 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 7: Node advancer - checking initialisation queue. Queue size 0.
2016-10-14 19:53:12.416 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2016-10-14 19:53:12.417 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 7: Response processed after 67ms/4837ms.
2016-10-14 19:53:16.572 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Command received zwave:device:15348538564:node7:config_decimal_param61 --> 5
2016-10-14 19:53:16.573 [DEBUG] [onverter.ZWaveConfigurationConverter] - NODE 7: Config parameter 61 not found in converter
2016-10-14 19:53:16.581 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: No messages returned from converterI don’t think this is where the problem is though is it? Maybe it’s easier to email me the full log?
mhh thats all after deleting and readding it
2016-10-14 20:17:46.705 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWave controller start inclusion - mode 2
2016-10-14 20:17:46.705 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Setting controller into INCLUSION mode, highPower:true networkWide:true.
2016-10-14 20:17:46.706 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
2016-10-14 20:17:46.706 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
2016-10-14 20:17:46.708 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A C1 01 70
2016-10-14 20:17:46.710 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A C1 01 70
2016-10-14 20:17:46.717 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 01 01 00 00 B2
2016-10-14 20:17:46.720 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2016-10-14 20:17:46.722 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 07 00 4A 01 01 00 00 B2
2016-10-14 20:17:46.724 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 07 00 4A 01 01 00 00 B2
2016-10-14 20:17:46.726 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], priority=High, dest=255, callback=0, payload=01 01 00 00
2016-10-14 20:17:46.727 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: Learn ready.
2016-10-14 20:17:46.727 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInclusionEvent
2016-10-14 20:17:46.731 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], priority=High, dest=255, callback=0, payload=C1 01
2016-10-14 20:17:46.733 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], priority=High, dest=255, callback=0, payload=01 01 00 00
2016-10-14 20:17:46.734 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=AddNodeToNetwork, callback id=0, expected=AddNodeToNetwork, cancelled=false transaction complete!
2016-10-14 20:17:46.734 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2016-10-14 20:17:46.735 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Response processed after 23ms/4837ms.
2016-10-14 20:17:51.917 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandler}={thing.type=zwave:device, thing.id=zwave:device:15348538564:node7, service.id=399, service.bundleid=197, service.scope=singleton} - org.openhab.binding.zwave
2016-10-14 20:17:51.943 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler.
2016-10-14 20:17:51.961 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Controller initialised.
2016-10-14 20:17:51.961 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Controller status changed to ONLINE.
2016-10-14 20:17:51.962 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Controller is ONLINE. Starting device initialisation.
2016-10-14 20:17:51.963 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=400, service.bundleid=197, service.scope=singleton} - org.openhab.binding.zwave
2016-10-14 20:17:51.965 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Updating node properties.
2016-10-14 20:17:51.968 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Updating node properties. MAN=271
2016-10-14 20:17:51.969 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Updating node properties. MAN=271. SET. Was 271
2016-10-14 20:17:51.973 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Controller status changed to ONLINE.
2016-10-14 20:17:51.973 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Initialising Thing Node...
2016-10-14 20:17:51.974 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Controller is ONLINE. Starting device initialisation.
2016-10-14 20:17:51.976 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Polling intialised at 1800 seconds - start in 1800000 milliseconds.
2016-10-14 20:17:51.985 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.core.thing.binding.ThingHandler}={thing.type=zwave:device, thing.id=zwave:device:15348538564:node7, service.id=399, service.bundleid=197, service.scope=singleton} - org.openhab.binding.zwave
2016-10-14 20:17:51.989 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Handler disposed. Unregistering listener.
2016-10-14 20:17:52.012 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=400, service.bundleid=197, service.scope=singleton} - org.openhab.binding.zwave
2016-10-14 20:17:52.915 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandler}={thing.type=zwave:fibaro_fgwp101_00_000, thing.id=zwave:device:15348538564:node7, service.id=401, service.bundleid=197, service.scope=singleton} - org.openhab.binding.zwave
2016-10-14 20:17:53.181 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler.
2016-10-14 20:17:53.193 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Controller initialised.
2016-10-14 20:17:53.194 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Controller status changed to ONLINE.
2016-10-14 20:17:53.195 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Controller status changed to ONLINE.
2016-10-14 20:17:53.195 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Controller is ONLINE. Starting device initialisation.
2016-10-14 20:17:53.196 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Controller is ONLINE. Starting device initialisation.
2016-10-14 20:17:53.198 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Updating node properties.
2016-10-14 20:17:53.201 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Command received zwave:device:15348538564:node7:switch_binary --> REFRESH
2016-10-14 20:17:53.204 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Updating node properties. MAN=271
2016-10-14 20:17:53.204 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Updating node properties. MAN=271. SET. Was 271
2016-10-14 20:17:53.206 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Initialising Thing Node...
2016-10-14 20:17:53.207 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Initialising channel zwave:device:15348538564:node7:switch_binary
2016-10-14 20:17:53.208 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Initialising cmd channel zwave:device:15348538564:node7:switch_binary
2016-10-14 20:17:53.208 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Initialising poll channel zwave:device:15348538564:node7:switch_binary
2016-10-14 20:17:53.209 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Initialising state channel zwave:device:15348538564:node7:switch_binary
2016-10-14 20:17:53.210 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Initialising state channel zwave:device:15348538564:node7:switch_binary
2016-10-14 20:17:53.212 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=402, service.bundleid=197, service.scope=singleton} - org.openhab.binding.zwave
2016-10-14 20:17:53.211 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Polling intialised at 1800 seconds - start in 50 milliseconds.
2016-10-14 20:17:53.216 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Command received zwave:device:15348538564:node7:sensor_power --> REFRESH
2016-10-14 20:17:53.217 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Polling intialised at 1800 seconds - start in 50 milliseconds.
2016-10-14 20:17:53.218 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Command received zwave:device:15348538564:node7:meter_kwh --> REFRESH
2016-10-14 20:17:53.219 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Polling intialised at 1800 seconds - start in 50 milliseconds.
2016-10-14 20:17:53.221 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Command received zwave:device:15348538564:node7:meter_watts --> REFRESH
2016-10-14 20:17:53.222 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Polling intialised at 1800 seconds - start in 50 milliseconds.
2016-10-14 20:17:53.224 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Command received zwave:device:15348538564:node7:meter_reset --> REFRESH
2016-10-14 20:17:53.225 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Polling intialised at 1800 seconds - start in 50 milliseconds.
2016-10-14 20:17:53.227 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Command received zwave:device:15348538564:node7:config_decimal_param61 --> REFRESH
2016-10-14 20:17:53.228 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Polling intialised at 1800 seconds - start in 50 milliseconds.
2016-10-14 20:17:53.214 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Initialising channel zwave:device:15348538564:node7:sensor_power
2016-10-14 20:17:53.231 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Initialising cmd channel zwave:device:15348538564:node7:sensor_power
2016-10-14 20:17:53.232 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Initialising poll channel zwave:device:15348538564:node7:sensor_power
2016-10-14 20:17:53.232 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Initialising state channel zwave:device:15348538564:node7:sensor_power
2016-10-14 20:17:53.233 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Initialising channel zwave:device:15348538564:node7:meter_kwh
2016-10-14 20:17:53.233 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Initialising cmd channel zwave:device:15348538564:node7:meter_kwh
2016-10-14 20:17:53.234 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Initialising poll channel zwave:device:15348538564:node7:meter_kwh
2016-10-14 20:17:53.234 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Initialising state channel zwave:device:15348538564:node7:meter_kwh
2016-10-14 20:17:53.234 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Initialising channel zwave:device:15348538564:node7:meter_watts
2016-10-14 20:17:53.235 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Initialising cmd channel zwave:device:15348538564:node7:meter_watts
2016-10-14 20:17:53.236 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Initialising poll channel zwave:device:15348538564:node7:meter_watts
2016-10-14 20:17:53.236 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Command received zwave:device:15348538564:node7:config_decimal_param62 --> REFRESH
2016-10-14 20:17:53.236 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Initialising state channel zwave:device:15348538564:node7:meter_watts
2016-10-14 20:17:53.237 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Polling intialised at 1800 seconds - start in 50 milliseconds.
2016-10-14 20:17:53.237 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Initialising channel zwave:device:15348538564:node7:meter_reset
2016-10-14 20:17:53.238 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Initialising cmd channel zwave:device:15348538564:node7:meter_reset
2016-10-14 20:17:53.239 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Initialising poll channel zwave:device:15348538564:node7:meter_reset
2016-10-14 20:17:53.239 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Command received zwave:device:15348538564:node7:notification_send --> REFRESH
2016-10-14 20:17:53.239 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Initialising state channel zwave:device:15348538564:node7:meter_reset
2016-10-14 20:17:53.240 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Polling intialised at 1800 seconds - start in 50 milliseconds.
2016-10-14 20:17:53.240 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Initialising channel zwave:device:15348538564:node7:config_decimal_param61
2016-10-14 20:17:53.241 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Initialising cmd channel zwave:device:15348538564:node7:config_decimal_param61
2016-10-14 20:17:53.244 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Initialising poll channel zwave:device:15348538564:node7:config_decimal_param61
2016-10-14 20:17:53.246 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Initialising state channel zwave:device:15348538564:node7:config_decimal_param61
2016-10-14 20:17:53.248 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Initialising channel zwave:device:15348538564:node7:config_decimal_param62
2016-10-14 20:17:53.250 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Initialising cmd channel zwave:device:15348538564:node7:config_decimal_param62
2016-10-14 20:17:53.252 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Initialising poll channel zwave:device:15348538564:node7:config_decimal_param62
2016-10-14 20:17:53.253 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Initialising state channel zwave:device:15348538564:node7:config_decimal_param62
2016-10-14 20:17:53.254 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Initialising channel zwave:device:15348538564:node7:notification_send
2016-10-14 20:17:53.256 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Initialising cmd channel zwave:device:15348538564:node7:notification_send
2016-10-14 20:17:53.257 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Initialising poll channel zwave:device:15348538564:node7:notification_send
2016-10-14 20:17:53.258 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Initialising state channel zwave:device:15348538564:node7:notification_send
2016-10-14 20:17:53.259 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Polling intialised at 1800 seconds - start in 1800000 milliseconds.
2016-10-14 20:18:13.428 [DEBUG] [ve.internal.protocol.ZWaveController] - Stopping inclusion timer.
2016-10-14 20:18:13.429 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.
Hmm - isn’t there all the initialisation stuff - eg -
2016-10-14 20:13:23.412 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: Node advancer: STATIC_VALUES - checking PROTECTION
no
I delete the device in habmin
Start inclusion (just to get the device back in the inbox)
add the device from the inbox
this does not cause to have all the initialisation stuff
this only comes up once I restart openhab… I think thats also the reason for:
that said. let me restart openhab for you
as I said … restarting openhab is the only way to get that logging. hope that is what you are looking for:
2016-10-14 21:03:04.716 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 7: Node advancer - advancing to UPDATE_DATABASE
2016-10-14 21:03:04.717 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInitializationStateEvent
2016-10-14 21:03:04.718 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Got an event from Z-Wave network: ZWaveInitializationStateEvent
2016-10-14 21:03:04.731 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 7: Node advancer: loop - UPDATE_DATABASE try 0: stageAdvanced(true)
2016-10-14 21:03:04.739 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 7: Node advancer: UPDATE_DATABASE
2016-10-14 21:03:04.748 [ERROR] [ve.internal.protocol.ZWaveController] - Exception during ZWave thread: Input 2. {}
java.lang.NullPointerException
at org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveCommandClass$CommandClass.getCommandClass(ZWaveCommandClass.java:622)[197:org.openhab.binding.zwave:2.0.0.201610140851]
at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.advanceNodeStage(ZWaveNodeInitStageAdvancer.java:734)[197:org.openhab.binding.zwave:2.0.0.201610140851]
at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.handleNodeQueue(ZWaveNodeInitStageAdvancer.java:230)[197:org.openhab.binding.zwave:2.0.0.201610140851]
at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.ZWaveIncomingEvent(ZWaveNodeInitStageAdvancer.java:1294)[197:org.openhab.binding.zwave:2.0.0.201610140851]
at org.openhab.binding.zwave.internal.protocol.ZWaveController.notifyEventListeners(ZWaveController.java:546)[197:org.openhab.binding.zwave:2.0.0.201610140851]
at org.openhab.binding.zwave.internal.protocol.ZWaveController.handleIncomingRequestMessage(ZWaveController.java:249)[197:org.openhab.binding.zwave:2.0.0.201610140851]
at org.openhab.binding.zwave.internal.protocol.ZWaveController.handleIncomingMessage(ZWaveController.java:213)[197:org.openhab.binding.zwave:2.0.0.201610140851]
at org.openhab.binding.zwave.internal.protocol.ZWaveController.access$7(ZWaveController.java:207)[197:org.openhab.binding.zwave:2.0.0.201610140851]
at org.openhab.binding.zwave.internal.protocol.ZWaveController$ZWaveInputThread.run(ZWaveController.java:1303)[197:org.openhab.binding.zwave:2.0.0.201610140851]
2016-10-14 21:03:09.576 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 7: Timeout while sending message. Requeueing - 2 attempts left!
2016-10-14 21:03:09.577 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 7: Got an error while sending data. Resending message.
2016-10-14 21:03:09.578 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 4. Queue={}
2016-10-14 21:03:09.579 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 3
2016-10-14 21:03:09.581 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 07 03 86 13 7A 25 C5 ED
2016-10-14 21:03:09.583 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 7: Sending REQUEST Message = 01 0A 00 13 07 03 86 13 7A 25 C5 ED
2016-10-14 21:03:09.594 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
2016-10-14 21:03:09.597 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2016-10-14 21:03:09.606 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8
2016-10-14 21:03:09.608 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8
2016-10-14 21:03:09.609 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01
2016-10-14 21:03:09.610 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 7: Sent Data successfully placed on stack.
2016-10-14 21:03:09.612 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 C5 00 00 02 2C
2016-10-14 21:03:09.616 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2016-10-14 21:03:09.618 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 C5 00 00 02 00 00 22
2016-10-14 21:03:09.620 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 C5 00 00 02 00 00 22
2016-10-14 21:03:09.622 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=C5 00 00 02
2016-10-14 21:03:09.624 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0A 00 04 00 07 04 86 14 7A 01 1B
2016-10-14 21:03:09.624 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 7: SendData Request. CallBack ID = 197, Status = Transmission complete and ACK received(0)
2016-10-14 21:03:09.628 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Config, dest=7, callback=197, payload=07 03 86 13 7A
2016-10-14 21:03:09.630 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=C5 00 00 02
2016-10-14 21:03:09.631 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=197, expected=ApplicationCommandHandler, cancelled=false MISMATCH
2016-10-14 21:03:09.632 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2016-10-14 21:03:09.634 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 04 00 07 04 86 14 7A 01 1B
2016-10-14 21:03:09.636 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 0A 00 04 00 07 04 86 14 7A 01 1B
2016-10-14 21:03:09.638 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 07 04 86 14 7A 01
2016-10-14 21:03:09.639 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 7: Application Command Request (ALIVE:UPDATE_DATABASE)
2016-10-14 21:03:09.640 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 7: Incoming command class VERSION
2016-10-14 21:03:09.641 [DEBUG] [ommandclass.ZWaveVersionCommandClass] - NODE 7: Received COMMAND_CLASS_VERSION command V1
2016-10-14 21:03:09.642 [DEBUG] [ommandclass.ZWaveVersionCommandClass] - NODE 7: Process Version Command Class Report
2016-10-14 21:03:09.643 [DEBUG] [ommandclass.ZWaveVersionCommandClass] - NODE 7: Requested Command Class = FIRMWARE_UPDATE_MD, Version = 1
2016-10-14 21:03:09.644 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 7: Version = 1, version set. Enabling extra functionality.
2016-10-14 21:03:09.646 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Config, dest=7, callback=197, payload=07 03 86 13 7A
2016-10-14 21:03:09.648 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 07 04 86 14 7A 01
2016-10-14 21:03:09.649 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationCommandHandler, callback id=197, expected=ApplicationCommandHandler, cancelled=false transaction complete!
2016-10-14 21:03:09.650 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2016-10-14 21:03:09.652 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2016-10-14 21:03:09.653 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 7: Node advancer - UPDATE_DATABASE: Transaction complete (SendData:Request) success(true)
2016-10-14 21:03:09.654 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 7: Node advancer - checking initialisation queue. Queue size 0.
2016-10-14 21:03:09.656 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 7: Response processed after 72ms/3957ms.
2016-10-14 21:03:09.658 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 2
2016-10-14 21:03:09.660 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 08 00 13 06 01 00 25 A8 6E
2016-10-14 21:03:09.663 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 6: Sending REQUEST Message = 01 08 00 13 06 01 00 25 A8 6E
2016-10-14 21:03:09.670 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 7: Stage UPDATE_DATABASE. Initialisation retry timer triggered. Increased to 10000
2016-10-14 21:03:09.671 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 7: Node advancer - UPDATE_DATABASE: queue length(0), free to send(true)
2016-10-14 21:03:09.672 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 7: Initialisation retry timer started 10000
2016-10-14 21:03:09.673 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 7: Node advancer: loop - UPDATE_DATABASE try 1: stageAdvanced(false)
2016-10-14 21:03:09.674 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 7: Node advancer: UPDATE_DATABASE
Let’s try this -:
I try once the bundles are compiled
Hmmm - I must have kicked off the wrong build - I’ve just started the right one (I hope ;)).
ok - the device initialisation works again.
Alarm Command Class was added
When I send an alarm notification to the plug it still does not illuminate according to parameter 63
08:19:10.462 [INFO ] [smarthome.event.ItemCommandEvent ] - Item 'node7_sendnoti' received command 1
08:19:10.469 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Command received zwave:device:15348538564:node7:notification_send --> 1
08:19:10.471 [DEBUG] [.commandclass.ZWaveAlarmCommandClass] - NODE 7: Creating new message for command NOTIFICATION_REPORT
08:19:10.473 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
08:19:10.473 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
08:19:10.488 [INFO ] [marthome.event.ItemStateChangedEvent] - node7_sendnoti changed from 3 to 1
08:19:10.478 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0F 00 13 07 08 71 05 00 00 00 00 01 01 25 38 85
08:19:10.511 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 7: Sending REQUEST Message = 01 0F 00 13 07 08 71 05 00 00 00 00 01 01 25 38 85
08:19:10.535 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
08:19:10.538 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
08:19:10.540 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8
08:19:10.543 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8
08:19:10.545 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01
08:19:10.548 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 7: Sent Data successfully placed on stack.
08:19:10.552 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 38 00 00 03 D0
08:19:10.561 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
08:19:10.566 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 38 00 00 03 00 00 DE
08:19:10.571 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 38 00 00 03 00 00 DE
08:19:10.577 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=38 00 00 03
08:19:10.581 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 7: SendData Request. CallBack ID = 56, Status = Transmission complete and ACK received(0)
08:19:10.584 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 7: Starting initialisation from DONE
08:19:10.588 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@1802991 already registered
08:19:10.592 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=7, callback=56, payload=07 08 71 05 00 00 00 00 01 01
08:19:10.596 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=38 00 00 03
08:19:10.599 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=56, expected=SendData, cancelled=false transaction complete!
08:19:10.602 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
08:19:10.605 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
08:19:10.608 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 7: Response processed after 84ms/4261ms.
So this is for the wall plug right? I now have one of these to play with so will try and do some tests today or tomorrow.
Yes - perfect!
Not so perfect - I lied to you … I have the Aeon version which supports the COLOR command class, not the Fibaro…
Can you confirm parameter 34 is set to 63, and parameter 35 is set to something other than 0 (the default)?
The notification being sent looks ok. I can mess around with some of the parts of the message if needbe (one in particular might need to be set, but this works ok with other devices so I’d like to check config is right first…