日志规范

dong4j 10/21/2018 Spring

开发中日志这个问题，每个公司都强调，也制定了一大堆规范，但根据实际情况看，效果不是很明显，主要是这个东西不好测试和考核，没有日志功能一样跑啊。

但是没有日志, 一旦系统出现问题, 将导致排查问题时困难重重. 因此好的日志输出有利于快速定位问题

但是我们在什么时候打印日志? 需要打印什么信息? 用什么日志级别? 这些问题都将应用我们排查问题时的速度

因此这里制定一个日志规范, 将日志相关的常识性问题做一个总结.

日志等级说明

trace, debug: 理论上 "不属于错误", 只是打印一些状态, 提示信息, 以便开发过程中观察.
info: 理论上 "不属于错误", 只是一些提示性的信息, 但是即使在开发完成, 正式上线的系统中, 也有保留的价值.
warn: 属于轻微的 "警告", 程序中出现了一些异常情况, 但是影响不大, 还可以正常使用.
error: 属于 "普通的错误", 在程序可以控制的范围内, 不会造成连锁影响或巨大影响.
fatal: 属于 "致命错误", 可导致整个系统或者一系列功能无法使用, 甚至导致系统瘫痪, 关闭.

规范

日志必须显示 日志等级, 时间精确到毫秒

以前也说过, 显示日志等级,可以配合插件来高亮不同日志等级, 还可以设置声音提示. 显示日志等级也有利于在现网搜索特定级别的日志.

以下是利用 Grep Console 插件显示的效果, 能区分不同的日志等级

用以下命令获取某段时间特定等级或关键字的日志

# sed -n '/开始时间/,/结束时间/p' all.log | grep '关键字' | > snippet.log
sed -n '/2018-08-21 16:27:57.569/,/2018-08-21 16:36:14.604/p' all.log | grep 'INFO' | > snippet.log

1
2

修改（包括新增）操作必须打印日志

大部分问题都是修改导致的。数据修改必须有据可查

条件分支必须打印条件值，重要参数必须打印

尤其是分支条件的参数，打印后就不用分析和猜测走那个分支了，很重要！如下面代码里面的 messageType，一定要打印值，因为他决定了代码走那个分支

/**
 * Instance rocket mq handler.
 * 根据消息类型选择处理器处理消息
 *
 * @param messageType the message type
 * @return the rocket mq handler
 */
@Override
public MessageHandler instance(String messageType) {
    Class<? extends MessageHandler> cls = null;
    log.info("message type = {}", messageType);
    switch (MessageType.valueOf(messageType)) {
        case BUSINESS_LOG:
            cls = BusinessLogHandler.class;
            break;
        case WORD_ANALYSIS:
            cls = WordAnalysisHandler.class;
            break;
        default:
            log.error("Unknown MessageType, messageType = {} ", messageType);
            break;
    }
    return SpringContext.getInstance(cls);
}

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24

数据量大的时候需要打印数据量

前后打印日志和最后的数据量，主要用于分析性能，能从日志中知道查询了多少数据用了多久. 自己视情况而决定是否打印，我一般建议打印.

不要使用 System.out.println() 来记录日志

使用 System.out.println() 不会输出到日志文件.

本地开发时, 觉得方便就直接使用 System.out.println() 输出, 本地是看得到信息, 但是一到线上环境, 日志全部输出到文件中, 使用 System.out.println() 输出的信息就全部没有了.

System.out.println() 一般是开发时输出不重要的信息, 建议使用 log.debug 代替.

使用 lombok, 应该比 System.out.println() 更方便吧!

建议

日志这个东西，更多是靠自觉，项目组这么多人，不可能一个一个看代码，然后加日志. 打印日志更多的是一种习惯, 需要有意识的去培养这种习惯.

1.不要依赖debug，多依赖日志。

别人面对对象编程，你面对debug编程. 有些人无论什么语言，最后都变成了面对debug编程.... 这个习惯非常非常不好！debug会让你写代码的时候偷懒不打日志，而且很浪费时间. 改掉这个恶习.

只有在必要的情况下才会 debug, 更多的是通过日志来分析流程, 因为在生产环境, 尤其是现公司的生产环境, 远程 debug 是不可能的, 只能依赖日志.

代码开发测试完成之后不要急着提交，先跑一遍看看日志是否看得懂. 日志是给人看的，只要热爱编程的人才能成为合格程序员, 不要匆匆忙忙写完功能测试ok就提交代码，日志也是功能的一部分. 要有精益求精的工匠精神！

日志最佳实践

现有代码存在的最大问题就是排查问题时, 没有日志可看, 不得不加入日志后再部署再看问题, 这样就很尴尬

合理的日志等级以及日志埋点能够快速定位问题

针对现在代码中存在的问题和以后的迁移工作, 在做需求开发时, 尽量按照以下方式修改日志相关的代码.

删除 printStackTrace()

删除所有的 printStackTrace() 方法 , 改用日志输出

e.printStackTrace 会直接输出到 System.err (如果是 tomcat部署, 就会输出到 catalina.out)

我们的所有日志配置全部通过 log4j.xml 或者 log4j2.xml 控制,

try {
	// do something
} catch (Exception e) {
   // todo 删除 printStackTrace(), 改用 log.error 输出
	e.printStackTrace();
}

1
2
3
4
5
6

使用slf4j api

正确使用 error 日志级别

public void error(String msg, Throwable t);

错误的做法:

# 框架会发现最后一个参数是多余的，并查看其是否是一个异常对象，如果是则输出堆栈，否则忽略
log.error("Failed to format {}", s, e);

1
2

使用占位符代替连接符, 提高效率

log.info("解析错误,错误码:" + status);

替换为

log.info("解析错误,错误码: {}", status);

基本的日志编码规范

以下是规范的日志写法, 希望以后开发时, 注意以下几点

获取 log, 日志对象名统一使用 log 如果有父类, 统一在父类中获取 log
```
protected log log = logFactory.getlog(getClass());
```
1
如果没有父类, 在当前类中获取 log
```
private static final log log = logFactory.getlog(类名.class);
```
1
可以使用 live templates 快速输入, 需要自己设置

以上方式是没有使用 lombok 插件的情况, 如果使用, 直接在类上加 @Slf4j 即可, 然后使用 log 对象打印日志

如果使用新框架, 可以使用 Logs 工具类打印日志

输出 Exceptions 的全部 Throwable 信息，因为 log.error(msg) 和 log.error(msg,e.getMessage()) 这样的日志输出方法会丢失掉最重要的 StackTrace 信息。

void foo(){
    try{
        // do something
    } catch (Exception e) {
        log.error(e.getMessage()); // 错误
        log.error("Bad things", e.getMessage()); // 错误
        log.error("Bad things", e); // 正确
        // error 允许拼接字符串, 因为 error 毕竟没有 info 和 debug 多, 而且需要输出参数信息时, 也只有这种方式
        log.error("Bad things " + user, e);
    }
}

1
2
3
4
5
6
7
8
9
10
11

不允许记录日志后又抛出异常，因为这样会多次记录日志，只允许记录一次日志.

void foo() throw LogException {
    try{
        // do something
    } catch (NoUserException e) {
         log.error("No user available", e);
         // 这里抛出异常后, 上级又会处理一次异常
         throw new UserServiceException("Nouseravailable", e);
    }
}

1
2
3
4
5
6
7
8
9

不允许出现 System print(包括 System.out.println 和 System.error.println) 语句

不允许出现 printStackTrace

void foo() throw LogException {
    try{
        // do something
    } catch (NoUserException e) {
        e.printStackTrace(); // 错误
        log.error("No user available", e);
    }
}

1
2
3
4
5
6
7
8

使用 slf4j 代替 log4j

slf4j 中的占位符—不再需要冗长的级别判断

在 log4j 中，为了提高运行效率，往往在输出信息之前，还要进行级别判断，以避免无效的字符串连接操作。如下：
```
if (log.isDebugEnabled()){
    log.debug("debug：" + name);
}
```
1
2
3
slf4j 巧妙的解决了这个问题：先传入带有占位符的字符串，同时把其他参数传入，在 slf4j 的内容部实现中，如果级别合适再去用传入的参数去替换字符串中的占位符，否则不用执行。
```
log.info("{} is {}", new String[]{“x",“y"});
```
1

不在循环中打印日志

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

1
2
3
4
5
6
7
8
9
10

如果 readData() 抛出异常并且 hasNext() 返回 true，这段代码就会不停在打印日志

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

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15

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

日志追踪系统

仅仅依赖以上日志规范只能做到单个应用的日志规范记录, 但是这些分散的数据对于问题排查，或是流程优化都帮助有限.

对于一个跨进程/跨线程的场景, 汇总收集并分析海量日志就显得尤为重要. 要能做到追踪每个请求的完整调用链路, 收集调用链路上每个服务的性能数据, 计算性能数据和比对性能指标等能有效排查问题, 分析系统瓶颈. 最后还能对日志进行大数据分析, 带来更高的利润.

因此以后会考虑做日志追溯系统

这里有一篇以前写的日志追踪系统设计和日志追踪系统实现

日志规范

# 日志等级说明

# 规范

# 建议

# 日志最佳实践

# 删除 printStackTrace()

# 使用slf4j api

# 正确使用 error 日志级别

# 使用 占位符 代替 连接符, 提高效率

# 基本的日志编码规范

# 日志追踪系统