日志打印的5点建议

Published: 03 May 2014 Category: Java

最近我们介绍了几款日志分析的工具，比如Scribe和LogStash这类的开源项目，以及Splunk这样的企业级工具，还有像SumoLogic和PaperTrail这样的托管服务。你可以使用这些工具从海量的日志数据提取到一些有价值的信息。

不过还有一件事它们是帮不了你的。它们都依赖于你实际输出到日志文件里面的数据。日志数据保质保量的重任就落到你肩上了。因此万一情况不妙，你又得在日志文件不全的情况下自己去调试代码，那估计你只好赶紧把原先订好的晚餐取消掉了。

为了减少出现类似的情况，我这里想分享5点日志打印的心得，希望能对你有所帮助：

线程名

就像Ringo一样，线程名应该是Java里最被低估的功能之一了。因为其实它的表述性很强。那又怎样？就像我们的名字一样，我们会给它赋予一个含义。

线程名最有用的时候应该就是多线程的情况下了。许多日志框架都会记录当前方法调用所在线程的名字。不幸的是，一般看起来都是这样的：“http-nio-8080-exec-3″，这是线程池或者容器自动分配的线程名。

我经常听到有谣传称线程名是不可变的。当然不是。线程名就是你日志中最优质的不动产，你得确保自己能正确的使用它们。通常给它赋值会带上上下文的详细信息，比如说Servlet或者任务的名字之类的，以及一些动态的上下文信息比如用户ID。

这么做的话，你的代码看起来应该是这样的：

Thread.currentThread().setName(ProcessTask.class.getName() + “: “+ message.getID);

更高级的做法是引入一个ThreadLocal的变量，然后配置一个appender，自动把里面的信息输出到日志中。

当多个线程同时在往文件中写入日志而你需要关注其中某个线程的时候，这个功能尤其有用。如果你在一个分布式或者SOA环境中运行的话，这么做还会有一个额外的好处，下面我们很快就会看到。

分布式标识符

在SOA或者消息驱动的架构中，某个任务的执行可能会涉及到多台机器。这种架构下如果出了错要进行处理的话，要想知道到底发生了什么，这里所牵涉到的相关机器以及它们的状态就显得至关重要。很多日志分析器只是帮你把这些日志收集起来，它们假设你已经有一个唯一的标志符，可以用它来进行过滤。

从设计的角度来看，这意味着系统中每一个入站操作都需要有一个唯一的ID，处理过程中会一直携带着这个ID直到处理结束。这里如果使用持久性标识比如说用户ID之类的可能并不适合，因为在一个日志文件中一个用户可能会有多个请求在同时进行处理，这就很难提取出具体的某个处理流。UUID是个不错的选择，你可以把它存储到线程名或者TLS——ThreadLocal Storage里面。

不要使用循环

你经常会看到有在循环体中进行日志打印，这么做的前提是循环的次数是有限的。

如果不出什么问题的话当然还好。不过如果代码碰到一些异常的输入导致循环无法退出的话，这就不妙了。这可不止是循环无法结束的问题了，你的程序还一直在往磁盘或者网络中写入数据。

如果只是写到自己的设备中，结果可能就只是挂了一台服务器，但如果是一个分布式的环境，就可能就是一整个集群都瘫了。所以最好还是不要在循环里面打印日志，尤其是当涉及到异常处理的时候。

我们来看一个例子，这里是在循环中来打印异常的信息：

void read() {
    while (hasNext()) {
        try {
            readData();
        } catch {Exception e) {
            // this isn’t recommend
            logger.error(“error reading data“, e);
        }
    }
}

如果readData()抛出异常并且hasNext()返回true，这段代码就会不停在打印日志。一个解决方法就是不要每次都打印出来：

void read() {
    int exceptionsThrown = 0;
    while (hasNext()) {
        try {
            readData();
        } catch {Exception e) {
            if (exceptionsThrown < THRESHOLD) {
                logger.error(“error reading data", e);
                exceptionsThrown++;
            } else {
                // Now the error won’t choke the system.
            }
        }
    }
}

还有一个方法就是把日志操作从循环中去掉，在另外的地方进行打印，只记录第一个或者最后一个异常就好了。

未捕获的异常

维斯特洛有一道最后的防御墙，而你有Thread.uncaughtExceptionHandler。请确认你已经用上它们了。如果没有的话，你的异常可能这么没了，而你只能拿到很少的一些上下文信息，同时这些异常在哪打印，是否打印，你也不好控制。

如果你的代码出现异常却没有记录下来，或者记录下来了却没有相关的状态信息，那真是非常失败。

尽管在uncaughtExceptionHandler里面看似已经访问不了线程里面的任何变量了（它已经挂了），但你至少还有一个当前线程的引用。如果结合刚才提到的第一条建议的话，至少日志中还能打印出一个有意义的thread.getName()的值。

捕获外部调用的异常

只要你调用到了JVM以外的接口，那么发生异常的概率就大大提升了。这包括WEB服务，HTTP,数据库，文件系统，操作系统或者其它的一些JNI调用。你得把每一个调用都当成一个定时炸弹来处理。

大多数情况下，外部调用之所以会失败是因为传入了错误的参数。为了修复这些问题，把这些请求参数记录到日志中是非常有必要的。

你可能不想记录错误信息，而是直接去抛出异常，这样做也没有问题。不过这么做的话，你要尽可能把相关的参数都收集起来，放到异常信息里面去。

你得确保在上一层调用中捕获了异常并且记录到了日志里。

try {
    return s3client.generatePresignedUrl(request);
} catch (Exception e) {
    String err = String.format(“Error generating request: %s bucket: %s key: %s. method: %s", request, bucket, path, method);
    log.error(err, e); //这里你也可以抛出一个异常，记得把ERR信息带上。
}

原创文章转载请注明出处：日志打印的5点建议

英文原文链接