According to the log rule executed correctly. On/Off commands were sent at a right time with a correct delay. However physical On/Off recorder events were delayed by 22xec and delay between On and Of events is only about a 1 sec.
Where is a truth?
It's not impossible for both to be "true." A command could have been sent to the device, then for some reason, it could have not reported this state back to the hub until some time later. That reason could be a problem with the device or the mesh network it lives on that caused a delay, something unusual about the reporting configuration of a device (e.g., if it's polling only), or it not acting on the command at all and something entirely different happening later (another rule or app, a physical on/off, etc.).
That last thing seems possible in your case; given the "Produced by" column, another rule also seems to be acting on this device. But even then, it's unusual that there are not listed commands from that rule that should have caused this.
I don't see any actual logs in your screenshot, and those would be quite helpful for knowing with that rule is actually doing when. As you know, this would greatly help in additional troubleshooting.
When I was testing all this setup many times mainly for calibrating the dispensed volume everything was working perfectly fine. Since everything was working exactly as expected 100% of times I did not look for any logs and/or events. Today I was simply checking how this rule ran automatically (this was very first automatic run) I noticed this time stamps funny behavior.
I guess, this question is for developers.
Correct. Since everything was tested very positive I did not turn on any logs but simply relied on checking device events.
OK, just in case I will turn on all rule logs and see what happens.
OK. So, what steps have you taken to rule out any of those issues as possible problems?
That is not what your screenshots show, which is two different rules, the most recent of which has a different name than the one you just showed in your last post:
As of now none because I don't even know this is a problem. As I mentioned while conducting many test runs for calibration I did not notice any abnormal behavior and therefore did not check nether events or logs. This could be something to do with how device events are reported.
Again, this is question for the developers.
There is only one single rule which should run at 1:30am every day (and it did).
I have no idea why device events logs is showing what you see.
What, exactly, do you want someone to look into? Do you not actually have two different rules like your screenshot shows? Otherwise, it could be any of the reasons I mentioned above. Without more information, it's impossible to say exactly which it may have been in this case.
Also: I didn't think of this before, but do you have hub backups scheduled around 1:00 or 1:30 AM? That may (or may not) be an intense process that could cause delays for a minute or so while it runs. While it shouldn't be a problem, I still normally try to avoid anything important around my hub backup times (which I've also moved to a different schedule).
Now I want an answer why I am seeing device event reporting which does not look right.
Yes, this is only one rm rule for this device scheduled to run daily at 1:30am.
Without any information about the actual device (e.g., protocol, manufacturer and model, driver, etc.) or an answer to any of the questions above asking for more information, it is impossible to say. It seems you may be unfamiliar with the basics of app, device, and hub troubleshooting, so hopefully this document will help:
In particular, if it's a Z-Wave device, you may want to look at the Z-Wave troubleshooting doc linked to from that one. In any case, you may also want to look at device and apps stats to see if anything stands out; possibly Logs > Location Events to see if you see "severeLoad" or anything else concerning around this time; and Logs/Past Logs in general to see if any errors, warnings, spammyness, or anything else stands out.
In the future, I would also suggest keeping at least action logging (if not all logging) enabled for this rule, and I would also look into that (so far mysterious) second rule to see if it might be sending commands to the device as well. Logs are normally helpful for troubleshooting rules.
The device is ZWave ZEN-17 using the built-in driver. Once again, except for the abnormally looked device events page everything is working as expected and 100% reliable. There is nothing to troubleshoot except for that events reporting.
This is based on the lack of information provided about what you have done to troubleshoot the problem so far. Because of both that and the lack of information provided to answer subsequent, related questions, I can only assume it was none. If that is not the case, this question remains unanswered (and in this case that document provides information about ways you can get started and information that would be helpful to share about what you've tried so far):
Back to this issue:
This kind of information is helpful to know, so thanks for sharing. There are unlikely to be any parsing problems or delays as a result of the built-in driver, as I have seen no similar reports, but if you want to be extra-sure, debug logging will show you everything the hub gets from the device even if the hub doesn't parse it into an event (so it can't hurt to enable, though I doubt it will be enlightening).
But that is something to troubleshoot. Since we now know that this is a Z-Wave device (thanks to the above, one reason this kind of information is helpful to know upfront), I would also look into Z-Wave troubleshooting.
Again, if I didn't check that device events page I would not even notice anything abnormal. I did run this rule many times manualy for calibrating pump run time in order to dispense the desired amount of fluid. Surprisingly the results were very consistent (I actually expected much wider dispersion). Last night it was a very first automatic rule run. The reason why I checked the device events page was to make sure pum was running a specified time. Surprisingly what I saw was very confusing. And I was even more confused when you said this page didn't look right.
And again, nothing is wrong with the device an rule. Everything is working as it should. But yes, something is not right with the device events page.
I will turn on logs for this rule and will chek what it will show and how this will corelate with the device event page.
Were you awake at this time to verify if the switch did or didn’t turn off exactly when expected? That is not clear from the above, although my assumption was that the claim is that the event reporting only was delayed. However, a delay with either the actual outcome or the reported event on the hub could be explained by a mesh problem, as can be troubleshooted with the steps above.
No, I was sleeping. And this is why I checked the device event page at morning. But I 100%+ sure the pump was running because it never failed during many test runs.
If I may chime in and this might not really help your questioning, if you look at the event logs, when triggered by a rule, virtual button, etc. a switch will report the type as being digital, but in this case, we are seing physical that should mean that someone used the button on the device, I know that the ZEN17 does not have a physical button but if I'm not mistaking, it does have the ability to install buttons on the inputs to be used as a physical button. So if this this was triggered by RM, why is it reported physical?
In this application Relay-1 is an On/Off pump switch and Sensor-1 (configured as a Contact Sensor) is connected to the Liquid Level Sensor for reporting "Bottle Empty" status. That is it.
BTW, the recorded sensor events are only related to my testing.
This is a question to whoever created a built-in driver for the device.
And this is a reason why I created this thread.
That is just the command; the question above is related to the (hopefully) resulting event.
Whether an event shows as "physical" or "digital" seems to be a very different question from anything posed in your original post...
This device doesn't actually report anything back differently from physical vs. digital events (that I know of; if someone has definitive clues, please provide the Z-Wave commands you'll see with debug logging enabled that show the difference). So, as with many similar devices, the physical and digital annotations seem to be a best guess from the driver. I'm honestly not seeing how "digital" would ever get set in this one at all, though it's possible I'm missing something...
In any case, I guess the moral of this story is not to read too much into that.
I really want to know what happened for 22 seconds. It's 100% reliable, except for the logs it produces and the unknown reason for 22 seconds. I think that summarizes it pretty well.
Yes, your summary is reasonable.
How can I help to debug this issue?
The problem is - this specific setup cannot be used for the testing and debugging. It is functional deployed Vinegar Dispenser for the automated AC Drain Line cleaning.
But I do have another ZEN-17 which is not yet used. I can set it up and run a copy of the rule. Please let me know if this makes a sense?
@vitaliy_kh - While not a direct response to your initial question, I am wondering if you have explored the following Auto-Off Feature of the ZEN17? Seems much safer to have the ZEN17 automatically turn off the output versus depending on a Z-Wave message to properly turn things off? What if the Z-Wave mesh goes down after the pump is turned on? What happens if your Hubitat Hub were to lock up for some reason? Etc...