日志记录由记录器处理两次

Question

我有一个要登录的 Web 应用程序。 logging.properties 文件提供了一些我无法影响的默认日志记录。它记录服务器启动、关闭等。

这些是此类日志的示例（正常的，这里没有错）：

2016/01/22 12:25:10  INFO (ApplicationContext.java:671 [ServerService Thread Pool -- 64]) - Initializing Spring root WebApplicationContext
2016/01/22 12:25:13  INFO (ConfigureListener.java:202 [ServerService Thread Pool -- 64]) - Initializing Mojarra 2.1.28-jbossorg-6  for context '/MyServices'
2016/01/22 12:25:15  INFO (DeploymentHandlerUtil.java:137 [ServerService Thread Pool -- 28]) - JBAS015859: Deployed "MyServices.war" (runtime-name : "MyServices.war")
2016/01/22 12:25:15  INFO (BootstrapListener.java:93 [Controller Boot Thread]) - JBAS015874: JBoss EAP 6.4.0.GA (AS 7.5.0.Final-redhat-21) started in 27257ms - Started 485 of 520 services (63 services are lazy, passive or on-demand)

现在我也可以使用我自己的方法登录我的应用程序，指定使用：

private static final org.slf4j.Logger LOG = org.slf4j.LoggerFactory.getLogger(PropertiesValues.class);
...
LOG.info("Properties loaded.");

问题是当这些日志被命中时，会导致重复记录，其中每一行都有两个时间戳，两个日志级别，两个来源，例如：

2016/01/22 11:50:49  INFO (AbstractLoggingWriter.java:71 [ServerService Thread Pool -- 111]) - 2016/01/22 11:50:49  INFO (EnvironmentLoader.java:128 [ServerService Thread Pool -- 111]) - Starting Shiro environment initialization.
2016/01/22 11:50:49  INFO (AbstractLoggingWriter.java:71 [ServerService Thread Pool -- 111]) - 2016/01/22 11:50:49  INFO (EnvironmentLoader.java:141 [ServerService Thread Pool -- 111]) - Shiro environment initialized in 125 ms.
...
2016/01/22 11:51:20  INFO (AbstractLoggingWriter.java:71 [http-localhost/127.0.0.1:8443-6]) - 2016/01/22 11:51:20  INFO (PropertiesValues.java:101 [http-localhost/127.0.0.1:8443-6]) - Properties loaded.

注意日志被处理了两次。也就是说 - 将要打印的每一行都运行再次通过记录器，从而产生两个时间戳、两个日志级别和两个来源。我可以通过更改 log4j.properties 文件中的最后一行来解决这个问题：

log4j.rootLogger=INFO, STDOUT
log4j.additivity.rootLogger=false
log4j.appender.STDOUT=org.apache.log4j.ConsoleAppender
log4j.appender.STDOUT.Target=System.out
log4j.appender.STDOUT.layout=org.apache.log4j.PatternLayout
log4j.appender.STDOUT.layout.ConversionPattern=%d{yyyy/MM/dd HH:mm:ss} %5p (%F:%L [%t]) - %m%n

只能是 %m，但我觉得这是一个糟糕的解决方案，导致所有内容的源都显示为 AbstractLoggingWriter.java:71。

有没有办法让我的日志显示正确的方法和行号，并按照我选择的格式而不是服务器格式？同时，我也不想丢失服务器提供的日志。

我的 Maven 依赖项是：

<dependency>
    <groupId>org.slf4j</groupId>
    <artifactId>slf4j-log4j12</artifactId>
    <version>1.7.5</version>
</dependency>
<dependency>
    <groupId>org.slf4j</groupId>
    <artifactId>slf4j-api</artifactId>
    <version>1.7.5</version>
</dependency>
<dependency>
    <groupId>log4j</groupId>
    <artifactId>log4j</artifactId>
    <version>1.2.17</version>
</dependency>

Answer 1

很难说到底发生了什么，但我会尝试猜测。我看到你使用 JBoss，它使用 commons-logging 来记录事件。您将 log4j 设置为输出到标准输出。可能来自 JBoss 的 Logger 抓取发送到 stdout 的内容并将其记录下来，因此您有一条消息被装饰了两次。

尝试使用 JBoss 中的 org.jboss.logging.Logger 而不是 slf4j 或者作为一个卑鄙的把戏，您可以尝试通过添加来关闭 log4j 输出 log4j.appender.STDOUT.Threshold=off 至 log4j.properties

Answer 2

我们的应用程序遇到了同样的问题，我们通过在 Web 应用程序的 jboss-deployment-structure.xml 到 WEB-INF 中添加以下内容来解决该问题：

<?xml version="1.0" encoding="utf-8"?>
<jboss-deployment-structure>
   <deployment>
       <!-- Exclusions allow you to prevent the server from automatically adding some dependencies -->
       <exclude-subsystems>  
           <subsystem name="logging" />
       </exclude-subsystems>  
   </deployment>
</jboss-deployment-structure>

Answer 3

我对这里发生的事情的理解如下：

有两种 log4j 实现交织在一起，尽管它们不是故意的。

一种方法在超级 class 中执行修饰并在当前 class 中记录消息。另一个在给定的 class 中执行修饰和登录，但仍然调用 super class （出于某种原因）。

现在由于 class-loading 的混淆，super-class 来自 log4j 的一个实现（处理装饰）还有另一个 class 现在再次（新版本或旧版本）处理装饰和消息记录。

根据我的理解，这解释了为什么装饰是重复的，但整个消息没有损坏。

尝试使用

-verbose:class

jvm 选项启动 jboss 并将输出通过管道传输到文件。这将有助于确定 classes 是从哪个 jar 加载的。

然后您可以决定这是否是您想要的样子。

日志记录由记录器处理两次

Logging is processed by the logger twice

java

log4j

slf4j

maven