[SOLVED] Strange rules behavior (including timers)

Karol · March 29, 2019, 3:29pm

Most of rules are in one rules file (gates, guards and other), only vioce/notification rules are in separate file. All variables used by inside functions are defined on the beginning of each file:

Main.rules:

var Timer tOD = null
var Number nOD = 0
var Timer tOP = null
var Number nOP = 0
var Timer tWWZ = null
var Number nWWZ = 0
var Timer tBZSIPNZA = null
var Timer tOF = null
var Number nOF = 0
var Timer tRBW = null
var Number nRBW = 0
var Timer tSOBW = null
var Number nSOBW = 0
var Timer tRBG = null
var Number nRBG = 0
var Timer tSOBG = null
var Number nSOBG = 0
var Timer tDDF = null
var Number nDDF = 0
var Timer tAOFPD = null
var Number nAOFPD = 0

var DateTime lOswietlenieDrogiTOn = null
var Number lOswietlenieDrogiTPassed
var DateTime lOswietleniePosesjiTOn = null
var Number lOswietleniePosesjiTPassed
var DateTime lWegielWZasobnikuTBrak = null
var Number lWegielWZasobnikuTPassed
var DateTime lBramaGarazowaTOpened = null
var Number lBramaGarazowaTPassed
var DateTime lBramaWjazdowaTOpened = null
var Number lBramaWjazdowaTPassed
...

Notification.rules:

var Timer tFCTZZ = null
var Number nFCTZZ = 0

Added delay doesn’t change a thing. Maybe… maybe excetion appears less than before, but still it’s annoying, especially because each exception kills rule that generated it.

I’ve rewrited TTS rule to simplier version:

rule "TTS Function v3"
  when
	  Item Read_Trigger changed to ON
  then
    logInfo("KWI.debug.rules","R_DEBUG: FCTZZv3 1")
    Group_Speaker_AllSpeakers.allMembers.forEach [item |
      item.sendCommand(60)
    ]
    createTimer(now.plusSeconds(2), [|
      logInfo("KWI.debug.rules","R_DEBUG: FCTZZv3 2")
      say(InfoToRead.state.toString)
      //say(InfoToRead.state.toString, new PercentType(60))
      logInfo("KWI.debug.rules","R_DEBUG: FCTZZv3 3")
    ])
    createTimer(now.plusSeconds(17), [|
      logInfo("KWI.debug.rules","R_DEBUG: FCTZZv3 4")
      Group_Speaker_AllSpeakers.allMembers.forEach [item |
        item.sendCommand(30)
      ]
    ])
    logInfo("KWI.debug.rules","R_DEBUG: FCTZZv3 5")
end

Exceptions are reduced but still happen quite often. It looks like everytime when “cascade timers” occure in code, problem reveals.

PS Java Runtime Environment: openjdk-8-jre-headless, openjdk version “1.8.0_191”

Karol · March 29, 2019, 5:16pm

Maybe I’m looping but I’d rather ask…
Let’s consider 2 pair of the rules that supports one of my gates events…

rule "Gate Opening"
  when
    Item Stan_bramy_garazowej changed to OFF
  then
    logInfo("KWI.debug.rules","REGRUN: Ruch bramy garażowej - Otwarta")
    if(tRBG === null) {
      logInfo("KWI.debug.rules","R_DEBUG: tRBG 1 (" + tRBG + ")")
      nRBG = 0
      logInfo("KWI.debug.rules","R_DEBUG: tRBG 2 (" + tRBG + ")")
      tRBG = createTimer(now, [|
        logInfo("KWI.debug.rules","R_DEBUG: tRBG 3 (" + tRBG + ")")
        nRBG += 1
        logInfo("KWI.debug.rules","R_DEBUG: tRBG 4 (" + tRBG + ")")
        switch (nRBG.intValue) {
          case 1 : {
            logInfo("KWI.debug.rules","R_DEBUG: tRBG 5 (" + tRBG + ")")
            Stan_bramy_garazowej_N.sendCommand(ON)
            Brama_garazowa_LOG.postUpdate(ON)
            if(PARTITION_PW_Piwnica_ARMED.state == OFF) {
              logInfo("rules.IB","Brama garażowa została otwarta.")
              InfoToRead.sendCommand("Brama garażowa została otwarta.")
            } else {
              logInfo("rules.IB","Brama garażowa została otwarta w trybie czuwania alarmu!")
              InfoToRead.sendCommand("Brama garażowa została otwarta w trybie czuwania alarmu!")
            }
            CCTV_CamFront_Pos2.sendCommand(ON)
            logInfo("KWI.debug.rules","R_DEBUG: tRBG 6 (" + tRBG + ")")
            tRBG.reschedule(now.plusSeconds(4))
            logInfo("KWI.debug.rules","R_DEBUG: tRBG 7 (" + tRBG + ")")
          }
          case 2 : {
            logInfo("KWI.debug.rules","R_DEBUG: tRBG 8 (" + tRBG + ")")
            if(PARTITION_PW_Piwnica_ARMED.state == OFF) {
              sendTelegramPhoto("Karol", "http://192.168.1.100/tmpfs/snap.jpg?usr=admin&pwd=xxxxx", "Brama garażowa została otwarta. - Zdjęcie nr 1 i..." )
              sendTelegramPhoto("Ewelina", "http://192.168.1.100/tmpfs/snap.jpg?usr=admin&pwd=xxxxx", "Brama garażowa została otwarta. - Zdjęcie nr 1 i..." )
            } else {
              sendTelegramPhoto("Karol", "http://192.168.1.100/tmpfs/snap.jpg?usr=admin&pwd=xxxxx", "Brama garażowa została otwarta w trybie czuwania alarmu. - Zdjęcie nr 1 i..." )
              sendTelegramPhoto("Ewelina", "http://192.168.1.100/tmpfs/snap.jpg?usr=admin&pwd=xxxxx", "Brama garażowa została otwarta w trybie czuwania alarmu. - Zdjęcie nr 1 i..." )
            }
            logInfo("KWI.debug.rules","R_DEBUG: tRBG 9 (" + tRBG + ")")
            tRBG.reschedule(now.plusSeconds(2))
            logInfo("KWI.debug.rules","R_DEBUG: tRBG 10 (" + tRBG + ")")
          }
          case 3 : {
            logInfo("KWI.debug.rules","R_DEBUG: tRBG 11 (" + tRBG + ")")
            CCTV_CamFront_Pos1.sendCommand(ON)
            logInfo("KWI.debug.rules","R_DEBUG: tRBG 12 (" + tRBG + ")")
            tRBG.reschedule(now.plusSeconds(3))
            logInfo("KWI.debug.rules","R_DEBUG: tRBG 13 (" + tRBG + ")")
          }
          case 4 : {
            logInfo("KWI.debug.rules","R_DEBUG: tRBG 14 (" + tRBG + ")")
            sendTelegramPhoto("Karol", "http://192.168.1.100/tmpfs/snap.jpg?usr=admin&pwd=xxxxx", "...zdjęcie nr 2." )
            sendTelegramPhoto("Ewelina", "http://192.168.1.100/tmpfs/snap.jpg?usr=admin&pwd=xxxxx", "...zdjęcie nr 2." )
            logInfo("KWI.debug.rules","R_DEBUG: tRBG 15 (" + tRBG + ")")
            tRBG.reschedule(now.plusSeconds(2))
            logInfo("KWI.debug.rules","R_DEBUG: tRBG 16 (" + tRBG + ")")
          }
          case 5 : {
            logInfo("KWI.debug.rules","R_DEBUG: tRBG 17 (" + tRBG + ")")
            CCTV_CamFront_Pos5.sendCommand(ON)
            logInfo("KWI.debug.rules","R_DEBUG: tRBG 18 (" + tRBG + ")")
            tRBG.reschedule(now.plusSeconds(1))
            logInfo("KWI.debug.rules","R_DEBUG: tRBG 19 (" + tRBG + ")")
          }
          default: {
            logInfo("KWI.debug.rules","R_DEBUG: tRBG 20 (" + tRBG + ")")
            tRBG = null
            logInfo("KWI.debug.rules","R_DEBUG: tRBG 21 (" + tRBG + ")")
          }
        }
      ])
    }
end
rule "Gate Closing"
  when
    Item Stan_bramy_garazowej changed to ON
  then
    logInfo("KWI.debug.rules","REGRUN: Ruch bramy garażowej - Zamknięta")
    logInfo("KWI.debug.rules","R_DEBUG: tRBG 22 (" + tRBG + ")")
    tRBG?.cancel
    logInfo("KWI.debug.rules","R_DEBUG: tRBG 23 (" + tRBG + ")")
    Stan_bramy_garazowej_N.sendCommand(OFF)
    Brama_garazowa_LOG.postUpdate(OFF)
    if(PARTITION_PW_Piwnica_ARMED.state == OFF) {
      logInfo("rules.IB","Brama garażowa została zamknięta.")
      InfoToRead.sendCommand("Brama garażowa została zamknięta.")
    } else {
      logInfo("rules.IB","Brama garażowa została zamknięta w trybie czuwania alarmu.")
      InfoToRead.sendCommand("Brama garażowa została zamknięta w trybie czuwania alarmu.")
    }
    SendNotification_Triggr.sendCommand(ON)
    logInfo("KWI.debug.rules","R_DEBUG: tRBG 24 (" + tRBG + ")")
end


rule "Gate Guard - Opening"
  when
    Item Stan_bramy_garazowej changed to OFF
  then
    if(tSOBG === null) {
      logInfo("KWI.debug.rules","R_DEBUG: tSOBG 1 (" + nSOBG + ") (" + tSOBG + ")")
      logInfo("KWI.debug.rules","REGRUN: Strażnik otwartej bramy garażowej")
      nSOBG = 0
      logInfo("KWI.debug.rules","R_DEBUG: tSOBG 2 (" + nSOBG + ") (" + tSOBG + ")")
      lBramaGarazowaTOpened = now
      logInfo("KWI.debug.rules","R_DEBUG: tSOBG 3 (" + nSOBG + ") (" + tSOBG + ")")
      tSOBG = createTimer(now.plusMinutes(20), [|
        logInfo("KWI.debug.rules","R_DEBUG: tSOBG 4 (" + nSOBG + ") (" + tSOBG + ")")
        nSOBG = nSOBG + 1
        logInfo("KWI.debug.rules","R_DEBUG: tSOBG 5 (" + nSOBG + ") (" + tSOBG + ")")
        switch (nSOBG.intValue) {
          case 1 : {
            logInfo("KWI.debug.rules","R_DEBUG: tSOBG 6 (" + nSOBG + ") (" + tSOBG + ")")
            lBramaGarazowaTPassed = Math::round(( now.millis - lBramaGarazowaTOpened.millis ) / 60000).intValue
            logInfo("rules.IB","Gate remain open for " + lBramaGarazowaTPassed.intValue + " minutes!")
            InfoToRead.sendCommand("Gate remain open for " + lBramaGarazowaTPassed.intValue + " minutes!")
            Read_Trigger.sendCommand(ON)
            CCTV_CamFront_Pos1.sendCommand(ON)
            logInfo("KWI.debug.rules","R_DEBUG: tSOBG 7 (" + nSOBG + ") (" + tSOBG + ")")
            tSOBG.reschedule(now.plusSeconds(6))
            logInfo("KWI.debug.rules","R_DEBUG: tSOBG 8 (" + nSOBG + ") (" + tSOBG + ")")
          }
          case 2 : {
            logInfo("KWI.debug.rules","R_DEBUG: tSOBG 9 (" + nSOBG + ") (" + tSOBG + ")")
            sendTelegramPhoto("Karol", "http://192.168.1.100/tmpfs/snap.jpg?usr=admin&pwd=XXXXX", "Gate remain open for " + lBramaGarazowaTPassed.intValue + " minutes!" )
            logInfo("KWI.debug.rules","R_DEBUG: tSOBG 10 (" + nSOBG + ") (" + tSOBG + ")")
            tSOBG.reschedule(now.plusSeconds(2))
            logInfo("KWI.debug.rules","R_DEBUG: tSOBG 11 (" + nSOBG + ") (" + tSOBG + ")")
          }
          case 3 : {
            logInfo("KWI.debug.rules","R_DEBUG: tSOBG 12 (" + nSOBG + ") (" + tSOBG + ")")
            CCTV_CamFront_Pos5.sendCommand(ON)
            nSOBG = 0
            logInfo("KWI.debug.rules","R_DEBUG: tSOBG 13 (" + nSOBG + ") (" + tSOBG + ")")
            tSOBG.reschedule(now.plusMinutes(20))
            logInfo("KWI.debug.rules","R_DEBUG: tSOBG 14 (" + nSOBG + ") (" + tSOBG + ")")
          }
        }
      ])
    }
end
rule "Gate Guard - Closing"
  when
    Item Stan_bramy_garazowej changed to ON
  then
    logInfo("KWI.debug.rules","R_DEBUG: tSOBG 15 (" + nSOBG + ") (" + tSOBG + ")")
    logInfo("rules.IB","Guard: Gate closed.")
    logInfo("KWI.debug.rules","R_DEBUG: tSOBG 16 (" + nSOBG + ") (" + tSOBG + ")")
    tSOBG.cancel
    logInfo("KWI.debug.rules","R_DEBUG: tSOBG 17 (" + nSOBG + ") (" + tSOBG + ")")
    lBramaGarazowaTOpened = null
    logInfo("KWI.debug.rules","R_DEBUG: tSOBG 19 (" + nSOBG + ") (" + tSOBG + ")")
    tSOBG = null
    logInfo("KWI.debug.rules","R_DEBUG: tSOBG 19 (" + nSOBG + ") (" + tSOBG + ")")
end

Question is, that should I cancel timer from “Opening” in “Closing” scenario…

Let’s asume that Gate Guard is running in endles loop and monitor gate status and opening time. Next gate closes and trigger timer cancelation in “Gate Guard - Opening” rule. Lets assume that this rule was somewhere in the middle, executing lines of code, for example reading via TTS gate status info, so:
a. waiting on timer (in one of case’s),
b. or executing lines just before reschedulig it.

What will happen if we cancel that timer then:
a. Timer is canceled and rule is ended, or some of inside lines of code will be yet executed?
b. Rest of lines (to another reschedule?/case?) will be executed?

So finally… Should I or not and when:
a. cancel timer (?.cancel/.cancel/.cancel()),
b. set handle to “null”?
c. how should I exit neverending loop in “Gate Guard”?

Sory if those are stupid questions. I have the impression that I am wandering around. ;-/

rlkoshak · March 29, 2019, 8:58pm

If the Timer lambda is executing it will complete executing to the end of the lambda. If the Timer is rescheduled in the lambda then it will be rescheduled. So you should add a check in the Timer before rescheduling it to make sure that it is appropriate to reschedule the Timer.

Karol · March 30, 2019, 12:27am

So if I have rule that is triggered with some “OFF” state like bellow and it’s running in loop:

rule "Strażnik otwartej bramy wjazdowej - Otwarta"
  when
    Item Stan_bramy_wjazdowej changed to OFF
  then
    if(tSOBW === null) {
      nSOBW = 0
      lBramaWjazdowaTOpened = now
      tSOBW = createTimer(now.plusMinutes(20), [|
        nSOBW = nSOBW + 1
        switch (nSOBW.intValue) {
          case 1 : {
            lBramaWjazdowaTPassed = Math::round(( now.millis - lBramaWjazdowaTOpened.millis ) / 60000).intValue
            tSOBW.reschedule(now.plusSeconds(3))
          }
          case 2 : {
            //Some actions
            tSOBW.reschedule(now.plusSeconds(2))
          }
          case 3 : {
            nSOBW = 0
            tSOBW.reschedule(now.plusMinutes(20))
          }
        }
      ])
    }
end
rule "Strażnik otwartej bramy wjazdowej - Zamknięta"
  when
    Item Stan_bramy_wjazdowej changed to ON
  then
    tSOBW?.cancel
    lBramaWjazdowaTOpened = null
    tSOBW = null
end

and in second part (rule - bellow first one) I’m canceling timer form the first rule, this won’t be enough to stop both rules?
If so… Should I add some new var, and set it to “0” when I want to stop this rules and check its value (for egxamlpe with IF) before each reschedule timer atempt in the firs rule?

rlkoshak · March 30, 2019, 2:09am

It’s important to be clear.

The stuff between the [ | ] in your createTimer is not part of your Rule when it runs. Your first Rule runs everything up to the call to createTimer and then exits.

In 20 minutes, if the Timer doesn’t get cancelled, the stuff between [ | ] executes on its own. This is commonly considered part of the Timer. It is not part of the Rule.

When you call cancel on a Timer, you are not stopping a Rule. You are stopping a Timer.

It’s important to get the nomenclature right because it confuses us when you don’t and you might get bad advice.

As for your question… When your Timer actually executes, it remains executing for perhaps 10 milliseconds, maybe 50. That is 1/100th of a second. So if you happen to have a case where Stan_bramy_wjazdowej changes to ON inside that 1/100th of a second when the Timer happens to be running the code between the lambda than yes, you might have a problem where the second Rule cancels the Timer but the running Timer reschedules it. The chances of this happening are infinitesimally small.

In all other cases, the Timer will be in a “scheduled” state. And any timer in this state can be canceled and when it is canceled, the stuff between the [ | ] will never run (until the Timer is created or rescheduled again).

Karol · March 30, 2019, 10:40am

Thanks for great explanation. So it warka as it should, as I expected to be.

Look at this log and exception (complete rule you have above):

2019-03-30 09:46:28.279 [INFO ] [...] - R_DEBUG: tSOBG 4 (0) (org.eclipse.smarthome.model.script.internal.actions.TimerImpl@3ff9c1e2)	<- Just before this was created/rescheduled timer. nSOBG = 0 so it's first case, beggining of lambda.
2019-03-30 09:46:28.280 [INFO ] [...] - R_DEBUG: tSOBG 5 (1) (org.eclipse.smarthome.model.script.internal.actions.TimerImpl@3ff9c1e2)	<- Next step just before enetering switch/case code.
2019-03-30 09:46:28.281 [INFO ] [...] - R_DEBUG: tSOBG 6 (1) (org.eclipse.smarthome.model.script.internal.actions.TimerImpl@3ff9c1e2)	<- Mark in beggining in Case #1
2019-03-30 09:46:28.282 [INFO ] [...] - R_DEBUG: tSOBG 7 (1) (org.eclipse.smarthome.model.script.internal.actions.TimerImpl@3ff9c1e2)	<- Mark before first reschdule
2019-03-30 09:46:28.283 [INFO ] [...] - R_DEBUG: tSOBG 8 (1) (org.eclipse.smarthome.model.script.internal.actions.TimerImpl@3ff9c1e2)	<- Mark after sending first reschdule
2019-03-30 09:46:28.287 [INFO ] [...] - REGRUN: Funkcja czytająca tekst ze zmiennej
2019-03-30 09:46:28.287 [INFO ] [...] - R_DEBUG: FCTZZv3 1
2019-03-30 09:46:28.290 [INFO ] [...] - R_DEBUG: FCTZZv3 5
2019-03-30 09:46:34.284 [INFO ] [...] - R_DEBUG: FCTZZv3 2
2019-03-30 09:46:34.284 [INFO ] [...] - R_DEBUG: tSOBG 4 (1) (org.eclipse.smarthome.model.script.internal.actions.TimerImpl@3ff9c1e2)	<- Another mark after first reschedule, lambda beginning
2019-03-30 09:46:34.285 [INFO ] [...] - R_DEBUG: tSOBG 5 (2) (org.eclipse.smarthome.model.script.internal.actions.TimerImpl@3ff9c1e2)	<- After inrementation nSOBG = 1, code entering Case #2
2019-03-30 09:46:34.285 [INFO ] [...] - R_DEBUG: tSOBG 9 (2) (org.eclipse.smarthome.model.script.internal.actions.TimerImpl@3ff9c1e2)	<- First mark inside Case #2
2019-03-30 09:46:38.963 [INFO ] [...] - R_DEBUG: FCTZZv3 3

2019-03-30 09:46:40.122 [INFO ] [...] - REGRUN: Brama garazowa - Command								<- Close gate COMMAND was send (it's not Stan_bramy_garazowej state change yet)
2019-03-30 09:46:40.126 [INFO ] [...] - REGRUN: Brama garazowa - Command								<- You can ignore this one (neded for my state logic)
2019-03-30 09:46:45.289 [INFO ] [...] - R_DEBUG: FCTZZv3 4
2019-03-30 09:46:47.615 [INFO ] [...] - REGRUN: Ruch bramy garażowej - Zamknięta
2019-03-30 09:46:47.616 [INFO ] [...] - R_DEBUG: tSOBG 15 (2) (org.eclipse.smarthome.model.script.internal.actions.TimerImpl@3ff9c1e2)	<- Gate closed - changed gate state "Stan_bramy_garazowej" to  ON - 2'nd rule (gate closing, timer canceling) of "Gate Guard"
2019-03-30 09:46:47.616 [INFO ] [...] - R_DEBUG: tRBG 22 (null)
2019-03-30 09:46:47.617 [INFO ] [...] - R_DEBUG: tSOBG 16 (2) (org.eclipse.smarthome.model.script.internal.actions.TimerImpl@3ff9c1e2)	<- Another mark in 2'nd rule just before canceling timer
2019-03-30 09:46:47.618 [INFO ] [...] - R_DEBUG: tRBG 23 (null)
2019-03-30 09:46:47.618 [INFO ] [...] - R_DEBUG: tSOBG 17 (2) (org.eclipse.smarthome.model.script.internal.actions.TimerImpl@3ff9c1e2)	<- After timer canceling, before setting lBramaGarazowaTOpened = null
2019-03-30 09:46:47.620 [INFO ] [...] - R_DEBUG: tRBG 24 (null)
2019-03-30 09:46:47.620 [INFO ] [...] - R_DEBUG: tSOBG 19 (2) (org.eclipse.smarthome.model.script.internal.actions.TimerImpl@3ff9c1e2)	<- Before setting tSOBG = null
2019-03-30 09:46:47.621 [INFO ] [...] - R_DEBUG: tSOBG 20 (2) (null)									<- After setting tSOBG = null (and it is null), end of that rule
2019-03-30 09:46:47.630 [INFO ] [...] - REGRUN: Funkcja czytająca tekst ze zmiennej
2019-03-30 09:46:47.630 [INFO ] [...] - R_DEBUG: FCTZZv3 1
2019-03-30 09:46:47.634 [INFO ] [...] - REGRUN: Funkcja wysyłająca notyfikacje PUSH ze zmiennej
2019-03-30 09:46:47.637 [INFO ] [...] - R_DEBUG: FCTZZv3 5
2019-03-30 09:46:48.543 [INFO ] [...] - R_DEBUG: tSOBG 10 (2) (null)									<- And here weird thing happen... Mark in Case #2
2019-03-30 09:46:48.544 [ERROR] [org.quartz.core.JobRunShell         ] - Job DEFAULT.2019-03-30T09:44:08.221+01:00: Proxy for org.eclipse.xtext.xbase.lib.Procedures$Procedure0: [ | {
  logInfo(<XStringLiteralImpl>,<XBinaryOperationImplCustom>)
  <null>.nSOBG = <XBinaryOperationImplCustom>
  logInfo(<XStringLiteralImpl>,<XBinaryOperationImplCustom>)
  org.eclipse.xtext.xbase.impl.XSwitchExpressionImpl@56833cee
} ] threw an unhandled Exception:
java.lang.NullPointerException: cannot invoke method public abstract boolean org.eclipse.smarthome.model.script.actions.Timer.reschedule(org.joda.time.base.AbstractInstant) on null

Look for this marks:

2019-03-30 09:46:34.285 [INFO ] […] - R_DEBUG: tSOBG 9 (2) (org.eclipse.smarthome.model.script.internal.actions.TimerImpl@3ff9c1e2) <- First mark inside Case #2
2019-03-30 09:46:48.543 [INFO ] […] - R_DEBUG: tSOBG 10 (2) (null) <- And here weird thing happen… Mark in Case #2

12 second passed between them. How it’s possible??

(fragment of rule)

            logInfo("KWI.debug.rules","R_DEBUG: tSOBG 9 (" + nSOBG + ") (" + tSOBG + ")")
            sendTelegramPhoto("Karol", "http://192.168.1.100/tmpfs/snap.jpg?usr=admin&pwd=xxxxx", "Brama garażowa pozostaje otwarta od " + lBramaGarazowaTPassed.intValue + " minut!" )
            sendTelegramPhoto("Ewelina", "http://192.168.1.100/tmpfs/snap.jpg?usr=admin&pwd=xxxxx", "Brama garażowa pozostaje otwarta od " + lBramaGarazowaTPassed.intValue + " minut!" )
            logInfo("KWI.debug.rules","R_DEBUG: tSOBG 10 (" + nSOBG + ") (" + tSOBG + ")")

In meantime tSOBG was set to null, and Voilà.

Bu Whyyyy…?

rossko57 · March 30, 2019, 10:47am

I’ll begin by saying other people use timers without problems.
You have quite complex cascading timers and interactions, the problems here are going to come from us not understanding the interactions properly.
Your ‘big picture’ is a bit too big to hold in the head at one time

I really would not go adding yet more variables here.
If you do have a need to “check up” on a timer, it does have methods to see if it is running or finished.

In your most recent example, if you set the lBramaWjazdowaTOpened to null outside of the timer code, and the timer code is running or will still run for whatever reason, then yes it will break the timer code.

When that kind of thing is likely to happen, you can code defensively. Test to see if’s null before using it.
Or you can change the logic - does that other rule need to set it null? If the timer is cancelled, does it really matter about the variable state?

Karol · March 30, 2019, 12:24pm

If main condition is “tSOBW === null”, then yes, I have to set it in the end no null (I think).

Nothing (non of the rules) is modyfing variables used inside each pair of gates rules (4 rules per gate, each pair have it’s own vars), so no outside modification are made.

As you see in last post, timer wasn’t cancel as it should:

 logInfo("KWI.debug.rules","R_DEBUG: tSOBG 9 (" + nSOBG + ") (" + tSOBG + ")")
            sendTelegramPhoto("Karol", "http://192.168.1.100/tmpfs/snap.jpg?usr=admin&pwd=C2H5CooH", "Brama garażowa pozostaje otwarta od " + lBramaGarazowaTPassed.intValue + " minut!" )

//somewere here timer should be canceled...

            sendTelegramPhoto("Ewelina", "http://192.168.1.100/tmpfs/snap.jpg?usr=admin&pwd=C2H5CooH", "Brama garażowa pozostaje otwarta od " + lBramaGarazowaTPassed.intValue + " minut!" )
            logInfo("KWI.debug.rules","R_DEBUG: tSOBG 10 (" + nSOBG + ") (" + tSOBG + ")")

Am I wright?

rossko57 · March 30, 2019, 1:19pm

I have not done any analysis to see why you think the timer was cancelled between those two lines; but sure, it could happen.

The important part is that timer.cancel does not work like that.
Cancel removes a scheduled future execution. If the timer code block is already running at that moment, it will not stop or abort it.
Indeed, in your case many of paths through the timer code block end up with reshedule. Then the “cancelled” timer will run again later. A zombie timer, if you like.

Or at least, it would unless you had also set the handle to null, which would cause the reshedule to fail in exactly the way we see also.

I think we need a “design review” here. What tasks do to in sequence, which ones depend on earlier actions or calculations, when and how a sequence should be aborted.
After that, we’ll work out how to do it.
Maybe start with this Gate one.

As an example, maybe you want gate opening to start turning a camera, wait for that to happen, then capture a photo.
Do we care if the gate closes before that finishes?
Do we check if camera turn completes, or just allow a fixed time?
There is more than one way to do things.

Karol · March 30, 2019, 3:46pm

Ok. I will decribe my logic, but did you see sequence decriptions on the right 4 post above?

There you can see when timer.cancel occures and that there is some strange delay between two entry near tags (only 2 function are executed between them).

rossko57 · March 30, 2019, 9:47pm

Alright, we talking about this?

After tSOBG 9 LOG, your action is sendTelegramPhoto()
I don’t know how long that takes to execute, but it sounds like a job that will take a while. It has to fetch the photo over http from somewhere else before sending it to telegram.

There is a lot of other stuff going on at the same time, so the photo send is competing for resources.

All the time this is going on - the timer code block is executing.
After tSOBG 9 log, but before tSOBG 10 log, we see tSOBG 15-16 etc.
These come from the “Gate Guard - Closing” rule (someone has opened and closed the gate within 12 seconds, not surprising).

This rule -

cancels the timer - which will have no effect while the timer code is running, doing the telegram.
sets the timer handle and the lBramaGarazowaTPassed variable both to null. That will cause an error the next time the still-running timer code tries to use one or the other of them.

So, yep, there’s the problem. Gate opening starts a long running sequence, gate closing tries to abort it and makes a mess.

We could add more complication to try and make a less messy abort process.

I think a more robust approach is to break up your sequence into simpler tasks and review what is needed, and what is not. Why would you want not to send photo just because the gate has closed? We can obviously avoid trouble if we don’t need to stop that part of the sequence.
Other tasks might really need to be stopped, that’s okay we can do that as smaller job.

Not do everything in one long-running job.

Karol · March 30, 2019, 10:22pm

In described scenario gate was initially open and stays that way from:

2019-03-30 09:43:07.959 [INFO ] [arthome.model.script.KWI.debug.rules] - REGRUN: Brama garazowa - Command
2019-03-30 09:43:07.961 [INFO ] [arthome.model.script.KWI.debug.rules] - REGRUN: Brama garazowa - Command
2019-03-30 09:43:08.175 [INFO ] [arthome.model.script.KWI.debug.rules] - R_DEBUG: FCTZZv3 3
2019-03-30 09:43:08.218 [INFO ] [arthome.model.script.KWI.debug.rules] - REGRUN: Ruch bramy garażowej - Otwarta

Then, after about 3m I closed gate at “2019-03-30 09:46:40.122”, what you can see in log. At this particular moment “Gate Guard - Opening” rule was somewhere about telegram lines. Execution of first photo send proces was triggered at “2019-03-30 09:46:34.285”, and the second photo action was triggered at “2019-03-30 09:46:48.543”.

Why in your opinion “Gate Guard - Closing” rule pauses execution of telegtram?
Why would the execution of the photo send functions of both photographs should take more than a few ms? After all, the execution of each command take place in the background, and their execution lasts several-dozen ms. Rule executes them one after another, not waiting them to end. - Am I right? That’s why we need to use timers?

Karol · March 30, 2019, 11:04pm

I think that in my configuration it’s highly probable that in such moments like this with telegram, I’m running out of some threads. Meybe rules threads or other. I don’t know yet, but lets see what was triggered at the same moment in above scenario (teoreticly - some I could miss, and some could just end earlier - don’t coexist with other from list in some moment):

Rule (1): Gate Guard - Open
Rule (2): TTS via Read_Trigger.sendCommand(ON) - Takes about 10-20s to complete
Command (1): CCTV_CamFront_Pos1
Command (2): sendTelegramPhoto
Rule (3): Gate Guard - Closed
Rule (4): Gate Closed
Rule (5): Gate Commands (its subject was not touched (it does not matter) but it is run at the same time).
Command (3): sendTelegramPhoto
and many others Commands (as I assume) and maybe few Rules…

So teoreticly, before 2’nd telegram there was 5 rules running and probalby over a dozen of commands Ii’m not sure).

Could this situation affect my OH to generate such delays, what in the meantime led to handler set to null and whereby exceptoin was generated?

It’s new issue for me so maybe you could share some knowledge with me:

How to monitor free:

threadpool:thingHandler=3
threadpool:discovery=3
threadpool:safeCall=3
threadpool:RuleEngine=15
and others(?)

To which category are included:

Rules,
Commands,
State updates,
Items refreshes,
etc.

Where and how I could trim those values?

My HW is:

Intel® Core™2 Duo CPU E6550 @ 2.33GHz (4vCPU),
4GB RAM.

System threads usage:

openhab> config:list "(service.pid=org.eclipse.smarthome.threadpool)"
> shell:threads --list |grep "discovery" |wc -l
> shell:threads --list |grep "safeCall" |wc -l
> shell:threads --list |grep "thingHandler" |wc -l
> shell:threads --list |grep "RuleEngine" |wc -l
----------------------------------------------------------------
Pid:            org.eclipse.smarthome.threadpool
BundleLocation: null
Properties:
   discovery = 5
   safeCall = 10
   service.pid = org.eclipse.smarthome.threadpool
   thingHandler = 5
       4      4
      10     10
       5      5
       0      0

rossko57 · March 30, 2019, 11:55pm

Making more threads etc. is a bandage to overcome long running threads. It might change your chances but it is not fixing the error source. Don’t do it, code differently, we’ll help.

I don’t think so. Each line completes before the next line can run.

It takes an understanding of what each line does.
Example
myLight.sendCommand(ON)
This only does what it says, which does lead to confusion.
It puts the command on the openHAB event bus, then ends.
It doesn’t wait for the light to turn on; it doesn’t even wait for the command to arrive at a binding.
So for our rule-writing purposes, it does look like it goes off and does the real work in the background, though the takes just a mS to execute.

Actions like
results = sendHttpGetRequest( "http://zzz.com" )
obviously take some time, and it will not move on to the next line until it’s fetched the remote data - which could take many seconds. You might use the results data in the next line, so it must wait.

sendTelegramPhoto("Ewelina", "http://192.168.1....
comes in the same category but worse.
It must fetch the photo from the (I guess) camera - how long does that take, is the camera busy sometimes? - then push the whole message to the remote telegram service - how often does that make you wait a few seconds, does it throttle your data speed? How many other TCP activities are going on on your machine, does it have to wait for network access?

You can’t do anything about all that, you can’t stop it hogging a thread while it’s happening. We can stop it causing errors, we can break threads into smaller chunks that gives everybody a turn.

Karol · March 31, 2019, 12:10am

Is there some way to run such “heavy” commands like sendTelegram or http get in backgroud?

PS After all, is there a way to change rules threads and safecalls in OH 2.4?

rossko57 · March 31, 2019, 12:15am

An example.
Requirement -
When gate opens, aim camera, allow 3 seconds, send a photo snapshot.
Don’t do this more frequently than every five minutes.


var Timer snapshotTimer = null

rule "snapshots"
when
   Item gate changed to OPEN
then
   camera.sendCommand("positioning")
         // we need to wait 3 secs for that
   if (snapshotTimer === null) {  // don't do it if timer already exists
      snapshotTimer = createTimer( now.plusSeconds(3) , [ |
         sendTelegramPhoto( blah blah )
            // now make an anonymous timer to unblock 
         createTimer( now.plusMinutes(5) , [ |
            snapshotTimer = null
          ] )
          // the snapshotTimer has finished but will stay non-null for 5 minutes
      ] )
   } else {
      logInfo("test", "Gate opened but telegram blocked")
   }
end

Karol · March 31, 2019, 12:29am

But thats another rule running. Too many small rules will consume all rule threads.
And what will happen if camera will not respond in 3s in that case? Will it bo or not the same effect as before?

rossko57 · March 31, 2019, 12:39am

But small rules don’t keep hold of the thread for very long. That little example finishes in a couple of milliseconds. The same work gets done in the end. The point is that you can’t break the timer by setting it to to null in some other rule, because the timer takes care of that by itself.

Well, that’s why I’m asking for your requirement. Is there any way for the camera to tell openHAB to that it’s ready? That would be great; instead of a timer we can trigger a telegram-sending rule from camera-move-complete event.

Karol · March 31, 2019, 12:43am

It could be problem because it’s possible that camera could be out of range sometimes for example.

Karol · March 31, 2019, 1:14am

To organize the acquired knowledge (a little):

Timer can be canceled ONLY when it’s in scheduled state? When it was already executed, lines of code inside him won’t stop running.
When (in my example) code from switch/case #2 clausule (“case 2 :”) is still running (truing to get/send image from camera - connection lost, waiting for timeout), canceling timer will do nothing?
If I will add additional veryfication like “if( !== null) { reschedule…” before reshedule I should avoid this exception…?