前言

Github:https://github.com/HealerJean

博客:http://blog.healerjean.com

一、概要

1、为什么要记录日志

打印调试:用日志来记录变量或者某一段逻辑,记录程序运行的流程,即程序运行了哪些代码,方便排查逻辑问题。

问题定位:程序出异常或者出故障时快速的定位问题,方便后期解决问题。因为线上生产环境无法 debug,在测试环境去模拟一套生产环境费时费力。所以依靠日志记录的信息定位问题,这点非常重要。

监控告警 & 用户行为审计:格式化后日志可以通过相关监控系统配置多维度的监控视图,让我们可以掌握系统运行情况或者记录用户的操作行为并对日志采集分析,用于建设业务大盘使用。

2、什么时候记录日志

1、代码初始化时或进入逻辑入口时:系统或者服务的启动参数。核心模块或者组件初始化过程中往往依赖一些关键配置,根据参数不同会提供不一样的服务。务必在这里记录INFO日志,打印出参数以及启动完成态服务表述。

2、业务流程预期不符:项目代码中结果与期望不符时也是日志场景之一(,暗示数据或逻辑可能有错误的地方),简单来说所有流程分支都可以加入考虑。取决于开发人员判断能否容忍情形发生。常见的合适场景包括外部参数不正确,数据处理问题导致返回码不在合理范围内等等。

3、编程语言提示异常:这类捕获的异常是系统告知开发人员需要加以关注的,是质量非常高的报错。应当适当记录日志,根据实际结合业务的情况使用 WARN或者 ERROR级别 (数据库存储过程中出现异常,比如唯一索引冲突,列格式不正确,事务需要回滚等)

4、需要保留痕迹的地方:比如用户行为留痕,为合规或审计留痕等

5、系统/业务核心逻辑的关键动作:系统中核心角色触发的业务动作是需要多加关注的,是衡量系统正常运行的重要指标,建议记录INFO级别日志(重要的业务流程状态变化,以及对应的分支处)。

6、第三方服务远程调用:微服务架构体系中有一个重要的点就是第三方永远不可信,对于第三方服务远程调用建议打印请求和响应的参数,方便在和各个终端定位问题,不会因为第三方服务日志的缺失变得手足无措。

二、基本规范

1、日志记录原则

概括 说明
隔离性 日志输出不能影响系统正常运行;
安全性 日志打印本身不能存在逻辑异常或漏洞,导致产生安全问题;
数据安全 不允许输出机密、敏感信息,如用户联系方式、身份证号码、token等;
可监控分析 日志可以提供给监控进行监控,分析系统进行分析
可定位排查 日志信息输出需有意义,需具有可读性,可供日常开发同学排查线上问题。

2、日志等级

级别 说明
DEBUG DEUBG 级别的主要输出调试性质的内容,该级别日志主要用于在开发、测试阶段输出。该级别的日志应尽可能地详尽,开发人员可以将各类详细信息记录到 DEBUG 里,起到调试的作用,包括参数信息,调试细节信息,返回值信息等等,便于在开发、测试阶段出现问题或者异常时,对其进行分析。
INFO INFO 级别的主要记录系统关键信息,旨在保留系统正常工作期间关键运行指标,开发人员可以将初始化系统配置、业务状态变化信息,或者用户业务流程中的核心处理记录到 INFO日志中,方便日常运维工作以及错误回溯时上下文场景复现。建议在项目完成后,在测试环境将日志级别调成 INFO,然后通过 INFO级别的信息看看是否能了解这个应用的运用情况,如果出现问题后是否这些日志能否提供有用的排查问题的信息。
WARN warn 级别在产生不符合预期的结果,但业务并未受损的情况下可以使用,warn 级别的日志可不产生短信报警,可与公司及时消息打通报警或者邮件报警,解决的时效性要求低,但需要关注。 比如,某个方法入参为空或者该参数的值不满足运行该方法的条件时。在 WARN级别的时应输出较为详尽的信息,以便于事后对日志进行分析
ERROR ERROR级别主要针对于一些不可预知的信息,诸如:错误、异常等,比如,在 catch 块中抓获的网络通信、数据库连接等异常,若异常对系统的整个流程影响不大,可以使用 WARN 级别日志输出。在输出 ERROR 级别的日志时,尽量多地输出方法入参数、方法执行过程中产生的对象等数据,在带有错误、异常对象的数据时,需要将该对象一并输出。打印该日志意味着系统出现潜在问题,需要报警,并且需要相关人员马上介入解决。error 日志需要包含问题出现时必要的信息,比如用户信息,调用栈信息等。error级别的日志文件可以独立,以便报警处理

1)如何选择 WARN / ERROR

image-20231103115426498

3)常见的 WARN级别异常

1、用户输入参数错误

2、非核心组件初始化失败

3、后端任务处理最终失败(如果有重试且重试成功,就不需要WARN)

4、数据插入幂等

4)常见的 ERROR级别异常

1、程序启动失败

2、核心组件初始化失败

3、连不上数据库

4、核心业务访问依赖的外部系统持续失败

5、OOM

5)注意事项

不要滥用ERROR级别日志。一般来说在配置了告警的系统中,WARN 级别一般不会告警,ERROR 级别则会设置监控告警甚至电话报警,ERROR 级别日志的出现意味着系统中发生了非常严重的问题,必须有人立即处理。

错误的使用 ERROR级别日志,不区分问题的重要程度,只要是问题就采用 ERROR 级别日志,这是极其不负责任的表现,因为大部分系统中的告警配置都是根据单位时间内 ERROR 级别日志出现的数量来定的,随意打 ERROR 日志将会造成极大的告警噪音,造成重要问题遗漏。

三、常见的日志格式

1、摘要日志

摘要日志是格式化的标准日志文件,可用于监控系统进行监控配置和离线日志分析的日志,通常系统对外提供的服务以及集成的第三方服务都需要打印对应的服务摘要日志,摘要日志格式一般需包含以下几类关键信息:

调用时间、日志链路 id ( traceIdrpcId)、线程名、接口名、方法名、调用耗时、调用是否成功(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)

2、详细日志

详细日志是用于补充摘要日志中的一些业务参数的日志文件,用于问题排查。详细日志一般包含以下几类信息:

调用时间、日志链路 id ( traceIdrpcId)、线程名、接口名、方法名、调用耗时、调用是否成功(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)

3、业务执行日志

**建议格式:<日志场景><日志含义>带业务参数的具体信息**

业务执行日志就是系统执行过程中输出的日志,一般没有特定格式,是开发人员用于跟踪代码执行逻辑而打印的日志,个人看来在摘要日志、详细日志、错误日志齐全的情况下,需要打印系统执行日志的地方比较少。如果一定要打印业务执行日志,需要关注以下几个点:

1、这个日志是否一定要打印?如果不打印是否会影响后续问题排查,如果打印这个日志后续输出频率是否会太高,造成线上日志打印过多。

2、日志格式是否辨识度高?如果后续对该条日志进行监控或清洗,是否存在无法与其他日志区分或者每次打印的日志格式都不一致的问题?

3、输出当前执行的关键步骤和描述,明确的表述出打印该条日志的作用,方便后续维护人员阅读

4、日志中需包含明确的打印意义,当前执行步骤的关键参数。

<scene_bind_feature><feature_exists>功能已经存在[tagSource='MIF_TAG',tagValue='123']

四、异常常见类

1、StackTraceElement

 StackTraceElement s= e.getStackTrace()[0];
方法 说明
s.getFileName() 记录报错的文件
s.getMethodName() 记录报错的方法:
s.getLineNumber() 记录报错的行号:
e.getMessage() 记录报错的信息(不全面)
e.getClassName() 记录报错的类名字
logger.error("错误堆栈", e); 打印详细的堆栈信息:
public static void main(String[] args) {

    try {
        int i =1/0 ;
    }catch (Exception e){
        log(e,ExceptionLogUtils.class );
    }
}


public static void log(Throwable e,Class c){
    Logger logger = LoggerFactory.getLogger(c);

    StackTraceElement s= e.getStackTrace()[0];//数组长度为 1
    logger.error("\n\n-----------------"+
                 "\n报错文件名:"+s.getFileName()+
                 "\n报错的类:"+s.getClassName()+
                 "\n报错方法::"+s.getMethodName()+
                 "\n报错的行:"+ s.getLineNumber()+
                 "\n报错的message:"+ e.getMessage()+
                 "\n错误堆栈:\n"+getStackTrace(e)+
                 "\n------------------\n\n");
}



//获取堆栈信息
public static String getStackTrace(Throwable throwable){
    StringWriter sw = new StringWriter();
    PrintWriter pw = new PrintWriter(sw);
    try
    {
        throwable.printStackTrace(pw);
        return sw.toString();
    } finally
    {
        pw.close();
    }
}



11:40:53.732 [main] ERROR com.duodian.youhui.admin.utils.ExceptionLogUtils - 

-----------------
报错文件名:ExceptionLogUtils.java
报错的类com.duodian.youhui.admin.utils.ExceptionLogUtils
报错方法::main
报错的行68
报错的message/ by zero
错误堆栈
java.lang.ArithmeticException: / by zero
	at com.duodian.youhui.admin.utils.ExceptionLogUtils.main(ExceptionLogUtils.java:68)

------------------

2、 Thread.currentThread().getStackTrace()

public static void main(String[] args) {
    logInfo("HealerJean",ExceptionLogUtils.class);
}


public static void logInfo(String msg,Class c){
    Logger logger = LoggerFactory.getLogger(c);
    String location="";
    StackTraceElement[] stacks = Thread.currentThread().getStackTrace();
    System.out.println(stacks.length); //长度为3
    for(StackTraceElement stackTraceElement:stacks){
        logger.info("\n\n**************"+
                    "\n打印文件名:"+stackTraceElement.getFileName() +
                    "\n打印类名:"+ stackTraceElement.getClassName() +
                    "\n方法名:" +  stackTraceElement.getMethodName() +
                    "\n行号:"  +  stackTraceElement.getLineNumber() +
                    "\n打印内容:"+msg+
                    "\n**************\n\n");
        System.out.println(location);
    }

}


11:44:47.685 [main] INFO com.duodian.youhui.admin.utils.ExceptionLogUtils - 

**************
打印文件名Thread.java
打印类名java.lang.Thread
方法名getStackTrace
行号1559
打印内容:HealerJean
**************


11:44:47.689 [main] INFO com.duodian.youhui.admin.utils.ExceptionLogUtils - 

**************
打印文件名ExceptionLogUtils.java
打印类名com.duodian.youhui.admin.utils.ExceptionLogUtils
方法名logInfo
行号31
打印内容:HealerJean
**************


11:44:47.689 [main] INFO com.duodian.youhui.admin.utils.ExceptionLogUtils - 

**************
打印文件名ExceptionLogUtils.java
打印类名com.duodian.youhui.admin.utils.ExceptionLogUtils
方法名main
行号49
打印内容:HealerJean
**************

3、工具类获取堆栈信息

ExceptionUtils

<dependency>
  <groupId>org.apache.commons</groupId>
  <artifactId>commons-lang3</artifactId>
  <version>3.1</version>
</dependency>
ExceptionUtils.getStackTrace(e)

4、ThrowableExceptionError

Throwablejava.lang包中一个专门用来处理异常的类。它有两个子类,即ErrorException,它们分别用来处理两组异常。

1)Error

**用来处理程序运行环境方面的异常,Error无法预期的错误因此,这是不可捕捉的,无法采取任何恢复的操作,一般只能显示错误的信息 **

比如,虚拟机错误、装载错误和连接错误,这类异常主要是和硬件有关的,而不是由程序本身抛出的。

比如 OutOfMemoryError,试多少次很大概率出错的。

2)Exception

java 提供了两类主要的异常:运行时异常 runtime exception 和一般异常 checked exception但是在逻辑上又科分成检查异常和非检查异常

a、正常分类

运行时异常

Java程序运行时常常遇到的各种异常的处理,其中包括隐式异常。比如,程序中除数为0引起的错误、数组下标越界错误等,这类异常也称为运行时异常,,因为它们虽然是由程序本身引起的异常,但不是程序主动抛出的,而是在程序运行中产生的。

运行时异常我们可以不处理。这样的异常由虚拟机接管。出现运行时异常后,系统会把异常一直往上层抛,一直遇到处理代码。如果不对运行时异常进行处理,那么出现运行时异常之后,要么是线程中止,要么是主程序终

一般异常

这些异常也称为显式异常。它们都是在程序中用语句抛出、并且也是用语句进行捕获的,比如,文件没找到引起的异常、类没找到引起的异常等。

JAVA要求程序员对其进行 catch。所以,面对这种异常不管我们是否愿意,只能 catch 捕获,要么用throws字句声明抛出,交给它的父类处理,否则编译不会通过。

b、逻辑分类:

checked 检查异常和 unchecked非检查异常。

checked Exception 就是在写代码的时候,IDE(比如Eclipse) 会要求你写 try catch的那种Exception,比如IOException。这种ExceptionJava 的设计者要求你的程序去处理的。这种异常一般不会影响程序的主体,容易手动诊断修复,所以 Java要求你在catch下面写出处理的代码,以保证程序遇到此类 exception之后还可以正常运行

unchecked 这一类就是你在代码处理了 checked exception之后,你在运行时候依然会遇到的 exception,所以又叫做RunTimeException,比如NullPointerException, IndexOutOfBoundsException。此类exception相较于前面那种更容易影响程序运行,从设计者角度不提倡从程序中catch出来并处理,当然你也可以这么做。

/**
* 将CheckedException转换为UncheckedException
*/
public static RuntimeException toUncheckedException(Exception e) {
    if (e instanceof RuntimeException) {
        return (RuntimeException) e;
    } else {
        return new RuntimeException(e);
    }
}

五、日志实战

1、打印公约

1)打印日志的代码不允许失败,阻断流程!

一定要确保不会因为日志打印语句抛出异常造成业务流程中断,如下图所示,shopnull 的会导致抛出 NPE

// 反例
public void doSth(){    
  log.info("do sth and print log: {}", shop.getId());    
  // 业务逻辑    ...
}

2)禁止使用 System.out.println() 输出日志

通过分析 System.out.println 源码可知,System.out.println 是一个同步方法,在高并发的情况下,大量执行 println方法会严重影响性能。

// 反例
public void doSth(){   
  System.out.println("doSth...");    
  // 业务逻辑    ...
}

3)禁止直接使用日志系统(Log4jLogback)中的API

⬤ 直接使用 Log4j 或者 Logback 中的API会导致系统代码实现强耦合日志系统,后续需要切换日志实现时会产生比较大的改造成本,统一使用 SLF4J 或者 JCL 等日志框架的 API,其是使用门面模式的日志框架,可以做到解耦具体日志实现的作用,有利于后续维护和保证各个类的日志处理方式统一。

禁止直接使用日志系统的 API(比如 log4j 日志系统),应该使用门面模式提供的接口可以安装 lombok插件,类上使用 @Slf4j 注解,然后代码中直接使用 log.info(“message:{}”, msg);

正例
// 使用 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);

4)声明日志工具对象 Logger 应声明为 private static final

⬤ 声明为private 防止 logger 对象被其他类非法使用。

⬤ 声明为 static是为了防止重复 newlogger 对象;防止 logger被序列化,导致出现安全风险;处于资源考虑,logger的构造方法参数是 Class,决定了 logger是根据类的结构来进行区分日志,所以一个类只要一个 logger,故 static

⬤ 声明为 final 是因为在类的生命周期无需变更 logger,避免程序运行期对 logger进行修改。

// 正例
private static final Logger LOGGER = LoggerFactory.getLogger(xxx.class);

5) 对于 trace/ debug / info 级别的日志输出,必须进行日志级别的开关判断

如果配置的日志级别是 warn的话,以下日志不会打印,但是会执行字符串拼接操作,如果 name 是对象, 还会执行 toString()方法,浪费了系统资源,执行了上述操作,最终日志却没有打印,因此建议加日志开关判断

// 反例
public void doSth(){   
  String name = "xxx";    
  logger.trace("print debug log" + name);    
  logger.debug("print debug log" + name);    
  logger.info("print info log" + name);    
  // 业务逻辑    ...
}

6) 捕获异常后不要使用 e.printStackTrace() 打印日志

1、e.printStackTrace() 打印出的堆栈日志跟业务代码日志是交错混合在一起的,通常排查异常日志不太方便。

2、e.printStackTrace() 语句产生的字符串记录的是堆栈信息,如果信息太长太多,字符串常量池所在的内存块没有空间了,即内存满了,系统请求将被阻塞。

// 反例
public void doSth(){    
  try{        
    // 业务逻辑        ...    
  } catch (Exception e){        
    e.printStackTrace();    
  }}
// 正例
public void doSth(){    
  try{        
    // 业务逻辑        ...    
  } catch (Exception e){        
    log.error("execute failed", e);   
  }}

7)打印异常日志一定要输出全部错误信息

没有打印异常 e,无法定位出现什么类型的异常

// 正例
void error(String var1, Throwable var2);
public void doSth(){    
  try{        
    // 业务逻辑        ...    
  } catch (Exception e){        
    log.error("execute failed", e);    
}}

8)日志打印时禁止直接用JSON工具将对象转换成String

1、fastjson 等序列化组件是通过调用对象的 get 方法将对象进行序列化,如果对象里某些 get 方法被覆写,存在抛出异常的情况,则可能会因为打印日志而影响正常业务流程的执行。

2、打日志过程中对一些对象的序列化过程也是比较耗性能的。首先序列化过程本身时一个计算密集型过程,费 cpu。其次这个过程会产生很多中间对象,对内存也不太友好。

// 反例
public void doSth(){    
  log.info("do sth and print log, data={}", JSON.toJSONString(data));    
  // 业务逻辑    ...
}

可以使用对象的 toString() 方法打印对象信息,如果代码中没有对 toString() 有定制化逻辑的话,可以使用 apacheToStringBulider工具。

// 正例
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));
}

9)不要打印无意义(无业务上下文、无关联日志链路id)的日志

// 反例
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);    
  // 业务逻辑    ...
}

10)不要在循环中打印 INFO 级别日志

// 反例
public void doSth(){    
  for(String s : strList) {      
    log.info("do sth and print log: {}", s);        
    // 业务逻辑        ...    
  }
}

11)不要打印重复的日志

反例分析

1、在每一个嵌套环节都打印了重复的日志。

2、不要记录日志后又抛出异常。抛出去的异常,一般外层会处理。如果不处理,那为什么还要抛出去?原则是,无论是否发生异常,都不要在不同地方重复记录针对同一事件的日志消息。

正例:直接干掉或者将日志降级成debug级别日志

// 反例
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;    
  }
}

12)避免敏感信息输出

13)日志单行大小必须不超过 200K

14)日志语言尽量使用英文

建议:尽量在打印日志时输出英文,防止中文编码与终端不一致导致打印出现乱码的情况,对故障定位和排查存在一定的干扰。

15)在核心业务逻辑中遇到if…else等条件,尽量每个分支首行都打印日志

在编写核心业务逻辑代码时,如遇到if…else…或者switch这样的条件,可以在分支的首行就打印日志,这样排查问题时,就可以通过日志,确定进入了哪个分支,代码逻辑更清晰,也更方便排查问题了。

// 建议
public void doSth(){    
  if(user.isVip()){        
    log.info("该用户是会员,Id:{},开始处理会员逻辑",user,getUserId());        
    //会员逻辑    
  }else{        
    log.info("该用户是非会员,Id:{},开始处理非会员逻辑",user,getUserId())        
      //非会员逻辑    
  }}

16)建议只打印必要的参数,不要整个对象打印

// 反例
public void doSth(){    
  log.info("print log, data={}", data.toString());    
  // 业务逻辑    ...
}
// 正例
public void doSth(){    
  log.info("print log, id={}, type={}", data.getId(), data.getType());    
  // 业务逻辑    ...
}

ContactAuthor