到目前为止,我是如何 debug 的呢?当然是在本地跑起来,一通操作,然后紧盯控制台,坐等要关注的信息出现,这很多时候足以应付需要。可是若是生产环境出现了 bug,让咱去修复呢?这就引入了一堆问题——该在哪里去找日志?该如何去迅速找到自己想要的日志?再上升到理论,在开发的时候如何在出现 bug 时能给出最清晰明了的日志以帮助定位问题?
为此,必须去了解日志框架及其配置,以及最佳实践。现在使用的最为广泛的日志框架是 log4j2,其使用 slf4j 作为门面,因此对其进行学习。下面说的 log4j 指代 log4j2。
log4j 作为一个日志框架,它和控制台输出相较有何区别?主要是它具有更高的自定义性和扩展性——它能控制日志的格式(除日志文本之外,还能带上时间,线程名,类名等,这通过用户给定的格式化字符串去配置),能控制日志的目的地,能控制日志输出级别…这些玩意都在一个配置文件中进行配置,因此修改不需要更改源代码。
log4j 的官方文档处记录了一些关于 log4j 的 文章,官网中关于 log4j 的 架构文档 也是值得阅读的。
log4j 有三个重要组件:Logger,Appender,Layout,其中 Logger 抽象特定日志级别的日志打印器,如 ERROR 级别,FATAL 级别,INFO 级别;Appender 抽象日志的目的地,如文件,控制台;Layout 抽象日志的格式,如格式化形式,HTML 形式。
或许可以说,日志框架有三个要素:打印什么种类的日志?打印到哪里去?打印什么内容?
何谓日志级别
这里首先引入了一个新概念——什么是日志级别?显然,我们打的日志本身就是分场合的——展示特定信息的,追溯请求全流程的,仅用于 debug 的,打印错误的,将日志的“场合”抽象出来对规范的日志有利。
但是,日志框架所抽象出来的并非是日志“种类”,而是日志级别,虽然不知道为何这样设计,但既然都这样实践这么多年了……
log4j 有 8 个级别,按优先级降序排序:
| OFF > FATAL > ERROR > WARN > INFO > DEBUG > TRACE > ALL
|
OFF
:Nothing!
FATAL
:指明足以终止程序运行的事件,比如连接数据库失败,必需的配置未找到
ERROR
:指明错误,但应用可继续运行(用户的输入错误应当放到 WARN)
WARN
:指明可能导致错误的事件,或有必要提醒的事件
INFO
:程序运行描述信息,粒度较粗
DEBUG
:细粒度的描述信息,主要用于帮助 debug
TRACE
:程序运行轨迹,最细的粒度
ALL
:Everything!
FATAL 是“致命的”,在有些语言里也用 CRITICAL
可以认为 OFF 和 ALL 是标识性的,没有日志处在 OFF 级别,ALL 级别代表所有日志(自定义的日志级别可能在 ALL 级别上才打印)。
当设置日志级别为特定的优先级的时候,只有大于等于该优先级的日志会被打印,比如,当我们设置优先级为 INFO 的时候,只有 FATAL,ERROR,WARN,INFO 的信息得到打印。
Learn log4j2.xml in Y Minutes
log4j 的配置是最重要的一部分(想必也不会有几个人去自定义 Appender 之类的,因此对其的使用,即配置是最重要的),至于具体使用,则留给 slf4j。这里我认为直接采取类似Learn X in Y Minutes
的形式即可,描述直接结合配置,事半功倍鸭!
考虑到当前对日志框架没必要深入(长期基本也没必要深入,毕竟是配置文件,试错成本低),因此只学习最基本的东西。
官方的关于配置的文档见 此,未免讲的有点过于宽泛了吧?
log4j 的默认配置
下面展示的是 log4j 没有检查到任何配置时的默认配置,十分沉默,只有 FATAL 和 ERROR 的日志会被输出(到控制台)。
| <?xml version="1.0" encoding="UTF-8"?>
<Configuration status="WARN"> <Appenders> <Console name="Console" target="SYSTEM_OUT"> <PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n"/> </Console> </Appenders> <Loggers> <Root level="error"> <AppenderRef ref="Console"/> </Root> </Loggers> </Configuration>
|
这里定义了一个 Appender 和一个 Logger,Appender 代表日志的目的地,这里是控制台,其目标是标准输出流;Logger 代表日志打印者,这里的 Logger 是根日志打印器 Root,这代表所有日志如果没有被其它日志打印器“拦截”的话,就会来到根日志打印器。
这里的 Appender 使用 PatternLayout(显然,Appender 要使用特定的 Layout,直接将其包含在自己的子标签中即可)。
默认配置用一句话去概述,就是所有优先级大于等于 ERROR 的日志会送往标准输出流,其它的忽略,这显然仅供测试时 DEBUG 使用,无法适应生产环境。
打印日志到文件
要打印日志到文件,就得先添加作为文件的目的地,并在日志打印器中去引用它,代码类似下面。
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21
| <?xml version="1.0" encoding="UTF-8"?> <Configuration status="WARN"> <Properties> <property name="logFile">logs/thelog.log</property> </Properties> <Appenders> <Console name="Console" target="SYSTEM_OUT"> <PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n"/> </Console> <File name="File" fileName="${logFile}"> <PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n"/> </File> </Appenders> <Loggers> <Root level="INFO"> <AppenderRef ref="Console" /> <AppenderRef ref="File" /> </Root> </Loggers> </Configuration>
|
这样配置,所有大于等于 INFO,即 INFO,WARN,ERROR,FATAL 的日志会被同时输出到文件logs/thelog.log
和控制台上。
Properties 用于定义可重用的字符串常量。
分离不同级别的日志
先声明,想让某特定级别的日志输出到特定位置不一定不能实现,但是是没有实践意义的。
考虑这样的需求,我们想把所有 INFO 以上的日志都打印到控制台,把所有 WARN 以上的日志都打印到特定文件以供查阅,这通过配置 AppenderRef 的级别去实现。
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23
| <?xml version="1.0" encoding="UTF-8"?>
<Configuration status="WARN"> <Properties> <property name="logFile">logs/warn.log</property> </Properties> <Appenders> <Console name="Console" target="SYSTEM_OUT"> <PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n"/> </Console> <File name="file" fileName="${logFile}"> <PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n"/> </File> </Appenders> <Loggers>
<Root level="INFO"> <AppenderRef ref="Console" /> <AppenderRef ref="file" level="WARN" /> </Root> </Loggers> </Configuration>
|
注意:AppenderRef 的级别设置的比 Logger 的级别更低是无效的,比如 Logger 级别设置为 INFO,AppenderRef 的级别设置为 TRACE,则仍旧只有 INFO 及以上的日志会来到该 Appender。
分离框架和业务代码的日志
再进一步,我们想要能够分离框架的日志和业务的日志,这样来更好地帮助 debug;同时,我们也想在某个地方能同时看到所有的日志。为此,需要定义额外的 logger 了,但代码仍旧是比较容易理解的。
这里需要引入两个新概念:Logger 的 Name,以及 additivity,Logger 的 Name 一般情况下使用包名,这代表这个包下的类打的日志会来到这个 Logger;additivity 则表示这个 Logger 是否会在处理这个日志后把这个日志“冒泡”到父 Logger(是的,Logger 有继承性),默认为 true,即冒泡。
Logger 的 Name 通常使用包名,这是由于我们在业务代码中 getLogger 时通常是通过全限定类名,如果随便写的话那肯定全跑 Root 上去了。
从需求出发:我们要让框架的日志输出到logs/framework.log
,业务的日志输出到logs/bussiness.log
,控制台上只输出框架日志。
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32
| <?xml version="1.0" encoding="UTF-8"?>
<Configuration status="WARN"> <Properties> <property name="logDir">logs</property> <property name="frameworkLogFile">${logDir}/framework.log</property> <property name="bussinessLogFile">${logDir}/bussiness.log</property> </Properties> <Appenders> <Console name="Console" target="SYSTEM_OUT"> <PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n"/> </Console> <File name="framework" fileName="${frameworkLogFile}"> <PatternLayout pattern="SPRING %d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n"/> </File> <File name="bussiness" fileName="${bussinessLogFile}"> <PatternLayout pattern="BUSSINESS %d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n"/> </File> </Appenders> <Loggers> <Logger name="me.yuuki" additivity="false" level="WARN"> <AppenderRef ref="bussiness" /> </Logger> <Logger name="org.springframework" level="TRACE"> <AppenderRef ref="framework" /> </Logger> <Root level="INFO"> <AppenderRef ref="Console"/> </Root> </Loggers> </Configuration>
|
上面的配置会达到下面的结果:
me.yuuki
包下的 WARN 级别及以上的日志会去到logs/bussiness.log
org.springframework
包下的 TRACE 级别及以上的日志会去到logs/framework.log
和控制台(注意,TRACE 及以上的日志都会去到控制台!这就是说 Root 的 level 设置被“覆盖”掉了)
- 其它包下的 INFO 级别及以上的日志会去到控制台
关于 Logger 的继承性
Logger 使用 NAME 来表示继承性——不考虑相等的情况,如果 Logger A 的 NAME 是 Logger B 的 NAME 的前缀(其实还得带上一个.
),则 B 是 A 的子类,比如,me.yuuki.dao
是me.yuuki
的子类,同时一切 Logger 都是 Root 的子类。
从当前看来,继承性主要表现在三个地方:
- 子类的日志能够冒泡到父类
- 子类的日志级别会使用父类的级别如果没有配置
- 子类的日志级别会覆盖父类的日志级别
Root 的默认级别为 ERROR。
比如上面的例子中,me.yuuki
设置不冒泡,因此只自己处理了;org.springframework
的日志级别是 TRACE,因此覆盖了 Root 的 INFO,因此打到org.springframework
的日志打到 Root,即输出到控制台上的是 TRACE 级别。
比如,下面的配置将me.yuuki.dao
的日志输出到logs/dao.log
,me.yuuki.service
的日志输出到logs/service.log
,me.yuuki
(除dao
)的日志输出到logs/bussiness.log
,所有日志输出到控制台。
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41
| <?xml version="1.0" encoding="UTF-8"?>
<Configuration status="WARN"> <Properties> <property name="logDir">logs</property> <property name="daoLogFile">${logDir}/dao.log</property> <property name="serviceLogFile">${logDir}/service.log</property> <property name="BizLogFile">${logDir}/bussiness.log</property> </Properties> <Appenders> <Console name="Console" target="SYSTEM_OUT"> <PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n"/> </Console> <File name="dao" fileName="${daoLogFile}"> <PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n"/> </File> <File name="service" fileName="${serviceLogFile}"> <PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n"/> </File> <File name="bussiness" fileName="${BizLogFile}"> <PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n"/> </File> </Appenders> <Loggers>
<Logger name="me.yuuki.dao" additivity="false"> <AppenderRef ref="dao" /> </Logger> <Logger name="me.yuuki.service"> <AppenderRef ref="service" /> </Logger> <Logger name="me.yuuki"> <AppenderRef ref="bussiness" /> </Logger> <Root level="TRACE"> <AppenderRef ref="Console"/> </Root> </Loggers> </Configuration>
|
在测试和生产环境使用不同配置
如何在不改变配置文件的情况下让配置文件能直接在测试和生产环境中同时使用?显然我们需要一个类似 profile 之类的东西,而 log4j 确实提供了这种功能,负责该功能的实体称为 Arbiter,仲裁者。仲裁者的行为就像某些语言的 when 语句,或 mybatis 的 if 语句,但有一些更复杂的标签使其能实现 switch 的功能。
下面就两种复杂程度不同的 Arbiter 配置进行描述,when 和 switch 这两个关键字描述它们的行为再适合不过。但 arbiter 能出现的地方远不止于此,容易找到更优雅的编写方案。
when
下面的代码使用了 SystemPropertyArbiter,它根据系统属性 env 的值进行裁决,在生产环境时将文件输出到/tmp/prod.log
上,在开发环境时输出到logs/dev.log
上。
| <Properties> <SystemPropertyArbiter propertyName="env" propertyValue="dev"> <property name="logFile">logs/dev.log</property> </SystemPropertyArbiter> <SystemPropertyArbiter propertyName="env" propertyValue="prod"> <property name="logFile">/tmp/prod.log</property> </SystemPropertyArbiter> </Properties>
|
但是最常用的当然还是 Spring boot profile:
| <Properties> <SpringProfile name="dev | test"> <property name="logFile">logs/dev.log</property> </SpringProfile> <SpringProfile name="prod"> <property name="logFile">/tmp/prod.log</property> </SpringProfile> </Properties>
|
switch
实现 switch 要使用 SELECT 标签,它的所有子标签都为 Arbiter,它会找到第一个为真的 Arbiter 并应用,log4j 提供了一个 DefaultArbiter,它始终为真。
| <Properties> <Select> <SystemPropertyArbiter propertyName="env" propertyValue="dev"> <property name="logFile">logs/dev.log</property> </SystemPropertyArbiter> <SystemPropertyArbiter propertyName="env" propertyValue="prod"> <property name="logFile">/tmp/prod.log</property> </SystemPropertyArbiter> <DefaultArbiter> <property name="logFile">logs/others.log</property> </DefaultArbiter> </Select> </Properties>
|
切割切割!
但何不做得更绝一些,完成一些彻底的切割?
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58
| <?xml version="1.0" encoding="UTF-8"?> <Configuration status="INFO"> <Select> <SystemPropertyArbiter propertyName="env" propertyValue="dev"> <Appenders> <Console name="Console" target="SYSTEM_OUT"> <PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n"/> </Console>
<File name="file" fileName="logs/dev.log"> <PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n"/> </File> </Appenders>
<Loggers>
<Root level="INFO"> <AppenderRef ref="Console" /> <AppenderRef ref="file" /> </Root> </Loggers> </SystemPropertyArbiter> <SystemPropertyArbiter propertyName="env" propertyValue="prod"> <Appenders> <Console name="Console" target="SYSTEM_OUT"> <PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n"/> </Console>
<File name="file" fileName="logs/prod.log"> <PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n"/> </File> </Appenders> <Loggers>
<Root level="INFO"> <AppenderRef ref="Console" /> <AppenderRef ref="file" /> </Root> </Loggers>
</SystemPropertyArbiter> <DefaultArbiter> <Appenders> <Console name="Console" target="SYSTEM_OUT"> <PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n"/> </Console> </Appenders> <Loggers> <Root level="INFO"> <AppenderRef ref="Console" /> </Root> </Loggers> </DefaultArbiter> </Select> </Configuration>
|
关于 PatternLayout
PatternLayout 即格式化日志输出,使用一个模式字符串去作为格式,这应该是使用最广泛的 Layout,关于其使用的各种模式,直接翻 文档 吧,这里给一个例子。
| <PatternLayout> <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [ %t ] [%c{1.}] - [ %p ] %m%n</pattern> </PatternLayout>
|
关于 Appender
关于 Appender 的文档见 此,仍旧是给出示例。
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33
| <Appenders> <Console name="Console" target="SYSTEM_OUT" follow="true"> <ThresholdFilter level="info" onMatch="ACCEPT" onMismatch="DENY"/> <PatternLayout> <pattern>${LOG_PATTERN}</pattern> </PatternLayout> </Console> <RollingFile name="File" fileName="${FILE_PATH}/platform.log" filePattern="${FILE_PATH}/platform/$${date:yyyy-MM}/%d{yyyy-MM-dd}-%i.log"> <PatternLayout> <pattern>${LOG_PATTERN}</pattern> </PatternLayout> <Policies> <SizeBasedTriggeringPolicy size="50MB"/> <TimeBasedTriggeringPolicy modulate="true" interval="1" /> </Policies> <DefaultRolloverStrategy max="1000"/> </RollingFile> <RollingFile name="commonFile" fileName="${FILE_PATH}/common.log" filePattern="${FILE_PATH}/common/$${date:yyyy-MM}/%d{yyyy-MM-dd}-%i.log.gz"> <PatternLayout> <pattern>${LOG_PATTERN}</pattern> </PatternLayout> <Policies> <SizeBasedTriggeringPolicy size="50MB"/> </Policies> <DefaultRolloverStrategy max="1000"/> </RollingFile> </Appenders>
|