No idea then. Either it’s the part between OH and whatever gateway the dimmers are using, or the dimmers itself. I’d bet on the first part.
Just so I understand what you’re suggesting…are you saying that the issue may be between the Aeotec stick and OH rather than with the device itself? (I realize that’s not a guarantee) Because if that’s the case I wonder if its worth buying a Zooz 800 to see if that resolves it.
It’s impossible to say what is happening without debug logs - otherwise the statement above about it being a gateway issue is purely a guess and IMHO likely wrong. You need to enable debug logging and look to see what is happening. This is described in the zwave binding docs.
1 Like
If you are on the 4.1 release; on the UI Settings page, Add-on settings, you can set the ZWave binding to debug right there. Do your test and reset back to INFO. Post log or use the log viewer here
1 Like
Thanks everyone, I went ahead and got more detailed logs. The switches actually cooperated on this pretty well since one switched worked and one didn’t. (These are not the only misbehaving switches but I think if I can solve it with these two, its probably going to be solved for everyone) I’ve uploaded the full debug logs here and NODE 38 and NODE 39 are the ones to focus on. In this case, NODE 38 worked and NODE 39 did not. I can see obvious differences between them in the logs but while I can see that there was a failure on the part of NODE 39, I’m not sure why.
Thank you for pointing out how to change to DEBUG!
openhab.log (777.7 KB)
There is a lot going on in your network in a very short time and not all is good. There is a lot of duplicate messages and the message queue seems to get backlogged. I have to ask more questions to better understand what you are doing and your configurations. I’m looking at simplification and then rerun the test, then readd the parameters you need slowly.
- In the picture above why are there two items linked to the dimmer channel? Possible remove?
- What item is linked to the double tap channel? Possible remove-Do you use it for something? In the manual double tap is used to send a basic set (ON/OFF) to another node in Association group 3 with no effect on the light connected to the switch.
- On the UI page for the dimmers what is the command poll? It looks like 150ms and that is too fast. For the next test set it to zero.
- Also on the UI page do you have the controller in the association groups 2 or 3, if yes remove.
- What and how did you generate the log? That is, did you execute a rule for OH or flip a switch on the device? It looks like OFF was sent to a dozen or so switches (sometimes twice)- hence the question about the channels.
- Are you mostly using ON/OFF, not the dimmer percentages?
- What are the values of parameters 7-12?
@apella12 thank you for reviewing the logs. Answers inline below.
In the picture above why are there two items linked to the dimmer channel? Possible remove?
This was to solve another issue with this switch. I discovered that if I set the dimmer to 100% and then pressed the switch to “OFF”, it often would still report that the switch was at 100% illumination even though the lights were off. I linked the double-tap channel and the dimmer channel because this seemed to allow the switch to report its state correctly when used at the wall.
What item is linked to the double tap channel? Possible remove-Do you use it for something? In the manual double tap is used to send a basic set (ON/OFF) to another node in Association group 3 with no effect on the light connected to the switch.
That’s the Double Tap item that OpenHab created. Are you saying I shouldn’t have an item associated with Double Taps at all?
On the UI page for the dimmers what is the command poll? It looks like 150ms and that is too fast. For the next test set it to zero.
You are correct, I have it set to 150ms. When I run the next test I’ll change it to 0
Also on the UI page do you have the controller in the association groups 2 or 3, if yes remove.
I did…and done
What and how did you generate the log? That is, did you execute a rule for OH or flip a switch on the device? It looks like OFF was sent to a dozen or so switches (sometimes twice)- hence the question about the channels.
Yes, this is based off a rule that is used to turn off all of the lights on the first floor of my house. I had been sending the command twice in an attempt to force the light to respond. However, now that I see what’s happening in the log, I realize that was both unnecessary and counterproductive. This is what the rule looks like now but I’m going to remove one of the dimmer group commands.
Are you mostly using ON/OFF, not the dimmer percentages?
I prefer to use OFF to percentages
What are the values of parameters 7-12?
That parameter is poorly named. It is really just the basic on/off from the manual operation of the switch. However since you are using this to update the Dimmer when using the manual switch, I think it is
Ok for now. I made a DB change to recognize basic commands on the dimmer channel that should fix this in the future.
One thought that might work, as you are not using the dimmer, would be to have the rule send ON/OFF on the double tap channel and just use that item for status, etc. However, we should just see where we are so far on reducing duplications and excess traffic.
I just ran another test. I turned on every light downstairs and updated all of the switches with the parameters you requested. One thing that I couldn’t do was remove the Controller from group 3. But it is no longer in group 2. On this test, every switch and dimmer turned off except for one of the kitchen lights again (NODE 38). Something I noticed though is that the dimmer status and DoubleTap status are again out of sync with each other. NODE 39 is off (as expected) but while the dimmer says “0”, the DoubleTap says Triggered.
This behavior is restricted to GE/Jasco dimmers. All other dimmers & switches function just fine.
TBH I’m not exactly sure why all the lights are not going off. In the first log Node 39 sent 16 reports that it was off. My theory was it was too busy sending messages to turn off?
The good news is that the GE devices seem better behaved. Go ahead and put the command poll back, but at 5 seconds (5000). That should get the channels back in sync. (Was the command poll still on Nodes 6 and 10?). The zooz devices (35,36,37,46-48, 50, 54 &57) are also causing congestion. For the next try eliminate the command poll on these devices. Also in the rule create a one second (or 1.5 sec) delay between the commands to shut off the lights. The messages are piling up and could be causing the problems overloading the controller.
Edit: Also feel free to use Info logging, except when running the all off rule. It will keep the file a manageable size. Also don’t try to heal any nodes for awhile, that causes a lot congestion
I decided to run a simpler test because the issue occurs even with single commands. This should be easier to read. In this test, the same dimmer was turned on & off via the UI. The light responded properly until the very last log entry when it did not respond the to the command of setting the value to zero. The switch will respond if I keep hitting the button though. (NODE 45). I can adjust the other devices but while the logs are much less congested now, the behavior overall is mostly the same.
15:53:56.645 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=238, payload=EE 00 00 06 02 D2 7F 7F 7F 7F 00 00 03 06 0D 00 00 03 01 00 00
15:53:56.645 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 45: SendData Request. CallBack ID = 238, Status = Transmission complete and ACK received(0)
15:53:56.646 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 45: resetResendCount initComplete=true isDead=false
15:53:56.646 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 2502: Transaction COMPLETED
15:53:56.646 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 45: Response processed after 74ms
15:53:56.646 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 45: TID 2502: Transaction completed
15:53:56.647 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 45: notifyTransactionResponse TID:2502 DONE
15:53:56.647 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 45: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
15:53:56.648 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
15:53:56.648 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
15:54:02.296 [INFO ] [openhab.event.ItemCommandEvent ] - Item 'Z045__Living_Room_Lights_Dimmer' received command 0
15:54:02.297 [INFO ] [openhab.event.ItemStatePredictedEvent] - Item 'Z045__Living_Room_Lights_Dimmer' predicted to become 0
15:54:02.298 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 45: Command received zwave:device:a4fe67a0cc:node45:switch_dimmer --> 0 [PercentType]
15:54:02.298 [DEBUG] [ass.ZWaveMultiLevelSwitchCommandClass] - NODE 45: Creating new message for command SWITCH_MULTILEVEL_SET
15:54:02.298 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 45: SECURITY not supported
15:54:02.297 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Z045__Living_Room_Lights_Dimmer' changed from 100 to 0
15:54:02.298 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 45: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured
15:54:02.298 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 45: Adding to device queue
15:54:02.299 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 45: Added 2503 to queue - size 4
15:54:02.299 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
15:54:02.299 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 2D 03 26 01 00 25 EF 25
15:54:02.299 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 45: Sending REQUEST Message = 01 0A 00 13 2D 03 26 01 00 25 EF 25
15:54:02.299 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT
15:54:02.299 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 2503: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 239
15:54:02.301 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
15:54:02.301 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
15:54:02.301 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
15:54:02.301 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ZWaveSerialController_FramesAcknowledged' changed from 2930 to 2931
15:54:02.301 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 2503: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 239
15:54:02.301 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK
15:54:02.301 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
15:54:02.301 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
15:54:02.307 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
15:54:02.307 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ZWaveSerialController_StartFrames' changed from 9247 to 9248
15:54:02.307 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
15:54:02.307 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
15:54:02.308 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 2503: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 239
15:54:02.308 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
15:54:02.308 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 2503: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 239
15:54:02.308 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
15:54:02.308 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 45: sentData successfully placed on stack.
15:54:02.308 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 2503: Advanced to WAIT_REQUEST
15:54:02.308 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 45: TID 2503: Transaction not completed
15:54:02.308 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
15:54:02.308 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
15:54:02.370 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ZWaveSerialController_StartFrames' changed from 9248 to 9249
15:54:02.371 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 18 00 13 EF 00 00 06 02 D2 7F 7F 7F 7F 00 00 03 06 0D 00 00 03 01 00 00 C7
15:54:02.371 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=239, payload=EF 00 00 06 02 D2 7F 7F 7F 7F 00 00 03 06 0D 00 00 03 01 00 00
15:54:02.371 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=239, payload=EF 00 00 06 02 D2 7F 7F 7F 7F 00 00 03 06 0D 00 00 03 01 00 00
15:54:02.371 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 2503: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 239
15:54:02.372 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
15:54:02.372 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 2503: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 239
15:54:02.372 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking TID 2503: (Callback 239)
15:54:02.372 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - Callback match!
15:54:02.372 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Correlated to TID 2503: callback 239
15:54:02.372 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=239, payload=EF 00 00 06 02 D2 7F 7F 7F 7F 00 00 03 06 0D 00 00 03 01 00 00
15:54:02.373 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 45: SendData Request. CallBack ID = 239, Status = Transmission complete and ACK received(0)
15:54:02.373 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 45: resetResendCount initComplete=true isDead=false
15:54:02.373 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 2503: Transaction COMPLETED
15:54:02.373 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 45: Response processed after 74ms
15:54:02.373 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 45: TID 2503: Transaction completed
15:54:02.373 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 45: notifyTransactionResponse TID:2503 DONE
15:54:02.373 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 45: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
15:54:02.373 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
15:54:02.374 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
This is the snippet in the log viewer. It actually looks fine (no command poll yet - right?). Maybe it is the device?
edit: 72ms is pretty good response; From your big file this is an extract of node 45. One completely rejected because the controller was busy. One ok and one kinda slow 570 ms.
Command poll was off for this device. I decided to test it on another switch (Same model) and the behavior is consistent. I can (via UI) turn the switch on and off multiple times until finally, the command doesn’t register. But then if I hit the UI control a few more times, it continues to turn back on and off. It is only the GE dimmers as I said though. So I don’t think its an issue with the individual switch so much as the GE dimmers. I vaguely remember they had strange behavior in Homeseer as well but I was able to get them working via a workaround.
I think, if anything, this validates my desire to replace these specifically.
To me this tends to confirm that the root cause of this behavior is network congestion related. As congestion can be caused by any/all the devices, my suggestions above regarding the Zooz devices and rule timing could help (without an investment in new devices).
Might want to review this posting for other ideas [SOLVED] Unresponsive Z-Wave Network: Tools and Approaches to track down the issues - Tutorials & Examples / Solutions - openHAB Community
EDIT: Corrected Node 47 to 39
Absolutely, no reason not to exhaust all testing first. I’ve changed the command poll on all of the nodes requested and ran my “All Off” rule for the first floor. I had every light on downstairs and the nodes that did not properly respond are : 8, 10, and 39. The really weird part about this continues to be that the night light changes state properly. So when the lights are on, the night light turns off. And when the light is supposed to be off, the night light comes back on. That means the switch is absolutely receiving the command but only changing the state of the blue night light and not the actual load. I did do the test with DEBUG just to capture all information:
openhab.log (590.4 KB)
Also, I realized that Node 6 has never failed (its my office so the room I’m sitting in often when testing). I can trigger the light over and over again without any failure. Its the exact same type of dimmer as the ones that fail. The settings themselves are all the same. I found something very odd though on the Thing configuration page. This is Node 6:
This is Node 8:
Only Node 6 has that Lock Timeout option (which I don’t believe it should have) and it is the only switch of that type to be working properly.
Just as an additional data point : I can send any command of 1% - 100% to these switches and they will work every single time. The ONLY command that does not work every time is OFF or 0%.
Interesting. Possible work around if 1% looks off? Maybe only for the ones that don’t always work?
Log is much better, although I think spacing the OFF commands will help also. Two nodes seem problematic. Node 13 sends a lot of updates. Is the controller in the other Association groups? Node 47 jams things up because it doesn’t respond. Is it remote from the controller? Could you test w/o it and see if it helps.
Can’t explain the lock Timeout- seems misplaced as not a lock device. Did you have a lock as Node 6 sometime in the past? I think the closeness to controller is also an explanation.
Unfortunately 1% doesn’t work since the lights stay on at that level. What I really want to figure out is why NODE 8 works every time but none of the others do. Is there a place I can look at the actual configuration of the Things on the server? I’d love to see if there is something different there.
Spacing the commands really does nothing since I can isolate a single dimmer and run the command and still have the issue.
On the left side of the UI click on developer tools, then API explorer, then things. Use GET with your thing ID.
Well, I think I may have fixed it. I had set the dim rate to 1 on most of my dimmers. The default, I believe, is 3. As far as I can tell, all of the switches where I have moved it back to 3 are now responding with 100% success. I don’t think this exercise went to waste since this significantly cleaned up my network regardless so thank you.
I am going to have to go through every device now to check and see if that is the case but it seems 
to be working. Thank you very much for the help and I have a much better understanding of how to troubleshoot in the future as well.
1 Like