[SOLVED] Zigbee vs. Zwave performance

My setup is made up entirely of zwave devices. I’ve read that zigbee can perform up to 6 times faster than zwave. I wanted to test that as I’ve noticed some lag between, say tapping a button on my AeotecWallMote and the time it takes for a bulb to turn on. Sometimes a 5-6 second lag. So I wanted to see if zigbee would perform better, so I bought a Nortek zwave/zigbee controller, a Centralite zigbee motion sensor and a GE zigbee bulb. When the motion sensor is triggered, the bulb comes on almost instantly. Similar to using a traditional electrical switch. Is this the experience I should expect with zigbee devices? Is there anyway to get zwave devices to perform faster? I may replace some of my room switches with zigbee devices where possible, id this is the case.

Thanks

RPi3/Openhabian 2.4. zwave 2.5 snapshot binding from 3/28

The performance of your zwave devices sounds degraded. I have ~125 zwave devices, and there is never 5-6 second lag. You may want to look into some debug logging to find where the delay is occurring. The number of devices, their distances, the composition of the building, etc. will all play a part. It’s possible that it is in your zwave network, but it could also be a rule or system issue.

I’ve used both zwave and zigbee for motion and door/window sensors. The zigbee devices could at times perform very slightly faster, but we’re talking milliseconds. However, they also dropped off the network frequently and required batteries to be replaced at least every 6 months. My zwave devices never fall off the network and the batteries have lasted over 2 years. Zigbee range was also much reduced vs zwave, requiring more devices to keep the mesh healthy. I’ve dropped zigbee except for some GE Link bulbs. For mains powered devices, zigbee might make sense, but remember that zigbee and zwave are both mesh networks… the more devices that you have of a particular type, the stronger that mesh will be.

Please quote the source of that claim.

While ZigBee may be faster in some situations, it’s usually marginal (within the millisecond order of magnitude). As a generalized statement that’s complete nonsense.
And please only ever compare apples to apples (similarly sized mesh of devices without misbehaving devices, same functionality, …).

There’s a problem with your setup then. Dunno the wall mote but I suspect it’s sending SCENE_ACTIVATION or CENTRAL_SCENE commands that need to be processed in your OH server.
You mustn’t compare that scenario to a directly sent command.
Lots of possible reasons (beyond zwave) where that delay originates from, rule processing just being one of them.
Or your input device is waiting for subsequent action taken (such as another tap to distinguish single from double taps) before sending its first message.

ZigBee protocol does run faster - up to 25 times even. But, that doesn’t mean that it will make any real difference, and this is only true if you are using really old ZWave devices. Most newer ZWave devices run at 100kpbs where ZigBee runs at 250kbps - so it’s still 2.5 times faster - and slightly older devices run at 40kbps (which is where you get the 6x speed difference from - 250/40).

However - that does not mean that you should see any appreciable difference - both protocols should work pretty quickly, and if you are seeing 5-6 second lags, then it’s probably caused by network timeouts.

ZigBee does however work a little better than ZWave in that multiple transactions can be outstanding at once.

It’s normally not the protocol that is the root cause of problems though, so a straight speed comparison is pretty much meaningless.

I have both, something isn’t working with your zwave stuff.

A common source of error is not having enough threads to process the events. Check in your events.log if you get the event several seconds before it is processed you might have a thread issue.

I experienced lag in my system, but once I got the threads sorted everything runs smooth and quickly.
Review your rules as well, for instance I had rules that ran on every power and energy update in the system.

Regards S

The devices in question, including the controller (Aeotec z-stick) are all in the same room. None of the devices are more than 12ft away from the controller. I don’t always get a 5 second delay, but there is almost always a noticeable delay. I’m not sure, but I think it may the WallMotes which may be the cause, as I can toggle the bulbs from the sitemap and the response is almost instantaneous. My rules are pretty simple. Here is an example:

when
	Item scene received update
then
	val sceneval = scene.state
	
	if(sceneval == 1.0){
		val lrlightstate = LRWindowLight_Switch.state
		
		if(lrlightstate == ON){

			LRWindowLight_Switch.sendCommand(OFF)
			LRWindowLight_Switch.postUpdate(OFF)
		}
		else{
			LRWindowLight_Switch.sendCommand(ON)
			LRWindowLight_Switch.postUpdate(ON)
		}
	} else if(sceneval == 2.0){
		val desklightstate = Desk_Light_Switch.state

		if(desklightstate  == ON){
			// Desk_Light_Switch.sendCommand(OFF)
			Desk_Light_Switch.postUpdate(OFF)
		}
		else{
			// Desk_Light_Switch.sendCommand(ON)
			Desk_Light_Switch.postUpdate(ON)
		}
		
	} ```

In any case, what should I look for in the log that would help me determine what might be the cause of the delay?

Thanks for the reply.

Using the legacy rule engine (:smirk:), there is always a slight delay the first time a rule is triggered, so keep that in mind too.

Look for…

  1. the time of the raw zwave event coming in from the Wallmote,
  2. the time of the Wallmote central scene Item changing value,
  3. the time of the zwave message being sent to the zwave light
  4. the ACK coming back from the zwave light

The times between 1-2 and 2-3 are your rule and OH system. The time between 3-4 is your zwave network. I’m assuming you are using a zwave light too, but if you are just using the zigbee bulb, disregard 3-4. You could dig into the zigbee log, but this should not be a factor. Reading logs is a lot easier with the log viewer.

Another thing to try is temporarily removing all rules except the one for the lighting automation. Also, when you look in the log, check to see what other zwave communications are happening… there could be a device acting up and spamming the network. You’re also on a Pi… if using an SD card, you may want to test it or swap it out with a backup.

This is not necessary… an Item’s state will update after sending it a command.

I also have long reaction times occasionally (one bad in 5 good), I’m guessing it is my concrete slab between the floors that are part of this. I see quite often “Transaction not complete” on different nodes (many nodes, not one in particular) - is this an indication of bad radio performance? Or is it normal under some circumstances?

I have also connected up a SDR to see if there’s a lot of disturbance in my house, but it is fairlly quiet on the zwave channels, so this shouldn’t be the reason.

I have a log of the communication between one of the WallMotes and one of the zwave bulbs. I haven’t been able to get a log of the delay, but maybe there is something in here that might point to a potential problem. Node 63 is the WallMote and node 10 is the bulb.

2019-04-07 20:39:57.313 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=63, callback=0, payload=00 3F 09 60 0D 00 01 5B 03 16 00 02 
2019-04-07 20:39:57.318 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=63, callback=0, payload=00 3F 09 60 0D 00 01 5B 03 16 00 02 
2019-04-07 20:39:57.330 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-04-07 20:39:57.331 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0D 00 04 00 3F 07 60 0D 02 01 20 01 FF 7E 
2019-04-07 20:39:57.334 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 63: Application Command Request (ALIVE:DONE)
2019-04-07 20:39:57.338 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=63, callback=0, payload=00 3F 07 60 0D 02 01 20 01 FF 
2019-04-07 20:39:57.341 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 63: resetResendCount initComplete=true isDead=false
2019-04-07 20:39:57.344 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 63: Decapsulating COMMAND_CLASS_MULTI_CHANNEL
2019-04-07 20:39:57.347 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 63: Incoming command class COMMAND_CLASS_CENTRAL_SCENE, endpoint 0
2019-04-07 20:39:57.350 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 63: SECURITY not supported
2019-04-07 20:39:57.353 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 63: Received COMMAND_CLASS_CENTRAL_SCENE V2 CENTRAL_SCENE_NOTIFICATION
2019-04-07 20:39:57.355 [DEBUG] [dclass.ZWaveCentralSceneCommandClass] - NODE 63: Received scene 2 at key 0 [Single Press]
2019-04-07 20:39:57.359 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 63: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2019-04-07 20:39:57.361 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 63: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_CENTRAL_SCENE, value=2.0
2019-04-07 20:39:57.365 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 63: Updating channel state zwave:device:f21cd9de:node63:scene_number to 2.0 [DecimalType]
2019-04-07 20:39:57.370 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 63: Commands processed 1.
2019-04-07 20:39:57.372 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 63: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@16d85bd.
2019-04-07 20:39:57.376 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-04-07 20:39:57.378 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-04-07 20:39:57.382 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=63, callback=0, payload=00 3F 07 60 0D 02 01 20 01 FF 
2019-04-07 20:39:57.386 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-04-07 20:39:57.389 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 63: Application Command Request (ALIVE:DONE)
2019-04-07 20:39:57.392 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 63: resetResendCount initComplete=true isDead=false
2019-04-07 20:39:57.395 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 63: Decapsulating COMMAND_CLASS_MULTI_CHANNEL
2019-04-07 20:39:57.398 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 63: Incoming command class COMMAND_CLASS_BASIC, endpoint 2
2019-04-07 20:39:57.401 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 63: SECURITY not supported
2019-04-07 20:39:57.404 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 63: Received COMMAND_CLASS_BASIC V0 BASIC_SET
2019-04-07 20:39:57.406 [DEBUG] [.commandclass.ZWaveBasicCommandClass] - NODE 63: Basic report, value = 255
2019-04-07 20:39:57.409 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 63: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2019-04-07 20:39:57.411 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 63: Got a value event from Z-Wave network, endpoint=2, command class=COMMAND_CLASS_BASIC, value=255
2019-04-07 20:39:57.413 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 63: Commands processed 1.
2019-04-07 20:39:57.415 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 63: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@c029aa.
2019-04-07 20:39:57.417 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-04-07 20:39:57.419 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-04-07 20:39:57.421 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-04-07 20:39:57.423 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-04-07 20:39:57.481 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Command received zwave:device:f21cd9de:node10:switch_dimmer --> OFF [OnOffType]
2019-04-07 20:39:57.484 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 10: Creating new message for command SWITCH_MULTILEVEL_SET
2019-04-07 20:39:57.487 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 10: SECURITY not supported
2019-04-07 20:39:57.490 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 10: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured
2019-04-07 20:39:57.492 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 10: Adding to device queue
2019-04-07 20:39:57.497 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 10: Added 21609 to queue - size 23
2019-04-07 20:39:57.499 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-04-07 20:39:57.503 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 0A 03 26 01 00 25 F8 15 
2019-04-07 20:39:57.508 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 10: Sending REQUEST Message = 01 0A 00 13 0A 03 26 01 00 25 F8 15 
2019-04-07 20:39:57.513 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2019-04-07 20:39:57.517 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-04-07 20:39:57.520 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-04-07 20:39:57.523 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 21609: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 248
2019-04-07 20:39:57.524 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-04-07 20:39:57.526 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-04-07 20:39:57.528 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2019-04-07 20:39:57.527 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Polling intialised at 86400 seconds - start in 1500 milliseconds.
2019-04-07 20:39:57.541 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-04-07 20:39:57.541 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2019-04-07 20:39:57.542 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-04-07 20:39:57.546 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-04-07 20:39:57.548 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-04-07 20:39:57.550 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 21609: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 248
2019-04-07 20:39:57.552 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-04-07 20:39:57.554 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 21609: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 248
2019-04-07 20:39:57.556 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-04-07 20:39:57.558 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 10: sentData successfully placed on stack.
2019-04-07 20:39:57.561 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 21609: Advanced to WAIT_REQUEST
2019-04-07 20:39:57.562 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 10: TID 21609: Transaction not completed
2019-04-07 20:39:57.564 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-04-07 20:39:57.566 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-04-07 20:39:57.660 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 F8 00 00 0F 1C 
2019-04-07 20:39:57.663 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=248, payload=F8 00 00 0F 
2019-04-07 20:39:57.666 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=248, payload=F8 00 00 0F 
2019-04-07 20:39:57.667 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 21609: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 248
2019-04-07 20:39:57.669 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-04-07 20:39:57.671 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 21609: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 248
2019-04-07 20:39:57.673 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 21609: (Callback 248)
2019-04-07 20:39:57.675 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2019-04-07 20:39:57.677 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 21609: callback 248
2019-04-07 20:39:57.679 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=248, payload=F8 00 00 0F 
2019-04-07 20:39:57.681 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 10: SendData Request. CallBack ID = 248, Status = Transmission complete and ACK received(0)
2019-04-07 20:39:57.682 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 10: resetResendCount initComplete=true isDead=false
2019-04-07 20:39:57.684 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 21609: Transaction COMPLETED
2019-04-07 20:39:57.686 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 10: Response processed after 163ms
2019-04-07 20:39:57.688 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 10: TID 21609: Transaction completed
2019-04-07 20:39:57.689 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 10: notifyTransactionResponse TID:21609 DONE
2019-04-07 20:39:57.691 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2019-04-07 20:39:57.693 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-04-07 20:39:57.695 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-04-07 20:39:57.791 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 0A 03 20 03 00 D8 
2019-04-07 20:39:57.795 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=10, callback=0, payload=00 0A 03 20 03 00 
2019-04-07 20:39:57.797 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=10, callback=0, payload=00 0A 03 20 03 00 
2019-04-07 20:39:57.799 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-04-07 20:39:57.800 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 10: Application Command Request (ALIVE:DONE)
2019-04-07 20:39:57.802 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 10: resetResendCount initComplete=true isDead=false
2019-04-07 20:39:57.804 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 10: Incoming command class COMMAND_CLASS_BASIC, endpoint 0
2019-04-07 20:39:57.806 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 10: SECURITY not supported
2019-04-07 20:39:57.807 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 10: Received COMMAND_CLASS_BASIC V1 BASIC_REPORT
2019-04-07 20:39:57.809 [DEBUG] [.commandclass.ZWaveBasicCommandClass] - NODE 10: Basic report, value = 0
2019-04-07 20:39:57.811 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2019-04-07 20:39:57.813 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_BASIC, value=0
2019-04-07 20:39:57.815 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Updating channel state zwave:device:f21cd9de:node10:switch_dimmer to 0 [PercentType]
2019-04-07 20:39:57.818 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Updating channel state zwave:device:f21cd9de:node10:color_color to 0 [PercentType]
2019-04-07 20:39:57.822 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 10: Commands processed 1.
2019-04-07 20:39:57.824 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 10: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@c208a6.
2019-04-07 20:39:57.826 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-04-07 20:39:57.828 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-04-07 20:39:57.830 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-04-07 20:39:57.832 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-04-07 20:39:58.225 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0D 00 04 00 0A 07 60 0D 01 01 20 03 00 B5 
2019-04-07 20:39:58.232 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=10, callback=0, payload=00 0A 07 60 0D 01 01 20 03 00 
2019-04-07 20:39:58.237 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=10, callback=0, payload=00 0A 07 60 0D 01 01 20 03 00 
2019-04-07 20:39:58.239 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-04-07 20:39:58.242 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 10: Application Command Request (ALIVE:DONE)
2019-04-07 20:39:58.244 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 10: resetResendCount initComplete=true isDead=false
2019-04-07 20:39:58.246 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 10: Decapsulating COMMAND_CLASS_MULTI_CHANNEL
2019-04-07 20:39:58.249 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 10: Incoming command class COMMAND_CLASS_BASIC, endpoint 1
2019-04-07 20:39:58.251 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 10: SECURITY not supported
2019-04-07 20:39:58.253 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 10: Received COMMAND_CLASS_BASIC V0 BASIC_REPORT
2019-04-07 20:39:58.255 [DEBUG] [.commandclass.ZWaveBasicCommandClass] - NODE 10: Basic report, value = 0
2019-04-07 20:39:58.258 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2019-04-07 20:39:58.260 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Got a value event from Z-Wave network, endpoint=1, command class=COMMAND_CLASS_BASIC, value=0
2019-04-07 20:39:58.263 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 10: Commands processed 1.
2019-04-07 20:39:58.266 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 10: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@89c066.
2019-04-07 20:39:58.268 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-04-07 20:39:58.270 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-04-07 20:39:58.272 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-04-07 20:39:58.274 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-04-07 20:39:58.450 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 0A 03 26 01 00 DC 
2019-04-07 20:39:58.456 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=10, callback=0, payload=00 0A 03 26 01 00 
2019-04-07 20:39:58.460 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=10, callback=0, payload=00 0A 03 26 01 00 
2019-04-07 20:39:58.462 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-04-07 20:39:58.464 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 10: Application Command Request (ALIVE:DONE)
2019-04-07 20:39:58.466 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 10: resetResendCount initComplete=true isDead=false
2019-04-07 20:39:58.468 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 10: Incoming command class COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0
2019-04-07 20:39:58.470 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 10: SECURITY not supported
2019-04-07 20:39:58.473 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 10: Received COMMAND_CLASS_SWITCH_MULTILEVEL V2 SWITCH_MULTILEVEL_SET
2019-04-07 20:39:58.475 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 10: Switch Multi Level set, value = 0
2019-04-07 20:39:58.478 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2019-04-07 20:39:58.480 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_SWITCH_MULTILEVEL, value=0
2019-04-07 20:39:58.483 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Updating channel state zwave:device:f21cd9de:node10:switch_dimmer to 0 [PercentType]
2019-04-07 20:39:58.490 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Updating channel state zwave:device:f21cd9de:node10:color_color to 0 [PercentType]
2019-04-07 20:39:58.494 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 10: Commands processed 1.
2019-04-07 20:39:58.497 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 10: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1e2eea7.
2019-04-07 20:39:58.500 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-04-07 20:39:58.502 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-04-07 20:39:58.505 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-04-07 20:39:58.507 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-04-07 20:39:59.027 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Polling...
2019-04-07 20:39:59.030 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Polling zwave:device:f21cd9de:node10:switch_dimmer
2019-04-07 20:39:59.033 [DEBUG] [erter.ZWaveMultiLevelSwitchConverter] - NODE 10: Generating poll message for COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0
2019-04-07 20:39:59.036 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 10: Creating new message for command SWITCH_MULTILEVEL_GET
2019-04-07 20:39:59.038 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 10: SECURITY not supported
2019-04-07 20:39:59.041 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 10: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured
2019-04-07 20:39:59.044 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Polling skipped for zwave:device:f21cd9de:node10:switch_dimmer on COMMAND_CLASS_BASIC
2019-04-07 20:39:59.047 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Polling zwave:device:f21cd9de:node10:meter_kwh
2019-04-07 20:39:59.049 [DEBUG] [ternal.converter.ZWaveMeterConverter] - NODE 10: Generating poll message for COMMAND_CLASS_METER, endpoint 0
2019-04-07 20:39:59.052 [DEBUG] [ternal.converter.ZWaveMeterConverter] - NODE 10: Generating poll message for COMMAND_CLASS_METER, endpoint 0
2019-04-07 20:39:59.055 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 10: Creating new message for application command METER_GET
2019-04-07 20:39:59.057 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 10: SECURITY not supported
2019-04-07 20:39:59.065 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 10: Command Class COMMAND_CLASS_METER is NOT required to be secured
2019-04-07 20:39:59.068 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Polling zwave:device:f21cd9de:node10:meter_watts
2019-04-07 20:39:59.070 [DEBUG] [ternal.converter.ZWaveMeterConverter] - NODE 10: Generating poll message for COMMAND_CLASS_METER, endpoint 0
2019-04-07 20:39:59.072 [DEBUG] [ternal.converter.ZWaveMeterConverter] - NODE 10: Generating poll message for COMMAND_CLASS_METER, endpoint 0
2019-04-07 20:39:59.075 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 10: Creating new message for application command METER_GET
2019-04-07 20:39:59.077 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 10: SECURITY not supported
2019-04-07 20:39:59.080 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 10: Command Class COMMAND_CLASS_METER is NOT required to be secured
2019-04-07 20:39:59.082 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Polling zwave:device:f21cd9de:node10:color_color
2019-04-07 20:39:59.085 [DEBUG] [erter.ZWaveMultiLevelSwitchConverter] - NODE 10: Generating poll message for COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0
2019-04-07 20:39:59.087 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 10: Creating new message for command SWITCH_MULTILEVEL_GET
2019-04-07 20:39:59.089 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 10: SECURITY not supported
2019-04-07 20:39:59.092 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 10: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured
2019-04-07 20:39:59.094 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Polling skipped for zwave:device:f21cd9de:node10:color_color on COMMAND_CLASS_BASIC
2019-04-07 20:39:59.096 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Polling zwave:device:f21cd9de:node10:color_color
2019-04-07 20:39:59.099 [DEBUG] [ternal.converter.ZWaveColorConverter] - NODE 10: Generating poll message for COMMAND_CLASS_SWITCH_COLOR, endpoint 0
2019-04-07 20:39:59.101 [DEBUG] [.commandclass.ZWaveColorCommandClass] - NODE 10: Creating new message for application command SWITCH_COLOR_GET 2
2019-04-07 20:39:59.104 [DEBUG] [.commandclass.ZWaveColorCommandClass] - NODE 10: Creating new message for application command SWITCH_COLOR_GET 3
2019-04-07 20:39:59.107 [DEBUG] [.commandclass.ZWaveColorCommandClass] - NODE 10: Creating new message for application command SWITCH_COLOR_GET 4
2019-04-07 20:39:59.109 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 10: SECURITY not supported
2019-04-07 20:39:59.112 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 10: Command Class COMMAND_CLASS_SWITCH_COLOR is NOT required to be secured
2019-04-07 20:39:59.114 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 10: SECURITY not supported
2019-04-07 20:39:59.117 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 10: Command Class COMMAND_CLASS_SWITCH_COLOR is NOT required to be secured
2019-04-07 20:39:59.119 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 10: SECURITY not supported
2019-04-07 20:39:59.122 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 10: Command Class COMMAND_CLASS_SWITCH_COLOR is NOT required to be secured
2019-04-07 20:39:59.124 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 10: Adding to device queue
2019-04-07 20:39:59.126 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 10: Added 21610 to queue - size 23
2019-04-07 20:39:59.128 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-04-07 20:39:59.130 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 0A 02 26 02 25 F9 15 
2019-04-07 20:39:59.132 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 10: Sending REQUEST Message = 01 09 00 13 0A 02 26 02 25 F9 15 
2019-04-07 20:39:59.134 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-04-07 20:39:59.136 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2019-04-07 20:39:59.136 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 21610: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 249
2019-04-07 20:39:59.137 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 10: Adding to device queue
2019-04-07 20:39:59.137 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-04-07 20:39:59.139 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-04-07 20:39:59.139 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 10: Added 21611 to queue - size 23
2019-04-07 20:39:59.140 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 21610: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 249
2019-04-07 20:39:59.140 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-04-07 20:39:59.141 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2019-04-07 20:39:59.141 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 10: Adding to device queue
2019-04-07 20:39:59.143 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-04-07 20:39:59.143 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 10: Added 21612 to queue - size 24
2019-04-07 20:39:59.144 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-04-07 20:39:59.145 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2019-04-07 20:39:59.146 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-04-07 20:39:59.147 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 10: Adding to device queue
2019-04-07 20:39:59.148 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-04-07 20:39:59.149 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 10: Added 21613 to queue - size 25
2019-04-07 20:39:59.150 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-04-07 20:39:59.152 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 10: Adding to device queue
2019-04-07 20:39:59.152 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-04-07 20:39:59.154 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 21610: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 249
2019-04-07 20:39:59.154 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 10: Added 21614 to queue - size 26
2019-04-07 20:39:59.156 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-04-07 20:39:59.157 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 21610: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 249
2019-04-07 20:39:59.159 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-04-07 20:39:59.159 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-04-07 20:39:59.161 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 10: sentData successfully placed on stack.
2019-04-07 20:39:59.161 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 10: Adding to device queue
2019-04-07 20:39:59.162 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 21610: Advanced to WAIT_REQUEST
2019-04-07 20:39:59.162 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 10: Added 21615 to queue - size 27
2019-04-07 20:39:59.164 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 10: TID 21610: Transaction not completed
2019-04-07 20:39:59.164 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-04-07 20:39:59.165 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 10: Adding to device queue
2019-04-07 20:39:59.165 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-04-07 20:39:59.167 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 10: Added 21616 to queue - size 28
2019-04-07 20:39:59.168 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-04-07 20:39:59.170 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-04-07 20:39:59.966 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 F9 00 00 52 40 
2019-04-07 20:39:59.971 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=249, payload=F9 00 00 52 
2019-04-07 20:39:59.975 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=249, payload=F9 00 00 52 
2019-04-07 20:39:59.978 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 21610: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 249
2019-04-07 20:39:59.981 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-04-07 20:39:59.984 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 21610: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 249
2019-04-07 20:39:59.986 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 21610: (Callback 249)
2019-04-07 20:39:59.989 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2019-04-07 20:39:59.991 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 21610: callback 249
2019-04-07 20:39:59.995 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=249, payload=F9 00 00 52 
2019-04-07 20:39:59.998 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 10: SendData Request. CallBack ID = 249, Status = Transmission complete and ACK received(0)
2019-04-07 20:40:00.001 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 10: resetResendCount initComplete=true isDead=false
2019-04-07 20:40:00.003 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 21610: Advanced to WAIT_DATA
2019-04-07 20:40:00.006 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 10: TID 21610: Transaction not completed
2019-04-07 20:40:00.009 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-04-07 20:40:00.012 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.```



Also, I keep seeing this logged quite often, every 30 seconds or so. Node 14 is an Aoetec zwave switch:

```2019-04-07 20:38:10.505 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=14, callback=0, payload=00 0E 12 32 02 21 64 00 01 78 32 00 1E 00 01 78 31 00 00 00 00 
2019-04-07 20:38:10.507 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-04-07 20:38:10.512 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 14: Application Command Request (ALIVE:DONE)
2019-04-07 20:38:10.515 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 14: resetResendCount initComplete=true isDead=false
2019-04-07 20:38:10.518 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 14: Incoming command class COMMAND_CLASS_METER, endpoint 0
2019-04-07 20:38:10.520 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 14: SECURITY not supported
2019-04-07 20:38:10.526 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 14: Received COMMAND_CLASS_METER V3 METER_REPORT
2019-04-07 20:38:10.535 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 14: Meter: Type=Electric(1), Scale=kWh(0), Value=96.306
2019-04-07 20:38:10.537 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 14: Got an event from Z-Wave network: ZWaveMeterValueEvent
2019-04-07 20:38:10.540 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 14: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_METER, value=96.306
2019-04-07 20:38:10.543 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 14: Updating channel state zwave:device:f21cd9de:node14:meter_kwh to 96.306 [DecimalType]
2019-04-07 20:38:10.548 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 14: Commands processed 1.
2019-04-07 20:38:10.552 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 14: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@16ece70.
2019-04-07 20:38:10.553 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-04-07 20:38:10.555 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-04-07 20:38:10.557 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-04-07 20:38:10.559 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-04-07 20:38:10.697 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 18 00 04 00 0E 12 32 02 21 74 00 00 B6 96 00 00 00 00 00 00 00 00 00 00 BA 
2019-04-07 20:38:10.702 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=14, callback=0, payload=00 0E 12 32 02 21 74 00 00 B6 96 00 00 00 00 00 00 00 00 00 00 ```

Wallmote messgae received: 20:39:57.331
Bulb ACK received: 20:39:57.660

The rest is command polling and everything looks good. However, your bulb is reporting it’s state all on its own, so you can disable the command polling.

That is a meter report from the switch. The frequency of the reports is probably be configurable.

Thanks for the reply. I’ll keep an eye on the logs.

I finally was able have the log running while having the latency issue. I pressed one of the buttons on my wall mote and it flashed blue twice and then red, indicating that it could not communicate with the controller. I look at the Aeotec controller, and I see the light is stuck on the color red. At this point the log put appears “stalled”. After some time, there was output from the log again. The controller was alternating colors every second or so, as usual. The bulb did not turn on though, I had to press the button again.

I don’t understand the messages, but there is a 37 second gap in there, probably while the output was stalled. I hope this sheds some light on things.

@chris will need to take a look, but can you provide a bit more log from before, and the actual log file?

I need to clarify that a bit. My battery was going flat and I hit send before finished.

It could be a coincidence but around 37s appears to be a standard zwave serial static controller ‘issue’. This definitely should not happen and you need to look deeper.

It appears to be a standard “issue” as the timeout of that size is not defined in the specs anywhere so it is an oddball that some zwave users suffer from time to time.

I have heard about this delay from users of HC2 and HCL but never had it myself. Evidently openHAB is not immune so I would be very interested in your logs as it is on my list of things to understand.

I’ll try to get more from the log this evening. I should add that I get this behavior with two different Aeotec controllers. One I have as a backup.

I opened the archived log file where I got the original log. I selected a much more text around the area with the 37 second gap.I should also add that I have disabled command polling for the bulbs and dimmer involved.

this too, please

Here’s another one from just this evening. There is a gap of about 1m 37ZWave Log Viewer.pdf (51.6 KB)
seconds after the 19:52:07 entry:

The full log going back a few days is here:
openhab.log

@chris @robmac @5iver

Firstly, I would suggest to look at the node 59 configuration as it is swamping the network with spam. It is sending updates roughly every second for multiple channels - and they are typically the same. This should be able to be adjusted to only send when there is an update to the data.

Here the energy is always the same, power is always 0, and voltage is changing, but it’s just noise.

There’s a gap of about 1 day 1 hour 30 minutes -:

This log doesn’t show dates, but it changes from 22nd to 23rd. I can’t find the time 19:52:07 at all in the log.