Annoying log: Rule 'Update timestamp': null

OH 2.5.10, openhabian - raspbian stretch on RPI 3.

I have such rule:

rule "Update timestamp"
    Item gBathroom1Sensor received update or
    Item gFridgeSensor received update or
    Item gLivingroomSensor received update or
    Item gBedroom1Sensor received update or
    Item gCorridorMotion received update or
    Item gKitchenMotion received update or
    Item gBedroom1Motion received update or
    Item gBedroom2Motion received update or
    Item gBalconyMotion received update or
    Item gBathroom2Sensor received update or
    Item gDustSensor received update or
    Item gLivingroomThermostat received update or
    Item gFibaroMotion received update or
    Item gAeotecMotion received update
    logInfo("Update timestamp", String::format("triggeringItem: %s, name: %s", triggeringItem,
    var lastUpdateItem = gLastUpdate.members.findFirst[ i | i != null && == + "_lastUpdate" ]
    logInfo("Update timestamp", String::format("lastUpdateItem: %s", lastUpdateItem))
    postUpdate(lastUpdateItem, new DateTimeType())

and sometimes it gives such log output:

2020-12-03 16:33:03.098 [INFO ] [rthome.model.script.Update timestamp] - triggeringItem: gLivingroomThermostat (Type=GroupItem, BaseType=NumberItem, Members=2, State=UNDEF, Label=null, Category=null), name: gLivingroomThermostat
2020-12-03 16:33:03.106 [INFO ] [rthome.model.script.Update timestamp] - triggeringItem: gLivingroomThermostat (Type=GroupItem, BaseType=NumberItem, Members=2, State=UNDEF, Label=null, Category=null), name: gLivingroomThermostat
2020-12-03 16:33:03.203 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'Update timestamp': null
2020-12-03 16:33:03.215 [INFO ] [rthome.model.script.Update timestamp] - lastUpdateItem: gLivingroomThermostat_lastUpdate (Type=DateTimeItem, State=2020-12-03T16:28:06.249+0100, Label=Termostat Salon, Category=time, Groups=[gLastUpdate])

All items in when clause are groups. Those groups have couple of other items connected to each of them. Those other items are connected to binding channels (zwave, mqtt, etc…).
This error happens only if there are two updates of the same group in very short interval. In the attached log You see the first update is at 16:33:03.098 and the second at 16:33:03.106. It looks like the second update is happening during execution of the rule, because the logs are interleaved. But I don’t have any clue what is causing this error. I do not see any other symptoms of this error, everything seems to work fine, but the error is just annoying. It happens cuple of times per hour.

This rule is going to be pounded hard with so many group update triggers. Remember, for every 1 update to a member of the group there will be N-1 updates to the Group as the updates are processed by the aggregation function.

So you will likely have a lot of instances of this rule running at the same time and the rule will be likely running while updates are being processed by gLastUpdate Group. If you run a findFrist on the members while it’s updating that can often result in an error.

If you can change the trigger from updates to the Group to updates to Members of the Group that might work. You can figure out which Group triggered the rule by checking which Groups the triggering Item belongs to.

Another approach that I think might work (might only work in OH 3, might not work at all) is to use the timestamp profile on lastupdate Items linked to the same channels as the members of the groups. Add all of those timestamp Items to gGroupName_lastUpdate Group with MAX as the aggregation function. The state of that Group should be the most recent datetime of the update for any of the members.

I’m not sure if MAX would work, but LATEST would.

1 Like

That’s what I get from going from memory. Thanks for the correction.

1 Like

I surrounded this line of code with lock guards:

var lastUpdateItem = gLastUpdate.members.findFirst[ i | i != null && == + "_lastUpdate" ]

and for two days I do not have any errors.