生产和测试环境中需要日志来记录、跟踪和分析系统的运行状态,但是有太多带有杂讯的日志又会影响跟踪,甚至可能对系统的运行带来影响。
我们需要怎样的日志
- 可以被记录、跟踪、分析和归档
- 了解系统运行的必要信息,方便排查和分析
- 最小化对系统性能的影响
Java日志实践
Log4j等日志框架默认info级别以上,不建议在生产环境打开debug级别的日志
等级 | 适用范围 |
Fatal | 严重的,造成服务中断的错误 |
Error | 其他错误运行期错误,非业务错误 |
Warn | 警告信息,如程序调用了一个旧版本的接口,可选参数不合法,非业务预期的状态但仍可继续处理等 |
Info | 有意义的内容,重要业务方法调用开始及结束 |
Debug | 调试信息,变量在方法过程中的变化等信息 |
Trace | 更详细的跟踪信息 |
内容
方法/事件的调用和结束,可附带重要输入/输出信息以及耗时等方法过程中某些较为重要的其他方法(诸如Client)的调用的输入/输出信息及耗时等重要变量的变化
什么不应该输出
敏感重要的信息,例如用户隐私信息,token以及sessionkey等信息冗余信息,例如对整个对象toString输出,或者json字符串格式化后输出不合适的Threshold级别,例如「权限鉴定」失败抛出error级别的信息由于现阶段没有合适的Profiler的应用,日志输出可能需要很大程度上承担性能分析的作用,以下为示例
字段 | 行为描述 | 行为级别 | 描述(TRACE情况下打印) | 参数(建议入口打印) | 耗时 |
示例 | queryItemSearch | INVOKE/TRACE/END | callClientXXXX | {“KeyA”:”ValueA”} | 20ms |
以上参数均为可选,但是建议同一模块或子模块下使用同一规则,以方便统计分析归档等。
logger.info("[doSomething][INVOKE]Param:.....");
// ...
logger.info("[doSomething][TRACE ][queryDB1]cost:100ms");
// ..
logger.info("[doSomething][END ]cost:200ms");
Log4j的配置
以下为Log4j的示例
log4j.properties
log4j.rootLogger=INFO,logFile
log4j.logger.com.danga.ttserver=ERROR
log4j.additivity.com.danga.ttserver=false
logFile appender
log4j.appender.logFile.Threshold=INFO
log4j.appender.logFile=org.apache.log4j.DailyRollingFileAppender
log4j.appender.logFile.File=/data/logs/(tomcat|jboss|timer)/${service}/${module-app(-subAction)}.log
log4j.appender.logFile.DatePattern='.'yyyyMMdd
log4j.appender.logFile.layout=org.apache.log4j.PatternLayout
log4j.appender.logFile.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss,SSS}[%-5p][%t](%c{3}:%L):%m%n
log4j.appender.logFile.encoding=UTF-8
在高并发情况下,当有大量请求至同一容器,我们很难通过日志简单的还原一次业务请求的明细过程。
我们可以藉由Log4j 提供的 MDC( mapped diagnostic context) 来解决这个问题。MDC (Apache Log4j 1.2.17 API)
// 下述代码嵌入请求入口(Filter、拦截器等)
MDC.put("TRACE_ID", "cx4jbc0jzovd"); // 随机生成追踪用的 ID修改 Log4j 的对应 pattern
log4j.appender.logFile.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss,SSS}[%-5p][%t](%c{3}:%L):%m%n
log4j.appender.logFile.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss,SSS}[%-5p][%t][%X{TRACE_ID}](%c{3}:%L):%m%n