ivy’s page

I’ve been working on a web service system that allows labs to send in analysis results. The client registers a load of results, and one of the administrative users of the system (on the receiving end) required detailed usage information (logdata) about the processed data, account info and -in case of errors- details on what went wrong.

Like any problem, there are many solutions, but the two that come in mind are

• A proxy based solution; where a separate system intercepts, logs, and if required transforms the exchanged SOAP messages.
• Internal logging; let the application itself log processing information and errors.

The proxy based solution could typically be implemented by an Enterprise Server Bus, or a generic Web Service Management component (e.g. Oracle WS Manager). The exchanged SOAP messages should be tailored to contain enough information for the logging purposes, and the additional info could be filtered out before the message is returned to the client. The advantage of this solution is that it is flexible, reusable for other service systems, and it could be used for many other aspects (like security). The disadvantage is that no such system had been implemented yet in the company, and implementing it is outside the scope of the project. And of course, it has to be working by yesterday . Additionally, the architecture had already become a long connection of systems (Load-balanceer – Web Server – Application Server – Interconnect – Database) and the main reason for the logging requirement is bad experiences with failing components with no one noticing (specifically Interconnect).

Custom logging had naturally been built in with log4j. The code had been instrumented (manually) with appropriate log statements for mostly debug purposes.
So, all around the code base are Java log statements like

logger.debug("Executing stored procedure X");

Which would result in a logline in a logfile like

DEBUG 2006/11/07 15:39:12 Executing stored procedure X

It wasn’t hard to configure an additional appender that would log important messages to a file or database the back-end people had access to. The thing that challenged me a bit was that each logged line had to contain account data (among other things the used account name and/or ip-address of the sender). To them, it didn’t matter whether logging occurs during the login phase or deep down the business logic. But because things like security is only handled in Servlet Filters, account data is not available in the business logic.

I considered two options:

• Passing all required data along with the calls. This requires changing the method signatures and thus the API. This is a bit, no, quite a bit absurd for just logging.
• Putting all the data in a ThreadLocal object. That’s like a global variable, but scoped to a Thread. If you do this a lot your code will get ugly fast.

Luckily, this need has already been addressed the logging library. And while I think it’s implemented with the Threadlocal mechanism, I don’t really have to care. The log4j framework contains a facility called Mapped Diagnostic Context (MDC), which -I will quote- helps in situations where one application is involved in simultaneously serving multiple clients, and you are interested in separating or distinguishing log content from each of these multiple clients..

With MDC we can add logging context variables as we pass through the security/filter layer and log as we always would in the business logic. A neat filter for adding some MDC variables would be something like:

package any;

import java.io.*;
import javax.servlet.*;
import org.apache.log4j.Logger;
import org.apache.log4j.MDC;
import java.security.Principal;

/**
 * A filter that adds (and removes) MD Context variables
*/
public class AddToMDCFilter implements Filter {
  private final static Logger logger =
    Logger.getLogger(LoggingFilter.class.getName());

  public void init(FilterConfig filterConfig)
  {
  }

  public void destroy()
  {
  }

  public void doFilter(ServletRequest request,
                       ServletResponse response,
                       FilterChain chain)
  {
    try
    {
      // add the context variables
      MDC.put("ipAddress", request.getRemoteAddr() );
      Principal user = request.getUserPrincipal();
      MDC.put("user", (user==null)?"unknown":user.getName() );

      // pass on the request
      chain.doFilter(request, response);
    }
    finally
    {
      // no matter what happens, clean up
      //   the variables associated with this Thread/Request
      MDC.remove("ipAddress");
      MDC.remove("user");
    }
  }
}

Add this to your web.xml file to activate it for each request. To make sure this ends up in your appender output (e.g. logfile), configure your log log4.conf file as follows:

%Time etc %X{ipAddress} - %X{user} %n%m
#log4j.appender.ROLLING=org.apache.log4j.RollingFileAppender
#log4j.appender.ROLLING.File=logFile.log
#log4j.appender.ROLLING.Threshold=INFO
#log4j.appender.ROLLING.MaxFileSize=10000KB
#log4j.appender.ROLLING.MaxBackupIndex=10
#log4j.appender.ROLLING.layout=org.apache.log4j.PatternLayout
#log4j.appender.ROLLING.layout.ConversionPattern=%5p %d{DATE}\
  [%.10t] %.15X{ipAddress}-%.9X{user}-%m%n

# And/Or, log to the database
log4j.appender.JDBC=org.apache.log4j.jdbc.JDBCAppender
log4j.appender.JDBC.Threshold=INFO
log4j.appender.JDBC.URL=jdbc:oracle:thin:@databaseHost.com:1521:SID
log4j.appender.JDBC.Driver=oracle.jdbc.driver.OracleDriver
log4j.appender.JDBC.User=scott
log4j.appender.JDBC.Password=tiger
log4j.appender.JDBC.layout=org.apache.log4j.PatternLayout
log4j.appender.JDBC.layout.ConversionPattern=CALL \
  INSERT_LOGSTATEMENT( '%X{ipAddress}', %X{user}, '%m' )%n

Now you’re set up! If your business logic logs just like this:

logger.info("Some info statement");

Your logfile will show:

INFO 2006/11/07 16:39:12 Thread-0001 127.0.0.1 \
  - someuser - Some info statement

It solved the trick for me

This entry was posted on Tuesday, November 7th, 2006 at 5:10 pm and is filed under Computer. You can follow any responses to this entry through the RSS 2.0 feed. You can skip to the end and leave a response. Pinging is currently not allowed.