Tomcat and Logging

Tomcat is a very popular java application server. It is very light weight and easy to use. It's derivative, tcserver, is also very nice. It has all the goodness of tomcat, and on top of that it gives you the feel of a real J2EE app server (tomcat is only java servlet compliant).

Logging from your webapp in tomcat is a piece of cake. For example, if you like to use SLF4J logging API together with logback as the backend, you just drop the jars in the webapp's WEB-INF/lib and the configuration (logback.groovy) in WEB-INF/classes and you're good to go.

You will notice, however, that something else is eating away your disk space beside your webapp's logs. Tomcat has its own logging. It writes several files, has its own logging configuration (and logging technology) and even does its own rotation for (only) some of the files. A log rotation scheme that can't be easily disabled and might not fit your global rotation scheme.

By default tomcat uses juli, which is based on the standard java.util.logging with some enhancements for supporting per-webapp configuration. This only matters to those that don't have their own logging set up inside their webapp. Also, the default configuration is quite surprising. It sets up several files for different categories that may or may not interest you.
There's:

manager.log and host-manager.log for the respective webapps (which you may not want to have deployed, but the empty log files will still be created).
localhost.log will have message about servlets coming up and down.
catalina.log will contain mostly internal tomcat messages.
Some logging messages will be sent to stdout and get mixed with actual direct writes to stdout/stderr as well as with the output from scripts that start and stop tomcat. If you redirect this to a file (catalina.out) it is not rotated and can grow very big over time. Some messages are send to both catalina.log and catalina out, which is confusing if not just redundant.

All the files created (this doesn't include the console output) use the juli file handler that by default adds a date stamp to the file name (for rolling). It is not configurable! You simply can't remove it (you can just change the prefix and suffix but there will always be a date in the middle).

These are all the options I can think about (after scouring the net for solutions):
* Replace tomcat logging with log4j or logback (requires dropping the jars in the bin dir and changing the startup script to include them in the classpath)
* Replace the juli FileHandler with the standard java.util.logging FileHandler and have only a single handler for everything, since we don't need the per-webapp logging (we set that up within the webapp)
* Use SocketHandler to write to syslog instead of directly into a file
* Use MemoryHandle since most of these message can be ignored until we actually have a problem
* Use nop logging configuration, but again we lose troubleshooting information

In any case setting the sallowOutput option to true in the context configuration file will catch some messages written to stdout/stderr and redirect them to the webapp logger. It doesn't catch all messages though (I think ones that are written early).

For rotation I want to use logrotate so it is possible to:
* Use SocketHandler to write to syslog, and syslog can be told to reopen its log files
* Enhance the logging framework to listen to a signal to reopen its files
* Use cronolog (but again we lose control of the file naming since it adds a date suffix - I want to use numbers)
* Use the (nonatomic) copytruncate option in logrotate but risk losing some messages

In the end I decided to do the following:
* Comment out everything it tomcat's logging.properties except a single catch-all FileHandler, using the default java.util.logging FileHandler instead of juli's. This includes disabling the ConsoleHandler (I don't need it since I'm running tomcat in a server and never interactively)
* Rotate the created files (the single log and the stdout redirected to a file) using logrotate with the copytruncate flag (this is not safe for the stdout file, but I don't expect it to grow much now that it doesn't include any of tomcat's own logging)
* Enabled the swallowOutput flag
* Use syslog for all the logback logs and rotate with logrotate them without copytruncate

Gradle ebuild

Latest ebuild can be found in github: https://github.com/asssaf/portage/tree/master/dev-java/gradle-bin

Pretty ugly (uses the bundled jars instead of installed ones), but it works.

# dev-java/gradle-bin-0.9_rc1.ebuild

# Copyright 1999-2010 Gentoo Foundation
# Distributed under the terms of the GNU General Public License v2

EAPI="2"

inherit java-pkg-2

MY_PN=${PN%%-bin}
#MY_PV=${PV/_pre/-preview-}
MY_PV=${PV/_rc/-rc-}
MY_P="${MY_PN}-${MY_PV}"

DESCRIPTION="Build Tool for Java"
SRC_URI="http://dist.codehaus.org/${MY_PN}/${MY_P}-bin.zip"
HOMEPAGE="http://www.gradle.org/"
LICENSE="Apache-2.0"
SLOT="0"
KEYWORDS="~x86"

RDEPEND=">=virtual/jdk-1.5"

IUSE=""

S="${WORKDIR}/${MY_P}"


src_unpack() {
unpack ${A}
}


# TODO we should use jars from packages, instead of what is bundled
src_install() {
#TODO set GRADLE_HOME
#local jar JARS="gradle-core gradle-open-api gradle-ui gradle-wrapper"

local gradle_home="${ROOT}/usr/share/${PN}"

insinto "${gradle_home}"
#doins gradle-imports || die "Failed to install files"

cd lib
for jar in *.jar; do
 java-pkg_newjar ${jar} ${jar}
done

insinto "${gradle_home}/lib/plugins"
doins plugins/*

#sed -i "s/-${PV}.jar/.jar/" bin/gradle || die "Failed to patch launcher script"
#dobin bin/gradle || die "Failed to copy launcher script"
java-pkg_dolauncher "gradle" --main org.gradle.launcher.GradleMain --java_args "-Dgradle.home=${gradle_home}"
}

Update (2-Aug-10): I'm getting a NoClassDefError when trying to run JUnit tests. I've switched to the stable 0.8, which seems to work fine (just renamed the ebuild).

Update (27-Aug-10): I found a workaround for this issue. Adding the following lines to the build.gradle file fixes it:

test.bootstrapClasspath('/opt/sun-jdk-1.6.0.20/jre/lib/rt.jar')
test.bootstrapClasspath('/usr/share/gradle-bin/lib/commons-lang-2.5.jar')

Also updated the ebuild to 0.9_rc1.

Update (3-Nov-10): I've added additional enhancements to the ebuild but decided that keeping the blog up to date is the wrong way to go about it so I'm doing all ebuild maintenance in github from now on. My portage repository is here (and this ebuild is under dev-java/gradle-bin).

BTrace Rocks!

At work we're using a maven based build process. On the build machine it takes a while to finish the complete build (about 2 hours).

One of the final parts of the build is to generate the mvn:site. This stage takes, in my opinion, longer than it would seem necessary. Looking at #top, the machine is almost idle and there are 14 processes listed in #ps, where the last one keeps changing (I guess it finishes a directory and a new is spawned for the next one).

Due to bad design, there's no logging whatsoever in this stage and the machine seems stuck. I wanted to debug this on the build machine but didn't want to distrupt the running build (so can't start in debug mode).

To the rescue comes BTrace. A DTrace clone for java, allowing you to write small java scripts that can monitor and profile running java code. BTrace allows you to attach to an existing JVM process, without requiring any special switches to be added a priori to its command line (although it does support an -agent scenario).

That was so cool! Just downloaded one of the examples on the BTrace site, found the process pid using #jps so I can attach to it, and voila. I get printouts of all file accesses done by maven.
The BTrace examples page is full of actuall useful scripts. For example there's a script to print stacktraces for all threads (similar to #jstack).

Profiling Java Applications

A new beta of simon 2 is out. Also, btrace (https://btrace.dev.java.net/source/browse/btrace/docs/usersguide.html?rev=1.6) looks like an interesting alternative to JIP. It even has a visualvm plugin.

Tomcat Logging, Another Rant

For integration with another application I need the logs comming out of tomcat to have predictable names. This is not a problem for my webapp log which is created by log4j. Apparently this can be done with java logging as well. However, the tomcat main log uses JULI by default, which always creates log files with the date embedded in the file name.

There doesn't seem to be a way to configure it otherwise (except to change the logging to use a different mechanism).

Eclipse Java Execution Environment Description Files

At work I'm working on a java project that needs some command line arguments passed to the JRE to work correctly (maximum allowed memory, etc.).

I have these set in the Installed JREs section in Eclipse's preferences which is all good. However, it gets real frustrating because whenever I upgrade my JDK these get lost. This is because the JDK I had is no longer there an is automatically removed by eclipse, and the new one is detected and added without any customizations.

So I tried to tell my project to use an "Execution Environment" instead of a specific JRE. However eclipse (3.4) doesn't let you modify it's list of execution enviroments (or customize the command line arguments). You can, however, define a new JRE using an Execution Environment Description file.

It was hard to find documentation about this so called .ee file. I found just one page that described the possible settings that can be put in the file, with a short description, but I had to reverse engineer the values for these settings.

Finally I came up with this, which actually works:

## Execution Environment description file for MyProject
-Dee.name=MyProject_EE
-Djava.home=${ee.home}/jre
-Dee.executable=${ee.home}/jre/bin/java
-Dee.executable.console=${ee.home}/jre/bin/java
-Dee.bootclasspath=${ee.home}/jre/lib/resources.jar:${ee.home}/jre/lib/rt.jar:${ee.home}/jre/lib/jsse.jar:${ee.home}/jre/lib/jce.jar:${ee.hom$
-Dee.language.level=1.6
-Dee.library.path=${ee.home}/jre/lib/i386:${ee.home}/jre/lib/i386/server
-Dee.src=${ee.home}/src.zip
-Dee.javadoc.http://java.sun.com/javase/6/docs/api/index.html
-Dee.ext.dirs=${ee.home}/jre/lib/ext
-Dee.vm.library=${ee.home}/jre/lib/i386/server/libjvm.so
-server
-Xmx768m
-XX:MaxNewSize=384m
-XX:MaxPermSize=144m
-XX:+UseConcMarkSweepGC
-XX:+CMSClassUnloadingEnabled
-Dcom.sun.management.jmxremote=true
-Dcom.sun.management.jmxremote.authenticate=false
-Dcom.sun.management.jmxremote.ssl=false

Notice the ${ee.home} in the paths. It seems that this is the only variable that can be used in the ee file. It get's replaced with the path to the ee file, so for this to work the ee file must be placed in the JDK's base directory.
The reason I'm using this variable instead of absolute paths is that on the next JDK upgrade I'll just need to copy the file to the new JDK's directory and it will continue working (soft linking the jdk directory doesn't work - eclipse follows the links and creates a broken JRE).
Of course you could generate a new ee file for each JDK version.

I also created another variant of this ee file with JIP command line arguments, so I have two JREs defined. This way when ever I want to profile my project, I don't need to create a special runtime configuration, but just choose a the other JRE. To make things even easier, I have two Server (tomcat) definitions, one with each JRE. Starting tomcat with JIP is just a matter of starting the second server instead of the first. Pretty nifty.
BTW, the extra setting for JIP is:

-javaagent:/usr/local/jip-1.1.1/profile/profile.jar -Dprofile.properties=/var/proj/MyProject/webapp.profile.properties

P.S.: It would be great to see this file coming from the upstream package. Maybe sun can include it in their JDK distrubtion, or maybe it could be added to gentoo's package (possibly with an eclipse/OSGi use flag?)