Rule not executed

I am really desperate now. I have a rule for a motion sensor which collapses the motion state and the last update time on one line. It seems that the rule is not being executed which I conclude out of a debug statement I put into the rules “body”. I have other rules which are similar being all executed.

Below is the excerpt from the items and rules file.

 String Motion_GF_Entrance_Formatted "Bewegung [%s]" (gGFEntrance)
Switch Motion_GF_Entrance "Eingang: [MAP(de.map):%s]" (gGFMotion) {mqtt="<[mqtthub:MyMQTT/26/4/V_TRIPPED:state:REGEX((.*))]"}
DateTime Motion_GF_Entrance_Lastupdate "Letzte Aktualisierung [%1$tA, %1$td.%1$tm.%1$tY %1$tT]"

Excerpt from rules file

   /*
     * Set lastupdate
     */
    val org.eclipse.xtext.xbase.lib.Functions$Function1 lastUpdate = [
        org.openhab.core.library.items.DateTimeItem item |
    
                postUpdate(item, now.toString());
    ]



rule "Motion GF Entrance Update"
        when
                Item Motion_GF_Entrance received update
        then
                logDebug("Motion_GF_Entrance Update", "in rule")
                lastUpdate.apply(Motion_GF_Entrance_Lastupdate)
                postUpdate(Motion_GF_Entrance_Formatted, Motion_GF_Entrance.state)
end

From the log I see the update event for the item Motion_GF_Entrance but nothing more. No error in the log, no output and no update to Motion_GF_Entrance_Formatted.

        2015-10-06 20:43:56 - LightLevel_GF_Entrance state updated to 0.0
        2015-10-06 20:43:56 - LightLevel_GF_Entrance_Lastupdate state updated to 2015-10-06T20:43:56
        2015-10-06 20:43:57 - LightLevel_GF_Entrance_Formatted state updated to 0.0 Lux - (0.0/24.0) @Tue:20:43
   >> 2015-10-06 20:43:58 - Motion_GF_Entrance state updated to 1
       2015-10-06 20:45:00 - Tom_MacbookPro received command ON
       2015-10-06 20:45:00 - Tom_Nexus received command ON
       2015-10-06 20:47:47 - Date state updated to 2015-10-06T20:47:4

I absolutely have no glue how to go forward from here.
So any help is highly, highly appreciated.

Everything looks correct to my eye.

However, you only copied from your events.log. Your logDebug statement and any errors will appear in openhab.log.

Do you have openHAB running in DEBUG mode or have you updated logback.xml to log out the DEBUG statements? If not the log statement will not show up in your logs at all.

I’d try switching it to logInfo instead of logDebug for now (you can remove or change back to logDebug later) and watch openhab.log in addition to events.log. Then add a log statement to your lambda before and after the postUpdate to see if it is completing execution of that. I’ve found sometimes when a lambda fails for some reason it can do so silently and the rule just stops.

I looked as well into openhab.log the output wasn’t there and debug log level was switched since the log file was swamped with debug statements. There are also no errors I could see in the openhab.log. To me it looks like the rule is not being executed.

Weird. I usually have the problem where a rule triggers too much when I use “received update”. Did you check that there were no errors when the rules file is loaded? Maybe there is a syntax error somewhere that prevented the rule from even loading and you missed it with all the stuff that gets printed in the debug log.

You can force it to reload the file by updating the timestamp on the file (e.g. on Linux the “touch” command).

Beyond that I’m stumped. It looks correct.

No errors during load. I have a bunch of other rules before and after that particular rule. The other rules work as expected. Really strange. I extracted parts of the debug log where the item seems to accessed. I have not looked into the sources so far to understand what is going on but anyway may be somebody on the forum can spot something here.

2015-10-05 23:37:14.724 [DEBUG] [rg.eclipse.xtext.xbase.typing.AbstractTypeProvider] -  getType: Pair(Motion_GF_Entrance, null)
2015-10-05 23:37:14.726 [DEBUG] [g.eclipse.xtext.linking.impl.DefaultLinkingService] - before getLinkedObjects: node: 'Motion_GF_Entrance'
2015-10-05 23:37:14.729 [DEBUG] [org.eclipse.xtext.xbase.scoping.XbaseScopeProvider] - enter getScope(Motion_GF_Entrance, XAbstractFeatureCall#feature)
2015-10-05 23:37:15.108 [DEBUG] [org.eclipse.xtext.xbase.scoping.XbaseScopeProvider] - sortedDescriptionsFromLowestToHighest:
FeatureScopeDescription [receiverType=null, descriptionProvider=XFeatureCallSugarDescriptionProvider [featuresForTypeProvider=StaticImplicitMethodsFeatureForTypeProvider [context=init.r$
FeatureScopeDescription [receiverType=null, descriptionProvider=DefaultJvmFeatureDescriptionProvider [featuresForTypeProvider=StaticImplicitMethodsFeatureForTypeProvider [context=init.r$
2015-10-05 23:37:15.125 [DEBUG] [on.types.util.LoggingTypeArgumentDecorator.Primary] - Initialized argument context for request ReceiverRequest [receiver=null]
2015-10-05 23:37:15.134 [DEBUG] [on.types.util.LoggingTypeArgumentDecorator.Primary] - Initialized argument context for request ReceiverRequest [receiver=null]
2015-10-05 23:37:15.330 [DEBUG] [org.eclipse.jetty.util.Scanner                    ] - scanned [/opt/openhab/contexts]: {}
2015-10-05 23:37:15.599 [DEBUG] [org.eclipse.xtext.xbase.scoping.XbaseScopeProvider] - leave getScope(Motion_GF_Entrance, XAbstractFeatureCall#feature)
2015-10-05 23:37:16.056 [DEBUG] [org.eclipse.jetty.util.Scanner                    ] - scanned [/opt/openhab/webapps]: {}
2015-10-05 23:37:16.066 [DEBUG] [org.eclipse.jetty.util.Scanner                    ] - scanned [/opt/openhab/contexts]: {}
2015-10-05 23:37:16.227 [DEBUG] [g.eclipse.xtext.linking.impl.DefaultLinkingService] - after getLinkedObjects: node: 'Motion_GF_Entrance' result: Motion_GF_Entrance
2015-10-05 23:37:16.239 [DEBUG] [rg.eclipse.xtext.xbase.typing.AbstractTypeProvider] -   getTypeForIdentifiable: org.eclipse.xtext.common.types.impl.JvmGenericTypeImplCustom@ff3876 (vis$
2015-10-05 23:37:16.242 [DEBUG] [rg.eclipse.xtext.xbase.typing.AbstractTypeProvider] -    cache hit: false for: org.eclipse.xtext.common.types.impl.JvmGenericTypeImplCustom@ff3876 (visi$
2015-10-05 23:37:16.251 [DEBUG] [rg.eclipse.xtext.xbase.typing.AbstractTypeProvider] -   result: JvmParameterizedTypeReference: org.openhab.core.library.items.SwitchItem getTypeForIdent$
2015-10-05 23:37:16.254 [DEBUG] [rg.eclipse.xtext.xbase.typing.AbstractTypeProvider] -   cache skip: JvmParameterizedTypeReference: org.openhab.core.library.items.SwitchItem
2015-10-05 23:37:16.256 [DEBUG] [rg.eclipse.xtext.xbase.typing.AbstractTypeProvider] -   cache hit: false for: Pair(Motion_GF_Entrance, null)
2015-10-05 23:37:16.258 [DEBUG] [rg.eclipse.xtext.xbase.typing.AbstractTypeProvider] -  result: JvmParameterizedTypeReference: org.openhab.core.library.items.SwitchItem getType(raw) : P$
2015-10-05 23:37:16.261 [DEBUG] [org.eclipse.xtext.xbase.scoping.XbaseScopeProvider] - sortedDescriptionsFromLowestToHighest:
FeatureScopeDescription [receiverType=JvmParameterizedTypeReference: org.openhab.core.library.items.SwitchItem, descriptionProvider=XFeatureCallSugarDescriptionProvider [featuresForType$
FeatureScopeDescription [receiverType=JvmParameterizedTypeReference: org.openhab.core.library.items.SwitchItem, descriptionProvider=DefaultJvmFeatureDescriptionProvider [featuresForType$
FeatureScopeDescription [receiverType=JvmParameterizedTypeReference: org.openhab.core.library.items.SwitchItem, descriptionProvider=XFeatureCallSugarDescriptionProvider [featuresForType$
FeatureScopeDescription [receiverType=JvmParameterizedTypeReference: org.openhab.core.library.items.SwitchItem, descriptionProvider=DefaultJvmFeatureDescriptionProvider [featuresForType$
2015-10-05 23:37:16.263 [DEBUG] [on.types.util.LoggingTypeArgumentDecorator.Primary] - Initialized argument context for request ReceiverRequest [receiver=JvmParameterizedTypeReference: $
2015-10-05 23:37:16.319 [DEBUG] [on.types.util.LoggingTypeArgumentDecorator.Primary] - Initialized argument context for request ReceiverRequest [receiver=JvmParameterizedTypeReference: $
2015-10-05 23:37:16.321 [DEBUG] [on.types.util.LoggingTypeArgumentDecorator.Primary] - Initialized argument context for request ReceiverRequest [receiver=JvmParameterizedTypeReference: $
2015-10-05 23:37:16.324 [DEBUG] [on.types.util.LoggingTypeArgumentDecorator.Primary] - Initialized argument context for request ReceiverRequest [receiver=JvmParameterizedTypeReference: $

Slight changes:

import org.openhab.core.library.types.*

rule "Motion GF Entrance Update"
when
  Item Motion_GF_Entrance received update
then
  logDebug("Motion_GF_Entrance Update", "in rule")
  Motion_GF_Entrance_Lastupdate.postUpdate(new DateTimeType())
  Motion_GF_Entrance_Formatted.postUpdate(Motion_GF_Entrance.state.toString)
end
1 Like

@watou: Ok that did the trick.

I changed my logDebug to logInfo to have the chance to see something. After openhab restart I saw the string initiation exception.
Obviously the problem was the last statement in the rule which you correctly suggested to change to

Motion_GF_Entrance_Formatted.postUpdate(Motion_GF_Entrance.state.toString)

Thanks!!!