[SOLVED] Yet another problem with a rule stopping (but not all)

[pedrolima]

• Platform information:
  • Hardware: Raspberry Pi 3 Model B
  • OS: Raspbian GNU/Linux 9 (stretch)
  • Java Runtime Environment: OpenJDK Runtime Environment (build 1.8.0_242-8u242-b08-1~deb9u1-b08)
  • openHAB version: 2.5.3-1

With no apparent reason, one specific rule just stop working after some hours while two others continue working without any problem.

val actions = getActions("mqtt","mqtt:systemBroker:embedded-mqtt-broker")
var Timer offTimer = null
val Number hours = now.getHourOfDay

rule "Sensor 433mhz Sonoff Bridge"

when
   Item Sensor433mhz changed or
   Channel "mqtt:systemBroker:embedded-mqtt-broker:MQTT433mhz" triggered
then

   switch Sensor433mhz.state {

      case "79E006": {
         if ((hours > 19 || hours < 3)
             && Luz_Entrada_Frente.state.toString !== "ON") {
            actions.publishMQTT("cmnd/LuzEntradaFrente/POWER", "ON")
            if(Alexa_Boas_Vindas.state == ON) {
               offTimer = createTimer(now.plusSeconds(10), [|
                  if(Sensor433mhz.state.toString == "29E006" || Sensor433mhz.state.toString == "1961E6") {
                     Conta_Alexa.sendCommand(Alexa_Msg_Boas_Vindas.state.toString)
                  }
               ])
            }
            offTimer = createTimer(now.plusSeconds(20), [|
               actions.publishMQTT("cmnd/LuzEntradaFrente/POWER", "OFF")
            ])
         }else if(Alexa_Boas_Vindas.state == ON) {
            offTimer = createTimer(now.plusSeconds(10), [|
               if(Sensor433mhz.state.toString == "29E006" || Sensor433mhz.state.toString == "1961E6") {
                  Conta_Alexa.sendCommand(Alexa_Msg_Boas_Vindas.state.toString)
               }
            ])
         }
      }

      case "7CAC81": {
         Alarme.sendCommand(ON)
      }

      case "7CAC82": {
         Alarme.sendCommand(OFF)
      }
   }

   if(Sensor433mhz.state.toString !== "") {
      offTimer = createTimer(now.plusMinutes(1), [|
         Sensor433mhz.postUpdate("")
      ])
   }

end

Strange thing here is, I only have to get inside rule, save it and BAM, it starts working again.

So this is the events.log BEFORE I hit save:

2020-03-31 21:11:23.135 [vent.ChannelTriggeredEvent] - mqtt:systemBroker:embedded-mqtt-broker:MQTT433mhz triggered {"Time":"2020-03-31T21:11:22","RfReceived":{"Sync":12630,"Low":420,"High":1240,"Data":"79E006","RfKey":"None"}}
2020-03-31 21:11:23.163 [vent.ItemStateChangedEvent] - Sensor433mhz changed from  to 79E006

And this is the events.log AFTER I hit save:

2020-03-31 21:12:56.275 [vent.ChannelTriggeredEvent] - mqtt:systemBroker:embedded-mqtt-broker:MQTT433mhz triggered {"Time":"2020-03-31T21:12:56","RfReceived":{"Sync":12610,"Low":410,"High":1250,"Data":"79E006","RfKey":"None"}}
2020-03-31 21:12:56.297 [vent.ItemStateChangedEvent] - Sensor433mhz changed from  to 79E006
2020-03-31 21:12:58.336 [vent.ItemStateChangedEvent] - Luz_Entrada_Frente changed from OFF to ON

Now, on my openhab.log file I do have some weird things happening after I have hit save on that rule:

2020-03-31 21:12:48.221 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'sensores_433mhz_iluminacao.rules'
2020-03-31 21:13:23.333 [ERROR] [org.quartz.core.JobRunShell         ] - Job DEFAULT.Timer 190 2020-03-31T21:13:23.316+01:00: Proxy for org.eclipse.xtext.xbase.lib.Procedures$Procedure0: [ | {
  <XFeatureCallImplCustom>.postUpdate(<XStringLiteralImpl>)
} ] threw an unhandled Exception: 
java.lang.NullPointerException: null
	at org.eclipse.smarthome.model.script.engine.ScriptError.<init>(ScriptError.java:65) ~[?:?]
	at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.invokeFeature(ScriptInterpreter.java:140) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:991) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:954) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:235) ~[?:?]
	at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:215) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.evaluateArgumentExpressions(XbaseInterpreter.java:1205) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._invokeFeature(XbaseInterpreter.java:1135) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeFeature(XbaseInterpreter.java:1081) ~[?:?]
	at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.invokeFeature(ScriptInterpreter.java:151) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:861) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:231) ~[?:?]
	at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:215) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:458) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:239) ~[?:?]
	at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:215) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.evaluate(XbaseInterpreter.java:201) ~[?:?]
	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.$Proxy218.apply(Unknown Source) ~[?:?]
	at org.eclipse.smarthome.model.script.internal.actions.TimerExecutionJob.execute(TimerExecutionJob.java:48) ~[?:?]
	at org.quartz.core.JobRunShell.run(JobRunShell.java:202) [bundleFile:?]
	at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573) [bundleFile:?]
2020-03-31 21:13:23.395 [ERROR] [org.quartz.core.ErrorLogger         ] - Job (DEFAULT.Timer 190 2020-03-31T21:13:23.316+01:00: Proxy for org.eclipse.xtext.xbase.lib.Procedures$Procedure0: [ | {
  <XFeatureCallImplCustom>.postUpdate(<XStringLiteralImpl>)
} ] threw an exception.
org.quartz.SchedulerException: Job threw an unhandled exception.
	at org.quartz.core.JobRunShell.run(JobRunShell.java:213) [bundleFile:?]
	at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573) [bundleFile:?]
Caused by: java.lang.NullPointerException
	at org.eclipse.smarthome.model.script.engine.ScriptError.<init>(ScriptError.java:65) ~[?:?]
	at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.invokeFeature(ScriptInterpreter.java:140) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:991) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:954) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:235) ~[?:?]
	at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:215) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.evaluateArgumentExpressions(XbaseInterpreter.java:1205) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._invokeFeature(XbaseInterpreter.java:1135) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeFeature(XbaseInterpreter.java:1081) ~[?:?]
	at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.invokeFeature(ScriptInterpreter.java:151) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:861) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:231) ~[?:?]
	at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:215) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:458) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:239) ~[?:?]
	at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:215) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.evaluate(XbaseInterpreter.java:201) ~[?:?]
	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.$Proxy218.apply(Unknown Source) ~[?:?]
	at org.eclipse.smarthome.model.script.internal.actions.TimerExecutionJob.execute(TimerExecutionJob.java:48) ~[?:?]
	at org.quartz.core.JobRunShell.run(JobRunShell.java:202) ~[?:?]
	... 1 more

Any help here will be much appreciated.

Thanks guys!

[rossko57]

@pedrolima

2020-03-31 21:11:23.135 [vent.ChannelTriggeredEvent] - mqtt:systemBroker:embedded-mqtt-broker:MQTT433mhz triggered {"Time":"2020-03-31T21:11:22","RfReceived":{"Sync":12630,"Low":420,"High":1240,"Data":"79E006","RfKey":"None"}} 
2020-03-31 21:11:23.163 [vent.ItemStateChangedEvent] - Sensor433mhz changed from to 79E006

That’s going to trigger your rule twice within a few milliseconds, isn’t it?

As both versions of the rule will be running in parallel, but will be manipulating a common timer, quite frankly I would expect it all to go wrong sometimes.

You could confirm the theory by adding logInfo()'s as first and last lines in your rule.

Standard practice for this kind of thing is to see if the common timer handle is already “in use” before attempting to do things with it.
But given your rapidfire triggering, the usual techniques may not suffice here either.

Why the dual triggering?

@pedrolima

[ERROR] [org.quartz.core.JobRunShell ]

Looks like an orphaned timer, potentially from any timer started by that rule file. Ordinary enough, providing you are expecting a timer to be running (waiting) at the time of your edit/touch.

[SOLVED] Unhandled Exception w/o active rules

That looks like the sort of report you get from orphaned Timers - typically, a long running timer was spawned by a rule, and the rule file was later edited on other business. When the rule file reloads, the context for the waiting timer is destroyed - but the quartz scheduled timer job is not. Maybe hours later, the now “orphaned” timer code executes and usually fails with a NullPointerException because some variable it references no longer exists.

[pedrolima]

First of all, thank you very much!

You are always very fast to answer.

Now, regarding the two triggers. I actually don’t like this and I honestly have though about that already.

In the past I only had this trigger: Item Sensor433mhz changed

And then because I noticed the rule stopped working, I tried adding also this second trigger: Channel “mqtt:systemBroker:embedded-mqtt-broker:MQTT433mhz” triggered

In your oppinion, what’s the best one to keep? What’s the one method I should use that will make it better codding?

If you think I should keep the “Channel” trigger, then how can I get the value that comes from there?

Thanks!

[rossko57]

@pedrolima

I only had this trigger: Item Sensor433mhz changed

Go back to that.

No need to guess if the rule is failing to trigger, add a logInfo() as the first line and find out.

@pedrolima

val Number hours = now.getHourOfDay

What do you think that hours variable contains, when the rule runs? Bearing in mind that line, being outside of any rule, gets evaluated only when the rules file is loaded/touched.
I would have thought you would want to use the value of “now” at the time the rule runs?

[pedrolima]

@rossko57

What do you think that hours variable contains, when the rule runs? Bearing in mind that line, being outside of any rule, gets evaluated only when the rules file is loaded/touched.
I would have thought you would want to use the value of “now” at the time the rule runs?

Hum… so what you are trying to say is that if I place that inside the rule, it will always get the correct “now” time?

I mean, I should be able to get the hours each time the rule runs, so is that your oppinion?

I just tested it right now and it keeps working btw and yes, after I asked you what was the best one I just removed the “channel” trigger and kept only the “item” trigger.

[pedrolima]

Well, it seems that placing thing differently inside code did the trick!

So far it’s working and the code is like so:

rule "Sensor 433mhz Sonoff Bridge"

when
   Item Sensor433mhz changed
then

   val actions = getActions("mqtt","mqtt:systemBroker:embedded-mqtt-broker")
   var Timer offTimer = null
   val Number hours = now.getHourOfDay

   switch Sensor433mhz.state {

      case "79E006": {
         if ((hours > 19 || hours < 3)
             && Luz_Entrada_Frente.state.toString !== "ON") {
            actions.publishMQTT("cmnd/LuzEntradaFrente/POWER", "ON")
            if(Alexa_Boas_Vindas.state == ON) {
               offTimer = createTimer(now.plusSeconds(10), [|
                  if(Sensor433mhz.state.toString == "29E006" || Sensor433mhz.state.toString == "1961E6") {
                     Conta_Alexa.sendCommand(Alexa_Msg_Boas_Vindas.state.toString)
                  }
               ])
            }
            offTimer = createTimer(now.plusSeconds(20), [|
               actions.publishMQTT("cmnd/LuzEntradaFrente/POWER", "OFF")
            ])
         }else if(Alexa_Boas_Vindas.state == ON) {
            offTimer = createTimer(now.plusSeconds(10), [|
               if(Sensor433mhz.state.toString == "29E006" || Sensor433mhz.state.toString == "1961E6") {
                  Conta_Alexa.sendCommand(Alexa_Msg_Boas_Vindas.state.toString)
               }
            ])
         }
      }

      case "7CAC81": {
         Alarme.sendCommand(ON)
      }

      case "7CAC82": {
         Alarme.sendCommand(OFF)
      }
   }

   if(Sensor433mhz.state.toString !== "") {
      offTimer = createTimer(now.plusMinutes(1), [|
         Sensor433mhz.postUpdate("")
      ])
   }

end

If it stops working again I will reopen this.

EDIT: 5 days have passed and the simple solution of passing the 2 “val” and 1 “var” inside “then” simply worked. Thanks a lot for the help @rossko57