日志那些事儿——由一次bug引发的思考-client jar应该如何输出日志

前言

前面几篇“日志那些事儿”讲解了日志的重要性和相关使用。以slf4j+logback的使用为例,我们的步骤为:

  • 在工程中引入slf4j、logback相关Jar包
  • 编写配置文件logback.groovy/logback.xml等
  • 使用LoggerFactory.getLogger()得到logger使用。
    从上面可以看出使用过程中非常重要的一个部分为编写配置文件logback.xml,配置文件中通常是配置我们所需要的appender和相关的logger,例如说配置console输出或者配置文件输出等。

一次需求和一次bug

一次需求

前段时间做过一次需求,要求的是尽量无侵入的输出某些请求参数到日志中,Web框架是Webx,在web层采用了valve实现了类似切片功能,在service层直接使用了aop。当然这些都不算关键,关键在于要尽量少的侵入应用,并且要在多个系统中使用。由于在不同应用中可能使用了不同类型的日志框架,所以将关键的aop逻辑、日志输出逻辑封装在client jar中,供应用系统使用。

一次bug

起因

前两天需要对系统升级某项功能,需要引入一个新的jar,升级完成在日常测试环境中部署够,服务功能正常,但是却发现一个非常严重的bug——所有的日志全部不输出了。经排查之后发现是引入的新client jar中使用了slf4j+log4j2,而原应用中使用的是slf4j+logback。前者中引入log4j2-slf4j-impl,后者中的logback-classic中都用org.slf4j.impl.StaticLoggerBinder.class,所以会发生multiple_bindings的错误,按照slf4j的官方文档的说明:

NOTE The warning emitted by SLF4J is just that, a warning. Even when multiple bindings are present, SLF4J will pick one logging framework/implementation and bind with it. The way SLF4J picks a binding is determined by the JVM and for all practical purposes should be considered random. As of version 1.6.6, SLF4J will name the framework/implementation class it is actually bound to.

由于两个StaticLoggerBinder.class属于同名同包,按照hotspot的Jvm规范,会加载classpath下靠前的那个jar中的StaticLoggerBinder。

If the 2 classes have the same package name, i.e. com.mycompany.Client, then you end up in a situation where it is somewhat arbitrary which version of Client is loaded. It comes down to which is on the classpath first. This is a JAR hell situation.

所以,日志停止输出的原因很肯定是因为slf4j binding到了log4j-slf4j-impl中的StaticLoggerBinder,而没有使用logback进行输出。

解决

分析了原因,解决起来了就很简单了,暴力exclude了引入的client jar包中的log4j2相关依赖。重新部署验证后发现日志可以输出,问题解决

对于slf4j的思考

  • 这样做虽然解决了问题,但是并不完美。因为client jar包中引入了log4j2,并且配置了log4j2.xml的配置文件,本意肯定是想使用log4j2输出相关日志到自己指定文件,但是由于我暴力干掉了log4j2,client想输出日志到指定文件是不可能的了,client会将其日志输出到应用主日志中。

  • 当系统中出现两个及以上StaticLoggerBinder.class的时候,肯定不算是“最佳实践”。日志系统虽多,择其善者而从之。

对于client jar设计的思考

一次需求,一次bug,其实都与日志系统相关。这次bug的根本原因也算是因为client jar没有考虑到使用者的感受,把log4j2强加给使用者。client jar可能会有一些记录日志的需求,例如记录一些信息用于调试。那么当client jar有日志输出需求,如何更好地进行设计呢?

我觉得得从以下几个方面考虑:

  • 缩小jar包依赖范围,如果是基于maven,可以把client工程中依赖的日志相关jar scope设置为provided.
  • “感知”应用系统所使用的日志框架,匹配相应的日志框架
  • 不使用配置文件,改用编码配置logger

对于第二点,client jar必须要“感知”应用系统所使用的日志框架,例如究竟是使用了log4j还是log4j2,还是slf4j+logback,亦或者slf4j+log4j等,这样才可以知道client jar中可以使用哪些日志api。对于第三点,由于我们一般都通过xml等配置文件配置日志logger,但这种方式很不灵活。要适配多少种日志系统,就需要在client jar的classpath下放置多少种日志配置文件,而且没法在运行时指定appender,设置layout等等。

总结

如果在client jar中有日志输出的需求,一定要好好设计,千万不能坑了使用者。下篇文章将围绕如何设计包含日志输出的client jar。

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

推荐阅读更多精彩内容