Testing Z-Wave binding on openHAB-2

shorty707 · March 26, 2016, 7:43pm

that pending feature sounds very good

Here are 2 issues with the current version:

my (second) Aeon ZW100 Multisensor now also shows I saw that device had a recent edit in the Db… mhh

10:49:01.690 [ERROR] [ding.zwave.handler.ZWaveThingHandler] - NODE 9: Size error 2<>1 from config_42_2
10:49:02.024 [INFO ] [marthome.event.ConfigStatusInfoEvent] - org.eclipse.smarthome.config.core.status.events.ConfigStatusInfoEvent@121bb36
10:49:02.039 [INFO ] [smarthome.event.ThingUpdatedEvent   ] - Thing 'zwave:device:15348538564:node9' has been updated.
10:49:02.723 [INFO ] [smarthome.event.ThingUpdatedEvent   ] - Thing 'zwave:device:15348538564:node9' has been updated.
10:49:02.737 [INFO ] [marthome.event.ConfigStatusInfoEvent] - org.eclipse.smarthome.config.core.status.events.ConfigStatusInfoEvent@848a24
10:49:02.880 [ERROR] [ding.zwave.handler.ZWaveThingHandler] - NODE 9: Size error 2<>1 from config_44_2

my Fibaro RGBW sometimes causes:

20:34:23.433 [INFO ] [smarthome.event.ThingUpdatedEvent   ] - Thing 'zwave:device:15348538564:node12' has been updated.
java.lang.ArrayIndexOutOfBoundsException: 1120:34:23.549 [ERROR] [ve.internal.protocol.ZWaveController] - Exception during ZWave thread: Input 2.

	at org.openhab.binding.zwave.internal.protocol.SerialMessage.getMessagePayloadByte(SerialMessage.java:337)
	at org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveMeterCommandClass.handleApplicationCommandRequest(ZWaveMeterCommandClass.java:136)
	at org.openhab.binding.zwave.internal.protocol.serialmessage.ApplicationCommandMessageClass.handleRequest(ApplicationCommandMessageClass.java:118)
	at org.openhab.binding.zwave.internal.protocol.ZWaveController.handleIncomingRequestMessage(ZWaveController.java:240)
	at org.openhab.binding.zwave.internal.protocol.ZWaveController.handleIncomingMessage(ZWaveController.java:207)
	at org.openhab.binding.zwave.internal.protocol.ZWaveController.access$6(ZWaveController.java:201)
	at org.openhab.binding.zwave.internal.protocol.ZWaveController$ZWaveInputThread.run(ZWaveController.java:1072)
20:34:28.439 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 12: Timeout while sending message. Requeueing - 2 attempts left!
20:34:28.440 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 12: Got an error while sending data. Resending message.
java.lang.ArrayIndexOutOfBoundsException: 11
20:34:28.560 [ERROR] [ve.internal.protocol.ZWaveController] - Exception during ZWave thread: Input 2.
	at org.openhab.binding.zwave.internal.protocol.SerialMessage.getMessagePayloadByte(SerialMessage.java:337)
	at org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveMeterCommandClass.handleApplicationCommandRequest(ZWaveMeterCommandClass.java:136)
	at org.openhab.binding.zwave.internal.protocol.serialmessage.ApplicationCommandMessageClass.handleRequest(ApplicationCommandMessageClass.java:118)
	at org.openhab.binding.zwave.internal.protocol.ZWaveController.handleIncomingRequestMessage(ZWaveController.java:240)
	at org.openhab.binding.zwave.internal.protocol.ZWaveController.handleIncomingMessage(ZWaveController.java:207)
	at org.openhab.binding.zwave.internal.protocol.ZWaveController.access$6(ZWaveController.java:201)
	at org.openhab.binding.zwave.internal.protocol.ZWaveController$ZWaveInputThread.run(ZWaveController.java:1072)
20:34:33.450 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 12: Timeout while sending message. Requeueing - 1 attempts left!
20:34:33.451 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 12: Got an error while sending data. Resending message.
java.lang.ArrayIndexOutOfBoundsException: 11
20:34:33.568 [ERROR] [ve.internal.protocol.ZWaveController] - Exception during ZWave thread: Input 2.
	at org.openhab.binding.zwave.internal.protocol.SerialMessage.getMessagePayloadByte(SerialMessage.java:337)
	at org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveMeterCommandClass.handleApplicationCommandRequest(ZWaveMeterCommandClass.java:136)
	at org.openhab.binding.zwave.internal.protocol.serialmessage.ApplicationCommandMessageClass.handleRequest(ApplicationCommandMessageClass.java:118)
	at org.openhab.binding.zwave.internal.protocol.ZWaveController.handleIncomingRequestMessage(ZWaveController.java:240)
	at org.openhab.binding.zwave.internal.protocol.ZWaveController.handleIncomingMessage(ZWaveController.java:207)
	at org.openhab.binding.zwave.internal.protocol.ZWaveController.access$6(ZWaveController.java:201)
	at org.openhab.binding.zwave.internal.protocol.ZWaveController$ZWaveInputThread.run(ZWaveController.java:1072)

chris · March 26, 2016, 8:09pm

Only 2? I’m sure there will be more .

Well I guess it’s no surprise that it’s doing the same thing as the other… I guess this should be changed, but it would be really great if you can capture a debug log of this message so I can actually see the data…

This likely means that the device is sending corrupted data, which does happen occasionally. Again, a debug log of this would be very useful, although I am adding an exception into the code to better handle exactly this issue…

vespaman · March 26, 2016, 10:13pm

Frequent errors in my log, current version;

22:37:40.200 [WARN ] [ocol.ZWaveController$ZWaveSendThread] - NODE 59: Too many retries. Discarding message: Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=59, payload=3B 06 60 0D 01 04 32 01 
22:37:40.200 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 28
22:37:40.200 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0D 00 13 3B 06 60 0D 01 04 32 01 25 FF 5D 
22:37:40.201 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 59: Sending REQUEST Message = 01 0D 00 13 3B 06 60 0D 01 04 32 01 25 FF 5D 
22:37:40.208 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
22:37:40.209 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
22:37:40.209 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8 
22:37:40.209 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8 
22:37:40.209 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, payload=01 
22:37:40.209 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 59: Sent Data successfully placed on stack.
22:37:40.228 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 FF 00 00 03 17 
22:37:40.228 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
22:37:40.228 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 FF 00 00 03 00 00 19 
22:37:40.228 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 FF 00 00 03 00 00 19 
22:37:40.228 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, payload=FF 00 00 03 
22:37:40.228 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 59: SendData Request. CallBack ID = 255, Status = Transmission complete and ACK received(0)
22:37:40.228 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent message Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=59, payload=3B 06 60 0D 01 04 32 01 
22:37:40.228 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv message Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, payload=FF 00 00 03 
22:37:40.229 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=255, expected=ApplicationCommandHandler, cancelled=false      MISMATCH
22:37:40.244 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 12 00 04 00 3B 0C 60 0D 04 01 32 02 01 84 00 00 03 B8 B8 
22:37:40.244 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
22:37:40.244 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 12 00 04 00 3B 0C 60 0D 04 01 32 02 01 84 00 00 03 B8 B8 
22:37:40.244 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 12 00 04 00 3B 0C 60 0D 04 01 32 02 01 84 00 00 03 B8 B8 
22:37:40.244 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, payload=00 3B 0C 60 0D 04 01 32 02 01 84 00 00 03 B8 
22:37:40.244 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 59: Application Command Request (ALIVE:DONE)
22:37:40.244 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 59: Incoming command class MULTI_INSTANCE
22:37:40.245 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 59: Received Multi-instance/Multi-channel Request
22:37:40.245 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 59: Requested Command Class = METER (0x32)
22:37:40.245 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 59: Endpoint = 4, calling handleApplicationCommandRequest.
22:37:40.245 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 59: Received Meter Request
22:37:40.245 [ERROR] [ve.internal.protocol.ZWaveController] - Exception during ZWave thread: Input 2.
java.lang.ArrayIndexOutOfBoundsException

shorty707 · March 27, 2016, 7:24am

dont see that tested on a battery device

shorty707 · March 27, 2016, 7:50am

the new device
http://www.cd-jackson.com/index.php/zwave/zwave-device-database/zwave-device-list/devicesummary/290

Is not resolved from unknown to the correct device on wakeup:

09:46:09.495 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 1B 00 49 84 11 15 04 07 01 5E 80 71 85 70 72 86 30 31 84 59 73 5A 8F 98 7A EF 20 D6 
09:46:09.498 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
09:46:09.500 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 1B 00 49 84 11 15 04 07 01 5E 80 71 85 70 72 86 30 31 84 59 73 5A 8F 98 7A EF 20 D6 
09:46:09.502 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 1B 00 49 84 11 15 04 07 01 5E 80 71 85 70 72 86 30 31 84 59 73 5A 8F 98 7A EF 20 D6 
09:46:09.503 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationUpdate[0x49], type=Request[0x00], priority=High, dest=255, payload=84 11 15 04 07 01 5E 80 71 85 70 72 86 30 31 84 59 73 5A 8F 98 7A EF 20 
09:46:09.504 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 17: Application update request. Node information received.
09:46:09.520 [WARN ] [tocol.commandclass.ZWaveCommandClass] - NODE 17: Unsupported command class ASSOCIATION_GROUP_INFO
09:46:09.527 [WARN ] [tocol.commandclass.ZWaveCommandClass] - NODE 17: Unsupported command class FIRMWARE_UPDATE_MD
09:46:09.529 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 17: Is awake with 0 messages in the wake-up queue.
09:46:09.531 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveWakeUpEvent
09:46:09.533 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent message Message: class=SendData[0x13], type=Request[0x00], priority=Immediate, dest=17, payload=11 02 84 08 
09:46:09.536 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv message Message: class=ApplicationUpdate[0x49], type=Request[0x00], priority=High, dest=255, payload=84 11 15 04 07 01 5E 80 71 85 70 72 86 30 31 84 59 73 5A 8F 98 7A EF 20 
09:46:09.538 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationUpdate, callback id=76, expected=SendData, cancelled=false      MISMATCH
09:46:10.533 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 17: No more messages, go back to sleep
09:46:10.534 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 17: Creating new message for application command WAKE_UP_NO_MORE_INFORMATION
09:46:10.535 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
09:46:10.535 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
09:46:10.537 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 11 02 84 08 25 4D 12 
09:46:10.538 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 17: Sending REQUEST Message = 01 09 00 13 11 02 84 08 25 4D 12 
09:46:10.549 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
09:46:10.551 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
09:46:10.552 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8 
09:46:10.553 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8 
09:46:10.554 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, payload=01 
09:46:10.555 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 17: Sent Data successfully placed on stack.
09:46:10.564 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 4D 00 00 02 A4 
09:46:10.567 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
09:46:10.570 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 4D 00 00 02 00 00 AA 
09:46:10.573 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 4D 00 00 02 00 00 AA 
09:46:10.576 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, payload=4D 00 00 02 
09:46:10.578 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 17: SendData Request. CallBack ID = 77, Status = Transmission complete and ACK received(0)
09:46:10.581 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent message Message: class=SendData[0x13], type=Request[0x00], priority=Immediate, dest=17, payload=11 02 84 08 
09:46:10.585 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv message Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, payload=4D 00 00 02 
09:46:10.587 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=77, expected=SendData, cancelled=false        transaction complete!
09:46:10.589 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
09:46:10.590 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 17: Went to sleep
09:46:10.591 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 17: Is sleeping
09:46:10.593 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 17: Response processed after 54ms/3951ms.

chris · March 27, 2016, 7:55am

Really? And you are using the latest versions of everything?

chris · March 27, 2016, 7:58am

I’m not sure what you’re trying to show with this log? If the device isn’t known, then please provide a log during discovery.

shorty707 · March 27, 2016, 8:02am

yes
ran my nightly script this morning
this refrehs everything… esh + any binding i have

chris · March 27, 2016, 8:02am

And HABmin?

shorty707 · March 27, 2016, 8:02am

oops

shorty707 · March 27, 2016, 8:09am

you need that? (its node 17)

10:06:09.773 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
10:06:09.773 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
10:06:09.774 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - Starting ZWave inclusion scan for zwave:serial_zstick:15348538564
10:06:09.774 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 16: Device discovery completed
10:06:09.775 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 4A 05 B4 
10:06:09.776 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 4A 05 B4 
10:06:09.784 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 17: Device discovery completed
10:06:09.795 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 17: Device could not be resolved to a thingType! 7FFFFFFF:7FFFFFFF:7FFFFFFF::0.0
10:06:09.930 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 02 06 11 00 A7 
10:06:09.934 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
10:06:09.935 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 07 00 4A 02 06 11 00 A7 
10:06:09.936 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 07 00 4A 02 06 11 00 A7 
10:06:09.937 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], priority=High, dest=255, payload=02 06 11 00 
10:06:09.938 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: Done.
10:06:09.939 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInclusionEvent
10:06:09.940 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent message Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], priority=High, dest=255, payload=05 
10:06:09.941 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv message Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], priority=High, dest=255, payload=02 06 11 00 
10:06:09.941 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=AddNodeToNetwork, callback id=0, expected=AddNodeToNetwork, cancelled=false        transaction complete!
10:06:09.942 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
10:06:09.942 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Response processed after 165ms/3951ms.
10:06:09.979 [INFO ] [smarthome.event.InboxAddedEvent     ] - Discovery Result with UID 'zwave:device:15348538564:node17' has been added.
10:06:09.982 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'zwave:device:15348538564:node17' to inbox.
10:06:09.984 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 3: Device discovery completed
10:06:09.993 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 3: Device could not be resolved to a thingType! 7FFFFFFF:7FFFFFFF:7FFFFFFF::0.0
10:06:09.996 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 5: Device discovery completed
10:06:10.005 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 5: Device could not be resolved to a thingType! 7FFFFFFF:7FFFFFFF:7FFFFFFF::0.0
10:06:10.008 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 7: Device discovery completed
10:06:10.017 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 7: Device could not be resolved to a thingType! 7FFFFFFF:7FFFFFFF:7FFFFFFF::0.0
10:06:10.019 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 9: Device discovery completed
10:06:10.029 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 11: Device discovery completed
10:06:10.038 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 12: Device discovery completed
10:06:10.046 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 13: Device discovery completed
10:06:10.055 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 15: Device discovery completed
10:06:10.065 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 15: Device could not be resolved to a thingType! 7FFFFFFF:7FFFFFFF:7FFFFFFF::0.0
10:06:10.067 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Setting controller into INCLUSION mode.
10:06:10.068 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
10:06:10.068 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
10:06:10.069 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A 81 FF CE 
10:06:10.070 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A 81 FF CE 
10:06:10.075 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A FF 01 00 00 4C 
10:06:10.078 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
10:06:10.079 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 07 00 4A FF 01 00 00 4C 
10:06:10.081 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 07 00 4A FF 01 00 00 4C 
10:06:10.082 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], priority=High, dest=255, payload=FF 01 00 00 
10:06:10.082 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: Learn ready.
10:06:10.083 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInclusionEvent
10:06:10.084 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent message Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], priority=High, dest=255, payload=81 FF 
10:06:10.085 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv message Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], priority=High, dest=255, payload=FF 01 00 00 
10:06:10.086 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=AddNodeToNetwork, callback id=0, expected=AddNodeToNetwork, cancelled=false        transaction complete!
10:06:10.086 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
10:06:10.087 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Response processed after 15ms/3951ms.
10:06:20.416 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 1C 00 4A FF 02 11 15 04 07 01 5E 80 71 85 70 72 86 30 31 84 59 73 5A 8F 98 7A EF 20 AB 
10:06:20.425 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
10:06:20.427 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 1C 00 4A FF 02 11 15 04 07 01 5E 80 71 85 70 72 86 30 31 84 59 73 5A 8F 98 7A EF 20 AB 
10:06:20.429 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 1C 00 4A FF 03 11 15 04 07 01 5E 80 71 85 70 72 86 30 31 84 59 73 5A 8F 98 7A EF 20 AA 
10:06:20.429 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 1C 00 4A FF 02 11 15 04 07 01 5E 80 71 85 70 72 86 30 31 84 59 73 5A 8F 98 7A EF 20 AB 
10:06:20.431 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], priority=High, dest=255, payload=FF 02 11 15 04 07 01 5E 80 71 85 70 72 86 30 31 84 59 73 5A 8F 98 7A EF 20 
10:06:20.432 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: New node found.
10:06:20.433 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent message Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], priority=High, dest=255, payload=81 FF 
10:06:20.435 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv message Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], priority=High, dest=255, payload=FF 02 11 15 04 07 01 5E 80 71 85 70 72 86 30 31 84 59 73 5A 8F 98 7A EF 20 
10:06:20.436 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 1C 00 4A FF 05 11 15 04 07 01 5E 80 71 85 70 72 86 30 31 84 59 73 5A 8F 98 7A EF 20 AC 
10:06:20.440 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=AddNodeToNetwork, callback id=0, expected=AddNodeToNetwork, cancelled=false        transaction complete!
10:06:20.440 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
10:06:20.441 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=1
10:06:20.443 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 1C 00 4A FF 03 11 15 04 07 01 5E 80 71 85 70 72 86 30 31 84 59 73 5A 8F 98 7A EF 20 AA 
10:06:20.445 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 1C 00 4A FF 03 11 15 04 07 01 5E 80 71 85 70 72 86 30 31 84 59 73 5A 8F 98 7A EF 20 AA 
10:06:20.446 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], priority=High, dest=255, payload=FF 03 11 15 04 07 01 5E 80 71 85 70 72 86 30 31 84 59 73 5A 8F 98 7A EF 20 
10:06:20.447 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - NODE 17: Adding slave.
10:06:20.448 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInclusionEvent
10:06:20.448 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 17: Including node.
10:06:20.449 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 17: Newly included node already exists - not initialising.
10:06:20.450 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent message Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], priority=High, dest=255, payload=81 FF 
10:06:20.452 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv message Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], priority=High, dest=255, payload=FF 03 11 15 04 07 01 5E 80 71 85 70 72 86 30 31 84 59 73 5A 8F 98 7A EF 20 
10:06:20.452 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=AddNodeToNetwork, callback id=0, expected=AddNodeToNetwork, cancelled=false        transaction complete!
10:06:20.453 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
10:06:20.454 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
10:06:20.455 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 1C 00 4A FF 05 11 15 04 07 01 5E 80 71 85 70 72 86 30 31 84 59 73 5A 8F 98 7A EF 20 AC 
10:06:20.457 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 1C 00 4A FF 05 11 15 04 07 01 5E 80 71 85 70 72 86 30 31 84 59 73 5A 8F 98 7A EF 20 AC 
10:06:20.458 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], priority=High, dest=255, payload=FF 05 11 15 04 07 01 5E 80 71 85 70 72 86 30 31 84 59 73 5A 8F 98 7A EF 20 
10:06:20.459 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: Protocol done.
10:06:20.460 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent message Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], priority=High, dest=255, payload=81 FF 
10:06:20.462 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv message Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], priority=High, dest=255, payload=FF 05 11 15 04 07 01 5E 80 71 85 70 72 86 30 31 84 59 73 5A 8F 98 7A EF 20 
10:06:20.462 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=AddNodeToNetwork, callback id=0, expected=AddNodeToNetwork, cancelled=false        transaction complete!
10:06:20.463 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
10:06:39.778 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.
10:06:39.781 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
10:06:39.781 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
10:06:39.783 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 4A 05 B4 
10:06:39.784 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 4A 05 B4 
10:06:39.937 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A FF 06 11 00 5A 
10:06:39.939 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
10:06:39.940 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 07 00 4A FF 06 11 00 5A 
10:06:39.941 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 07 00 4A FF 06 11 00 5A 
10:06:39.942 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], priority=High, dest=255, payload=FF 06 11 00 
10:06:39.943 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: Done.

chris · March 27, 2016, 8:12am

Sorry - should have been more specific… I meant during the initialisation (which is where the ESH discovery happens) - not the inclusion… There’s two parts I want to see - firstly that it’s got the manufacturer data, and secondly what happens when it tries to run through the discovery inbox addition…

shorty707 · March 27, 2016, 9:22am

maybe its time for me to learn the best way to do this…
I always try to trigger the needed and catch the log directly on karaf shell …

Is it better to just let it run until it happens and find the appropriate part in habmin log viewer for that node?
For “initializaton” of an unknown node… there is no option to “reinitialize” in habmin… so should I just leave logging on debug and wait?

chris · March 27, 2016, 9:26am

In my opinion, yes. That way you capture everything that’s happening. If you’re only logging information when you’re looking for a known problem, then you’ll never find the unknown ones (ie the ones you weren’t expecting).

No - this is a good point. I’ll add this (it was possible in HABmin1 and it is useful).

The easiest way at the moment is to delete the XML for this node (if it exists) and restart the binding. The problem of course is that his will generate a lot of traffic, so you’ll need to filter. However, given this is a battery device, you can choose when to wake it up, so just wait until after all the other startup traffic has completed.

chris · March 27, 2016, 9:43am

So - it seems this is already included and I’d forgotten I’d added it… It’s in the tools menu - select the device, select advanced mode, then you should see it…

shorty707 · March 27, 2016, 9:52am

not really sure if that is the correct logging now:

11:49:40.256 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 1B 00 49 84 11 15 04 07 01 5E 80 71 85 70 72 86 30 31 84 59 73 5A 8F 98 7A EF 20 D6 
11:49:40.259 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
11:49:40.261 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 1B 00 49 84 11 15 04 07 01 5E 80 71 85 70 72 86 30 31 84 59 73 5A 8F 98 7A EF 20 D6 
11:49:40.262 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 1B 00 49 84 11 15 04 07 01 5E 80 71 85 70 72 86 30 31 84 59 73 5A 8F 98 7A EF 20 D6 
11:49:40.264 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationUpdate[0x49], type=Request[0x00], priority=High, dest=255, payload=84 11 15 04 07 01 5E 80 71 85 70 72 86 30 31 84 59 73 5A 8F 98 7A EF 20 
11:49:40.269 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 17: Application update request. Node information received.
11:49:40.270 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 17: Node is ALIVE. Init stage is PING:{}.
11:49:40.271 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveNodeStatusEvent
11:49:40.271 [DEBUG] [g.zwave.internal.ZWaveNetworkMonitor] - NODE 17: Node Status event - Node is ALIVE
11:49:40.272 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 17: Node Status event during initialisation - Node is ALIVE
11:49:40.272 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 17: Node advancer - PING: queue length(0), free to send(true)
11:49:40.272 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 17: Node advancer: loop - PING try 1: stageAdvanced(false)
11:49:40.273 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 17: Node advancer: PING - send NoOperation
11:49:40.273 [DEBUG] [ndclass.ZWaveNoOperationCommandClass] - NODE 17: Creating new message for command No Operation
11:49:40.274 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 17: Node advancer - queued packet. Queue length is 1
11:49:40.274 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
11:49:40.274 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
11:49:40.275 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 17: Node Status event - Node is ALIVE
11:49:40.275 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 08 00 13 11 01 00 25 14 C5 
11:49:40.276 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 17: Creating new instance of command class ZWAVE_PLUS_INFO
11:49:40.276 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 17: Sending REQUEST Message = 01 08 00 13 11 01 00 25 14 C5 
11:49:40.276 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 17: Command class ZWAVE_PLUS_INFO, endpoint null created
11:49:40.277 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 17: Application update is adding command class ZWAVE_PLUS_INFO.
11:49:40.277 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 17: Adding command class ZWAVE_PLUS_INFO to the list of supported command classes.
11:49:40.278 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 17: Creating new instance of command class BATTERY
11:49:40.279 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 17: Command class BATTERY, endpoint null created
11:49:40.279 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 17: Application update is adding command class BATTERY.
11:49:40.280 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 17: Adding command class BATTERY to the list of supported command classes.
11:49:40.280 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 17: Creating new instance of command class ALARM
11:49:40.281 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 17: Command class ALARM, endpoint null created
11:49:40.282 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 17: Application update is adding command class ALARM.
11:49:40.283 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 17: Adding command class ALARM to the list of supported command classes.
11:49:40.284 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 17: Creating new instance of command class ASSOCIATION
11:49:40.284 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 17: Command class ASSOCIATION, endpoint null created
11:49:40.285 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 17: Application update is adding command class ASSOCIATION.
11:49:40.285 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 17: Adding command class ASSOCIATION to the list of supported command classes.
11:49:40.286 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 17: Creating new instance of command class CONFIGURATION
11:49:40.287 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 17: Command class CONFIGURATION, endpoint null created
11:49:40.288 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 17: Application update is adding command class CONFIGURATION.
11:49:40.289 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 17: Adding command class CONFIGURATION to the list of supported command classes.
11:49:40.289 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
11:49:40.290 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 17: Creating new instance of command class MANUFACTURER_SPECIFIC
11:49:40.291 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 17: Command class MANUFACTURER_SPECIFIC, endpoint null created
11:49:40.292 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 17: Application update is adding command class MANUFACTURER_SPECIFIC.
11:49:40.292 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 17: Adding command class MANUFACTURER_SPECIFIC to the list of supported command classes.
11:49:40.293 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 17: Creating new instance of command class VERSION
11:49:40.294 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 17: Command class VERSION, endpoint null created
11:49:40.295 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 17: Application update is adding command class VERSION.
11:49:40.296 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 17: Adding command class VERSION to the list of supported command classes.
11:49:40.297 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 17: Creating new instance of command class SENSOR_BINARY
11:49:40.298 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 17: Command class SENSOR_BINARY, endpoint null created
11:49:40.299 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 17: Application update is adding command class SENSOR_BINARY.
11:49:40.300 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 17: Adding command class SENSOR_BINARY to the list of supported command classes.
11:49:40.301 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 17: Creating new instance of command class SENSOR_MULTILEVEL
11:49:40.302 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 17: Command class SENSOR_MULTILEVEL, endpoint null created
11:49:40.302 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 17: Application update is adding command class SENSOR_MULTILEVEL.
11:49:40.303 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 17: Adding command class SENSOR_MULTILEVEL to the list of supported command classes.
11:49:40.304 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 17: Creating new instance of command class WAKE_UP
11:49:40.305 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 17: Command class WAKE_UP, endpoint null created
11:49:40.305 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 14 00 00 02 FD 
11:49:40.306 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 17: Application update is adding command class WAKE_UP.
11:49:40.307 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 17: Adding command class WAKE_UP to the list of supported command classes.
11:49:40.309 [WARN ] [tocol.commandclass.ZWaveCommandClass] - NODE 17: Unsupported command class ASSOCIATION_GROUP_INFO
11:49:40.310 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 17: Creating new instance of command class POWERLEVEL
11:49:40.311 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 17: Command class POWERLEVEL, endpoint null created
11:49:40.312 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 17: Application update is adding command class POWERLEVEL.
11:49:40.313 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 17: Adding command class POWERLEVEL to the list of supported command classes.
11:49:40.314 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 17: Creating new instance of command class DEVICE_RESET_LOCALLY
11:49:40.315 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 17: Command class DEVICE_RESET_LOCALLY, endpoint null created
11:49:40.316 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 17: Application update is adding command class DEVICE_RESET_LOCALLY.
11:49:40.317 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 17: Adding command class DEVICE_RESET_LOCALLY to the list of supported command classes.
11:49:40.318 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 17: Creating new instance of command class MULTI_CMD
11:49:40.319 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 17: Command class MULTI_CMD, endpoint null created
11:49:40.319 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 17: Application update is adding command class MULTI_CMD.
11:49:40.320 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 17: Adding command class MULTI_CMD to the list of supported command classes.
11:49:40.321 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 17: Creating new instance of command class SECURITY
11:49:40.322 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 17: Command class SECURITY, endpoint null created
11:49:40.325 [INFO ] [mmandclass.ZWaveSecurityCommandClass] - NODE 17: setupNetworkKey useSchemeZero=false
11:49:40.468 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 17: Application update is adding command class SECURITY.
11:49:40.469 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 17: Adding command class SECURITY to the list of supported command classes.
11:49:40.470 [WARN ] [tocol.commandclass.ZWaveCommandClass] - NODE 17: Unsupported command class FIRMWARE_UPDATE_MD
11:49:40.471 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 17: Is awake with 0 messages in the wake-up queue.
11:49:40.472 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveWakeUpEvent
11:49:40.473 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 17: Wakeup during initialisation.
11:49:40.473 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 17: Node advancer - PING: queue length(1), free to send(false)
11:49:40.474 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 17: Node advancer - queued packet. Queue length is 1
11:49:40.475 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
11:49:40.476 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent message Message: class=SendData[0x13], type=Request[0x00], priority=Poll, dest=12, payload=0C 01 00 
11:49:40.478 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv message Message: class=ApplicationUpdate[0x49], type=Request[0x00], priority=High, dest=255, payload=84 11 15 04 07 01 5E 80 71 85 70 72 86 30 31 84 59 73 5A 8F 98 7A EF 20 
11:49:40.479 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationUpdate, callback id=14, expected=SendData, cancelled=false      MISMATCH
11:49:40.479 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=1
11:49:40.480 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8 
11:49:40.481 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8 
11:49:40.482 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, payload=01 
11:49:40.482 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 17: Sent Data successfully placed on stack.
11:49:40.483 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
11:49:40.484 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 14 00 00 02 00 00 F3 
11:49:40.485 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 14 00 00 02 00 00 F3 
11:49:40.486 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, payload=14 00 00 02 
11:49:40.487 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 17: SendData Request. CallBack ID = 20, Status = Transmission complete and ACK received(0)
11:49:40.487 [WARN ] [l.serialmessage.SendDataMessageClass] - NODE 17: Already processed another send data request for this callback Id, ignoring.
11:49:41.476 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 17: No more messages, go back to sleep
11:49:41.478 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 17: Creating new message for application command WAKE_UP_NO_MORE_INFORMATION
11:49:41.483 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 2. Queue={}
11:49:45.278 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA 
11:49:45.279 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 17: Sending ABORT Message = 01 03 00 16 EA 
11:49:45.280 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA 
11:49:45.281 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 16 EA 
11:49:45.281 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 17: Timeout while sending message. Requeueing - 0 attempts left!
11:49:45.282 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 17: Is sleeping
11:49:45.283 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 17: Putting message SendData in wakeup queue.
11:49:45.283 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 1
11:49:45.284 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 17: Putting message SendData in wakeup queue.
11:49:45.284 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
11:49:45.285 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 17: Message already on the wake-up queue. Removing original.
11:49:45.285 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 17: Putting message SendData in wakeup queue.
11:50:31.995 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0C 00 04 00 09 06 31 05 01 22 00 C1 2E 
11:50:31.999 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
11:50:32.000 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0C 00 04 00 09 06 31 05 01 22 00 C1 2E 
11:50:32.001 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 0C 00 04 00 09 06 31 05 01 22 00 C1 2E 
11:50:32.002 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, payload=00 09 06 31 05 01 22 00 C1 
11:50:32.003 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 9: Application Command Request (ALIVE:DONE)
11:50:32.003 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 9: Incoming command class SENSOR_MULTILEVEL
11:50:32.003 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 9: Received Sensor Multi Level Request
11:50:32.004 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 9: Sensor Multi Level REPORT received
11:50:32.004 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 9: Sensor Type = Temperature(1), Scale = 0
11:50:32.005 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 9: Sensor Value = 19.3
11:50:32.005 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveMultiLevelSensorValueEvent
11:50:32.006 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 9: Got an event from Z-Wave network: ZWaveMultiLevelSensorValueEvent
11:50:32.006 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 9: Got a value event from Z-Wave network, endpoint = 0, command class = SENSOR_MULTILEVEL, value = 19.3
11:50:32.007 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 9: Config updated
11:50:32.277 [INFO ] [smarthome.event.ThingUpdatedEvent   ] - Thing 'zwave:device:15348538564:node9' has been updated.
11:50:32.279 [DEBUG] [erter.ZWaveMultiLevelSensorConverter] - NODE 9: Sensor is reporting scale 0, requiring conversion to 0. Value is now 19.3.
11:50:32.280 [DEBUG] [converter.ZWaveCommandClassConverter] - Converted temperature from 19.3C to 19.3C
11:50:32.281 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Updating zwave:device:15348538564:node9:sensor_temperature to 19.3
11:50:32.282 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 17: Transaction not completed: node address inconsistent.  lastSent=17, incoming=255
11:50:32.283 [INFO ] [marthome.event.ConfigStatusInfoEvent] - org.eclipse.smarthome.config.core.status.events.ConfigStatusInfoEvent@a5e091
11:50:32.356 [INFO ] [marthome.event.ItemStateChangedEvent] - zwave_device_15348538564_node9_sensor_temperature changed from 19.5 to 19.3
11:50:32.360 [INFO ] [marthome.event.ItemStateChangedEvent] - WohnzimmerHealth changed from 19.5° (50% LF), Lux: 9 to 19.3° (50% LF), Lux: 9
11:50:32.433 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0B 00 04 00 09 05 31 05 05 01 32 FE 
11:50:32.435 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
11:50:32.437 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0B 00 04 00 09 05 31 05 05 01 32 FE 
11:50:32.438 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 0B 00 04 00 09 05 31 05 05 01 32 FE 
11:50:32.440 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, payload=00 09 05 31 05 05 01 32 
11:50:32.441 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 9: Application Command Request (ALIVE:DONE)
11:50:32.443 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 9: Incoming command class SENSOR_MULTILEVEL
11:50:32.444 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 9: Received Sensor Multi Level Request
11:50:32.445 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 9: Sensor Multi Level REPORT received
11:50:32.446 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 9: Sensor Type = RelativeHumidity(5), Scale = 0
11:50:32.446 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 9: Sensor Value = 5E+1
11:50:32.446 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveMultiLevelSensorValueEvent
11:50:32.447 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 9: Got an event from Z-Wave network: ZWaveMultiLevelSensorValueEvent
11:50:32.447 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 9: Got a value event from Z-Wave network, endpoint = 0, command class = SENSOR_MULTILEVEL, value = 5E+1
11:50:32.448 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 9: Config updated
11:50:32.683 [INFO ] [smarthome.event.ThingUpdatedEvent   ] - Thing 'zwave:device:15348538564:node9' has been updated.
11:50:32.685 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Updating zwave:device:15348538564:node9:sensor_relhumidity to 50
11:50:32.686 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 17: Transaction not completed: node address inconsistent.  lastSent=17, incoming=255
11:50:32.689 [INFO ] [marthome.event.ConfigStatusInfoEvent] - org.eclipse.smarthome.config.core.status.events.ConfigStatusInfoEvent@116ea7a

shorty707 · March 27, 2016, 9:55am

mhh
I tried that as first step

I only see “Set device as FAILed” in advanced mode

the “Reinitialize” is only there for nodes that are not “unknown”

chris · March 27, 2016, 9:55am

No - it’s a bit after this that I need - feel free to email me a larger log if you like (although I might not look at it for a while as I’ve got some other stiff to look at).

chris · March 27, 2016, 9:57am

Yep - it’s only shown after initialisation is complete… Ok - not so helpful in this case

vespaman · March 27, 2016, 10:10am

Chris,

I’m trying to get habmin configuration to work, I don’t know if you remember, but I have had issues with it earlier. Anyway, I can change a name of a thing, as well as polling period. But if I e.g. want to change a node setting, e.g. association group or a configuration parameter, after I press the green save, I get:

In the log I get one line;
11:59:01.014 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 37: Configuration update received

If I hit F5 and select the node, the change I made never made it. In the pic above I changed to BASIC_SET, but reopening, field is once again empty.

Could this be because I am using textual .items file?