第九章：日志隔离

问题：日志隔离

这个章节处理一个相对困难的问题，为在同一个 web 或 EJB 容器运行的多个客户端提供一个隔离的日志环境。在接下来的章节中，"应用" 一词用来表示 web 应用以及 J2EE 应用。在隔离的日志环境中，每个应用将会看到一个不同的 logback 环境。所以一个应用的 logback 配置不会影响到另一个。从技术角度看，每个 web 应用都会保存一份 LoggerContext 的独立拷贝。在 logback 中，LoggerContext 产生的每个 logger 对象只要在内存中存活，都会被保留。这个问题的一个变体是隔离应用的日志与容器本身的日志。

最简单的方法

假设你的容器支持子级优先加载，那么日志隔离可以通过在每个应用中内置一份 slf4j 与 logback 的 jar 包完成。对于 web 应用，将 slf4j 与 logback 的 jar 包放在 WEB-INF/lib 文件夹下，这种方式可以有效的赋予每个 web 应用隔离的日志环境。logback.xml 文件放在 WEB-INF/classes 下，当 logback 被加载进内存时，该配置会被加载。

由于容器提供了类加载器隔离，每个 web 应用将会加载自己拷贝的 LoggerContext 以及自己拷贝的 logback.xml。

其实，也不全是。有时候你会被迫将 SLF4J 与 logback 的 jar 包放在同一个地方供所有的应用访问。通常，这是因为共享库需要使用 SLF4J。在这种情况下，所有的应用将会共享同一个日志环境。有许多其它的应用场景需要将 SLF4J 与 logback 的 jar 包放在同一个地方，那么所有的应用都会看到，这样就不能通过类加载隔离来对日志环境进行隔离了。但是并不是没有其它的办法，请继续往下阅读。

上下文选择器

logback 提供了一种机制为每个单独 SLF4J 实例以及 logback 类加载进内存提供了多个 logger context。当你写下：

Logger logger = LoggerFactory.getLogger("foo");

LoggerFactory 类中的 getLogger() 方法会要求 SLF4J 绑定 ILoggerFactory。当 SLF4J 绑定到 logback，会委托 ContextSelector 实例去返回 ILoggerFactory。ContextSelector 的实现一直都会返回同一个 LoggerContext 实例，也就是默认的 logger context。

你可以通过 logback.ContextSelector 这个系统属性指定不同的上下文选择器。假设你想指定 myPackage.myContextSelector 这个类的实例为上下文选择器，那么你可以通过如下方式添加一个系统属性：

-Dlogback.ContextSelector=myPackage.myContextSelector

这个上下文选择器需要实现 ContextSelector 这个接口，并且有一个构造方法，该构造方法仅仅只接收 LoggerContext 实例作为参数。

ContextJNDISelector

logback-classic 附带了一个名为 ContextJNDISelector 的选择器，它基于 JNDI 查找的有效数据去选择一个 logger 上下文。这个方法利用 J2EE 规范强制 JNDI 数据分离。因此，同样的环境变量在不同的应用中能够设置不同的值。换句话说，在不同的应用中调用 LoggerFactory.getLogger() 不同 logger 上下文中的 logger。即使所有的应用都共享内存中同一个 LoggerFactory 类。这样就能够对你的日志进行隔离。

要开启 ContextJNDISelector，需要设置系统属性 logback.ContextSelector 为 "JNDI"。如下：

-Dlogback.ContextSelector=JNDI

注意，JNDI 是 ch.qos.logback.classic.selector.ContextJNDISelector 的缩写形式。

在应用中设置 JNDI

在你的每个应用中，你需要为应用命名 logger 上下文。对于 web 应用，通过 web.xml 指定 JNDI 环境条目。如果你应用的名字为 "kenobi"，那么你可以添加如下的 XML 元素到你的 web.xml 文件中：

<env-entry>
  <env-entry-name>logback/context-name</env-entry-name>
  <env-entry-type>java.lang.String</env-entry-type>
  <env-entry-value>kenobi</env-entry-value>
</env-entry>

假设你已经开启了 ContextJNDISelector，那么将使用一个名为 "kenobi" 的 logger 上下文来为 Kenobi 打印日志。而且，logger 上下文 "kenobi" 会按照约定使用线程上下文类加载器去寻找一个名为 logback-kenobi.xml 的配置文件进行初始化。因此，对于例子中 "kenobi" web 应用，应该将 logback-kenobi.xml 放在 WEB-INF/classes 文件夹下。

只要你喜欢，通过设置 "logback/configuration-resource" JNDI 变量，你可以不按照约定，而是指定一个不同的配置文件。例如，对于 "kenobi" web 应用，如果你想指定配置文件为 aFolder/my_config.xml 而不是约定的 logback-kenobi.xml，你可以在 web.xml 中添加如下的 xml 元素：

<env-entry>
  <env-entry-name>logback/configuration-resource</env-entry-name>
  <env-entry-type>java.lang.String</env-entry-type>
  <env-entry-value>aFolder/my_config.xml</env-entry-value>
</env-entry>

my_config.xml 文件需要放在 WEB-INF/classes/aFolder/ 下。需要记住的一点是，使用当前线程的上下文类加载来查找配置文件作为 Java 资源。

通过 Tomcat 配置 ContextJNDISelector

首先，将 logback 的 jar 包 (logback-classic-1.3.0-alpha4.jar, logback-core-1.3.0-alpha4.jar and slf4j-api-1.8.0-beta1.jar) 放在 Tomcat 全局的类文件夹下。在 Tomcat 6.x 中，这个文件夹是 $TOMCAT_HOME/lib/。

系统属性 logback.ContextSelector 可以在 catalina.sh 脚本中添加如下的行来进行设置。Windows 下为 catalina.bat。在 $TOMCAT_HOME/bin 文件夹下。

JAVA_OPTS="$JAVA_OPTS -Dlogback.ContextSelector=JNDI"

应用热部署

当 web 应用被回收或者关闭时，我们强烈推荐关闭现有的 LoggerContext，以便正确的进行垃圾回收。logback 附带了一个名为 ContextDetachingSCL 的 ServletContextListener，用来分离旧 web 应用中的 ContextSelector 实例。可以在 web.xml 中添加如下的行来指定：

<listener>
  <listener-class>ch.qos.logback.classic.selector.servlet.ContextDetachingSCL</listener-class>
</listener>

NOTE 大部分的容器会按照声明的顺序调用 contextInitialized() 方法，但是按照相反的顺序调用 contextDestroyed() 方法。也就是说，如果你在 web.xml 中声明了多个 ServletContextListener，那么 ContextDetachingSCL 应该第一个声明，那么在应用关闭的时候，它的 contextDestroyed() 方法将会在 最后 被调用。

更好的性能

当 ContextJNDISelector 处于活动状态，每次查找一个 logger，JNDI 查找必须被执行。这样对性能会有影响，特别是当你使用一个非静态的 logger 时。logback 附带了一个名为 LoggerContextFilter 的过滤器，为了避免 JNDI 查找的消耗而特意设计。可以通过在 web.xml 中添加如下的行来指定：

<filter>
  <filter-name>LoggerContextFilter</filter-name>
  <filter-class>ch.qos.logback.classic.selector.servlet.LoggerContextFilter</filter-class>
</filter>
<filter-mapping>
  <filter-name>LoggerContextFilter</filter-name>
  <url-pattern>/*</url-pattern>
</filter-mapping>

在每个 http 请求开始的时候，LoggerContextFilter 会获取应用相关的 logger 上下文，然后把它放在 ThreadLocal 变量中。ContextJNDISelector 会看 ThreadLocal 变量是否已经被设置，如果是，那么 JNDI 查找将会跳过。在每个 http 请求结束的时候，ThreadLocal 变量就会为 null。使用 LoggerContextFilter 会大幅度的提高 logger 检索性能。

使 ThreadLocal 为 null，可以让 web 应用在停止或者回收时对它进行垃圾回收。

在共享库中改进静态引用

当 SLF4J 与 logback 组件被所有应用共享时，ContextJNDISelector 可以很好的创建日志隔离。当 ContextJNDISelector 处于活动状态时，每次对 LoggerFactory.getLogger() 的调用将会返回一个属于正在被调用/当前应用的一个 logger 上下文中的 logger。

通常是通过静态引用来引用一个 logger。(你们前面的例子全部是通过实例变量来引用😓)例如：

public class Foo {
  static Logger logger = LoggerFactory.getLogger(Foo.class);
  ...
}

静态 logger 引用在内存以及在 CPU 中都是有效率的。使用一个 logger 引用用于该类的所有实例。而且，当加载类到内存中时，这个 logger 实例只会被查找一次。如果宿主类属于某个应用程序，比如 kenobi，那么这个静态的 logger 将通过抽象的 ContextJNDISelector 附加到 kenobi 的 logger 上下文中。类似的，如果宿主类属于其它的应用，比如 yoda，那么它的静态 logger 引用将会再一次通过抽象的 ContextJNDISelector 附加到 logger 的上下文中。

如果一个名为 Mustafar 的类，属于某个类库，被 kenobi 与 yoda 共享。只要 Mustafar 没有使用静态引用，那么每次对 LoggerFactory.getLogger() 的调用将会返回一个属于正在被调用/当前的应用的 logger 上下文中的 logger。但是如果 Mustafar 有一个静态的引用，那么当应用第一次调用它时，这个 logger 将会被附加到 logger 上下文中。因此，一旦共享类使用静态的 logger 引用， ContextJNDISelector 不会提供日志隔离。这个问题很长时间都没有得到解决。

透明且完美的解决这个问题的唯一方法是引入另一个间接级别的内部 logger，这样每个 logger 以某种方式将工作委托给一个附加在合适上下文的内部 logger 上。这个方法实现起来非常困难，并且会产生大量的计算开销。这个并不是我们追求的方式。(无语了😶，前面说完美，然后马上说不行)

不言而喻，一个非常简单方式去解决 "共享类的静态 logger" 问题的方式是将共享类移到 web 应用的内部。(也就是不进行共享) (废话一大堆，罗里吧嗦)。如果不共享不可能实现，我们可以使用 SiftingAppender 使用 JNDI 数据作为隔离标准去进行日志隔离。

这段话翻译的我真的是蛋疼的很。外国人不是思维特别严谨的吗？我怎么觉得反复无常，飘忽不定呢。还是我根本就没理解作者想要说的是什么？

logback 内置了一个名为 JNDIBasedContextDiscriminator 的鉴别器。它可以返回由 ContextJNDISelector 计算得来的当前 logger 上下文的名字。SiftingAppender 与 JNDIBasedContextDiscriminator 结合使用将会为每个 web 应用创建一个单独的 appender。

<configuration>

  <statusListener class="ch.qos.logback.core.status.OnConsoleStatusListener" />  

  <appender name="SIFT" class="ch.qos.logback.classic.sift.SiftingAppender">
    <discriminator class="ch.qos.logback.classic.sift.JNDIBasedContextDiscriminator">
      <defaultValue>unknown</defaultValue>
    </discriminator>
    <sift>
      <appender name="FILE-${contextName}" class="ch.qos.logback.core.FileAppender">
        <file>${contextName}.log</file>
        <encoder>
          <pattern>%-50(%level %logger{35}) cn=%contextName - %msg%n</pattern>
         </encoder>
      </appender>
     </sift>
    </appender>

  <root level="DEBUG">
    <appender-ref ref="SIFT" />
  </root>
</configuration>

如果 kenobi 与 yoda 都是 web 应用，那么上面的配置将会把 yoda 的日志输出到 yoda.log，kenobi 的日志输出到 kenobi.log 中。这甚至适用共享类中静态 logger 生成的日志。

你可以通过 logback-starwars 这个项目来对这项技术进行尝试。

上面这个方法解决了日志隔离的问题，但是相对比较复杂。它需要合理的使用 ContextJNDISelector 以及通过 SiftingAppender 包裹 appender 进行托管。SiftingAppender 本身就不是一个平凡的东西。

每个日志上下文都可以通过同个文件或者不同的文件进行配置。选择权在于你。让所有的上下文使用同一份配置文件会更加简单，因为只有一份文件需要去维护。为每个应用维护一个配置文件会更难维护，但是会更加的灵活。

我们已经完成了吗？可以宣布胜利，然后回家了吗？不全是。

假设 web 应用 yoda 已经在 kenobi 之前被初始化。为了初始化 yoda，访问 http://localhost:port/yoda/servlet 将会调用 YodaServlet。这个 servlet 仅仅只会说 hello，以及在调用 Mustafar 中的 foo 方法之前打印消息，不必感到奇怪，它只是简单的打印消息，然后返回。

在 YodaServlet 被调用后，yoda.log 会包含如下内容：

DEBUG ch.qos.starwars.yoda.YodaServlet             cn=yoda - in doGet()
DEBUG ch.qos.starwars.shared.Mustafar              cn=yoda - in foo()

注意两个日志条目是如何与 "yoda" 上下文的名字相关联的。logger ch.qos.starwars.shared.Mustafar 会一直附加在 'yoda' 上下文中，直到服务被停止。

访问 http://localhost:port/kenobi/servlet 将会在 kenobi.log 中输出：

DEBUG ch.qos.starwars.kenobi.KenobiServlet          cn=kenobi - in doGet()
DEBUG ch.qos.starwars.shared.Mustafar               cn=yoda - in foo()

尽管 logger ch.qos.starwars.shared.Mustafar 输出日志到 kenobi.log 中，但是它仍然是附加在 'yoda' 上。因此，我们有两个日志上下文输出日志到同一个文件。虽然日志隔离可以按照我们的意愿进行，但是 FileAppender 实例并不能安全写入到同一个文件中，除非它们开启 prudent 模式。否则的话，目标文件将会被毁坏。

下面是在 prudent 模式下的配置文件：

<configuration>

  <statusListener class="ch.qos.logback.core.status.OnConsoleStatusListener" />  

  <appender name="SIFT" class="ch.qos.logback.classic.sift.SiftingAppender">
    <discriminator class="ch.qos.logback.classic.sift.JNDIBasedContextDiscriminator">
      <defaultValue>unknown</defaultValue>
    </discriminator>
    <sift>
      <appender name="FILE-${contextName}" class="ch.qos.logback.core.FileAppender">
        <file>${contextName}.log</file>
        <prudent>true</prudent>
        <encoder>
          <pattern>%-50(%level %logger{35}) cn=%contextName - %msg%n</pattern>
         </encoder>
      </appender>
     </sift>
    </appender>

  <root level="DEBUG">
    <appender-ref ref="SIFT" />
  </root>
</configuration>

如果你可以跟上我们目前的讨论，并且你已经尝试过 logback-starwars 这个示例。那么你现在一定是沉迷于日志记录。那么你应该考虑 专业帮助。