Wednesday, March 03, 2010

Enable debug/trace level logging for Tomcat 6 Realms

Keywords:
tomcat 6 realm logging juli logging.properties debug="9" debug="99" debug="true" JNDIRealm trace verbose jndi realm JNDIRealm

Problem:
Apparently Tomcat 6 Logging is greatly improved ... more granularity, flexibility in choosing java.util.logging or log4j, etc. This is great, but I'm happy with the default logging - ie if something goes wrong let me get the detail from a log file.

This attitude hits a snag where things go wrong and there's nothing in the logs - in my case, setup of a org.apache.catalina.realm.JNDIRealm is not letting me in but there's no details why. It used to be a matter of simply setting debug="9" on the Realm definition and you have verbose logging - the examples in the Tomcat 6 Realm documentation still use this:
<Realm className="org.apache.catalina.realm.JNDIRealm" debug="99"
    connectionURL="ldap://localhost:389"
    userPattern="uid={0},ou=people,dc=mycompany,dc=com"
    roleBase="ou=groups,dc=mycompany,dc=com"
    roleName="cn"
    roleSearch="(uniqueMember={0})"
/>
But this has no effect on logging. You'll get a warning telling you as much:
03/03/2010 10:56:08 AM org.apache.tomcat.util.digester.SetPropertiesRule begin
WARNING: [SetPropertiesRule]{Server/Service/Engine/Realm} Setting property 'debug'
 to '99' did not find a matching property.
What's the minimum I have to do to enable debug?

Solution:
You have to edit the $CATALINA_HOME/conf/logging.properties file.

1. Configure debug logging for Realms and Authentication

Insert the following lines (in blue):
############################################################
# Facility specific properties.
# Provides extra control for each logger.
############################################################
# This would turn on trace-level for everything
# the possible levels are: SEVERE, WARNING, INFO, CONFIG, FINE, FINER, FINEST or ALL
#org.apache.catalina.level = ALL
#org.apache.catalina.handlers = 2localhost.org.apache.juli.FileHandler
org.apache.catalina.realm.level = ALL
org.apache.catalina.realm.useParentHandlers = true
org.apache.catalina.authenticator.level = ALL
org.apache.catalina.authenticator.useParentHandlers = true

org.apache.catalina.core.ContainerBase.[Catalina].[localhost].level = INFO
org.apache.catalina.core.ContainerBase.[Catalina].[localhost].handlers = 2localhost.org.apache.juli.FileHandler
This will give you debug/trace level logging to console and the file assuming you've kept the default config. But you only see debug in the console, not the catalina.[date yyyy-MM-dd].log file - in fact, the log file empty? The buffering means the file-logging is only written when the buffer is full.

2. Disable buffering for FileHandler logging

(until the issue is resolved of course) Insert the line (in blue):
1catalina.org.apache.juli.FileHandler.level = FINE
1catalina.org.apache.juli.FileHandler.directory = ${catalina.base}/logs
1catalina.org.apache.juli.FileHandler.prefix = catalina.
1catalina.org.apache.juli.FileHandler.bufferSize = -1
These two inserts give you pretty much the equivalent of the old debug="9" and you'll (hopefully) get the verbose information required - happy debugging ...