Zwave Device shows double on- and off-entries in log

[Domoberry]

Hi Forum,
I'm using Zwave with Domoticz to control some switches and some thermostats. This is a question specifically on the Domoticz log for the switches, which show double entries for 'On' and 'Off', e.g. even though I click in the Domoticz UI once to switch on or off the switch, the log for that switch shows two entries for each. Any advice on what the root cause might be and how to resolve?

Here is an example from the Log of one of the switches:

Code: Select all

2019-11-02 14:37:43	Off
2019-11-02 14:37:43	Off
2019-11-02 14:37:31	On
2019-11-02 14:37:31	On

When looking at the log output in the OpenZwave control panel, there are sometimes errors logged:

Code: Select all

2019-11-02 14:37:34.578 Error, Node020, ERROR: Dropping command, expected response not received after 1 attempt(s)
2019-11-02 14:37:34.578 Always, 
2019-11-02 14:37:34.578 Always, Dumping queued log messages
2019-11-02 14:37:34.578 Always, 
2019-11-02 14:37:34.578 Always, 
2019-11-02 14:37:34.578 Always, End of queued log message dump
2019-11-02 14:37:34.578 Always, 
2019-11-02 14:37:46.062 Error, Node020, ERROR: Dropping command, expected response not received after 1 attempt(s)
2019-11-02 14:37:46.063 Always, 
2019-11-02 14:37:46.063 Always, Dumping queued log messages
2019-11-02 14:37:46.063 Always, 
2019-11-02 14:37:46.063 Always, 
2019-11-02 14:37:46.063 Always, End of queued log message dump
2019-11-02 14:37:46.063 Always,

Note that the OpenZwave log does not always capture these two errors when the switch is (de)activated. The Domoticz log of the switch always has the two 'on' and 'off' entries. So, perhaps this is a non-related problem.
Other information:

• ZWave controller: Aeotec Z-Stick G5 ZWave+
• ZWave device: Zwave-plus 2 relay switch FGS-223
• The Zwave device is located very close to the controller (but was included when at a different location)
• Domoticz: Version: 4.10717
• Another ZWave switch (Neo CoolCam Smartplug) does not show these 'double on/off' log entries
• The other switch in the FGS-223 shows the same behavior
• The switches are also controlled via a dzVents script (this might be irrelevant)
• Another post suggests a range issue and/or bad inclusion. The controller and device are very close and I fear that excluding and re-including leads to new IDX numbers need to redefine the device in Domoticz, so did not yet try that.

And... I'm not an expert and Zwave is to some extend 'a step into the unknown' yet have found this forum to be a great source of information!

[akamming]

I have 2 Fibaro FGS223 devices. Both have the same behaviour. it does not cause any errors on my system. So i never tried to resolve… i think it is the standard behaviour of this device..

[Domoberry]

Hi Akamming, thanks for the reply.
Indeed, could be just the way this device happens to work. In general, the FGS-223 works fine.
Do you see any errors in the OpenZwave log for either of the FGC-223's?

[lost]

Hi Akamming, thanks for the reply.
Indeed, could be just the way this device happens to work. In general, the FGS-223 works fine.
Do you see any errors in the OpenZwave log for either of the FGC-223's?

The command is supposed to be sent by the controller. So a second one may result from a timeout (switch not acknowledging 1st command in time) but they show up in the same second so that's strange: Maybe checking logs (more precise action time) should help figure this out.

See here:
https://www.silabs.com/documents/login/ ... -Guide.pdf

6.2.2 + 6.3 p 12. Timeout is supposed to be 1.6s and first retransmission attempted 100ms after. So with defaults a timeout may show a 1st retry 1.7s after initial switch. On your side it's in the same second.

But see 7.5: Looks timeout can be changed and set in 10ms steps. Maybe Domoticz OZW configuration sets this to a value that may be too short for a device slow to ack messages and increasing this & restarting OWZ/Domoticz may help?

[Domoberry]

Hi Lost,
Thanks for the tip; I will need to look into these settings, I'm not sure where to find them in the Zwave settings exactly, but to find something, start looking first.
Further, I performed a manual 'on' via the Domoticz and recorded the corresponding entry in the Domoticz log file. Removed some log entries from other devices and re-ordered specifically the 'Status: User: Admin …" entry as this appeared in the log out of sequence. I replaced it such that all time stamps are sequential (I'm not sure why a log entries shows up out of sequence).
There are also two 'on' entries in the log for the device.
Perhaps this shines further light on what is happening. It shows a time out notice some 3 seconds later.
Node 20 is the FGC-223 dual switch.

Code: Select all

2019-11-06 17:14:07.769 Status: User: Admin initiated a switch command (303/FGS-223 Outside House/On) 
2019-11-06 17:14:07.770 OpenZWave: Domoticz has send a Switch command! NodeID: 20 (0x14) 
2019-11-06 17:14:07.781 (Z-Stick G5 ZWave+) Light/Switch (FGS-223 Outside House) 
2019-11-06 17:14:07.961 (Z-Stick G5 ZWave+) Light/Switch (FGS-223 Outside House) 
2019-11-06 17:14:10.735 (Z-Stick G5 ZWave+) Usage (FGS-223 Pwr House lights) 
2019-11-06 17:14:10.736 (Z-Stick G5 ZWave+) General/kWh (FGS-223 kWh Meter) 	
2019-11-06 17:14:10.839 Status: OpenZWave: Received timeout notification from HomeID: 3484712579, NodeID: 20 (0x14) 

Two things not so clear to me:
- why does the line "Z-Stick G5 ZWave+) Light/Switch (FGS-223 Outside House)" show up twice?
- why is there a time-out at the end?

[Domoberry]

On the retry settings:
- in the Domoticz/device/setup/node management/ZWave control panel I cannot find such setting for the Zwave controller
- in the Domotics/device/setup/Zwave controller I see this setting:

Code: Select all

 
5. RetryTimeout: 3000 (ms) (actual: 3000)

[lost]

On the retry settings:
- in the Domoticz/device/setup/node management/ZWave control panel I cannot find such setting for the Zwave controller
- in the Domotics/device/setup/Zwave controller I see this setting:

Code: Select all

 
5. RetryTimeout: 3000 (ms) (actual: 3000)

In your log, we see the command taken into account by Domoticz and... sent 2 times (second 180ms after first) on OZW side... and one timeout at 3s+58ms after 1st command.

Then I believe 1st command send fails (because timeout 3s+ after, second would be before), OZW somehow immediately noticed this on controller management side, and re-send very shortly.

So the 3s timeout setup makes sense with logs and must not be the issue. I'm not aware enough of z-wave radio interface to figure-out what could lead OZW re-send without waiting for the timeout.

Can imagine that some collision detection (another device sending at the exact same moment) could be a reason, but this should not happen every time for this single device type!

Another reason may be there is a way for the device to immediately discard a command (because not ready to handle it...), triggering a re-send by controller... and this one is never ready at first and always needs to be "ass kicked" before proceeding

Some devices, in their parameters documentation or settings, warn that frequent reports from other side functions (like temperature...) may harm base function (switching, here) and make it less responsive. But behavior should not be deterministic IMO.

=> You can dig in z-wave specs (or ask on OZW mailing list) to try to find a reason for this or try the prayer-wheel manufacturer ticket machine. But timeout change is not needed here. You can also just live with this, some devices are buggy... Let me know if you finally find the root cause, always interesting to know!

[Domoberry]

Thanks Lost for your comments! Relevant feedback!
Adding some additional information to keep this post 'actual'.
- There is not a time-out error with every switch action. Some do, others don't. A time-out error is shown in the Domoticz log as "Status: OpenZWave: Received timeout notification from HomeID: xxxxxxxxxx, NodeID: 20 (0x14)"
- If there are time out errors, they appear some 3 seconds after Domoticz has send a command: "Status: User: Admin initiated a switch command (303/FGS-223 Outside House/On)". This is in line with device setting. Time-outs happens randomly with 'off' commands as well.
- Only if there is a time-out error in the Domoticz log, there is a corresponding error in the OZW log
- The Domoticz log always shows the two ZWave entries 180 ms apart
- I now feel that the 'time out error' and the 'always two entries problem' are different events with different causes
- The manual for the FGS-223 does not mention a setting dealing with the transmission settings (afaik)
- I have an alarm system also using the same 868 MHz band (I cannot find the exact frequencies it uses). It is very close the both the ZWave controller and the FGS-223 (< 1m). This could cause collision errors. I cannot easily shutdown the security system (duh), yet it is on the to-do list: see if this resolves the time-out errors.
- To avoid misunderstandings: The FGS-223 works fine in practice
Asks:
- Zwave EU operates on 868.40, 868.42 or 899.85 MHz. Is there a way to force the controller to use a specific channel?
- I do not feel that excluding and renewed including the FGS-223 would make sense. Agree?
- What does the Domoticz log entry "(Z-Stick G5 ZWave+) Light/Switch (FGS-223 Outside House)" actually mean: something like 'OZW or Domoticz has asked the ZWave controller to perform certain action' or rather feedback like: 'The OZW or the ZWave controller has performed certain action' ?

I will update this post when new information becomes available.