Log4j Help Needed!!!--Config read, level not set?

[gordonjl]

Hey, All,

I'm attempting to use spring's Log4jConfigListener in an exploded web app I have and need some help. The problem is that, despite Log4jConfigListener correctly reading the log4j.properties file, the log level never goes below INFO even though the root logger is set to DEBUG.

My Environment:

• Tomcat 5.0.30 or Tomcat 5.0.28 (I've tried both)
  My app is Tapestry-based web app with Spring and Hibernate.
  I am using commons-logging to log within my code.
  The commons-logging.jar and log4j.jar are in the web app's /WEB-INF/lib directory
  

.

My Config:


Web.xml:

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE web-app
PUBLIC "-//Sun Microsystems, Inc.//DTD Web Application 2.3//EN"
"http&#58;//java.sun.com/dtd/web-app_2_3.dtd">
<!-- generated by Spindle, http&#58;//spindle.sourceforge.net -->
<web-app>
	<display-name>JASF Time Manager</display-name>

	<!--
		- Key of the system property that should specify the root directory of this
		- web app. Applied by WebAppRootListener or Log4jConfigListener.
	-->
	<context-param>
		<param-name>webAppRootKey</param-name>
		<param-value>jasf.root</param-value>
	</context-param>
	<!--
		- Location of the Log4J config file, for initialization and refresh checks.
		- Applied by Log4jConfigListener.
	-->
	<context-param>
		<param-name>log4jConfigLocation</param-name>
		<param-value>/WEB-INF/classes/log4j.properties</param-value>
	</context-param>

	<context-param>
		<param-name>contextConfigLocation</param-name>
		<param-value>/WEB-INF/applicationContext.xml</param-value>
	</context-param>




	<filter>
		<filter-name>hibernateSessionFilter</filter-name>
		<filter-class>
			com.jasf.web.filters.OpenSessionInViewFilter
		</filter-class>
	</filter>

	<filter>
		<filter-name>redirect</filter-name>
		<filter-class>org.apache.tapestry.RedirectFilter</filter-class>
	</filter>

	<filter-mapping>
		<filter-name>hibernateSessionFilter</filter-name>
		<url-pattern>/app</url-pattern>
	</filter-mapping>

	<filter-mapping>
		<filter-name>redirect</filter-name>
		<url-pattern>/</url-pattern>
	</filter-mapping>

	<listener>
		<listener-class>
			org.springframework.web.util.Log4jConfigListener
		</listener-class>
	</listener>
	<listener>
		<listener-class>
			org.springframework.web.context.ContextLoaderListener
		</listener-class>
	</listener>


	<servlet>
		<servlet-name>jasf</servlet-name>
		<servlet-class>
			org.apache.tapestry.ApplicationServlet
		</servlet-class>
		<load-on-startup>1</load-on-startup>
	</servlet>

	<servlet-mapping>
		<servlet-name>jasf</servlet-name>
		<url-pattern>/app</url-pattern>
	</servlet-mapping>
</web-app>

Log4j.properties (lifted from the petclinic example and slightly modified):

# For JBoss: Avoid to setup Log4J outside $JBOSS_HOME/server/default/deploy/log4j.xml!
# For all other servers: Comment out the Log4J listener in web.xml to activate Log4J.

log4j.debug=true

log4j.rootLogger=DEBUG, stdout, logfile

log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern=%d %p &#91;%c&#93; - <%m>%n

log4j.appender.logfile=org.apache.log4j.RollingFileAppender
log4j.appender.logfile.File=$&#123;jasf.root&#125;/WEB-INF/petclinic.log
log4j.appender.logfile.MaxFileSize=512KB
# Keep three backup files.
log4j.appender.logfile.MaxBackupIndex=3
# Pattern to output&#58; date priority &#91;category&#93; - message
log4j.appender.logfile.layout=org.apache.log4j.PatternLayout
log4j.appender.logfile.layout.ConversionPattern=%d %p &#91;%c&#93; - %m%n

And the console output:

INFO: Processing Context configuration file URL file:C:\tomcat\jakarta-tomcat-5.0.28\conf\Catalina\localhost\jasf.xml
log4j: Parsing for [root] with value=[DEBUG, stdout, logfile].
log4j: Level token is [DEBUG].
log4j: Category root set to DEBUG
log4j: Parsing appender named "stdout".
log4j: Parsing layout options for "stdout".
log4j&#58; Setting property &#91;conversionPattern&#93; to &#91;%d %p &#91;%c&#93; - <%m>%n&#93;.
log4j&#58; End of parsing for "stdout".
log4j&#58; Parsed "stdout" options.
log4j&#58; Parsing appender named "logfile".
log4j&#58; Parsing layout options for "logfile".
log4j&#58; Setting property &#91;conversionPattern&#93; to &#91;%d %p &#91;%c&#93; - %m%n&#93;.
log4j&#58; End of parsing for "logfile".
log4j&#58; Setting property &#91;file&#93; to &#91;C&#58;\work\jasf\context\/WEB-INF/petclinic.log&#93;.
log4j&#58; Setting property &#91;maxFileSize&#93; to &#91;512KB&#93;.
log4j&#58; Setting property &#91;maxBackupIndex&#93; to &#91;3&#93;.
log4j&#58; setFile called&#58; C&#58;\work\jasf\context\/WEB-INF/petclinic.log, true
log4j&#58; setFile ended
log4j&#58; Parsed "logfile" options.
log4j&#58; Finished configuring.
log4j&#58; Parsing for &#91;root&#93; with value=&#91;DEBUG, stdout, logfile&#93;.
log4j&#58; Level token is &#91;DEBUG&#93;.
log4j&#58; Category root set to DEBUG
log4j&#58; Parsing appender named "stdout".
log4j&#58; Parsing layout options for "stdout".
log4j&#58; Setting property &#91;conversionPattern&#93; to &#91;%d %p &#91;%c&#93; - <%m>%n&#93;.
log4j&#58; End of parsing for "stdout".
log4j&#58; Parsed "stdout" options.
log4j&#58; Parsing appender named "logfile".
log4j&#58; Parsing layout options for "logfile".
log4j&#58; Setting property &#91;conversionPattern&#93; to &#91;%d %p &#91;%c&#93; - %m%n&#93;.
log4j&#58; End of parsing for "logfile".
log4j&#58; Setting property &#91;file&#93; to &#91;C&#58;\work\jasf\context\/WEB-INF/petclinic.log&#93;.
log4j&#58; Setting property &#91;maxFileSize&#93; to &#91;512KB&#93;.
log4j&#58; Setting property &#91;maxBackupIndex&#93; to &#91;3&#93;.
log4j&#58; setFile called&#58; C&#58;\work\jasf\context\/WEB-INF/petclinic.log, true
log4j&#58; setFile ended
log4j&#58; Parsed "logfile" options.
log4j&#58; Finished configuring.

--the above shows the file was picked up correctly....


A piece of code that makes a debug call _and_ that is called on startup:

 log.info("Starting execution...");
        log.fatal("is de-f*cking bugging enabled?  " + log.isDebugEnabled());

        SimpleDateFormat dateFormatter = new SimpleDateFormat(
                "MM/dd/yyyy HH:mm");

        Calendar today = Calendar.getInstance();
        today.set(Calendar.HOUR, 0);
        today.set(Calendar.MINUTE, 0);

        log.debug("Testing with date:  "
                + dateFormatter.format(today.getTime()));

...and the pertinent output logged to the console:

Mar 22, 2005 9:53:27 PM com.jasf.jobs.PayPeriodJob executeInternal
INFO: Starting execution...
Mar 22, 2005 9:53:27 PM com.jasf.jobs.PayPeriodJob executeInternal
[color=red][b]SEVERE: is de-f*cking bugging enabled?  false[/b][/color]
Mar 22, 2005 9&#58;53&#58;27 PM org.springframework.jdbc.datasource.JdbcTransactionObjectSupport <clinit>
INFO&#58; JDBC 3.0 Savepoint class is available
Hibernate&#58; select payperiod0_.id as id, payperiod0_.endDate as endDate, payperiod0_.complete as complete, payperiod0_.startDate as startDate, payperiod0_.status as status from PayPeriod payperiod0_ where &#40;payperiod0_.status=? &#41;
Mar 22, 2005 9&#58;53&#58;27 PM com.jasf.jobs.PayPeriodJob executeInternal
INFO&#58; 03/22/2005 12&#58;00 is less than active period's end date of 03/27/2005 12&#58;00

This looks like to me that some other logging file is getting picked up and read first, ignoring my logging file that _clearly_ was loaded.[/b]

[pepper]

I'm having the same problem. Did you ever resolve your problem?

[gordonjl]

I solved my problem by downloading the latest commons-logging and log4j jars and putting them in the WEB-INF/lib directory. The only problem I have now is that it doesn't seem like log4j is watching the file. It requires reloading my app (in tomcat) for logging changes to get picked up.

Cheers.

[pepper]

Hmmm....I downloaded Spring 1.2-rc1 (was previously using 1.1.5 with same problems), log4j 1.2.9, and commons logging 1.0.4, but am still having the same problem (DEBUG not recognized). I am also having the watcher problem that you described.

[pepper]

Oops...when I had created a superclass of the class that I was testing with, I used the commons logger. I can now see debug statements, but still have the watcher problem.