Zwave devices keep changing to 0

fennepa · July 26, 2023, 2:58pm

Hello, Since some time now I’m experiencing issues with my zwave devices, that I do not understand or have been able to solve so far. I have seen numerous posts that may fit my situation somewhat, but not close enough to really get enthusiastic yet, as the analysis often requires quite a hands on approach.
I’m running openhab openHAB 3.4.4 on a PI4. my zwave network consists out of a Aeotec Gen5 Z-Wave USB stick. I have 6 Ecodim Dimmers, 2 Idinio floor dimmers and 2 Fibaro RGBW Controller 2. all my devices are mains connected.

I’m having several issues, but I would like to primarily resolve the first one. Obviously, I don’t know if the things that I’m experiencing are related to each other, so completeness may go a long way:

whenever I interact with any of the physical ecodim dimmers through a rule or the main ui, (issuing a sendcommand), I notice that I often trigger two ‘changes’ from the device. The first change normally is the expected value as issued with sendcommand, immediately followed with an additional ‘change’ either back to the previous state or a value that is somewhere between the previous and the new state. This behaviour is driving me nuts as it basically renders my UI and rules automation useless. For example:

2023-07-26 16:13:25.693 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'KitchenWallLightsDimmer_Device' received command 60
2023-07-26 16:13:25.700 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'KitchenWallLightsDimmer_Device' predicted to become 60
2023-07-26 16:13:25.708 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'KitchenWallLightsDimmer_Device' changed from 0 to 60
2023-07-26 16:13:30.750 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'KitchenWallLightsDimmer_Device' changed from 60 to 0

the time difference between both events is fluctuating. this time it was 5 sec, but it can also be as quick as 0.3 sec.

both of the Idinio devices become unresponsive at random once every 4 to 6 weeks each. There seems to be no pattern although it got a bit better after I disabled the zwave network heal at 2AM. After unplugging them, the connections are re-established in most cases. With my Fibaro devices I have never experienced any failures and with the 6 ecodims I have 2 failures or so per year. the response times are really fluctuating, from instantly snappy up to 15 sec in extreme cases.
to start my analysis somewhere I wanted enable the zwave logging as indicated in the docs, but log:set DEBUG org.openhab.binding.zwave is not working: -bash: log:set: command not found

any suggestions on where to start investigating? thx

rlkoshak · July 26, 2023, 3:05pm

Disable autoupdate. Items | openHAB

How dense is your mesh? Maybe the connections for these devices to the mesh are tenuous or you have a choke point (e.g. all messages for one part of the mesh have only one router they can use to route back to the controller).

You have to run those commands from the Karaf Console. The Console | openHAB.

If you are on OH 4 you can set the logging level by navigating to Settings → bindings → Zwave and click the little gear icon in the upper right.

fennepa · July 26, 2023, 3:36pm

thx. I disabled autoupdate, activated the debugging and disabled all of my rules. problem did not disappear, although after several attempts I do not seem to get the double change returned anymore. I need help to decrypt such a log, I notice: NODE 11: TID 217580: Transaction not completed

==> /var/log/openhab/events.log <==
2023-07-26 17:29:45.543 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'KitchenWallLightsDimmer_Device' received command 0
2023-07-26 17:29:45.633 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'KitchenWallLightsDimmer_Device' changed from 58 to 78
==> /var/log/openhab/openhab.log <==
2023-07-26 17:29:45.560 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Command received zwave:device:7b22ab1c42:node5:switch_dimmer --> 0 [PercentType]
2023-07-26 17:29:45.561 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 5: Creating new message for command SWITCH_MULTILEVEL_SET
2023-07-26 17:29:45.561 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: SECURITY NOT required on COMMAND_CLASS_SWITCH_MULTILEVEL
2023-07-26 17:29:45.562 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured
2023-07-26 17:29:45.562 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: Adding to device queue
2023-07-26 17:29:45.563 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: Added 217578 to queue - size 1
2023-07-26 17:29:45.563 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2023-07-26 17:29:45.563 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 05 03 26 01 00 25 46 A4 
2023-07-26 17:29:45.564 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 5: Sending REQUEST Message = 01 0A 00 13 05 03 26 01 00 25 46 A4 
2023-07-26 17:29:45.565 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2023-07-26 17:29:45.565 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 217578: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 70
2023-07-26 17:29:45.566 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2023-07-26 17:29:45.566 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Polling initialised at 86400 seconds - start in 5000 milliseconds.
2023-07-26 17:29:45.566 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2023-07-26 17:29:45.567 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2023-07-26 17:29:45.567 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 217578: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 70
2023-07-26 17:29:45.567 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2023-07-26 17:29:45.568 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2023-07-26 17:29:45.568 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2023-07-26 17:29:45.572 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2023-07-26 17:29:45.573 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2023-07-26 17:29:45.573 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2023-07-26 17:29:45.574 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 217578: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 70
2023-07-26 17:29:45.574 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2023-07-26 17:29:45.575 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 217578: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 70
2023-07-26 17:29:45.575 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2023-07-26 17:29:45.575 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 5: sentData successfully placed on stack.
2023-07-26 17:29:45.576 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 217578: Advanced to WAIT_REQUEST
2023-07-26 17:29:45.576 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: TID 217578: Transaction not completed
2023-07-26 17:29:45.576 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2023-07-26 17:29:45.577 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2023-07-26 17:29:45.588 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 46 00 00 03 AE 
2023-07-26 17:29:45.589 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=70, payload=46 00 00 03 
2023-07-26 17:29:45.590 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=70, payload=46 00 00 03 
2023-07-26 17:29:45.590 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 217578: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 70
2023-07-26 17:29:45.591 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2023-07-26 17:29:45.591 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 217578: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 70
2023-07-26 17:29:45.592 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 217578: (Callback 70)
2023-07-26 17:29:45.592 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2023-07-26 17:29:45.593 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 217578: callback 70
2023-07-26 17:29:45.594 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=70, payload=46 00 00 03 
2023-07-26 17:29:45.594 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 5: SendData Request. CallBack ID = 70, Status = Transmission complete and ACK received(0)
2023-07-26 17:29:45.595 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: resetResendCount initComplete=true isDead=false
2023-07-26 17:29:45.596 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 217578: Transaction COMPLETED
2023-07-26 17:29:45.596 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: Response processed after 31ms
2023-07-26 17:29:45.597 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: TID 217578: Transaction completed
2023-07-26 17:29:45.597 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: notifyTransactionResponse TID:217578 DONE
2023-07-26 17:29:45.598 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2023-07-26 17:29:45.599 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2023-07-26 17:29:45.600 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2023-07-26 17:29:45.622 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 05 03 26 03 4E 9F 
2023-07-26 17:29:45.624 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=5, callback=0, payload=00 05 03 26 03 4E 
2023-07-26 17:29:45.624 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=5, callback=0, payload=00 05 03 26 03 4E 
2023-07-26 17:29:45.625 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2023-07-26 17:29:45.626 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: Application Command Request (ALIVE:DONE)
2023-07-26 17:29:45.626 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: resetResendCount initComplete=true isDead=false
2023-07-26 17:29:45.627 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: Incoming command class COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0
2023-07-26 17:29:45.627 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: SECURITY NOT required on COMMAND_CLASS_SWITCH_MULTILEVEL
2023-07-26 17:29:45.628 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 5: Received COMMAND_CLASS_SWITCH_MULTILEVEL V2 SWITCH_MULTILEVEL_REPORT
2023-07-26 17:29:45.629 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 5: Switch Multi Level report, value = 78
2023-07-26 17:29:45.629 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2023-07-26 17:29:45.630 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_SWITCH_MULTILEVEL, value=78
2023-07-26 17:29:45.631 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Updating channel state zwave:device:7b22ab1c42:node5:switch_dimmer to 78 [PercentType]
2023-07-26 17:29:45.632 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: Commands processed 1.
2023-07-26 17:29:45.633 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@49ef5d.
2023-07-26 17:29:45.633 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2023-07-26 17:29:45.634 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2023-07-26 17:29:45.635 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2023-07-26 17:29:45.636 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

fennepa · July 26, 2023, 3:42pm

I’m not sure how I can validate the route of each message. my network map looks like this:

the 5 is the node for these kitchenwalllights. it seems to me that it has enough options to find a way to the controller… the Idinio devices however are 12 and 14. these have to travel through 13 and 3 respectively.

rlkoshak · July 26, 2023, 4:17pm

You can’t really.

The network map is useful but it’s important to understand what the map means. The lines indicate which nodes each sees as a neighbor. That doesn’t mean that messages can’t flow to a node that isn’t listed as a neighbor. But it could be an indication of a bottleneck if, for example, a bunch of nodes only have one apparent path of neighbors to the controller.

Node five looks like it sees plenty of neighbors including the controller so that’s probably not a problem.

Click on those links. Are they two way or does 14 only see 13 as a neighbor but not the other way, or vice versa? Again, note that the link doesn’t mean that’s how the messages are flowing, just that during the last heal node 14 only saw node 13 as a neighbor (or vice versa).

Are these battery powered?

Is there some distance between these nodes?

fennepa · July 26, 2023, 4:54pm

clicking on a node does not trigger an action in my installation. I can only hover over them. this unwinds the spaghetti to show only the neighbours of that node. Are you indicating that my devices could be failing due to the disability to find a way to the controller? Device 14 actually has 6 other devices within 3 meters, with direct line of sight, since my physical dimmers are all located in the same wall. 4 of those are within 3~4 meters from the controller… If anything I’m more worried about 2 devices battling to be the host this time, like my 2 kids!

rlkoshak · July 26, 2023, 5:21pm

I don’t expect it to, but it should tell you the direction of the link.

Look in the upper left corner:

That shows the link between node 11 and 6 is bidirectional (i.e. 11 sees 6 as a neighbor and 6 sees 11 as a neighbor).

It’s a possibility that could be indicated by which nodes see the other nodes as neighbors as that can be an indication of a sparse mesh.

fennepa · July 26, 2023, 6:30pm

I’m sorry. I misread. click the link, not the node. it seems that all of my links between all of the nodes are bidirectional

apella12 · July 26, 2023, 6:36pm

There is a zwave debug viewer here; Z-Wave Log Viewer (opensmarthouse.org)

your snippet would look like this;

There is not enough information to analyze. It looks like the device sends it’s current state in response to the command to go to zero. However, I would need to see what happens in the next 5 to 10 seconds. As a point of information dimmers are, as a rule, very slow to react to a command. I did not look at the device parameters, but sometimes you can speed that up. I see that you have the command poll set for 5 seconds. That should be close, but it may take a bit longer.

Since the device responded in 24ms there is no communication issue.

fennepa · July 27, 2023, 3:24pm

what else is needed to analyse. I do not have more in my log.

apella12 · July 27, 2023, 3:38pm

That is odd. There should be a poll in 5 seconds. That whole log is less than one second.

fennepa · July 28, 2023, 10:00am

I have been playing around with the polling settings for several devices (different brands) and none of them seem to be doing any polling. ever. So I think I will have to look into the proper working of the controller or anything in my installation. The controller does not seem to have any config options relating to polling as far as I can tell. Is it possible to poll a device manually from the console or something? not sure where to start actually…

also: Does my polling issue relate to the inaccurate updates of the devices?

rlkoshak · July 28, 2023, 1:44pm

You can send the REFRESH command to an Item and the binding should go out and poll the device for it’s latest states.

I wouldn’t think so. If that were the case I’d think it wouldn’t work at all instead of working intermittently.

apella12 · July 28, 2023, 2:19pm

IMO it could be related based on the log. It could also be the (non-compliant) way your device works.

What the binding is supposed to do is send a SET command based on your action, then based on this parameter on the UI page
command poll
send a GET after 1.5 seconds (In this case). From your log, I believe you have this set at 5 seconds. Then the device sends a REPORT as to it’s state at that time. What happened in the log is the device sent a REPORT in response to the SET before the device had time to react (dimmers take maybe 3-5 seconds to get to a new state. If that is all the log you have, the binding may assume the REPORT is the answer and not send the GET. That’s why I asked for the next 5 seconds in the log.

If that is what is happening, you may need a rule to REFRESH as suggested by @rlkoshak after 10 seconds or so. My question on the log snippet. Did you command 0 and did the light go out? (regardless of the value in the OH UI)

fennepa · July 28, 2023, 4:43pm

I have something like a result here. I created a rule in blockly to send the refresh command to the device and I pressed “run rule” (I did not implement anything to trigger the rule on a itemchange or anything yet. I then send a command to the device through the ui. The result is that I do see a polling action in my log:

however, the item state almost immediately went back to value 0 (for which I do not have a change in the log) and the device is actually on, but I dont think it is at 78%, but rather something like 40.

fennepa · July 28, 2023, 5:23pm

it is not really possible to actually recreate this use case. When I slide the dimmer to 0 or press 0 on the slider in mainUI. I have to do that several times and even then the lights do not fully go to 0. however the changed state is in line with the intensity of the physical light, I think.

2023-07-28 18:47:10.390 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'KitchenWallLightsDimmer_Device' received command 99
2023-07-28 18:47:11.997 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'KitchenWallLightsDimmer_Device' changed from 91 to 96
2023-07-28 19:11:53.942 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'KitchenWallLightsDimmer_Device' received command 20
2023-07-28 19:11:54.052 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'KitchenWallLightsDimmer_Device' received command 0
2023-07-28 19:11:54.143 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'KitchenWallLightsDimmer_Device' changed from 96 to 97
2023-07-28 19:11:55.586 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'KitchenWallLightsDimmer_Device' changed from 97 to 98
2023-07-28 19:13:03.399 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'KitchenWallLightsDimmer_Device' received command 79
2023-07-28 19:13:03.603 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'KitchenWallLightsDimmer_Device' received command 0
2023-07-28 19:13:06.563 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'KitchenWallLightsDimmer_Device' changed from 98 to 19

the values are all over the place. when I finally slide the dimmer 0 once more. the item is on 0, the lights go out, but this is in my log:

2023-07-28 19:19:04.508 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'KitchenWallLightsDimmer_Device' received command 2
2023-07-28 19:19:06.565 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'KitchenWallLightsDimmer_Device' changed from 19 to 0

I’m confused as to what is cause and what is effect.

apella12 · July 28, 2023, 6:33pm

I’m finding this hard to follow without a blow by blow on what you are doing with the slider. I generally SET dimmer level with a rule as the slider never seems to land exactly where I want.

Anyway I think I found this device in the DB. Can you set parameter 2 to zero, that might help? Also referencing the picture I posted what is your command poll time?

fennepa · July 28, 2023, 7:37pm

This is the config for the thing. it is a ECO-DIM.07. I changed the ‘Notify load status change’ into 2 after the snapshot…

apella12 · July 28, 2023, 7:46pm

Ok “two” should be okay. Zero disables completely, “two” only sends notification if operated from the switch (not OH). I’m thinking this should stop the report immediately after the command (eliminating at least one intermediate value). See if that helps.

fennepa · July 28, 2023, 8:03pm

there seems to be some improvement. I watch the mainUI item slider on a seperate screen and it is not making 2 moves after one command anymore. I gave it 2 inputs that went fine, but it didn’t respond on the 3th at all. it stayed on 50:

my next command was 75 and the result was 0, as if the command was hanging in a queue: