Item update state by itself

New behavior since the last update to OpenHab 2.5.5-1. I use some flag to trigger event on my rollershutter based on sun position. The new problem is about some flag. I use a rule to set the flag in the morning and reset it at the night. During the day, without any apparent reason, the flag is set to OFF by itself. It could happen 1 hour or more after my rule set the flag to ON.

There is the rule not triggered anymore because of the flag “FlagStoreLivingOpeningRequested” setting to OFF by itself:

 rule "Store opening with sun position"
 when
     Item Azimuth received update
 then
 if (FlagStoreLivingOpeningRequested.state == ON) {
	if (Azimuth.state >= 105 && FlagStoreLiving1Opened.state == OFF) {
		Thread::sleep(500) //Force a delay if RF command was sent just before. Fix timing issue.
	    sendCommand( RolShut_FF_living1, "UP" )
	    FlagStoreLiving1Opened.sendCommand(ON)
	    logInfo(logName, "Ouverture rideau motorise no1")
	}
	if (Azimuth.state >= 120 && FlagStoreLiving2Opened.state == OFF) {
		Thread::sleep(500) //Force a delay if RF command was sent just before. Fix timing issue.
	    sendCommand( RolShut_FF_living2, "UP" )
	    FlagStoreLiving2Opened.sendCommand(ON)
	    logInfo(logName, "Ouverture rideau motorise no2")
	}
    if (Azimuth.state >= 140 && FlagStoreLiving3Opened.state == OFF) {
		Thread::sleep(500) //Force a delay if RF command was sent just before. Fix timing issue.
	    sendCommand( RolShut_FF_living3, "UP" )
	    FlagStoreLiving3Opened.sendCommand(ON)
	    Thread::sleep(500)
	    sendCommand( RolShut_FF_living4, "UP" )
	    FlagStoreLiving4Opened.sendCommand(ON)
	    logInfo(logName, "Ouverture rideau motorise no3 et no4")
	}
}

end

See below the log when I trigger the rule by myself and when the flag is set to off by itself later:

2020-06-04 04:54:03.647 [ome.event.ItemCommandEvent] - Item 'FlagStoreLivingOpeningRequested' received command ON
2020-06-04 04:54:03.654 [vent.ItemStateChangedEvent] - FlagStoreLivingOpeningRequested changed from OFF to ON

2020-06-04 06:09:52.507 [ome.event.ItemCommandEvent] - Item 'FlagStoreOpeningRequested' received command OFF
2020-06-04 06:09:52.512 [ome.event.ItemCommandEvent] - Item 'FlagStoreLateOpeningRequested' received command OFF
2020-06-04 06:09:52.518 [ome.event.ItemCommandEvent] - Item 'FlagStoreLivingOpeningRequested' received command OFF
2020-06-04 06:09:52.524 [ome.event.ItemCommandEvent] - Item 'FlagStoreLiving1Opened' received command OFF
2020-06-04 06:09:52.531 [ome.event.ItemCommandEvent] - Item 'FlagStoreLiving2Opened' received command OFF
2020-06-04 06:09:52.537 [ome.event.ItemCommandEvent] - Item 'FlagStoreLiving3Opened' received command OFF
2020-06-04 06:09:52.543 [ome.event.ItemCommandEvent] - Item 'FlagStoreLiving4Opened' received command OFF
2020-06-04 06:09:52.553 [ome.event.ItemCommandEvent] - Item 'vTimeOfDay' received command DAY
2020-06-04 06:09:52.556 [vent.ItemStateChangedEvent] - FlagStoreLivingOpeningRequested changed from ON to OFF

The only curious thing is about those flag changed by themselve exactly at the same time as vTimeOfDay change of status. However I don’t see the link with this rule. See below, based on “Design Pattern: Time of day” from @rlkoshak.

rule "Calculate time of day state"
when
   // See configuration in  paper UI for offset sunset et evening night
   System started or
   Channel 'astro:sun:local:rise#event' triggered START or
   Channel 'astro:sun:local:set#event' triggered START or
   Channel 'astro:sun:local:eveningNight#event' triggered START or
   Time cron "0 1 0 * * ? *" or // one minute after midnight so give Astro time to calculate 
   the new day's times
   Time cron "0 0 5 * * ? *" or
   Time cron "0 0 22 * * ? *" or
   Time cron "0 59 23 * * ? *"
then  
   //Thread::sleep(1000) // make sure we are a tad past midnight to give Astro a chance 
    to recalculate DateTimes for today

   val morning_start = now.withTimeAtStartOfDay.plusDays(1).minusHours(19)  // 5h00 AM
	vMorning_Time.postUpdate(morning_start.toString)
   val day_start = new DateTime(vSunrise_Time.state.toString)
   val afternoon_start = new DateTime(vEvening_Time.state.toString)
   val evening_start = new DateTime(vSunset_Time.state.toString) 
   val bed_start = now.withTimeAtStartOfDay.plusDays(1).minusHours(2)		//22h00 
	vBed_Time.postUpdate(bed_start.toString)
   val night_start = now.withTimeAtStartOfDay.plusDays(1).minusMinutes(1)	//23h59
	vNight_Time.postUpdate(night_start.toString)

   var curr = "UNKNOWN" 
   switch now {
	case now.isAfter(morning_start)   && now.isBefore(day_start):		curr = "MORNING"
	case now.isAfter(day_start) 	  && now.isBefore(afternoon_start): curr = "DAY"
	case now.isAfter(afternoon_start) && now.isBefore(evening_start):  	curr = "AFTERNOON"
	case now.isAfter(evening_start)   && now.isBefore(bed_start):     	curr = "EVENING"
	case now.isAfter(bed_start) 	  && now.isBefore(night_start):     curr = "BED"
	case now.isAfter(night_start)	  || now.isBefore(morning_start):	curr = "NIGHT"
   }

   logInfo(logName, "Current time of day is " + curr)
   vTimeOfDay.sendCommand(curr)
end

The only rule triggering the flag to OFF is related to Time of Day with this rule:

rule "Evening time started"
when 
    Item vTimeOfDay changed to "EVENING"
then
    logInfo(logName, "Il fait maintenant noir dehors. Ouverture des lumieres")
   Toast_FF_living_LG_TV.sendCommand("Il fait maintenant noir dehors. Ouvertures des lumières extérieures")
   sendCommand(SgSay, "Il fait maintenant noir dehors. J'ouvre les lumières extérieures")
   logInfo(logName, SgSay.state.toString)
   Thread::sleep(10000) // attente 10 sec - on veut entendre la voix avant l'action
   sendCommand(gEveningLights, ON)
   sendCommand( RolShut_FF_bed1, "DOWN" )  		  // Fermeture rideau motorisé chambre principale

    //We close all roller shutter. Stop following sun position
    FlagStoreLivingOpeningRequested.sendCommand(OFF)
    FlagStoreLiving1Opened.sendCommand(OFF)
    FlagStoreLiving2Opened.sendCommand(OFF)
    FlagStoreLiving3Opened.sendCommand(OFF)
    FlagStoreLiving4Opened.sendCommand(OFF)
    sendCommand( RolShut_FF_livingAll, "DOWN" )
end

Is someone have an idea how I could troubleshoot this issue? By global research, I’m 100% sure I don’t have any other rule triggering the flag to OFF.

If the rule “Evening time started” is the only one Setting the flag to OFF your log should show the logInfo lines of this rule. Since you didn’t post all log-entries for rhe time in question: Do those lines show?

May we see the corresponding state changed event, which would tell us what the state was at the time of the unexpected commands.

Good question. I didn’t check that yet. vTimeOfDay trig to Evening at 21:48 that day. And yes all the flag related to RollerShutter trig to OFF as they should do. No ItemStateChangedEvent however because the state was already OFF since 6:09Am. All other actions related to the light work correctly when TimeOfDay trigger to evening.

2020-06-04 21:48:00.003 [vent.ChannelTriggeredEvent] - astro:sun:local:eveningNight#event triggered START
2020-06-04 21:48:00.097 [ome.event.ItemCommandEvent] - Item 'vTimeOfDay' received command EVENING
2020-06-04 21:48:00.101 [vent.ItemStateChangedEvent] - vTimeOfDay changed from AFTERNOON to EVENING

2020-06-04 21:48:10.152 [ome.event.ItemCommandEvent] - Item 'gEveningLights' received command ON
2020-06-04 21:48:10.165 [ome.event.ItemCommandEvent] - Item 'RolShut_FF_bed1' received command DOWN
2020-06-04 21:48:10.173 [ome.event.ItemCommandEvent] - Item 'FlagStoreLivingOpeningRequested' received command OFF
2020-06-04 21:48:10.179 [ome.event.ItemCommandEvent] - Item 'FlagStoreLiving1Opened' received command OFF
2020-06-04 21:48:10.185 [ome.event.ItemCommandEvent] - Item 'FlagStoreLiving2Opened' received command OFF
2020-06-04 21:48:10.193 [ome.event.ItemCommandEvent] - Item 'FlagStoreLiving3Opened' received command OFF
2020-06-04 21:48:10.199 [ome.event.ItemCommandEvent] - Item 'FlagStoreLiving4Opened' received command OFF
2020-06-04 21:48:10.205 [ome.event.ItemCommandEvent] - Item 'RolShut_FF_livingAll' received command DOWN
2020-06-04 21:48:10.224 [ome.event.ItemCommandEvent] - Item 'light_OUT_outside_shed' received command ON
2020-06-04 21:48:10.244 [ome.event.ItemCommandEvent] - Item 'light_OUT_outside_house' received command ON
2020-06-04 21:48:10.255 [nt.ItemStatePredictedEvent] - light_OUT_outside_shed predicted to become ON
2020-06-04 21:48:10.274 [nt.ItemStatePredictedEvent] - light_OUT_outside_house predicted to become ON
2020-06-04 21:48:10.295 [vent.ItemStateChangedEvent] - light_OUT_outside_shed changed from OFF to ON
2020-06-04 21:48:10.301 [vent.ItemStateChangedEvent] - light_OUT_outside_house changed from OFF to ON

Maybe we have something here @rossko57… At 4:54am Astro binding trigger Item vTimeOfDay to DAY. During this period of the year, it happen before 5:00Am, time I force it in the rule “Calculate time of day state” (see in the previous post). So I skip the step “MORNING” passing directly from “NIGHT to DAY”

 Channel 'astro:sun:local:rise#event' triggered START
2020-06-04 04:54:00.016 [vent.ChannelTriggeredEvent] - astro:sun:local:rise#event triggered START
2020-06-04 04:54:00.061 [vent.ChannelTriggeredEvent] - astro:sun:local:civilDawn#event triggered END
2020-06-04 04:54:00.072 [vent.ItemStateChangedEvent] - astro_sun_local_phase_name changed from CIVIL_DAWN to SUN_RISE
2020-06-04 04:54:00.082 [vent.ItemStateChangedEvent] - Sunrise_Azimuth changed from 54.819112154220974 to 54.44105610022625
2020-06-04 04:54:00.170 [ome.event.ItemCommandEvent] - Item 'vTimeOfDay' received command DAY
2020-06-04 04:54:00.174 [vent.ItemStateChangedEvent] - vTimeOfDay changed from NIGHT to DAY 

2020-06-04 04:58:00.008 [vent.ChannelTriggeredEvent] - astro:sun:local:daylight#event triggered START
2020-06-04 04:58:00.022 [vent.ChannelTriggeredEvent] - astro:sun:local:rise#event triggered END
2020-06-04 04:58:00.027 [vent.ItemStateChangedEvent] - astro_sun_local_phase_name changed from SUN_RISE to DAYLIGHT

2020-06-04 05:00:00.115 [ome.event.ItemCommandEvent] - Item 'vTimeOfDay' received command DAY

2020-06-04 06:09:52.507 [ome.event.ItemCommandEvent] - Item 'FlagStoreOpeningRequested' received command OFF
2020-06-04 06:09:52.512 [ome.event.ItemCommandEvent] - Item 'FlagStoreLateOpeningRequested' received command OFF
2020-06-04 06:09:52.518 [ome.event.ItemCommandEvent] - Item 'FlagStoreLivingOpeningRequested' received command OFF
2020-06-04 06:09:52.524 [ome.event.ItemCommandEvent] - Item 'FlagStoreLiving1Opened' received command OFF
2020-06-04 06:09:52.531 [ome.event.ItemCommandEvent] - Item 'FlagStoreLiving2Opened' received command OFF
2020-06-04 06:09:52.537 [ome.event.ItemCommandEvent] - Item 'FlagStoreLiving3Opened' received command OFF
2020-06-04 06:09:52.543 [ome.event.ItemCommandEvent] - Item 'FlagStoreLiving4Opened' received command OFF
2020-06-04 06:09:52.553 [ome.event.ItemCommandEvent] - Item 'vTimeOfDay' received command DAY

But I still not understand the link of that with my issue of Flag triggering by themselve…

Generic advice - always look for state changed events, as well as command events, or you might miss surprises.
Surprises can include stuff like Items being reinitialized in the night to NULL, sometimes seen in connection with zwave.
Another surprise can be when autoupdate is suppressed for some reason, and command does not result in state update.

Of course you don’t always get a change in response to a command, which itself carries diagnostic meaning (it was already in that state) but for us remote viewers we can’t tell whether changes are absent or filtered out.

This is worth looking at harder. Why would your “Calculate time of day state” rule run at that time, 06:09?
Not a cron.
Leaves spurious System started - this is a possibility. Any other System started rules you might observe? Look in events.log preceding for Thing update events (not Thing status events) which are sometimes associated.

I also now recall a post about Astro oddities - have a look, then have a look at midnight for your astro scheduling/Items for oddballs like UNDEF. There is currently no ‘astronomical night’ for example, at quite modest latitudes.

Ok, thanks. I’ll continue to investigate following your advice. I do use zwave and I already get some issue related to NIGHT to NULL. I will take a look if it still happen.

About spurious system start I’ll do a test and remove that line from my rule as a test for tomorrow morning. Will see if it change something.

Not sure to understand what you meen by autoupdate. Do you mean I should configure all the flag as autoupdate = false. I never understand correctly that concept of autoupdate…

Currently:

//Flag
Switch FlagStoreOpeningRequested
Switch FlagStoreLateOpeningRequested
Switch FlagStoreLivingOpeningRequested
Switch FlagStoreLiving1Opened
Switch FlagStoreLiving2Opened
Switch FlagStoreLiving3Opened
Switch FlagStoreLiving4Opened

Should it be like this?:

//Flag
Switch FlagStoreOpeningRequested {autoupdate="false"}
Switch FlagStoreLateOpeningRequested {autoupdate="false"}
Switch FlagStoreLivingOpeningRequested {autoupdate="false"}
Switch FlagStoreLiving1Opened {autoupdate="false"}
Switch FlagStoreLiving2Opened {autoupdate="false"}
Switch FlagStoreLiving3Opened {autoupdate="false"}
Switch FlagStoreLiving4Opened {autoupdate="false"}

What I mean is that you rely on autoupdate.
When you send a command to an Item, that does not of itself change the state at all.
In general, the command would pass out through the binding to a device, something happens, and the device sends a status report to the binding that gets used to update the Item state.
Autoupdate speeds that up, by listening for commands to each Item and guessing the outcome, then updating the Item state…

When an Item is not linked to a binding at all, the only way the state gets updated after a command is by autoupdate. For many of your Items/rules you are relying on that to happen…

Autoupdate is enabled on each Item by default, you don’t need to change anything.

It is possible to accidentally stop autoupdate working, for example by adding a broken link to the Item.
Or indeed, when there is a real link to a binding, but the Thing is offline or similar.
I don’t think there is any way to mess it up where the Item has no links at all (but bear in mind broken links can hidden).

All I’m suggesting is that you look hard at your relevant Items and make sure the expected state changes follow commands. If they don’t, we can look deeper.

Based on what @rossko57 says, I would suggest to send a postUpdate instead of a sendCommand to your Flag items.

Then I see in the rule “Evening time started” a Thread:sleep of 10 seconds! Use it only for max 500ms (see Why have my Rules stopped running? Why Thread::sleep is a bad idea)

And maybe a typo but sendCommand(gEveningLights, ON) won’t work, the action sendCommand only accept strings. My advise is to use Item.sendcommandgEveningLights.sendCommand(ON) (see https://www.openhab.org/docs/configuration/rules-dsl.html#myitem-sendcommand-new-state-versus-sendcommand-myitem-new-state)

The typo and the Thread:sleep can cause unpredictable outcomes, such as a Flag item which set its self :wink:

I changed all the item.sendCommand by item.postUpdate. It do not change my issue but I now know it’s the way to do. However I find out another clue I didn’t post in the previous message.

I initialise some value during a System started rule:

rule "Initialisation"
when
    System started
then
    gWTR_Sensor.members.forEach [item |
	   item.sendCommand(OFF)
    ]
    NbSpaTemperatureTrigger.sendCommand(0)
    FlagStoreOpeningRequested.postUpdate(OFF)
    FlagStoreLateOpeningRequested.postUpdate(OFF)
    FlagStoreLivingOpeningRequested.postUpdate(OFF)
    FlagStoreLiving1Opened.postUpdate(OFF)
    FlagStoreLiving2Opened.postUpdate(OFF)
    FlagStoreLiving3Opened.postUpdate(OFF)
    FlagStoreLiving4Opened.postUpdate(OFF)
end

I got all those variables to update at the same time following that log.

2020-06-14 05:24:50.021 [ome.event.ItemCommandEvent] - Item 
'NbSpaTemperatureTrigger' received command 0
2020-06-14 05:24:50.035 [ome.event.ItemCommandEvent] - Item 'vTimeOfDay' received 
command DAY
2020-06-14 05:24:50.043 [nt.ItemStatePredictedEvent] - WTR_FF_LaveVaisselle_alarm 
predicted to become OFF
2020-06-14 05:24:50.061 [nt.ItemStatePredictedEvent] - WTR_SS_Laveuse_alarm 
predicted to become OFF
2020-06-14 05:24:50.073 [nt.ItemStatePredictedEvent] - WTR_SS_SalleBainSS_alarm 
predicted to become OFF
2020-06-14 05:24:50.086 [nt.ItemStatePredictedEvent] - WTR_FF_SalleBainFF_alarm 
predicted to become OFF
2020-06-14 05:24:50.118 [nt.ItemStatePredictedEvent] - 
WTR_SS_TankEauChaude_alarm predicted to become OFF
2020-06-14 05:24:50.142 [vent.ItemStateChangedEvent] - 
FlagStoreLivingOpeningRequested changed from ON to OFF 

So now, I’m sure my real issue is a non requested reset from OpenHab. I don’t know why it happen everytime around the same hour. I’ll put a logInfo into that rule to see if it fire at another time during the day. Today, I’ll work to remove the long Thread:sleep in my rule. Will see if it change something. I’ll also remove the typo about gEveningLights as proposed.

Any advice about how to figure out what could cause precisely that reset? Any log special log I could activate? I was working around “time of day state” but it could be anything else. I may do it the hard way by deactivating binding one by one (starting by the Zwave) but probably a better way to proceed?

As I said earlier, look for Thing updated events in your events.log
These have been observed to precede unexpected initialization events.

I did not figure out yet why my initialisation rule ‘‘When System started’’ trigger. But the workaround in my case was to remove Flag initialisation from that rule and move them to my persistence service (influxdb) with strategy ‘‘restoreOnStartup’’. Thanks for your help.