- WHY
为什么要做日志?
原因1:跟踪应用的警告和错误,标识程序运行中的危险操作、错误操作,进而便于在出现问题时排查问题
原因2:跟踪崩溃bug,在开发过程中,日志可以帮助开发者和软件测试人员跟踪程序崩溃的原因
原因3:跟踪性能下降的问题范围,产品所反映出来的性能问题,很难在开发过程中暴露出来,这需要进行全方位的测试跟踪,而通过日志提供的详细执行时间记录可以很方便的找出应用的性能瓶颈
原因4:跟踪操作流程,通过对日志跟踪,你可以获取操作发生的具体环境,操作的结果
补充原因:
了解项目的运行状态
发现潜在的性能问题
价值化(大数据分析)
- WHICH
日志都有什么级别?
日志打印通常有四种级别,从高到低分别是:ERROR、WARN、INFO、DEBUG。
2.1. ERROR
ERROR:该级别的错误需要马上被处理,当ERROR错误发生时,已经影响了用户的正常访问,是需要马上得到管理员介入并处理的。常见的ERROR异常有:空指针异常,数据库不可用,关键路径的用例无法继续执行等。
2.2. WARN
WARN:对于WARN级别的日志,虽然不需要管理员马上处理,但是也需要引起重视。WARN日志有两种级别:一个是解决方案存在明显的问题(例如Try Catch语句中由于不确定会出现什么异常,而用Exception统一捕获抛出的问题),另一个是潜在的问题和建议(例如系统性能可能会伴随着时间的迁移逐渐不能满足服务需要)。应用程序可以容忍这些信息,不过它们应该被及时地检查及修复。某些用户危险的操作,例如一直采用错误密码尝试登陆管理员账号的行为,也可以提升到WARN日志级别记录。
2.3. INFO
INFO:主要用于记录系统运行状态、用户的操作行为等信息。该日志级别,常用于反馈系统当前状态给最终用户。
2.4. DEBUG
DEBUG:该级别日志的主要作用是对系统每一步的运行状态进行精确的记录。通过该种日志,可以查看某一个操作每一步的执行过程,可以准确定位是何种操作,何种参数,何种顺序导致了某种错误的发生。可以保证在不重现错误的情况下,也可以通过DEBUG级别的日志记录对问题进行诊断。一般来说,在生产环境中,不会输出该级别的日志。
2.5 其他说明
ERROR是错误的意思,但不代表出现异常的地方就该打ERROR。
ERROR是相对程序正确运行来说的,如果出现了ERROR那就代表出问题了,开发人员必须要查一下原因,或许是程序问题,或许是环境问题,或许是理论上不该出错的地方出错了。总之,如果你觉得某个地方出问题时需要解决,就打ERROR,如果不需要解决就不要打ERROR。
举例而言:
如果有一个接口。调用者传过来的参数不在你的接受范围内,在这种情况下你不能打ERROR,因为传什么值是用户决定的,并不影响程序正确运行。想象一下,如果你的服务器上有监控程序的话,检测到ERROR或WARN就报警,参数错误你也打ERROR,那运维人员会疯掉的。
这种调用者传入的接口参数错误问题,就应该打个INFO了,调用者说你的接口总是返回错误代码,你可以告诉他,是他的哪个参数传错了。
WARN是指出现了不影响程序正确运行的问题,WARN也是问题但不影响程序正常运行,如果WARN出现的过于频繁或次数太多,那就代表你要检查一下程序或环境或依赖程序是否真的出问题了。
假如你访问一个接口,设置了一个超时,超时之后会抛异常,你在try块里不该打ERROR也不该打INFO来无视它,这时你应该打WARN,紧紧是警告一下,如果超时过多那就该检查一下了,是不是对方接口有问题了或者是网络环境出问题了。
INFO和DEBUG就是指一般的信息了。在程序出问题时,如果这条log可以帮助你分析问题或查看程序的运行情况,那就应该打个INFO。如果仅仅是为了在调试阶段查看程序是否运行正确那就要打DEBUG。
- What
日志该打印什么信息?
时间 进程|线程 级别 模块 Filter 操作者 入参 内容
时间,包含时区信息和毫秒,建议使用ISO-8601时间格式
进程ID:
线程ID:线程ID相当重要,在解决多线程问题的时候,这一项信息是必不可少的
级别,例如 warn、info 和 error
模块:哪个类,假如是分布式服务的话,需要指明是哪个服务的哪个类
Filter:主要用于查找某一类LOG时候方便,这个Filter是开发人员在开发过程中自己定义的,可以是
开发人员:便于寻找代码中的问题
请求会话话标识:便于追踪用户的操作行为历史
内容:LOG信息
以下内容也在打印考虑范围内:
会话标识。能知道是哪个客户端或者是哪个用户触发、登陆账号、seesion信息等。
其他信息:
场景信息(谁,什么功能等);
状态信息(开始,中断,结束)以及重要参数;
版本号、线程号等。
日志格式:日志格式统一使用主语+谓语+宾语+状语的格式,日志打印应该遵从人类的自然语言,任何没有开发经验或是外行人都能从你的日志中捕获到有用的信息。
主语:就是会话的发起者
谓语:就是这条日志将要具体进行什么样的操作
宾语:行为对象
状语:行为产生的结果
可以加入分隔符,使用分隔符使每个域都能够清晰识别,分隔符可以提高日志可分析性。
使用[]进行参数变量隔离,这样的格式写法,可读性更好,对于排查问题更有帮助
3.1. 需要打印的ERROR级别的日志
主要类型有:
读写配置文件失败
网络断线
所有第三方对接的异常(包括第三方返回错误码)
所有影响功能使用的异常
3.2. 需要打印的WARN级别的日志
异常:由于在程序运行之前不能明确异常引发的原因,异常只进行了简单的捕获抛出,需要将这种笼统处理的异常打印为WARN格式的日志,提醒管理员干预处理
有容错机制的时候出现的错误情况
找不到配置文件,但是系统能自动创建配置文件
性能即将接近临界值的时候
业务异常的记录,危险操作
3.3. 需要打印的INFO级别的日志
Request && Response
系统操作行为:读写文件、定时任务等
不符合业务逻辑预期:打印关键的参数,要能从这些参数中清楚地看出,谁的操作与预期不符,为什么与预期不符。并且唯一定位到这条日志,要包含用户id或者流水号
对外提供的接口入口处:打印接口的唯一标识和简短描述,并且要将调用方传入的参数原样打印出来,这样当系统出现问题时,就能很容易的判断出是否是调用方出现了问题
调用其它系统接口的前后:打印所调用接口的系统名称/接口名称和传入参数/响应参数,这样能方便做问题定界,通过这两条日志可以清楚地看出是否是所调用的系统出现了问题
系统模块的入口与出口处:可以是重要方法级或模块级,记录它的输入与输出,方便定位
非预期执行:为程序在“有可能”执行到的地方打印日志
switch case语句块中的default
if…else if…else中很少出现的else情况
try catch语句块中catch分支。
服务状态变化(尽可能记录线索):程序中重要的状态信息的变化应该记录下来,方便查问题时还原现场,推断程序运行过程
一些可能很耗时的业务处理:批处理,IO操作
程序运行耗时:通过它可以跟踪为什么系统响应变慢或者太快
大批量数据的执行进度
3.4. 需要打印的DEBUG级别的日志
注意: 在生产环境中不能打印DEBUG级别的日志,DEBUG级别的日志只能用于开发调试或测试环节,同时在输出DEBUG级别的日志的时候,也应该依据项目组的开发需求打印日志,尽量做到:
开发人员和测试人员都能看懂
通过阅读DEBUG级别的日志后不需要重现问题,就能准确的定位解决问题
- WHERE
程序入口:在入口打印日志是因为这个时候传递进来的参数没有经过任何处理,将它打印在日志文件中能一眼就知道程序的原始数据是否符合我们的预期,是不是传递进来的原始数据就出现 的问题。
计算结果,测试关心的程序的输出结果是否符合预期,那么对于计算过程不应该关心,仅给出计算结果就能判断是否符合预期。
重要信息:这一点可能很宽泛,因为不同的业务逻辑重点可能并不一样,例如在有的重要参数不能为空,此时就需要判断是否为空,如果为空则记录到日志中;还有的例如传递进来的参数经过一系列的算法处理过后,此时也需要打印日志来查看是否计算正确。但切记,尽量不要直接在for循环中打印日志,特别是for循环特别大时,这样你的日志可能分分钟被冲得不见踪迹,甚至带来性能上的影响。
异常捕获:在异常打印出详细的日志能让你快速定位错误在哪里,例如在程序抛出异常捕获时,在平时我们经常就是直接在控制台打印出堆栈信息e.printStackTrace(),但在实际的生产环境更加艰苦,更别说有IDE来让你查看控制台信息,此时就需要我们将堆栈信息记录在日志中,以便发生异常时我们能准确定位程序在哪里出错。
4.1常见的日志打印处
函数开始结束处
重要函数的开始结束出应该打上log ,这样在看log时会比较直观,什么时候开始什么时候结束就会一目了然,万一中间出异常导致程序退出了,也知道是在哪个函数突然中断的。也同样适用于一个重要逻辑块的开始结束。
返回结果时
尽量在重要函数或web接口的每个返回分支打印返回结果。在出现不好分析的异常时,从细节下手,这时log会派上用场。如果跟合作方在数据方面出现争议也可以及时拿出证据。特别是在调用外部系统接口时,一定要打印结果。
在多线程中
日志最好要记录线程ID日志还要记录线程ID,否则可能不知道是哪个线程的作业,也无法有条理的来观察一个线程。
需要记录程序耗时处
访问一个第三方接口、上传下载文件等可能耗时的操作,都要记录完成这个操作所耗的时间。否则程序性能出了问题,你不知道是网络原因呢,还是你调用的第三方接口性能出现问题呢,还是你自己程序的问题呢。
批量操作
涉及到数量的操作要打印log,比如查询数据库和批量拷贝文件、上传下载、批量格式转换等批量操作,设计到的数量要打印出来。
分布式系统追踪请求
RequestID:我们通常用RequestID来对请求进行唯一的标记,目的是可以通过RequestID将一个请求在系统中的执行过程串联起来,这在分布式系统中的威力是巨大的。该RequestID通常会随着响应返回给调用者,如果调用出现问题,调用者也可以通过提供RequestID帮助服务提供者定位问题。
如何使用requestId在分布式系统追踪请求
5.WHEN
当你遇到问题的时候,只能通过debug功能来确定问题,你应该考虑打日志,良好的系统,是可以通过日志进行问题定位的。
经常以功能为核心进行开发,你应该在提交代码前,可以确定通过日志可以看到整个流程。
和一个外部系统进行通信时,要记录下你的系统传出和读入的数据,这样以便查明是否为外部系统的问题。系统集成是一件苦差事,而诊断两个应用间的问题(想像下不同的公司,环境,技术团队)尤其困难。
- NOTICE
使用Slf4j来记录日志
使用门面模式的日志框架,有利于维护和各个类的日志处理方式统一。
Java是面向对象编程。
反例:UserServiceImpl interface = new UserServiceImpl();
应该面向接口的对象编程,而不是面向实现,这也是软件设计模式的原则,
正确的做法应该是:
UserService interface = new UserServiceImpl();
日志框架里面也是如此,日志有门面接口,有具体实现的实现框架,所以大家不要面向实现编程。
考虑日志对性能的影响:日志的频繁打印会对模块的性能产生极大的影响。当日志产生的速度大于日志文件写磁盘的速度,会导致日志内容积压在内存中,导致内存泄漏。
不打印重复的日志,避免重复打印日志,浪费磁盘空间,务必在log4j.xml中设置 additivity = false【阿里开发手册规约中有强调】
正例:
<logger name="com.taobao.dubbo.config" additivity="false">
1
不打无用的、无意义、不完全的日志。
无用、无意义例子:(不要这样做)
if(message instanceof TextMessage){
//do sth
}else{
log.warn("Unknown message type");
}
上面打印的warn信息,看日志根本无法清楚识别消息类型是什么,上述例子只是充当了提示信息,对解决问题毫无帮助。
正确的打印内容应该是: 消息类型;消息ID;上下文信息;出问题的原因。
无用、无意义例子:(不要这样做)
log.info("调用客户系统开始...");
...
log.info("调用客户系统结束...");
...
log.info("用户签约失败...");
当我们看到这样的日志的时候,没有包含任何有意义的信息。调用开始,我想知道谁调用的,入参是啥;调用结束,我想知道调用结果,出参是啥,调用成功还是失败;同样,用户签约失败,我想知道的是哪个用户失败,为什么失败;显然都没展示,所以这样的日志是没有任何意义的。
不完全的日志例子:(不要这样做)
log.error('XX 发生异常', e.getMessage());
1
e.getMessage()只会记录记录错误基本描述信息,不会记录详细的堆栈异常信息。
正确的打印方式应该是:
log.error('XX 发生异常', e);//这样就会打印堆栈信息
1
在异常捕获代码中务必打印堆栈信息
示例:
try {
int i=1/0;
} catch (Exception ex) {
logger.info("--- getMessage ---");
logger.error(ex.getMessage());
System.out.println();
logger.info("--- print Stack Trace ---");
logger.error("打印异常堆栈信息",ex);
}
控制台输出为:
2018-12-27 11:02:16,737 INFO main com.Test [//] — getMessage —
2018-12-27 11:02:16,739 ERROR main com.Test [//] / by zero
2018-12-27 11:02:16,739 INFO main com.Test [//] — print Stack Trace —
2018-12-27 11:02:16,740 ERROR main com.Test [//] 打印异常堆栈信息
java.lang.ArithmeticException: / by zero
at com.Test.main(Test.java:17)
打印了异常堆栈信息才能快速定位问题。
4.预期会被正常处理的异常,仅需要打印基本信息留作记录,不需要去打印异常堆栈信息,使用堆栈的跟踪是一个巨大的开销,要谨慎使用。
5.不打印混淆信息的日志:所打印出来的日志都应该是清楚准确的表达,当你不能确定具体原因的时候,不能在日志中只是展示一种可能的情况,这样会影响对问题的判断,这样的日志千万不能打。
反例:
Connection connection = ConnectionFactory.getConnection();
if (connection == null) {
log.warn("System initialized unsuccessfully");
}
一般不在循环里打印日志
日志文件推荐至少保存 15 天,因为有些异常具备以“周”为频次发生的特点【阿里开发手册规约中有强调】
应用中的扩展日志【阿里开发手册规约中有强调】
命名方式:appName_logType_logName.log
logType:日志类型
logName:日志描述
这种命名的好处:通过文件名就可知道日志文件属于什么应用,什么类型,什么目的,也有利于归类查找。推荐对日志进行分类,如将错误日志和业务日志分开存放,便于开发人员查看,也便于通过日志对系统进行及时监控。
正例: mppserver 应用中单独监控时区转换异常,如:mppserver _ monitor _ timeZoneConvert . log
谨慎地选择记录日志的级别,生产环境原则上禁止输出 debug 日志;有选择地输出info日志。
特殊情况:
有可能有些问题只会在线上出现,那么此时就需要用到debug来进行问题定位和分析。
如果有上述特殊情况,在生产情况下需要开启DEBUG,需要使用开关进行管理,不能一直开启。
日志打印的时候不能因为打印日志引入新的异常,例如空指针异常
反例:(不要这么做)
log.debug("Processing request with id: {}", request.getId());
//request对象如果是null,那么就会出现NPE。
日志打印的时候,假如需要处理列表、数组类的数据,最好是只输出对象的大小,或者某些关键字段,例如:编号(Commons Beanutils),如果将全部内容打印出来可能会占用大量的资源
写完功能,进行测试时,尽量不用编辑器的调试,而是通过日志来查看功能实现和进行异常定位、分析。
你需要进行功能逻辑判断的要点也可能是你打日志的要点,会出现的异常正是日志需要去记录的。没有编辑器的debug调试,你也可以清楚的知道功能实现的逻辑,异常的原因和快速定位问题。
需要明确对象的toString方法是否输出的东西就是你想要的东西,是否需要重写对象的toString方法
另外,建议打印对象信息时,可以采用json格式打印,这样查看起来更清晰。
log.info("用户绑卡,实名校验,用户信息:{}", JSONObject.toJSONString(userInfo));
1
使用参数化信息的方式:不要进行字符串拼接,那样会产生很多String对象,占用空间,影响性能。
反例:(不要这么做)
logger.debug("Processing trade with id: " + id + " symbol: " + symbol);
1
正例:
logger.debug("UserName is:[{}] and age is : [{}] ", name, age);
//加一个"[]"可读性会更强一些。
记录非预期执行情况
为程序在“有可能”执行到的地方打印日志。如果我想删除一个文件,结果返回成功。但事实上,那个文件在你想删除之前就不存在了。最终结果是一致的,但程序得让我们知道这种情况,要查清为什么文件在删除之前就已经不存在。
如果要抛出异常,就把异常留给最终处理的方法进行打印,不要在抛出异常的地方进行打印。
反例:(不要这么做)
try {
//do sth
} catch (Exception e) {
logger.error('XX 发生异常', e);
throw new IOException();
}
如果你在方法的开始和结束都记录了日志,那么你可以人工找出效率不高的代码。
因为打印的日志有时间戳,你可以根据开始和结束时间获得执行时间,如果执行时间较长,可能就是代码效率有问题。
如果你的方法名的含义很清晰,看日志将是一件愉快的事情。同样的,分析异常也更得更简单了,因为你知道每一步都在干些什么。所以:方法的命名很重要
作为一个webserver,建议将请求者的ip和请求时间,打印到日志中
在和资源打交道的时候,也要记录关键的信息,比如说磁盘访问,比如数据库访问,比如请求网络服务器,这些都算是与小系统的交互,必须要将输入和输出写入日志。而且这些内容都会伴有异常,遇到异常更是要以error写入logger。
异常捕获后除了抛出异常、打印日志外,还可以做哪些操作?
可以提示问题原因。
可以提供可能的解决办法。
尝试解决问题,比如:
比如说碰到了一个主机访问异常,你可以在异常体中尝试重启主机。
比如连接不成功,可以尝试重新连接。
- HOW
实现进入方法前打印参数,退出方法时打印输出的方式
代码里要记录的方法很多的话,可以用AOP切面、拦截器、过滤器来实现参数和结果的日志打印。这样减少了重复的代码,不过使用它得特别小心,不注意的话可能会导致输出大量的日志,这种日志最合适的级别就是DEBUG了。如果你发现某个方法调用的太频繁,记录它的日志可能会影响性能的话,只需要调低它的日志级别就可以了,或者把日志直接删了(或者整个方法调用只留一个?)不过日志多了总比少了要强。把日志记录当成单元测试来看,你的代码应该布满了日志就像它的单元测试到处都是一样。系统没有任何一部分是完全不需要日志的。记住,有时候要知道你的系统是不是正常工作,你只能查看不断刷屏的日志。
7.1. 拦截器
Spring Boot中通过配置拦截器Interceptor,可以拦截某个指定的方法或某一类指定的方法,在方法执行之前打印参数和请求信息,在方法执行完毕之后打印方法的执行结果
实现方式:
首先需要配置一个注解
其次需要设计该注解的实现(即拦截器具体要执行的操作)
最后配置该拦截器
/**
* 定义一个注解,一般为方法级别,在需要打印日志的方法上面使用
*/
@Target(ElementType.METHOD)
@Retention(RetentionPolicy.RUNTIME)
@Documented
public @interface LogPrint {
}
注意:
@Target
ElementType.TYPE:接口、类、枚举、注解
ElementType.FIELD:字段、枚举的常量
ElementType.METHOD:方法
ElementType.PARAMETER:方法参数
ElementType.CONSTRUCTOR:构造函数
ElementType.LOCAL_VARIABLE:局部变量
ElementType.ANNOTATION_TYPE:注解
ElementType.PACKAGE:包
@Retention
RetentionPolicy.SOURCE:这种类型的Annotations只在源代码级别保留,编译时就会被忽略
RetentionPolicy.CLASS —— 这种类型的Annotations编译时被保留,在class文件中存在,但JVM将会忽略
RetentionPolicy.RUNTIME —— 这种类型的Annotations将被JVM保留,所以他们能在运行时被JVM或其他使用反射机制的代码所读取和使用.
/**
* 拦截器方法具体要实现的功能,日志打印就在该部分实现
*/
@Service
public class LogPrintInterceptor implements HandlerInterceptor {
/**
* 请求处理之前进行调用(Controller方法调用之前)
*/
@Override
public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {
/**
* 在方法执行之前需要打印的日志,可以从servlet和handler中获取请求的参数信息
*/
// 千万千万要返回true,否则将不进入方法执行
return true;
}
/**
* 请求处理之后进行调用(Controller方法调用之后)
*/
@Override
public void postHandle(HttpServletRequest request, HttpServletResponse response, Object handler, ModelAndView modelAndView) throws Exception {
/**
* 在方法执行完之后需要打印的日志
*/
}
/**
* 渲染了对应的视图之后执行
*/
@Override
public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex) throws Exception {
/**
* 在方法执行完之后需要打印的日志
*/
}
}
/**
* 配置拦截器方法
*/
@Configuration
@EnableWebMvc
public class WebMvcConfig extends WebMvcConfigurerAdapter {
@Autowired
private LogPrintInterceptor logPrintInterceptor;
/**
* 配置注解拦截器
*/
@Override
public void addInterceptors(InterceptorRegistry registry) {
registry.addInterceptor(logPrintInterceptor)
.addPathPatterns("/**");
super.addInterceptors(registry);
}
}
7.2. 过滤器
同样的,也可以通过使用过滤器Filter来实现方法执行前后的参数回复信息的打印
实现方式:
首先创建一个Filter的实现类,在Filter的实现类的doFilter方法中实现方法执行前后的日志打印
最后配置该过滤器
@Service
public class LogPrintFilter implements Filter {
@Override
public void init(FilterConfig filterConfig) throws ServletException {
}
@Override
public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain)
throws IOException, ServletException {
/**
* 方法执行前日志打印
*/
// 实际业务
chain.doFilter(request, response);
/**
* 方法执行后日志打印
*/
}
@Override
public void destroy() {
}
}
@Configuration
@EnableWebMvc
public class WebMvcConfig extends WebMvcConfigurerAdapter {
@Bean
public FilterRegistrationBean logPrintFilterRegistration() {
FilterRegistrationBean registration = new FilterRegistrationBean();
// 这个位置只能采用创建新对象的方式来设置拦截器,采用注入的方式,实验失败
registration.setFilter(new LogPrintFilter());
registration.addUrlPatterns("/**");
registration.addInitParameter("paramName", "paramValue");
registration.setName("logPrint");
registration.setOrder(1);
return registration;
}
}
7.3. 切面
同样的,也可以通过切面的思想来实现方法执行前后的日志打印
实现方式:
实现切面Aspect类
@Aspect
@Component
public class LogPrintAspect {
/**
* 方法切点
*/
@Pointcut(value = "execution(* com.cmft.logplat.base.controller.*.*(..))")
private void pointcut(){
}
/**
* 方法执行之前
*/
@Before(value = "pointcut()")
public void before(JoinPoint joinPoint){
//
}
/**
* 方法执行之后
*/
@After(value = "pointcut()")
public void after(JoinPoint joinPoint){
//
}
}
注意:
如何配置切入点
配置切入点的时候尽可能约束到目标方法群,否则范围太宽的话,会造成某些外部插件的bean无法自动注入
原文:https://blog.csdn.net/nihaoa50/article/details/85242337
版权声明:本文为博主原创文章,转载请附上博文链接!