Time of Day rule randomly not working

Setup, Configuration and Use Scripts & Rules
1

I have a text rule that triggers using the astro binding to set a Dark state to on or off for automated lighting.

The astro binding works fine and updates the vTimeofDay variable. However my rule below fails every few days. Can anyone see where I am going wrong:

rule "Day rule"
when
  Item vTimeOfDay received command 
then
if((vTimeOfDay.state == "EVENING" || vTimeOfDay.state == "LATE NIGHT" || vTimeOfDay.state == "EARLY NIGHT" || vTimeOfDay.state == "NIGHT"  || vTimeOfDay.state == "DAWN") && Is_Dark.state != ON) {
    Is_Dark.postUpdate(ON)
    logInfo("startup.rules","vtimeofday is {} and Dark state {} turn on Dark ", vTimeOfDay.state,Is_Dark.state)
    }
if((vTimeOfDay.state == "MORNING" || vTimeOfDay.state == "AFTERNOON") && Is_Dark.state != OFF) {
  Is_Dark.postUpdate(OFF)
  logInfo("startup.rules","vtimeofday is {} and dark is {}  turn off Dark ",vTimeOfDay.state,Is_Dark.state)
  }
  end

Here are the events log files from this morning when it did not work and then the log file from the previous days when it did. I checked and the dark trigger ran last night so the rule should have run normally this morning.

2023-04-13 06:54:00.001 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:rise#event triggered START
2023-04-13 06:54:00.010 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:civilDawn#event triggered END
2023-04-13 06:54:00.014 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Now_time' changed from 2023-04-13T06:25:00.003742+0200 to 2023-04-13T06:54:00.002576+0200
2023-04-13 06:54:00.023 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'vTimeOfDay' received command MORNING
2023-04-13 06:54:00.029 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'vTimeOfDay' changed from DAWN to MORNING
2023-04-13 06:54:04.243 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'inverter1DC1Volt_input' changed from 162.06 to 205.61
2023-04-13 06:54:04.265 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'inverter1_voltG2' changed from 232.89 to 232.74
2023-04-13 06:54:04.273 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'inverter1_voltG3' changed from 246.58 to 245.9

2023-04-12 06:56:00.001 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:civilDawn#event triggered END
2023-04-12 06:56:00.003 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:rise#event triggered START
2023-04-12 06:56:00.010 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Now_time' changed from 2023-04-12T06:26:00.002933+0200 to 2023-04-12T06:56:00.004358+0200
2023-04-12 06:56:00.012 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'vTimeOfDay' received command MORNING
2023-04-12 06:56:00.016 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'vTimeOfDay' changed from DAWN to MORNING
2023-04-12 06:56:00.024 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Is_Dark' changed from ON to OFF
2

I’m still getting to grips with how DSL rules work myself, but would have used the approach below. Hopefully it’ll help.

rule "Day rule"
when
  Item vTimeOfDay changed 
then
if((vTimeOfDay.state == "EVENING" || vTimeOfDay.state == "LATE NIGHT" || vTimeOfDay.state == "EARLY NIGHT" || vTimeOfDay.state == "NIGHT"  || vTimeOfDay.state == "DAWN") && Is_Dark.state != ON) {
	Is_Dark.sendCommand(ON)
} else {
	Is_Dark.sendCommand(OFF)
}
logInfo("startup.rules","vtimeofday is {} and dark is {}  turn off Dark ",vTimeOfDay.state,Is_Dark.state)
end
3

thanks I’ll try that.

4

What’s in openhab.log?

When it didn’t work, what state was Is_Dark already in? If Is_Dark wasn’t OFF when vTimeOfDay changed to MORNING your rule would have basically exited without doing anything.

5

Hi Rich it ran fine the previous evening so Is_Dark was ON. In the morning there was nothing in the openhab.log file.

6

That’s your assumption. But you don’t know that’s the case. You don’t log it. You didn’t show the events.log showing it. If something happened over night that impacted the state of that Item that would cause your rule to appear to do nothing.

When debugging a problem, particularly an intermittent problem:

  • reject all assumptions without concrete evidence (e.g. log it out or it didn’t happen)
  • log out everything used by the rule in a way that it’s logged every time the rule runs.
  • leave breadcrumbs in the rule to see what parts of the rule actually execute.
7

I did review the events.log file and Is_Dark was ON from the previous evening, there is no other trace of that Item in the file. In fact that is how I know the rule is not running because lights keep coming on in the Morning when they should not have. I’ll add some more logging and see if that picks up the problem.

The @Maximo option seems to work although it’s not exactly what I want because it does not check if the dark state is off during the day so you get unnecessary logging. Besides I’d like to find out why this does not work!

8

Ok - I seem to be narrowing down the problem and it appears to me that the Openhab rule is not getting the correct information back from the Astro binding.

Here is my rule which logs the current vTimeofDay then does some if statements based on this. Then below you can see the Events Log and Openhab Log from this morning. Initially it logs VTimeofDay as Dawn and then in the IF statement it logs it as Morning. Not sure what other logging I can do to see why this is happening?

rule "Day rule"
when
  Item vTimeOfDay received command 
then
logInfo("startup.rules","Beginning of rule: vtimeofday is {} and Dark state is {}", vTimeOfDay.state,Is_Dark.state) 
if((vTimeOfDay.state == "EVENING" || vTimeOfDay.state == "LATE NIGHT" || vTimeOfDay.state == "EARLY NIGHT" || vTimeOfDay.state == "NIGHT"  || vTimeOfDay.state == "DAWN") && Is_Dark.state != ON) {
    Is_Dark.postUpdate(ON)
    logInfo("startup.rules","vtimeofday is {} and Dark state {} turn on Dark ", vTimeOfDay.state,Is_Dark.state)
    }
else if((vTimeOfDay.state == "MORNING" || vTimeOfDay.state == "AFTERNOON") && Is_Dark.state != OFF) {
  Is_Dark.postUpdate(OFF)
  logInfo("startup.rules","vtimeofday is {} and dark is {}  turn off Dark ",vTimeOfDay.state,Is_Dark.state)
  }
else {
  logInfo("startup.rules","End of rule if nothing happened: vtimeofday is {} and Dark state is {}", vTimeOfDay.state,Is_Dark.state)
}
end

Events.log

2023-04-16 06:49:00.001 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:rise#event triggered START
2023-04-16 06:49:00.003 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:civilDawn#event triggered END
2023-04-16 06:49:00.008 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Now_time' changed from 2023-04-16T06:19:00.001890+0200 to 2023-04-16T06:49:00.002899+0200
2023-04-16 06:49:00.017 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'vTimeOfDay' received command MORNING
2023-04-16 06:49:00.026 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'vTimeOfDay' changed from DAWN to MORNING
2023-04-16 06:49:00.031 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Is_Dark' changed from ON to OFF


Openhab.log

2023-04-16 06:49:00.016 [INFO ] [nhab.core.model.script.startup.rules] - Beginning of rule: vtimeofday is DAWN and Dark state is ON
2023-04-16 06:49:00.025 [INFO ] [nhab.core.model.script.startup.rules] - vtimeofday is MORNING and dark is ON  turn off Dark
9

I didn’t notice before that you trigger the rule on received command. It takes some time to process a command. The rule triggers before the Item changes state so vTimeOfDay.state likely is the state before the command, not the state after the command is processed.

So either change the rule trigger to changed or in your if statement check receivedCommand instead of the Item’s state.

10

Thanks - that makes sense and more importantly fixes this problem!