slf4j logging not working from invoked threads

[rcoe67]

I have an app that displays strange logging behaviour. My slf4j logging statements are correctly executed from the main thread but threads that are spawned do not write to the logs. The code is not the problem, because I also build a windows service, which uses a classpath of the same libs that I pass to the onejar's <lib> section.

I generate my libs thusly:

<target name="_lib.dependencies">
    <pathtofileset name="lib.dependencies"
                   pathrefid="common.classpath"
                   dir="${basedir}" />
    <pathtofileset name="lib.logging"
                   pathrefid="logging.classpath"
                   dir="${basedir}" />

    <copy todir="${build.dir}/libs" flatten="true">
        <fileset refid="lib.dependencies" />
        <fileset refid="lib.logging" />
        <fileset refid="lib.runtime" />
    </copy>

    <fileset id="lib.dependencies" dir="${build.dir}/libs">
        <include name="*.jar" />
    </fileset>
</target>

My onejar target includes those libs:

<one-jar destfile="${dist}/${scanner.jar}"
      onejarmainclass="com.xxx.xxx.filescan.FileScanner">
   <main>
        <fileset dir="${build.dir}" excludes="libs/**" />
   </main>
   <lib>
        <fileset refid="lib.dependencies" />
   </lib>
</one-jar>

When my app runs, I see several log statements but they stop when my app executes a new thread. For example, I use a FileVisitor to scan a file system and it should log at every 1000th file processed:

    if( processedFileCount % 1000 == 0 ) {
         logger.info( "{} files processed.", processedFileCount );
    }

Using a remote debugger, I can verify the line is called but there's no output written to the log. However, when run as a service, I see this:

2014-07-07 16:42:32,534 [FileScanner for P:\Release] INFO com.xxx.xxx.filescan.FileVisitor - 102000 files processed.

If I had to guess, the spawned thread is invoked by a different classloader instance from the main thread. But if so, I'd expect a ClassNotFound exception. Any pointers would be appreciated.

Thanks.

[rcoe67]

Here's a screen cap of the stack showing the logger hierarchy. The references are all correct, as is the parent logger's level. So, all seems normal in the JVM, just no log output.

[rcoe67]

Found the problem and it's actually unrelated to the multithreaded behaviour of my app...and it took forever to track down. So, hopefully this solution will help others.

The problem was caused by refactoring my code, such that I had separate libraries that each initialized their logger environments. Something I completely forgot is that when you use Log4J to configure the logging environment, the root logger is detached before being re-attached with the new config. So, in my case, I had some logging, because those statements were using the configured appender but then that appender became detached when the next library loaded and initialized its own logging environment. My fix was to put the relevant logging config into the main-class library and configure the logger once.