GAE and Log4j - Getting them to work a bit better together

Sunday, 3 October 2010

The Problem
App Engine supports Log4j, and you'll be able to see your log4j statements come through either as a stdout or stderr message. The trouble that I've had is that if you want to make full use of the nice log highlighting GAE supports in its console then all stdout / stderr messages will come through as a warning.

A good portion of Java frameworks use Log4j as their logging framework. I'm using Apache Wicket as my front-end framework for example, and when user has hit upon a bug on a page, I'd like to know about it as an error and not just a warning.

A Solution
Here's a Log4j Appender which I've written that creates JUL log statements based on original Log4j log events. A Log4j -> JUL bridge if you like, passing on the original severity level to JUL. It's pretty basic, but it works for me!

Here's the code for the Appender itself:
/**
 * 
 * @author Eurig Jones
 */
public class GAELogAppender extends AppenderSkeleton
{
    private static final Logger L = Logger.getLogger("log4j");

    @Override
    protected void append(LoggingEvent event)
    {
        StringBuilder b = new StringBuilder();
        Level level = event.getLevel();
        String s[] = event.getThrowableStrRep();

        b.append(event.getMessage().toString());

        if (s != null)
            for (String line : s)
                b.append(line).append('\n');

        if (level.equals(Level.FATAL))
            FATAL(b.toString());
        if (level.equals(Level.ERROR))
           ERROR(b.toString());
        if (level.equals(Level.WARN))
           WARN(b.toString());
        if (level.equals(Level.INFO))
           INFO(b.toString());
        if (level.equals(Level.DEBUG))
           DEBUG(b.toString());
        if (level.equals(Level.TRACE))
           TRACE(b.toString());
    }

    private void FATAL(String msg)
    {
        L.severe(msg);
    }

    private void ERROR(String msg)
    {
        L.severe(msg);
    }

    private void WARN(String msg)
    {
        L.warning(msg);
    }

    private void INFO(String msg)
    {
        L.info(msg);
    }

    private void DEBUG(String msg)
    {
        L.fine(msg);
    }

    private void TRACE(String msg)
    {
        L.finest(msg);
    }

    @Override
    public boolean requiresLayout()
    {
        return false;
    }

    @Override
    public void close()
    {
    }
}
Now all we need to do is setup the log4j.properties and logging.properties configurations correctly to make it work. Here is a snippet of my log4j.properties:
#log4j.appender.A1=org.apache.log4j.ConsoleAppender
#log4j.appender.A1.layout=org.apache.log4j.PatternLayout
#log4j.appender.A1.layout.ConversionPattern=%d ...
#log4j.appender.A1=org.apache.log4j.jul.JULAppender

log4j.appender.A1=chesspresso.server.log.GAELogAppender

log4j.logger=ERROR, A1

...
log4j.logger.org.apache.wicket=WARN, A1
...
Above shows that I've replaced the original ConsoleAppender - the default appender which GAE uses, with the new GAELogAppender. This allowing all Log4j statements to go through this instead of the console.

Now the GAE logging.properties file...
.level = INFO
chesspresso.server.log.GAELogAppender=FINEST
...
As you can see, I've added the GAELogAppender here to allow all severities to be filtered through. This means that anything that hits our new appender will reach the GAE logging system, as long as our log4j.properties will allow it to filter through.

I'm still a bit unsure of how exactly GAE Maps JUL severities in it's frontend. In JUL you have FINEST, FINER, INFO, WARNING, SEVERE but the front-end seems to display these differently. It has an ERROR and CRITICAL as well as a WARNING. SEVERE seems to be flagged as an ERROR, but how can you flag something as CRITICAL? Maybe it's in some documentation I've probably scanned through :-)

This is a quick implementation of this Appender for me and so far it works, but I'd love to hear some feedback about what it doesn't do (or doesn't do properly) as I've not used it in anger.

3 comments:

bf said...

This is faster:

if (level.equals(Level.FATAL))
FATAL(b.toString());
else if(level.equals(Level.ERROR))
ERROR(b.toString());
else if(level.equals(Level.WARN))
WARN(b.toString());
else if (level.equals(Level.INFO))
INFO(b.toString());
else if (level.equals(Level.DEBUG))
DEBUG(b.toString());
else //if (level.equals(Level.TRACE))
TRACE(b.toString());

Eurig Jones said...

Yes thanks!

And even quicker would be to order that if/else block based on how often levels are hit. So if debug is the most common call, then put that on the top.

bf said...

Your logging.properties is not correct. To let GAELogAppender log everything to JUL if it wants to you need this line:

log4j.level=ALL

as you created the logger with Logger.getLogger("log4j");