LOG使用规范(整理)

在开发B/S系统时,对于LOG,需要关注:

  1. 日志信息的集中采集、存储、信息检索:在WEB集群节点越来越多的情况下,让开发及系统维护人员能很方便的查看日志信息
  2. 日志信息的输出策略:日志信息输出全而不乱,便于跟踪和分析问题
  3. 关键业务的日志输出:基于度量数据采集、数据核查、系统安全等方面的考虑,关键业务系统对输出的日志信息有特殊的要求,需要做针对性的设计

本文主要从这3个方面进行说明,重点说明日志输出的使用

日志的采集和存储
对于目前存储日志,主要存在2种方式:

  1. 本地日志:直接存放在本地磁盘上
  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用户名渠道信息用户浏览器信息登录处理结果请求花费时间tokenIdsessionid
    Logout请求时间用户IP用户名渠道信息用户浏览器信息登出结果请求花费时间tokenidsessionid
    CheckLogin请求时间用户IP用户名渠道信息用户浏览器信息检查结果检查花费时间tokenidsessionId

  • 服务接口调用日志
    所有外部接口的调用需要记录接口访问信息,关键信息如下:
    请求时间、接口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日


参考
最后编辑于
©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 203,271评论 5 476
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 85,275评论 2 380
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 150,151评论 0 336
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 54,550评论 1 273
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 63,553评论 5 365
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 48,559评论 1 281
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 37,924评论 3 395
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 36,580评论 0 257
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 40,826评论 1 297
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 35,578评论 2 320
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 37,661评论 1 329
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 33,363评论 4 318
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 38,940评论 3 307
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 29,926评论 0 19
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 31,156评论 1 259
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 42,872评论 2 349
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 42,391评论 2 342

推荐阅读更多精彩内容

  • 在应用程序中添加日志记录总的来说基于三个目的:监视代码中变量的变化情况,周期性的记录到文件中供其他应用进行统计分析...
    时待吾阅读 4,953评论 0 6
  • 在应用程序中添加日志记录总的来说基于三个目的:监视代码中变量的变化情况,周期性的记录到文件中供其他应用进行统计分析...
    时待吾阅读 4,933评论 1 13
  • 一、Log4j简介 Log4j有三个主要的组件:Loggers(记录器),Appenders (输出源)和Layo...
    默默守护阅读 1,897评论 2 8
  • 日子总是像从指尖渡过的细纱,在不经意间悄然滑落。那些往日的忧愁和误用伤,在似水流年的荡涤下随波轻轻地逝去,而留下的...
    龙歌阅读 414评论 0 0
  • 人去世以后有两个去处 一个是天堂 一个是地狱 心善者上天堂 心恶者下地狱 天堂公司面对持续下降的人数 决定 使用一...
    每天都要写东西的黑文阅读 491评论 0 0