Rules not triggered

[ebaauw]

I think there's an issue with rule triggering. I have several rules that should trigger 10 minutes after a CLIPGenericStatus sensor has changed status to -2. One of these rules actual resets the status to 1. The rules seem to be triggered in random order, which is OK. However, after the rule that changes the status has executed, the remaining rules are no longer triggered. Presumably, because the conditions of the remaining rules are evaluated only after the previous rule has been executed. I would expect the conditions of all rules to be evaluated before any rule gets executed.

I think a very long time ago, we had a similar issue with rules that would set a CLIPGenericFlag and update it. My use case is a more complicated, since it involves multiple rules.

As a workaround, I now changed the condition for the rule that changes the status to be triggered 10 seconds after the other rules.

[ebaauw]

Now on v2.05.72, still seeing some issues with rule triggering for time-based conditions:

• ddx rules seem to be triggered twice, a second apart, looking at the deCONZ log and at the timestriggered attribute. No big deal for me, as the actions are idempotent;
• Rules with a single condition on /config/localtime in W7/T21:00:00/T09:00:00 didn't get triggered yesterday (Friday). The rules with value W120/T21:00:00/T08:00:00 did get triggered on Thursday. I restarted deCONZ Thursday (after installing v2.05.72), so this would have been the first trigger since deCONZ started. I think I've seen before that rules on localtime don't get triggered on the day the rule is created and/or the day deCONZ starts.

[ebaauw]

• ddx rules seem to be triggered twice, a second apart, looking at the deCONZ log and at the timestriggered attribute. No big deal for me, as the actions are idempotent;

https://github.com/dresden-elektronik/deconz-rest-plugin/blob/bb47cdbc19c257e3000fdb8475aa456830e6df94/rest_rules.cpp#L1387-L1391

It seems that QDateTime::secsTo() ignores the microseconds part of the QDateTime value, instead of rounding them to the nearest second. This means that any value in the range from -0.999 to 0.999 will evaluate to 0. Using QDateTime::msecsTo() instead seems to fix this:

            QDateTime dt = item->lastChanged().addSecs(c->seconds());
            qint64 delta = now.msecsTo(dt);
            if (delta < -500 || delta >= 500)
            {
                return false;
            }

• Rules with a single condition on /config/localtime in W7/T21:00:00/T09:00:00 didn't get triggered yesterday

https://github.com/dresden-elektronik/deconz-rest-plugin/blob/bb47cdbc19c257e3000fdb8475aa456830e6df94/rest_rules.cpp#L1820-L1823 I added an info message for the case when e.id().isEmpty(), i.e. when handleRuleEvent() is called for /config/localtime. It would seem that it is not always called every second for /config/localtime. If the time of the condition is missed, the rules doesn't get triggered. If I understand the code correctly, this could also cause ddx rules not to be fired.

@manup, I'm afraid this is beyond me. As far as I can tell, handleRuleEvent() is called only from eventQueueTimerFired(). The /config/localtime event is queued from idleTimerFired(). I'm not sure which timer is failing, but I suspect it's the idle timer. The skipping seems to happen when the REST API plugin is busy, e.g. when updating the database.

I'm inclined to move the code to update /config/localtime https://github.com/dresden-elektronik/deconz-rest-plugin/blob/bb47cdbc19c257e3000fdb8475aa456830e6df94/de_web_plugin.cpp#L14303-L14308 to eventQueueTimerFired(), but I'm afraid that will break the timer logic based on the queue not being empty. I'm not sure adding a separate timer to update /config/localtime is the answer either.

[ebaauw]

@manup, sorry to bug you. Could you please have a look at the update of /config/localtime? I'd like to fix this asap, but I'm not sure what approach to take.

[ebaauw]

I added an info message for the case when e.id().isEmpty(), i.e. when handleRuleEvent() is called for /config/localtime. It would seem that it is not always called every second for /config/localtime.

Did some extensive testing and debugging. Somehow sudo journalctl -afn 1000 -u deconz-gui | grep rule fails to show all log lines containing rule. A sudo grep rule /var/log/syslog does show them.

Except during startup, handleRuleEvent() seems to be called for /config/localtime every second alright. I changed the debug message to include the time value of /config/localtime, up to the millisecond.

My current theory is that evaluateRule(), which is triggered from handleRuleEvent(), might have faulty logic. It evaluates the rule conditions against the (current) time of execution of evaluateRule(), instead of against the (current) time from /config/localtime. Since idleTimerTriggered() sends an event for /config/localtime, it might take some time before handleRuleEvent() is called. Also, with over 250 rules, there might be some time between the first and last evaluateRule(). Combined this could cause the rule to be evaluated against a second later, missing the condition.

I changed evaluateRule() to set now to the time of /config/localtime, when the rule event is for /config/localtime. I'll keep that running for a while and see if it still misses some triggers. Maybe now should always refer to /config/localtime, so evaluateRule() should get the resource item for it. Or maybe handleRuleEvent() should do that once, and pass the value as parameter to evaluateRule().

[ebaauw]

In v2.05.73.

[ebaauw]

Damn. My 23:00:00 alarm didn't go off this evening. Looking at the log, deCONZ skipped two seconds, during database save. Note the times between the last SQL statement and the message that it took 2573ms to save the database. If I understand the code, the COMMIT takes the majority of that time, probably blocking the triggering of the timers. @manup, Is there a way to handle the commit asynchronously or do the database I/O in another thread?

Feb 27 23:00:00 pi2 deCONZ[14724]: 22:59:59:169 rule event at 22:59:59.152: /config/localtime
Feb 27 23:00:00 pi2 deCONZ[14724]: 22:59:59:541 Poll APS request to 0x00158D0002834C6C cluster: 0x0008 dropped, cluster doesn't exist
Feb 27 23:00:00 pi2 deCONZ[14724]: 23:00:00:152 DB save zll database items 0x00000081
Feb 27 23:00:00 pi2 deCONZ[14724]: 23:00:00:152 DB sql exec REPLACE INTO nodes (id, state, mac, name, groups, endpoint, modelid, manufacturername, swbuildid, ritems) VALUES ('327', 'normal', '00:15:8d:00:02:83:4c:6c-01', 'Bedroom Curtains', '5,0,65520', '1', 'lumi.curtain', 'LUMI', '04-13-2017', '{"attr/manufacturername":"LUMI","attr/modelid":"lumi.curtain","attr/name":"Bedroom Curtains","attr/swversion":"04-13-2017","attr/type":"Window covering device","attr/uniqueid":"00:15:8d:00:02:83:4c:6c-01","state/alert":null,"state/bri":254,"state/on":true,"state/reachable":true}')
...
Feb 27 23:00:04 pi2 deCONZ[14724]: 23:00:00:191 DB sql exec REPLACE INTO sensors (sid, name, type, modelid, manufacturername, uniqueid, swversion, state, config, fingerprint, deletedState, mode) VALUES ('434', 'Dining Room Fan', 'ZHAPower', 'SP 120', 'innr', '00:15:8d:00:02:17:92:69-01-0b04', '2.0', '{"current":0,"lastupdated":"2020-02-27T21:58:22","power":0,"voltage":235}', '{"on":true,"reachable":true}', '{"d":16,"ep":1,"in":[2820],"p":49246}', 'normal', '1')
Feb 27 23:00:04 pi2 deCONZ[14724]: 23:00:02:725 DB saved in 2573 ms
Feb 27 23:00:04 pi2 deCONZ[14724]: 23:00:02:725 don't close database yet, keep open for 900 seconds
Feb 27 23:00:04 pi2 deCONZ[14724]: 23:00:02:839 poll node 00:17:88:01:04:e3:8a:2e-0b
Feb 27 23:00:04 pi2 deCONZ[14724]: 23:00:02:839 Poll light node Washroom 1
Feb 27 23:00:04 pi2 deCONZ[14724]: 23:00:02:842 rule event at 23:00:02.842: /config/localtime
Feb 27 23:00:04 pi2 deCONZ[14724]: 23:00:02:862 rule event at 23:00:02.842: /config/localtime

[ebaauw]

Next idea: keep track when previous trigger for RConfigLocalTime happened, and check whether time for conditions falls between last trigger and current trigger time. Resource already keeps track of previous value, just need to enable millisecond resolution for RConfigLocalTime and use the value instead of lastSet() or lastChanged().

[Thomas-Vos]

Hi @ebaauw, I am currently running into this issue as well. The rule that doesn't get triggered looks like this:

{
    "actions": [
        {
            "address": "/groups/28/action",
            "body": {
                "bri_inc": -127
            },
            "method": "PUT"
        },
        {
            "address": "/sensors/83/state",
            "body": {
                "status": 2
            },
            "method": "PUT"
        }
    ],
    "conditions": [
        {
            "address": "/config/localtime",
            "operator": "in",
            "value": "T08:00:00/T23:00:00"
        },
        {
            "address": "/sensors/15/state/presence",
            "operator": "eq",
            "value": "false"
        },
        {
            "address": "/sensors/15/state/presence",
            "operator": "ddx",
            "value": "PT00:00:15"
        },
        {
            "address": "/sensors/83/state/status",
            "operator": "eq",
            "value": "1"
        }
    ],
    "created": "2020-06-04T11:52:31",
    "etag": "100c67af13910fd9ac47d611f3462bbf",
    "lasttriggered": "none",
    "name": "Motion sensor 15 dim",
    "owner": "F164495FDB",
    "periodic": 0,
    "status": "enabled",
    "timestriggered": 0
}

If I remove the localtime condition it works fine. The current value for localtime is "localtime": "2020-06-04T13:58:52" so I see no reason why this rule shouldn't be triggered.

I am using a manually built version of deCONZ based on (unrelated) pull request https://github.com/dresden-elektronik/deconz-rest-plugin/pull/2849 so your fixes of https://github.com/dresden-elektronik/deconz-rest-plugin/pull/2658 should be included but unfortunately the issue is still there.

[ebaauw]

This is unrelated, but a very interesting use case. Both the ddx and in conditions are evaluated as trigger (rather than as regular condition) on the clock event. The in condition evaluates to false, because it's not 8:00:00. So the rule isn't triggered.

I'm not even sure if I would consider this behaviour a bug; specifying multiple dx and/or ddx conditions will cause similar behaviour. I suspect you'll see the same behaviour on the Hue bridge. I see no easy way to fix this. Probably need to introduce a new operator next to in, that is always evaluated as a condition, and never as a trigger, cf. stable vs ddx (from the Hue API; I don't think deCONZ supports stable).

As workaround use a CLIPGenericFlag to set day vs night, with separate rules to set/clear it based on /config/localtime, and use a simple eq condition in this rule en lieu of the in condition.

[Thomas-Vos]

Thanks for the explanation Erik.

I suspect you'll see the same behaviour on the Hue bridge.

On a Hue bridge all works fine. The rule is triggered when presence is false for 15 seconds and if the time is between 8:00:00 and 23:00:00. I've been using this type of rule in my app Hue Essentials for a long time (on a Hue bridge) and it works fine. Philips Hue even uses this in their own app for the motion sensor. Here is an example of a rule the official Philips Hue app created on a Hue bridge:

{
    "name": "22:",
    "owner": "96ff60f4-134d-4b51-82b2-d685da51b82a",
    "created": "2020-06-04T15:37:49",
    "lasttriggered": "none",
    "timestriggered": 0,
    "status": "enabled",
    "recycle": true,
    "conditions": [
        {
            "address": "/sensors/39/state/presence",
            "operator": "eq",
            "value": "false"
        },
        {
            "address": "/sensors/39/state/presence",
            "operator": "ddx",
            "value": "PT00:09:15"
        },
        {
            "address": "/config/localtime",
            "operator": "in",
            "value": "T08:00:00/T23:00:00"
        },
        {
            "address": "/groups/6/state/any_on",
            "operator": "eq",
            "value": "true"
        }
    ],
    "actions": [
        {
            "address": "/scenes/9KOKePsm7-Gvrt8",
            "method": "PUT",
            "body": {
                "storelightstate": true
            }
        },
        {
            "address": "/groups/6/action",
            "method": "PUT",
            "body": {
                "transitiontime": 4,
                "bri_inc": -127
            }
        },
        {
            "address": "/sensors/246/state",
            "method": "PUT",
            "body": {
                "status": 2
            }
        }
    ]
}

I am now trying to get the same working on deCONZ, but the behaviour on deCONZ really surprises me as it is different than the Hue API. I see no reason why localtime shouldn't be used this way.

A new operator could be an option, but if the Hue bridge doesn't need it why does deCONZ need it? Could you reconsider this is a bug?

[ebaauw]

On a Hue bridge all works fine Could you reconsider this is a bug?

Yes, I think the deCONZ API still strives to be backwards compatible with the Hue bridge. There are many other differences as well, though.

A new operator could be an option

Obviously not, if we consider Hue-bridge-API compatibility.

but if the Hue bridge doesn't need it why does deCONZ need it?

Obviously the deCONZ REST API plugin implementation is different from the Hue bridge API implementation.

but the behaviour on deCONZ really surprises me as it is different than the Hue API.

The Hue bridge API documentation isn’t always clear. A lot of the rules functionality was reverse engineered from how the Hue bridge appeared to be working, rather than implemented from specs. We had quite some challenges back in the days to get the current functionality right.

[Thomas-Vos]

I agree that lots of documentation is missing for the Hue API, especially for the rules. That is indeed a big challenge to get it all working similar in deCONZ! However, it is really nice to be able to create rules that work on both deCONZ and a Hue bridge, so thanks for all your work so far that you keep improving the rules.

Should I create a new issue for this localtime bug? Unfortunately I am not familiar with the deCONZ code (and the language) so I can't fix this myself.

Working around this using your suggestion with separate rules/sensors works, but would require lots of changes in my code for something as simple as a time condition. So it would be very great if this could be fixed in the deCONZ API.

[ebaauw]

Should I create a new issue for this localtime bug? Unfortunately I am not familiar with the deCONZ code (and the language) so I can't fix this myself.

No big deal, but might be good to track this issue separately.

So it would be very great if this could be fixed in the deCONZ API.

The problem is that I wouldn't (yet?) know how to fix it. It's more a design flaw in how rules are evaluated than a programming error. I'm afraid fixing this might require re-factoring the rules evaluation logic completely. That will likely introduce more bugs (at least initially) than it will solve. Also we don't have any test suite, against which we can check the rules logic.

[stale[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

[Thomas-Vos]

Just want to add something I noticed to my previous comment. This is about rule with IN localtime not triggering as expected.

A rule with the following conditions DOES trigger when the sensor status changes:

"conditions": [
    {
        "address": "/sensors/160/state/lastupdated",
        "operator": "dx"
    },
    {
        "address": "/config/localtime",
        "operator": "in",
        "value": "T01:00:00/T23:00:00"
    }
]

A rule with the following conditions DOES NOT trigger when the sensor status changes:

"conditions": [
    {
        "address": "/sensors/160/state/lastupdated",
        "operator": "ddx",
        "value": "PT00:00:05"
    },
    {
        "address": "/config/localtime",
        "operator": "in",
        "value": "T01:00:00/T23:00:00"
    }
]

Difference is dx vs ddx which causes different behaviour.

[manup]

I think they should be all triggered by now, but there was still a problem with delays: addressed in https://github.com/dresden-elektronik/deconz-rest-plugin/pull/6398

I think this one here can be closed?