[SOLVED] Strange rules behavior (including timers)

Karol · March 26, 2019, 9:21pm

I have that strange error:

...
2019-03-26 21:42:25.656 [INFO ] [arthome.model.script.KWI.debug.rules] - RT: 10
2019-03-26 21:42:25.658 [ERROR] [org.quartz.core.JobRunShell         ] - Job DEFAULT.2019-03-26T21:42:25.656+01:00: Proxy for org.eclipse.xtext.xbase.lib.Procedures$Procedure0: [ | {
  <XFeatureCallImplCustom> += <XNumberLiteralImpl>
  org.eclipse.xtext.xbase.impl.XSwitchExpressionImpl@465f14db
} ] 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
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeOperation(XbaseInterpreter.java:1071) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeOperation(XbaseInterpreter.java:1061) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._invokeFeature(XbaseInterpreter.java:1047) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeFeature(XbaseInterpreter.java:992) ~[?:?]
        at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.invokeFeature(ScriptInterpreter.java:151) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:772) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:220) ~[?:?]
        at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:204) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:447) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:228) ~[?:?]
        at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:204) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:484) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:256) ~[?:?]
        at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:204) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:447) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:228) ~[?:?]
        at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:204) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.evaluate(XbaseInterpreter.java:190) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.ClosureInvocationHandler.doInvoke(ClosureInvocationHandler.java:46) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.AbstractClosureInvocationHandler.invoke(AbstractClosureInvocationHandler.java:29) ~[?:?]
        at com.sun.proxy.$Proxy192.apply(Unknown Source) ~[?:?]
        at org.eclipse.smarthome.model.script.internal.actions.TimerExecutionJob.execute(TimerExecutionJob.java:49) ~[?:?]
        at org.quartz.core.JobRunShell.run(JobRunShell.java:202) [109:org.eclipse.smarthome.core.scheduler:0.10.0.oh240]
        at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573) [109:org.eclipse.smarthome.core.scheduler:0.10.0.oh240]
2019-03-26 21:42:25.673 [ERROR] [org.quartz.core.ErrorLogger         ] - Job (DEFAULT.2019-03-26T21:42:25.656+01:00: Proxy for org.eclipse.xtext.xbase.lib.Procedures$Procedure0: [ | {
  <XFeatureCallImplCustom> += <XNumberLiteralImpl>
  org.eclipse.xtext.xbase.impl.XSwitchExpressionImpl@465f14db
} ] threw an exception.
org.quartz.SchedulerException: Job threw an unhandled exception.
        at org.quartz.core.JobRunShell.run(JobRunShell.java:213) [109:org.eclipse.smarthome.core.scheduler:0.10.0.oh240]
        at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573) [109:org.eclipse.smarthome.core.scheduler:0.10.0.oh240]
Caused by: java.lang.NullPointerException: cannot invoke method public abstract boolean org.eclipse.smarthome.model.script.actions.Timer.reschedule(org.joda.time.base.AbstractInstant) on null
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeOperation(XbaseInterpreter.java:1071) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeOperation(XbaseInterpreter.java:1061) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._invokeFeature(XbaseInterpreter.java:1047) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeFeature(XbaseInterpreter.java:992) ~[?:?]
        at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.invokeFeature(ScriptInterpreter.java:151) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:772) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:220) ~[?:?]
        at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:204) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:447) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:228) ~[?:?]
        at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:204) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:484) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:256) ~[?:?]
        at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:204) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:447) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:228) ~[?:?]
        at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:204) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.evaluate(XbaseInterpreter.java:190) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.ClosureInvocationHandler.doInvoke(ClosureInvocationHandler.java:46) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.AbstractClosureInvocationHandler.invoke(AbstractClosureInvocationHandler.java:29) ~[?:?]
        at com.sun.proxy.$Proxy192.apply(Unknown Source) ~[?:?]
        at org.eclipse.smarthome.model.script.internal.actions.TimerExecutionJob.execute(TimerExecutionJob.java:49) ~[?:?]
        at org.quartz.core.JobRunShell.run(JobRunShell.java:202) ~[?:?]
        ... 1 more
2019-03-26 21:42:27.655 [INFO ] [arthome.model.script.KWI.debug.rules] - RT: 6
...

As far I can see, it occure randomally somewhere between timer reschedule command and createtimer function.

This is fragment of RULE’s code:


//beginning of RULES file>
var Timer tRBW = null
var Number nRBW = 0
var Timer tSOBW = null
var Number nSOBW = 0
...
rule "Ruch bramy wjazdowej"
  when
    Item Stan_bramy_wjazdowej changed
  then
    logInfo("KWI.debug.rules","REGRUN: Ruch bramy wjazdowej")
    if(Stan_bramy_wjazdowej.state == OFF && tRBW === null) {
      //logInfo("rules.IB","START")
      logInfo("KWI.debug.rules","RR: 1")
      nRBW = 0
      logInfo("KWI.debug.rules","RR: 2")
      tRBW = createTimer(now, [|
      logInfo("KWI.debug.rules","RR: 3")
        nRBW += 1
        logInfo("KWI.debug.rules","RR: 4")
        //logInfo("rules.IB","nRBW = {}", nRBW)
        switch (nRBW.intValue) {
          case 1 : {
            logInfo("KWI.debug.rules","RR: 5")
            // Negacja wejścia Stan_bramy_wjazdowej na Stan_bramy_wjazdowej_N (na potrzeby korekty statusu GH)
            Stan_bramy_wjazdowej_N.sendCommand(ON)
            // Wirtualne dla bramy wjazdowej
            Brama_wjazdowa_LOG.postUpdate(ON)
            // Zapalanie oświetlenia drogi gdy jest ciemno
            if(Czujnik_swiatla.state == OFF) {
              logInfo("rules.IB","Oświetlenie drogi zostało włączone (na podstawie stanu czujnika światła i stanu bramy wjazdowej).")
              Oswietlenie_drogi.sendCommand(ON)
            }
            if(PARTITION_PW_Piwnica_ARMED.state == OFF) {
              logInfo("rules.IB","Brama wjazdowa została otwarta.")
              InfoToRead.sendCommand("Brama wjazdowa została otwarta.")
            } else {
              logInfo("rules.IB","Brama wjazdowa została otwarta w trybie czuwania alarmu!")
              InfoToRead.sendCommand("Brama wjazdowa została otwarta w trybie czuwania alarmu!")
            }
            Read_Trigger.sendCommand(ON)
            CCTV_CamFront_Pos5.sendCommand(ON)
            logInfo("KWI.debug.rules","RR: 6")
            tRBW.reschedule(now.plusSeconds(2))
            logInfo("KWI.debug.rules","RR: 7")
          }
          case 2 : {
            logInfo("KWI.debug.rules","RR: 8")
            if(PARTITION_PW_Piwnica_ARMED.state == OFF) {
              sendTelegramPhoto("Karol", "http://192.168.1.100/tmpfs/snap.jpg?usr=admin&pwd=xxxxx", "Brama wjazdowa została otwarta. - Zdjęcie nr 1 i..." )
              sendTelegramPhoto("Ewelina", "http://192.168.1.100/tmpfs/snap.jpg?usr=admin&pwd=xxxxx", "Brama wjazdowa została otwarta. - Zdjęcie nr 1 i..." )
            } else {
              sendTelegramPhoto("Karol", "http://192.168.1.100/tmpfs/snap.jpg?usr=admin&pwd=xxxxx", "Brama wjazdowa 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 wjazdowa została otwarta w trybie czuwania alarmu. - Zdjęcie nr 1 i..." )
            }
            logInfo("KWI.debug.rules","RR: 9")
            tRBW.reschedule(now.plusSeconds(2))
            logInfo("KWI.debug.rules","RR: 10")
          }
          case 3 : {
            logInfo("KWI.debug.rules","RR: 11")
            CCTV_CamFront_Pos4.sendCommand(ON)
            logInfo("KWI.debug.rules","RR: 12")
            tRBW.reschedule(now.plusSeconds(3))
            logInfo("KWI.debug.rules","RR: 13")
          }
          case 4 : {
            logInfo("KWI.debug.rules","RR: 14")
            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","RR: 15")
            tRBW.reschedule(now.plusSeconds(2))
            logInfo("KWI.debug.rules","RR: 16")
          }
          case 5 : {
            logInfo("KWI.debug.rules","RR: 17")
            CCTV_CamFront_Pos5.sendCommand(ON)
            logInfo("KWI.debug.rules","RR: 18")
            tRBW.reschedule(now.plusSeconds(1))
            logInfo("KWI.debug.rules","RR: 19")
          }
          default: {
            logInfo("KWI.debug.rules","RR: 19")
            tRBW = null
            logInfo("KWI.debug.rules","RR: 20")
          }
        }
      ])
    }
    logInfo("KWI.debug.rules","RR: 21")
    if(Stan_bramy_wjazdowej.state == ON) {
      tRBW?.cancel
      // Negacja wejścia Stan_bramy_wjazdowej na Stan_bramy_wjazdowej_N (na potrzeby korekty statusu GH)
      Stan_bramy_wjazdowej_N.sendCommand(OFF)
      // Wirtualne dla bramy wjazdowej
      Brama_wjazdowa_LOG.postUpdate(OFF)
      // Wyłączenie oświetlenia drogi
      if(Oswietlenie_drogi.state == ON) {
        logInfo("rules.IB","Oświetlenie drogi zostało wyłączone (na podstawie stanu czujnika światła i stanu bramy wjazdowej).")
        Oswietlenie_drogi.sendCommand(OFF)
      }
      if(PARTITION_PW_Piwnica_ARMED.state == OFF) {
        logInfo("rules.IB","Brama wjazdowa została zamknięta.")
        InfoToRead.sendCommand("Brama wjazdowa została zamknięta.")
      } else {
        logInfo("rules.IB","Brama wjazdowa została zamknięta w trybie czuwania alarmu!")
        InfoToRead.sendCommand("Brama wjazdowa została zamknięta w trybie czuwania alarmu!")
      }
      Read_Trigger.sendCommand(ON)
      SendNotification_Triggr.sendCommand(ON)
      logInfo("KWI.debug.rules","RR: 22")
    }
end
rule "Brama wjazdowa - Command"
  when
    Item Brama_wjazdowa_LOG received command
  then
    logInfo("KWI.debug.rules","RS: 1")
    logInfo("KWI.debug.rules","REGRUN: Brama wjazdowa - Command")
    if(receivedCommand == ON) Brama_wjazdowa.sendCommand(ON)
    if(receivedCommand == OFF) Brama_wjazdowa_LOG.sendCommand(ON)
    logInfo("KWI.debug.rules","RS: 2")
end
rule "Strażnik otwartej bramy wjazdowej - Otwarta"
  when
    Item Stan_bramy_wjazdowej changed to OFF
  then
    logInfo("KWI.debug.rules","RT: 1")
    if(tSOBW === null) {
      logInfo("KWI.debug.rules","RT: 2")
      logInfo("KWI.debug.rules","REGRUN: Strażnik otwartej bramy wjazdowej")
      //logInfo("rules.IB","Strażnik: Brama wjazdowa została otwarta.")
      logInfo("KWI.debug.rules","RT: 3")
      nSOBW = 0
      logInfo("KWI.debug.rules","RT: 4")
      lBramaWjazdowaTOpened = now
      logInfo("KWI.debug.rules","RT: 5")
      tSOBW = createTimer(now.plusMinutes(1), [|
        logInfo("KWI.debug.rules","RT: 6")
        nSOBW += 1
        logInfo("KWI.debug.rules","RT: 7")
        switch (nSOBW.intValue) {
          case 1 : {
            logInfo("KWI.debug.rules","RT: 8")
//            if(Stan_bramy_wjazdowej.state == ON) {
//              logInfo("rules.IB","Strażnik: Brama wjazdowa została zamknięta.")
//              tSOBW?.cancel
//              tSOBW = null
//              lBramaWjazdowaTOpened = null
//            } else {
              lBramaWjazdowaTPassed = Math::round(( now.millis - lBramaWjazdowaTOpened.millis ) / 60000).intValue
              //logInfo("rules.IB","Strażnik: Brama wjazdowa pozostaje otwarta od " + lBramaWjazdowaTPassed.intValue + " minut!")
              logInfo("rules.IB","Brama wjazdowa pozostaje otwarta od " + lBramaWjazdowaTPassed.intValue + " minut!")
              InfoToRead.sendCommand("Brama wjazdowa pozostaje otwarta od " + lBramaWjazdowaTPassed.intValue + " minut!")
              Read_Trigger.sendCommand(ON)
              //SendNotification_Triggr.sendCommand(ON)
              CCTV_CamFront_Pos4.sendCommand(ON)
              logInfo("KWI.debug.rules","RT: 9")
              tSOBW.reschedule(now.plusSeconds(2))
              logInfo("KWI.debug.rules","RT: 10")
//            }
          }
          case 2 : {
            logInfo("KWI.debug.rules","RT: 11")
            sendTelegramPhoto("Karol", "http://192.168.1.100/tmpfs/snap.jpg?usr=admin&pwd=xxxxx", "Brama wjazdowa pozostaje otwarta od " + lBramaWjazdowaTPassed.intValue + " minut!" )
            sendTelegramPhoto("Ewelina", "http://192.168.1.100/tmpfs/snap.jpg?usr=admin&pwd=xxxxx", "Brama wjazdowa pozostaje otwarta od " + lBramaWjazdowaTPassed.intValue + " minut!" )
            logInfo("KWI.debug.rules","RT: 12")
            tSOBW.reschedule(now.plusSeconds(2))
            logInfo("KWI.debug.rules","RT: 13")
          }
          case 3 : {
            logInfo("KWI.debug.rules","RT: 14")
            CCTV_CamFront_Pos5.sendCommand(ON)
            logInfo("KWI.debug.rules","RT: 15")
            nSOBW = 0
            logInfo("KWI.debug.rules","RT: 16")
            tSOBW.reschedule(now.plusMinutes(1))
            logInfo("KWI.debug.rules","RT: 17")
          }
        }
      ])
    }
    logInfo("KWI.debug.rules","RT: 18")
end
rule "Strażnik otwartej bramy wjazdowej - Zamknięta"
  when
    Item Stan_bramy_wjazdowej changed to ON
  then
  logInfo("KWI.debug.rules","RU: 1")
    logInfo("rules.IB","Strażnik: Brama wjazdowa została zamknięta.")
    logInfo("KWI.debug.rules","RU: 2")
    tSOBW?.cancel
    logInfo("KWI.debug.rules","RU: 4")
    lBramaWjazdowaTOpened = null
    logInfo("KWI.debug.rules","RU: 3")
    tSOBW = null
    logInfo("KWI.debug.rules","RU: 5")
end

I know and I will merge some of those rules into one, but where is the real problem?!

rlkoshak · March 26, 2019, 9:26pm

These logs and the Rules are far to long to look at without How to use code fences.

From what I can tell, there is an error begin thrown from inside a lambda (code between [ | ]).

Karol · March 26, 2019, 9:52pm

Sorry, fences corrected.

About error, any clue where inside lambda?

Strange for me it fact, that error occures randomally.

rlkoshak · March 26, 2019, 10:04pm

No idea. Best bet is to add logging to the beginning and ending of all your lambdas. That will tell you which one. Then you can add logging to find the line that causes it.

Given that Quartz is involved, I’d guess it’s in the body of a Timer which should narrow things down considerably.

The error seems to imply that you are trying to reschedule a Timer that is actually null, but that could be misleading. Lots of different errors can look like that. But it does give you a place to start looking.

Karol · March 26, 2019, 10:10pm

As you can see in code, i’ve added log line after each one line of real code…
Error occures between: RT: 10 - RT: 6 tag, after reschedule, but there is nothing more there.

In error is: " <XFeatureCallImplCustom> += <XNumberLiteralImpl>". Could be related with incrementation in next line?

rossko57 · March 27, 2019, 12:41am

Because you have several timers and rules that may run at any time in parallel, do not be too sure the error is actually associated with the last log entry.

This rule has a potential issue. When it runs, it creates a new timer using the handle tRBW
But there may already be a timer, it does not check.
Any existing timer will be ‘orphaned’ from the handle, meaning you cannot cancel it fr example.
But the orphan timer will still exist and still (try to) run at its scheduled time.

When the orphan does run, it happens to do things like reschedule or set null the handle tRBW.
That now won’t affect the orphan timer, but the more recent one created.
Sometime, it’s going to set tRBW to null, and the next time one or other of the timers tries to reschedule the null handle, it will generate the kind of error that you see.

I cannot tell if that is exactly what happened here, but you get the flaw in your rule?

Karol · March 27, 2019, 2:14pm

Yes, it’s possible that in one time there are multiple (but with different handle) timers running, but it’s not true (I think) that there is possibility tu run multiple tRBW timer because in cde there is:

if(Stan_bramy_wjazdowej.state == OFF &amp;&amp; **tRBW === null**) {

and in last “case” of that rule that timer is set to “null”.

Please correct me if I misunderstood (I hope that is not true)… In 1 instance of openhab it could be 1 timer sunning simultaneously and it does not matter that each rule has its own dedicated timer in my rules?

rossko57 · March 27, 2019, 2:31pm

Okay, as I read it before there was no null check. Looks good now.

You can have as many timers as you like.
They don’t have to have a “handle” variable at all.
A “handle” variable can only point to one timer at a time.
Destroying or changing a handle variable on its own will not stop the timer it used to point to.

That last does remind me, seeing as you have timers that run for minutes:

If you edit and reload a rules file, it creates anew any handle variables.
But any timers that were running before the edit will still be running …

That does cause a lot of “weird” errors during development, and there is no short cut around it.
You just have to understand what is going on.

Karol · March 27, 2019, 2:52pm

Very good point. I think I assumed that reloading rules kill timers. I will check it, but hint me how to change rules and prevent multiplying timers. What should I do after rule modification to prevent this?

PS Lest think for a minute…

I’m opening gate. - Rule is running, timer is started, handle is created.

Scenario 1:
2.1. I’m closing gate. - Timer and handle is destroyed (handles are destroyed?).
2.2 End - clear situation.
…If I’ll modify rule it doesn’t affect current situation.

Scenario 2:
2.2 I’m not closing gate. - Timer and handle still exist and running.
2.3 I’m doing some RULES modification and save them. - New hanldes are created (2 handles coexisting?)…
2.4 …but state of gate is still OPEN, so ther will not be new rule trigger, before opening gate again… oh, I’e just realized that that RULE will triigges because the state is OPEN (it will check actual status)… so probably you are right…
2.5 It will create new handlers and run timer.

What will happend when I’ll try to set it to null or cancel? Which one will be affected?

rossko57 · March 27, 2019, 3:38pm

You can not do it.

createTimer(…)

This timer exists independently of the rule that created it.
You can delete the whole rule file, and the timer will still go off at its scheduled time.

var Timer xx
xx = createTimer( …)

This timer exists independently of the rule that created it.
But you can “talk to it” using the handle xx, as in xx.cancel etc.

var Timer xx
xx = createTimer( …)
xx = null

This timer exists independently of the rule that created it.
Destroying the handle xx does not change the timer, and the timer will still go off at its scheduled time.
There is no way to “recover” the handle, no way to reconnect to the independent timer.

When you edit and reload a rule file, any old variables in it like xx are created brand new. Effectively destroying any old handles.

There is no short cut around it.
The only way to kill every timer is to stop and reboot openHAB.

You just have to understand what is going on.
If you have a timer that runs for two hours, when you see a weird timer-related error you have to think “Did I edit that file an hour ago? Might that timer have started an hour before that?”

In normal use, you’re not editing rules and this is not a problem.
Do you think this might explain the errors you got?

Karol · March 28, 2019, 12:20am

It’s strongly possible.
It’s hard to restart OH every time when you change rules, what is most often performed when you rewiting all you logic from (lest say) “other infrastructure”. Changes in config filles goest constantly on and on…
I will pause “development”, reboot OH, observe it for some time and let you know…

rossko57 · March 28, 2019, 12:37am

But these timers are all over after a few minutes, aren’t they? You could just wait them out or ignore “quartz” type errors during the period after an edit.

Karol · March 28, 2019, 12:39am

Still I have some errors but this time they was not tagged, so they are results of some different part of code. Searching for “+=” string I found section that Was not secured by " === null" check and just corrected it. Another restart and we will see…

PS Are rules/timers like below secured for that kind of errors?

    createTimer(now.plusSeconds(60), [|
      Light_Cloud_1_0.sendCommand(OFF)
    ])

rossko57 · March 28, 2019, 12:46am

An anonymous timer like that will continue to run. The problem is not that editing/reloading breaks the timer, it’s that the context, the linking, of any variables in the timer is usually destroyed. Such as the handles or increments in your other timers, they’ll all appear null.

Your simple example would I expect work as planned, since it refers only to an Item that doesn’t get messed up by rules reloads.
You might not be expecting the lights to go off, of course

Karol · March 28, 2019, 8:06am

I’m still fighting with errors… Doing some RULES modifications:

separating complex rules where state ON/OFF is processed inside rule, to two rules,
adding debuging info into all timers (i’m not sure which rule throw exception now (some other than before))…

and in meantime I have some other teoretical questions:

Will something bad happen when timer in some part of rule will end before functions inside that timer have a chance to end?

Example (in “case 1” - the “foreach” loop will not end in 1s):

...
rule "Reading text from var"
  when
	  Item Read_Trigger changed to ON
  then
    if(tFCTZZ === null) {
      nFCTZZ = 0
      tFCTZZ = createTimer(now, [|
        nFCTZZ += 1
        switch (nFCTZZ.intValue) {
          case 1 : {
            Group_Speaker_AllSpeakers.allMembers.forEach [item |
              item.sendCommand(60)
              //item.sendCommand(30)
            ]
            tFCTZZ.reschedule(now.plusSeconds(1))
          }
          case 2 : {
          ...

Is it ok to create timer in timer?

rule "Set alarm"
  when
    Item PARTITION_Piwnica_ARMED changed
  then
    createTimer(now.plusSeconds(2), [|
      if(PARTITION_Piwnica_ARMED.state == ON && PARTITION_P1_ARMED.state == ON) {
        WasLastAlarmArmFullMode.sendCommand(ON)
        InfoToRead.sendCommand("Włączono czuwanie systemu alarmowego w trybie pełnym.")
        SendNotification_Triggr.sendCommand(ON)
        createTimer(now.plusSeconds(2), [|
          ESP_PScreen_UP.sendCommand(ON)
          Zawor_gl_wody.sendCommand(OFF)
        ])
      }
<some_more_code>
      }
    ])
end

When something will go wrong inside rule/timer (timer covering the whole rule), will that rule be processed to the end? I’m asking because in last “case” in that rule I’m setting handle to null, and when exception occures, it’s in fact set to null as it suppose. That implicates fact, that when system will try to trigger that rule again, it will not trigger again (handle not null).
That push me to next question (related with question 2)… What about triggering rule inside rule when both rules have times inside (im setting switch to ON which trgger next rule (reading text, sending info, etc.))?

rossko57 · March 28, 2019, 11:10am

Don’t understand what you mean.
It’s quite normal to “trigger” something from inside a timer that goes away and does it’s own thing.
item.sendCommand would be a good example of that.

Look at timers as independent things, rules spawn them but they don’t live inside the rule.
A rule creates a timer, and immediately moves on. It doesn’t matter when the timer is due or how long it will take.
Likewise, by the moment a timer executes the rule that spawned it is most likely finished long ago.

Yes it will, unless you have thousands of group members.
The sendCommands don’t wait for a response, they just each go away and do their thing, asynchronously.

But let’s suppose you put in something that does take 2s, and afterwards reschedule the timer for 1s later. The timer will go off when it’s supposed to, do the 2s thing, then reschedule for 1s after that. No problem.

You could probably make weird things happen by rescheduling for 1s and then doing the 2s task, but that’s just dumb. In principle, you’d have two copies of the same timer code running at the same time.

Yep. Search this forum for “cascading timers”.

When things break, they stop running.
If the rule rule errors before or after it creates a timer, you won’t or will get the timer. The timer doesn’t care if the rule that spawned it finishes without error or not.
If a timer execution block has an error, the rule that spawned it is long ago finished, cannot know, and would not care if it did.

Don’t fully understand.
Remember, rules spawn or spin-off timers that do their thing independently.
Rules do not wait when they create a timer; spawn it and move on immediately.
openHAB is multi-threaded, you can have several rules (or timer blocks) running at the same moment at various stages.

If you do something that triggers another rule, it triggers another rule. You should expect that rule might start immediately. Or the system might be busy, and it’ll have to queue for a while and start shortly.
Asynchronous processing.

rossko57 · March 28, 2019, 11:17am

You mean, last case in that timer?
Yes, if the timer code errors before it gets to setting x=null, obviously the setting null does not happen.
If a rule checks for x==null before doing blah, blah will never happen again.
Errors stop things working properly.

Karol · March 28, 2019, 11:43am

Thanks for answer… I’m still looking…

I’ve disabled some of rules to simplify the analysis. Now there is only one rule with timer for my Gate. Rule has throw an exception again and I see something strange:

Once again rule:

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

Made for test Gate open/close sequence (sequence was short, because i managed to catch exception already on beginning of test):

OH restart.
Gate opening.

Log file below…

2019-03-28 11:57:20.281 [INFO ] [arthome.model.script.KWI.debug.rules] - REGRUN: Brama garazowa - Command
2019-03-28 11:57:22.669 [INFO ] [arthome.model.script.KWI.debug.rules] - REGRUN: Brama garazowa - Command
2019-03-28 11:57:22.677 [INFO ] [arthome.model.script.KWI.debug.rules] - REGRUN: Brama garazowa - Command
2019-03-28 11:57:32.158 [INFO ] [arthome.model.script.KWI.debug.rules] - REGRUN: Ruch bramy garażowej - Otwarta
2019-03-28 11:57:32.161 [INFO ] [arthome.model.script.KWI.debug.rules] - R_DEBUG: tRBG 1 (null)
2019-03-28 11:57:32.162 [INFO ] [arthome.model.script.KWI.debug.rules] - R_DEBUG: tRBG 2 (null)
2019-03-28 11:57:32.165 [INFO ] [arthome.model.script.KWI.debug.rules] - R_DEBUG: tRBG 3 (null)
2019-03-28 11:57:32.167 [INFO ] [arthome.model.script.KWI.debug.rules] - R_DEBUG: tRBG 4 (null)
2019-03-28 11:57:32.168 [INFO ] [arthome.model.script.KWI.debug.rules] - R_DEBUG: tRBG 5 (null)
2019-03-28 11:57:32.171 [INFO ] [arthome.model.script.KWI.debug.rules] - R_DEBUG: tRBG 6 (null)
2019-03-28 11:57:32.176 [ERROR] [org.quartz.core.JobRunShell         ] - Job DEFAULT.2019-03-28T11:57:32.163+01:00: Proxy for org.eclipse.xtext.xbase.lib.Procedures$Procedure0: [ | {
  logInfo(<XStringLiteralImpl>,<XBinaryOperationImplCustom>)
  <XFeatureCallImplCustom> += <XNumberLiteralImpl>
  logInfo(<XStringLiteralImpl>,<XBinaryOperationImplCustom>)
  org.eclipse.xtext.xbase.impl.XSwitchExpressionImpl@4ffbb13b
} ] 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
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeOperation(XbaseInterpreter.java:1071) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeOperation(XbaseInterpreter.java:1061) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._invokeFeature(XbaseInterpreter.java:1047) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeFeature(XbaseInterpreter.java:992) ~[?:?]
        at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.invokeFeature(ScriptInterpreter.java:151) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:772) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:220) ~[?:?]
        at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:204) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:447) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:228) ~[?:?]
        at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:204) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:484) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:256) ~[?:?]
        at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:204) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:447) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:228) ~[?:?]
        at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:204) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.evaluate(XbaseInterpreter.java:190) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.ClosureInvocationHandler.doInvoke(ClosureInvocationHandler.java:46) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.AbstractClosureInvocationHandler.invoke(AbstractClosureInvocationHandler.java:29) ~[?:?]
        at com.sun.proxy.$Proxy189.apply(Unknown Source) ~[?:?]
        at org.eclipse.smarthome.model.script.internal.actions.TimerExecutionJob.execute(TimerExecutionJob.java:49) ~[?:?]
        at org.quartz.core.JobRunShell.run(JobRunShell.java:202) [109:org.eclipse.smarthome.core.scheduler:0.10.0.oh240]
        at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573) [109:org.eclipse.smarthome.core.scheduler:0.10.0.oh240]
2019-03-28 11:57:32.214 [ERROR] [org.quartz.core.ErrorLogger         ] - Job (DEFAULT.2019-03-28T11:57:32.163+01:00: Proxy for org.eclipse.xtext.xbase.lib.Procedures$Procedure0: [ | {
  logInfo(<XStringLiteralImpl>,<XBinaryOperationImplCustom>)
  <XFeatureCallImplCustom> += <XNumberLiteralImpl>
  logInfo(<XStringLiteralImpl>,<XBinaryOperationImplCustom>)
  org.eclipse.xtext.xbase.impl.XSwitchExpressionImpl@4ffbb13b
} ] threw an exception.
org.quartz.SchedulerException: Job threw an unhandled exception.
        at org.quartz.core.JobRunShell.run(JobRunShell.java:213) [109:org.eclipse.smarthome.core.scheduler:0.10.0.oh240]
        at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573) [109:org.eclipse.smarthome.core.scheduler:0.10.0.oh240]
Caused by: java.lang.NullPointerException: cannot invoke method public abstract boolean org.eclipse.smarthome.model.script.actions.Timer.reschedule(org.joda.time.base.AbstractInstant) on null
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeOperation(XbaseInterpreter.java:1071) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeOperation(XbaseInterpreter.java:1061) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._invokeFeature(XbaseInterpreter.java:1047) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeFeature(XbaseInterpreter.java:992) ~[?:?]
        at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.invokeFeature(ScriptInterpreter.java:151) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:772) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:220) ~[?:?]
        at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:204) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:447) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:228) ~[?:?]
        at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:204) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:484) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:256) ~[?:?]
        at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:204) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:447) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:228) ~[?:?]
        at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:204) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.evaluate(XbaseInterpreter.java:190) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.ClosureInvocationHandler.doInvoke(ClosureInvocationHandler.java:46) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.AbstractClosureInvocationHandler.invoke(AbstractClosureInvocationHandler.java:29) ~[?:?]
        at com.sun.proxy.$Proxy189.apply(Unknown Source) ~[?:?]
        at org.eclipse.smarthome.model.script.internal.actions.TimerExecutionJob.execute(TimerExecutionJob.java:49) ~[?:?]
        at org.quartz.core.JobRunShell.run(JobRunShell.java:202) ~[?:?]
        ... 1 more

Notice handler value in step tagged “tRBG 3” (after timer creation). Shuldn’t it be something like:

2019-03-28 11:50:10.665 [INFO ] [arthome.model.script.KWI.debug.rules] - R_DEBUG: tRBG 1 (null)
2019-03-28 11:50:10.666 [INFO ] [arthome.model.script.KWI.debug.rules] - R_DEBUG: tRBG 2 (null)
2019-03-28 11:50:10.668 [INFO ] [arthome.model.script.KWI.debug.rules] - R_DEBUG: tRBG 3 (org.eclipse.smarthome.model.script.internal.actions.TimerImpl@74404300)
2019-03-28 11:50:10.669 [INFO ] [arthome.model.script.KWI.debug.rules] - R_DEBUG: tRBG 4 (org.eclipse.smarthome.model.script.internal.actions.TimerImpl@74404300)
2019-03-28 11:50:10.670 [INFO ] [arthome.model.script.KWI.debug.rules] - R_DEBUG: tRBG 5 (org.eclipse.smarthome.model.script.internal.actions.TimerImpl@74404300)

Once rule is acting like above, and other time like below. Why?

rossko57 · March 28, 2019, 12:13pm

I don’t know what a handle to a timer is supposed to look like, fearsome gobbledygook most likely.

.toString is a useful method for getting visible in logs?

logInfo("KWI.debug.rules","R_DEBUG: tRBG 5 (" + tRBG.toString + ")")

To be clear, tRBG and nRBG are defined as global vars at the head of your rules file? They must be global for the timer code to access them.

   tRBG.reschedule(now.plusSeconds(4))
   logInfo("KWI.debug.rules","R_DEBUG: tRBG 7 (" + tRBG + ")")
}

I’m beginning to get suspicious about rescheduling a timer that is still executing i.e. not having the reschedule as the last task.
Or maybe because it is inside a code block {} (switch-case here).
You’ve had this working in some form though, haven’t you?

Karol · March 28, 2019, 12:42pm

Everything was working when there was no timers in rule files, but Thread::sleep only instead (I know, I know…that was reason why I decided to rewrite all rules to timers, but as you can see, in functionality that is kind of regresion for me now).

PS And yes, vars are defined on the very beginning of that rules file.