uPortal and Commons Logging

Andrew Petro implemented the switch from a log4j-backed uPortal-specific LogService logging architecture to use of Apache Commons Logging directly on 22 September 2004 for the uPortal 2.4 release.

What Commons Logging buys us

One Fewer uPortal Component

The uPortal LogService has been deprecated and effectively replaced by an established, off-the-shelf opensource Apache Commons component. This is one fewer component for uPortal to maintain going forward.

Location-revealing logging

With uPortal components using Commons Logging directly, more expensive but more detailed log4j message formats which include the file and line number making the logging call, such as

# Pattern used during debugging
#
log4j.appender.R.layout.ConversionPattern=%5p [%t] %c{2}.[%x] (%F:%L) %d{MMM/dd HH:mm:ss} - %m%n

result in log files which include the filename and line number of the relevant Class, rather than a reference to the LogService class.

INFO [http-8080-Processor24] provider.SimpleSecurityContext.[] 
(SimpleSecurityContext.java:106) Sep/22 01:53:06 - User admin is authenticated
 WARN [http-8080-Processor24] services.Authentication.[] 
(Authentication.java:146) Sep/22 01:53:06 - Authentication Service recieved unknown additional descriptor

Filterable Logging

Java code calling Commons Logging directly produces log messages that "appear" to come from the client code. Contrastingly, code calling the LogService which in turn calls a logging implementation will produce log messages that "appear" to come from the LogService. Since the messages appear to come from the client code, they can be assigned to hierarchically defined Loggers in Log4J and/or the log message format can be set to include the class name and even line number invoking the logging for maximal debugging.

Here I've configured several uPortal framework components to log at different threshold levels into the same log file. I was likely debugging the groupsmanager when I wrote this configuration, attempting to get it and related components to log to the same place while filtering out all the other logging going on in the Portal.

log4j.logger.org.jasig.portal.properties.PropertiesManager= ERROR, GROUPSMANAGER
log4j.logger.org.jasig.portal.services.GroupService= DEBUG, GROUPSMANAGER
log4j.logger.org.jasig.portal.channels.groupsmanager= DEBUG, GROUPSMANAGER
log4j.logger.org.jasig.portal.utils.XSLT= DEBUG, GROUPSMANAGER

log4j.appender.GROUPSMANAGER=org.apache.log4j.FileAppender
log4j.appender.GROUPSMANAGER.File=i:\\portal\\logs\\org\\jasig\\portal\\channels\\groupsmanager\\log.txt
log4j.appender.GROUPSMANAGER.immediateFlush = true
log4j.appender.GROUPSMANAGER.append = false
log4j.appender.GROUPSMANAGER.Encoding=UTF-8
log4j.appender.GROUPSMANAGER.layout=org.apache.log4j.PatternLayout
log4j.appender.GROUPSMANAGER.layout.ConversionPattern=%5p [%t] (%F:%L) %d{HH:mm:ss} - %m%n

Allows deployers to choose a logging implementation

Commons Logging is a general logging API which can discover the appropriate logging implementation. If it finds a log4j.jar and an appropriate configuration file, it uses Log4J. Bereft of Log4J, if it finds itself to be living in JRE1.4 or better, it uses JDK1.4 logging. If it finds itself bereft both of Log4J and of a JRE 1.4 or later environment, it falls back on primitively logging sufficiently important messages to the console.

In actuality this is not expected to be an important advantage, as it is expected that the vast majority of deployers will choose to back the Commons Logging with Log4J.

Whereas the story used to be YourClass->LogService->Log4J->configured logging, what we are now likely to have is: YourClass->Commons Logging >Log4J>configured logging. Apache Commons Logging takes the place of the uPortal LogService.

Shared logging space

Use of Apache Commons Logging brings uPortal into an established community of Java code which uses Commons Logging. For instance, the Java CAS Client uses Commons Logging. You might choose to configure your Logger.properties file such that the edu.yale.its.tp.cas package logs alongside or in the same log file as some or all of your uPortal proper components, especially when troubleshooting CAS authentication. Use of commons logging makes this possible.

Here's an example of configuring log4j to log about CAS in a particular file:

log4j.logger.edu.yale.its.tp.cas=DEBUG, CAS

log4j.appender.CAS=org.apache.log4j.FileAppender
log4j.appender.CAS.File=i:\\portal\\logs\\edu\\yale\\its\\tp\\cas\\log.txt
log4j.appender.CAS.immediateFlush = true
log4j.appender.CAS.append = false
log4j.appender.CAS.Encoding=UTF-8
log4j.appender.CAS.layout=org.apache.log4j.PatternLayout
log4j.appender.CAS.layout.ConversionPattern=%5p [%t] %c{2}.[%x] %d{MMM/dd HH:mm:ss} - %m%n

Reduced dependencies

Dependency upon Commons Logging rather than uPortal LogService makes code written for uPortal more suitable for reuse in other projects.

Performance Opportunities

Suppose you have an object SomeObject, which has complicated state such that it is egregiously expensive to calculate its toString() method. Suppose, plausibly, that this complicated state becomes the subject of debugging messages.

The naive client code which includes logging will result in this expensive state being calculated even when the logging level is set such that the messages are not actually printed (because they are below the threshhold for logging).

public void someMethod(){
  log.trace("entering someMethod with state: " + this);
   // do some stuff
  log.trace("returning from someMethod with state: " + this);
}

Commons Logging affords the ability to programmatically determine whether the Log instance will log a message at a given level before attempting the log, allowing you, the application developer, to dodge computing the expensive String if it will just be thrown away anyway.

public void someMethod(){
  if(log.isTraceEnabled())
     log.trace("entering someMethod with state: " + this);
   // do some stuff
   if(log.isTraceEnabled())
     log.trace("returning from someMethod with state: " + this);
}

Using this pattern makes sense for the Trace and Debug levels. Higher levels are less likely to be unloggable and therefore probably don't benefit sufficiently to justify the more verbose construct required to implement this pattern.

I hasten to note that Apache Commons Logging, even when backed by Log4J with a custom message format including the location from which the logger was invoked, is fast. This pattern is an opportunity to ensure that the code invoking the fast logging implementation isn't slow.

Details of change

Configuring Log4J

The LogService previously had a role in configuring Log4J to find and use the Logger.properties file. This happened on first invocation of a log method of LogService.

/**
   *  Configures the Log4J system using the properties/Logger.properties file.
   *  Read the Log4J docs on how to setup one of these files to do anything
   *  you want. If this method isn't called before doing some logging, then
   *  Log4j will complain.
   */
  private final static void initialize () {
    // don't bother if we are already initialized
    if (bInitialized) {
      return;
    }
    try {
      String loggerPropsFileName = ResourceLoader.getResourceAsFileString(
          LogService.class, "/properties/Logger.properties");
      PropertyConfigurator.configureAndWatch(loggerPropsFileName);
    } catch (Exception e) {
      e.printStackTrace();
    }
    ...
}

Since LogService is now deprecated, it cannot be relied upon to be invoked in order to configure Log4J for uPortal.

For uPortal 2.4, the Ant build.xml includes code in the "compile" task to copy the Logger.properties file to the well known name "log4j.properties" and the well known location at the root of the classes tree of the webapp so that Commons Logging / Log4J will be able to find it automatically.

<!-- Copy the Logger.properties file to the well-known location
  	log4j expects.-->
  	<copy file="properties/Logger.properties" tofile="${build.home}/WEB-INF/classes/log4j.properties"/>