[SOLVED] How to check if two items change in 5 seconds? (Presence detection + alexa)

Modified as follow (the group gPhones is changing to ON)

rule "Someone came home"
when
    Member of gPhones changed to ON
then
    if(cameHomeTimer !== null) return; // do nothing if there is already a Timer

    cameHomeTimer = createTimer(now.plusSeconds(5), [ |

        val cameHome = gPhones.members.filter[ p | p.state == ON && p.lastUpdate !== null && p.lastUpdate.isAfter(now.minusMillis(5500)) ].map[ name.replace("_Phone_Home_Unifi_online", "") ]

        var message = "Benvenuti a casa, "
        switch(cameHome.size) {
            case 0: {
                logError("came home", "Unexpected number of phones: " + cameHome.size)
                return;
            }
            case 1 && cameHome.get(0) == "Andrea": message = "Benvenuto a casa, Andrea"
            case 1 && cameHome.get(0) == "Cate": message = "Benvenuta a casa, Caterina"
            case 1 && cameHome.get(0) == "Sofia": message = "Benvenuta a casa, Sofia"
            case 1 && cameHome.get(0) == "Edo": message = "Benvenuto a casa, Edoardo"
            default: {
                message = message + cameHome.members.reduce[ list, name | list + ", " + name ]
                val ind = message.lastIndexOf(",")
                message = new StringBuilder(str).replace(ind, ind+1," e").toString();
            }
        }

        Echo_Living_Room_TTS.sendCommand('<speak><break time="5s"/>"+message+"</speak>')
        cameHomeTimer = null
    ])
end

Not sure to understand the “default” part, and if the var message needs to be explicated before or not.

Nothing happening :frowning:

Sorry for silly questions. In the meantime I’m studying the Design Patterns …

Andrea

Add additional logging to see what variables are set to and where the Rule gets to.

The default executes when no other case matches. What you have is fine.

mmm, you mean add LogInfo?

trying this way:

rule "Someone came home"
when
    Member of gPhones changed to ON
then
    if(cameHomeTimer !== null) return; // do nothing if there is already a Timer

    cameHomeTimer = createTimer(now.plusSeconds(5), [ |

        val cameHome = gPhones.members.filter[ p | p.state == ON && p.lastUpdate !== null && p.lastUpdate.isAfter(now.minusMillis(5500)) ].map[ name.replace("_Phone_Home_Unifi_online", "") ]
        logInfo("check cameHome", "gPhones active members: " + cameHome)

        var message = "Benvenuti a casa, "
        switch(cameHome.size) {
            case 0: {
                logError("came home", "Unexpected number of phones: " + cameHome.size)
                return;
            }
            case 1 && cameHome.get(0) == "Andrea": message = "Benvenuto a casa, Andrea"
            case 1 && cameHome.get(0) == "Cate": message = "Benvenuta a casa, Caterina"
            case 1 && cameHome.get(0) == "Sofia": message = "Benvenuta a casa, Sofia"
            case 1 && cameHome.get(0) == "Edo": message = "Benvenuto a casa, Edoardo"
            default: {
                message = message + cameHome.members.reduce[ list, name | list + ", " + name ]
                val ind = message.lastIndexOf(",")
                message = new StringBuilder(str).replace(ind, ind+1," e").toString();
            }
        }
        logInfo("check message", "message is: " + message)
        Echo_Living_Room_TTS.sendCommand('<speak><break time="5s"/>"+message+"</speak>')
        cameHomeTimer = null
    ])
end

logs (two tests):

2019-01-31 17:00:02.573 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'alexa.rules'
2019-01-31 17:01:57.664 [INFO ] [marthome.model.script.check cameHome] - gPhones active members: [Andrea]
2019-01-31 17:01:57.911 [ERROR] [org.quartz.core.JobRunShell         ] - Job DEFAULT.2019-01-31T17:01:57.622+01:00: Proxy for org.eclipse.xtext.xbase.lib.Procedures$Procedure0: [ | {
  val cameHome
  logInfo(<XStringLiteralImpl>,<XBinaryOperationImplCustom>)
  var message
  org.eclipse.xtext.xbase.impl.XSwitchExpressionImpl@1e5a015a
  <XFeatureCallImplCustom>.sendCommand(<XStringLiteralImpl>)
  <null>.cameHomeTimer = <XNullLiteralImplCustom>
} ] threw an unhandled Exception: 
java.lang.reflect.UndeclaredThrowableException: null
	at com.sun.proxy.$Proxy201.apply(Unknown Source) ~[?:?]
	at org.eclipse.smarthome.model.script.internal.actions.TimerExecutionJob.execute(TimerExecutionJob.java:49) ~[?:?]
	at org.quartz.core.JobRunShell.run(JobRunShell.java:202) [107:org.eclipse.smarthome.core.scheduler:0.11.0.201901181547]
	at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573) [107:org.eclipse.smarthome.core.scheduler:0.11.0.201901181547]
Caused by: org.eclipse.smarthome.model.script.engine.ScriptExecutionException: Unknown variable or command '&&'; line 72, column 18, length 32
	at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.invokeFeature(ScriptInterpreter.java:147) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:902) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:226) ~[?:?]
	at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:204) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:481) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:256) ~[?:?]
	at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:204) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:447) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:228) ~[?:?]
	at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:204) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.evaluate(XbaseInterpreter.java:190) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.ClosureInvocationHandler.doInvoke(ClosureInvocationHandler.java:46) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.AbstractClosureInvocationHandler.invoke(AbstractClosureInvocationHandler.java:29) ~[?:?]
	... 4 more
2019-01-31 17:01:58.322 [ERROR] [org.quartz.core.ErrorLogger         ] - Job (DEFAULT.2019-01-31T17:01:57.622+01:00: Proxy for org.eclipse.xtext.xbase.lib.Procedures$Procedure0: [ | {
  val cameHome
  logInfo(<XStringLiteralImpl>,<XBinaryOperationImplCustom>)
  var message
  org.eclipse.xtext.xbase.impl.XSwitchExpressionImpl@1e5a015a
  <XFeatureCallImplCustom>.sendCommand(<XStringLiteralImpl>)
  <null>.cameHomeTimer = <XNullLiteralImplCustom>
} ] threw an exception.
org.quartz.SchedulerException: Job threw an unhandled exception.
	at org.quartz.core.JobRunShell.run(JobRunShell.java:213) [107:org.eclipse.smarthome.core.scheduler:0.11.0.201901181547]
	at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573) [107:org.eclipse.smarthome.core.scheduler:0.11.0.201901181547]
Caused by: java.lang.reflect.UndeclaredThrowableException
	at com.sun.proxy.$Proxy201.apply(Unknown Source) ~[?:?]
	at org.eclipse.smarthome.model.script.internal.actions.TimerExecutionJob.execute(TimerExecutionJob.java:49) ~[?:?]
	at org.quartz.core.JobRunShell.run(JobRunShell.java:202) ~[?:?]
	... 1 more
Caused by: org.eclipse.smarthome.model.script.engine.ScriptExecutionException: Unknown variable or command '&&'; line 72, column 18, length 32
	at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.invokeFeature(ScriptInterpreter.java:147) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:902) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:226) ~[?:?]
	at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:204) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:481) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:256) ~[?:?]
	at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:204) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:447) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:228) ~[?:?]
	at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:204) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.evaluate(XbaseInterpreter.java:190) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.ClosureInvocationHandler.doInvoke(ClosureInvocationHandler.java:46) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.AbstractClosureInvocationHandler.invoke(AbstractClosureInvocationHandler.java:29) ~[?:?]
	at com.sun.proxy.$Proxy201.apply(Unknown Source) ~[?:?]
	at org.eclipse.smarthome.model.script.internal.actions.TimerExecutionJob.execute(TimerExecutionJob.java:49) ~[?:?]
	at org.quartz.core.JobRunShell.run(JobRunShell.java:202) ~[?:?]
	... 1 more
2019-01-31 17:02:04.303 [WARN ] [io.openhabcloud.internal.CloudClient] - Jetty request 1777998 failed: null
2019-01-31 17:02:04.324 [WARN ] [io.openhabcloud.internal.CloudClient] - Response Failure: null
2019-01-31 17:04:53.441 [INFO ] [el.core.internal.ModelRepositoryImpl] - Validation issues found in configuration model 'alexa.rules', using it anyway:
There is no context to infer the closure's argument types from. Consider typing the arguments or put the closures into a typed context.
2019-01-31 17:04:53.518 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'alexa.rules'
2019-01-31 17:10:16.824 [WARN ] [io.openhabcloud.internal.CloudClient] - Jetty request 1781547 failed: null
2019-01-31 17:10:16.827 [WARN ] [io.openhabcloud.internal.CloudClient] - Response Failure: null
2019-01-31 17:10:49.824 [WARN ] [io.openhabcloud.internal.CloudClient] - Jetty request 1781742 failed: null
2019-01-31 17:10:49.826 [WARN ] [io.openhabcloud.internal.CloudClient] - Response Failure: null
2019-01-31 17:11:57.739 [WARN ] [io.openhabcloud.internal.CloudClient] - Jetty request 1782180 failed: null
2019-01-31 17:11:57.741 [WARN ] [io.openhabcloud.internal.CloudClient] - Response Failure: null
2019-01-31 17:37:54.633 [INFO ] [marthome.model.script.check cameHome] - gPhones active members: []
2019-01-31 17:37:54.642 [ERROR] [pse.smarthome.model.script.came home] - Unexpected number of phones: 0

Question: but if someone is already at home (gPhones group ON), if another is coming home the switch won’t change to ON, so the rule won’t trigger.

Just to complete my troubleshooting:

  • switched off all phones
  • wait for gPhones OFF
  • swiched on my phone

gPhones is ON, no logs :frowning:
maybe cameHomeTimer is not null -> trying reloading OH

edit:

  • the first issue
2019-01-31 19:26:28.986 [INFO ] [el.core.internal.ModelRepositoryImpl] - Validation issues found in configuration model 'alexa.rules', using it anyway:
There is no context to infer the closure's argument types from. Consider typing the arguments or put the closures into a typed context.

seems related to:

question is how to change this piece:

val cameHome = gPhones.members.filter[ p | p.state == ON && p.lastUpdate !== null && p.lastUpdate.isAfter(now.minusMillis(5500)) ].map[ name.replace("_Phone_Home_Unifi_online", "") ]

something is missing at the end, I think.

  • the second issue (the rule itself)

after reloading OH, I see finally the log:

2019-01-31 19:29:32.117 [INFO ] [marthome.model.script.check cameHome] - gPhones active members: []
2019-01-31 19:29:32.134 [ERROR] [pse.smarthome.model.script.came home] - Unexpected number of phones: 0

so before the cameHomeTimer was not null. That means (thinking loud), the issue is I’m not catching correctly the name of the member of the group … but why? maybe solving the first issue I’ll solve also the second (both related to val cameHome)?

Yes it will because we are using the Member of trigger. The Rule triggers when any member of gPhones changes to ON, not based on the state of gPhones itself.

OK, the error seems to be coming from the creation of the timer. It is specifically complaining about the &&. Can you confirm the first case statement with an && is line 72 of the file?

Caused by: org.eclipse.smarthome.model.script.engine.ScriptExecutionException: Unknown variable or command '&&'; line 72, column 18, length 32

I know we are allowed to use an && in a case statement (it’s used in the Time of Day DP).

I think I know the problem, because of the &&, we can’t take a shortcut on the comparison for the size being 1.

Edit the case 1 case statements as follows

case cameHome.size == 1 && cameHome.get(0)...

You don’t have to change it. there is nothing missing at the end. The result of the map will be a List of the names of the Items with the “_Phone_Home_Unifi_online” part removed, which is exactly what we want.

In this case there was no member of gPhones that met the following conditions:

  • ON
  • lastUpdate is not null
  • lastUpdate is within the last 5.5 seconds

If your phone turned ON more then 5.5 seconds ago it will not be in the list.

1 Like
switch(cameHome.size) {
            case 0: {
                logError("came home", "Unexpected number of phones: " + cameHome.size)
                return;
            }
            case cameHome.size == 1 && cameHome.get(0) == "Andrea": message = "Benvenuto a casa, Andrea"
            case cameHome.size == 1 && cameHome.get(0) == "Cate": message = "Benvenuta a casa, Caterina"
            case cameHome.size == 1 && cameHome.get(0) == "Sofia": message = "Benvenuta a casa, Sofia"
            case cameHome.size == 1 && cameHome.get(0) == "Edo": message = "Benvenuto a casa, Edoardo"
            default: {

the first case cameHome.size == 1 is line 72, I confirm

error log:

2019-01-31 19:38:36.404 [INFO ] [el.core.internal.ModelRepositoryImpl] - Validation issues found in configuration model 'alexa.rules', using it anyway:
There is no context to infer the closure's argument types from. Consider typing the arguments or put the closures into a typed context.
2019-01-31 19:38:36.574 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'alexa.rules'

is that expected?

It’s a warning. The code will work anyway.

Still

2019-01-31 20:04:49.625 [INFO ] [marthome.model.script.check cameHome] - gPhones active members: []
2019-01-31 20:04:49.650 [ERROR] [pse.smarthome.model.script.came home] - Unexpected number of phones: 0

troubleshooting ongoing …

To debug problems, you see what is wrong (no phone returned) and then figure out what all the values are that went into calculating that value are. Log out everything.

Then perform the step manually on paper to see why the computer is calculating the wrong thing.

You need to log out the state, lastUpdate for all the phones, and now to see why none of the Phone Items are passing through the filter.

It worked once (see post 24) so there has to be something about your Items that has changed.

The problem is nothing has changed … so maybe there is something matching casually

:frowning:

I’ve created the loginfo here:

val cameHome = gPhones.members.filter[ p | p.state == ON && p.lastUpdate !== null && p.lastUpdate.isAfter(now.minusMillis(5500)) ].map[ name.replace("_Phone_Home_Unifi_online", "") ]
        logInfo("check cameHome", "gPhones active members: " + cameHome)

but I’m not able to see in my logs, so there is an issue there, right?

Which is why

To debug problems, you see what is wrong (no phone returned) and then figure out what all the values are that went into calculating that value are. Log out everything.

Then perform the step manually on paper to see why the computer is calculating the wrong thing.

You need to log out the state, lastUpdate for all the phones, and now to see why none of the Phone Items are passing through the filter.

You need to log every single part of the filter command. You can’t do it inside the filter. You need to see ALL the information that goes into the calculation. That log statement only shows you the result of the calculation which we already know is wrong.

1 Like

OK,

I did some tests, and it seems sometimes is working, sometimes not.
The issue seems this part:

p.lastUpdate.isAfter(now.minusMillis(5500)) 

when it works:

2019-01-31 21:13:04.424 [INFO ] [pse.smarthome.model.script.variables] - state=ON: [Cate_Phone_Home_Unifi_online (Type=SwitchItem, State=ON, Label=Cate, Category=null, Groups=[gPeople, gPresence, gPhones]), Andrea_Phone_Home_Unifi_online (Type=SwitchItem, State=ON, Label=Andrea, Category=null, Groups=[gPeople, gPresence, gPhones])]
2019-01-31 21:13:04.427 [INFO ] [pse.smarthome.model.script.variables] - LastUpdate: [Cate_Phone_Home_Unifi_online (Type=SwitchItem, State=ON, Label=Cate, Category=null, Groups=[gPeople, gPresence, gPhones]), Andrea_Phone_Home_Unifi_online (Type=SwitchItem, State=ON, Label=Andrea, Category=null, Groups=[gPeople, gPresence, gPhones])]
2019-01-31 21:13:04.433 [INFO ] [pse.smarthome.model.script.variables] - isAfter: [Andrea_Phone_Home_Unifi_online (Type=SwitchItem, State=ON, Label=Andrea, Category=null, Groups=[gPeople, gPresence, gPhones])]
2019-01-31 21:13:04.448 [INFO ] [smarthome.model.script.check message] - message is: Benvenuto a casa, Andrea

when it’s not working (added also the map part):

2019-01-31 21:23:49.229 [INFO ] [pse.smarthome.model.script.variables] - state=ON: [Cate, Andrea]
2019-01-31 21:23:49.245 [INFO ] [pse.smarthome.model.script.variables] - LastUpdate: [Cate, Andrea]
2019-01-31 21:23:49.248 [INFO ] [pse.smarthome.model.script.variables] - isAfter: []
2019-01-31 21:23:49.256 [ERROR] [pse.smarthome.model.script.came home] - Unexpected number of phones: 0

Consider I’m using Andrea_Phone for test, Cate_Phone is always ON

Here the rule now (there was also a TTS sendCommand mistake):

rule "Someone came home"
when
    Member of gPhones changed to ON
then
    if(cameHomeTimer !== null) {
        return; // do nothing if there is already a Timer
    }
    cameHomeTimer = createTimer(now.plusSeconds(5), [ |

        val gPhones_state = gPhones.members.filter[ p | p.state == ON ].map[ name.replace("_Phone_Home_Unifi_online", "") ]
        val gPhones_lastupdate = gPhones.members.filter[ p | p.lastUpdate !== null ].map[ name.replace("_Phone_Home_Unifi_online", "") ]
        val gPhones_lastupdateisafter = gPhones.members.filter[ p | p.lastUpdate.isAfter(now.minusMillis(5500)) ].map[ name.replace("_Phone_Home_Unifi_online", "") ]
        val cameHome = gPhones.members.filter[ p | p.state == ON && p.lastUpdate !== null && p.lastUpdate.isAfter(now.minusMillis(5500)) ].map[ name.replace("_Phone_Home_Unifi_online", "") ]

        logInfo("variables", "state=ON: " + gPhones_state)
        logInfo("variables", "LastUpdate: " + gPhones_lastupdate)
        logInfo("variables", "isAfter: " + gPhones_lastupdateisafter)

        var message = "Benvenuti a casa, "
        switch(cameHome.size) {
            case 0: {
                logError("came home", "Unexpected number of phones: " + cameHome.size)
                return;
            }
            case cameHome.size == 1 && cameHome.get(0) == "Andrea": message = "Benvenuto a casa, Andrea"
            case cameHome.size == 1 && cameHome.get(0) == "Cate": message = "Benvenuta a casa, Caterina"
            case cameHome.size == 1 && cameHome.get(0) == "Sofia": message = "Benvenuta a casa, Sofia"
            case cameHome.size == 1 && cameHome.get(0) == "Edo": message = "Benvenuto a casa, Edoardo"
            default: {
                message = message + cameHome.members.reduce[ list, name | list + ", " + name ]
                val ind = message.lastIndexOf(",")
                message = new StringBuilder(str).replace(ind, ind+1," e").toString();
            }
        }
        logInfo("check message", "message is: " + message)
        Echo_Living_Room_TTS.sendCommand('<speak><break time="5s"/>' + message + '</speak>')
        cameHomeTimer = null
    ])
end

trying

p.lastUpdate.isAfter(now.minusMillis(5500).millis)

OK. So you know that the problem is Andrea_Phone is changing to ON more than 5.5 seconds before the filter runs, or Andrea_Phone.lastUpdate is null.

What I suspect is happening is the Rule is running too fast. It’s running before the new state is saved to the database meaning that the call to lastUpdate is returning the time of the state previous to the current one.

I would know for sure if you had actually logged out the value returned by lastUpdate instead of the list of Items.

What I meant above is to log out the actual values that are going into the calculation, not the results of the calculations.

logInfo("test", "Rule triggered by " + triggeringItem.name + " at " + now.toString)
gPhones.members.forEach[ p | 
    logInfo("test", "Values for " + p.name + "\n" +
            "State = " + p.state.toString + "\n"
            "LastUpdate = " + p.lastUpdate.toString)
]

With those lines of code you will have all the raw values going into the calculations.

Then you can go through them one by one and check off each of the comparisons in the filter. I’m sure you would immediately see that lastUpdate time for Andrea_Phone.lastUpdate is some minutes older than it should be and we would immediately know that is the cause of the problem.

There are a couple ways to solve this. I’m going to present the most reliable rather than the most straight forward (add a Thread::sleep to give persistence time to catch up).

val cameHome = gPhones.members.filter[ p | p.state == ON && (p.name == triggeringItem.name || (p.lastUpdate !== null && p.lastUpdate.isAfter(now.minusMillis(5500)))) ] .map[ name.replace...

The parens above may not line up. Be careful when you type it in.

The change is to include the Item that triggered the Rule no matter what it’s lastUpdate is.

1 Like
2019-01-31 22:03:12.576 [INFO ] [pse.smarthome.model.script.variables] - state=ON: [Cate, Andrea]
2019-01-31 22:03:12.581 [INFO ] [pse.smarthome.model.script.variables] - LastUpdate: [Cate, Andrea]
2019-01-31 22:03:12.585 [INFO ] [pse.smarthome.model.script.variables] - isAfter: []
2019-01-31 22:03:12.587 [INFO ] [.eclipse.smarthome.model.script.test] - Rule triggered by Andrea_Phone_Home_Unifi_online at 2019-01-31T22:03:12.587+01:00
2019-01-31 22:03:12.592 [INFO ] [.eclipse.smarthome.model.script.test] - Values for Cate_Phone_Home_Unifi_online
State = ON
LastUpdate = 2019-01-31T20:04:44.043+01:00
2019-01-31 22:03:12.598 [INFO ] [.eclipse.smarthome.model.script.test] - Values for Andrea_Phone_Home_Unifi_online
State = ON
LastUpdate = 2019-01-31T22:03:06.965+01:00
2019-01-31 22:03:12.611 [INFO ] [smarthome.model.script.check message] - message is: Benvenuto a casa, Andrea

It seems you are right. Without the triggeringItem.name we should have the same issue before:

2019-01-31 22:03:12.585 [INFO ] [pse.smarthome.model.script.variables] - isAfter: []

Rule triggered at 2019-01-31T22:03:12.587+01:00
Last Update: 2019-01-31T22:03:06.965+01:00

Maybe better to move from 5 to 10 secs (10500) ?

Wait a minute. That filter is happening inside the Timer. 5 seconds is plenty of time for persistence to catch up.

Timing of the saving shouldn’t be a problem.

What is the persistence strategy used to save these Items? If you are using anything besides everyChange that could be the source of the problem.

What database are you using and is the clock on the machine where it is running synchronized with the clock where OH is running (i.e. NTP configured)? The answer is yes if they are running on the same machine.

The logInfo("test", "Rule triggered by " + triggeringItem.name + " at " + now.toString) needs to go above the createTimer line. We really need the time from when the Rule triggered, not when the timer triggered.

There should then be a five second delay between when you see that log statement and the list of all the Phone Item log statements. Then compare the the that time with the lastUpdate time.

gPhones* 	: strategy = everyChange

I’m using influxdb for this group, but I’ve also the default mapdb.
Same machine, NTP configured.

Here the log modified as suggested:

2019-01-31 23:54:26.652 [INFO ] [.eclipse.smarthome.model.script.test] - Rule triggered by Andrea_Phone_Home_Unifi_online at 2019-01-31T23:54:26.648+01:00
2019-01-31 23:54:31.658 [INFO ] [pse.smarthome.model.script.variables] - state=ON: [Cate, Andrea]
2019-01-31 23:54:31.668 [INFO ] [pse.smarthome.model.script.variables] - LastUpdate: [Cate, Andrea]
2019-01-31 23:54:31.671 [INFO ] [pse.smarthome.model.script.variables] - isAfter: []
2019-01-31 23:54:31.683 [INFO ] [.eclipse.smarthome.model.script.test] - Values for Cate_Phone_Home_Unifi_online
State = ON
LastUpdate = 2019-01-31T20:04:44.043+01:00
2019-01-31 23:54:31.692 [INFO ] [.eclipse.smarthome.model.script.test] - Values for Andrea_Phone_Home_Unifi_online
State = ON
LastUpdate = 2019-01-31T23:54:26.155+01:00
2019-01-31 23:54:31.728 [INFO ] [smarthome.model.script.check message] - message is: Benvenuto a casa, Andrea

rule triggered at 23:54:26.648
last update at 23:54:26.155

So the rule is triggered after the persistence updating the db? If this is true, 5500 -> 500 ms are not always enough right?