Logging separation

The problem: Logging Separation

这一章节中，我们将讨论有关为多个运行在同一个web容器或EJB容器的应用提供分离的日志环境。在分离的日志环境中，每个应用看到的都是不同的日志环境，所以应用之间的配置不会相互干扰。更为专业的术语就是，每一个web-application都有一个独立的LoggerContext副本。在Logback中，每一个logger对象都是LoggerContext创造，Logger对象会在其内存的生命周期中都保持与LoggerContext的关联关系。而我们的问题就是如何处理分离的应用程序的日志记录以及容器本身的日志记录。

The simplest and easiest approach

假设你的容器支持 child-first class loading，应用间日志的分离可以简单地通过将 slf4j, logback jar文件，以及logback配置文件放在各个项目的路径下完成。

这种方法非常简单。但有时候你可能嫌弃同时管理这么多相同的配置文件，你就会想将 SLF4J 和 Logback 放在一个所有应用都能访问的地方。在这种情况下，所有应用就会共享同一个日志环境 logging enviroment，无法通过类加载器来分离日志环境了。

Context Selectors

Logback实现了一种当SLF4J和Logback类 已经被加载进内存来提供多个logger context时，获取这些类单例的机制。

当执行以下代码

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

LoggerFactory.getLogger()方法会先向SLF4J binding 请求ILoggerFactory。当使用logback实现时，这个返回ILoogerFactory的任务将会委托给ContextSelector对象。注意，ContextSelector的实现通常返回LoggerContext对象，这个类实现了ILoggerFactory接口。

logback binding 默认使用  DefaultContextSelector ，这 个实现通常返回相同的LoggerContext，称为 default logger context。

你可以指定使用不同context selector，通过设置 logback.ContextSelector 系统变量。例如在jvm启动时设置参数：

-Dlogback.ContextSelector=myPackage.myContextSelector

context selector 需要实现 ContextSelector接口，并且有一个只接受LoogerContext对象的构造函数。

Logback-classic 自带了一个selector叫  ContextJNDISelector，是基于JNDI实现的。这个方法利用了J2EE规范中的JNDI分离数据特点。因此，相同的环境变量在不同应用中可以设为不同的值。换句话说，不同应用调用LoggerFactory.getLogger（）会返回不同的logger context，即使这里只有一个LoggerFactory类被加载进内存并被所有应用共享。通过以下设置使用JNDI selector

-Dlogback.ContextSelector=JNDI

需要注意，JNDI是logback提供的 ch.qos.logback.classic.selector.ContextJNDISelector的简写形式。

Setting JNDI variables in applications

在你的每一个应用中，你需要注明应用的logging context。对于web-application，JNDI 环境入口在web.xml中指定。假设你的项目名为kenobi，你需要在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应用的日志上下文就会被命名为 kenobi。此外，“kenobi” logger context会查找名字为 logback-kenobi.xml的配置文件来初始化上下文配置。因此，你需要将logback-kenobi.xml放在logback资源查找的目录中。

如果你想，你也可以通过设置 JNDI中的变量 "logback/configuration-resource” 的值来 指定配置文件名。例如：

<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/目录下。

Configuring Tomcat for ContextJNDISelector

首先，将logback jars（ logback-classic-1.1.7.jar, logback-core-1.1.7.jar and slf4j-api-1.7.20.jar ）放置在tomcat的lib共享目录下。

然后设置jvm的启动参数，通过编辑catalina.sh , catalina.bat启动脚本

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

Hot deploying applications

当web-application被回收或关闭时，我们强烈建议当前有效的LoogerContext被关闭，这样它才能被GC正确的回收。Logback提供了一个实现了ServletContextListener 接口的类，叫 ContextDetachingSCL ，是被设计用来分离与旧web-application实例关联的ContextSelector实例。通过在web.xml中添加一下代码使用：

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

</listener>

大多数容器会顺序调用listeners的contextInitialized（）方法，并反序调用listeners的contextDestroyed（）方法。

Better performance

当ContextJNDISelector有效，每一次获取logger对象时，都会进行一次JNDI查找。这会对性能产生负面的影响，尤其是当你使用 non-static logger 引用时。Logback为了避免这种频繁的JNDI查找带来的消耗，提供了一个servlet filter  LoggerContextFilter，通过在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-request的开始，LoggerContextFilter会获得与应用关联的logger context，然后将它设为 ThreadLocal变量。ContextJNDISelector会首先查找ThreadLocal变量，如果在ThreadLocal中找到，则会跳过JNDI查找。需要注意，在LoggerContextFilter的doFilter（）方法之后，ThreadLocal变量将会被移除变为null。

ContextJNDISelector关键源码

private static final ThreadLocal<LoggerContext> threadLocal = new ThreadLocal<LoggerContext>();

public void setLocalContext(LoggerContext context) {

     threadLocal.set(context);

}

public LoggerContext getLoggerContext() {

          String contextName = null;

          Context ctx = null;

 

          // First check if ThreadLocal has been set already

          LoggerContext lc = threadLocal.get();

          if (lc != null) {

              return lc;

          }

 

          try {

              // We first try to find the name of our

              // environment's LoggerContext

              ctx = JNDIUtil.getInitialContext();

              contextName = (String) JNDIUtil.lookup(ctx, JNDI_CONTEXT_NAME);

          } catch (NamingException ne) {

              // We can't log here

          }

 

          if (contextName == null) {

              // We return the default context

              return defaultContext;

          } else {

              // Let's see if we already know such a context

              LoggerContext loggerContext = synchronizedContextMap.get(contextName);

 

              if (loggerContext == null) {

                  // We have to create a new LoggerContext

                loggerContext = new LoggerContext();

                loggerContext.setName(contextName);

                synchronizedContextMap.put(contextName, loggerContext);

                URL url = findConfigFileURL(ctx, loggerContext);

                if (url != null) {

                    configureLoggerContextByURL(loggerContext, url);

                } else {

                    try {

                        new ContextInitializer(loggerContext).autoConfig();

                    } catch (JoranException je) {

                    }

                }

                // logback-292

                if (!StatusUtil.contextHasStatusListener(loggerContext))

                    StatusPrinter.printInCaseOfErrorsOrWarnings(loggerContext);

            }

            return loggerContext;

        }

    }

Taming(改良) static references in shared libraries

ContextJNDISelector 在SLF4J和logback被所有应用共享的用例中，提供了良好的logging separation。当 ContextJNDISelector有效，每一次调用LoggerFactory.getLogger（）都会返回与当前应用相关的logger context。

引用一个logger的常见语法是静态引用，例如下面的例子：

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

静态的logger引用会有更高效的内存和cpu性能。这个class的所有实例只存在一个logger reference。此外，当这个class被加载进内存，这个logger实例也只会被获得一次而已。假设主要的class属于kenobi应用，则static logger会与kenobi 的logger context关联。假设有一个类叫Mustafar，同时属于kenobi 和 yoda应用，如果其logger未被声明为static，则每次调用LoggerFatory（）都会返回与当前应用logger context相关的logger，但是，如果被声明为static，则返回第一次调用它的应用的日志上下文相关的logger。因此，ContextJNDISelector不会为static logger references提供logging separation的功能。

能够透明并且完美的解决这个问题的唯一一种方法就是使用间接嵌入loggers的方式，这样logger-shell就会使用某种方法将工作委托给适合的logger context中的一个内部logger完成。

不说都知道，解决“shared class static logger”这个问题的最简单的方法就是通过将shared改成非shared，将原本共享的class变成应用独有。但是如果非得共享它们，也可以使用  SiftingAppender 来达到既使用JNDI，又要分离日志的功能。

Logback 自带了一个discriminator实现，叫  JNDIBasedContextDiscriminator ，会返回由ContextJNDISelector计算出的当前 logger context的名称。

下面是个配置的例子：

<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-applications，则kenobi的日志输出会输出到kenobi.log中，而yoda的日志会输出到yoda.log中。

你可以通过github下载 logback-starwars 项目来尝试刚才说的技术。

上面的方法虽然解决了日志的分离问题，但是也相当复杂。它需要正确的ContextJNDISelector配置，还要求使用SiftingAppender。

至此，我们也还没有完美解决这个问题。假设yoda应用比kenobi应用先初始化，初始化yoda应用后，访问 http://localhost:port/yoda/servlet 会调用YodaServlet，这个servlet输出hello，并且在调用foo方法前，Mustafar会输出简单的日志。调用YodaServlet后，yoda.log会包含以下内容

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

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

需要注意的是，直到server stop，Mustafar logger都会关联yoda的日志上下文。这时候你访问kenobi的servlet

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

可以看到，及时Mustafar的日志输出虽然定向到kenobi.log，但它仍然与yoda日志上下文关联。虽然logging separation 貌似跟我们想象的一样工作了，但为什么日志的内容并不如想象呢。原因是FileAppender实例没能安全的写入，除非开启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>