[rules-dev] Logging: howto show logging + best practices of slf4j

[Geoffrey De Smet]

Hi guys,

All System.out calls in drools production code have been replace by 
sl4j-api logging calls.
The unit tests and the examples use logback (which is the standard 
slf4j-api implementation) to output those calls to the console.

For example:
2012-08-08 21:23:41,101 [main] INFO  DroolsExamplesApp started.

*Where can I configure the logging?*

  * Production code (such as drools-core/src/main/java) isn't executed
    directly and therefor has no logging configuration.
  * For a unit test, configure your logging desires in
    src/test/resources/logback-test.xml
  * For an example application, configure your logging desires in
    src/main/resources/logback.xml
  * For a war, configure your logging desires in
    src/main/resources/logback.xml

Notice that drools-core does not depend on logback (unlike it's tests) 
or any other logging implementation:
the user can easily bridge the drools logs to his favorite logging 
system (for example with slf4j-jcl).

*What can I display in my log?*

Everything that gets logged, not just from drools, but /also from any 
other dependency/ (*).
(*) if they don't use slf4j, logging can be unified by bridges (for 
example with jcl-over-slf4j).

Here's an example that logs on debug level of drools and springframework 
and on warn level for all other dependencies:

<configuration>
   <logger name="org.drools" level="debug"/>
   <logger name="org.springframework" level="debug"/>
   <logger name="org.drools.foo.bar.MyReallyVerboseDebugClass" 
level="info"/>

   <root level="warn">
     <appender-ref ref="consoleAppender" />
   </root>
</configuration>

*How do I use logging in my classes?*

public class MyFoo {

     protected static transient Logger logger = 
LoggerFactory.getLogger(MyFoo.class);

     public void bar() {
          logger.trace("Something in a loop happened.");
          logger.debug("Something happened");
          logger.info("DroolsExamplesApp started.");
          logger.warn("That rule is pointless.");
          logger.error("Don't divide by zero.", myException); // it's 
probably better to only throw a RuntimeException to the user code and 
let him log it
     }

}
*
How do I make logging fast?*

1) Keep the Logger a static field: that way it's creation cost is 
independent of how many instances of your class are created

2) Avoid String concatenating when trace is disabled:
Slower:
   logger.trace("String a is " + a + " and string b is " + b + "."); // slow
Faster:
   logger.trace("String a is {} and string b is {}.", a, b);
Because it checks if trace is enabled first, before concatenating the 
String.
When performance matters, trace logging will be very likely disabled.

3) Don't use System.out or System.err.
Such an operation always synchronizes on a printstream and the user is 
unable to disable that performance cost.
Use logging instead, so the user can configure it to discard the 
messages and their performance cost.

*What best practices should I follow?*

1) Don't use custom flags to disable/enable logging:
                     boolean hideWarnings = Boolean.getBoolean( 
"drools.schema.hidewarnings" );
                     if ( !hideWarnings ) {
                         System.out.println( "Your SAX parser is not 
JAXP 1.2 compliant - turning off validation." );
                     }
Just do this instead:
     logger.warn( "Your SAX parser is not JAXP 1.2 compliant - turning 
off validation." );
which outputs as for example:
    ... org.drools.MySaxParserClass WARN Your SAX parser is not JAXP 1.2 
compliant - turning off validation.
Now, the user can easily hide that warning in the typical log 
configuration way:
   <logger name="org.drools.MySaxParserClass" level="error"/>
Instead of having to learn about "drools.schema.hidewarnings" and set 
that parameter somewhere.

2) Prefer logger.debug() (or logger.trace()) instead of logger.info().
Most log messages are not interesting enough to get the level info. 
Fight verbosity.
A good rule of thumb: Running your code for an hour should not output 
more than 10 info messages if nothing failed.

*The logging is too big for my console*

Use a fileAppender temporary for yourself, but don't add it to the 
default logback-test.xml configuration:

   <appender name="fileAppender" 
class="ch.qos.logback.core.rolling.RollingFileAppender">
     <file>local/log/drools.log</file>
     <rollingPolicy 
class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy">
<fileNamePattern>local/log/drools.%i.log.zip</fileNamePattern>
       <minIndex>1</minIndex>
       <maxIndex>3</maxIndex>
     </rollingPolicy>
     <triggeringPolicy 
class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
       <maxFileSize>5MB</maxFileSize>
     </triggeringPolicy>
     <encoder>
       <pattern>%d [%t] %-5p %m%n</pattern>
     </encoder>
   </appender>

   <root level="warn">
     <appender-ref ref="consoleAppender" />
     <appender-ref ref="fileAppender" />
   </root>

-- 
With kind regards,
Geoffrey De Smet

-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.jboss.org/pipermail/rules-dev/attachments/20120808/69849ba3/attachment.html