6/20/09

jxl.log

In an intranet production environment we have running a Glassfish v2 appserver with several J2EE applications which all use JexcelApi, a.k.a JXL, which is an open source library for accessing, generating or manipulating Microsoft Excel documents. We use version 2.6.3 of JXL because it's the recent one in the Maven repository which we use, however, at the official JXL site there are newer versions. Additionally we have log4j and Java Commons Logging (JCL), ignoring Glassfish's JSR-47 Java Util Logging (JUL) facility.

Application #1 uses purely log4j and gets its log4j.xml config from a custom location.
Application #2 runs Java Commons Logging with no explicite configuration file given, so JCL uses the default JUL facility of the appserver.

Application #1 had been running for a long time without problems but when we installed #2 we realized that a jxl.log file had been created in the glassfish/domain/domain1/config directory and it's rapidly growing. As it happens, we realized that when the partition had been fulled and all enterprise applications had been badly crashed.

I looked into the JexcelApi source and saw that it has a log4.xml which set everything into debug mode and set up a file appender for file jxl.log. It was clear that it's a demo config file and because of the JCL configuration mechanism, the Log4 DOM Configurator gained control and did its job. As Andy Khan wrote "The sample log4j file included along with the distribution is only indicative" and as Kevin replied at the Yahoo JexcelApi group back in 2007: "I think the problem occurs when using jexcelapi in an environment that where multiple logging frameworks are used. Some libraries use log4j, some use commons logging and some use the jdk logging framework. The ones that use log4j or commons logging sometimes look for a log4j.xml on the classpath. When jexcelapi is jarred up, the log4j.xml gets stuck in the "root" of the jar and often gets picked up by log4j or commons logging. Since the default log4j config of jexcelapi is so broad, it ends up overwriting the policies of other libraries." Yes, I can confirm it's definitively a problem.

So, the narrower task was to fix this particular problem but the broader task was to prepare for those cases when a jar in a j2ee application contains a log4j config for any reasons.
  • It's a good fix to remove log4j.xml from the jar, but say when we talk about Maven build system, it's not a trivial task to dig into an artifact and change it. What's more, who want to care about changing third party dependencies even when using Ant? Fortunately, later versions of JXL don't contain this config file so it could be a good fix to use one of them. Conclusion for component builders to not to put log4j (and any) config into the root of the artifact.
  • However, it could happen that it's not enough to change the jar to a newer one, make a new build and deploy to the appserver, because the appserver may hold the configured loggers running and some jar files in a devious working directory and couldn't release them when undeploying. Additionally, when it restarts it may pick up again the old wrong jars. Particularly, we have had the old jar files in the application/j2ee-apps and the webapps' directory of the Glassfish's domain directory and couldn't delete it even by hand until the appserver had been stopped.
  • As Application #1 showed us, it may be a rough but useful practice to get the log4j config from a custom location by giving an absolute file name in an environment variable. (-D argument of the JVM.) But this defends only the particular application. And when we don't want to use log4j in that application we also have to give a log4j config just for hide the corrupted one, which is unacceptable.
  • A good practice according to me, to follow Andreas Shaefer's tip regarding set up log4j logging in Glassfish in his blog entry: To the hell with JDK logging II.. In our case it prevented Application #1 from corrupt logging by placing a log4j.xml to the very front of the classpath, however, it enabledApplication #2 to use its special config.
Otherwise, a correct and useful logging tip collection would be very handsome for J2EE environment, but not a one which says that every logger instance method invocation should be an EJB call.