Friday, January 19, 2007

Configuring logging in your Spring configuration file

I detest multiple configuration files. Generally, I can't avoid having them, but whenever I can find a way to reduce the number of configuration files, the better.

So, when I need to tailor the logging levels in my application, I have a choice: edit the default logging file (possibly effecting other applications if that copy of the JDK is shared as is typical), or create a separate logging configuration file and point logging to it (in the case of the JDK's logging, this means setting the java.util.logging.config.file property).

When using Spring, I'd really like to put my custom logging levels in my Spring configuration file, so I don't have yet another file that has to travel with my application. There doesn't appear to be any way built into Spring to do this, but by adding a tiny Java class to the application (one that is reusable for each application), we gain the ability to do this.

The idea is to create a bean at the top of your Spring configuration file that will set your custom logging levels. For example:

<bean id="loggingConfigurer"
class="com.acme.logging.LoggingConfigurer"
lazy-init="false">
<constructor-arg>
<props>
<prop key="org.springframework">WARNING</prop>
<prop key="org.hibernate">WARNING</prop>
</props>
</constructor-arg>
</bean>

The LoggingConfigurer class is trivial:

package com.acme.logging;

import java.util.Iterator;
import java.util.Properties;
import java.util.logging.Level;
import java.util.logging.Logger;

/**
* Configures logging by being constructed.
* Especially useful when created as a bean from a Spring configuration file.
*/
public class LoggingConfigurer {

public LoggingConfigurer(Properties props) {
Iterator i = props.keySet().iterator();
while (i.hasNext()) {
String loggerName = (String) i.next();
String levelName = props.getProperty(loggerName);
try {
Level level = Level.parse(levelName);
Logger l = Logger.getLogger(loggerName);
l.setLevel(level);
}
catch ( IllegalArgumentException e ) {
System.err.println( "WARNING: Unable to parse '"
+ levelName + "' as a java.util.Level for logger "
+ loggerName + "; ignoring..." );
}
}
}
}

Now, when Spring is initialized, very early on in the process, it encounters the entry for our loggingConfigurer bean. Since the bean has lazy initialization turned off, it is immediately created and configured. That sets our logging levels to what we want.

Admittedly, this isn't perfect. For example, these few lines of logging show up when launching a Spring and Hibernate application (prior to our bean turning the logging level to WARNING):

Jan 19, 2007 3:44:41 PM org.springframework.core.CollectionFactory
INFO: JDK 1.4+ collections available
Jan 19, 2007 3:44:41 PM org.springframework.beans.factory.xml.XmlBeanDefinitionReader loadBeanDefinitions
INFO: Loading XML bean definitions from class path resource [baseContext.xml]
Jan 19, 2007 3:44:41 PM org.springframework.beans.factory.xml.XmlBeanDefinitionReader loadBeanDefinitions
INFO: Loading XML bean definitions from class path resource [unitTestingContext.xml]
Jan 19, 2007 3:44:41 PM org.springframework.context.support.AbstractRefreshableApplicationContext refreshBeanFactory
INFO: Bean factory for application context [org.springframework.context.support.ClassPathXmlApplicationContext;hashCode=2490106]: org.springframework.beans.factory.support.DefaultListableBeanFactory defining beans [loggingConfigurer,hibernateStatsService,mbeanServer,exporter,persistence,setPersistenceManager,customEditorConfigurer,mySessionFactory]; root of BeanFactory hierarchy
Jan 19, 2007 3:44:41 PM org.springframework.context.support.AbstractApplicationContext refresh
INFO: 8 beans defined in application context [org.springframework.context.support.ClassPathXmlApplicationContext;hashCode=2490106]
Jan 19, 2007 3:44:41 PM org.springframework.context.support.AbstractApplicationContext initMessageSource
INFO: Unable to locate MessageSource with name 'messageSource': using default [org.springframework.context.support.DelegatingMessageSource@a9a32c]
Jan 19, 2007 3:44:41 PM org.springframework.context.support.AbstractApplicationContext initApplicationEventMulticaster
INFO: Unable to locate ApplicationEventMulticaster with name 'applicationEventMulticaster': using default [org.springframework.context.event.SimpleApplicationEventMulticaster@2153fe]
Jan 19, 2007 3:44:41 PM org.springframework.beans.factory.support.DefaultListableBeanFactory preInstantiateSingletons
INFO: Pre-instantiating singletons in factory [org.springframework.beans.factory.support.DefaultListableBeanFactory defining beans [loggingConfigurer,hibernateStatsService,mbeanServer,exporter,persistence,setPersistenceManager,customEditorConfigurer,mySessionFactory]; root of BeanFactory hierarchy]

But this is a great improvement over the huge amounts of output from Spring and (especially) Hibernate that show up otherwise.

I'm sure a similar approach can be used with log4j. If anyone adapts this to log4j I'd love to know how that works.

4 comments:

Anonymous said...

Very cool, I was looking for something like this. Thanks!

freddy

Will Sargent said...

Did this for log4j:

http://tersesystems.com/post/9700076.jhtml

It's crude, but it'll work.

Claus said...

That's exactly what I was looking for. But it doesn't work. The bean is initialized by Spring but the debug output is printed regardless of the level.
The application I'm working on is a Tomcat 6 based Web-Application using Spring/Hibernate in the back-end.
Although I turned debug output for org.hibernate OFF, it fills the screen...
Help very much appreciated

Brian Gilstrap said...

Claus, Tomcat 6 has an implementation of java.utl.logging that is per-classloader. Are you including the hibernate jars with each webapp? If not, then you are probably altering the logging level for your webapp and not for the classloader that executes hibernate.

See the docs (http://tomcat.apache.org/tomcat-6.0-doc/logging.html) for the details.