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")
)

Answer 2

I had the same issue. Ended up just instantiating an empty logger in the class definition.

If I applied my method to your code then it would be,

import com.weiglewilczek.slf4s.{Logger, Logging}

class MyClass with Logging {
   val _ = Logger("") // <--Solved problem

   def doSomething() {
      logger.debug("Hello world")
  }
}

Note that I am very new to scala so I don't know the full implications of what I have just done.

Answer 3

The problem is that while the first thread is initializing the underlying logging implementation (blocking), for all other concurrent threads, SubstituteLoggerFactory is created. This substitute logger factory returns a SubstituteLogger instead the actual logger implementation. This issue isn't resolved in SLF4J-167.

It is less likely to meet this issue in Java, because often logger objects are created as a static variable, so the LoggerFactory is being initialized during the class loading. In Scala there is no static modifier and companion objects are initialized lazily. Furthermore, most testing frameworks in Scala execute tests in parallel.

To workaround this issue, you can change the test environment: as Bruno Bieth suggested you can initialize the LoggerFactory before the tests start. You can do that also in the test code rather than the build settings. You can also set the test to run sequentially, but then you lose speed.

Alternatively you can eagerly initialize a Logger initialized in a companion object. Ugly, but in most cases ensures that Foo objects created concurrently won't be initialized with a SubstituteLogger.

class Foo {
  val logger = Foo.singletonLogger
}

object Foo {
  val singletonLogger = LoggerFactory.getLogger(getClass)
}