Only Logging in listners not readers etc

[flurdy]

Hi,
I have a strange issue regarding logging:

We are using Commons logging with log4j and any log statements are only printed to the specific log4j logfile if they are in a listner. Any log statements in readers, writers etc are only outputed to the console (or in case of websphere in SystemOut.log) irrespective of the log level.


But the listeners and readers are in the same package and the log4j configuration is package based, so they should not be different.

Is there anything we have to consider, threading etc, that interferes with our logging in Spring Batch?

[flurdy]

Bump.

Any ideas how come log4j statements from classes in the same package gets ignored while listeners' log statements are printed?

[arno]

did you check your classpath to see if other facades like SLF4J don't interfere?

[dma_k]

Any ideas how come log4j statements from classes in the same package gets ignored while listeners' log statements are printed?

Tell us, how you package you application? And give exact log entries that are OK, and that are missing. Give us code lines, how you initialize logger in each case (static logger or not?). In my case:

my.war
  +- WEB-INF
    +- classes
      +- log4j.properties
      ...
    +- lib
      +- commons-logging-1.1.1.jar
      +- log4j-1.2.14.jar
      +- spring-batch-core-2.1.6.RELEASE.jar
      ...

When I deploy this to Tomcat, the configuration works as configured in log4j.properties (see the logs in /var/log/tomcat6/catalina.out (if you don't use juli-bridge) or log4j-configured logfile)

log4j.rootLogger=DEBUG, C

log4j.appender.C=org.apache.log4j.ConsoleAppender
log4j.appender.C.layout=org.apache.log4j.PatternLayout
log4j.appender.C.layout.ConversionPattern=%d{dd.MM HH:mm:ss} %-5p [%c] %m%n

log4j.logger.org.springframework.beans=INFO
log4j.logger.org.springframework.orm.hibernate3.HibernateTemplate=WARN

JBoss: see the log in jboss/logs/console.log which is configured by conf/jboss-log4j.xml (so above configuration is ignored).

[flurdy]

Our application structure:

app ear ->
-- jcl-over-slf4j-1.5.8.jar
-- log4j-1.2.16.jar
-- sl4fj-api-1.5.8.jar
-- sl4fj-log4j12-1.5.8.jar
-- spring-batch-core-2.1.6.RELEASE.jar
-- spring-batch-infrastructure-2.1.6.RELEASE.jar
-- spring-beans-3.0.5.RELEASE.jar
-- spring-core-3.0.5.RELEASE.jar
-- ....
-- foo-bar-module.jar
-- -- classes
-- -- -- org.foo.bar.job
-- -- -- -- FoobarWriter
-- -- -- -- FoobarWriteListener

External to the ear is a conf folder, which location is specified on the classpath, where the log4j.properties are:

log4j.rootCategory=INFO, GENERIC
log4j.appender.CONSOLE=org.apache.log4j.ConsoleAppender
log4j.appender.CONSOLE.Threshold=FATAL
log4j.appender.CONSOLE.layout=org.apache.log4j.PatternLayout
log4j.appender.CONSOLE.layout.ConversionPattern=%d{dd/MM/yyyy HH:mm:ss,SSS} [%t] %-5p %c %x - %m%n
...
log4j.appender.GENERIC=org.apache.log4j.RollingFileAppender
log4j.appender.GENERIC.File=C:/FoobarFiles/log/Generic.log
log4j.appender.GENERIC.Append=true
log4j.appender.GENERIC.Threshold=DEBUG
log4j.appender.GENERIC.layout=org.apache.log4j.PatternLayout
log4j.appender.GENERIC.layout.ConversionPattern=%d{dd/MM/yyyy HH:mm:ss,SSS} [%t] %-5p %c %x - %m%n
...
log4j.logger.org.foo.bar=WARN, GENERIC
log4j.logger.org.foo.bar.job=INFO, GENERIC
log4j.additivity.org.foo.bar.job=false

Deployment server is for this environment WebSphere 7.0.


Log statement code examples:

package org.foo.bar.job;
import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;
import org.springframework.batch.item.ItemWriter;
import java.util.List;
public class FoobarWriter  implements ItemWriter<Integer> {
private final Log log = LogFactory.getLog(getClass());
 public void write(List<? extends Integer> items ) throws Exception {
	if(log.isInfoEnabled()) log.info("Writer Blah is blah blah");
 }
}

package org.foo.bar.job;
import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;
import org.springframework.batch.core.StepListener;
import org.springframework.batch.core.annotation.BeforeStep;
import org.springframework.batch.core.StepExecution;
public class FoobarWriteListener  implements StepListener {
private final Log log = LogFactory.getLog(getClass());
@BeforeStep
 public void beforeStep(StepExecution stepExecution){
	if(log.isInfoEnabled()) log.info("Listener Blah is blah blah");
 }
}

Obviously example above is anonymised and simplified but that is a good equivalent of our code.

But only the listeners log statements are put into C:/FoobarFiles/log/Generic.log

23/03/2011 14:44:03,015 [WorkManager.FoobarWorkManager : 0] INFO  org.foo.bar.job.FoobarWriteListener  - Listener Blah is blah blah

while the writers log statements only end up in C:\Program Files(x86)\IBM\Websphere\AppServer\profiles\AppSrv 01\logs\FooBarServer\SystemOut.log

[3/23/11 16:31:02:109 IST] 00000024 FoobarWriter I org.foo.bar.job.FoobarWriter Writer Blah is blah blah

My only thought is that listeners and writers are separated by proxy objects or similar that breaks log4j configuration?

[dma_k]

I have a feeling, that problem is not connected with Spring Batch. It looks like (one some reason) FoobarWriter gets the factory, which is not dictated by jcl-over-slf4j. Check across all jars for presence of commons-logging.properties and META-INF/services/org.apache.commons.logging.LogFactory (the last one should only be in jcl-over-slf4j). Are FoobarWriter and FoobarWriteListener created in the same Spring context?

What I would do on your place:

1. (really works) Start your AS in debug mode (-Xdebug -Xrunjdwp:transport=dt_socket,address=8000,server=y ,suspend=y), but a breakpoint in LogFactory.getLog() and see what happens next.
2. If above it too heavy-weight, try to create a logger dynamically, e.g. LogFactory.getLog(getClass()).info("Listener Blah is blah blah"); and see if it makes a change
3. Have a look at LogFactory.getFactory() objects (should be the same for both classes):
   

   static {
   System.out.println("StepListener " + System.identityHashCode(LogFactory.getFactory()) + " " + LogFactory.getFactory().getClass().getName());
   }

Indeed the problem is weird.

My only thought is that listeners and writers are separated by proxy objects or similar that breaks log4j configuration?

How it can break log4j? Just wonder...

[flurdy]

Changing my classes to use the native SLF4J loggers directly fixed the problem.
So yes it looks like some commons logging was intefering somewhere.