How to control logging by 3rd-party components in webapp in Tomcat 5.5?

StackOverflow https://stackoverflow.com/questions/5479304

Question

We are using Tomcat 5.5 on Linux. Our webapp uses log4j for its logging (functionally-based and not many loggers), and intentionally sets the additivity of the loggers to false. Our loggers log to our own logfile. None of them log to the console.

A problem we are having is that when the level of our loggers are set to DEBUG we start getting lots of debug logging in catalina.out from 3rd party components, particularly oscache.

There is a minimal log4j.properties file in .../common/classes:

log4j.rootLogger=INFO, A1
log4j.appender.A1=org.apache.log4j.ConsoleAppender
log4j.appender.A1.layout=org.apache.log4j.PatternLayout

# Print the date in ISO 8601 format
log4j.appender.A1.layout.ConversionPattern=%d [%t] %-5p %c - %m%n

There is no log4g.properties file in .../webapps/ourapp/WEB-INF/classes.

The first thing I tried was changing to log4j.rootLogger=ERROR, A1 but that made no difference.

The next thing i tried was creating a .../webapps/ourapp/WEB-INF/classes/log4j.properties file containing the single line

log4j.logger.com.opensymphony.oscache=ERROR

to see if that would stop the oscache logging. It did, but surprisingly (to me) it stopped all the unwanted logging, not just the oscache logging. So I commented the line out and tried again. Still no unwanted logging from anything. I moved the file aside and now the unwanted logging came back. I created a zero-length log4j.properties and all the unwanted logging went away again (!) While that's short-term what I want, it makes me wonder about what other logging is being thrown away (and why!). So I'm uncomfortable just relying on that.

The "Logging" chapter in the Tomcat 5.5 docs merely says that you can do per-app configuration by putting a properties file in WEB-INF/classes but doesn't (at least not that I could find) talk about how that interacts with the configuration specified in common/classes.

So:

  • How are the 3rd-party components logging to catalina.out in the first place? I guess their logging could bubble up to the root logger but then why do they still log even when the root logger level is turned up to ERROR?
  • Why does setting the logger level on our loggers to DEBUG make this logging start? We have our own names for our loggers so there is no way the oscache and other stuff could be ancestors of our loggers.
  • Why does even a zero-length WEB-INF/classes/log4j.properties file stop a whole bunch of logging?
  • How can I do this the "right" way and limit the logging in a meaningful way rather than relying on some weird (to me) side effect to turn it off?

Curiouser and curiouser. I tried matt's suggestion of turning on debugging. I also made a more extensive log4j.properties file for the webapp:

log4j.rootLogger=INFO, SSOA1
log4j.appender.SSOA1=org.apache.log4j.ConsoleAppender
log4j.appender.SSOA1.layout=org.apache.log4j.PatternLayout

# Print the date in ISO 8601 format
log4j.appender.SSOA1.layout.ConversionPattern=%d [%t] %-5p %c - %m%n

log4j.logger.com.opensymphony.oscache=ERROR
#log4j.additivity.com.opensymphony.oscache=false

When tomcat starts up I see:

log4j: Using URL [file:/srv/www/tomcat5/base/webapps/myapp/WEB-INF/classes/log4j.properties] for automatic log4j configuration.
log4j: Reading configuration from URL file:/srv/www/tomcat5/base/webapps/myapp/WEB-INF/classes/log4j.properties
log4j: Parsing for [root] with value=[INFO, SSOA1].
log4j: Level token is [INFO].
log4j: Category root set to INFO
log4j: Parsing appender named "SSOA1".
log4j: Parsing layout options for "SSOA1".
log4j: Setting property [conversionPattern] to [%d [%t] %-5p %c - %m%n].
log4j: End of parsing for "SSOA1".
log4j: Parsed "SSOA1" options.
log4j: Parsing for [com.opensymphony.oscache] with value=[ERROR].
log4j: Level token is [ERROR].
log4j: Category com.opensymphony.oscache set to ERROR
log4j: Handling log4j.additivity.com.opensymphony.oscache=[null]
log4j: Finished configuring.

But despite the fact the oscache logger is having its level set to error, I still see stuff like this in the log:

2011-03-30 14:53:22,076 [main] DEBUG com.opensymphony.oscache.base.algorithm.AbstractConcurrentReadCache - get called (key=AUDIT_KEY_OLDEST_TIMSTAMP)

If I'm forcing the oscache logger level to ERROR (which the log4j debug output says I am), then why is this DEBUG message being sent at all? The child logger overriding the level in code?

What I did notice is that if I uncomment out the "additivity" line for the oscache logger in the webapp's log4j.properties file then the logging really does go away. So it appears the oscache logging is relying on ancestor appenders and not its own. But then it seems all the weirder that setting the oscache logger level to ERROR isn't stopping these things.

Was it helpful?

Solution 2

I've figured out what the heck is going on. The problem is that buried down in the bowels of another part of the webapp is the following code that is run when that component is put into debug mode:

public static synchronized void setDebugOn(boolean debugOn) {
    if (isAllDebugOn() ^ debugOn) {
        setAllDebugOn(debugOn);
        Enumeration en = LogManager.getCurrentLoggers();
        while (en.hasMoreElements()) {
            setDebugOn((Logger) en.nextElement(), debugOn);
        }
        setDebugOn(LogManager.getRootLogger(), debugOn);
    }
}

public static void setDebugOn(String name, boolean debugOn) {
    setDebugOn(getLogger(name), debugOn);
}

private static void setDebugOn(Logger logger, boolean debugOn) {
    logger.setLevel(debugOn ? Level.DEBUG : Level.INFO);
}

In other words, when this component is put in debug mode, it also puts EVERY SINGLE LOG4J LOGGER IN THE WEBAPP into debug mode (which I've verified by changing the code to print out the name of every logger inside of the last method of those three. So blammo -- all the 3rd-party stuff that happens to use log4j starts getting its debug output logged regardless of what log4j.properties says. Sigh.

When I change the method with that loop to only mess with the levels of specific loggers related to that component then my log4j.properties configuration starts working as expected.

OTHER TIPS

You could configure log4j.properties to get only your code logs as below and put it inot different file than catalina.out too.

handlers = org.apache.juli.FileHandler

org.apache.juli.FileHandler.level=ALL org.apache.juli.FileHandler.directory=${catalina.base}/logs org.apache.juli.FileHandler.prefix=yourapp-name.

com.yourproject.module.package.level=ALL

Licensed under: CC-BY-SA with attribution
Not affiliated with StackOverflow
scroll top