如何在使用testng、slf4s和logback的scala单元测试中启用日志记录

Question

我是Scala的新手，对Java的最新发展也不太熟悉，所以我有一个我认为是基本问题。

我正在编写一些Scala代码，并使用ScalaTest和TestNG进行测试。被测试的代码使用slf4s进行日志记录，由logback支持。

在我的“build.sbt”文件中，我已经添加了所有需要的库的依赖项：

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"

我会像这样记录日志（为了易读性，代码进行了简化）：

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

当我运行一个测试来执行这段代码（使用'sbt test'命令），我没有看到调试信息，但我确实在控制台上看到了这个打印：

    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

我在src/test/resources中有一个logback.xml文件，并且我知道日志记录本身是有效的，因为我可以看到Apache HttpClient库（它使用JCL）的输出。

我是否遗漏了什么？我记录的信息有助于通过测试探索我的代码的行为，并且似乎应该起作用。当然，我已经阅读了http://www.slf4j.org/codes.html#substituteLogger上的页面，但我不知道我的记录器是如何在日志记录子系统被配置之前被创建的。

更新：这是我的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>

- anelson

---

你能发布一下你的logback.xml文件内容吗？ - Ceki

我也遇到了同样的问题（logback core+classic 0.9.30, 1.0.0; slf4j-api 1.6.2）。我认为这与使用slf4s无关，而是一个运行时的问题。在某些运行中，一些类得到了配置，而在其他运行中，我看到了它们的错误。 - Ido Tamir

Answer 1

我认为这是因为SBT并行运行测试，并且Slf4j中的一些初始化代码不是线程安全的(!)。请参见http://jira.qos.ch/browse/SLF4J-167...它已经报告了两年多了！

作为解决方法，我通过在测试运行之前加载根记录器来初始化Slf4j。只需将以下内容添加到您的SBT设置中即可：

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

- Bruno Bieth

---

为了避免搜索"Setup"是什么，请在您的 build.scala 文件中使用 Tests.Setup，如果您还没有导入 Tests._。 - tonicebrian

请注意，在 SBT < 0.13.0 中，当测试被分叉时，Setup 不可用。从 SBT 0.13.0 开始，Setup 可用，但是 classloader 不可用，因为 Setup 是从主 JVM 运行的。从 0.13.0 文档中可以看到，“在分叉时，包含测试类的 ClassLoader 无法提供，因为它在另一个 JVM 中。在这种情况下只使用 () => Unit 变体。” https://github.com/sbt/sbt/blob/v0.13.0/src/sphinx/Detailed-Topics/Testing.rst#setup-and-cleanup - drstevens

还有一种选择是让测试框架执行此初始化。请参见 https://github.com/szeiger/junit-interface/pull/31 - Bruno Bieth

对于sbt 0.13.x，您可以使用以下代码：https://github.com/typesafehub/scalalogging/issues/23 - Diego Alvarez

这对我实际上解决了问题。请注意，提到的 SLF4J 票证和修复并不能解决测试中 scala-logging 的所有问题。这仍然会发生，因为在日志记录初始化完成之前，测试会继续进行。以下是 SLF4j 的调试输出：SLF4J: A number (23428) of logging calls during the initialization phase have been intercepted and are now being replayed. These are subject to the filtering rules of the underlying logging system. 在初始化之前，即使日志级别设置不同，isDebugEnabled 也可能为 true。 - kap

Answer 2

问题在于，当第一个线程正在初始化底层的日志记录实现（阻塞）时，对于所有其他并发线程，SubstituteLoggerFactory被创建。这个替代的日志记录工厂返回一个SubstituteLogger而不是实际的日志记录实现。这个问题在SLF4J-167中没有得到解决。

在Java中遇到这个问题的可能性较小，因为通常日志记录对象是作为静态变量创建的，所以LoggerFactory在类加载期间被初始化。在Scala中没有静态修饰符，伴生对象是惰性初始化的。 此外，Scala中的大多数测试框架都是并行执行测试的。

要解决这个问题，你可以改变测试环境：正如Bruno Bieth建议的那样，在测试开始之前初始化LoggerFactory。你也可以在测试代码中而不是构建设置中进行操作。你也可以将测试设置为按顺序运行，但这样会失去速度。

另外，你可以急切地初始化在伴生对象中初始化的Logger。虽然很丑陋，但在大多数情况下可以确保同时创建的Foo对象不会使用SubstituteLogger进行初始化。

class Foo {
  val logger = Foo.singletonLogger
}

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

- Ohad Bruker

Answer 3

我是一位有用的助手，可以为您进行文本翻译。以下是需要翻译的内容：

我曾经遇到过同样的问题。最终在类定义中实例化了一个空记录器。

如果我将我的方法应用于您的代码，则会变成：

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

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

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

请注意，我对Scala非常陌生，所以我不知道我刚才做的事情的全部含义。

- casey

Answer 4

如您在[这里][1]所看到的，slf4s 1.0.7 依赖于 slf4j 1.6.1。请尝试使用此版本来替换您其他的 slf4j 依赖项中的 1.6.3 版本。

- Heiko Seeberger