No reaction of dimmer, trying to understand zwave log file (what's that queue?)

tonus · September 28, 2021, 8:30pm

I was trying to debug a wall button, on which the lamps sometimes do not react. I have debug on, I looked at the openhab.log file, and I looked to that log via the nice zwave logfile viewer site Z-Wave Log Viewer from @chris. Still using OH2.12 on Openhabian, but the logfiles seems pretty much the same in OH3.

The rule reacts on the push of a button (Aeotec Wallmote, node 3) and puts the dimmer (node 5) of the lamp ON. Fairly simple. The logfile processed by the Zwave viewer looks OK:

Seems fine, button 3 is pressed, then the dimmer is switched off, and it replies with some messages, among which a new amount of Watts used.

Is this the correct interpretation?

However, I was suspicious because I see that the messages are placed in the queue, according to the line at 21:40:43.949.

What queue is that?
There is polling later on, is that something to be worried about?

2021-09-25 21:40:43.828 [DEBUG] [dclass.ZWaveCentralSceneCommandClass] - NODE 3: Received scene 3 at key 0 [Single Press]
2021-09-25 21:40:43.831 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2021-09-25 21:40:43.833 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_CENTRAL_SCENE, value=3.0
2021-09-25 21:40:43.836 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Updating channel state zwave:device:374344a4:node3:scene_number to 3.0 [DecimalType]
2021-09-25 21:40:43.841 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Commands processed 1.
2021-09-25 21:40:43.845 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1b95d87.
2021-09-25 21:40:43.847 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2021-09-25 21:40:43.849 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2021-09-25 21:40:43.851 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2021-09-25 21:40:43.851 [INFO ] [se.smarthome.model.script.Rule LA-WB] - lamps switched using wallmote
2021-09-25 21:40:43.852 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2021-09-25 21:40:43.937 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Command received zwave:device:374344a4:node5:switch_dimmer --> OFF [OnOffType]
2021-09-25 21:40:43.940 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 5: Creating new message for command SWITCH_MULTILEVEL_SET
2021-09-25 21:40:43.942 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: SECURITY NOT required on COMMAND_CLASS_SWITCH_MULTILEVEL
2021-09-25 21:40:43.944 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured
2021-09-25 21:40:43.946 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: Adding to device queue
2021-09-25 21:40:43.949 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: Added 316 to queue - size 2
2021-09-25 21:40:43.952 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2021-09-25 21:40:43.955 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 05 03 26 01 00 25 61 83 
2021-09-25 21:40:43.961 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 5: Sending REQUEST Message = 01 0A 00 13 05 03 26 01 00 25 61 83 
2021-09-25 21:40:43.967 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2021-09-25 21:40:43.969 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2021-09-25 21:40:43.970 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Command received zwave:device:374344a4:node6:switch_dimmer --> OFF [OnOffType]
2021-09-25 21:40:43.971 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2021-09-25 21:40:43.973 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 6: Creating new message for command SWITCH_MULTILEVEL_SET
2021-09-25 21:40:43.973 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2021-09-25 21:40:43.974 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2021-09-25 21:40:43.974 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 6: SECURITY NOT required on COMMAND_CLASS_SWITCH_MULTILEVEL
2021-09-25 21:40:43.976 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2021-09-25 21:40:43.976 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 6: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured
2021-09-25 21:40:43.979 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2021-09-25 21:40:43.989 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2021-09-25 21:40:43.991 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 316: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 97
2021-09-25 21:40:43.993 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: Adding to device queue
2021-09-25 21:40:43.994 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Polling initialised at 1800 seconds - start in 1500 milliseconds.
2021-09-25 21:40:43.995 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: Added 317 to queue - size 2
2021-09-25 21:40:43.997 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2021-09-25 21:40:43.999 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Polling initialised at 1800 seconds - start in 1500 milliseconds.
2021-09-25 21:40:43.999 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2021-09-25 21:40:44.020 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2021-09-25 21:40:44.022 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2021-09-25 21:40:44.024 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 316: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 97
2021-09-25 21:40:44.024 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 18 00 13 61 00 00 02 00 C7 7F 7F 7F 7F 00 00 03 00 00 00 00 03 01 00 00 51 
2021-09-25 21:40:44.027 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2021-09-25 21:40:44.029 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 316: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 97
2021-09-25 21:40:44.031 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2021-09-25 21:40:44.033 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 5: sentData successfully placed on stack.
2021-09-25 21:40:44.035 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 316: Advanced to WAIT_REQUEST
2021-09-25 21:40:44.038 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: TID 316: Transaction not completed
2021-09-25 21:40:44.040 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2021-09-25 21:40:44.042 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2021-09-25 21:40:44.050 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=97, payload=61 00 00 02 00 C7 7F 7F 7F 7F 00 00 03 00 00 00 00 03 01 00 00 
2021-09-25 21:40:44.053 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=97, payload=61 00 00 02 00 C7 7F 7F 7F 7F 00 00 03 00 00 00 00 03 01 00 00 
2021-09-25 21:40:44.055 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 316: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 97
2021-09-25 21:40:44.057 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2021-09-25 21:40:44.058 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 316: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 97
2021-09-25 21:40:44.060 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 316: (Callback 97)
2021-09-25 21:40:44.062 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2021-09-25 21:40:44.064 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 316: callback 97

Thanks for your help!

apella12 · September 28, 2021, 10:25pm

I see nothing of concern in these snippets.
There is probably a more technical answer, but the binding generates a message and puts in a queue. The binding then draws from the queue based on priority when it is okay to send another message. There can only be one message requiring a response outstanding per node.
As to the polling, you have that set on the thing UI page, near the bottom command poll interval. It can be shut off if you put zero. As you can see it is redundant and adds to traffic, but is not causing any problem that I can see.

Bob

chris · September 29, 2021, 12:35am

That is the transmit queue. All data is added to the queue before sending as the dongle can’t process more than one transaction at a time. The data seems to be sent a few milliseconds later - this is all fine.

Not at all - this is also normal. The binding requests the state a few seconds after sending the command to make sure the state is known. As stated above, you can change this repoll time if you want.

It’s not really “redundant” - it is there for a reason, and that is in case something didn’t work, the binding still wanted to know what state the device is in. All polling is a low priority task, so it should not cause a problem, but it’s also not redundant.

apella12 · September 29, 2021, 1:10am

Probably a little too strong as there are other connotations across the pond, but I just put it there to see if you were reading my posts .

Anyway as a rule I do not use in my system as I can usually see if a light goes on or not and try to minimize network traffic. I’m not a zealot on the issue however.

Bob

tonus · October 3, 2021, 7:06pm

Thanks @Chris and @apella12.
So OH is fine here, OH does the correct thing towards the Zwave stick. There is correct communication to the devices. So, the device for some reason does not perform its trick. Well, for a lamp that is not a big deal, I’d try to switch it on again. Good to see that OH and Zwave are doing fine

OK, that 's clear. So there is a queue from OH towards the Zwave controller (i.e. the dongle).

Just curious, is the raw message data, visible when you click the colorfull commands, the same as the raw Zwave messages ?

Thanks again,
Ton