- 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
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
- FINEST (lowest value)
- FINER
- FINE
- CONFIG
- INFO
- WARNING
- SEVERE (highest value)
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
- Clickable hyperlinks for local testing
- Nice mapping from log levels to GAE icons
- Same dependencies for local testing and production deployment
- 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.
- 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.
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
- Log4j
- GAE's jul
- The drop-down box in AppEngine manager app (Show only requests will show everyhing including requests with no errors).
