This is very good idea but time is a varible (2 different values). I am not sure if auto off could be reconfigured on a fly.
If you use my custom driver you could reconfigure the timers from RM using the "Set Parameter" command and giving the proper arguments. You can set it down to the second if you want, the "units" is adjustable on another setting.
It may not be perfectly reliable to the exact second, since it just uses some super basic internal clock susceptible to some drift but otherwise it should be reliable.
You may also want to set the power restore behavior to always off, in case power was lost while it was on, so it is not stuck in the on state.
1 Like
Thank you for the info. Daily run time is 3sec and once a month 100 sec. I have so far unused ZEN17. This will be a good testbed for trying things without destroying existing setup.
UPDATE
Log for the rule was turned on. Here it is from the latest night run:
Log shows no problems. Everything executed exactly as it should.
And here is associated a device events log (included yesterdays data):
Pattern is exactly the same. Commands are sent at a right time.
And again there is a pair of "physical" On/Off events, delayed by approximately 20sec and spaced by around 1 sec. I am near 100% sure, the same reporting will on every run.
And for sanity check I ran this rule once manually.
The app log is the same:
However the device event log is different:
This time it looks reasonable. The recorded "physical" event immediately follows a "command" from rule.
The only difference between this two runs - one was triggered and second one was manually executed. And please, don't tell me this is something to do with a ZWave Mesh. The mesh is very stable and reliable. Plus the activity at a night time is next to zero.
I don't think this is a problem with my setup. To my EE eyes it looks like when Trigger is involved hub is running Event Detection tasks and this creates some mess in a reporting.
If you manually trigger the on / off commands from the device page do you see the same delayed reports or does it work as expected?
I played a bit with the Relay-2 (it is not used and safe to play with) from the device page.
No delays, the response is instant.
Yes, it works as expected.
Only "physical" events are recorded (no commands):
So it does seem like something is causing the event log to be delayed, only when the commands run from your rules.
Does the time of the event log coincide with the event hitting the actual system logs?
One could argue that its just the event log, the device worked correctly and just the log was delayed. HOWEVER, if you were to have other actions that key off that switch state, the 22s delay could cause problems. Something like a repeat loop to confirm the device responded appropriately may not work as desired.
This could be a legit issue.
Could be proven further if you enabled debug logging enabled permanently, so you can capture full logs from the rule and device together. The debug logs should generate something as soon as in inbound message hits the driver.
My educated guess (I am EE who designed and debug many embedded controllers, starting with 8-bit CPUs and Assembler Programming Language back in a mid 80s) this observed phenomena is clearly related to the multitasking/multithreading. When rule runs manually all timing is near perfect. However when rule is Triggered all that delays are in place. The actual rule and hardware runs perfectly fine. But the reporting on the Device Events page becomes very messy. The difference is - when rule is Triggered task(s) related to the detecting Event and sending a Trigger to the rule are running and this is a reason for the observed behavior.
And this is up to developers to pay serious attention on the observed behavior because it may reveal some hiding problems or simply forget about this. 22sec delay is unbelievable huge even for very busy system which is absolutely not a case around midnight.
Now I am near 100% sure this is only log recording problem because everything else is near ideal.
Logging for the Rule is turned on. But I think, the logging for the device is active only for a 30min. However I can clone this rule and run the cloned version on the unused Relay-2. This may reveal something. Let me try this and see what happens.
Just in case, here is an update on the Cloned Rule Run.
The difference between real and cloned rule is - a clone uses unused Relay-2.
Rule was running 3 times:
- manual run;
- periodic schedule (just once);
- specific time (this is an exact Trigger for the real rule).
Surprise, but all 3 times everything was running perfectly fine.
Here is a log for the rule (all 3 runs):
Log for the Relay-2:
And Device Events log:
Time Stamps correlation between all 3 logs is next to ideal.
I am really confused about what is going on around 1:30am (what tasks might be running at this time). I will reschedule run time for the real rule and see what happens.
UPDATE
I ran a real rule rescheduled to run now and everything looks OK.
Perfect correlation between all 3 logs.
So, I will change Trigger to original 1:30am and see what happens
Change the filter on the logs so that it shows both the rule and the device.
So, my custom driver you can enable debug forever. OR to minimize changes, you can also turn on debug on the system driver, switch the driver to "device" and use the command to deleted scheduled job, then switch the driver back (do not save prefs after this or it will schedule the 30 mins shut off again).
If you do get a log with this, if you show a combined log with the rule and the logs from the device all together, IMO it will really paint the picture of what happened. (Also show corresponding event log entries to confirm they match times of debug logs)
Do you agree that this event logging delay would normally not cause a problem except in special cases like my example I thought of?
You know, it has not been established what the timing is of the various events. All we know are the device logs, not the running logs. It's impossible to tell what is going on with the information provided before @vitaliy_kh's last 2 posts. For example, we certainly don't know what the switch state is during the 22 seconds.
Here is a requested combined log for test run of real rule:
And a correspondent Device Events log:
To my eyes now everything looks OK.
Yeah true, I was assuming the switch state would coincide with the event log, but I do not know the inner workings. Maybe it is possible the state actually updates accordingly but the event log gets delays somehow?
Will have to see if it can be reproduced with full logging to match it up to the event log.
My few latest test runs for real and cloned rules did not have this delays. Everything looks OK.
How do I log a real switch state in the middle of the night?
One hint will be what debug logs or info logs from the device show relative to the event history. If those are logging in real time and only the event log is delayed, that is a clue. If both are delayed that could point us in another direction.
To capture the actual switch state, only thing I could think of would be another rule that triggers on the switch state changing, and then just logs something. I dont think that will trigger though until the event is put in the event history, so probably not useful.
We don't know that -- this is effectively the same question as what is the 22 seconds.
A rule that triggers off the switch state changing with logging all turned on would be good. It doesn't need any actions. That rule should be included in the logs filter.
2 Likes
To my eyes it looks like this is a case.
Recent test runs (few minutes ago) of real and cloned rules did not exhibit this phenomena.
But it was consistent for the past runs around midnight.
I am confused. What exactly should I ran and when?
Running all these tests now as we speak (did it few times) do not show any delays.
