Extra received command rule trigger but no command in events.log

Setup, Configuration and Use Scripts & Rules
1

I seem to be getting an extra execution of my rule with a received command trigger. I’m running version 2.5 docker image on a Synology NAS.

The rule:

var int garage_status = 0

rule "Garage Door Workaround"
when
   Item DoorGarage received command
then
   if (receivedCommand == ON){
      if (garage_status == 1){
         logInfo("Doors", "Garage door ON command, needs to be off")
         garage_status = 2
         DoorGarage.sendCommand(OFF)
         }
      else if (garage_status == 0){
         logInfo("Doors", "Garage door ON command normal")
         garage_status = -1
         }
   }
   else {
      if (garage_status == 0){
         logInfo("Doors", "Garage door OFF command, already off")
         garage_status = 1
      }
      else{
         garage_status = 0
      }
   }
   logInfo("Doors", "Garage door is now " + Long.toString(garage_status))
end

The DoorGarage item is a light switch using the Lutron binding. Alarm.com turns this virtual light switch on and off with the door. This rule is to workaround that alarm.com will issue the OFF command before the ON command sometimes. The events log for a test case:

2021-09-03 15:19:40.523 [ome.event.ItemCommandEvent] - Item 'DoorGarage' received command OFF
2021-09-03 15:19:40.524 [nt.ItemStatePredictedEvent] - DoorGarage predicted to become OFF
2021-09-03 15:19:45.713 [ome.event.ItemCommandEvent] - Item 'DoorGarage' received command ON
2021-09-03 15:19:45.714 [ome.event.ItemCommandEvent] - Item 'DoorGarage' received command OFF
2021-09-03 15:19:45.720 [nt.ItemStatePredictedEvent] - DoorGarage predicted to become ON
2021-09-03 15:19:45.726 [nt.ItemStatePredictedEvent] - DoorGarage predicted to become OFF
2021-09-03 15:19:45.731 [vent.ItemStateChangedEvent] - DoorGarage changed from OFF to ON

The openhab.log:

2021-09-03 15:19:41.638 [INFO ] [eclipse.smarthome.model.script.Doors] - Garage door OFF command, already off
2021-09-03 15:19:41.640 [INFO ] [eclipse.smarthome.model.script.Doors] - Garage door is now 1
2021-09-03 15:19:45.712 [INFO ] [eclipse.smarthome.model.script.Doors] - Garage door ON command, needs to be off
2021-09-03 15:19:45.714 [INFO ] [eclipse.smarthome.model.script.Doors] - Garage door is now 2
2021-09-03 15:19:45.716 [INFO ] [eclipse.smarthome.model.script.Doors] - Garage door is now 0
2021-09-03 15:19:45.887 [INFO ] [eclipse.smarthome.model.script.Doors] - Garage door OFF command, already off
2021-09-03 15:19:45.888 [INFO ] [eclipse.smarthome.model.script.Doors] - Garage door is now 1

So each execution of the rule prints the “Garage door is now…” line. There are 4 of them. In the openhab.log there are only 3 received command lines. Why isn’t the extra command in the events.log?

My speculation is the command goes to the Lutron binding which issues the command to the Lutron system. The system response with a message to the binding, and it can’t tell if it’s an update from it’s own command or a command from the lighting system, so it issues another command. Or is there some other reason my rule executes twice for the OFF command?

2

We should take note that DSL rules in 2.5 are fully multi-threading. More than one instance of the same rule may be executing in parallel.

These are very close together so I’d be pretty certain that is actually happening.

Does it matter? Reckon so; you’ve not explained but I guess the garage_status variable is a global. So if rule A changes it, rule B may change it something else before rule A exits. You can’t trust what is reported and it’s going to mess up steering the path through the rule with in-flight changes.

You can’t entirely trust the logging timestamp at this fine granularity either; note that the second time the rule is triggered it produces a logInfo() timestamped a millisecond before the command triggering it is logged.

3

Try this to turn it ON

when
   Item DoorGarage received command ON
then

To turn off you can use the expire binding or some other method.

Please explain what you want to happen with the light

4

I don’t want it turned off automatically, because if the door is left open I have a rule when the virtual switch is on for 5 minutes it tells us the door is left open. The rule is to work around alarm.com doing the door close before door open, which leaves the switch ON falsely.

5

It’s declared at the top of the rule file (look at what I posted again), so what I would call global. I understand the concurrent execution (and have been bitten by that on other things before), but that isn’t really the problem here. No matter what the global variable value is, printing it’s value is once per execution, and there is one more execution of the rule than the event log indicates.

Are you saying DSL is different in 3.0? I haven’t got around to trying that out.

6

Yes. But you’re on 2.5 so you get multi-threading.

Diagnostic aid -

var ruleCount = 0   // global counter

rule "your rule"
when
    blah
 then
   ruleCount = ruleCount+1
   logInfo("diag", "count " + ruleCount)
   // do first

   your rule

   logInfo("diag", "exit with count " + ruleCount)
   ruleCount = ruleCount-1
   // do last
end

I’ve no doubt some event is getting hidden here, maybe an identical event within the same millisecond. Couldn’t say if by logger or log viewer.
Confirming what’s going on helps to develop your fix.

7

Ok I re-dead your OP

What are the states of “garage_status”

I see 4 can you explain each one

-1 = 
0 =  off maybe
1 = on maybe
2 = I told you you were on now brake the rule

It only ever changes DoorGarage.sendCommand(OFF) and only after the first ever on command.

I assumed you had a momentary input my mistake.

What are all the Items do you have that relate to the door.

You get an OFF when you should get an ON on which item?

When you receive an ON command and the status is ON why dose it need to be OFF immediately as your rule below

   if (receivedCommand == ON){
      if (garage_status == 1){
         logInfo("Doors", "Garage door ON command, needs to be off")
         garage_status = 2
         DoorGarage.sendCommand(OFF)
         }

Then you command and run the rule again in status = 2 then the bit below changes it to 0

Then you get another command to turn it off when it already is off. I assume this is from the binding which is your issue?

8

No I didn’t. The switch item is tied to a virtual light switch in Lutron (the binding doesn’t know the difference, it’s just a switch with integration id xxx). It’s virtual in that there is no real switch, but Lutron can control it from its phone app (which I used for testing this) or the alarm.com integration. So when the door opens alarm.com turns the light switch ON and when it closes it turns it OFF. The problem needing this rule is when the door is opened and closed, sometimes alarm.com will do the OFF before the ON, which would leave the switch ON (making openhab think the door is open). This rule issues an OFF when it detects that this has happened.

The states are:
0 = switch OFF
-1 = switch was turned ON normally (OFF to ON). An OFF from here goes back to 0.
1 = An OFF was detected when already OFF (state 0). So after the ON and OFF is needed.
2 = ON command occurred so OFF is issued. When the OFF occurs go to 0.
My fix to handle always getting two OFF events is to add state 3 so two OFFs get it back to 0.

The reason for the numeric state in the first place is AFAIK there is no way to get the prior state of the item before the receivedCommand is applied to it.

I hope this helps and by looking at the rule again the rest of your questions are answered.

9

That is essentially correct. At command time the state most likely is the pre-command state, but if the effect of the command takes place swiftly enough, you cannot be certain of not getting new state.

Perhaps that’s a clue to how to process this; have the command take no effect at all, except as issued by the rule itself after it has looked at whatever it looks at.

10

Are you saying the two identical events in the same millisecond could make the event log only show one? I don’t know what logger vs. log viewer is. But did you mean help to develop the openhab fix? Or is it a feature? :slight_smile:

In any case, I added the ruleCount and tried it again. With 3 tests the events log showed 4 commands listed. From the times on my original post I can see the two OFF events could have been within a millisecond. Now they aren’t even close–the extra logs add that much time I guess.

Events log:

2021-09-10 08:21:27.727 [ome.event.ItemCommandEvent] - Item 'DoorGarage' received command OFF
2021-09-10 08:21:27.729 [nt.ItemStatePredictedEvent] - DoorGarage predicted to become OFF
2021-09-10 08:21:28.249 [ome.event.ItemCommandEvent] - Item 'DoorGarage' received command ON
2021-09-10 08:21:28.250 [nt.ItemStatePredictedEvent] - DoorGarage predicted to become ON
2021-09-10 08:21:28.257 [vent.ItemStateChangedEvent] - DoorGarage changed from OFF to ON
2021-09-10 08:21:28.905 [ome.event.ItemCommandEvent] - Item 'DoorGarage' received command OFF
2021-09-10 08:21:28.913 [nt.ItemStatePredictedEvent] - DoorGarage predicted to become OFF
2021-09-10 08:21:28.924 [vent.ItemStateChangedEvent] - DoorGarage changed from ON to OFF
2021-09-10 08:21:29.033 [ome.event.ItemCommandEvent] - Item 'DoorGarage' received command OFF
2021-09-10 08:21:29.034 [nt.ItemStatePredictedEvent] - DoorGarage predicted to become OFF

The openhab log:

2021-09-10 08:21:28.897 [INFO ] [eclipse.smarthome.model.script.Doors] - count 1
2021-09-10 08:21:28.898 [INFO ] [eclipse.smarthome.model.script.Doors] - Garage door OFF command, already off
2021-09-10 08:21:28.900 [INFO ] [eclipse.smarthome.model.script.Doors] - Garage door is now 1
2021-09-10 08:21:28.900 [INFO ] [eclipse.smarthome.model.script.Doors] - exit with count 2
2021-09-10 08:21:28.901 [INFO ] [eclipse.smarthome.model.script.Doors] - count 2
2021-09-10 08:21:28.902 [INFO ] [eclipse.smarthome.model.script.Doors] - Timer for Garage door started
2021-09-10 08:21:28.903 [INFO ] [eclipse.smarthome.model.script.Doors] - Garage door ON command, needs to be off
2021-09-10 08:21:28.905 [INFO ] [eclipse.smarthome.model.script.Doors] - Garage door is now 2
2021-09-10 08:21:28.906 [INFO ] [eclipse.smarthome.model.script.Doors] - count 3
2021-09-10 08:21:28.906 [INFO ] [eclipse.smarthome.model.script.Doors] - exit with count 3
2021-09-10 08:21:28.907 [INFO ] [eclipse.smarthome.model.script.Doors] - Garage door is now 0
2021-09-10 08:21:28.908 [INFO ] [eclipse.smarthome.model.script.Doors] - exit with count 3
2021-09-10 08:21:28.914 [INFO ] [eclipse.smarthome.model.script.Doors] - Garage door closed
2021-09-10 08:21:29.034 [INFO ] [eclipse.smarthome.model.script.Doors] - count 4
2021-09-10 08:21:29.035 [INFO ] [eclipse.smarthome.model.script.Doors] - Garage door OFF command, already off
2021-09-10 08:21:29.037 [INFO ] [eclipse.smarthome.model.script.Doors] - Garage door is now 1
2021-09-10 08:21:29.039 [INFO ] [eclipse.smarthome.model.script.Doors] - exit with count 4

I don’t know what you mean by this (command take no effect). To fix my rule to handle two OFFs just needs another state.

11

Did you miss out the count decrement part? No matter, we can see two rule exits with count 3 … which means we started two “instances” of the rule before the first got to the incrementing part.

I’m saying you want to stop the command “doing stuff” until after you have examined the current state.

This is common enough but usually revolves around Item commands and Item states. Here you’re looking at a global variable instead.

So, how is your command affecting this ‘state’ then? Only by the rule setting it. That’s great, until we throw in parallel threads doing the same thing. Must have one at a time processing, else we are not stopping this command taking effect before processing that command.

See reentrant locking, to make it queue commands.

Seeing the ‘count 3’ incident, I do not think you will fix this by adding extra variable states.

12

Yes, I missed that.

What are the problems with that? I seem to recall issues discussed that I never looked into it.

The worse parallel case would be the OFF and ON at the start, if the ON didn’t know the OFF happened.
I had a prior method that just incremented and decremented the state, which worked mostly (had issues when the Lutron system restarted–virtual switches are all ON when it starts and I have to turn them off). I may just put that prior method back in until I can migrate to OH 3 (same rule is always serialized, right?).

13

It is unforgiving. If your rule has an error because you forget to account for null states or overflow or suchlike, it will be locked until reloaded.
Write reliable code, which isn’t a problem for your simple rule, and you won’t get caught.

The horrible cautions are because people try to use it with long, slow running rules - which looks like a good idea - but their long rules are not bulletproof.

Really it’s the try-catch structure (that should avoid this error/lock issue) that is unreliable. DSL errors often break out of it somehow.

14

Ok. Thanks for the help. I’ll keep my previous rule and try this method out after moving to OH3.
I don’t know if the events.log thing should be reported as a bug.

15

I think its a fundamental misunderstanding that short rules are written by beginners.

Lets start again and make this your question.

If you do you could use something like when DoorGarage receives off command start a timer. When DoorGarage receives on command and timer is timing update DoorGarage to OFF

16

I’ve started the openhab 3 migration (have a 3.0.2 running together with my 2.5). I got notifications working first to move these door rules over. I updated the above rule to have the extra state, and it works fine. There’s a new problem in openhab 3 now. The updated workaround plus the “regular” open/close rules:

var Timer garage_timer = null

var int garage_status = 0

rule "Garage Door Workaround"
when
   Item DoorGarage received command
then
   if (receivedCommand == ON){
      if (garage_status == 1){
         logInfo("Doors", "Garage door ON command, needs to be off")
         garage_status = 2
         DoorGarage.sendCommand(OFF)
         }
      else if (garage_status == 0){
         logInfo("Doors", "Garage door ON command normal")
         garage_status = -1
         }
   }
   else {
      if (garage_status == 0){
         logInfo("Doors", "Garage door OFF command, already off")
         garage_status = 1
      }
      else if(garage_status == 2){
         garage_status = 3
      }
      else{
         garage_status = 0
      }
   }
   logInfo("Doors", "Garage door is now " + Long.toString(garage_status))
end

rule "Garage Door Open"
when
   Item DoorGarage changed to ON
then
   NotifyController.sendCommand("HI Garage service door opened.")

   garage_timer = createTimer(now.plusMinutes(5), [|
        garage_timer = null
        logInfo("Doors", "Garage door timer running, door is "+DoorGarage.state.toString)
        NotifyController.sendCommand("HA Garage service door is left open.")
        ])
   logInfo("Doors", "Timer for Garage door started")
end

rule "Garage Door Close"
when
   Item DoorGarage changed from ON to OFF
then
   logInfo("Doors", "Garage door closed")
   garage_timer?.cancel()
end

The workaround is better now. I’m not seeing the two OFF events that close together, so hard to see if openhab 3 would have the same bug/feature as 2.5 that prints just one in the events.log. The logs:

2021-09-16 12:32:26.674 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'DoorGarage' received command OFF
2021-09-16 12:32:26.675 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'DoorGarage' predicted to become OFF
2021-09-16 12:32:30.485 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'DoorGarage' received command ON
2021-09-16 12:32:30.485 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'DoorGarage' predicted to become ON
2021-09-16 12:32:30.488 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'DoorGarage' changed from OFF to ON
2021-09-16 12:32:30.491 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'NotifyController' received command HI Garage service door opened.
2021-09-16 12:32:30.506 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'DoorGarage' received command OFF
2021-09-16 12:32:30.507 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'NotifyControlFlag' received command ON
2021-09-16 12:32:30.508 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'NotifyController' changed from <something else> to HI Garage service door opened.
2021-09-16 12:32:30.509 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'DoorGarage' predicted to become OFF
2021-09-16 12:32:30.512 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'DoorGarage' changed from ON to OFF
2021-09-16 12:32:30.513 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'NotifyControlFlag' changed from OFF to ON
2021-09-16 12:32:30.677 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'DoorGarage' received command OFF
2021-09-16 12:32:30.678 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'DoorGarage' predicted to become OFF
2021-09-16 12:37:30.521 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'NotifyController' received command HA Garage service door is left open.

2021-09-16 12:32:26.677 [INFO ] [org.openhab.core.model.script.Doors ] - Garage door OFF command, already off
2021-09-16 12:32:26.679 [INFO ] [org.openhab.core.model.script.Doors ] - Garage door is now 1
2021-09-16 12:32:30.487 [INFO ] [org.openhab.core.model.script.Doors ] - Garage door ON command, needs to be off
2021-09-16 12:32:30.493 [INFO ] [org.openhab.core.model.script.Doors ] - Garage door is now 2
2021-09-16 12:32:30.510 [INFO ] [org.openhab.core.model.script.Doors ] - Garage door is now 3
2021-09-16 12:32:30.520 [INFO ] [org.openhab.core.model.script.Doors ] - Garage door closed
2021-09-16 12:32:30.527 [INFO ] [org.openhab.core.model.script.Doors ] - Timer for Garage door started
2021-09-16 12:32:30.682 [INFO ] [org.openhab.core.model.script.Doors ] - Garage door is now 0
2021-09-16 12:37:30.519 [INFO ] [org.openhab.core.model.script.Doors ] - Garage door timer running, door is OFF

The problem here is even though the door was closed (item changed to OFF), and the rule executed (the openhab.log shows that), it seems like the timer didn’t get canceled. Does openhab 3 need something changed in that I’m not aware of?

Make what my question? Not sure your point. And if this timer thing is suggesting how to get around the concurrent running of rules, moving to openhab 3 takes care of that.

17

OH3 “single-threading of rules” applies to one rule only at a time. Different rules may run in parallel at the same time.

You still have lots of commands and changes flying about in the space of milliseconds. In this case your rules “Garage Door Open” and “Garage Door Close” may execute in parallel.
If you restructure those into one rule, it will be compelled to deal with one change at a time.

18

I knew that.

but didn’t think about it here. Thanks for finding it.