Srikanth Shenoy's Blog

Experiences with using Log4J in J2EE applications

Logging with Log4J is simple and seems to be trivial and doesn't warrant a blog. However Logging in enterprise projects raises interesting requirements and possibilities.

The first question is where do you put your Logging library. With JDK Logging, you pretty much have no choice. It is always located in the classpath and loaded by bootstrap classloader, the mother of all class loaders.

Log4J brings two choices to the table. You can put it in application server's classpath or package it as a dependency library along with the EAR.

If yours is the only application hosted on the server, either choices will mean the same thing. However if there are multiple applications hosted on the same VM, care must be taken before putting the Log4J jar in the system classpath. In Log4J, all Loggers are singletons. This means if you have Loggers with same names in multiple EARs, then the Logger defined later overwrites the earlier one. In other words, you might find that the logs from your application end up in another application's logs.

This can be a problem even when there are no two loggers with same names. The catch-all root logger that exists in all your log4j configuration can pose a threat. If none of the defined logger categories are able to log the message, then the burden falls on the root logger. The root logger might be configured by the "other" application hosted on the shared server In other words never rely on the root logger and always defined a logical root logger. If you are using the fully qualified class name as your logger name, then define the toplevel package name uniquely identifying your application as the logical root logger. For instance "com.mycompany.myapplication" can be the logical root logger.

You might say, "Hey I have Log4J packaged in each EAR. So, the Loggers are singletons at the EAR level and I dont care about the names I assign to them". Before you go that route, consider how you aggregate messages per user basis. With Log4J, you are most probably using Nested Diagnostic Context (NDC) aren't you? Chances are that you are using a Servlet Filter to set the session id as the NDC contextual identifier. If your application is a standalone, then bundling the Log4J in your EAR is the right option.

However, if your application collaborates with other applications (EARs) and tracking user activity across applications with NDC is important to you then you are out of luck with Log4J bundled in the EAR. NDC manages a static stack of contextual information per thread. When your application makes call into another application's EJBs, then you are cutting across classloaders, and the NDC from the caller is not available in the callee. The only way that can be made available across applications is when the Log4J is loaded by the parent classloader.

Well, I might say "Put your Log4J library in the system classpath and your problems will be solved". But the reality is that you have to often live alongside other applications that have bundled Log4J in their EAR. Worse you might have to collaborate with them. Most likely you will not have the liberty to change their logging logic or configuration.

One solution that comes to my mind is using AOP in conjunction with ThreadLocal. For example if yours is the calling application and the callee relies on NDC, then you can store the identifier as ThreadLocal variable. Using Advices you can then associate the threadlocal value with the callee's NDC. And thus you have effectively carried over the unique identifier for the user activity acorss the thread of execution. The class using ThreadLocal should load from the system classpath though.

No matter how you log in your system, you might have run into situations needing to filter logs across multiple files, possibly across multiple applications for a given user at various times based on NDC. Utilities like Chainsaw or LogFactor5 do this for a single file. There is a need for having a broad based tool that does time based NDC filtering across multiple files. Perhaps there is a open source tool out there satisfying my requirements.

Another question perhaps outside the realm of Log4J itself is "How to correlate Logging that occurs across VMs?". A question that needs to be addressed in distributed environments. This may be impossible without encapsulating the correlation identifier in the invocation itself. The collaborating systems (caller and callee) should be able to interpret the correlation identifier. But then, it also results in tight coupling. I dont know if there is really a good solution to this problem.

Comments

• Distributed logging
  Does log4j's SocketAppender meet your needs for distributed logging?

  Posted by: jimothy on June 02, 2004 at 11:44 AM

• Distributed logging
  The latest version of Chainsaw, when used in combination with MDC and log4j's new receivers, can do much of this (log4j 1.3 will enter alpha soon, but Chainsaw v2 is available now).

  Here's how:

  Define a logfilepatternreceiver for each file you want to load (specifying the file location and pattern in the file), and then use 'view-create custom expression logpanel' to combine those events into a single panel. Of course, Chainsaw can use other sources as well (database, sockets, xml files, etc.)

  Here's the link to Chainsaw v2 (available via Web Start) - see the tutorial on the welcome panel:

  http://logging.apache.org/log4j/docs/chainsaw.html

  Scott

  Posted by: sdeboy on June 02, 2004 at 01:21 PM

• Distributed logging
  SocketAppender logs the messages at a remote server. It does not let you correlate logs from a single thread of execution spanning across multiplpe VMs though.

  Posted by: srikanth on June 02, 2004 at 08:27 PM

• Distributed logging
  Cool.. sounds like I can trade my custom greps in favor of this :)

  Posted by: srikanth on June 02, 2004 at 08:32 PM

• Distributed logging
  Not to mention those scripts aggregating filtered messages from multiple sources

  Posted by: srikanth on June 02, 2004 at 08:33 PM

• Thanks Srikanth ..your article has good insight into the log4j issues.I am facing one of the issues you mentioned,

  " This means if you have Loggers with same names in multiple EARs, then the Logger defined later overwrites the earlier one. In other words, you might find that the logs from your application end up in another application's logs."

  
  Is there any workaround for this.we have about 4 different modules running on same jvm and now we added another web module.we also have log4j in server class path,and we want the newly added webmodule use its own log4j configuration instead of the global configuration.Is there any way we can do this.Your help is very much appreciated.Thanks in advance.
  

  Posted by: malliksomepalli on December 16, 2005 at 09:49 AM

• Never mind..i fixed it

  Posted by: malliksomepalli on December 21, 2005 at 08:14 AM

• malliksomepalli, would you please elaborate on how you fix your problem? We have one application running on a WebLogic application server, and we are adding a new EJB application to the same server. The existing application packages the log4j.jar in its EAR but put the log4j.xml in a directory that is on the system class path. We also package the log4j.jar in the new EAR. We tried to package a new log4j.xml in the new EAR, also tried to put it outside the EAR with a different name and specified it with the log4j.configuration system property in the weblogic-application.xml. Nothing seems to work. The logger names for the new application are different but all the log messages went to the root logger defined by the existing application.

  Posted by: elatse on April 03, 2006 at 08:25 AM

This work is licensed under a Creative Commons License.