有效地记录日志可以简化企业的开发过程

如果您是一名开发人员，那您很可能就已经具有这种经验：您已经开发了一些代码以及一些测试用例。应用程序经过了严格的 QA 测试，您确信代码可以完全适合业务的需求。然而，在将应用程序最终交付终端用户的手里时，却会出现一些预想不到的问题。如果没有适当的日志消息，可能需要花费几天的时间来诊断这些问题。不幸的是，大部分项目对于日志都没有一个清晰的策略。如果没有这种策略，系统产生的日志消息就有可能无益于问题的分析和解决。在本文中，我们将讨论企业应用程序日志的各个方面的问题。您将看到一个 Java™ 平台上日志 API 的概述，学习一些最好的编写日志代码的实践，并了解如果需要在产品环境中对详细日志重新进行排序，应该如何处理。

选择日志 API

在使用 Java 平台进行开发时，可以使用两个主要的日志 API：Apache Log4J 和 Java Logging API，在 1.4 及更高版本的 Java 平台中都提供了这两个 API。与 Java Logging API 相比，Log4J 更加成熟，特性也更加丰富。这两个日志的实现都采用了一个类似的设计模式（如图 1 所示）。除非您的公司限制要使用第三方的库，否则我强烈建议使用 Log4J。如果您不能决定使用哪个 API，就可以使用 Apache Commons Logging API，它对底层的日志实现进行了封装。从理论上来说，这样不用修改代码就可以进行日志实现的切换。然而，实际上您很少会切换日志的实现；因此，我不建议使用 Apache Commons Logging API，因为它的复杂性并不没有给您带来其他特性。

日志概述

Log4J 和 Java Logging API 都采用了类似的设计和使用模式（如图 1 和清单 1 所示）。消息首先被创建，然后传递给一个具有特定优先权的日志对象。这些消息的目的和格式是由输出处理程序及其布局所决定。

            import org.apache.log4j.Logger;
            public class MyClass {
            /*
            * Obtain a logger for a message category. In this case, the message category is
            * the fully qualified class name of MyClass.
            */
            private static final Logger logger = Logger.getLogger(MyClass.class.getName());
            ...
            public void myMethod() {
            ...
            if (logger.isDebugEnabled()) {
            logger.debug("Executing with parameters: " + param1 + ":" + param2);
            }
            }
            }

一个好的日志实现中提供了很多不同的输出处理程序，最常见的文件输出处理程序和终端输出处理程序。Log4J 还提供了一些处理程序将消息发布到一个 JMS 主题中，或者将消息插入一个数据库表中。尽管这编写一个定制的附加器并不困难，但是编写和维护这种代码的总体成本不应低估。消息的格式可以通过 Layout 对象进行配置。最常见的 layout 对象是 PatternLayout，它根据所提供的模式对消息进行格式化。

清单 2 给出了一个 Log4J 的样例配置文件，它负责配置 FileAppender。在这种配置中，com.ambrosesoft.log.MyClass 类中的错误消息被发送给 FileAppender，后者将其写入一个名为 log.txt 的文件中。这些消息是根据与这个添加器相关的 layout（在这种情况中是 PatternLayout）进行格式化的。

<?xml version="1.0" encoding="UTF-8" ?>
            <!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">
            <log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/">
            <appender name="fileAppender" class="org.apache.log4j.FileAppender">
            <param name="File" value="log.txt"/>
            <param name="Append" value="true"/>
            <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="%d [%t] %p - %m%n"/>
            </layout>
            </appender>
            <category name="com.ambrosesoft.log.MyClass">
            <priority value="error"/>
            <appender-ref ref="fileAppender"/>
            </category>
            <root>
            <priority value="debug"/>
            <appender-ref ref="fileAppender"/>
            </root>
            </log4j:configuration>
            

日志最佳实践

关于日志，您要做的一个最重要的选择可能是确定一种模式，将每个日志消息分配给一个特定的 类别。常见的一种实践是使用每个类的全名，这些类的操作会被作为一个消息类别在日志中记录（正如我们在清单 1 中看到的一样），这是因为这可以让开发人员更细粒度地记录每个类的设置。然而，这只有在使用日志消息来跟踪执行过程时才能良好地工作。在企业级的应用程序中，有很多其他类型的日志消息。举例来说，一条日志消息可能是为安全顾问产生的，而另外一条日志消息则可能是会为了帮助进行性能调优而产生的。如果这两条消息所关注的是同一个类，这样就会被分配给相同的类别，这将很难在日志输出结果中对其进行区分。

为了避免这个问题，应用程序应该具有一组专用的日志记录程序，它们都进行了独特的分类，如清单 3 所示。每个日志记录程序都可以配置自己的优先级和输出处理程序。例如，安全性日志记录程序可以在将日志写入目的地之前对消息进行加密。有时应用程序的设计者应该与使用日志的用户（例如安全顾问）一起来商讨日志的输出格式，从而对这些消息进行更好的控制。

            import org.apache.log4j.Logger;
            public interface Loggers {
            Logger performance = Logger.getLogger("performance");
            Logger security = Logger.getLogger("security");
            Logger business = Logger.getLogger("business");
            }
            ...
            public class MyClass {
            ....
            if (Loggers.security.isWarnEnabled()) {
            Loggers.security.warn("Aclearcase/" target="_blank" >ccess denied: Username [" + userName + "] ...");
            }
            ...
            }
            

选择日志的级别

一个 类别 （例如 security）中的消息可以具有不同的 优先级。有些消息是为了调试而产生的，有些是为了警告而产生的，有些则是出现错误而产生的。消息的不同优先级可以通过记录 级别 来产生。最常用的日志级别有：

• Debug: 这个级别的消息中包含了非常广泛的上下文信息。通常用于问题诊断。
  
  
• Info: 这些消息包含了一些有助于在产品环境中（粒度较粗）帮助跟踪执行过程的上下文消息。
  
  
• Warning: 警告消息，说明系统中可能存在问题。例如，如果这个消息类别是有关安全性方面的，那么如果检测到字典攻击，就应该产生一条警告消息。
  
  
• Error: 错误消息说明系统中出现了严重的问题。这种问题通常都是不可恢复的，需要人工进行干预。

标准的 Java Logging API 和 Apache Log4J 在此之外又提供了一些日志级别。日志级别的主要目标是帮助您过滤有用信息中的噪声。为了防止出现使用错误的级别以及降低日志消息的效用的情况，在开始编码之前，必须为开发人员提供一个清晰的指导方针。

日志消息的格式

一旦选定日志记录程序并建立起日志级别之后，就可以开始构建日志消息了。在这样做时，重要的是要包含尽可能多的上下文信息，例如用户提供的参数，其他应用程序的状态信息。记录日志对象的一种方法是将它们转换成 XML。第三方库，例如 XStream（请参阅 参考资料）可以自动将 Java 对象转换成 XML 。尽管这是一种非常强大的机制，但是我们必须要考虑在速度与详细程度之间达到一种平衡。除了典型的应用程序状态信息之外，还应该记录以下信息：

• 线程 ID: 企业级的应用程序通常都是在多线程的环境中运行的。使用线程 ID 信息，您就可以将多个请求区分开来。
  
  
• 调用程序的标识: 调用程序的标识也是非常重要的信息。由于不同的用户具有不同的特权，它们的执行路径也可能会有很大的不同。将用户的标识放到日志消息中，这对于对安全性敏感的应用程序是非常大的一个帮助。
  
  
• 时间戳: 通常来说，用户只能近似地知道问题发生的时间。如果没有时间戳，就很难让别人来判断问题的原因所在。
  
  
• 源代码信息: 这包括类名、方法名和行号。除非您非常关注安全性，否则我建议您保留调试标记（-g），即使在编译产品时也是如此。如果没有调试标记，Java 编译器就会删除所有的行号信息，从而极大地减少日志消息的可用性。

上面这些信息（除了调用程序标识）都是由日志实现自动获取的。为了将这些信息包含到消息中，您只需要为输出处理程序配置一个适当的 layout 模式即可。要捕获调用者的标识，您可以利用 Log4J 中的诊断上下文特性（更多信息请参阅 参考资料）。诊断上下文让您可以将上下文信息与当前正在运行的线程关联在一起。这些信息可以在为输出进行格式化的同时而包含到每条消息中。

在 J2EE Web 应用程序中，应用逻辑将用户标识保存到诊断上下文中最好的地方是在一个 servlet 过滤器中。清单 4 中显示了要实现这种功能的必要代码。它使用了 Log4J 1.3 alpha 中提供的映射诊断上下文类（MDC）。您可以使用 Log4J 1.2 中提供的嵌套诊断上下文（NDC）实现相同的功能。有关 servlet 过滤器的更多通用信息，请参阅 参考资料 中的信息。

            import javax.servlet.Filter;
            ...
            import javax.servlet.http.HttpServletRequest;
            import javax.servlet.http.HttpSession;
            import org.apache.log4j.MDC;
            public class LoggerFilter implements Filter {
            public void doFilter(ServletRequest request, ServletResponse response,
            FilterChain chain) throws IOException, ServletException {
            // Retrieves the session object from the current request.
            HttpSession session = ((HttpServletRequest)request).getSession();
            // Put the username into the diagnostic context.
            // Use %X{username} in the layout pattern to include this information.
            MDC.put("username", session.getAttribute("username"));
            // Continue processing the rest of the filter chain.
            chain.doFilter(request, response);
            // Remove the username from the diagnostic context.
            MDC.remove("username");
            }
            ...
            }

使用 AspectJ 跟踪执行情况

在对问题进行诊断时，通常跟踪程序的执行情况会很有帮助。您可以在程序执行的不同地方持续发送日志消息吗？例如方法的入口函数和出口函数。这是一个老问题，在出现 AspectJ 之前一直都没有什么好的解决方案。使用 AspectJ，可以在应用程序的不同地方执行代码段。在 AspectJ 中，这些地方都称为 point cut，在 point cut 处所执行的代码称为 advice。point cut 和advice 合称 aspect。

关于 AspectJ，有一件事情非常神奇，aspect 不用很多努力就可以应用到整个应用程序中。有关 AspectJ 的更多信息，请参阅 参考资料。清单 5 给出了一个 AspectJ 源文件的例子，它用来对方法的入口和出口函数记录日志。在这个例子中，跟踪日志程序将在每次进入或退出 com.ambrosesoft 包的一个共有方法时都会记录一条日志。

            import org.apache.log4j.Logger;
            import java.lang.reflect.Field;
            public aspect AutoTrace {
            private static final Logger logger = Logger.getLogger(AutoTrace.class);
            pointcut publicMethods() : execution(public * com.ambrosesoft..*(..));
            pointcut loggableCalls() : publicMethods();
            /**
            * Inspect the class and find its logger object. If none is found, use
            * the one defined here.
            */
            private Logger getLogger(org.aspectj.lang.JoinPoint joinPoint) {
            try {
            /*
            * Try to discover the logger object.
            * The logger object must be a static field called logger.
            */
            Class declaringType = joinPoint.getSignature().getDeclaringType();
            Field loggerField = declaringType.getField("logger");
            loggerField.setAccessible(true);
            return (Logger)loggerField.get(null);
            } catch(NoSuchFieldException e) {
            /*
            * Cannot find a logger object, use the internal one.
            */
            return logger;
            } catch(Exception e) {
            throw new RuntimeException(e);
            }
            }
            /**
            * An aspect to log method entry.
            */
            before() : loggableCalls(){
            getLogger(thisJoinPoint).debug("Entering.." + thisJoinPoint.getSignature().toString());
            }
            /**
            * An aspect to log method exit.
            */
            after() : loggableCalls(){
            getLogger(thisJoinPoint).debug("Exiting.." + thisJoinPoint.getSignature().toString());
            }
            }

产品环境中的日志

一旦应用程序处于产品环境中之后，您通常都需要关闭调试或信息日志消息，从而对运行时的性能进行优化。然而，当有些不好的事情发生时，您又不能在开发环境中重现这个问题，那就可能需要在产品环境中激活调试消息了。重要的是能够修改日志的设置，而不用关闭服务器。诊断产品的问题即使不用花费数天来进行详细的调研，通常也需要几个小时的时间。在这段时间之内，开发人员需要激活或关闭应用程序不同范围的日志。如果每次修改日志的设置之后都需要重新启动产品应用程序，那么情况就会变得非常不可靠了。

幸运的是，Log4J 提供了一种简单的机制来解决这个问题。在 Log4J 1.2 中，DOMConfigurator 中的 configureAndWatch() 方法会对 Log4J 进行配置，并自动监视日志配置文件中的变化。这在清单 6 中进行了阐述。（注意，在 Log4J 1.3（目前仍是 alpha 版本） 中并不推荐使用 DOMConfigurator，它使用了一个更加灵活的实现 JoranConfigurator。）

为了确保 configureAndWatch() 是在 Log4J 初始化之前调用的，您应该在启动类中调用它。不同的应用程序服务器采用了不同的机制来执行启动代码（更多信息请参阅 参考资料）。详细信息请查看应用服务器的实现。有些应用服务器可能需要您将 Log4J 的库放到服务器的 classpath 中。日志配置文件应该保存到一个需要日志的人可以访问的位置。

            /*
            * Configure Log4J library and periodically monitor log4j.xml for any update.
            */
            DOMConfigurator.configureAndWatch("/apps/config/log4j.xml");
            

如果您的日志配置文件不能方便地进行访问（例如您的产品环境是由一个不同的组织进行维护的），那么您就必须使用一种不同的策略。标准的方法是使用 JMX，它提供了一个标准的 API 来管理自己的应用程序设置。在现代 JMX 兼容的服务器中，您可以使用管理 bean （或 MBeans ）来扩展应用服务器的管理终端的功能（更多有关使用 JMX 以及在 WebSphere Application Server 6.0 中使用 JMX 的内容，请参阅 参考资料 一节。）由于 JMX 方法非常复杂，如果您的情况需要使用 JMX，那就应该只用作这个用途。

记录敏感的数据

在记录产品环境中的日志时，除了技术方面的挑战之外，还存在一些业务问题需要克服。例如，记录敏感的信息可能会引起安全性的问题。并没有任何限制可以防止您将某个用户的用户名和密码保存到正文文件中。您还必须要保护其他敏感信息，例如 e-mail 地址、电话号码以及帐号信息。安全顾问和设计师有责任要确保这些信息不会未加任何处理就保存到日志中。对敏感信息使用安全性专用的日志程序可以帮助降低风险。您可以给这个日志程序配置一个专用的附加器，从而使用一种加密的格式来保存消息，或者将其保存到一个安全的地方。然而，防止出现安全风险的最佳方法是在项目开始之前就设置适当的编码规范，并在检查代码时强制施行这些规范。

从异常中提取有用信息

当发生一个非预期的异常时 —— 例如，如果数据库连接突然失效了，或者系统资源变得很低了 —— 就必须对其适当地进行处理，否则就会丢失有用的信息，这些信息在诊断问题时是非常有帮助的。首先，必须记录异常及其堆栈跟踪状况。其次，应该使用一种用户界面友好的方式来标识错误页面，这对于终端用户和技术支持小组来说都是非常有帮助的。

技术支持小组在接到一个技术支持电话时所面临的一个挑战是在用户所报告的问题与特定的日志异常之间建立某种关联。非常有用的一种简单技术是为每个异常都记录一个唯一的 ID。这个 ID 可以告诉用户，也可以包含在终端用户所填写的问题报告表单中。这样可以减少技术支持团队成员猜测的时间，让他们可以快速对问题作出响应。考虑到可读性的问题，可以定期对 ID 进行回收。

日志文件的管理

一个非常繁忙的应用程序的日志文件可能会迅速变得非常大。较大的日志文件很难使用，这是因为它们需要过滤大量的噪声才能找到有用的信号。Log 循环 是常见的一个可以帮助解决这个问题的实践。日志循环会周期性地对旧日志进行归档，这样新消息就可以总能写到一个相对较小的文件中。日志消息降低了一些效用来提高速度；您可能很少需要参考一周之前的日志消息。在 Log4J 1.2 中， DailyRollingFileAppender 附加器可以根据所提供的日期模式来循环使用日志文件。（在 Log4J 1.3 中，已经对这个循环日志文件附加器重新进行了设计。现在您可以提供一种策略来控制如何进行循环了。例如， TimeBasedRollingPolicy 定义了一种基于时间和日期的循环模式。）清单 7 显示了让 Log4J 在每天午夜对自己的日志文件进行循环所采用的配置片断。

            <?xml version="1.0" encoding="UTF-8" ?>
            <!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">
            <log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/">
            <appender name="fileAppender" class="org.apache.log4j.DailyRollingFileAppender">
            <param name="File" value="log.txt"/>
            <param name="Append" value="true"/>
            <param name="DatePattern" value="'.'yyyy-MM-dd"/>
            <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="%d [%t] %p - %m%n"/>
            </layout>
            </appender>
            ...
            </log4j:configuration>
            

集群环境中的日志

现在有越来越多的企业级应用程序是在集群环境或分布式环境中进行部署的。然而，集群环境中的日志需要更多规划，因为消息都是从不同的源头生成的（通常是不同的机器）。如果要对不同的机器记录日志，那就必须对这些机器的时间戳进行同步，否则日志消息的次序就混乱了。对机器间时钟进行同步的一种简单方法是使用一个时间服务器。有两种方法可以设置时间服务器。您可以指定一台内部的机器作为时间服务器。然后其他机器就可以使用网络时间协议（NTP）来与时间服务器的时间戳进行同步。另外，您可以使用 Internet 上提供的时间服务器（请参阅 参考资料）。在 AIX 上，xntpd 守护进程用来对不同机器的系统时间进行同步。当机器具有相同的时间之后，就可以对日志一起进行分析了。

在集群环境中搜集日志消息还面临着一些挑战。在这种环境中保存日志消息的一种简单方法是将它们保存到主机特定的日志文件中。当集群是使用 session affinity 配置时，这可以很好地工作 —— 如果对某个特定用户会话的请求都要到同一个服务器上，并且 EJB 也都是部署在本地的。在这种配置中，集群中的机器所产生的日志文件都可以独立进行分析。如果不是这种情况 —— 换而言之，如果任何给定的请求都可以由多台机器进行处理 —— 那么对不同日志文件中的日志消息进行分析就会变得更加困难。在这种情况中，一种好的办法是使用系统管理软件来管理日志消息，例如 IBM Tivoli® 软件（请参阅 参考资料 中的链接）。这种软件对所有的日志消息（在系统管理软件的术语中称之为 事件）提供了一个综合的视图，从而便于管理员使用。系统管理软件也可以根据所接收到的事件的类型触发一些操作（例如发送 e-mail 消息或传呼消息）。

结束语

在本文中，我们介绍了在规划日志策略时需要考虑哪些问题。正如在编程时所碰到的问题一样，从一开始就采用一个经过详细考虑的规划要比在进行的同时规划更能节省工作量。良好的日志策略可以极大地帮助对问题进行诊断。最终，终端用户可以获得更好的应用程序，并能从技术支持团队获得迅速的响应。