Logging in the Google AppEngine for Java (GAE/J) with slf4j, log4j and jul - and using Maven

Logging is an invaluable tool for debugging web applications, especially if you can't run them in debug mode. Developping an application on Google AppEngine allows you to do these steps prior to uploading it to the real server

• Run local JUnit tests (alhough that has its own problems if you use Jersey framework and an embedded Jetty)
• Run the application or the JUnit tests in debug mode (e.g. use mvn gae:debug and a remote debug session in Eclipse)
  
• Use logging

On the real appengine, you cannot run JUnit tests (at least I don't know how. Maybe you can somehow.) and you cannot run a remote debug session. Therefore you need logging. It's your only way to debug things that are different on the real appengine compared to the local test stub environment. And there are differences.

AppEngine uses java.utils.logging (also often called j.u.l. or just jul). As the blog from Fred Sauer (the man behin gwt-log) shows, the AppEngine web console nicely displays the differen log levels:

• DEBUG
• INFO
• WARN
• ERROR
• CRITICAL

AppEngine uses jul for logging, although ironically jul defines different log-levels, namelly:

• FINEST (lowest value)
• FINER
• FINE
  
• CONFIG
  
• INFO
• WARNING
• SEVERE (highest value) 

The mapping to the GAE levels is not completely clear to me yet.
To add more confusion to the mix, most code projects that I start today use slf4j, the Simple Logging Facade for Java. Slf4j allows to delegate to another logging framework and involves almost zero runtime overhead. Underneath I usually use log4j, an old, mature logging framework.

Clickable hyperlinks in log output
Log4j has nice things such as a PatternFormatter. If you use "(%F:%L)" in your pattern, you get "(Customer.java:33)", which your Eclipse console parses and turns it into a clickable link to the java file "Customer.java" in line 33. That is a very quick way from an unexpected log message to you fixing it: One click!
Be aware that line numbers in source code are rather expensive to generate, you should therefore not use this pattern in a production environment. However, you can simply use another confguration file, how nice.
There are other reasons for using framework such as log4j instead of just jul.

Situation
In my project I have this (not uncommon) situation:

• GAE uses jul
• Jersey uses jul
• Other bundled libraries and my code use slf4j

Goals

• Clickable hyperlinks for local testing
• Nice mapping from log levels to GAE icons
• Same dependencies for local testing and production deployment
  

Failed Attempts

• Use slf4j-jdk14 to route all log output to jul. This works and nicely uses the five different categories on the AppEngine, but at the cost of getting a default ugly pattern. Jul has no PatternFormatter.
• Write a custom formatter for jul.  This does not work, because a custom formatter can only be set to a known handler, such as the ConsoleHandler form jul. Unfortunately, the ConsoleHandler does not exist on AppEngine. Attemtps to get the existing handlers by creating a log and listing its handlers or parents failed: Its all emtpy on appengine.

Chosen Solution

• Use log4j with PatternFormatter
• Log4j put log messages to Sysatem.out which in turn are rendered by AppEngine as INFO level.
• Jersey and AppEngine still use all five levels and an ugly pattern.

Configuration
This is the main piece of this long post, because it didn't get it right first.

In  \src\main\webapp\WEB-INF\appengine-web.xml   you need to have

    <!-- Configure java.util.logging -->
    <system-properties>
        <property name="java.util.logging.config.file" value="WEB-INF/java-util-logging.properties"/>
    </system-properties>

to tell GAE where jul is configured.
In  \src\main\webapp\WEB-INF\java-util-logging.properties  you need

.level = ALL

or another of the jul level names, as you like (i.e. 'TRACE' does not work).

In \src\main\resources\log4j.properties  (if you put the file as usual in \src\test\resources\log4j.properties, it won't be deployed to the production server and hence you will have no logging there). In this file you will have

log4j.rootLogger=ALL, console

or a lower log level such as DEBUG, INFO or WARN.
And you can customize your output like:

log4j.appender.console=org.apache.log4j.ConsoleAppender
log4j.appender.console.layout=org.apache.log4j.PatternLayout
log4j.appender.console.layout.ConversionPattern=%-5p: %m  at %C.(%F:%L) on %d{ISO8601}%n

You may not use FileAppenders, as GAE does not allow to write files.
That's it. here is an overview how log messages will flow:

• GAE
  
• generates its own log messages and sends them to jul
• GAE checks if this level should be displayed (java-util-logging.properties), if yes:
• message appears at correct level with ugly pattern in GAE log
  
• Jersey
  
• generates log messages and sends them to jul
• GAE checks if this level should be displayed (java-util-logging.properties), if yes:
• message appears at correct level with ugly pattern in GAE log
  
• Other libraries and your code
  
• sends log messages to slf4j
• slf4j sends them to log4j
• log4j checks if this package & level should log (log4.properties), if yes:
• log message is formatted nicely
• and sends to System.out which is interpreted as a jul-messages at INFO level in GAE
  
• GAE checks if INFO level should be displayed (java-util-logging.properties), if yes:
• messages shown with nice pattern at INFO level in GAE log, real level represented as text. E.g. a complete log message then looks like this:
  03-02 02:05PM 23.948
  [myappname/1.340252283834355681].<stdout>: DEBUG: this is debug at org.example.app.Logtest.(Logtest.java:13) on 2010-03-02 22:05:23,947
  

So in the end you have 3 barriers for a log message until you see it:

• Log4j
• GAE's jul
• The drop-down box in AppEngine manager app (Show only requests will show everyhing including requests with no errors).
  

I hope this helps other people struggling with logging an maybe somebody has an even nicer solution.