This page last changed on Oct 29, 2013 by melchoir55.

Hey folks,

I've created a listener which outputs information along the drools logging channel whenever a rule activation occurs. When a rule activation occurs, you will get the following feedback:
1. Rule Name
2. The bindings and corresponding values in the "when" clause. Bindings are the variable names with a leading "$" symbol which you bind to objects.
3. The antecedent objects and their values. This should include all objects which were use to trigger the activation. In other words, all objects referenced in the when clause.

I would like feedback concerning whether this information is too much, or whether additional feedback would be useful. I would also appreciate feedback regarding the formatting of the output.

The controller is packaged here: https://dl.dropboxusercontent.com/u/3517960/OpenRemote-Controller-2.1.0_SNAPSHOT-2013-06-17.zip

Isaac,
I am happy to try it out. Where do I store this file, and where do I find the output?

Posted by pz1 at Oct 29, 2013 06:24

Hi Isaac,
I'll try it for sure. Is it enough just to place the jar in the controller lib or do I need to configure something more?

Posted by aktur at Oct 29, 2013 12:40

I don't actually have the software running, so take what I say with a grain of salt. I expect there is a jar somewhere on your system which corresponds to the jar I have compiled. This jar is the controller. You should only need to replace that jar with this one. You may also need to rename this jar to match the name of the old one.

If you're having difficulty I'll install everything in order to track down what you need to replace and where. I hadn't installed it yet because my HA gear doesn't actually arrive until tomorrow.

Posted by melchoir55 at Oct 29, 2013 16:43

The output is sent to the drools log. I assume there is a console in the controller GUI which this outputs to.

Posted by melchoir55 at Oct 29, 2013 16:47

It looks to me like I misunderstood how the controller is normally packaged. Give me a bit and I'll get it done properly.

Posted by melchoir55 at Oct 29, 2013 19:25

Sorry for the mixup. The link should now give you the controller in the packaging you are expecting!

Posted by melchoir55 at Oct 29, 2013 20:36

Today I tried to use this build on my ebox. Unfortunately, no joy. http://orb:8080/controller shows apache 503 error. The server log shows:

root@orb:~# cat  /opt/OpenRemote-Controller/logs/container/tomcat-server.log
Nov 2, 2013 12:35:29 PM org.apache.catalina.core.AprLifecycleListener init
INFO: The APR based Apache Tomcat Native library which allows optimal performance in production environments was not found on the java.library.path: /opt/OpenRemote-Controller/webapps/controller/WEB-INF/lib/native
Nov 2, 2013 12:35:29 PM org.apache.coyote.http11.Http11Protocol init
INFO: Initializing Coyote HTTP/1.1 on http-8080
Nov 2, 2013 12:35:29 PM org.apache.catalina.startup.Catalina load
INFO: Initialization processed in 5272 ms
Nov 2, 2013 12:35:30 PM org.apache.catalina.core.StandardService start
INFO: Starting service Catalina
Nov 2, 2013 12:35:30 PM org.apache.catalina.core.StandardEngine start
INFO: Starting Servlet Engine: Apache Tomcat/6.0.18
Nov 2, 2013 12:35:30 PM org.apache.catalina.startup.HostConfig deployWAR
INFO: Deploying web application archive webconsole.war
Nov 2, 2013 12:35:40 PM org.apache.catalina.loader.WebappClassLoader validateJarFile
INFO: validateJarFile(/opt/OpenRemote-Controller/webapps/controller/WEB-INF/lib/servlet-api.jar) - jar not loaded. See Servlet Spec 2.3, section 9.7.2. Offending class: javax/servlet/Servlet.class
Nov 2, 2013 12:35:42 PM org.apache.tomcat.util.modeler.Registry registerComponent
SEVERE: Null component Catalina:type=JspMonitor,name=jsp,WebModule=//localhost/controller,J2EEApplication=none,J2EEServer=none
Nov 2, 2013 12:35:42 PM org.apache.catalina.startup.HostConfig deployDirectory
SEVERE: Error deploying web application directory controller
java.lang.UnsupportedClassVersionError: org/openremote/controller/bootstrap/servlet/LogInitialization : Unsupported major.minor version 51.0 (unable to load class org.openremote.controller.bootstrap.servlet.LogInitialization)
	at org.apache.catalina.loader.WebappClassLoader.findClassInternal(WebappClassLoader.java:1851)
	at org.apache.catalina.loader.WebappClassLoader.findClass(WebappClassLoader.java:890)
	at org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1354)
	at org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1233)
	at org.apache.catalina.startup.WebAnnotationSet.loadClassAnnotation(WebAnnotationSet.java:145)
	at org.apache.catalina.startup.WebAnnotationSet.loadApplicationListenerAnnotations(WebAnnotationSet.java:73)
	at org.apache.catalina.startup.WebAnnotationSet.loadApplicationAnnotations(WebAnnotationSet.java:56)
	at org.apache.catalina.startup.ContextConfig.applicationAnnotationsConfig(ContextConfig.java:297)
	at org.apache.catalina.startup.ContextConfig.start(ContextConfig.java:1068)
	at org.apache.catalina.startup.ContextConfig.lifecycleEvent(ContextConfig.java:261)
	at org.apache.catalina.util.LifecycleSupport.fireLifecycleEvent(LifecycleSupport.java:117)
	at org.apache.catalina.core.StandardContext.start(StandardContext.java:4252)
	at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:791)
	at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:771)
	at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:525)
	at org.apache.catalina.startup.HostConfig.deployDirectory(HostConfig.java:926)
	at org.apache.catalina.startup.HostConfig.deployDirectories(HostConfig.java:889)
	at org.apache.catalina.startup.HostConfig.deployApps(HostConfig.java:492)
	at org.apache.catalina.startup.HostConfig.start(HostConfig.java:1149)
	at org.apache.catalina.startup.HostConfig.lifecycleEvent(HostConfig.java:311)
	at org.apache.catalina.util.LifecycleSupport.fireLifecycleEvent(LifecycleSupport.java:117)
	at org.apache.catalina.core.ContainerBase.start(ContainerBase.java:1053)
	at org.apache.catalina.core.StandardHost.start(StandardHost.java:719)
	at org.apache.catalina.core.ContainerBase.start(ContainerBase.java:1045)
	at org.apache.catalina.core.StandardEngine.start(StandardEngine.java:443)
	at org.apache.catalina.core.StandardService.start(StandardService.java:516)
	at org.apache.catalina.core.StandardServer.start(StandardServer.java:710)
	at org.apache.catalina.startup.Catalina.start(Catalina.java:578)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:616)
	at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:288)
	at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:413)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:616)
	at org.rzo.yajsw.app.WrapperJVMMain.executeMain(WrapperJVMMain.java:53)
	at org.rzo.yajsw.app.WrapperJVMMain.main(WrapperJVMMain.java:36)
Nov 2, 2013 12:35:42 PM org.apache.coyote.http11.Http11Protocol start
INFO: Starting Coyote HTTP/1.1 on http-8080
Nov 2, 2013 12:35:42 PM org.apache.catalina.startup.Catalina start
INFO: Server startup in 13336 ms

Probably I just need to change something in settings. Any hint?

Posted by aktur at Nov 02, 2013 11:47

I've copied your workspace, build it and it works on my ebox. However, I am unable to locate any rule's log file. Are there any log files supposed to be written? On ebox I haven't succeed to start the controller on console so I am unable to verify if anything is written to it.

Posted by aktur at Nov 02, 2013 13:51

The logging follows the drools log channel, which I assume prints to the console. I could additionally have it create an actual file. This wouldn't be too difficult. I'm not home today but I'll try to do this tomorrow.

Posted by melchoir55 at Nov 02, 2013 16:47

Well, I went ahead and made the build which I needed: OpenRemote-Controller-2.1.0_SNAPSHOT-2013-06-17.zip
Logs to the file logs/rules/drools.log and it looks like it does what I need, I'll be testing it for a while.

Posted by aktur at Nov 02, 2013 18:43

Did you just add a file handler to the listener? Would you mind sending me the change you made to the source code or pointing me at where I can find it?

Posted by melchoir55 at Nov 04, 2013 19:56

For adding the file output there is no need to add anything in java files. It is enough to add following lines to the log4j.properties

# ---- DROOLS RULES LOG ---------------------------------------------------------------------------

log4j.logger.OpenRemote.Controller.runtime.cache.event.processor.drools = ALL, rule-file, openremote-console
log4j.appender.rule-file = org.apache.log4j.RollingFileAppender
log4j.appender.rule-file.File = ../logs/rules/drools.log
log4j.appender.rule-file.Threshold = DEBUG 
log4j.appender.rule-file.MaxFileSize = 500KB
log4j.appender.rule-file.MaxBackupIndex = 10 
log4j.appender.rule-file.layout = org.apache.log4j.PatternLayout
log4j.appender.rule-file.layout.ConversionPattern = %p %d (Drools): %m%n

Nevertheless, I'm tweaking RuleListener.java and RuleEngine.java to get the output properly formatted and useful. Right now I'm getting an output like this:

DEBUG 2013-11-05 13:15:37,283 (Drools): Rule Activation Imminent: 
	rule "Zwerven2" // (package org.openremote.controller.protocol)
	Declarations 
		Declaration: "$e"
		Value:
			Sensor Name: "PIR2"
			Sensor Value: "0"
	LHS objects(antecedents)
		Class: "CustomState"
		Fields: 
			Event Name: "PIR2"
			Value: "0"

DEBUG 2013-11-05 13:15:37,293 (Drools): Rule Activation Imminent: 
	rule "Show event creation" // (package org.openremote.controller.protocol)
	Declarations 
		Declaration: "$z"
		Value:
			Custom declarative value
	LHS objects(antecedents)
		Class: "Zwerven_event"
		Fields: 
			Custom antecedent value

The first line is from regular sensor and the second uses an internal inserted fact. There is not much description about internally created facts (I've changed null to Custom...), and I would like to have more info there about fields and values.

So far I am quite happy with drools logs, they help me to speed up my development. What I miss though are conditions which lead to not firing rules. I don't have any log about new created facts unless there is a rule which would be activated on them. Moreover, as the Event(source=="xyz") binding is very weak, there is no way to detect a problem when I misspell "xyz". Especially when sensor name is long this leads to bugs very hard to detect and fix. I would love to have a feedback like "WARNING: there is no sensor with name "xyz", rule "abcd" will be never triggered!". Would it be possible?

I would be happy to share my altered java files. How can I get a workspace?

Posted by aktur at Nov 05, 2013 12:59

What I miss though are conditions which lead to not firing rules

Yes, that might help me to solving the problem with my sunscreen rules

Posted by pz1 at Nov 05, 2013 13:35

"I would be happy to share my altered java files. How can I get a workspace?"

I think you would need to discuss this with Juha. In the meantime I'd welcome just a cut/paste through skype of the formatting you have done. It would save me having to go fool around with it.

"Moreover, as the Event(source=="xyz") binding is very weak, there is no way to detect a problem when I misspell "xyz". Especially when sensor name is long this leads to bugs very hard to detect and fix. I would love to have a feedback like "WARNING: there is no sensor with name "xyz", rule "abcd" will be never triggered!". Would it be possible?"

This is something I noticed immediately upon seeing examples of drl files in OR. The best way to handle something like this is with a constant, or an enumeration (constant would probably be easier). With a constant you refer to the constant which stores the string, rather than the string itself. This has the advantage of your code failing at compile time rather than at run time. For example, there might be a class which looks something like:

class Constants{
  class Sensors{
    String xyz = "xyz"
  }
}

Your code would then look like "Event(source==package.Constants.Sensors.xyz)". There are more characters involved, but it is a lot less prone to error. In order to accomplish this, I would think we would need the controller to create its own constants file when it boots or synchs. This is possible technically, but it would be work.

" What I miss though are conditions which lead to not firing rules. I don't have any log about new created facts unless there is a rule which would be activated on them. "

This is a lot harder because drools never evaluates anything unless the evaluation will succeed. You therefore can't just print out the locals when a drool "fails" to fire. The best option I imagine is creating a drool which periodically sends snapshots of the contents of working memory. That way you could examine the working memory as it changed over time without actually hooking up to a debugger, and it would be formatted in a way which is more readable than a debugger. This would show you what existed. You would presumably be able to infer from that why your drool didn't fire.

I'd welcome any suggestions someone thinks is better.

Posted by melchoir55 at Nov 05, 2013 16:53

Just my 2cts:
From 20+ years ago I remember we had some rule based systems that had an agenda function where one could inspect the status of facts.
Doesn't Drools have something similar (internal possibly) that could be used for logging?

Posted by pz1 at Nov 06, 2013 14:42

The problem isn't in accessing the facts, it is in deciding when to access them. What should trigger a dump of the working memory to log? After playing around with our implementation of drools a bit I'm starting to think that it might be enough to simply log each event as they are inserted.

Posted by melchoir55 at Nov 07, 2013 05:31

The problem isn't in accessing the facts, it is in deciding when to access them. What should trigger a dump of the working memory to log? After playing around with our implementation of drools a bit I'm starting to think that it might be enough to simply log each event as they are inserted.

As fireAllRules() is called few times per second IMHO it would be OK to display new/altered/expired facts after a call to it. Right now I have in my version of RuleEngine this:

      knowledgeSession.fireAllRules();
      
      _factCount = knowledgeSession.getFactCount();
      if(_factCount != factCount){
         log.debug("Fact count changed from {0} to {1} on fireAllRules() after \"{2}\"", factCount, _factCount, evt.getSource());
      }
      factCount = _factCount;

It is quite good but I would welcome an output which shows more details about the fact.

Posted by aktur at Nov 07, 2013 12:35

Your code would then look like "Event(source==package.Constants.Sensors.xyz)". There are more characters involved, but it is a lot less prone to error. In order to accomplish this, I would think we would need the controller to create its own constants file when it boots or synchs. This is possible technically, but it would be work.

This would mean that drools user would be yet closer to java programmer than he is now. Without proper feedback about drools compilation errors during update this would lead to more confusion than the current situation.

Posted by aktur at Nov 07, 2013 12:41

Would you mind sending me the change you made to the source code or pointing me at where I can find it?

All changes are in my workspace https://svn.code.sf.net/p/openremote/code/workspace/michalrutka/Controller_2_1_0_FM_2013-06-17_RuleLogging/

Posted by aktur at Nov 08, 2013 15:47

I reviewed the changes you made to the log4j.properties file. When I made those changes, I was unable to successfully run the unit test suite. I was in a rush so I didn't investigate why. Did you experience the same problem?

Posted by melchoir55 at Nov 09, 2013 21:27

This would mean that drools user would be yet closer to java programmer than he is now. Without proper feedback about drools compilation errors during update this would lead to more confusion than the current situation.

We would build these constants into a gui, rather than have people actually typing them out. The gui would just use them in order to populate itself.

Posted by melchoir55 at Nov 09, 2013 21:28
Document generated by Confluence on Jun 05, 2016 09:30