RuleEngine hangs in endless-loop / deadlock when using multiple rules

[Dominic Lerbs]

Hi,

I am having some very strange issues with openHAB on a RaspberryPi 2.
I am using the latest build of openHAB 1.7.0.

Short description:
The RuleEngine seems to seems to hang in some endless-loop / deadlock situation when executing a rule for the first time. Further rules are not executed anymore.

Long description:

I have the following rules (Note that I already stripped down the rules to the bare minimum with which the problem still occurs):
lighting.rules

import org.openhab.core.library.types.*
import org.openhab.core.persistence.*
import org.openhab.model.script.actions.*

import org.joda.time.*

var Timer timer
var LocalTime lateEveningStart = new LocalTime(22, 00)
var LocalTime nightStart = new LocalTime(00, 00)
var LocalTime nightEnd = new LocalTime(6, 00)
var LocalTime dayStart = new LocalTime(8, 00)
var LocalTime dayEnd = new LocalTime(20, 00)

rule "Switch on corridor light"
when
    Item Aeon_CO_Motion changed to ON
then
    logInfo("Lighting.rules", "Executing switch on of corridor lights")
end



rule "Switch off corridor light"
when
    Item Aeon_CO_Motion changed to OFF
then
    logInfo("Lighting.rules", "Executing switch off of corridor lights")
end

mail.rules

import org.openhab.core.library.types.*
import org.openhab.core.persistence.*
import org.openhab.model.script.actions.*

import org.joda.time.*

var DateTime lastMailTime

rule "Send mail when humidity is too high"
when
    Item Aeon_CO_Humidity changed
then
    logInfo("Mail.rules", "Humidity changed to " + Aeon_CO_Humidity.state)
end

weather.rules

import org.openhab.core.library.types.*
import org.openhab.core.persistence.*
import org.openhab.model.script.actions.*

rule "Update max and min temperatures"
when
    Item Weather_Temperature changed or
    Time cron "0 0 0 * * ?"
then
    logInfo("Weather","Temperature changed from " + Weather_Temperature.historicState(now.minusMinutes(2)) + " to " + Weather_Temperature.state + " degrees.")
end

When I trigger the Aeon_CO_Motion Switch after a fresh restart, I can observe two situations. In 10% it works as expected and the rule gets executed. In the other 90%, however, the RuleEngine tries to execute rule lighting.rules, but it seems to hang forever while processing the "var LocalTime lateEveningStart = new LocalTime(22, 00)" line of the rule file (the rule is never executed).

In order to get more debug information, I have added the following outputs to RuleContextHelper:

IEvaluationContext evaluationContext = contextProvider.get();
logger.info("RuleModel for rule {} has {} variables",rule.getName(), ruleModel.getVariables());
for(XExpression expr : ruleModel.getVariables()) {
  logger.info("Expression is class {}",expr.getClass().toString());
  if (expr instanceof XVariableDeclaration) {
    XVariableDeclaration var = (XVariableDeclaration) expr;
    try {
      logger.info("Get right side of variable {}", var.getName());
      XExpression rightVar = var.getRight();
      logger.info("Creating script from XExpression");
      Script script = scriptEngine.newScriptFromXExpression(rightVar);
      logger.info("Executing script");
        Object initialValue = rightVar==null ? null : script.execute();
        logger.info("Variable '{}' on rule file '{}' is initialized with value '{}'",
          new Object[] { var.getName(), ruleModel.eResource().getURI().path(), initialValue });
        QualifiedName qualifiedName = QualifiedName.create(var.getName());
        logger.info("Created qualified name for rule variable {}: {}", var.getName(), qualifiedName);
      evaluationContext.newValue(qualifiedName, initialValue);
      logger.info("Value {} for variable {} added to EvaluationContext {}", initialValue, qualifiedName, evaluationContext);
     
    } catch (ScriptExecutionException e) {
      logger.warn("Variable '{}' on rule file '{}' cannot be initialized with value '{}': {}",
          new String[] { var.getName(), ruleModel.eResource().getURI().path(), var.getRight().toString(), e.getMessage() });
    }
  }
}

Log if rule is not executed:

2015-05-23 20:23:04.331 [INFO ] [runtime.busevents             ] - Aeon_CO_Motion received command ON
2015-05-23 20:23:04.340 [DEBUG] [m.r.internal.engine.RuleEngine] - handleEvent() called
2015-05-23 20:23:04.342 [DEBUG] [m.r.internal.engine.RuleEngine] - receiveCommand() called for item Aeon_CO_Motion and command ON
2015-05-23 20:23:04.375 [DEBUG] [m.r.internal.engine.RuleEngine] - stateChanged() called for item Aeon_CO_Motion
2015-05-23 20:23:04.383 [DEBUG] [m.r.internal.engine.RuleEngine] - Executing rule 'Switch on corridor light'
2015-05-23 20:23:04.385 [DEBUG] [o.u.i.items.ItemUIRegistryImpl] - Cannot retrieve item null for widget org.openhab.model.sitemap.Frame
2015-05-23 20:23:04.387 [INFO ] [m.r.i.engine.RuleContextHelper] - RuleContextHelper: GetContext()
2015-05-23 20:23:04.389 [INFO ] [m.r.i.engine.RuleContextHelper] - RuleModel for rule Switch on corridor light has [org.eclipse.xtext.xbase.impl.XVariableDeclarationImplCustom@760878 (name: timer, writeable: true), org.eclipse.xtext.xbase.impl.XVariableDeclarationImplCustom@1ac10e (name: lateEveningStart, writeable: true), org.eclipse.xtext.xbase.impl.XVariableDeclarationImplCustom@1cf2330 (name: nightStart, writeable: true), org.eclipse.xtext.xbase.impl.XVariableDeclarationImplCustom@422d1e (name: nightEnd, writeable: true), org.eclipse.xtext.xbase.impl.XVariableDeclarationImplCustom@1729169 (name: dayStart, writeable: true), org.eclipse.xtext.xbase.impl.XVariableDeclarationImplCustom@2db14e (name: dayEnd, writeable: true)] variables
2015-05-23 20:23:04.391 [INFO ] [m.r.i.engine.RuleContextHelper] - Expression is class class org.eclipse.xtext.xbase.impl.XVariableDeclarationImplCustom
2015-05-23 20:23:04.393 [INFO ] [m.r.i.engine.RuleContextHelper] - Get right side of variable timer
2015-05-23 20:23:04.394 [INFO ] [m.r.i.engine.RuleContextHelper] - Creating script from XExpression
2015-05-23 20:23:04.400 [INFO ] [m.r.i.engine.RuleContextHelper] - Executing script
2015-05-23 20:23:04.402 [INFO ] [m.r.i.engine.RuleContextHelper] - Variable 'timer' on rule file 'lighting.rules' is initialized with value 'null'
2015-05-23 20:23:04.404 [INFO ] [m.r.i.engine.RuleContextHelper] - Created qualified name for rule variable timer: timer
2015-05-23 20:23:04.407 [INFO ] [m.r.i.engine.RuleContextHelper] - Value null for variable timer added to EvaluationContext org.eclipse.xtext.xbase.int           erpreter.impl.DefaultEvaluationContext@17228a0
2015-05-23 20:23:04.409 [INFO ] [m.r.i.engine.RuleContextHelper] - Expression is class class org.eclipse.xtext.xbase.impl.XVariableDeclarationImplCustom
2015-05-23 20:23:04.410 [INFO ] [m.r.i.engine.RuleContextHelper] - Get right side of variable lateEveningStart
2015-05-23 20:23:04.411 [INFO ] [m.r.i.engine.RuleContextHelper] - Creating script from XExpression
2015-05-23 20:23:04.416 [INFO ] [m.r.i.engine.RuleContextHelper] - Executing script
2015-05-23 20:23:04.436 [DEBUG] [.io.net.http.SecureHttpContext] - security is disabled - processing aborted!
2015-05-23 20:23:04.438 [DEBUG] [.o.u.w.i.servlet.WebAppServlet] - Servlet request received!
2015-05-23 20:23:04.439 [DEBUG] [.o.u.w.i.servlet.WebAppServlet] - reading sitemap home
2015-05-23 20:23:13.938 [DEBUG] [.o.m.c.i.folder.FolderObserver] - Refreshing folder 'sitemaps'
2015-05-23 20:23:13.941 [DEBUG] [.o.m.c.i.folder.FolderObserver] - Refreshing folder 'persistence'
2015-05-23 20:23:13.943 [DEBUG] [.o.m.c.i.folder.FolderObserver] - Refreshing folder 'rules'

Log if rule is executed:

2015-05-23 20:20:51.449 [INFO ] [runtime.busevents             ] - Aeon_CO_Motion received command ON
2015-05-23 20:20:51.451 [DEBUG] [m.r.internal.engine.RuleEngine] - handleEvent() called
2015-05-23 20:20:51.453 [DEBUG] [m.r.internal.engine.RuleEngine] - receiveCommand() called for item Aeon_CO_Motion and command ON
2015-05-23 20:20:51.482 [DEBUG] [m.r.internal.engine.RuleEngine] - stateChanged() called for item Aeon_CO_Motion
2015-05-23 20:20:51.491 [DEBUG] [m.r.internal.engine.RuleEngine] - Executing rule 'Switch on corridor light'
2015-05-23 20:20:51.492 [INFO ] [m.r.i.engine.RuleContextHelper] - RuleContextHelper: GetContext()
2015-05-23 20:20:51.494 [INFO ] [m.r.i.engine.RuleContextHelper] - RuleModel for rule Switch on corridor light has [org.eclipse.xtext.xbase.impl.XVariableDeclarationImplCustom@4da415 (name: timer, writeable: true), org.eclipse.xtext.xbase.impl.XVariableDeclarationImplCustom@afcb82 (name: lateEveningStart, writeable: true), org.eclipse.xtext.xbase.impl.XVariableDeclarationImplCustom@19d79ae (name: nightStart, writeable: true), org.eclipse.xtext.xbase.impl.XVariableDeclarationImplCustom@df76da (name: nightEnd, writeable: true), org.eclipse.xtext.xbase.impl.XVariableDeclarationImplCustom@1ce647d (name: dayStart, writeable: true), org.eclipse.xtext.xbase.impl.XVariableDeclarationImplCustom@1aa3f4c (name: dayEnd, writeable: true)] variables
2015-05-23 20:20:51.495 [INFO ] [m.r.i.engine.RuleContextHelper] - Expression is class class org.eclipse.xtext.xbase.impl.XVariableDeclarationImplCustom
2015-05-23 20:20:51.496 [INFO ] [m.r.i.engine.RuleContextHelper] - Get right side of variable timer
2015-05-23 20:20:51.497 [INFO ] [m.r.i.engine.RuleContextHelper] - Creating script from XExpression
2015-05-23 20:20:51.509 [INFO ] [m.r.i.engine.RuleContextHelper] - Executing script
2015-05-23 20:20:51.510 [INFO ] [m.r.i.engine.RuleContextHelper] - Variable 'timer' on rule file 'lighting.rules' is initialized with value 'null'
2015-05-23 20:20:51.511 [INFO ] [m.r.i.engine.RuleContextHelper] - Created qualified name for rule variable timer: timer
2015-05-23 20:20:51.512 [INFO ] [m.r.i.engine.RuleContextHelper] - Value null for variable timer added to EvaluationContext org.eclipse.xtext.xbase.interpreter.impl.DefaultEvaluationContext@efe28b
2015-05-23 20:20:51.512 [INFO ] [m.r.i.engine.RuleContextHelper] - Expression is class class org.eclipse.xtext.xbase.impl.XVariableDeclarationImplCustom
2015-05-23 20:20:51.513 [INFO ] [m.r.i.engine.RuleContextHelper] - Get right side of variable lateEveningStart
2015-05-23 20:20:51.513 [INFO ] [m.r.i.engine.RuleContextHelper] - Creating script from XExpression
2015-05-23 20:20:51.516 [INFO ] [m.r.i.engine.RuleContextHelper] - Executing script
2015-05-23 20:20:51.939 [DEBUG] [.io.net.http.SecureHttpContext] - security is disabled - processing aborted!
2015-05-23 20:20:51.940 [DEBUG] [.o.u.w.i.servlet.WebAppServlet] - Servlet request received!
2015-05-23 20:20:51.942 [DEBUG] [.o.u.w.i.servlet.WebAppServlet] - reading sitemap home
2015-05-23 20:20:51.989 [INFO ] [m.r.i.engine.RuleContextHelper] - Variable 'lateEveningStart' on rule file 'lighting.rules' is initialized with value '22:00:00.000'
2015-05-23 20:20:51.990 [INFO ] [m.r.i.engine.RuleContextHelper] - Created qualified name for rule variable lateEveningStart: lateEveningStart
2015-05-23 20:20:51.996 [INFO ] [m.r.i.engine.RuleContextHelper] - Value 22:00:00.000 for variable lateEveningStart added to EvaluationContext org.eclipse.xtext.xbase.interpreter.impl.DefaultEvaluationContext@efe28b
2015-05-23 20:20:51.996 [INFO ] [m.r.i.engine.RuleContextHelper] - Expression is class class org.eclipse.xtext.xbase.impl.XVariableDeclarationImplCustom
2015-05-23 20:20:51.997 [INFO ] [m.r.i.engine.RuleContextHelper] - Get right side of variable nightStart
2015-05-23 20:20:51.998 [INFO ] [m.r.i.engine.RuleContextHelper] - Creating script from XExpression
2015-05-23 20:20:52.002 [INFO ] [m.r.i.engine.RuleContextHelper] - Executing script
2015-05-23 20:20:52.156 [INFO ] [m.r.i.engine.RuleContextHelper] - Variable 'nightStart' on rule file 'lighting.rules' is initialized with value '00:00:00.000'
2015-05-23 20:20:52.157 [INFO ] [m.r.i.engine.RuleContextHelper] - Created qualified name for rule variable nightStart: nightStart
2015-05-23 20:20:52.158 [INFO ] [m.r.i.engine.RuleContextHelper] - Value 00:00:00.000 for variable nightStart added to EvaluationContext org.eclipse.xt           ext.xbase.interpreter.impl.DefaultEvaluationContext@efe28b
2015-05-23 20:20:52.159 [INFO ] [m.r.i.engine.RuleContextHelper] - Expression is class class org.eclipse.xtext.xbase.impl.XVariableDeclarationImplCustom
2015-05-23 20:20:52.160 [INFO ] [m.r.i.engine.RuleContextHelper] - Get right side of variable nightEnd
2015-05-23 20:20:52.161 [INFO ] [m.r.i.engine.RuleContextHelper] - Creating script from XExpression
2015-05-23 20:20:52.164 [INFO ] [m.r.i.engine.RuleContextHelper] - Executing script
2015-05-23 20:20:52.313 [INFO ] [m.r.i.engine.RuleContextHelper] - Variable 'nightEnd' on rule file 'lighting.rules' is initialized with value '06:00:00.000'
2015-05-23 20:20:52.314 [INFO ] [m.r.i.engine.RuleContextHelper] - Created qualified name for rule variable nightEnd: nightEnd
2015-05-23 20:20:52.315 [INFO ] [m.r.i.engine.RuleContextHelper] - Value 06:00:00.000 for variable nightEnd added to EvaluationContext org.eclipse.xtext.xbase.interpreter.impl.DefaultEvaluationContext@efe28b
2015-05-23 20:20:52.316 [INFO ] [m.r.i.engine.RuleContextHelper] - Expression is class class org.eclipse.xtext.xbase.impl.XVariableDeclarationImplCustom
2015-05-23 20:20:52.317 [INFO ] [m.r.i.engine.RuleContextHelper] - Get right side of variable dayStart
2015-05-23 20:20:52.318 [INFO ] [m.r.i.engine.RuleContextHelper] - Creating script from XExpression
2015-05-23 20:20:52.320 [INFO ] [m.r.i.engine.RuleContextHelper] - Executing script
2015-05-23 20:20:52.475 [INFO ] [m.r.i.engine.RuleContextHelper] - Variable 'dayStart' on rule file 'lighting.rules' is initialized with value '08:00:00.000'
2015-05-23 20:20:52.476 [INFO ] [m.r.i.engine.RuleContextHelper] - Created qualified name for rule variable dayStart: dayStart
2015-05-23 20:20:52.477 [INFO ] [m.r.i.engine.RuleContextHelper] - Value 08:00:00.000 for variable dayStart added to EvaluationContext org.eclipse.xtext.xbase.interpreter.impl.DefaultEvaluationContext@efe28b
2015-05-23 20:20:52.478 [INFO ] [m.r.i.engine.RuleContextHelper] - Expression is class class org.eclipse.xtext.xbase.impl.XVariableDeclarationImplCustom
2015-05-23 20:20:52.478 [INFO ] [m.r.i.engine.RuleContextHelper] - Get right side of variable dayEnd
2015-05-23 20:20:52.479 [INFO ] [m.r.i.engine.RuleContextHelper] - Creating script from XExpression
2015-05-23 20:20:52.481 [INFO ] [m.r.i.engine.RuleContextHelper] - Executing script
2015-05-23 20:20:52.628 [INFO ] [m.r.i.engine.RuleContextHelper] - Variable 'dayEnd' on rule file 'lighting.rules' is initialized with value '20:00:00.000'
2015-05-23 20:20:52.629 [INFO ] [m.r.i.engine.RuleContextHelper] - Created qualified name for rule variable dayEnd: dayEnd
2015-05-23 20:20:52.630 [INFO ] [m.r.i.engine.RuleContextHelper] - Value 20:00:00.000 for variable dayEnd added to EvaluationContext org.eclipse.xtext.xbase.interpreter.impl.DefaultEvaluationContext@efe28b
2015-05-23 20:20:52.632 [DEBUG] [m.r.internal.engine.RuleEngine] - Context has been set
2015-05-23 20:20:52.633 [DEBUG] [m.r.internal.engine.RuleEngine] - New Thread created
2015-05-23 20:20:52.634 [DEBUG] [m.r.internal.engine.RuleEngine] - Thread has been started
2015-05-23 20:20:52.699 [INFO ] [.o.model.script.Lighting.rules] - Executing switch on of corridor lights

Note: I was doing exactly the same steps: Restarted openHAB and changed the Aeon_CO_Motion in the classic UI

When the RuleContextHelper calls script.execute() for line "var LocalTime lateEveningStart = new LocalTime(22, 00)" of the lighing.rules, the call never returns. It seems to hang indefinitely in this line of ScriptImpl: https://github.com/openhab/openhab/blob/6249457ff8c67ab92ac752690e433dbf0a71d99f/bundles/model/org.openhab.model.script/src/org/openhab/model/script/internal/engine/ScriptImpl.java#L59

Any ideas what could cause these issues (do I have some problem in my rule files?) or how I could further anyalyze the problem?

I've already spend several days trying to find out what's wrong but I couldn't get further than what I've already described...

Thanks!
Dominic

[Dominic Lerbs]

Once or twice I could even see some exception stacktrace of xText.
It is possible that I was debugging openHAB at that time with breakpoints in eclipse, though. So I am not sure if this was caused by the same issue as above or by debugging:

23:41:33.557 [ERROR] [e.x.l.lazy.LazyLinkingResource:214  ] - resolution of uriFragment 'xtextLink_::0.2.0.2.0.0::0::/1' failed.
java.lang.ClassCastException: [Ljava.lang.Object; cannot be cast to [Lorg.eclipse.emf.common.notify.Adapter;
    at org.eclipse.emf.ecore.impl.MinimalEObjectImpl.eBasicAdapterArray(MinimalEObjectImpl.java:588) ~[org.eclipse.emf.ecore_2.8.3.v20130125-0546.jar:na]
...
at org.eclipse.xtext.common.types.access.JvmTypeChangeDispatcher.requestNotificationOnChange(JvmTypeChangeDispatcher.java:79) ~[org.eclipse.xtext.common.types_2.3.0.v201206120633.jar:na]
    at org.eclipse.xtext.common.types.impl.JvmDeclaredTypeImplCustom.requestNotificationOnChange(JvmDeclaredTypeImplCustom.java:188) ~[org.eclipse.xtext.common.types_2.3.0.v201206120633.jar:na]
...
at org.eclipse.xtext.util.PolymorphicDispatcher.invoke(PolymorphicDispatcher.java:291) [org.eclipse.xtext.util_2.3.0.v201206120633.jar:na]
    at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:218) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
    at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.evaluate(XbaseInterpreter.java:204) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
    at org.openhab.model.script.internal.engine.ScriptImpl.execute(ScriptImpl.java:59) [org.openhab.model.script_1.7.0.201505210948.jar:na]
    at org.openhab.core.scriptengine.ScriptExecutionThread.run(ScriptExecutionThread.java:44) [org.openhab.core.scriptengine_1.7.0.201505210948.jar:na]

and

23:41:34.623 [INFO ] [.x.c.types.util.TypeReferences:237  ] - Couldn't find JvmType for name 'org.eclipse.xtext.xbase.lib.StringExtensions' in context org.eclipse.xtext.xbase.resource.XbaseResource@1589683 uri='mail.rules'
java.lang.NullPointerException: null
    at org.eclipse.emf.common.notify.impl.BasicNotifierImpl.eNotify(BasicNotifierImpl.java:374) ~[org.eclipse.emf.common_2.8.0.v20130125-0546.jar:na]
    at org.eclipse.emf.common.notify.impl.NotifyingListImpl.dispatchNotification(NotifyingListImpl.java:261) ~[org.eclipse.emf.common_2.8.0.v20130125-0546.jar:na]

and

23:42:47.324 [INFO ] [m.r.i.engine.RuleContextHelper:79   ] - Executing script
23:42:47.344 [ERROR] [x.x.scoping.XbaseScopeProvider:189  ] - error during scoping
java.lang.NullPointerException: null
    at org.eclipse.emf.ecore.util.EcoreUtil.getAdapter(EcoreUtil.java:148) [org.eclipse.emf.ecore_2.8.3.v20130125-0546.jar:na]
    at org.eclipse.xtext.resource.containers.ResourceSetBasedAllContainersStateProvider.get(ResourceSetBasedAllContainersStateProvider.java:27) ~[org.eclipse.xtext_2.3.0.v201206120633.jar:na]
    at org.eclipse.xtext.resource.containers.StateBasedContainerManager.getState(StateBasedContainerManager.java:70) ~[org.eclipse.xtext_2.3.0.v201206120633.jar:na]

Please find the complete log output attached.
Could be some (concurrency?) problem within xtext?

[Dominic Lerbs]

One more thing to add:
I am not able to reproduce this problem when deleting either weather.rules or mail.rules. So lighting.rules + weather.rules works and also lighting.rules + mail.rules, but not all three at the same time...