Announcement Announcement Module
Collapse
No announcement yet.
Only Logging in listners not readers etc Page Title Module
Move Remove Collapse
X
Conversation Detail Module
Collapse
  • Filter
  • Time
  • Show
Clear All
new posts

  • Only Logging in listners not readers etc

    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?

  • #2
    Bump.

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

    Comment


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

      Comment


      • #4
        Originally posted by flurdy View Post
        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:

        Code:
        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)

        Code:
        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).

        Comment


        • #5
          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:
          Code:
          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:

          Code:
          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");
           }
          }
          Code:
          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
          Code:
          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
          Code:
          [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?

          Comment


          • #6
            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):
              Code:
              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...

            Comment


            • #7
              Slf4j

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

              Comment

              Working...
              X