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.
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.
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?
So it would seem. Try adding Antje half second to see if it works more reliably. In that run it was only off by about 100 msec.
I will try 6 secs.
thank you VERY MUCH for your help during this troubleshooting … I’ve learned more than in 2 years with OH 
Thank you!!!
two more questions:
2019-02-01 09:20:05.096 [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.
thank you!!!
Andrea
It’s complaining about the arguments passed to a lambda. I recommend loading the file in VSCode to tell you which one it is complaining about. Then give those lambdas a type. I suspect it’s the map so you would use
.reduce[ String list, String name |
Well, some of this could be learned by looking at the language docs, like the map reduce filter forEach like stuff to do with Lists, but Design Pattern: Working with Groups in Rules is a little better than the official docs.
The timing issue has nothing to do with the language and everything to do with the timing and how OH itself works and you won’t find any docs that help you with that.
The best place to start is the OH Rules docs page. There is a link to the Xtend Docs on the Rules Doc page, so go there to review how to do things like the switch statement and such. Finally, review the Design Patterns for tested generic approaches to solve common problems.
ciao Rik,
I’m already working with VSCode, all my files are open via VSCode, but I don’t see any warning or problem or output at all. Do I need to debug somehow?
All I can recommend then is to keep adding the Types to the variables to the left of the | in all the [ ] until the warning goes away.
like “p”? may I ask you an example?
I gave you an example above. Here it is again with the full line.
cameHome.members.reduce[ list, name | list + ", " + name ]
For the filter, you would use GenericItem as the type for p.
The map doesn’t have arguments (i.e. no |) so it wouldn’t be complaining about that.
Found it, it was in reduce as you said.
Sorry, I didn’t understand first time I read. THANK YOU !!!
Andrea
just studying the rule, in order to simplify other my if/else super-nested rules
why here we are using “.size”?
switch(cameHome.size)
is because in this case we should have “0” or “1” right (and at the beginning we were also thinking about using a case 2 as well)?
Otherwise, if for example I have to say “if a switch changes OFF, please modify also another switch accordingly” I should simply use:
switch setAway {
case setAway.get(0) == "Andrea": sendCommand(Andrea_Presence, OFF)
case setAway.get(0) == "Cate": sendCommand(Cate_Presence, OFF)
}
of couse, if I have just 2 cases, I can use if/else as well. But switch can be useful if I need to add more cases in the future right?
Thanks for your guidance
Andrea
Because the size of the list tells you how many people just came home. Before you had the additional requirements that the message is in Italian and therefore the gender changes the message, it was the simplest way to decide between the messages. Now that the “who” has come home is important, it may not be the best choice. But you still need to take it into consideration so you can handle the case where more than one person comes home.
@rlkoshak sorry to bother you again, but …
this morning I’ve tested when two people join the network simultaneously. But the result was unexpected: Alexa reply with two messages instead of the “default” message.
I was expected “Benvenuti a casa, Andrea e Cate”. But I hear “Benvenuto a casa, Andrea” and then after a while “Benvenuta a casa, Caterina”.
Here the log:
2019-02-11 09:04:18.126 [INFO ] [.eclipse.smarthome.model.script.test] - Rule triggered by Andrea_Phone_Home_Unifi_online at 2019-02-11T09:04:18.085+01:00
2019-02-11 09:04:23.181 [INFO ] [.eclipse.smarthome.model.script.test] - Values for Andrea_Phone_Home_Unifi_online
State = ON
LastUpdate = 2019-02-11T09:04:17.815+01:00
2019-02-11 09:04:23.187 [INFO ] [.eclipse.smarthome.model.script.test] - Values for Cate_Phone_Home_Unifi_online
State = OFF
LastUpdate = 2019-02-11T08:05:47.176+01:00
2019-02-11 09:04:23.201 [INFO ] [smarthome.model.script.check message] - message is: Benvenuto a casa, Andrea
2019-02-11 09:04:38.245 [INFO ] [.eclipse.smarthome.model.script.test] - Rule triggered by Cate_Phone_Home_Unifi_online at 2019-02-11T09:04:38.245+01:00
2019-02-11 09:04:43.272 [INFO ] [.eclipse.smarthome.model.script.test] - Values for Andrea_Phone_Home_Unifi_online
State = ON
LastUpdate = 2019-02-11T09:04:17.815+01:00
2019-02-11 09:04:43.298 [INFO ] [.eclipse.smarthome.model.script.test] - Values for Cate_Phone_Home_Unifi_online
State = ON
LastUpdate = 2019-02-11T09:04:38.246+01:00
2019-02-11 09:04:43.334 [INFO ] [smarthome.model.script.check message] - message is: Benvenuta a casa, Caterina
As you can see, it seems the second phone joins 20 secs after the first one.
I think I have two options: wait more than 20 secs, or change the mechanism. It seems quite unreliable, isn’t it?
My current rule is:
// Presence (Home) Unifi in
rule "Welcome home my dear"
when
Member of gPhones changed to ON
then
if(cameHomeTimer !== null) {
return; // do nothing if there is already a Timer
}
logInfo("test", "Rule triggered by " + triggeringItem.name + " at " + now.toString)
cameHomeTimer = createTimer(now.plusSeconds(5), [ |
val cameHome = gPhones.members.filter[ p | p.state == ON && (p.name == triggeringItem.name || (p.lastUpdate !== null && p.lastUpdate.isAfter(now.minusSeconds(6)))) ].map[ name.replace("_Phone_Home_Unifi_online", "") ]
gPhones.members.forEach[ p | logInfo("test", "Values for " + p.name + "\n" + "State = " + p.state.toString + "\n" + "LastUpdate = " + p.lastUpdate.toString)]
var String 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.reduce[ String list, String name | list + ", " + name ]
val ind = message.lastIndexOf(",").toString
//message = new StringBuilder(str).replace(ind, ind+1," e").toString();
message = message.replace(ind, " e ").toString();
}
}
logInfo("check message", "message is: " + message)
Echo_Living_Room_TTS_Volume.sendCommand('90')
//Echo_Living_Room_TTS.sendCommand('<speak><break time="2s"/>' + message + '</speak>')
Echo_Living_Room_TTS.sendCommand(message)
cameHomeTimer = null
])
end
Since that is the case the Rule performed correctly.
If you mean change the mechanism for detecting when a phone is detected home then yes, either of those approaches are what you will need to do.
The problem isn’t the Rule. The problem is the delay for when the phones are detected home.