日志还是调试?

  在这段时间的面试过程中,印象比较深的是一个面试官问到了关于 java 日志的问题,我当时只想了SLF4J 和 log4j,就简单说了一些日志在工作环境中的一些作用和日志的级别设置。面试官也主要提到了一些打日志的规范。这儿我想说一下日志打印的一些看法。

  
线程名
  就像Ringo一样,线程名应该是Java里最被低估的功能之一了。因为其实它的表述性很强。那又怎样?就像我们的名字一样,我们会给它赋予一个含义。
  线程名最有用的时候应该就是多线程的情况下了。许多日志框架都会记录当前方法调用所在线程的名字。不幸的是,一般看起来都是这样的:“http-nio-8080-exec-3″,这是线程池或者容器自动分配的线程名。
  我经常听到有谣传称线程名是不可变的。当然不是。线程名就是你日志中最优质的不动产,你得确保自己能正确的使用它们。通常给它赋值会带上上下文的详细信息,比如说Servlet或者任务的名字之类的,以及一些动态的上下文信息比如用户ID。
  这么做的话,你的代码看起来应该是这样的:

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

更高级的做法是引入一个ThreadLocal的变量,然后配置一个appender,自动把里面的信息输出到日志中。
  当多个线程同时在往文件中写入日志而你需要关注其中某个线程的时候,这个功能尤其有用。如果你在一个分布式或者SOA环境中运行的话,这么做还会有一个额外的好处,下面我们很快就会看到。
  
分布式标识符
  在SOA或者消息驱动的架构中,某个任务的执行可能会涉及到多台机器。这种架构下如果出了错要进行处理的话,要想知道到底发生了什么,这里所牵涉到的相关机器以及它们的状态就显得至关重要。很多日志分析器只是帮你把这些日志收集起来,它们假设你已经有一个唯一的标志符,可以用它来进行过滤。
  从设计的角度来看,这意味着系统中每一个入站操作都需要有一个唯一的ID,处理过程中会一直携带着这个ID直到处理结束。这里如果使用持久性标识比如说用户ID之类的可能并不适合,因为在一个日志文件中一个用户可能会有多个请求在同时进行处理,这就很难提取出具体的某个处理流。UUID是个不错的选择,你可以把它存储到线程名或者TLS——ThreadLocal Storage里面。
  
不要使用循环
  你经常会看到有在循环体中进行日志打印,这么做的前提是循环的次数是有限的。
  如果不出什么问题的话当然还好。不过如果代码碰到一些异常的输入导致循环无法退出的话,这就不妙了。这可不止是循环无法结束的问题了,你的程序还一直在往磁盘或者网络中写入数据。
  如果只是写到自己的设备中,结果可能就只是挂了一台服务器,但如果是一个分布式的环境,就可能就是一整个集群都瘫了。所以最好还是不要在循环里面打印日志,尤其是当涉及到异常处理的时候。
  我们来看一个例子,这里是在循环中来打印异常的信息:

1
2
3
4
5
6
7
8
9
10
void read() {
while (hasNext()) {
try {
readData();
} catch {Exception e) {
// this isn’t recommend
logger.error(“error reading data“, e);
}
}
}

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

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
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调用。你得把每一个调用都当成一个定时炸弹来处理。
  大多数情况下,外部调用之所以会失败是因为传入了错误的参数。为了修复这些问题,把这些请求参数记录到日志中是非常有必要的。
  你可能不想记录错误信息,而是直接去抛出异常,这样做也没有问题。不过这么做的话,你要尽可能把相关的参数都收集起来,放到异常信息里面去。
  你得确保在上一层调用中捕获了异常并且记录到了日志里。

1
2
3
4
5
6
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信息带上。
}

日志还是调试?

  在合适的时候你可以使用调试。如果你一直都是用调试的话,那就继续吧。我个人倾向于使用日志,尽管有的时候环境允许我进行实时的调试。当我找到我在苦苦追寻的问题的原因后,我会检查一遍记录日志的语句,然后删掉它们。它们已经完成了自己调试的使命,现在已经不再需要它们了。不过后来我发现,我自己在写一些以前删掉过的日志记录的语句,至少我自己是有这样的经历。为什么呢?这是因为修复一个BUG并不意味着所有的BUG都修复了。BUG是永远也改不完的。但是散落在文件各处的日志记录给查找下一个BUG的相关信息增加了难度。换句话说,日志文件中的干扰信息太多了,这就是为什么我删掉它们的原因。那同样的,我们是不是可以把已经通过的单元测试也给删掉呢?这会节省掉很多编译的时间,不是吗?当然,我们不会这么做。
  用一句话来总结下?选择日志还是调试,随你个人的喜好吧,也得看你在查找什么类型的问题。

Reference:

-------------本文结束感谢您的阅读-------------
Thank you for your encouragement