佳佳的博客

Appearance

Logback 手册 - 第八章：映射诊断上下文 ​

🏷️ Logback 手册

来源：https://logback.qos.ch/manual/mdc.html
作者：Ceki Gülcü, Sébastien Pennec, Carl Harris
版权所有 © 2000-2022 QOS.ch Sarl

本文档采用 创作共用 署名 - 非商业性 - 相同方式共享 2.5 许可证 授权。

Lock the doors.

锁好门。

—LEROY CAIN，哥伦比亚号任务控制负责人

WARNING

为了运行本章中的示例，您需要确保类路径上存在某些 jar 文件。请参考 设置页面 获取更多详细信息。

logback 的设计目标之一是审计和调试复杂的分布式应用程序。大多数实际的分布式系统需要同时处理多个客户端。在这样一个系统的典型多线程实现中，不同的线程将处理不同的客户端。为了区分一个客户端的日志输出与另一个客户端的日志输出，可能会采用一种可能但不太鼓励的方法，即为每个客户端实例化一个新的独立的记录器。这种技术会导致记录器的增加，并可能增加其管理开销。

一种更轻量级的技术是为服务于给定客户端的每个日志请求唯一标记。尼尔·哈里森在书籍《Pattern Languages of Program Design 3》（R. Martin, D. Riehle, and F. Buschmann 编辑，Addison-Wesley，1997）中描述了这种方法。Logback 利用了 SLF4J API 中包含的这种技术的变体：映射诊断上下文（Mapped Diagnostic Contexts，MDC）。

为了为每个请求唯一标记，用户将上下文信息放入 MDC（映射诊断上下文）中。下面是 MDC 类的主要部分。请参考 MDC 的 javadoc 获取完整的方法列表。

java
package org.slf4j;

public class MDC {
  //将由*key*标识的上下文值放入当前线程的上下文映射中。
  public static void put(String key, String val);

  //获取由`key`参数标识的上下文。
  public static String get(String key);

  //删除由`key`参数标识的上下文。
  public static void remove(String key);

  //清除 MDC 中的所有条目。
  public static void clear();
}

MDC 类仅包含静态方法。它允许开发人员将信息放入可以随后由某些 logback 组件检索的 诊断上下文 中。MDC 在 每个线程的基础上 管理上下文信息。通常，在开始处理新的客户端请求时，开发人员会将相关的上下文信息（如客户端 ID、客户端 IP 地址、请求参数等）插入到 MDC 中。如果适当配置了 logback 组件，它们将自动在每个日志条目中包含此信息。

请注意，由 logback-classic 实现的 MDC 假定值以适度频率放入 MDC 中。还请注意，子线程不会自动继承其父线程的映射诊断上下文的副本。

接下来的应用程序 SimpleMDC 演示了这个基本原理。

示例 7.1：基本的 MDC 用法（ logback-examples/src/main/java/chapters/mdc/SimpleMDC.java)

java
package chapters.mdc;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;

import ch.qos.logback.classic.PatternLayout;
import ch.qos.logback.core.ConsoleAppender;

public class SimpleMDC {
  static public void main(String[] args) throws Exception {

    //您可以随时向 MDC 中放入值。在其他任何操作之前，
    //我们先放入名字
    MDC.put("first", "Dorothy");

    [ SNIP ]
    
    Logger logger = LoggerFactory.getLogger(SimpleMDC.class);
    //现在我们放入姓氏
    MDC.put("last", "Parker");

    //根据 Dorothy Parker 所说，这是英语中最美丽的两个词：
    logger.info("Check enclosed.");
    logger.debug("The most beautiful two words in English.");

    MDC.put("first", "Richard");
    MDC.put("last", "Nixon");
    logger.info("I am not a crook.");
    logger.info("Attributed to the former US president. 17 Nov 1973.");
  }

  [ SNIP ]

}

main 方法首先将值 Dorothy 与键 first 关联到 MDC 中。您可以在 MDC 中放置任意数量的值 / 键关联。具有相同键的多次插入将覆盖较旧的值。然后代码继续配置 logback。

为了简洁起见，我们省略了配置 logback 的配置文件 simpleMDC.xml 中的代码。以下是该文件的相关部分。

xml
<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender"> 
  <layout>
    <Pattern>%X{first} %X{last} - %m%n</Pattern>
  </layout> 
</appender>

请注意，在 PatternLayout 转换模式中使用了 %X 说明符。%X 转换说明符用于键名为 first 和键名为 last 的键各一次。在获取与 SimpleMDC.class 相对应的记录器之后，代码将值 Parker 与名为 last 的键相关联。然后，它用不同的消息两次调用记录器。代码最后通过设置 MDC 的不同值并发出多个日志请求来完成。运行 SimpleMDC 会产生以下结果：

txt
Dorothy Parker - Check enclosed.
Dorothy Parker - The most beautiful two words in English.
Richard Nixon - I am not a crook.
Richard Nixon - Attributed to the former US president. 17 Nov 1973.

如果适当配置，SimpleMDC 应用程序可以说明 logback 布局如何自动输出 MDC 信息。此外，放置到 MDC 中的信息可以由多个记录器调用使用。

高级用法 ​

在客户端 - 服务器体系结构中，Mapped Diagnostic Contexts 发挥了最大的作用。通常，多个客户端将由服务器上的多个线程提供服务。虽然 MDC 类中的方法是静态的，但诊断上下文是按线程分配的，允许每个服务器线程带有不同的 MDC 戳记。MDC 操作（例如 put() 和 get()）仅影响 当前 线程和当前线程的子项的 MDC，其他线程中的 MDC 保持不变。鉴于 MDC 信息是按线程管理的，因此每个线程都将拥有自己的 MDC 副本。因此，当使用 MDC 编程时，开发人员无需担心线程安全性或同步问题，因为它会安全且透明地处理这些问题。

下一个示例有点更加高级。它显示了如何在客户端 - 服务器设置中使用 MDC。服务器端实现了示例 7.2 中显示的 NumberCruncher 接口。NumberCruncher 接口包含一个名为 factor() 的方法。使用 RMI 技术，客户端调用服务器应用程序的 factor() 方法以检索整数的不同因子。

示例 7.2：服务接口（logback-examples/src/main/java/chapters/mdc/NumberCruncher.java)

java
package chapters.mdc;

import java.rmi.Remote;
import java.rmi.RemoteException;

/**
 * NumberCruncher factors positive integers.
 */
public interface NumberCruncher extends Remote {
  /**
   * Factor a positive integer `number` and return its
   * distinct factor's as an integer array.
   * */
  int[] factor(int number) throws RemoteException;
}

在 Example 7.3 中列出了 NumberCruncherServer 应用程序，该应用程序实现了 NumberCruncher 接口。它的主要方法在本地主机上导出了一个 RMI 注册表，该注册表接受来自已知端口的请求。

示例 7.3：服务器端（logback-examples/src/main/java/chapters/mdc/NumberCruncherServer.java)

java
package chapters.mdc;

import java.rmi.RemoteException;
import java.rmi.registry.LocateRegistry;
import java.rmi.registry.Registry;
import java.rmi.server.UnicastRemoteObject;
import java.util.Vector;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;

import ch.qos.logback.classic.LoggerContext;
import ch.qos.logback.classic.joran.JoranConfigurator;
import ch.qos.logback.core.joran.spi.JoranException;

/**
 * A simple NumberCruncher implementation that logs its progress when
 * factoring numbers. The purpose of the whole exercise is to show the
 * use of mapped diagnostic contexts in order to distinguish the log
 * output from different client requests.
 * */
public class NumberCruncherServer extends UnicastRemoteObject
  implements NumberCruncher {

  private static final long serialVersionUID = 1L;

  static Logger logger = LoggerFactory.getLogger(NumberCruncherServer.class);

  public NumberCruncherServer() throws RemoteException {
  }

  public int[] factor(int number) throws RemoteException {
    // The client's host is an important source of information.
    try {
      MDC.put("client", NumberCruncherServer.getClientHost());
    } catch (java.rmi.server.ServerNotActiveException e) {
      logger.warn("Caught unexpected ServerNotActiveException.", e);
    }

    // The information contained within the request is another source
    // of distinctive information. It might reveal the users name,
    // date of request, request ID etc. In servlet type environments,
    // useful information is contained in the HttpRequest or in the  
    // HttpSession.
    MDC.put("number", String.valueOf(number));

    logger.info("Beginning to factor.");

    if (number <= 0) {
      throw new IllegalArgumentException(number +
        " is not a positive integer.");
    } else if (number == 1) {
      return new int[] { 1 };
    }

    Vector<Integer> factors = new Vector<Integer>();
    int n = number;

    for (int i = 2; (i <= n) && ((i * i) <= number); i++) {
      // It is bad practice to place log requests within tight loops.
      // It is done here to show interleaved log output from
      // different requests. 
      logger.debug("Trying " + i + " as a factor.");

      if ((n % i) == 0) {
        logger.info("Found factor " + i);
        factors.addElement(new Integer(i));

        do {
          n /= i;
        } while ((n % i) == 0);
      }

      // Placing artificial delays in tight loops will also lead to
      // sub-optimal results. :-)
      delay(100);
    }

    if (n != 1) {
      logger.info("Found factor " + n);
      factors.addElement(new Integer(n));
    }

    int len = factors.size();

    int[] result = new int[len];

    for (int i = 0; i < len; i++) {
      result[i] = ((Integer) factors.elementAt(i)).intValue();
    }

    // clean up
    MDC.remove("client");
    MDC.remove("number");

    return result;
  }

  static void usage(String msg) {
    System.err.println(msg);
    System.err.println("Usage: java chapters.mdc.NumberCruncherServer configFile\n" +
      "   where configFile is a logback configuration file.");
    System.exit(1);
  }

  public static void delay(int millis) {
    try {
      Thread.sleep(millis);
    } catch (InterruptedException e) {
    }
  }

  public static void main(String[] args) {
    if (args.length != 1) {
      usage("Wrong number of arguments.");
    }

    String configFile = args[0];

    if (configFile.endsWith(".xml")) {
      try {
        LoggerContext lc = (LoggerContext) LoggerFactory.getILoggerFactory();
        JoranConfigurator configurator = new JoranConfigurator();
        configurator.setContext(lc);
        lc.reset();
        configurator.doConfigure(args[0]);
      } catch (JoranException je) {
        je.printStackTrace();
      }
    }

    NumberCruncherServer ncs;

    try {
      ncs = new NumberCruncherServer();
      logger.info("Creating registry.");

      Registry registry = LocateRegistry.createRegistry(Registry.REGISTRY_PORT);
      registry.rebind("Factor", ncs);
      logger.info("NumberCruncherServer bound and ready.");
    } catch (Exception e) {
      logger.error("Could not bind NumberCruncherServer.", e);

      return;
    }
  }
}

factor(int number) 方法的实现非常重要。首先将客户端的主机名放入关键字为 client 的 MDC 中。客户端请求的数字被放入关键字为 number 的 MDC 中。在计算整数参数的不同因子之后，将结果返回给客户端。但在返回结果之前，通过调用 MDC.remove() 方法来清除 client 和 number 的值。通常，put() 操作应该由相应的 remove() 操作平衡。否则，MDC 将包含某些关键字的旧值。我们建议尽可能在 finally 块中执行 remove() 操作，确保无论代码的执行路径如何都会调用它们。

在这些理论解释之后，我们准备运行数值处理器示例。使用以下命令启动服务器：

bash
java chapters.mdc.NumberCruncherServer src/main/java/chapters/mdc/mdc1.xml

mdc1.xml 配置文件如下：

Example 7.4: Configuration file (logback-examples/src/main/java/chapters/mdc/mdc1.xml)

xml
<configuration>
  <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
    <layout>
      <Pattern>%-4r [%thread] %-5level C:%X{client} N:%X{number} - %msg%n</Pattern>
    </layout>	    
  </appender>
  
  <root level="debug">
    <appender-ref ref="CONSOLE"/>
  </root>  
</configuration>

请注意在 Pattern 选项中使用了 %X 转换说明符。

以下命令启动 NumberCruncherClient 应用程序的一个实例：

bash
java chapters.mdc.NumberCruncherClient hostname

其中 hostname 是运行 NumberCruncherServer 的主机。

执行多个客户端实例，并请求服务器分解第一个客户端的数字 129，不久之后再从第二个客户端请求数字 71，服务器将输出以下内容：

txt
70984 [RMI TCP Connection(4)-192.168.1.6] INFO  C:orion N:129 - Beginning to factor.
70984 [RMI TCP Connection(4)-192.168.1.6] DEBUG C:orion N:129 - Trying 2 as a factor.
71093 [RMI TCP Connection(4)-192.168.1.6] DEBUG C:orion N:129 - Trying 3 as a factor.
71093 [RMI TCP Connection(4)-192.168.1.6] INFO  C:orion N:129 - Found factor 3
71187 [RMI TCP Connection(4)-192.168.1.6] DEBUG C:orion N:129 - Trying 4 as a factor.
71297 [RMI TCP Connection(4)-192.168.1.6] DEBUG C:orion N:129 - Trying 5 as a factor.
71390 [RMI TCP Connection(4)-192.168.1.6] DEBUG C:orion N:129 - Trying 6 as a factor.
71453 [RMI TCP Connection(5)-192.168.1.6] INFO  C:orion N:71 - Beginning to factor.
71453 [RMI TCP Connection(5)-192.168.1.6] DEBUG C:orion N:71 - Trying 2 as a factor.
71484 [RMI TCP Connection(4)-192.168.1.6] DEBUG C:orion N:129 - Trying 7 as a factor.
71547 [RMI TCP Connection(5)-192.168.1.6] DEBUG C:orion N:71 - Trying 3 as a factor.
71593 [RMI TCP Connection(4)-192.168.1.6] DEBUG C:orion N:129 - Trying 8 as a factor.
71656 [RMI TCP Connection(5)-192.168.1.6] DEBUG C:orion N:71 - Trying 4 as a factor.
71687 [RMI TCP Connection(4)-192.168.1.6] DEBUG C:orion N:129 - Trying 9 as a factor.
71750 [RMI TCP Connection(5)-192.168.1.6] DEBUG C:orion N:71 - Trying 5 as a factor.
71797 [RMI TCP Connection(4)-192.168.1.6] DEBUG C:orion N:129 - Trying 10 as a factor.
71859 [RMI TCP Connection(5)-192.168.1.6] DEBUG C:orion N:71 - Trying 6 as a factor.
71890 [RMI TCP Connection(4)-192.168.1.6] DEBUG C:orion N:129 - Trying 11 as a factor.
71953 [RMI TCP Connection(5)-192.168.1.6] DEBUG C:orion N:71 - Trying 7 as a factor.
72000 [RMI TCP Connection(4)-192.168.1.6] INFO  C:orion N:129 - Found factor 43
72062 [RMI TCP Connection(5)-192.168.1.6] DEBUG C:orion N:71 - Trying 8 as a factor.
72156 [RMI TCP Connection(5)-192.168.1.6] INFO  C:orion N:71 - Found factor 71

可以看到，客户端是从名为 orion 的机器运行的。即使服务器近乎同时在单独的线程中处理客户端请求，通过查看 MDC 的输出，仍然可以区分与每个客户端请求相关的日志输出。例如，请注意与 number 关联的时间戳，即要分解的数字。

仔细的读者可能已经注意到，线程名称也可以用于区分每个请求。如果服务器端技术重新使用线程，则线程名称可能会引起混淆。在这种情况下，可能很难确定每个请求的边界，即给定线程完成服务请求的时间和开始服务下一个请求的时间。由于 MDC 受应用程序开发人员控制，因此 MDC 印戳不会遇到这个问题。

自动化访问 MDC ​

如我们所见，当处理多个客户端时，MDC 非常有用。在管理用户身份验证的 Web 应用程序中，一种简单的解决方案可能是将用户的名称设置为 MDC 中的值，并在用户注销后将其删除。不幸的是，使用这种技术并不总是能获得可靠的结果。由于 MDC 在 每个线程 基础上管理数据，因此重新使用线程的服务器可能会导致 MDC 中包含错误的信息。

为了在处理请求时始终使 MDC 中包含的信息正确，一种可能的方法是在处理过程开始时存储用户名，并在该过程结束时删除它。在这种情况下，servlet Filter 就非常有用了。

在 servlet 过滤器的 doFilter 方法中，我们可以通过请求（或其中的 cookie）检索相关用户数据，将其存储在 MDC 中。其他过滤器和 servlet 的后续处理将自动从先前存储的 MDC 数据中受益。最后，在我们的 servlet 过滤器重新获得控制权时，我们有机会清理 MDC 数据。

这是一个这样的过滤器的实现：

示例 7.5: 用户 Servlet 过滤器（logback-examples/src/main/java/chapters/mdc/UserServletFilter.java）

java
package chapters.mdc;

import java.io.IOException;
import java.security.Principal;

import javax.servlet.Filter;
import javax.servlet.FilterChain;
import javax.servlet.FilterConfig;
import javax.servlet.ServletException;
import javax.servlet.ServletRequest;
import javax.servlet.ServletResponse;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpSession;

import org.slf4j.MDC;

public class UserServletFilter implements Filter {

  private final String USER_KEY = "username";
  
  public void destroy() {
  }

  public void doFilter(ServletRequest request, ServletResponse response,
    FilterChain chain) throws IOException, ServletException {

    boolean successfulRegistration = false;

    HttpServletRequest req = (HttpServletRequest) request;    
    Principal principal = req.getUserPrincipal();
    // Please note that we could have also used a cookie to 
    // retrieve the user name

    if (principal != null) {
      String username = principal.getName();
      successfulRegistration = registerUsername(username);
    } 

    try {
      chain.doFilter(request, response);
    } finally {
      if (successfulRegistration) {
        MDC.remove(USER_KEY);
      }
    }
  }

  public void init(FilterConfig arg0) throws ServletException {
  }
  

  /**
   * Register the user in the MDC under USER_KEY.
   * 
   * @param username
   * @return true id the user can be successfully registered
   */
  private boolean registerUsername(String username) {
    if (username != null && username.trim().length() > 0) {
      MDC.put(USER_KEY, username);
      return true;
    }
    return false;
  }
}

当调用过滤器的 doFilter() 方法时，它首先在请求中查找 java.security.Principal 对象。该对象包含当前经过身份验证的用户的名称。如果找到用户信息，则将其注册到 MDC 中。

一旦过滤器链完成，过滤器会从 MDC 中移除用户信息。

我们刚刚概述的方法仅为请求的持续时间和处理请求的线程设置 MDC 数据。其他线程不受影响。此外，任何给定的线程在任何时间点都将包含正确的 MDC 数据。

MDC 和受控线程 ​

无法始终通过子线程从发起线程继承映射的诊断上下文。当使用 java.util.concurrent.Executors 进行线程管理时就是这种情况。例如，newCachedThreadPool 方法创建一个 ThreadPoolExecutor，和其他线程池代码一样，它具有复杂的线程创建逻辑。

在这种情况下，建议在将任务提交给执行器之前，在原始（主）线程上调用 MDC.getCopyOfContextMap()。当任务运行时，作为其第一个操作，应调用 MDC.setContextMap() 将存储的原始 MDC 值的副本与新的 Executor 管理的线程关联起来。

MDCInsertingServletFilter ​

在 Web 应用程序中，了解与给定 HTTP 请求相关的主机名、请求 URI 和用户代理通常很有帮助。MDCInsertingServletFilter 将这些数据插入到 MDC 中，使用以下键。

MDC 键MDC 值
req.remoteHost由 getRemoteHost() 方法返回的值
req.xForwardedFor"X-Forwarded-For" 标头的值
req.method由 getMethod() 方法返回的值
req.requestURI由 getRequestURI() 方法返回的值
req.requestURL由 getRequestURL() 方法返回的值
req.queryString由 getQueryString() 方法返回的值
req.userAgent"User-Agent" 标头的值

要安装 MDCInsertingServletFilter，请将以下行添加到您的 Web 应用程序的 web.xml 文件中

xml
<filter>
  <filter-name>MDCInsertingServletFilter</filter-name>
  <filter-class>
    ch.qos.logback.classic.helpers.MDCInsertingServletFilter
  </filter-class>
</filter>
<filter-mapping>
  <filter-name>MDCInsertingServletFilter</filter-name>
  <url-pattern>/*</url-pattern>
</filter-mapping>

如果您的 Web 应用程序有多个过滤器，请确保 MDCInsertingServletFilter 在其他过滤器之前声明。 例如，假设您的 Web 应用程序的主要处理在过滤器 'F' 中完成，如果 MDCInsertingServletFilter 在 'F' 之后出现，则 'F' 调用的代码将看不到 MDCInsertingServletFilter 设置的 MDC 值。

安装过滤器后，与每个 MDC 键对应的值将根据作为第一个选项传递的键由 %X 转换词 输出。例如，要在一行上打印远程主机名，后跟请求 URI，日期后跟消息，可以将 PatternLayout 的模式设置为：

java
%X{req.remoteHost} %X{req.requestURI}%n%d - %m%n