在开发B/S系统时,对于LOG,需要关注:
- 日志信息的集中采集、存储、信息检索:在WEB集群节点越来越多的情况下,让开发及系统维护人员能很方便的查看日志信息
- 日志信息的输出策略:日志信息输出全而不乱,便于跟踪和分析问题
- 关键业务的日志输出:基于度量数据采集、数据核查、系统安全等方面的考虑,关键业务系统对输出的日志信息有特殊的要求,需要做针对性的设计
本文主要从这3个方面进行说明,重点说明日志输出的使用
日志的采集和存储
对于目前存储日志,主要存在2种方式:
- 本地日志:直接存放在本地磁盘上
- 远程日志:发往�日志平台,用作数据分析和日志处理并展现。如用户访问行为的记录,异常日志,性能统计日志等。
日志工具的选择
推荐使用SLF4J(Simple Logging Facade for Java)作为日志的api,SLF4J是一个用于日志系统的简单Facade,允许最终用户在部署其应用时使用其所希望的日志系统。与使用apache commons-logging和直接使用log4j相比,SLF4J提供了一个名为参数化日志的高级特性,可以显著提高在配置为关闭日志的情况下的日志语句性能
//slf4j
log.debug("Found {} records matching filter: '{}'", records, filter);
//log4j
log.debug("Found " + records + " records matching filter: '" + filter + "'");
可以看出SLF4J的方式一方面更简略易读,另一方面少了字符串拼接的开销,并且在日志级别达不到时(这里例子即为设置级别为debug以上),不会调用对象的toString方法。
日志输出级别(由高到低)
ERROR:系统中发生了非常严重的问题,必须马上有人进行处理。没有系统可以忍受这个级别的问题的存在。比如:NPEs(空指针异常),数据库不可用,关键业务流程中断等等
WARN:发生这个级别问题时,处理过程可以继续,但必须对这个问题给予额外关注。这个问题又可以细分成两种情况:一种是存在严重的问题但有应急措施(比如数据库不可用,使用Cache);第二种是潜在问题及建议(ATTENTION),比如生产环境的应用运行在Development模式下、管理控制台没有密码保护等。系统可以允许这种错误的存在,但必须及时做跟踪检查
INFO:重要的业务处理已经结束。在实际环境中,系统管理员或者高级用户要能理解INFO输出的信息并能很快的了解应用正在做什么。比如,一个和处理机票预订的系统,对每一张票要有且只有一条INFO信息描述 "[Who] booked ticket from [Where] to [Where]"。另外一种对INFO信息的定义是:记录显著改变应用状态的每一个action,比如:数据库更新、外部系统请求
DEBUG:用于开发人员使用。将在TRACE章节中一起说明这个级别该输出什么信息
TRACE:非常具体的信息,只能用于开发调试使用。部署到生产环境后,这个级别的信息只能保持很短的时间。这些信息只能临时存在,并将最终被关闭。要区分DEBUG和TRACE会比较困难,对一个在开发及测试完成后将被删除的LOG输出,可能会比较适合定义为TRACE级别
推荐使用debug,info,warn,error级别即可,对于不同的级别可以设置不同的输出路径,如debug,info输出到一个文件,warn,error输出到一个带error后缀的文件
日志API规范
- Log对象的声明和初始化,仅以下代码是符合规范的
// (推荐)
private static final Logger logger = LoggerFactory.getLogger(Xxx.class);
private final Logger logger = LoggerFactory.getLogger(getClass());
private static final Logger logger = LoggerFactory.getLogger("loggerName");
private static Logger logger = LoggerFactory.getLogger(Xxx.class);
protected final Logger logger = LoggerFactory.getLogger(getClass());
private Logger logger = LoggerFactory.getLogger(getClass());
protected Logger logger = LoggerFactory.getLogger(getClass());
不得使用System.out, System.err进行日志记录,请改使用logger.debug、logger.error
debug/info级别的信息,信息本身需要计算或合并的,必须加 isXxxEnabled() 判断在前,这样可以大大提高高并发下的效率。如:
if (logger.isDebugEnabled()) {
logger.debug(test());
}
private String test(){
int i = 0;
while (i < 1000000) {
i++;
}
return "";
}
如果不加 isXxxEnabled() 判断,test()在info级别下也会执行。
注意error和warn级别的区别,导致业务不正常服务的,用error级别;错误是预期会发生的,并且已经有了其他的处理流程,使用warn级别
正确的记录异常信息
记录异常信息是“记录所有信息”中的一个重要组成,但很多开发人员只是把logging当做处理异常的一种方式。他们通常返回缺省值,然后当做什么都没发生。 其他时候,他们先log异常信息,然后再抛出包装过的异常。如:
log.error("IO exception", e);
throw new MyCustomException(e);
这种方法总是会打印两次相同的 stack trace信息,因为有些地方会捕捉MyCustomException异常,然后输出导致问题的日志信息。
但有时基于某些原因我们真的想log异常信息怎么办?很过见多的log语句有一半以上都是错的,
如:
try {
Integer x = null;
++x;
} catch (Exception e) {
//A
log.error(e);
//B
log.error(e, e);
//C
log.error(""+ e);
//D
log.error(e.toString());
//E
log.error(e.getMessage());
//F
log.error(null, e);
//G
log.error("", e);
//H
log.error("{}", e);
//I
log.error("{}", e.getMessage());
//J
log.error("Error reading configuration file: " + e);
//K
log.error("Error reading configuration file: "+ e.getMessage());
//L
log.error("Error reading configuration file", e);
}
上面只有G、L是对的,L的处理方式更好一些
注意:捕获异常后不处理也不输出log是一种非常不负责任的行为,这会造成问题很难被定位,极大地提高debug成本!
- 重要方法入口,业务流程前后及处理的结果等,推荐记录log,并使用debug级别,如:
public String printDocument(Document doc, Mode mode) {
log.debug("Entering printDocument(doc={}, mode={})", doc, mode);
//Lengthy printing operation
String id = "Id";
log.debug("Leaving printDocument(): {}", id);
return id;
}
因为对于非开发人员掌控的环境(无法做DEBUG),记录方法调用、入参、返回值的方式对于排查问题会有很大帮助。
- Log的内容一定要确保不会因为Log语句的问题而抛出异常造成中断,如:
log.debug("Processing request with id: {}", request.getId());
你能确保request对象不是NULL吗?如果request为null,就会抛出NullPointerException。
- 避免拖慢应用系统
输出太多日志信息:通常每小时输出到disk的数据量达到几百MiB就已经是上限了不正确使用toString() 或字符串拼接方法。
try {
log.trace("Id=" + request.getUser().getId() + " accesses" + manager.getPage().getUrl().toString())
} catch(NullPointerException e) {
}
- 日志信息中尽量包含数据和描述:
easy to read, easy to parse
一些反模式的例子
log.debug("Message processed");
log.debug(message.getJMSMessageID());
log.debug("Message with id '{}' processed", message.getJMSMessageID());
if (message instanceof TextMessage)
//...
else {
log.warn("Unknown message type");
}
为什么不包含 message type, message id, etc,包含个message content很难吗?另一个anti-pattern是magic-log。
有些开发人员为了自己查找信息方便,输出类似“&&&!#”的Log,而不是“Message with XYZ id received”。
最后,Log 不要涉及密码及个人信息(身份证、银行卡号etc)
- 关键业务系统日志的要求
用户浏览日志
使用WEB服务器或应用服务器实现日志输出,关键信息包括:访问时间
、用户IP
、访问的URL
、用户浏览器信息
、HTTP状态码
、请求处理时间
用户登录日志
用于记录用户的Login、Logout、CheckLogin请求情况,关键信息如下:
Login
:请求时间
、用户IP
、用户名
、渠道信息
、用户浏览器信息
、登录处理结果
、请求花费时间
、tokenId
、sessionid
Logout
:请求时间
、用户IP
、用户名
、渠道信息
、用户浏览器信息
、登出结果
、请求花费时间
、tokenid
、sessionid
CheckLogin
:请求时间
、用户IP
、用户名
、渠道信息
、用户浏览器信息
、检查结果
、检查花费时间
、tokenid
、sessionId
服务接口调用日志
所有外部接口的调用需要记录接口访问信息,关键信息如下:
请求时间、接口URL、接口方法、调用结果、执行时间
配置规范
统一使用log4j.xml、log4j2.xml、logback配置。
所有的jar包中不推荐包含log4j.xml、log4j.properties、logback.xml文件,避免干扰实际的业务系统。
注意Logger间的继承关系,如:
- log4j的继承是通过命名来实现的。
- 子logger会默认继承父logger的appender,将它们加入到自己的Appender中;除非加上了additivity="false",则不再继承父logger的appender。
- 子logger只在自己未定义输出级别的情况下,才会继承父logger的输出级别。
Log文件位置和命名,目前Log文件的位置统一放在相同目录下面,Log名字通常以业务名开头,如xxx.log.2015-11-19等。
日志格式:必选打印数据项: 发生时间、日志级别、日志内容,可选文件和行号。
远程日志的输出需要注意host和port,区分cagegory。
作者 @九都散人
2015 年 11月 22日