Rules and timers not created (?)

The more I add components to my OpenHAB, logic and rules, the more strange things happen inside.

I had some problem with rules and delays inside them that are now resolved. But now I have issues with NOT CREATING TIMER(?).

I had a rule (I noticed issue on this one for now) that normally works, but sometimes it fails to complete. It start running, and when inside it timer is created, it doesn’t.

Rule fragment:

rule "Gate opening"
  when
    Item Stan_bramy_wjazdowej changed to OFF //Opening
  then
    logInfo("KWI.debug.rules","REGRUN: Gate move - Opened")
    if(tRBW === null) {
      logInfo("KWI.debug.rules","R_DEBUG: tRBW 1")
      nRBW = 0
      logInfo("KWI.debug.rules","R_DEBUG: tRBW 2")
      tRBW = createTimer(now, [|
        logInfo("KWI.debug.rules","R_DEBUG: tRBW 3 (" + tRBW + ")")
        nRBW = nRBW + 1
        logInfo("KWI.debug.rules","R_DEBUG: tRBW 4 (" + tRBW + ")")

and log from one of run iterations:

2019-04-05 15:30:18.226 [INFO ] [arthome.model.script.KWI.debug.rules] - REGRUN: Gate move - Opened
2019-04-05 15:30:18.227 [INFO ] [arthome.model.script.KWI.debug.rules] - R_DEBUG: tRBW 1
2019-04-05 15:30:18.229 [INFO ] [arthome.model.script.KWI.debug.rules] - R_DEBUG: tRBW 2
2019-04-05 15:30:18.231 [INFO ] [arthome.model.script.KWI.debug.rules] - R_DEBUG: tRBW 3 (null)
2019-04-05 15:30:18.231 [INFO ] [arthome.model.script.KWI.debug.rules] - R_DEBUG: tRBW 4 (null)
2019-04-05 15:30:18.232 [INFO ] [arthome.model.script.KWI.debug.rules] - R_DEBUG: tRBW 5 (null)
2019-04-05 15:30:18.241 [INFO ] [arthome.model.script.KWI.debug.rules] - R_DEBUG: tRBW 6 (null)

As you can see, in step “R_DEBUG: tRBW 3 (null)” timer should be created already, but it’s still null (to the end of rule run.

Could it be related with free threads? Are timeras dependent from threads?

My thread settings:
openhab> config:list “(service.pid=org.eclipse.smarthome.threadpool)”

shell:threads --list |grep “uleEngine” | wc -l
shell:threads --list |grep “discovery” | wc -l
shell:threads --list |grep “safeCall” | wc -l
shell:threads --list |grep “thingHandler” | wc -l


Pid: org.eclipse.smarthome.threadpool
BundleLocation: null
Properties:
RuleEngine = 15
discovery = 5
safeCall = 10
service.pid = org.eclipse.smarthome.threadpool
thingHandler = 5
6 6
7 7
10 10
6 6

Is this variable defined outside of the rule on top of the rule file? Same question regarding nRBW. can you please post the full rule code.

Yes, all vars ore on the very beginning of rule files.

createTimer is wrong

createTimer(now.plusSeconds(10)

your code
createTimer(now

Your timer end in the same time you create it.

TRBW is a variable that holds a handle, or a pointer, to your timer.

After you have created a timer and stored its handle in the variable, there is nothing to stop some other code setting that variable to null, or to anything else.

That will not stop the timer going off at its sceduled time later.
Of course if the timer code looks at the variable, it will be null or whatever.

The problem lies elsewhere. These processes work for other people. Tracking down your problem amongst many complicated rules, cascading timers, and interacting events will be difficult for you.

Non of other rules operate on that handle in the same time (all actions are logged - non other matching log entries ). Even if… entry “logInfo(“KWI.debug.rules”,“R_DEBUG: tRBW 3 (” + tRBW + “)”)” happens few ms atfter timer creation and should not by null.

Lets assume that the timer threads (there are 2 of them if i’m right) are bussy. What will happen if i’ll try to create another one?

Something did it. Your variable absolutely did not set itself to null.

The likelihood of multiple simultaneous runs of the same code can be difficult to predict, for an example of hard to spot problems.

Put all the rules that you think work on this variable in one file on their own. Show us the whole file, show us the events.log and openhab.log relating to the rule trigger and the later timer execution(s) when you see the error.

Thinking about this, didn’t we conclude earlier that on your relatively powerful box, a timer scheduled for ‘now’ can start executing before it’s handle gets finalised back into the variable?

Why would you need such a timer?

You are right. It’s too powerfull box issue. In meantime I’ve switched debug on and noticed that handle need about 3-5ms to set (to be visible under variable), but in this time code from timer creation to handle null check is being executed fatser. Then the rule is interrupted by my check.

About that timer… This is switching machine, and CASE 1 of it. In this step CCTV camera is geting positioned and it takes time (about 2s). So yes I need that timer. In this case I need to add some thread::sleep for about 10-20ms (just to be sure) after timer creation to be sure that check execution will not overtake handle creation… unless you have other suggestions… :wink:

I have two rules execution examples from past:

Ex.1 - This one “failed” (not been completed):

2019-04-05 18:32:39.555 [INFO ] [arthome.model.script.KWI.debug.rules] - REGRUN: Gate move - Opened
2019-04-05 18:32:39.555 [INFO ] [arthome.model.script.KWI.debug.rules] - R_DEBUG: tRBW 1
2019-04-05 18:32:39.555 [INFO ] [arthome.model.script.KWI.debug.rules] - R_DEBUG: tRBW 2
// Timer and handle creation
2019-04-05 18:32:39.557 [DEBUG] [t.internal.actions.TimerExecutionJob] - Executing timer 'DEFAULT.2019-04-05T18:32:39.556+02:00: Proxy for org.eclipse.xtext.xbase.lib.Procedures$Procedure0: [ | {
  logInfo(<XStringLiteralImpl>,<XBinaryOperationImplCustom>)
  <null>.nRBW = <XBinaryOperationImplCustom>
  logInfo(<XStringLiteralImpl>,<XBinaryOperationImplCustom>)
  org.eclipse.xtext.xbase.impl.XSwitchExpressionImpl@5954b857
} ]'
2019-04-05 18:32:39.557 [INFO ] [arthome.model.script.KWI.debug.rules] - R_DEBUG: tRBW 3 (null)
2019-04-05 18:32:39.557 [INFO ] [arthome.model.script.KWI.debug.rules] - R_DEBUG: tRBW 4 (null)
2019-04-05 18:32:39.558 [INFO ] [arthome.model.script.KWI.debug.rules] - R_DEBUG: tRBW 5 (null)
2019-04-05 18:32:39.559 [INFO ] [arthome.model.script.KWI.debug.rules] - R_DEBUG: tRBW 6 (null)
// null to the end. Bellow I'm interrupting the rule. Handle didn't make it to set.
2019-04-05 18:32:39.559 [INFO ] [arthome.model.script.KWI.debug.rules] - tRBW: Przerwano (1)

Ex.2 - This one passed to the end:

2019-04-05 18:36:35.648 [INFO ] [arthome.model.script.KWI.debug.rules] - REGRUN: Gate move - Opened
2019-04-05 18:36:35.649 [INFO ] [arthome.model.script.KWI.debug.rules] - R_DEBUG: tRBW 1
2019-04-05 18:36:35.649 [INFO ] [arthome.model.script.KWI.debug.rules] - R_DEBUG: tRBW 2
// Timer and handle creation
2019-04-05 18:36:35.651 [DEBUG] [t.internal.actions.TimerExecutionJob] - Executing timer 'DEFAULT.2019-04-05T18:36:35.649+02:00: Proxy for org.eclipse.xtext.xbase.lib.Procedures$Procedure0: [ | {
  logInfo(<XStringLiteralImpl>,<XBinaryOperationImplCustom>)
  <null>.nRBW = <XBinaryOperationImplCustom>
  logInfo(<XStringLiteralImpl>,<XBinaryOperationImplCustom>)
  org.eclipse.xtext.xbase.impl.XSwitchExpressionImpl@5954b857
} ]'
// Handle still null
2019-04-05 18:36:35.651 [INFO ] [arthome.model.script.KWI.debug.rules] - R_DEBUG: tRBW 3 (null)
// Here is set already
2019-04-05 18:36:35.654 [INFO ] [arthome.model.script.KWI.debug.rules] - R_DEBUG: tRBW 4 (org.eclipse.smarthome.model.script.internal.actions.TimerImpl@29896ce1)
2019-04-05 18:36:35.654 [INFO ] [arthome.model.script.KWI.debug.rules] - R_DEBUG: tRBW 5 (org.eclipse.smarthome.model.script.internal.actions.TimerImpl@29896ce1)
2019-04-05 18:36:35.655 [DEBUG] [model.script.actions.ScriptExecution] - Scheduled code for execution at 2019-04-05T18:56:35.654+02:00
2019-04-05 18:36:35.656 [INFO ] [arthome.model.script.KWI.debug.rules] - R_DEBUG: tRBW 6 (org.eclipse.smarthome.model.script.internal.actions.TimerImpl@29896ce1)
// Here null check is running and it passes further to CASE 2, 3 and so on...
2019-04-05 18:36:35.656 [INFO ] [arthome.model.script.KWI.debug.rules] - R_DEBUG: tRBW 7 (org.eclipse.smarthome.model.script.internal.actions.TimerImpl@29896ce1)...

Or simply setup the time to some millis later:

tRBW = createTimer(now.plusMillis(20), [|
// ...
]

I was’t aware of a timing issue, never saw this when using this piece of code. :blush:

I’m unable to reproduce this now/null thing at all, using an old core-duo laptop.

I can see how it might all fall down, createTimer sets everything up and returns a result. The original thread then uses the result to set the handle-variable, but a true multi-threading machine could already be executing the independent timer lambda by now.
If true, it’s only going to show up with (now) as the scheduled time AND early use of the handle within the timer code. I expect you’d need a powerful multi-core environment, not sure about that. Cannot reproduce on my hardware, with or without competing loads.

Yes. So you can issue the camera reposition directly from the “parent” rule, and set up your timer for 2s for the next task. There’s no need for a ‘now’ timer here.

Corrects done. I’ll observe it for some time and let know…

My “to-powerfull-box” is Lenovo ThinkCentre M57 (if I remember correctly). Core 2 Duo E6550 @ 2.33GHz 4GB RAM.

That’s not very different from this old Thinkpad, core 2 duo 2.1GHz, but I cannot reproduce.
Oracle java 8 181