论如何打印日志

博客原文

日志满天飞总是不好的，代码是程序员的艺术品，日志也是其中一部分。

写在前面的话

程序员在程序中打印日志的目的一般有两个：定位问题和显示程序运行状态。试想有那么一个夜晚，突然手机响了，美梦中惊醒，报警短信，然后不到两分钟leader电话来了，你用快速又娴熟的动作爬起来，打开电脑当你打开日志文件准备查问题的时候，傻了，这日志谁写的，问题被杂乱的日志埋葬了，一时急火攻心，终于通过对照源代码和日志，在数小时之后解决了问题。可见日志的重要性。

其实好的日志打印方式还有一个作用，能实现一些业务运营方面的统计工作，比如你在每个操作的关键位置都有对当前用户的操作记下一条日志，这样就能统计出，该业务功能走到每一步的用户数，从而能分辨出是在哪一步损失了用户，从而做相应的业务流程的优化。

可能大家认为日志不管咋打印都不会影响功能逻辑，抛开影响系统性能不说，这有点高级了，其实从上面的话中也可以看出，日志其实很重要的，所以下面我将从几个方面讨论一下如何打印日志，以便理清我自己的思路，同时提醒程序员同行们，这样后面维护你的代码的程序员，少一点吃屎，更少一点对你的咒骂，为和谐美好的程序员天堂添砖加瓦（好伟大呀，哈哈）。

目录：

1. 方便定位问题的日志如何打
2. 显示程序运行状态的日志如何打
3. 可以用作运营统计的日志如何打
4. 什么样的日志不应该打

1. 方便定位问题的日志

这是日志的最主要的用途。

• 日志明确标志属于哪次请求
  打印的每一条日志中尽量包含请求流水号，以便区分这条日志是属于哪次请求的日志，日志样例：

log.warn("账户创建和升级功能，无法识别操作类型（0：创建，1：升级），请求流水号：{}，当前值：{}" , flowNo, operType);

如果获取不到流水号，则需要打印明确能缩小日志归属范围的字段信息，如用户号、协议号、手机号等。

• 在对外提供的接口入口处打印一条日志
  打印接口的唯一标识和中文（如果你English enough可以打英文）简短描述，并且要将调用方传入的参数原样打印出来。这样当系统出现问题时，你就能很容易的判断出是否是调用方出现了问题。日志样例：

log.info("addUpAccount&账户创建和升级接口，外部系统入参：{}" , JSONObject.toJSONString(request));

• 在调用其它系统接口的前后各打印一条日志
  打印所调用接口的系统名称/接口名称和传入参数/响应参数，这样能方便做问题定界，通过这两条日志可以清楚地看出是否是所调用的系统出现了问题，传染到我了。日志样例：

log.info("调用cif业务订购，bcc入参：{}"  , JSONObject.toJSONString(request));
log.info("调用cif业务订购，cif响应：{}"  , JSONObject.toJSONString(cifResponse));

• 不符合业务逻辑预期打印一条日志
  打印关键的参数，要能从这些参数中清楚地看出，谁的操作与预期不符，为什么与预期不符。并且唯一定位到这条日志，要包含用户id或者流水号。日志样例：

// 校验重复签约
int count = agreementService.countSignAndPre(externalUserId, userInfo.getUserId(), agreementType);
if (count == 1) {
    // 已经签约过，不允许重复签约
    log.warn("签约失败，不允许重复签约！用户信息：{}，协议类型：{}，来源系统：{}，外部系统用户号：{}",
        JSONObject.toJSONString(userInfo), agreementType, systemCode, externalUserId);
}

• 业务处理出现异常打印一条日志
  主要打印异常信息和业务逻辑描述。日志样例：

try {
    //业务逻辑处理
} catch (BizException e) {
    log.warn("账户升级过程中出现业务异常", e);
}catch (Exception e) {
    log.error("账户升级过程中出现无法识别的异常", e);
}

• 极少出现的else情况打印一条日志
  打印业务功能描述和该极少出现的参数值，还有唯一定位一次请求的请求流水号。日志样例：

if("0".equals(operType)){ 
    //创建账户
}else if("1".equals(operType)){ 
    //升级账户
}else{
    log.warn("账户创建和升级功能，无法识别操作类型（0：创建，1：升级），请求流水号：{}，当前值：{}" , flowNo, operType);
}

2. 显示程序运行状态的日志

系统程序日复一日/月复一月/年复一年的运行着，查看系统的运行状态是必不可少的，比如一些可能和耗时的业务处理，批处理，IO操作等。

• 耗时（可能出现超时）业务逻辑处理时间打印一条日志
  打印业务逻辑描述和处理时间。日志样例：

long startTime = System.currentTime();  
//业务逻辑处理
log.info("绑定银行卡总耗时 : "  +  (System.currentTime() - startTime) + "ms");　

• 批量处理大量数据时显示处理进度打印n条日志
  在夜间做对账处理时，一般都是批量处理大量数据，这是应打印的日志包括：对账功能描述和处理进度，每处理1000（视情况而定）条打印一条。日志样例：

log.info("业务开通状态对账功能处理中，总数据量：{}，当前处理到：{}", total, current);

3. 可用作运营统计的日志

从业务上来说，一个大的功能往往是由多个小功能组成，这些大的功能组成一个完整的系统。比如一个系统包括注册用户/开通某项业务/绑定银行卡/消费下单，从而达到一个电商类系统的最终目的。针对这个系统运营人员经常会要一些数据如多少注册用户，多少开通业务用户，多少绑卡用户，多少下过单的用户，如果是这样的粗粒度的统计需求，可能写几条sql搂一下数据库就搞定了。但是如果需要更加细致统计，如绑卡功能分为这样几步：用户实名校验，银行卡校验，发送短信验证码，校验短信验证码，签协议绑卡。日志样例：

...
log.info("用户绑卡，实名校验，用户信息：{}", JSONObject.toJSONString(userInfo));
...
log.info("用户绑卡，银行卡校验，用户信息：{}", JSONObject.toJSONString(userInfo));
...
log.info("用户绑卡，发送短信验证码，用户信息：{}", JSONObject.toJSONString(userInfo));
...
log.info("用户绑卡，校验短信验证码，用户信息：{}", JSONObject.toJSONString(userInfo));
...
log.info("用户绑卡，签协议绑卡，用户信息：{}", JSONObject.toJSONString(userInfo));
...

通过后台日志可以做到细粒度的运营统计分析，当然还有其他更专业的技术实现这种运营分析的功能，这种方法可以作为一个过渡期的方法。只要有一个好的打印日志的习惯，通过大数据的分析，日志还有其它的价值。

4. 不应该打印的日志

• 无意义的日志
  日志样例：

log.info("调用客户系统开始...");
...
log.info("调用客户系统结束...");
...
log.info("用户签约失败...");

当我们看到这样的日志的时候，没有包含任何有意义的信息。调用开始，我想知道谁调用的，入参是啥；调用结束，我想知道调用结果，出参是啥，调用成功还是失败；同样，用户签约失败，我想知道的是哪个用户失败，为什么失败；显然都没展示，所以这样的日志是没有任何意义的。

• 混淆信息的日志
  所打印出来的日志都应该是清楚准确的表达，当你不能确定具体原因的时候，不能在日志中只是展示一种可能的情况，这样会影响对问题的判断，这样的日志千万不能打。日志样例：

Connection connection = ConnectionFactory.getConnection();  
if (connection == null) {  
    log.warn("System initialized unsuccessfully");  
}  

结束lala