Set last tripped/alarm date, or last action date to an item - best practice?

The rule with the ? was from youir example - see 2nd post in this thread.

Now i included your last example. But nothing happens.

I get many log-messages if i open a window, but all with the same text:

2017-01-12 19:37:12.902 [INFO ] [c.internal.ModelRepositoryImpl] - Refreshing model 'fensterkontakte.rules'
2017-01-12 19:37:44.301 [INFO ] [org.openhab.model.script.Test ] - There are 16 contacts that have a last update
2017-01-12 19:37:44.309 [INFO ] [org.openhab.model.script.Test ] - There are 16 contacts that have a last update
2017-01-12 19:37:44.309 [INFO ] [org.openhab.model.script.Test ] - There are 16 contacts that have a last update
2017-01-12 19:37:44.324 [INFO ] [org.openhab.model.script.Test ] - There are 16 contacts that have a last update
2017-01-12 19:38:34.216 [INFO ] [org.openhab.model.script.Test ] - There are 16 contacts that have a last update
2017-01-12 19:38:34.247 [INFO ] [org.openhab.model.script.Test ] - There are 16 contacts that have a last update
2017-01-12 19:38:34.327 [INFO ] [org.openhab.model.script.Test ] - There are 16 contacts that have a last update
2017-01-12 19:38:34.343 [INFO ] [org.openhab.model.script.Test ] - There are 16 contacts that have a last update
2017-01-12 19:38:34.347 [INFO ] [org.openhab.model.script.Test ] - There are 16 contacts that have a last update
2017-01-12 19:38:41.542 [INFO ] [org.openhab.model.script.Test ] - There are 16 contacts that have a last update
2017-01-12 19:38:41.601 [INFO ] [org.openhab.model.script.Test ] - There are 16 contacts that have a last update
2017-01-12 19:38:41.614 [INFO ] [org.openhab.model.script.Test ] - There are 16 contacts that have a last update
2017-01-12 19:38:41.646 [INFO ] [org.openhab.model.script.Test ] - There are 16 contacts that have a last update
2017-01-12 19:38:41.680 [INFO ] [org.openhab.model.script.Test ] - There are 16 contacts that have a last update
2017-01-12 19:38:41.684 [INFO ] [org.openhab.model.script.Test ] - There are 16 contacts that have a last update
2017-01-12 19:38:41.699 [INFO ] [org.openhab.model.script.Test ] - There are 16 contacts that have a last update
2017-01-12 19:38:41.780 [INFO ] [org.openhab.model.script.Test ] - There are 16 contacts that have a last update
2017-01-12 19:38:41.795 [INFO ] [org.openhab.model.script.Test ] - There are 16 contacts that have a last update
2017-01-12 19:38:45.196 [INFO ] [org.openhab.model.script.Test ] - There are 16 contacts that have a last update
2017-01-12 19:38:45.206 [INFO ] [org.openhab.model.script.Test ] - There are 16 contacts that have a last update

I’ve learned a lot in the past year. And I will continue to learn, as will you.

Given the lack of errors it looks like mostRecent is not OPEN. Time for more logging:

Thread::sleep(300) // give persistence time to catch up
val haveHistory = gFensterkontakte.members.filter[c|c.lastUpdate != null]
logInfo("Test", "There are " + haveHistory.size + " contacts that have a last update")

val mostRecent = haveHistory.sortBy[lastUpdate].last
logInfo("Test", "Most recent contact is " + mostRecent.name + " and its state is " + mostRecent.state)
if(mostRecent == null) logError("Test", "Failed to find most recent")
else if(mostRecent.state == OPEN){
    val dt = gKontakteZeit.members.filter[dt|dt.name == mostRecent.name+"_last_opened").head
    if(dt == null) logError("Test", "Failed to find " + mostRecent.name+"_last_opened")
    else dt.postUpdate(new DateTimeType)
}
else {
    logInfo("Test", mostRecent.name + " is not OPEN")
}

logfile:

2017-01-12 19:59:25.018 [INFO ] [c.internal.ModelRepositoryImpl] - Refreshing model 'fensterkontakte.rules'
2017-01-12 19:59:55.236 [INFO ] [org.openhab.model.script.Test ] - There are 16 contacts that have a last update
2017-01-12 19:59:55.241 [INFO ] [org.openhab.model.script.Test ] - There are 16 contacts that have a last update
2017-01-12 19:59:55.926 [INFO ] [org.openhab.model.script.Test ] - There are 16 contacts that have a last update
2017-01-12 19:59:55.931 [INFO ] [org.openhab.model.script.Test ] - There are 16 contacts that have a last update
2017-01-12 19:59:57.189 [INFO ] [org.openhab.model.script.Test ] - Most recent contact is Kontakt_EG_WC and its state is CLOSED
2017-01-12 19:59:57.192 [INFO ] [org.openhab.model.script.Test ] - Most recent contact is Kontakt_EG_WC and its state is CLOSED
2017-01-12 19:59:57.333 [INFO ] [org.openhab.model.script.Test ] - Most recent contact is Kontakt_EG_WC and its state is CLOSED
2017-01-12 19:59:57.493 [INFO ] [org.openhab.model.script.Test ] - Most recent contact is Kontakt_EG_WC and its state is CLOSED
2017-01-12 19:59:58.209 [INFO ] [org.openhab.model.script.Test ] - Kontakt_EG_WC is not OPEN
2017-01-12 19:59:58.221 [INFO ] [org.openhab.model.script.Test ] - Kontakt_EG_WC is not OPEN
2017-01-12 19:59:58.321 [INFO ] [org.openhab.model.script.Test ] - Kontakt_EG_WC is not OPEN
2017-01-12 19:59:58.329 [INFO ] [org.openhab.model.script.Test ] - Kontakt_EG_WC is not OPEN

I´ve only one datetime item for Kontakt_EG_WC for testing. Rest of contact items there are no additional datetime items.

Next test, now it seems to work…

Now i opened the windows and let it open, on the last tests i opened the windows only for 2-3 seconds and closed it.

2017-01-12 20:08:36.521 [INFO ] [c.internal.ModelRepositoryImpl] - Refreshing model 'fensterkontakte.rules'
2017-01-12 20:08:46.924 [INFO ] [org.openhab.model.script.Test ] - There are 16 contacts that have a last update
2017-01-12 20:08:46.932 [INFO ] [org.openhab.model.script.Test ] - There are 16 contacts that have a last update
2017-01-12 20:08:46.933 [INFO ] [org.openhab.model.script.Test ] - There are 16 contacts that have a last update
2017-01-12 20:08:47.052 [INFO ] [org.openhab.model.script.Test ] - There are 16 contacts that have a last update
2017-01-12 20:08:47.235 [INFO ] [org.openhab.model.script.Test ] - There are 16 contacts that have a last update
2017-01-12 20:08:48.426 [INFO ] [org.openhab.model.script.Test ] - Most recent contact is Kontakt_OG_Kizi_W_Nord and its state is CLOSED
2017-01-12 20:08:48.426 [INFO ] [org.openhab.model.script.Test ] - Most recent contact is Kontakt_OG_Kizi_W_Nord and its state is CLOSED
2017-01-12 20:08:48.509 [INFO ] [org.openhab.model.script.Test ] - Most recent contact is Kontakt_OG_Kizi_W_Nord and its state is CLOSED
2017-01-12 20:08:48.595 [INFO ] [org.openhab.model.script.Test ] - Most recent contact is Kontakt_OG_Kizi_W_Nord and its state is CLOSED
2017-01-12 20:08:48.698 [INFO ] [org.openhab.model.script.Test ] - Most recent contact is Kontakt_OG_Kizi_W_Nord and its state is CLOSED
2017-01-12 20:08:49.311 [INFO ] [org.openhab.model.script.Test ] - Kontakt_OG_Kizi_W_Nord is not OPEN
2017-01-12 20:08:49.319 [INFO ] [org.openhab.model.script.Test ] - Kontakt_OG_Kizi_W_Nord is not OPEN
2017-01-12 20:08:49.327 [INFO ] [org.openhab.model.script.Test ] - Kontakt_OG_Kizi_W_Nord is not OPEN
2017-01-12 20:08:49.413 [INFO ] [org.openhab.model.script.Test ] - Kontakt_OG_Kizi_W_Nord is not OPEN
2017-01-12 20:08:49.420 [INFO ] [org.openhab.model.script.Test ] - Kontakt_OG_Kizi_W_Nord is not OPEN
2017-01-12 20:08:52.407 [INFO ] [org.openhab.model.script.Test ] - There are 16 contacts that have a last update
2017-01-12 20:08:52.518 [INFO ] [org.openhab.model.script.Test ] - Most recent contact is Kontakt_OG_Kizi_W_Nord and its state is CLOSED
2017-01-12 20:08:52.522 [INFO ] [org.openhab.model.script.Test ] - Kontakt_OG_Kizi_W_Nord is not OPEN
2017-01-12 20:08:52.524 [INFO ] [org.openhab.model.script.Test ] - There are 16 contacts that have a last update
2017-01-12 20:08:52.545 [INFO ] [org.openhab.model.script.Test ] - There are 16 contacts that have a last update
2017-01-12 20:08:52.591 [INFO ] [org.openhab.model.script.Test ] - There are 16 contacts that have a last update
2017-01-12 20:08:52.596 [INFO ] [org.openhab.model.script.Test ] - There are 16 contacts that have a last update
2017-01-12 20:08:52.613 [INFO ] [org.openhab.model.script.Test ] - There are 16 contacts that have a last update
2017-01-12 20:08:52.615 [INFO ] [org.openhab.model.script.Test ] - There are 16 contacts that have a last update
2017-01-12 20:08:52.659 [INFO ] [org.openhab.model.script.Test ] - There are 16 contacts that have a last update
2017-01-12 20:08:52.679 [INFO ] [org.openhab.model.script.Test ] - There are 16 contacts that have a last update
2017-01-12 20:08:52.731 [INFO ] [org.openhab.model.script.Test ] - Most recent contact is Kontakt_OG_Kizi_W_Nord and its state is CLOSED
2017-01-12 20:08:52.736 [INFO ] [org.openhab.model.script.Test ] - Kontakt_OG_Kizi_W_Nord is not OPEN
2017-01-12 20:08:52.764 [INFO ] [org.openhab.model.script.Test ] - Most recent contact is Kontakt_OG_Kizi_W_Nord and its state is CLOSED
2017-01-12 20:08:52.766 [INFO ] [org.openhab.model.script.Test ] - Most recent contact is Kontakt_OG_Kizi_W_Nord and its state is CLOSED
2017-01-12 20:08:52.772 [INFO ] [org.openhab.model.script.Test ] - Most recent contact is Kontakt_OG_Kizi_W_Nord and its state is CLOSED
2017-01-12 20:08:52.773 [INFO ] [org.openhab.model.script.Test ] - Most recent contact is Kontakt_OG_Kizi_W_Nord and its state is CLOSED
2017-01-12 20:08:52.775 [INFO ] [org.openhab.model.script.Test ] - Kontakt_OG_Kizi_W_Nord is not OPEN
2017-01-12 20:08:52.776 [INFO ] [org.openhab.model.script.Test ] - Most recent contact is Kontakt_OG_Kizi_W_Nord and its state is CLOSED
2017-01-12 20:08:52.775 [INFO ] [org.openhab.model.script.Test ] - Kontakt_OG_Kizi_W_Nord is not OPEN
2017-01-12 20:08:52.776 [INFO ] [org.openhab.model.script.Test ] - Most recent contact is Kontakt_OG_Kizi_W_Nord and its state is CLOSED
2017-01-12 20:08:52.775 [INFO ] [org.openhab.model.script.Test ] - Kontakt_OG_Kizi_W_Nord is not OPEN
2017-01-12 20:08:52.782 [INFO ] [org.openhab.model.script.Test ] - Kontakt_OG_Kizi_W_Nord is not OPEN
2017-01-12 20:08:52.783 [INFO ] [org.openhab.model.script.Test ] - Kontakt_OG_Kizi_W_Nord is not OPEN
2017-01-12 20:08:52.786 [INFO ] [org.openhab.model.script.Test ] - Kontakt_OG_Kizi_W_Nord is not OPEN
2017-01-12 20:08:52.796 [INFO ] [org.openhab.model.script.Test ] - Most recent contact is Kontakt_OG_Kizi_W_Nord and its state is CLOSED
2017-01-12 20:08:52.798 [INFO ] [org.openhab.model.script.Test ] - Kontakt_OG_Kizi_W_Nord is not OPEN
2017-01-12 20:08:56.105 [INFO ] [org.openhab.model.script.Test ] - There are 16 contacts that have a last update
2017-01-12 20:08:56.127 [INFO ] [org.openhab.model.script.Test ] - There are 16 contacts that have a last update
2017-01-12 20:08:56.155 [INFO ] [org.openhab.model.script.Test ] - Most recent contact is Kontakt_OG_Kizi_W_Nord and its state is CLOSED
2017-01-12 20:08:56.157 [INFO ] [org.openhab.model.script.Test ] - Kontakt_OG_Kizi_W_Nord is not OPEN
2017-01-12 20:08:56.172 [INFO ] [org.openhab.model.script.Test ] - Most recent contact is Kontakt_OG_Kizi_W_Nord and its state is CLOSED
2017-01-12 20:08:56.175 [INFO ] [org.openhab.model.script.Test ] - Kontakt_OG_Kizi_W_Nord is not OPEN
2017-01-12 20:09:10.806 [INFO ] [org.openhab.model.script.Test ] - There are 16 contacts that have a last update
2017-01-12 20:09:10.851 [INFO ] [org.openhab.model.script.Test ] - There are 16 contacts that have a last update
2017-01-12 20:09:10.976 [INFO ] [org.openhab.model.script.Test ] - Most recent contact is Kontakt_EG_WC and its state is OPEN
2017-01-12 20:09:11.025 [INFO ] [org.openhab.model.script.Test ] - Most recent contact is Kontakt_EG_WC and its state is OPEN

The multiple triggers of the rule you are seeing and the fact that the state takes awhile to become OPEN are not problems with the Rules and not something I can correct short of assuring you that the rule as written works just fine with these multiple triggers.

I changed my lighting rule to the same and there is also the same behavior. If i switch the light on and immediately off again, the state-changing will not be triggered and i get no new datetime.

So i can´t do anything about that?

What do you think is the problem here? Will it be better if i put every item to the “when” part of the rule instead of the group-item?

@rlkoshak I like how clean your rules are with the item naming convention. What does N_D stand for? I’m assuming D = Door but N = ?

I kind of want to adopt your naming scheme :slight_smile:

Ha! I just abandoned that naming scheme. I came up with it in the beginning but found myself not using it consistently and finding special cases where it didn’t fit.

But for completeness, my old naming convention was:

// Naming Conventions:
//  - Groups all start with a lowercase g
// 	- Items are all capitalized camel case
//  - Takes the form of X_X_Name
//	- The first letter denotes the Item type:
//		None	Internal utility
//		'N'		Sensor
//		'S'		Switch
//		'T'		Trigger (switch without a state)
//		'W'		Weather
//	- The second letter denotes the object type
//		None	Internal utility
//		'C'		Controller
//		'D'		Door
//		'I'		Input
//		'L'		Light
//		'V'		Value
//		'W'		Window

The fact that I had to document my naming scheme in my Items file in a comment should have been my first clue this approach was untenable.

I’ve since vastly simplified this scheme:

// Naming Convention: Starts with
// - g : Group
// - v : Value/Sensor
// - a : Actuator
// - t : Timer using Expire binding

What is after that initial letter is kind of free form. I usually do camel case first letter capitalized after that for an Item. Associated Items are named with a “_” followed by the what it is.

The one exception I have is Timers that are associated Items do not start with “t” and instead start the same as the “parent” Item and end with “_Timer”.

For an example from my current rewrite of my rules:

Group:Contact:OR(OPEN,CLOSED) gDoorSensors "The doors are [MAP(en.map):%s]"

Group:DateTime:MAX gDoorsLast "The last door event was [%1$tm/%1$td %1$tH:%1$tM]"

Group:Switch:OR(ON, OFF) gDoorsTimers

Switch aGarageOpener1 "Garage Door Opener 1"
  
Contact vGarageOpener1 "Garage Door Opener 1 is [MAP(en.map):%s]"
  (gDoorSensors)
  { mqtt="<[chimera:entry_sensors/main/garage/door1:state:default]" }
  
Switch vGarageOpener1_Timer // Gets set to ON when vGarageOpener1's state changes to OPEN, gets set to OFF (i.e. timer canceled) when vGarageOpener1's state changed to CLOSED, triggers an alerting rule when receives OFF command
  (gDoorsTimers)
  { expire="1h,command=OFF" }
  
DateTime vGarageOpener1_LastUpdate "Garage Door Opener 1 [%1$tm/%1$td %1$tH:%1$tM]"
  (gDoorsLast)

...
Group:Switch:OR(ON,OFF) gPresent

Switch vPresent "Presence [MAP(en.map):%s]" 
  <present>

Switch tPresent { expire="5m,command=OFF" } // when it goes OFF it fires a rule to set vPresent to OFF, gets set to ON when gPresent goes to OFF

I’m not super happy with my treatment of Timers but it is a minor concession to make writing my rules slightly easier. It is a whole lot easier to just append “_Timer” than it is to parse out the name of an Item and replace the first character. But not massively so so I might end up doing that eventually. After I get my system back up and running fully.

Thank you for that!
I agree on your first part where having to document all those abreviations would mean something. Your new simple approach looks much better! :slight_smile:

Quick question, if you look at your 2nd post in this thread you have a rule that loops though gDoorSensors to create a timestamp whenever the state changes. Do you run this rule in OH2?

I’m running OH2B5 and i find that after a few executions it seems to break OH2 and none of my rules function. Only way to fix it is a restart. I’ve since removed that code and went to a non-automated approach inside each individual rule… Just curious if you have the same problem with that code.

Thanks!

Yes.

I’ve had no similar problem. All I can say is it works just fine for me.

Hmm ok. I upgraded off the Beta to the snapshot #717 and still same issue. Its very strange. The same snip of code you use after a few executes or edits of .rules file will cause ALL rules to stop running.

The Rule:

rule "A Door's State Changed. Log Timestamp"
when
        Item vHouseDoor changed or
        Item vPatioDoor1 changed or
        Item vGarageDoor changed
then
{
//***********************************************************************************************************************************************
// 													DETERMINE WHAT DOOR OPENED FROM GROUP gDoorSensors	 										*
//***********************************************************************************************************************************************
   	gDoorSensors?.members.filter(door|door.changedSince(now.minusSeconds(1))).forEach[ door |
   		logInfo("RULE.DOORSENSOR", "[INFO] Door state changed: {}", door.name)
        
//***********************************************************************************************************************************************
// 														SET TIMESTAMP WHEN DOOR OPENS	 														*
//***********************************************************************************************************************************************	
		if(door.state == 1) {
			gDoorSensorsTime?.members.filter(dt|dt.name == door.name+"_LastUpdate").head.postUpdate(new DateTimeType)
			logInfo("RULE.DOORSENSOR", "[NOTICE] Setting OPEN timestamp for door: {} ", door.name)
		}
    ]
}
end

Debug logs don’t show much. I’ve enabled debug logs via:

openhab> log:set DEBUG org.eclipse.smarthome
openhab> log:set DEBUG  org.openhab.model.rule

And when i re-saved the .rule the logs looked like this when the rule execution failed:

2017-01-14 23:17:56.008 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model '04-doorsensors_dimmers.rules'
2017-01-14 23:17:56.167 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model '04-doorsensors_dimmers.rules'
2017-01-14 23:17:57.900 [DEBUG] [clipse.smarthome.core.items.ItemUtil] - Converting OnOffType 'ON' to DecimalType '1' for item 'Kitchen_Window_PIR'
2017-01-14 23:17:57.902 [DEBUG] [ntime.internal.engine.RuleEngineImpl] - Executing rule 'Kitchen Window PIR'
2017-01-14 23:17:57.910 [INFO ] [del.script.RULE.MOTION.KitchenWindow] - --> Motion Detected
2017-01-14 23:17:59.227 [DEBUG] [clipse.smarthome.core.items.ItemUtil] - Converting OnOffType 'ON' to DecimalType '1' for item 'vGarageDoor'
2017-01-14 23:17:59.230 [DEBUG] [ntime.internal.engine.RuleEngineImpl] - Executing rule 'A Door's State Changed. Log Timestamp'
2017-01-14 23:18:01.437 [DEBUG] [clipse.smarthome.core.items.ItemUtil] - Converting OnOffType 'OFF' to DecimalType '0' for item 'vGarageDoor'
2017-01-14 23:18:01.525 [DEBUG] [clipse.smarthome.core.items.ItemUtil] - Converting OnOffType 'OFF' to DecimalType '0' for item 'vGarageDoor'
2017-01-14 23:18:01.885 [DEBUG] [thome.io.rest.core.item.ItemResource] - Received HTTP PUT request at 'items/alexa_phone/state' with value 'OFF'.
2017-01-14 23:18:01.888 [DEBUG] [thome.io.rest.core.item.ItemResource] - Received HTTP PUT request at 'items/chris_phone/state' with value 'ON'.
2017-01-14 23:18:03.480 [DEBUG] [ntime.internal.engine.RuleEngineImpl] - Executing rule 'Garage Door State Changed'
2017-01-14 23:18:03.490 [DEBUG] [ntime.internal.engine.RuleEngineImpl] - Executing rule 'Alexa Presence Check/Counter'
2017-01-14 23:18:03.495 [DEBUG] [ntime.internal.engine.RuleEngineImpl] - Executing rule 'A Door's State Changed. Log Timestamp'
2017-01-14 23:18:03.499 [DEBUG] [ntime.internal.engine.RuleEngineImpl] - Executing rule 'Garage Door State Changed'
2017-01-14 23:18:03.515 [DEBUG] [ntime.internal.engine.RuleEngineImpl] - Executing rule 'Chris Presence Check/Counter'
2017-01-14 23:18:03.553 [INFO ] [arthome.model.script.RULE.DOORSENSOR] - [INFO] Door state changed: vGarageDoor
2017-01-14 23:18:03.644 [DEBUG] [clipse.smarthome.core.items.ItemUtil] - Converting OnOffType 'ON' to DecimalType '1' for item 'vGarageDoor'
2017-01-14 23:18:03.732 [DEBUG] [clipse.smarthome.core.items.ItemUtil] - Converting OnOffType 'ON' to DecimalType '1' for item 'vGarageDoor'
2017-01-14 23:18:07.411 [DEBUG] [clipse.smarthome.core.items.ItemUtil] - Converting OnOffType 'OFF' to DecimalType '0' for item 'vGarageDoor'
2017-01-14 23:18:09.083 [DEBUG] [clipse.smarthome.core.items.ItemUtil] - Converting OnOffType 'ON' to DecimalType '1' for item 'vGarageDoor'

You can see the rule refresh happening at the top. Then at the bottom the rule executing, only half of it… not the setting timestamp to the item… And right after that i opened and closed the sensor a few times and no rules fire:

2017-01-14 23:18:03.553 [INFO ] [arthome.model.script.RULE.DOORSENSOR] - [INFO] Door state changed: vGarageDoor
2017-01-14 23:18:03.644 [DEBUG] [clipse.smarthome.core.items.ItemUtil] - Converting OnOffType 'ON' to DecimalType '1' for item 'vGarageDoor'
2017-01-14 23:18:03.732 [DEBUG] [clipse.smarthome.core.items.ItemUtil] - Converting OnOffType 'ON' to DecimalType '1' for item 'vGarageDoor'
2017-01-14 23:18:07.411 [DEBUG] [clipse.smarthome.core.items.ItemUtil] - Converting OnOffType 'OFF' to DecimalType '0' for item 'vGarageDoor'
2017-01-14 23:18:09.083 [DEBUG] [clipse.smarthome.core.items.ItemUtil] - Converting OnOffType 'ON' to DecimalType '1' for item 'vGarageDoor'

What happens if it takes longer than a second to get into the rule? What happens if the door.state is not (or no longer) 1? I’d put a logInfo before the group search and another in a else clause to see if either is happening.

I’ve changed that value to something longer and also put a loginfo at the start of the rule with no checks required to execute the line. When it breaks everything breaks - no rules run. I’m just in the middle of a full OH2 reinstall to see if that makes a difference…

After a complete OH2 reinstall and Snapshot #723.

I have yet to have RULES break but for some reason i can’t get the rule to work correctly with “changedSince(now.minusSeconds(5))”. I changed the value to 5 seconds for a larger gap incase that was the problem. I’ve tried all numbers including the default of 1 and same results.

Items:

Group gDoorSensors1
Switch 		vGarageDoor	 				"Garage Door [MAP(doorsensor.map):%s]"           <door>           (gDoorSensors1, gRemindDoorSensors)    	{ channel="zwave:device:159a54632e2:node15:sensor_binary"
Switch 		vHouseDoor					"House Door [MAP(doorsensor.map):%s]" 				<frontdoor>			(gDoorSensors1, gRemindDoorSensors)    	{ channel="zwave:device:159a54632e2:node13:sensor_binary" }

Rule:

rule "A Door's State Changed. Log Timestamp"
when
        Item vGarageDoor changed
then
{
	logInfo("RULE.DOORSENSOR", "### A Door's State Changed. Log Timestamp ###") 
	gDoorSensors1.members.filter(s|s.changedSince(now.minusSeconds(5))).forEach[ door |
                logInfo("RULE.DOORSENSOR", "[INFO] Door state changed: {}", door.name)
        ]
    ]
}
end

Openhab Log for ON/OFF Trigger:

2017-01-16 10:29:55.674 [INFO ] [arthome.model.script.RULE.DOORSENSOR] - ### A Door's State Changed. Log Timestamp ###
2017-01-16 10:29:55.685 [INFO ] [arthome.model.script.RULE.DOORSENSOR] - ### A Door's State Changed. Log Timestamp ###

If i change the rule so it’s !s.changedSince(now.minusSeconds(5)) instead of s.changedSince(now.minusSeconds(5)) Like this:

rule "A Door's State Changed. Log Timestamp"
when
        Item vGarageDoor changed
then
{
	logInfo("RULE.DOORSENSOR", "### A Door's State Changed. Log Timestamp ###") 
	gDoorSensors1.members.filter(s|!s.changedSince(now.minusSeconds(5))).forEach[ door |
                logInfo("RULE.DOORSENSOR", "[INFO] Door state changed: {}", door.name)
        ]
    ]
}
end

I get the following results now:

OPEN:

2017-01-16 10:37:00.284 [INFO ] [arthome.model.script.RULE.DOORSENSOR] - ### A Door's State Changed. Log Timestamp ###
2017-01-16 10:37:00.290 [INFO ] [arthome.model.script.RULE.DOORSENSOR] - [INFO] Door state changed: vHouseDoor
2017-01-16 10:37:00.294 [INFO ] [arthome.model.script.RULE.DOORSENSOR] - [INFO] Door state changed: vGarageDoor

CLOSED:

2017-01-16 10:37:37.619 [INFO ] [arthome.model.script.RULE.DOORSENSOR] - ### A Door's State Changed. Log Timestamp ###
2017-01-16 10:37:37.624 [INFO ] [arthome.model.script.RULE.DOORSENSOR] - [INFO] Door state changed: vHouseDoor
2017-01-16 10:37:37.627 [INFO ] [arthome.model.script.RULE.DOORSENSOR] - [INFO] Door state changed: vGarageDoor

Am i missing something?

What persistence are you using? Are these Items being persisted?

Try a Thread::sleep(100) to give persistence a chance to catch up. I’ve found that often the rule gets triggered before persistence has finished saving the update.

I use this rule, see my postings in this thread.

Thread::sleep(300) // give persistence time to catch up
val haveHistory = gFensterkontakte.members.filter[c|c.lastUpdate != null]
logInfo("Test", "There are " + haveHistory.size + " contacts that have a last update")

val mostRecent = haveHistory.sortBy[lastUpdate].last
logInfo("Test", "Most recent contact is " + mostRecent.name + " and its state is " + mostRecent.state)
if(mostRecent == null) logError("Test", "Failed to find most recent")
else if(mostRecent.state == OPEN){
    val dt = gKontakteZeit.members.filter[dt|dt.name == mostRecent.name+"_last_opened").head
    if(dt == null) logError("Test", "Failed to find " + mostRecent.name+"_last_opened")
    else dt.postUpdate(new DateTimeType)
}
else {
    logInfo("Test", mostRecent.name + " is not OPEN")
}

Which items do i have to persist for this rule working? And which persistence do i have to use? Do i have to use rrd4j or is it working with mapDB too? I know that mapDB is not working with OH2. But i only want to know, if i need to persist every change for a longer time or if it´s enough to store the latest value?

I have to groups used inside my rule: “gFensterkontakte” and “gKontakteZeit”

I will try that tonight. I’m running mapdb for restore & mysql for historical and persisting all values:

mapdb.persist

Strategies {
    default = everyUpdate
}

Items {
    // persist all items on every change and restore them from the db at startup
    * : strategy = everyChange, restoreOnStartup
}

mysql.persist

Strategies {
        default = everyUpdate
}

Items {
        // persist all items on every change and restore them from the db at startup
        * : strategy = everyChange
}

I persist the items in a rrd4j databese and this rrd4j files for window contacts and lights get always corruptet.

I have to delete them manually and then it´s working for some time.

Strategy is everyChange, everyMinute, restoreOnStartup

Is rrd4j the wrong persistence for this case?

All other rrd4j files are working without problems. Only the rrd4j files generated from this items of the rule are corrupt.

I persist the items with MapDB also, this persistence is working. Even if i remove all lights*.rrd-files, and restart openhab, i get the last time of opening the window last time or power on the lights.

There is no “wrong” persistence engine. RRd4j has its advantages and disadvantages. But if all you want is the lastUpdate time and you don’t need to check on historic data then MapDB is probably a better choice. If you want accurate data for a long time, MySQL, InfluxDB, et al would be better choices.

For this case the only interesting thing is the last update of the item.

So i will switch to MapDB - i´m using it already for the last state after reboot.

My main persistence is rrd4j, so if i remove the items from this rule from rrd4j and want to use the already running MapDB persistence, i have to add mapdb in the rule behind the command item.lastupdate?