第 8 章：Map 的诊断上下文

**锁上门

—哥伦比亚特派团控制部飞行总监 LEROY CAIN **

logback的设计目标之一是审核和调试复杂的分布式应用程序。大多数现实世界的分布式系统都需要同时处理多个 Client 端。在这种系统的典型多线程实现中，不同的线程将处理不同的 Client 端。将一个 Client 端的日志记录输出与另一个 Client 端的日志记录输出区分开的一种可能但略微沮丧的方法包括为每个 Client 端实例化一个新的单独的 Logger。此技术促进 Logger 的扩散，并可能增加其 Management 开销。

一种更轻松的技术包括对服务给定 Client 端的每个日志请求进行唯一标记。尼尔·哈里森(Neil Harrison)在 R. Martin，D.Riehle 和 F.Buschmann(Addison-Wesley，1997)编辑的《程序设计 3 的模式语言中的*记录诊断消息的模式》中描述了这种方法。 Logback 利用了 SLF4J API 中包含的此技术的一种变体：Map 诊断上下文(MDC)。

为了唯一标记每个请求，用户将上下文信息放入MDC，即“Map 的诊断上下文”的缩写。 MDC 类的主要部分如下所示。有关方法的完整列表，请参考MDC javadocs。

package org.slf4j;

public class MDC {
  //Put a context value as identified by key
  //into the current thread's context map.
  public static void put(String key, String val);

  //Get the context identified by the key parameter.
  public static String get(String key);

  //Remove the context identified by the key parameter.
  public static void remove(String key);

  //Clear all entries in the MDC.
  public static void clear();
}

MDC类仅包含静态方法。它使开发人员可以将信息放置在“诊断上下文”中，这些信息随后可以由某些 logback 组件检索。 MDC基于每个线程Management 上下文信息。通常，在开始为新的 Client 请求提供服务时，开发人员会将相关的上下文信息(例如 ClientID，Client 的 IP 地址，请求参数等)插入MDC。如果配置正确，则 Logback 组件将自动在每个日志条目中包含此信息。

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

下一个名为SimpleMDC的应用程序演示了此基本原理。

*例 7.1：基本 MDC 用法(logback-examples/src/main/java/chapters/mdc/SimpleMDC.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 {

    // You can put values in the MDC at any time. Before anything else
    // we put the first name
    MDC.put("first", "Dorothy");

    [ SNIP ]
    
    Logger logger = LoggerFactory.getLogger(SimpleMDC.class);
    // We now put the last name
    MDC.put("last", "Parker");

    // The most beautiful two words in the English language according
    // to 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 ]

}

主要方法开始于将值* Dorothy 与MDC中的键 first *关联。您可以根据需要在MDC中放置任意数量的值/键关联。使用相同密钥的多次插入将覆盖较早的值。然后，代码 continue 进行配置，以进行 logback。

为了简洁起见，我们省略了使用配置文件simpleMDC.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对应的 Logger 后，代码将值 Parker 与名为 last *的键相关联。然后，它使用不同的消息两次调用 Logger。通过将MDC设置为不同的值并发出多个日志记录请求来完成代码。运行 SimpleMDC 会产生：

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中的信息可由多个 Logger 调用使用。

Advanced Use

Map 的诊断上下文在 Client 端服务器体系结构中最为突出。通常，服务器上的多个线程将为多个 Client 端提供服务。尽管MDC类中的方法是静态的，但诊断上下文是基于每个线程进行 Management 的，从而允许每个服务器线程带有不同的MDC标记。 MDC操作(例如put()和get())仅影响* current *线程的MDC和当前线程的子代。其他线程中的MDC保持不受影响。假设MDC信息是在每个线程的基础上进行 Management 的，则每个线程将拥有自己的MDC副本。因此，使用MDC进行编程时，开发人员无需担心线程安全性或同步性，因为它可以安全透明地处理这些问题。

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

*示例 7.2：服务界面(logback-examples/src/main/java/chapters/mdc/NumberCruncher.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;
}

下面的示例 7.3 中列出的NumberCruncherServer应用程序实现了NumberCruncher接口。它的主要方法是在 localhost 上导出 RMI 注册表，该注册表在一个知名端口上接受请求。

*例 7.3：服务器端(logback-examples/src/main/java/chapters/mdc/NumberCruncherServer.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 端的主机名放在* client 键下的MDC中。根据 Client 的要求，将要分解的数字放在MDC的键 number 下。计算完整数参数的不同因子后，结果将返回给 Client 端。但是，在返回结果之前，将通过调用MDC.remove()方法清除 client 和 number *的值。通常，put()操作应由相应的remove()操作平衡。否则，MDC将包含某些键的陈旧值。我们建议尽可能在 final 块内执行remove()操作，以确保无论代码的执行路径如何都可以调用它们。

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

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

下面列出了* mdc1.xml *配置文件：

例 7.4：配置文件(logback-examples/src/main/java/chapters/mdc/mdc1.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>

请注意，“模式”选项中使用了*％X *转换说明符。

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

java chapters.mdc.NumberCruncherClient hostname

其中* hostname *是运行NumberCruncherServer的主机

执行 Client 端的多个实例，并请求服务器将第一个 Client 端的数字 129 分解为因子，然后不久之后第二个 Client 端的服务器将其分解为数字 71，服务器输出以下内容：

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

Client 端从名为* orion 的计算机运行，如上面的输出所示。即使服务器在单独的线程中几乎同时处理 Client 端的请求，也可以通过研究MDC的输出来区分与每个 Client 端请求有关的日志记录输出。请注意例如与 number *关联的邮票，即要分解的数字。

细心的 Reader 可能已经注意到，线程名称也可以用于区分每个请求。如果服务器端技术回收线程，则线程名称可能引起混乱。在那种情况下，可能很难确定每个请求的边界，即给定线程何时完成为一个请求提供服务以及何时开始为下一个请求提供服务。因为MDC受应用程序开发人员控制，所以MDC戳不会受到此问题的影响。

自动访问 MDC

如我们所见，与多个 Client 打交道时，MDC非常有用。对于 Management 用户身份验证的 Web 应用程序，一种简单的解决方案可能是在MDC中设置用户名，并在用户注销后将其删除。不幸的是，使用这种技术并不总是可能获得可靠的结果。由于MDC基于每个线程Management 数据，因此回收线程的服务器可能会导致MDC中包含错误的信息。

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

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

这是这种过滤器的实现：

*示例 7.5：用户 servlet 过滤器(logback-examples/src/main/java/chapters/mdc/UserServletFilter.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 和托管线程

Map 的诊断上下文的副本不能始终由工作线程从发起线程继承。使用java.util.concurrent.Executors进行线程 Management 时就是这种情况。例如，newCachedThreadPool方法创建ThreadPoolExecutor，并且像其他线程池代码一样，它具有复杂的线程创建逻辑。

在这种情况下，建议在将任务提交给执行者之前在原始(主)线程上调用MDC.getCopyOfContextMap()。当任务运行时，作为第一个动作，它应调用MDC.setContextMapValues()将原始 MDC 值的存储副本与新的Executor托管线程相关联。

MDCInsertingServletFilter

在 Web 应用程序中，了解与给定 HTTP 请求关联的主机名，请求 uri 和用户代理通常会很有帮助。 MDCInsertingServletFilter在以下键下将此类数据插入 MDC。

MDC key	MDC value
req.remoteHost	由getRemoteHost()方法返回
req.xForwardedFor	"X-Forwarded-For"Headers 的值
req.method	由getMethod()方法返回
req.requestURI	由getRequestURI()方法返回
req.requestURL	由getRequestURL()方法返回
req.queryString	由getQueryString()方法返回
req.userAgent	“用户代理”Headers 的值

要安装MDCInsertingServletFilter，请将以下行添加到 Web 应用程序的* web.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>

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

安装过滤器后，％X conversion word将根据密钥通过作为第一个选项输出与每个 MDC 密钥相对应的值。例如，要打印远程主机，然后在一行上打印请求 URI，在下一行上打印日期，然后在消息上打印消息，则可以将PatternLayout的模式设置为：

％X{req.remoteHost}％X{req.requestURI}％n％d-％m％n