[Springframework-developer] Going insane - Log4J logging in Spring

SourceForge Headquarters 1320 Columbia Street Suite 310 San Diego, CA 92101 +1 (858) 422-6466

I haven't got any satisfaction on my self-exploration to set up log4j
logging of my spring application under a fresh clean install of Tomcat
5.0.19 on Windows XP using JDK 1.4.2_02.

My modest goal is to get Spring debug messages to appear in a log. I am
deploying a servlet that uses a config file very similar to the petclinic
example. When Tomcat starts up, the logger of choice is the JDK 1.4 logger.
All the output is displaying exactly as the default logging.properties in
the JRE directories. I can modify this properties file to get the results I
need, but I want the log4j logger to work. Now I can understand why Tomcat
is defaulting to the log4J messages for its startup messages, since log4j is
not on any Tomcat paths. This makes sense.

I am running Tomcat using a system parameter -Dlog4j.debug=true to turn on
the log4j debugging. My org.springframework.web.util.Log4jConfigListener
loads properly and log4j begins to initialize my log4j.properties file. No
problem here as it finds and parses all of the categories and appenders just
perfect. In fact, my FileAppender creates the logging file for its future
output at this time.

Next Spring's org.springframework.web.context.ContextLoaderListener loads,
but the problem is that its logging output is still using the JDK 1.4
logging! 

I have tried everything I can think of without success. Is this a Tomcat 5
bug? Anyone else doing this successfully?

Some things I have tried:
1. Made sure that my app is using the same version of common-logging-api.jar
as Tomcat 5 (1.0.3). In Tomcat, this jar is picked up by the bootstrap
process finding it in the <tomcat>/bin directory. For all I know, the
version I have in my <webapp>/WEB-INF/lib directory is getting ignored, but
I made sure the same jar is in both places.

2. I have added log4j.jar to every lib directory under Tomcat in order to
get it to use log4j without success. Have no idea why that is. I have since
removed log4j from Tomcat's directories and it appears only in my
<webapp>/WEB-INF/lib directory.

Here are my config details:

web.xml
=======
<web-app>
	<context-param>
		<param-name>log4jConfigLocation</param-name>
		<param-value>/WEB-INF/classes/log4j.properties</param-value>
	</context-param>
	<listener>

<listener-class>org.springframework.web.util.Log4jConfigListener</listener-c
lass>
	</listener>
</web-app>

Log4j.properties
================
# Set root logger, this is the default unless overridden below
log4j.rootCategory=DEBUG, CONSOLE, FILE

# CONSOLE is set to be a ConsoleAppender.
log4j.appender.CONSOLE=org.apache.log4j.ConsoleAppender
log4j.appender.CONSOLE.layout=org.apache.log4j.PatternLayout
log4j.appender.CONSOLE.layout.ConversionPattern=%-4r [%t] %-5p %c %x - %m%n
log4j.appender.CONSOLE.Threshold=WARN

log4j.appender.FILE=org.apache.log4j.FileAppender
log4j.appender.FILE.File=../logs/debug.log
log4j.appender.FILE.Append=False
log4j.appender.FILE.layout=org.apache.log4j.PatternLayout
log4j.appender.FILE.layout.ConversionPattern=%d %-5p %c %m\n

#log4j.category.org.springframework=WARN
#log4j.category.net.sf.hibernate=WARN
#log4j.category.net.sf.hibernate.SQL=DEBUG

log4j.category.com.jcoverage=INFO
log4j.category.net.sf.hibernate.util.JDBCExceptionReporter=ERROR

log4j.debug output
==================
Mar 18, 2004 7:14:35 PM org.apache.catalina.core.StandardHostDeployer
install
INFO: Processing Context configuration file URL
file:C:\tools\jakarta-tomcat-5.0.19\conf\Catalina\localhost\jobs_and_progres
s.xml
log4j: Trying to find [log4j.properties] using context classloader
WebappClassLoader
  delegate: false
  repositories:
    /WEB-INF/classes/
----------> Parent Classloader:
StandardClassLoader
  delegate: true
  repositories:
    file:C:\tools\jakarta-tomcat-5.0.19\shared\classes\
----------> Parent Classloader:
StandardClassLoader
  delegate: true
  repositories:
    file:C:\tools\jakarta-tomcat-5.0.19\common\classes\
    file:C:\tools\jakarta-tomcat-5.0.19\common\endorsed\xercesImpl.jar
    file:C:\tools\jakarta-tomcat-5.0.19\common\endorsed\xmlParserAPIs.jar
    file:C:\tools\jakarta-tomcat-5.0.19\common\lib\ant.jar
    file:C:\tools\jakarta-tomcat-5.0.19\common\lib\commons-collections.jar
    file:C:\tools\jakarta-tomcat-5.0.19\common\lib\commons-dbcp-1.1.jar
    file:C:\tools\jakarta-tomcat-5.0.19\common\lib\commons-el.jar
    file:C:\tools\jakarta-tomcat-5.0.19\common\lib\commons-pool-1.1.jar
    file:C:\tools\jakarta-tomcat-5.0.19\common\lib\jasper-compiler.jar
    file:C:\tools\jakarta-tomcat-5.0.19\common\lib\jasper-runtime.jar
    file:C:\tools\jakarta-tomcat-5.0.19\common\lib\jconn2.jar
    file:C:\tools\jakarta-tomcat-5.0.19\common\lib\jmx.jar
    file:C:\tools\jakarta-tomcat-5.0.19\common\lib\jsp-api.jar
    file:C:\tools\jakarta-tomcat-5.0.19\common\lib\naming-common.jar
    file:C:\tools\jakarta-tomcat-5.0.19\common\lib\naming-factory.jar
    file:C:\tools\jakarta-tomcat-5.0.19\common\lib\naming-java.jar
    file:C:\tools\jakarta-tomcat-5.0.19\common\lib\naming-resources.jar
    file:C:\tools\jakarta-tomcat-5.0.19\common\lib\servlet-api.jar
----------> Parent Classloader:
sun.misc.Launcher$AppClassLoader@e80a59

.
log4j: Using URL
[file:/C:/projects/jpp/development/war/WEB-INF/classes/log4j.properties] for
automatic log4j configuration.
log4j: Reading configuration from URL
file:/C:/projects/jpp/development/war/WEB-INF/classes/log4j.properties
log4j: Parsing for [root] with value=[DEBUG, CONSOLE, FILE].
log4j: Level token is [DEBUG].
log4j: Category root set to DEBUG
log4j: Parsing appender named "CONSOLE".
log4j: Parsing layout options for "CONSOLE".
log4j: Setting property [conversionPattern] to [%-4r [%t] %-5p %c %x -
%m%n].
log4j: End of parsing for "CONSOLE".
log4j: Setting property [threshold] to [WARN].
log4j: Parsed "CONSOLE" options.
log4j: Parsing appender named "FILE".
log4j: Parsing layout options for "FILE".
log4j: Setting property [conversionPattern] to [%d %-5p %c %m
].
log4j: End of parsing for "FILE".
log4j: Setting property [append] to [false].
log4j: Setting property [file] to [../logs/debug.log].
log4j: setFile called: ../logs/debug.log, false
log4j: setFile ended
log4j: Parsed "FILE" options.
log4j: Parsing for [net.sf.hibernate.util.JDBCExceptionReporter] with
value=[ERROR].
log4j: Level token is [ERROR].
log4j: Category net.sf.hibernate.util.JDBCExceptionReporter set to ERROR
log4j: Handling
log4j.additivity.net.sf.hibernate.util.JDBCExceptionReporter=[null]
log4j: Parsing for [org.springframework] with value=[WARN].
log4j: Level token is [WARN].
log4j: Category org.springframework set to WARN
log4j: Handling log4j.additivity.org.springframework=[null]
log4j: Parsing for [com.jcoverage] with value=[INFO].
log4j: Level token is [INFO].
log4j: Category com.jcoverage set to INFO
log4j: Handling log4j.additivity.com.jcoverage=[null]
log4j: Parsing for [net.sf.hibernate] with value=[WARN].
log4j: Level token is [WARN].
log4j: Category net.sf.hibernate set to WARN
log4j: Handling log4j.additivity.net.sf.hibernate=[null]
log4j: Finished configuring.
log4j: Parsing for [root] with value=[DEBUG, CONSOLE, FILE].
log4j: Level token is [DEBUG].
log4j: Category root set to DEBUG
log4j: Parsing appender named "CONSOLE".
log4j: Parsing layout options for "CONSOLE".
log4j: Setting property [conversionPattern] to [%-4r [%t] %-5p %c %x -
%m%n].
log4j: End of parsing for "CONSOLE".
log4j: Setting property [threshold] to [WARN].
log4j: Parsed "CONSOLE" options.
log4j: Parsing appender named "FILE".
log4j: Parsing layout options for "FILE".
log4j: Setting property [conversionPattern] to [%d %-5p %c %m
].
log4j: End of parsing for "FILE".
log4j: Setting property [append] to [false].
log4j: Setting property [file] to [../logs/debug.log].
log4j: setFile called: ../logs/debug.log, false
log4j: setFile ended
log4j: Parsed "FILE" options.
log4j: Parsing for [net.sf.hibernate.util.JDBCExceptionReporter] with
value=[ERROR].
log4j: Level token is [ERROR].
log4j: Category net.sf.hibernate.util.JDBCExceptionReporter set to ERROR
log4j: Handling
log4j.additivity.net.sf.hibernate.util.JDBCExceptionReporter=[null]
log4j: Parsing for [org.springframework] with value=[WARN].
log4j: Level token is [WARN].
log4j: Category org.springframework set to WARN
log4j: Handling log4j.additivity.org.springframework=[null]
log4j: Parsing for [com.jcoverage] with value=[INFO].
log4j: Level token is [INFO].
log4j: Category com.jcoverage set to INFO
log4j: Handling log4j.additivity.com.jcoverage=[null]
log4j: Parsing for [net.sf.hibernate] with value=[WARN].
log4j: Level token is [WARN].
log4j: Category net.sf.hibernate set to WARN
log4j: Handling log4j.additivity.net.sf.hibernate=[null]
log4j: Finished configuring.
Mar 18, 2004 7:14:36 PM
org.springframework.beans.factory.xml.XmlBeanDefinitionReader
loadBeanDefinitions
INFO: Loading XML bean definitions from resource
[/WEB-INF/resources/spring/jpp-business-tier.xml] of ServletContext