正文

Java 日志管理最佳实践

IP云
IP云V管理员/2 阅读
10/31
提示：扫一扫查出行
【扫一扫了解最新限行尾号】
复制提示

转：http://blog.jobbole.com/51155/

日志记录是应用程序运行中必不可少的一部分。具有良好格式和完备信息的日志记录可以在程序出现问题时帮助开发人员迅速地定位错误的根源。对于开 发人员来说，在程序中使用日志API记录日志并不复杂，不过遵循一些最佳实践可以更好的利用日志。本文介绍了在Java程序中记录日志的最佳实践，同时也 介绍了如何使用开源软件对日志进行聚合和分析。

概述

对于现在的应用程序来说，日志的重要性是不言而喻的。很难想象没有任何日志记录功能的应用程序运行 在生产环境中。日志所能提供的功能是多种多样的，包括记录程序运行时产生的错误信息、状态信息、调试信息和执行时间信息等。在生产环境中，日志是查找问题 来源的重要依据。应用程序运行时的产生的各种信息，都应该通过日志 API 来进行记录。很多开发人员习惯于使用 System.out.println、System.err.println 以及异常对象的 printStrackTrace 方法来输出相关信息。这些使用方式虽然简便，但是所产生的信息在出现问题时并不能提供有效的帮助。这些使用方式都应该改为使用日志 API。使用日志 API 并没有增加很多复杂度，但是所提供的好处是显著的。

尽管记录日志是应用开发中并不可少的功能，在 JDK 的最初版本中并不包含日志记录相关的 API 和实现。相关的 API（java.util.logging 包，JUL）和实现，直到 JDK 1.4 才被加入。因此在日志记录这一个领域，社区贡献了很多开源的实现。其中比较流行的包括 log4j 及其后继者 logback。除了真正的日志记录实现之外，还有一类与日志记录相关的封装 API，如 Apache Commons Logging 和 SLF4J。这类库的作用是在日志记录实现的基础上提供一个封装的 API 层次，对日志记录 API 的使用者提供一个统一的接口，使得可以自由切换不同的日志记录实现。比如从 JDK 的默认日志记录实现 JUL 切换到 log4j。这类封装 API 库在框架的实现中比较常用，因为需要考虑到框架使用者的不同需求。在实际的项目开发中则使用得比较少，因为很少有项目会在开发中切换不同的日志记录实现。 本文对于这两类库都会进行具体的介绍。

记录日志只是有效地利用日志的第一步，更重要的是如何对程序运行时产生的日志进行处理和分析。典型的 情景包括当日志中包含满足特定条件的记录时，触发相应的通知机制，比如邮件或短信通知；还可以在程序运行出现错误时，快速地定位潜在的问题源。这样的处理 和分析的能力对于实际系统的维护尤其重要。当运行系统中包含的组件过多时，日志对于错误的诊断就显得格外重要。

本文首先介绍关于日志 API 的基本内容。

Java 日志 API

从功能上来说，日志 API 本身所需求的功能非常简单，只需要能够记录一段文本即可。API 的使用者在需要进行记录时，根据当前的上下文信息构造出相应的文本信息，调用 API 完成记录。一般来说，日志 API 由下面几个部分组成：

  • 记录器（Logger）：日志 API 的使用者通过记录器来发出日志记录请求，并提供日志的内容。在记录日志时，需要指定日志的严重性级别。
  • 格式化器（Formatter）：对记录器所记录的文本进行格式化，并添加额外的元数据。
  • 处理器（Handler）：把经过格式化之后的日志记录输出到不同的地方。常见的日志输出目标包括控制台、文件和数据库等。

记录器

当 程序中需要记录日志时，首先需要获取一个日志记录器对象。一般的日志记录 API 都提供相应的工厂方法来创建记录器对象。每个记录器对象都是有名称的。一般的做法是使用当前的 Java 类的名称或所在包的名称作为记录器对象的名称。记录器的名称通常是具有层次结构的，与 Java 包的层次结构相对应。比如 Java 类“com.myapp.web.IndexController”中使用的日志记录器的名称一般是 “com.myapp.web.IndexController”或“com.myapp.web”。除了使用类名或包名之外，还可以根据日志记录所对应 的功能来进行划分，从而选择不同的名称。比如用“security”作为所有与安全相关的日志记录器的名称。这样的命名方式对于某些横切的功能比较实用。 开发人员一般习惯于使用当前的类名作为日志记录器的名称，这样可以快速在日志记录中定位到产生日志的 Java 类。使用有意义的其他名称在很多情况下也是一个不错的选择。

在通过日志记录器对象记录日志时，需要指定日志的严重性级别。根据每个记录器对 象的不同配置，低于某个级别的日志消息可能不会被记录下来。该级别是日志 API 的使用者根据日志记录中所包含的信息来自行决定的。不同的日志记录 API 所定义的级别也不尽相同。日志记录封装 API 也会定义自己的级别并映射到底层实现中相对应的实际级别。比如 JDK 标准的日志 API 使用的级别包括 OFF、SEVERE、WARNING、INFO、CONFIG、FINE、FINER、FINEST 和 ALL 等，Log4j 使用的级别则包括 OFF、FATAL、ERROR、WARN、INFO、DEBUG、TRACE 和 ALL 等。一般情况下，使用得比较多的级别是 FATAL、ERROR、WARN、INFO、DEBUG 和 TRACE 等。这 6 个级别所对应的情况也有所不同：

  • FATAL：导致程序提前结束的严重错误。
  • ERROR：运行时异常以及预期之外的错误。
  • WARN：预期之外的运行时状况，不一定是错误的情况。
  • INFO：运行时产生的事件。
  • DEBUG：与程序运行时的流程相关的详细信息。
  • TRACE：更加具体的详细信息。

在这 6 个级别中，以 ERROR、WARN、INFO 和 DEBUG 作为常用。

日 志记录 API 的使用者通过记录器来记录日志消息。日志消息在记录下来之后只能以文本的形式保存。不过有的实现（如 Log4j）允许在记录日志时使用任何 Java 对象。非 String 类型的对象会被转换成 String 类型。由于日志记录通常在出现异常时使用，记录器在记录消息时可以把产生的异常（Throwable 类的对象）也记录下来。

每个记录器对 象都有一个运行时对应的严重性级别。该级别可以通过配置文件或代码的方式来进行设置。如果没有显式指定严重性级别，则会根据记录器名称的层次结构关系往上 进行查找，直到找到一个设置了严重性级别的名称为止。比如名称为“com.myapp.web.IndexController”的记录器对象，如果没有 显式指定其严重性级别，则会依次查找是否有为名称“com.myapp.web”、“com.myapp”和“com”指定的严重性级别。如果仍然没有找 到，则使用根记录器配置的值。

通过记录器对象来记录日志时，只是发出一个日志记录请求。该请求是否会完成取决于请求和记录器对象的严重性级 别。记录器使用者产生的低于记录器对象严重性级别的日志消息不会被记录下来。这样的记录请求会被忽略。除了基于严重性级别的过滤方式之外，日志记录框架还 支持其他自定义的过滤方式。比如 JUL 可以通过实现 java.util.logging.Filter 接口的方式来进行过滤。Log4j 可以通过继承 org.apache.log4j.spi.Filter 类的方式来过滤。

格式化器

实际记录的日志中除了使用记录器对象时提供的消息之外，还包括一些元数据。这些元数据由日志记录框架来提供。常用的信息包括记录器的名称、时间戳、线程名等。格式化器用来确定所有这些信息在日志记录中的展示方式。不同的日志记录实现提供各自默认的格式化方式和自定义支持。

JUL 中通过继承 java.util.logging.Formatter 类来自定义格式化的方式，并提供了两个标准实现 SimpleFormatter 类和 XMLFormatter 类。清单 1 中给出了 JUL 中自定义格式化器的实现方式，只需要继承自 Formatter 类并实现 format 方法即可。参数 LogRecord 类的对象中包含了日志记录中的全部信息。

清单 1. JUL 中自定义格式化器的实现
1
2
3
4
5
public class CustomFormatter extends Formatter {
    public String format(LogRecord record) {
        return String.format("<%s> [%s] : %s", new Date(record.getMillis()), record.getLoggerName(), record.getMessage());
    }
 }

对于自定义的格式化器类，需要在 JUL 的配置文件中进行指定，如清单 2 所示。

清单 2. 在 JUL 配置文件中指定自定义的格式化器类
1
java.util.logging.ConsoleHandler.formatter = logging.jul.CustomFormatter

Log4j 在格式化器的实现上要简单一些，由 org.apache.log4j.PatternLayout 类来负责完成日志记录的格式化。在自定义时不需要创建新的 Java 类，而是通过配置文件指定所需的格式化模式。在格式化模式中，不同的占位符表示不同类型的信息。比如“%c”表示记录器的名称，“%d”表示日 期，“%m”表示日志的消息文本，“%p”表示严重性级别，“%t”表示线程的名称。清单 3 给出了 Log4j 配置文件中日志记录的自定义方式。

清单 3. Log4j 中日志记录的自定义方式
1
log4j.appender.stdout.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss} [%p] %c - %m%n

日志处理器

日志记录经过格式化之后，由不同的处理器来进行处理。不同的处理器有各自不同的处理方式。比如控制台处理器会把日志输出到控制台中，文件处理器把日志写入到文件中。除了这些之外，还有写入到数据库、通过邮件发送、写入到 JMS 队列等各种不同的处理方式。

日志处理器也可以配置所处理日志信息的最低严重性级别。低于该级别的日志不会被处理。这样可以控制所处理的日志记录数量。比如控制台处理器的级别一般设置为 INFO，而文件处理器则一般设置为 DEBUG。

日志记录框架一般提供了比较多的日志处理器实现。开发人员也可以创建自定义的实现。

Java 日志封装 API

除 了 JUL 和 log4j 这样的日志记录库之外，还有一类库用来封装不同的日志记录库。这样的封装库中一开始以 Apache Commons Logging 框架最为流行，现在比较流行的是 SLF4J。这样封装库的 API 都比较简单，只是在日志记录库的 API 基础上做了一层简单的封装，屏蔽不同实现之间的区别。由于日志记录实现所提供的 API 大致上比较相似，封装库的作用更多的是达到语法上的一致性。

在 Apache Commons Logging 库中，核心的 API 是 org.apache.commons.logging.LogFactory 类和 org.apache.commons.logging.Log 接口。LogFactory 类提供了工厂方法用来创建 Log 接口的实现对象。比如 LogFactory.getLog 可以根据 Java 类或名称来创建 Log 接口的实现对象。Log 接口中为 6 个不同的严重性级别分别定义了一组方法。比如对 DEBUG 级别，定义了 isDebugEnabled()、debug(Object message) 和 debug(Object message, Throwable t) 三个方法。从这个层次来说，Log 接口简化了对于日志记录器的使用。

SLF4J 库的使用方式与 Apache Commons Logging 库比较类似。SLF4J 库中核心的 API 是提供工厂方法的 org.slf4j.LoggerFactory 类和记录日志的 org.slf4j.Logger 接口。通过 LoggerFactory 类的 getLogger 方法来获取日志记录器对象。与 Apache Commons Logging 库中的 Log 接口类似，Logger 接口中的方法也是按照不同的严重性级别来进行分组的。Logger 接口中有同样 isDebugEnabled 方法。不过 Logger 接口中发出日志记录请求的 debug 等方法使用 String 类型来表示消息，同时可以使用包含参数的消息，如清单 4 所示。

清单 4. SLF4J 的使用方式
1
2
3
4
5
6
7
8
public class Slf4jBasic {
   private static final Logger LOGGER = LoggerFactory.getLogger(Slf4jBasic.class);
   public void logBasic() {
       if (LOGGER.isInfoEnabled()) {
           LOGGER.info("My log message for %s", "Alex");
       }
   }
}

MDC

MDC（Mapped Diagnostic Context，映射调试上下文）是 log4j 和 logback 提供的一种方便在多线程条件下记录日志的功能。某些应用程序采用多线程的方式来处理多个用户的请求。在一个用户的使用过程中，可能有多个不同的线程来进行 处理。典型的例子是 Web 应用服务器。当用户访问某个页面时，应用服务器可能会创建一个新的线程来处理该请求，也可能从线程池中复用已有的线程。在一个用户的会话存续期间，可能有 多个线程处理过该用户的请求。这使得比较难以区分不同用户所对应的日志。当需要追踪某个用户在系统中的相关日志记录时，就会变得很麻烦。

一种解决的办法是采用自定义的日志格式，把用户的信息采用某种方式编码在日志记录中。这种方式的问题在于要求在每个使用日志记录器的类中，都可以访问到用户相关的信息。这样才可能在记录日志时使用。这样的条件通常是比较难以满足的。MDC 的作用是解决这个问题。

MDC 可以看成是一个与当前线程绑定的哈希表，可以往其中添加键值对。MDC 中包含的内容可以被同一线程中执行的代码所访问。当前线程的子线程会继承其父线程中的 MDC 的内容。当需要记录日志时，只需要从 MDC 中获取所需的信息即可。MDC 的内容则由程序在适当的时候保存进去。对于一个 Web 应用来说，通常是在请求被处理的最开始保存这些数据。清单 5 中给出了 MDC 的使用示例。

清单 5. MDC 使用示例
1
2
3
4
5
6
7
8
9
public class MdcSample {
   private static final Logger LOGGER = Logger.getLogger("mdc");
   public void log() {
       MDC.put("username", "Alex");
       if (LOGGER.isInfoEnabled()) {
           LOGGER.info("This is a message.");
       }
   }
}

清单 5 中，在记录日志前，首先在 MDC 中保存了名称为“username”的数据。其中包含的数据可以在格式化日志记录时直接引用，如清单 6 所示，“%X{username}”表示引用 MDC 中“username”的值。

清单 6. 使用 MDC 中记录的数据
1
log4j.appender.stdout.layout.ConversionPattern=%X{username} %d{yyyy-MM-dd HH:mm:ss} [%p] %c - %m%n

日志记录最佳实践

下面主要介绍一些在记录日志时的比较好的实践。

检查日志是否可以被记录

当 日志记录器收到一个日志记录请求时，如果请求的严重性级别低于记录器对象的实际有效级别，则该请求会被忽略。在日志记录方法的实现中会首先进行这样的检 查。不过推荐的做法是在调用 API 进行记录之前，首先进行相应的检查，这样可以避免不必要的性能问题，如清单 7 所示。

清单 7. 检查日志是否可以被记录
1
2
3
if (LOGGER.isDebugEnabled()) {
   LOGGER.debug("This is a message.");
}

清单 7 中的做法的作用在于避免了构造日志记录消息所带来的开销。日志消息中通常包含与当前上下文相关的信息。为了获取这些信息并构造相应的消息文本，不可避免会 产生额外的开销。尤其对于 DEBUG 和 TRACE 级别的日志消息来说，它们所出现的频率很高，累加起来的开销比较大。因此在记录 INFO、DEBUG 和 TRACE 级别的日志时，首先进行相应的检查是一个好的实践。而 WARN 及其以上级别的日志则一般不需要进行检查。

日志中包含充分的信息

日 志中所包含的信息应该是充分的。在记录日志消息时应该尽可能多的包含当前上下文中的各种信息，以方便在遇到问题时可以快速的获取到所需的信息。比如在网上 支付功能中，与支付相关的日志应该完整的包含当前用户、订单以及支付方式等全部信息。一种比较常见的做法是把相关的日志记录分散在由不同日志记录器所记录 的日志中。当出现问题之后，需要手工查找并匹配相关的日志来定位问题，所花费的时间和精力会更多。因此，应该尽可能在一条日志记录中包含足够多的信息。

使用合适的日志记录器名称

一 般的日志记录实践是使用当前 Java 类的全名作为其使用的日志记录器的名称。这样做可以得到一个与 Java 类和包的层次结构相对应的日志记录器的层次结构。可以很方便的按照不同的模块来设置相应的日志记录级别。不过对于某些全局的或是横切的功能，如安全和性能 等，则推荐使用功能相关的名称。比如程序中可能包含用来提供性能剖析信息的日志记录。对于这样的日志记录，应该使用同一名称的日志记录器，如类似 “performance”或“performance.web”。这样当需要启用和禁用性能剖析时，只需要配置这些名称的记录器即可。

使用半结构化的日志消息

在 介绍日志记录 API 中的格式化器时提到过，日志记录中除了基本的日志消息之外，还包括由日志框架提供的其他元数据。这些数据按照给定的格式出现在日志记录中。这些半结构化的 格式使得可以通过工具提取日志记录中的相关信息进行分析。在使用日志 API 进行记录时，对于日志消息本身，也推荐使用半结构化的方式来组织。

比如一个电子商务的网站，当用户登录之后，该用户所产生的不同操作所对应的日志记录中都可以包含该用户的用户名，并以固定的格式出现在日志记录中，如清单 8 所示。

清单 8. 使用半结构化的日志消息
1
2
3
[user1] 用户登录成功。
[user1] 用户成功购买产品 A。
[user2] 订单 003 付款失败。

当需要通过日志记录来排查某个用户所遇到的问题时，只需要通过正则表达就可以很快地查询到用户相关的日志记录。

日志聚合与分析

在 程序中正确的地方输出合适的日志消息，只是合理使用日志的第一步。日志记录的真正作用在于当有问题发生时，能够帮助开发人员很快的定位问题所在。不过一个 实用的系统通常由很多个不同的部分组成。这其中包括所开发的程序本身，也包括所依赖的第三方应用程序。以一个典型的电子商务网站为例，除了程序本身，还包 括所依赖的底层操作系统、应用服务器、数据库、HTTP 服务器和代理服务器和缓存等。当一个问题发生时，真正的原因可能来自程序本身，也可能来自所依赖的第三方程序。这就意味着开发人员可能需要检查不同服务器 上不同应用程序的日志来确定真正的原因。

日志聚合的作用就在于可以把来自不同服务器上不同应用程序产生的日志聚合起来，存放在单一的服务器 上，方便进行搜索和分析。在日志聚合方面，已经有不少成熟的开源软件可以很好的满足需求。本文中要介绍的是 logstash，一个流行的事件和日志管理开源软件。logstash 采用了一种简单的处理模式：输入 -> 过滤器 -> 输出。logstash 可以作为代理程序安装到每台需要收集日志的机器上。logstash 提供了非常多的插件来处理不同类型的数据输入。典型的包括控制台、文件和 syslog 等；对于输入的数据，可以使用过滤器来进行处理。典型的处理方式是把日志消息转换成结构化的字段；过滤之后的结果可以被输出到不同的目的地，比如 ElasticSearch、文件、电子邮件和数据库等。

Logstash 在使用起来很简单。从官方网站下载 jar 包并运行即可。在运行时需要指定一个配置文件。配置文件中定义了输入、过滤器和输出的相关配置。清单 9 给出了一个简单的 logstash 配置文件的示例。

清单 9. logstash 配置文件示例
1
2
3
4
5
6
7
8
9
10
11
12
13
input {
 file {
   path => [ "/var/log/*.log", "/var/log/messages", "/var/log/syslog" ]
   type => 'syslog'
 }
}
 
output {
 stdout {
debug => true
debug_format => "json"
 }
}

清单 9 中定义了 logstash 收集日志时的输入（input）和输出（output）的相关配置。输入类型是文件（file）。每种类型输入都有相应的配置。对于文件来说，需要配置的 是文件的路径。对每种类型的输入，都需要指定一个类型（type）。该类型用来区分来自不同输入的记录。代码中使用的输出是控制台。配置文件完成之后，通 过“java -jar logstash-1.1.13-flatjar.jar agent -f logstash-simple.conf”就可以启动 logstash。

在日志分析中，比较重要的是结构化的信息。而日志信息通常只是 一段文本，其中的不同字段表示不同的含义。不同的应用程序产生的日志的格式并不相同。在分析时需要关注的是其中包含的不同字段。比如 Apache 服务器会产生与用户访问请求相关的日志。在日志中包含了访问者的各种信息，包括 IP 地址、时间、HTTP 状态码、响应内容的长度和 User Agent 字符串等信息。在 logstash 收集到日志信息之后，可以根据一定的规则把日志信息中包含的数据提取出来并命名。logstash 提供了 grok 插件可以完成这样的功能。grok 基于正则表达式来工作，同时提供了非常多的常用类型数据的提取模式，如清单 10 所示。

清单 10. 使用 grok 提取日志记录中的内容
1
2
3
4
5
//Apache 访问日志
49.50.214.136 GET /index.html 200 1150 "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.17 (KHTML, like Gecko) Chrome/24.0.1312.57 Safari/537.17"
 
//grok 提取模式
%{IP:client} %{WORD:method} %{URIPATHPARAM:request} %{NUMBER:status} %{NUMBER:bytes} %{QS:useragent}

在经过上面 grok 插件的提取之后，Apache 访问日志被转换成包含字段 client、method、request、status、bytes 和 useragent 的格式化数据。可以根据这些字段来进行搜索。这对于分析问题和进行统计都是很有帮助的。

当 日志记录通过 logstash 进行收集和处理之后，通常会把这些日志记录保存到数据库中进行分析和处理。目前比较流行的方式是保存到 ElasticSearch 中，从而可以利用 ElasticSearch 提供的索引和搜索能力来分析日志。已经有不少的开源软件在 ElasticSearch 基础之上开发出相应的日志管理功能，可以很方便的进行搜索和分析。本文中介绍的是 Graylog2。

Graylog2 由服务器和 Web 界面两部分组成。服务器负责接收日志记录并保存到 ElasticSearch 之中。Web 界面则可以查看和搜索日志，并提供其他的辅助功能。logstash 提供了插件 gelf，可以把 logstash 收集和处理过的日志记录发送到 Graylog2 的服务器。这样就可以利用 Graylog2 的 Web 界面来进行查询和分析。只需要把清单 9 中的 logstash 的配置文件中的 output 部分改成清单 11 中所示即可。

清单 11. 配置 logstash 输出到 Graylog2
1
2
3
4
5
output {
 gelf {
   host => '127.0.0.1'
 }
}

在安装 Graylog2 时需要注意，一定要安装与 Graylog2 的版本相对应的版本的 ElasticSearch，否则会出现日志记录无法保存到 ElasticSearch 的问题。本文中使用的是 Graylog2 服务器 0.11.0 版本和 ElasticSearch 0.20.4 版本。

除了 Graylog2 之外，另外一个开源软件 Kibana 也比较流行。Kibana 可以看成是 logstash 和 ElasticSearch 的 Web 界面。Kibana 提供了更加丰富的功能来显示和分析日志记录。与代码清单中的 logstash 的配置相似，只需要把输出改为 elasticsearch 就可以了。Kibana 可以自动读取 ElasticSearch 中包含的日志记录并显示。

了解你的 logger

我们使用 logger 方法的方式可能会带来巨大的开销：

1、创建消息字符串

2、组织包含在消息字符串中的数据

我们应该查阅所选择的日志管理工具、引擎的 javadoc 文档，了解使用它们 logger 的最有效的方法。例如，我们可以创建一条这样的消息：

LOGGER.info(“Person name is “ + person.getName());

这就创建了不必要的字符串实例。使用SLF4J，正确的用法应该是：

LOGGER.info(“Person name is {}“, person.getName());

这里的格式化字符串是常量，不可变消息只有在允许 logging 的情况下才会被创建。

小结

日 志记录是应用程序开发中的重要一环。不过这一环比较容易被开发人员忽视，因为它所产生的影响在程序运行和维护时。对于一个生产系统来说，日志记录的重要性 是不言而喻的。本文首先以 java.util.logging 包和 log4j 为例介绍了 Java 日志 API 的主要组成部分和使用方式，同时也介绍了 Apache Commons Logging 和 SLF4J 两种日志封装 API。本文也给出了一些记录日志时应该采用的最佳实践。最后介绍了如何使用开源工具对日志进行聚合和分析。通过本文，开发人员可以了解如何在开发中有效 的使用日志。