实战总结｜系统日志规范及最佳实践
阿里妹导读
一、概要
1.1 什么是日志？
1.2 为什么要记录日志？
1.3 什么时候记录日志？
代码初始化时或进入逻辑入口时：系统或者服务的启动参数。核心模块或者组件初始化过程中往往依赖一些关键配置，根据参数不同会提供不一样的服务。务必在这里记录INFO日志，打印出参数以及启动完成态服务表述。
编程语言提示异常：这类捕获的异常是系统告知开发人员需要加以关注的，是质量非常高的报错。应当适当记录日志，根据实际结合业务的情况使用WARN或者ERROR级别。
业务流程预期不符：项目代码中结果与期望不符时也是日志场景之一，简单来说所有流程分支都可以加入考虑。取决于开发人员判断能否容忍情形发生。常见的合适场景包括外部参数不正确，数据处理问题导致返回码不在合理范围内等等。
系统/业务核心逻辑的关键动作：系统中核心角色触发的业务动作是需要多加关注的，是衡量系统正常运行的重要指标，建议记录INFO级别日志。
第三方服务远程调用：微服务架构体系中有一个重要的点就是第三方永远不可信，对于第三方服务远程调用建议打印请求和响应的参数，方便在和各个终端定位问题，不会因为第三方服务日志的缺失变得手足无措。
二、基本规范
2.1 日志记录原则
隔离性：日志输出不能影响系统正常运行；
安全性：日志打印本身不能存在逻辑异常或漏洞，导致产生安全问题；
数据安全：不允许输出机密、敏感信息，如用户联系方式、身份证号码、token等；
可监控分析：日志可以提供给监控进行监控，分析系统进行分析；
可定位排查：日志信息输出需有意义，需具有可读性，可供日常开发同学排查线上问题。
2.2 日志等级设置规范
DEBUG
INFO
WARN
ERROR
用户输入参数错误
非核心组件初始化失败
后端任务处理最终失败（如果有重试且重试成功，就不需要WARN）
数据插入幂等
程序启动失败
核心组件初始化失败
连不上数据库
核心业务访问依赖的外部系统持续失败
OOM
2.3 常见日志格式
调用时间
日志链路id(traceId、rpcId)
线程名
接口名
方法名
调用耗时
调用是否成功(Y/N)
错误码
系统上下文信息(调用系统名、调用系统ip、调用时间戳、是否压测(Y/N))
2022-12-12 06:05:05,129 [0b26053315407142451016402xxxxx 0.3 - /// - ] INFO [SofaBizProcessor-4-thread-333] - [(interfaceName,methodName,1ms,Y,SUCCESS)(appName,ip地址,时间戳,Y)调用时间
日志链路id(traceId、rpcId)
线程名
接口名
方法名
调用耗时
调用是否成功(Y/N)
系统上下文信息(调用系统名、调用系统ip、调用时间戳、是否压测(Y/N))
请求入参
请求出参
2022-12-12 06:05:05,129 [0b26053315407142451016402xxxxx 0.3 - /// - ] INFO [SofaBizProcessor-4-thread-333] - [(interfaceName,methodName,1ms,Y,SUCCESS)(appName,ip地址,时间戳,Y)(参数1,参数2)(xxxx)这个日志是否一定要打印？如果不打印是否会影响后续问题排查，如果打印这个日志后续输出频率是否会太高，造成线上日志打印过多。
日志格式是否辨识度高？如果后续对该条日志进行监控或清洗，是否存在无法与其他日志区分或者每次打印的日志格式都不一致的问题？
输出当前执行的关键步骤和描述，明确的表述出打印该条日志的作用，方便后续维护人员阅读。
日志中需包含明确的打印意义，当前执行步骤的关键参数。
[scene_bind_feature][feature_exists]功能已经存在[tagSource='MIF_TAG',tagValue='123']三、日志最佳实践
3.1 强制
public void doSth(){ log.info("do sth and print log: {}", shop.getId()); // 业务逻辑 ...}public void doSth(){ System.out.println("doSth..."); // 业务逻辑 ...}分析：
通过分析System.out.println源码可知，System.out.println是一个同步方法，在高并发的情况下，大量执行println方法会严重影响性能。
public void println(String x) { synchronized (this) { print(x); newLine(); }}不能实现日志按等级输出。具体来说就是不能和日志框架一样，有 debug，info，error等级别的控制。 System.out、System.error打印的日志都并没有打印在日志文件中，而是直接打印在终端，无法对日志进行收集。
public void doSth(){ log.info("doSth..."); // 业务逻辑 ...}// 使用 SLF4J: import org.slf4j.Logger; import org.slf4j.LoggerFactory; private static final Logger logger = LoggerFactory.getLogger(xxx.class); // 使用 JCL: import org.apache.commons.logging.Log; import org.apache.commons.logging.LogFactory; private static final Log log = LogFactory.getLog(xxx.class);声明为private防止logger对象被其他类非法使用。 声明为static是为了防止重复new出logger对象；防止logger被序列化，导致出现安全风险；处于资源考虑，logger的构造方法参数是Class，决定了logger是根据类的结构来进行区分日志，所以一个类只要一个logger，故static。 声明为final是因为在类的生命周期无需变更logger，避免程序运行期对logger进行修改。
private static final Logger LOGGER = LoggerFactory.getLogger(xxx.class);public void doSth(){ String name = "xxx"; logger.trace("print debug log" + name); logger.debug("print debug log" + name); logger.info("print info log" + name); // 业务逻辑 ...}分析：
public void doSth(){ if (logger.isTraceEnabled()) { logger.trace("print trace log {}", name); } if (logger.isDebugEnabled()) { logger.debug("print debug log {}", name); } if (logger.isInfoEnabled()) { logger.info("print info log {}", name; } // 业务逻辑 ...}public void doSth(){ try{ // 业务逻辑 ... } catch (Exception e){ e.printStackTrace(); }}分析：
e.printStackTrace()打印出的堆栈日志跟业务代码日志是交错混合在一起的，通常排查异常日志不太方便。 e.printStackTrace()语句产生的字符串记录的是堆栈信息，如果信息太长太多，字符串常量池所在的内存块没有空间了，即内存满了，系统请求将被阻塞。
public void doSth(){ try{ // 业务逻辑 ... } catch (Exception e){ log.error("execute failed", e); }}没有打印异常e，无法定位出现什么类型的异常
public void doSth(){ try{ // 业务逻辑 ... } catch (Exception e){ log.error("execute failed"); }}没有记录详细的堆栈异常信息，只记录错误基本描述信息，不利于排查问题。
public void doSth(){ try{ // 业务逻辑 ... } catch (Exception e){ log.error("execute failed", e.getMessage()); }}正例：
void error(String var1, Throwable var2);public void doSth(){ try{ // 业务逻辑 ... } catch (Exception e){ log.error("execute failed", e); }}public void doSth(){ log.info("do sth and print log, data={}", JSON.toJSONString(data)); // 业务逻辑 ...}分析：
fastjson等序列化组件是通过调用对象的get方法将对象进行序列化，如果对象里某些get方法被覆写，存在抛出异常的情况，则可能会因为打印日志而影响正常业务流程的执行。
打日志过程中对一些对象的序列化过程也是比较耗性能的。首先序列化过程本身时一个计算密集型过程，费cpu。其次这个过程会产生很多中间对象，对内存也不太友好。
public void doSth(){ log.info("do sth and print log, data={}", data.toString()); log.info("do sth and print log, data={}", ToStringBuilder.reflectionToString(data, ToStringStyle.SHORT_PREFIX_STYLE));}不带任何业务信息的日志，对排查故障毫无意义。
public void doSth(){ log.info("do sth and print log"); // 业务逻辑 ...}对于无异常分支的代码打印日志，一般流程下，异常分支都会打日志，如果没有出现异常，那就说明正常执行了。
public void doSth(){ doIt1(); log.info("do sth 111"); doIt2(); log.info("do sth 222");}正例：
日志一定要带相关的业务信息，有利于排查问题快速定位到原因。
public void doSth(){ log.info("do sth and print log, id={}", id); // 业务逻辑 ...}对于打印过多的无意义日志，可以直接干掉或者以debug级别打印。
public void doSth(){ for(String s : strList) { log.info("do sth and print log: {}", s); // 业务逻辑 ... }}public void doSth(String s){ log.info("do sth and print log: {}", s); doStep(s);}private void doStep(String s){ log.info("do sth and print log: {}", s); // 业务逻辑 ...}public void doSth(String s) { try { doStep(s); } catch (Exception e){ log.error("something wrong", e); }}private void doStep(String s){ try { // 业务逻辑 } catch (Exception e){ log.error("something wrong", e); throw e; }}在每一个嵌套环节都打印了重复的日志。
不要记录日志后又抛出异常。抛出去的异常，一般外层会处理。如果不处理，那为什么还要抛出去？原则是，无论是否发生异常，都不要在不同地方重复记录针对同一事件的日志消息。
3.2 推荐
public String doSth(String id, String type){ log.info("start: {}, {}", id, type); String res = process(id, type); log.info("end: {}, {}, {}", id, type, res};}public void doSth(){ if(user.isVip()){ log.info("该用户是会员,Id:{},开始处理会员逻辑",user,getUserId()); //会员逻辑 }else{ log.info("该用户是非会员,Id:{},开始处理非会员逻辑",user,getUserId()) //非会员逻辑 }}public void doSth(){ log.info("print log, data={}", data.toString()); // 业务逻辑 ...}分析：
public void doSth(){ log.info("print log, id={}, type={}", data.getId(), data.getType()); // 业务逻辑 ...}使用这个种方法需及时防止npe，并考虑是否核心场景，核心场景建议还是打全，避免漏打、少打影响线上问题定位&排查。
阿里云开发者社区，千万开发者的选择
阿里云开发者社区，百万精品技术内容、千节免费系统课程、丰富的体验场景、活跃的社群活动、行业专家分享交流，欢迎点击【阅读原文】加入我们。
微信扫码关注该文公众号作者
戳这里提交新闻线索和高质量文章给我们。
来源: qq
点击查看作者最近其他文章