Which logger is selected?
A commonly used logger is Apache Log4J. But there are also other loggers. And there are many default configuration which make the whole thing mysterious. Let’s take a look. In this analysis, we are using Apache commons-logging-1.0.4.jar and log4j-1.2.8.jar.A typical first call to the logger is the following as in a class BatchJob.java:
public class BatchJob
{
private static Log logger = LogFactory.getLog(BatchJob.class);
...
}Most of the secrets are implemented in the following class
org.apache.commons.logging.impl.LogFactoryImpl extends LogFactory.The class LogFactory is in the same package. The javadoc of the class LogFactoryImpl reveals how the logging implementation is selected. The javadoc is the following:
Concrete subclass of LogFactory that implements the following algorithm to dynamically select a logging implementation class to instantiate a wrapper for.
- Use a factory configuration attribute named org.apache.commons.logging.Log to identify the requested implementation class.
- Use the org.apache.commons.logging.Log system property to identify the requested implementation class.
- If Log4J is available, return an instance of org.apache.commons.logging.impl.Log4JLogger.
- If JDK 1.4 or later is available, return an instance of org.apache.commons.logging.impl.Jdk14Logger.
- Otherwise, return an instance of org.apache.commons.logging.impl.SimpleLog.
The selection algorithm will become clearer if you look at the actual code in the class LogFactoryImpl:
/**
* Return the fully qualified Java classname of the Log
* implementation we will be using.
*/
protected String getLogClassName() {
// Return the previously identified class name (if any)
if (logClassName != null) {
return logClassName;
}
logClassName = (String) getAttribute(LOG_PROPERTY);
if (logClassName == null) { // @deprecated
logClassName = (String) getAttribute(LOG_PROPERTY_OLD);
}
if (logClassName == null) {
try {
logClassName = System.getProperty(LOG_PROPERTY);
} catch (SecurityException e) {;}
}
if (logClassName == null) { // @deprecated
try {
logClassName = System.getProperty(LOG_PROPERTY_OLD);
} catch (SecurityException e) {;}
}
if ((logClassName == null) && isLog4JAvailable()) {
logClassName = "org.apache.commons.logging.impl.Log4JLogger";
}
if ((logClassName == null) && isJdk14Available()) {
logClassName = "org.apache.commons.logging.impl.Jdk14Logger";
}
if ((logClassName == null) && isJdk13LumberjackAvailable()) {
logClassName =
"org.apache.commons.logging.impl.Jdk13LumberjackLogger";
}
if (logClassName == null) {
logClassName = "org.apache.commons.logging.impl.SimpleLog";
}
return (logClassName);
}In the test case that I executed with the batch job, if you put the log4j-1.2.8.jar in the classpath, the logger class used will be org.apache.commons.logging.impl.Log4JLogger. Otherwise, the logger class is org.apache.commons.logging.impl.Jdk14Logger.
How to configure log attributes.
One mistake that I made was to put something like the following in the command line:-Dlog4j.configuration=file:/c:/workspaces/appName/src/config/jobs/job1.propertiesNotice: In eclipse, the -Dlog4j.configuration must be set as VM arguments, not the Program arguments.
The purpose is for the logger to use the configuration in the job1.properties file. But it does not work! Finally I found that this is because I did not put log4j-1.2.8.jar on the classpath. Obviously the log4j.configuration option only works for Log4JLogger in log4j-1.2.8.jar, not other logger class such as Jdk14Logger !
Besides the command line option for specifying log attributes, a more familiar way is to use the log4j.properties file. From my test results, if you use Log4JLogger, you can put log4j.properties on the classpath, and it will be picked up by the logger. But what if you also specify the commandline –Dlog4j.configuration parameter? The answer is that the command line property file will override the log4j.properties file. This is not a surprise. I believe this is a convention of Java. For example, if you specify classpath using –cp option in the command line, it will override the environment variable CLASSPATH.
Advanced class loader stuff
Now the next thing that is interesting is how the LogFactoryImpl determines if log4j is available to use. The actual method is the following:/**
* Is a Log4J implementation available?
*/
protected boolean isLog4JAvailable() {
try {
loadClass("org.apache.log4j.Logger");
loadClass("org.apache.commons.logging.impl.Log4JLogger");
return (true);
} catch (Throwable t) {
return (false);
}
}
As a comparison, the following method determines if the jdk logger is available:/** * ReturnIn all cases, the essential method called is loadClass(), which is the following:trueif JDK 1.4 or later logging * is available. Also checks that theThrowableclass * supportsgetStackTrace(), which is required by * Jdk14Logger. */ protected boolean isJdk14Available() { try { loadClass("java.util.logging.Logger"); loadClass("org.apache.commons.logging.impl.Jdk14Logger"); Class throwable = loadClass("java.lang.Throwable"); if (throwable. getDeclaredMethod("getStackTrace", null) == null) { return (false); } return (true); } catch (Throwable t) { return (false); } }.
private static Class loadClass( final String name )
throws ClassNotFoundException
{
Object result = AccessController.doPrivileged(
new PrivilegedAction() {
public Object run() {
ClassLoader threadCL = getContextClassLoader();
if (threadCL != null) {
try {
return threadCL.loadClass(name);
} catch( ClassNotFoundException ex ) {
// ignore
}
}
try {
return Class.forName( name );
} catch (ClassNotFoundException e) {
return e;
}
}
});
if (result instanceof Class)
return (Class)result;
throw (ClassNotFoundException)result;
}
Notice that a general programming rule is that we should not use exception for decision making. But in the special case here, we are using the ClassNotFoundException to determine if the logger implementation class is available.The above method uses the following method, which is also in LogFactoryImpl:
/**
* Return the thread context class loader if available.
* Otherwise return null.
*
* The thread context class loader is available for JDK 1.2
* or later, if certain security conditions are met.
*
* @exception LogConfigurationException if a suitable class
* loader cannot be identified.
*/
protected static ClassLoader getContextClassLoader()
throws LogConfigurationException
{
ClassLoader classLoader = null;
try {
// Are we running on a JDK 1.2 or later system?
Method method = Thread.class.
getMethod("getContextClassLoader", null);
// Get the thread context class loader (if there is one)
try {
classLoader = (ClassLoader)method.
invoke(Thread.currentThread(), null);
} catch (IllegalAccessException e) {
throw new LogConfigurationException
("Unexpected IllegalAccessException", e);
} catch (InvocationTargetException e) {
/**
* InvocationTargetException is thrown by
* 'invoke' when the method being invoked
* (getContextClassLoader) throws an exception.
*
* getContextClassLoader() throws
* SecurityException when the context class
* loader isn't an ancestor of the calling class's
* class loader, or if security permissions are
* restricted.
*
* In the first case (not related), we want to ignore
* and keep going. We cannot help but also ignore
* the second with the logic below, but other calls
* elsewhere (to obtain a class loader) will trigger
* this exception where we can make a distinction.
*/
if (e.getTargetException() instanceof
SecurityException) {
; // ignore
} else {
// Capture 'e.getTargetException()' exception for
// details alternate: log 'e.getTargetException()',
// and pass back 'e'.
throw new LogConfigurationException
("Unexpected InvocationTargetException",
e.getTargetException());
}
}
} catch (NoSuchMethodException e) {
// Assume we are running on JDK 1.1
classLoader = LogFactory.class.getClassLoader();
}
// Return the selected class loader
return classLoader;
}
Configuration of java.util.logging.Logger
Some applications use java.util.logging.Logger. For example, the reference implementation of JSF from sun jsf-impl-1.2.jar uses this logger in the source code. How to configure it?By default, this logger uses the configuration file in %JAVA_HOME%/jre/lib/logging.properties. In order to customize this, you can create a properties file, say C:\workshop\foo\logs\logging.properties. Then you need pass this as a parameter when invoking java:
-Djava.util.logging.config.file=C:\workshop\foo\logs\logging.properties
The following is a sample file logging.properties:
#logging.properties handlers= java.util.logging.FileHandler, java.util.logging.ConsoleHandler .level=FINE java.util.logging.FileHandler.pattern = C:/workshop/foo/logs/java%u.log java.util.logging.FileHandler.formatter = java.util.logging.SimpleFormatter
This property file will cause the log to go to the file C:/workshop/foo/logs/java%u.log and the log level is FINE. Here %u is a count number. It will be 0, etc. See http://docs.oracle.com/javase/1.4.2/docs/api/java/util/logging/FileHandler.html for details about how to configure the location of this file.
Merge java.util.log into log4j
Say you are using Log4j in your application. And the application uses a third party library that uses java.util.logging. You can configure for each log. But the log messages will go to separate log files. You would like these log messages to go to the same log file in the time order that they are generated. How to do that? A web application using jsf-impl-1.2.jar of Sun is such an application because jsf-impl-1.2.jar uses java.util.logging. The following is one solution.You can delegate the log from java.util.log to log4j. The website http://wiki.apache.org/myfaces/Trinidad_and_Common_Logging has a class JavaLoggingToCommonLoggingRedirector.java. To use this class in the web application. You can do the following.
- Copy the class JavaLoggingToCommonLoggingRedirector.java into your project. For example, you can have the following:
package com.foo.example.util; import java.util.Map; import java.util.concurrent.ConcurrentHashMap; import java.util.logging.Handler; import java.util.logging.Level; import java.util.logging.LogManager; import java.util.logging.LogRecord; import java.util.logging.Logger; import org.apache.commons.logging.Log; import org.apache.commons.logging.LogFactory; /** * Writes JDK log messages to commons logging. */ public class JavaLoggingToCommonLoggingRedirector { static JDKLogHandler activeHandler; /** * Activates this feature. */ public static void activate() { try { Logger rootLogger = LogManager.getLogManager().getLogger(""); // remove old handlers for (Handler handler : rootLogger.getHandlers()) { rootLogger.removeHandler(handler); } // add our own activeHandler = new JDKLogHandler(); activeHandler.setLevel(Level.ALL); rootLogger.addHandler(activeHandler); rootLogger.setLevel(Level.ALL); // done, let's check it right away!!! Logger.getLogger(JavaLoggingToCommonLoggingRedirector.class.getName()).info("activated: sending JDK log messages to Commons Logging"); } catch (Exception exc) { LogFactory.getLog(JavaLoggingToCommonLoggingRedirector.class).error("activation failed", exc); } } public static void deactivate() { Logger rootLogger = LogManager.getLogManager().getLogger(""); rootLogger.removeHandler(activeHandler); Logger.getLogger(JavaLoggingToCommonLoggingRedirector.class.getName()).info("dactivated"); } protected static class JDKLogHandler extends Handler { private Map<String, Log> cachedLogs = new ConcurrentHashMap<String, Log>(); private Log getLog(String logName) { Log log = cachedLogs.get(logName); if (log == null) { log = LogFactory.getLog(logName); cachedLogs.put(logName, log); } return log; } @Override public void publish(LogRecord record) { Log log = getLog(record.getLoggerName()); String message = record.getMessage(); Throwable exception = record.getThrown(); Level level = record.getLevel(); if (level == Level.SEVERE) { log.error(message, exception); } else if (level == Level.WARNING) { log.warn(message, exception); } else if (level == Level.INFO) { log.info(message, exception); } else if (level == Level.CONFIG || level == Level.FINE ) { log.debug(message, exception); } else { log.trace(message, exception); } } @Override public void flush() { // nothing to do } @Override public void close() { // nothing to do } } }Note that I modified the class a little bit. I added the code "|| level == Level.FINE" to log FINE messages as DEBUG messages.
- In web.xml, add the following:
<listener> <listener-class> com.foo.example.util.LogUtilListener</listener-class> </listener>
The listener class is the following:
package com.foo.example.util; import javax.servlet.ServletContextEvent; import javax.servlet.ServletContextListener; public class LogUtilListener implements ServletContextListener { public void contextInitialized(ServletContextEvent arg0) { JavaLoggingToCommonLoggingRedirector.activate(); } public void contextDestroyed(ServletContextEvent arg0) { JavaLoggingToCommonLoggingRedirector.deactivate(); } } - Modify the log4j.properties to log the message from the third-party library. In our case, the library is jsf-impl-1.2.jar. Assume that you want to see the log messages from the package com.sun.faces.lifecycle in jsf-impl-1.2.jar. You can add the following:
log4j.logger.javax.enterprise.resource.webcontainer.jsf=DEBUG,fileout
Note that if you uselog4j.logger.com.sun.faces=DEBUG,fileout
then it won't work even though the class LifecycleImpl is in the package com.sun.faces.lifecycle. This is surprising. But after looking at the source code of LifecycleImpl.java, you can see the reason. In that class, the logger is defined as follows:
private static Logger logger = Util.getLogger(Util.FACES_LOGGER + Util.LIFECYCLE_LOGGER);And Util.FACES_LOGGER has the value "javax.enterprise.resource.webcontainer.jsf" ! That is why we need to use this value in log4j.properties. You can also use the complete name "Util.FACES_LOGGER + Util.LIFECYCLE_LOGGER" which is equal to "javax.enterprise.resource.webcontainer.jsf.lifecycle". But since "javax.enterprise.resource.webcontainer.jsf" is a "parent" logger name of it, so that will cover the subpackages.
On the other hand, if you just use java.util.logging and check the log file, you can see that the log messages contain the package name and even the method name! The following is the sample:
Jan 30, 2012 3:03:07 PM com.sun.faces.lifecycle.LifecycleImpl execute FINE: Skipping rest of execute() because of a reload Jan 30, 2012 3:03:09 PM com.sun.faces.lifecycle.LifecycleImpl render FINE: render(com.icesoft.faces.context.BridgeFacesContext@d0da01) Jan 30, 2012 3:03:09 PM com.sun.faces.lifecycle.LifecycleImpl phase FINE: phase(RENDER_RESPONSE 6,com.icesoft.faces.context.BridgeFacesContext@d0da01) Jan 30, 2012 3:03:09 PM com.sun.faces.lifecycle.RenderResponsePhase execute FINE: Entering RenderResponsePhase Jan 30, 2012 3:03:09 PM com.sun.faces.lifecycle.RenderResponsePhase execute FINE: About to render view /home.jspxThe corresponding log code in java in the class LifeCycleImpl.java is as follows:
public class LifecycleImpl extends Lifecycle {
...
public void execute(FacesContext context) throws FacesException {
......
for (int i = 1; i < phases.length; i++) { // Skip ANY_PHASE placeholder
if (context.getRenderResponse() ||
context.getResponseComplete()) {
break;
}
phase((PhaseId) PhaseId.VALUES.get(i), phases[i], context);
if (reload((PhaseId) PhaseId.VALUES.get(i), context)) {
if (logger.isLoggable(Level.FINE)) {
logger.fine("Skipping rest of execute() because of a reload");
}
context.renderResponse();
}
}
}
...
}
As the comparison, the log messages from log4j after the log merge are as follows:
2012-02-01 16:29:33,219 DEBUG [lifecycle]: Skipping rest of execute() because of a reload 2012-02-01 16:29:33,797 DEBUG [lifecycle]: render(com.icesoft.faces.context.BridgeFacesContext@8673f8) 2012-02-01 16:29:33,797 DEBUG [lifecycle]: phase(RENDER_RESPONSE 6,com.icesoft.faces.context.BridgeFacesContext@8673f8) 2012-02-01 16:29:33,797 DEBUG [lifecycle]: Entering RenderResponsePhase 2012-02-01 16:29:33,797 DEBUG [lifecycle]: About to render view /home.jspxIf you want to see the actual class name and method name of the log message from java.util.logging, you can modify the JDKLogHandler class:
public void publish(LogRecord record) {
Log log = getLog(record.getLoggerName());
String message = record.getMessage();
Throwable exception = record.getThrown();
String completeClassName = record.getSourceClassName();
int pos = completeClassName.lastIndexOf(".");
String className = completeClassName.substring(pos + 1);
String methodName = record.getSourceMethodName();
message = className + ":" + methodName + " " + message;
Level level = record.getLevel();
...
}
Here we make use of the class java.util.logging.LogRecord. This class has the API that gives the class name and method name.
Note that the strategy used above to delegate java util log to log4j works for a single web application. If there are multiple web applications on the same server, the java util log in different web applications will be delegated to the same log file. To avoid this, you have to do something different. Reference[1] gives a solution for this.
References
- http://blog.mycila.com/2011/01/jdk-logging-per-webapp.html
- http://www.slf4j.org
No comments:
Post a Comment