How to get logging working in scala unit tests with testng, slf4s, and logback

Question

I'm new to Scala, and not that familiar with recent developments in Java, so I am having what I assume is a basic problem.

I'm writing some Scala code, and testing it with test fixtures using ScalaTest and TestNG. The code under test uses slf4s to perform its logging, backed by logback.

In my 'build.sbt' file I have dependencies for all the libraries I need:

scalaVersion := "2.9.1"

// Add test dependencies on scalatest and testng

libraryDependencies ++= Seq("org.scalatest" %% "scalatest" % "1.6.1" % "test", "org.testng" % "testng" % "6.1.1" % "test")

// Use the slf4j logging facade for logging
libraryDependencies += "org.slf4j" % "slf4j-api" % "1.6.3"

//use the slf4j connectors to implement the JCL logging facade in terms of slf4j (which in turn is implemented in terms of logback)
//confused yet?
libraryDependencies += "org.slf4j" % "jcl-over-slf4j" % "1.6.3"

//use logback for the back-end slf4j logging impl.
libraryDependencies ++= Seq("ch.qos.logback" % "logback-core" % "0.9.30", "ch.qos.logback" % "logback-classic" % "0.9.30")

//use slf4s to expose the slf4j logging facade in scala

libraryDependencies += "com.weiglewilczek.slf4s" %% "slf4s" % "1.0.7"

//Add the dispatch HTTP client dependency

libraryDependencies ++= Seq(
  "net.databinder" %% "dispatch-http" % "0.8.5"
)

//I can't figure out how to use the dispatch HTTP client library, so just use the apache one

libraryDependencies += "org.apache.httpcomponents" % "httpclient" % "4.1.2"

I perform logging like this (code simplified for readability):

class MyClass extends Logging {
   def doSomething() {
      logger.debug("Hello world")
  }
}

when I run a test that exercises this code (using the 'sbt test' command) I do not see the debug message, but I do see this printed to the console:

    SLF4J: The following loggers will not work because they were created
SLF4J: during the default configuration phase of the underlying logging system.
SLF4J: See also http://www.slf4j.org/codes.html#substituteLogger
SLF4J: MyClass

I have a logback.xml file in src/test/resources, and I know logging itself is working as I see output from the Apache HttpClient library (which uses JCL).

Am I missing something? The information I'm logging is helpful in exploring the behavior of my code with tests, and besides it seems like this should work. I have of course read the page at http://www.slf4j.org/codes.html#substituteLogger but I don't see how my logger is getting created before the logging subsystem has been configured.

UPDATE: Here is the contents of my logback.xml:

<configuration>
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <!-- encoders are assigned the type
     ch.qos.logback.classic.encoder.PatternLayoutEncoder by default -->
        <encoder>
            <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} %line --- %msg%n</pattern>
        </encoder>
    </appender>

    <root level="debug">
        <appender-ref ref="STDOUT" />
    </root>
</configuration>

Answer 1

I think it's because SBT runs the tests in parallel and some initialization code in Slf4j is not thread safe (!). See http://jira.qos.ch/browse/SLF4J-167 ... it's been reported more than 2 years ago!

As a workaround I initialize Slf4j by loading the root logger before the tests run. To do so just add this to your SBT settings:

testOptions += Setup( cl =>
   cl.loadClass("org.slf4j.LoggerFactory").
     getMethod("getLogger",cl.loadClass("java.lang.String")).
     invoke(null,"ROOT")
)