log4j外部配置文件失效问题

0 目录

  • 1 问题描述
  • 2 问题复现
  • 3 问题定位
    • 3.1 log4j自动加载配置文件原理
    • 3.2 开启log4j调试信息
    • 3.3 PropertyConfigurator.configure(logCfgFile)的调用栈
  • 4 结论
  • 5 问题规避
    • 5.1 不提供默认配置文件
    • 5.2 设置环境变量

1 问题描述

我司的一个java工程，使用了外部的log4j配置文件。工程启动时会手动加载log4j外部配置文件。

 PropertyConfigurator.configure(logCfgFile);

最近发生了一个诡异的问题，外部配置文件中的日志等级明明设置为INFO，但是日志中却打印出了大量debug级别的日志。
在该工程的resources目录下，也有一个log4j配置文件，是本地测试时使用的，其中将部分包的日志等级设为了DEBUG。
很自然地想到，问题就处在这个工程内部的配置文件上。

2 问题复现

笔者建立了一个Demo来复现问题。
内部配置文件（resources目录下）：

log4j.rootLogger=info,stdout
log4j.appender.stdout = org.apache.log4j.ConsoleAppender
log4j.appender.stdout.Target = System.out
log4j.appender.stdout.layout = org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern =  %d{ABSOLUTE} %5p %c{1}:%L - %m%n

log4j.logger.com.django.practice=debug

外部配置文件

log4j.rootLogger=info,stdout
log4j.appender.stdout = org.apache.log4j.ConsoleAppender
log4j.appender.stdout.Target = System.out
log4j.appender.stdout.layout = org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern =  %d{ABSOLUTE} %5p %c{1}:%L - %m%n

注意：两个配置文件只有最后一行有差别

代码：

public class TestDemo {
    public static void main(String[] args){
        // 当且仅当传入了log4j配置文件时，才进行手动加载
        if (args.length >= 1) {
            String logCfgFile = args[0];
            PropertyConfigurator.configure(logCfgFile);
        }
        Logger logger = LoggerFactory.getLogger(TestDemo.class);
        logger.debug("Debug message");
        logger.info("Info message");
    }
}

现在来启动程序。
不传入配置文件时（即使用工程内部的配置文件），输出如下：

13:53:17,198 DEBUG TestDemo:47 - Debug message
13:53:17,200  INFO TestDemo:48 - Info message

符合预期

传入外部配置文件时：输出如下：

13:54:42,909 DEBUG TestDemo:47 - Debug message
13:54:42,911  INFO TestDemo:48 - Info message

与预期不符，按照外部配置文件的配置，这里应该只输出INFO日志。

很好，问题已复现！那么这就已经解决了一半的问题。

3 问题定位

3.1 log4j自动加载配置文件原理

众所周知，log4j会自动加载默认的配置文件。其中的玄机就在于org.apache.log4j.LogManager中的静态块。摘录如下：

 static {
    // By default we use a DefaultRepositorySelector which always returns 'h'.
    Hierarchy h = new Hierarchy(new RootLogger((Level) Level.DEBUG));
    repositorySelector = new DefaultRepositorySelector(h);

    /** Search for the properties file log4j.properties in the CLASSPATH.  */
    String override =OptionConverter.getSystemProperty(DEFAULT_INIT_OVERRIDE_KEY,
                               null);

    // if there is no default init override, then get the resource
    // specified by the user or the default config file.
    if(override == null || "false".equalsIgnoreCase(override)) {

      String configurationOptionStr = OptionConverter.getSystemProperty(
                              DEFAULT_CONFIGURATION_KEY, 
                              null);

      String configuratorClassName = OptionConverter.getSystemProperty(
                                                   CONFIGURATOR_CLASS_KEY, 
                           null);

      URL url = null;

      // if the user has not specified the log4j.configuration
      // property, we search first for the file "log4j.xml" and then
      // "log4j.properties"
      if(configurationOptionStr == null) {  
    url = Loader.getResource(DEFAULT_XML_CONFIGURATION_FILE);
    if(url == null) {
      url = Loader.getResource(DEFAULT_CONFIGURATION_FILE);
    }
      } else {
    try {
      url = new URL(configurationOptionStr);
    } catch (MalformedURLException ex) {
      // so, resource is not a URL:
      // attempt to get the resource from the class path
      url = Loader.getResource(configurationOptionStr); 
    }   
      }
      
      // If we have a non-null url, then delegate the rest of the
      // configuration to the OptionConverter.selectAndConfigure
      // method.
      if(url != null) {
        LogLog.debug("Using URL ["+url+"] for automatic log4j configuration.");
        try {
            OptionConverter.selectAndConfigure(url, configuratorClassName,
                       LogManager.getLoggerRepository());
        } catch (NoClassDefFoundError e) {
            LogLog.warn("Error during default initialization", e);
        }
      } else {
        LogLog.debug("Could not find resource: ["+configurationOptionStr+"].");
      }
    } else {
        LogLog.debug("Default initialization of overridden by " + 
            DEFAULT_INIT_OVERRIDE_KEY + "property."); 
    }  
  }

这个静态块完成的就是自动加载默认配置文件的功能：在类路径下首先去寻找log4j.xml，如果不存在则寻找log4j.properties。
这里笔者想要纠正一下一个普通的错误说法：

log4j会在类加载时自动加载默认的配置文件

这里对时间点的描述不够准确，更准确地说，应该是：

log4j会在类初始化时自动加载默认的配置文件

jvm的类加载机制中，类的生命周期有7个阶段

加载、验证、准备、解析、初始化、使用和卸载

image.png

而静态块执行的时间点，是在初始化阶段。
对于类初始化的时机，虚拟机规范是这样规定的，有且只有下面5种情况需要立即对类进行初始化：

1） 遇到new、getstatic、putstatic或invokestatic这四条字节码指令时，如果类没有进行初始化，则需要先触发其初始化。生成这四条指令的场景Java代码场景是：使>用new关键词实例化类的对象、读取或设置一个类的静态字段(被final修饰、已在编译期把结果放入常量池的静态字段除外)、调用一个类的静态方法的时候。
2）使用java.lang.reflect包的方法对类进行反射调用的时候，如果类还没有进行过初始化，则需要先进行初始化。
3）当初始化一个类的时候，如果发现其父类还没有初始化，则需要先初始化其父类。
4）当虚拟机启动时，用户需要制定一个要执行的主类(包含main()方法的那个类)，虚拟机会先初始化这个主类

  1. 当使用JDK1.7的动态语言支持时，如果一个java.lang.invoke.MethodHandle实例最后的解析结果是REF_getStatic、REF_putStatic、REF_invokeStatic的方法句柄，并>且这个方法句柄对应的类没有进行过初始化，则需要先触发其初始化。

到这里我们就可以明确一个事实了，通常而言，当我们首次使用Log4j的Logger打印日志时，会触发org.apache.log4j.LogManager
的初始化过程，从而加载默认的配置文件。

3.2 开启log4j调试信息

为了详细查看log4j配置加载情况，笔者增加了虚拟机参数：-Dlog4j.debug，并重新运行程序。

不传入配置文件时（即使用工程内部的配置文件），输出如下：

log4j: Trying to find [log4j.xml] using context classloader sun.misc.Launcher$AppClassLoader@42a57993.
log4j: Trying to find [log4j.xml] using sun.misc.Launcher$AppClassLoader@42a57993 class loader.
log4j: Trying to find [log4j.xml] using ClassLoader.getSystemResource().
log4j: Trying to find [log4j.properties] using context classloader sun.misc.Launcher$AppClassLoader@42a57993.
log4j: Using URL [jar:file:/Volumes/CaseSensitiveHD/projects/practice/target/practice-1.0.0.jar!/log4j.properties] for automatic log4j configuration.
log4j: Reading configuration from URL jar:file:/Volumes/CaseSensitiveHD/projects/practice/target/practice-1.0.0.jar!/log4j.properties
log4j: Parsing for [root] with value=[info,stdout].
log4j: Level token is [info].
log4j: Category root set to INFO
log4j: Parsing appender named "stdout".
log4j: Parsing layout options for "stdout".
log4j: Setting property [conversionPattern] to [%d{ABSOLUTE} %5p %c{1}:%L - %m%n].
log4j: End of parsing for "stdout".
log4j: Setting property [target] to [System.out].
log4j: Parsed "stdout" options.
log4j: Parsing for [com.django.practice] with value=[debug].
log4j: Level token is [debug].
log4j: Category com.django.practice set to DEBUG
log4j: Handling log4j.additivity.com.django.practice=[null]
log4j: Finished configuring.
15:02:33,529 DEBUG TestDemo:48 - Debug message
15:02:33,530  INFO TestDemo:49 - Info message

可以看到，log4j的确是自动到类路径下去加载了log4j.properties。

传入外部配置文件时：输出如下：

log4j: Trying to find [log4j.xml] using context classloader sun.misc.Launcher$AppClassLoader@42a57993.
log4j: Trying to find [log4j.xml] using sun.misc.Launcher$AppClassLoader@42a57993 class loader.
log4j: Trying to find [log4j.xml] using ClassLoader.getSystemResource().
log4j: Trying to find [log4j.properties] using context classloader sun.misc.Launcher$AppClassLoader@42a57993.
log4j: Using URL [jar:file:/Volumes/CaseSensitiveHD/projects/practice/target/practice-1.0.0.jar!/log4j.properties] for automatic log4j configuration.
log4j: Reading configuration from URL jar:file:/Volumes/CaseSensitiveHD/projects/practice/target/practice-1.0.0.jar!/log4j.properties
log4j: Parsing for [root] with value=[info,stdout].
log4j: Level token is [info].
log4j: Category root set to INFO
log4j: Parsing appender named "stdout".
log4j: Parsing layout options for "stdout".
log4j: Setting property [conversionPattern] to [%d{ABSOLUTE} %5p %c{1}:%L - %m%n].
log4j: End of parsing for "stdout".
log4j: Setting property [target] to [System.out].
log4j: Parsed "stdout" options.
log4j: Parsing for [com.django.practice] with value=[debug].
log4j: Level token is [debug].
log4j: Category com.django.practice set to DEBUG
log4j: Handling log4j.additivity.com.django.practice=[null]
log4j: Finished configuring.
log4j: Parsing for [root] with value=[info,stdout].
log4j: Level token is [info].
log4j: Category root set to INFO
log4j: Parsing appender named "stdout".
log4j: Parsing layout options for "stdout".
log4j: Setting property [conversionPattern] to [%d{ABSOLUTE} %5p %c{1}:%L - %m%n].
log4j: End of parsing for "stdout".
log4j: Setting property [target] to [System.out].
log4j: Parsed "stdout" options.
log4j: Finished configuring.
15:03:45,221 DEBUG TestDemo:48 - Debug message
15:03:45,222  INFO TestDemo:49 - Info message

这里就比较有意思了。我们看到，这里输出了两次：

Finished configuring.

再仔细看，就会发现确实加载了两次配置文件。第一次是加载的工程内的默认配置文件，第二次加载的是外部提供的配置文件。
再看看我们的代码：


image.png

这里虽然手动制定了配置文件，但是log4j仍然首先会去加载类路径下的默认配置文件，然后再去加载我们指定的配置文件。

3.3 PropertyConfigurator.configure(logCfgFile)的调用栈

我们来追踪一下 PropertyConfigurator.configure(logCfgFile)的调用栈。

  static
  public
  void configure(String configFilename) {
    new PropertyConfigurator().doConfigure(configFilename,
                       LogManager.getLoggerRepository());
  }

LogManager#getLoggerRepository()

  static
  public
  LoggerRepository getLoggerRepository() {
    if (repositorySelector == null) {
        repositorySelector = new DefaultRepositorySelector(new NOPLoggerRepository());
        guard = null;
        Exception ex = new IllegalStateException("Class invariant violation");
        String msg =
                "log4j called after unloading, see http://logging.apache.org/log4j/1.2/faq.html#unload.";
        if (isLikelySafeScenario(ex)) {
            LogLog.debug(msg, ex);
        } else {
            LogLog.error(msg, ex);
        }
    }
    return repositorySelector.getLoggerRepository();
  }

log4j的配置信息是存在一个LoggerRepository对象实例中的。
可是我们调用PropertyConfigurator.configure(logCfgFile)时，并没有新建一个LoggerRepository实例，
而是复用读取默认配置文件生成的LoggerRepository实例！
问题来了，用户指定的配置文件会覆盖掉默认配置文件中共有的配置项，但是如果某个配置项只存在于默认配置文件，
那么就无法覆盖，这个配置信息会一直生效。

4 结论

从以上的分析已经可以得出结论：

PropertyConfigurator.configure(logCfgFile) 无法覆盖默认的配置文件中存在而指定的配置文件中
不存在的配置项。

我认为这是一个bug，至少来说，是不太清晰，容易导致误用。如果用户手动指定了配置文件，为什么还要去读取默认的配置文件，
光是读取也就罢了，当用户手动指定配置文件的时候清除默认配置信息就行了，但是这个清理工作也漏掉了！以至于让笔者花费了
一个下午的时间来调试这个问题。虽然笔者这样的使用场景（内部外部都有log4j配置文件）比较少见，但是，多少还是有一些别的
朋友也遇到过同样的问题把。

5 问题规避

现在我们知道了问题的根源,那么如何规避这个问题呢？
有两种方式。任意一种都可以解决问题。

5.1 不提供默认配置文件

手动指定配置文件时，不要提供log4j默认的配置文件：

resources/log4j.xml 或resources/log4j.properties

笔者删除了resources/log4j.properties文件后，重新运行程序，输出如下：

log4j: Trying to find [log4j.xml] using context classloader sun.misc.Launcher$AppClassLoader@42a57993.
log4j: Trying to find [log4j.xml] using sun.misc.Launcher$AppClassLoader@42a57993 class loader.
log4j: Trying to find [log4j.xml] using ClassLoader.getSystemResource().
log4j: Trying to find [log4j.properties] using context classloader sun.misc.Launcher$AppClassLoader@42a57993.
log4j: Trying to find [log4j.properties] using sun.misc.Launcher$AppClassLoader@42a57993 class loader.
log4j: Trying to find [log4j.properties] using ClassLoader.getSystemResource().
log4j: Could not find resource: [null].
log4j: Parsing for [root] with value=[info,stdout].
log4j: Level token is [info].
log4j: Category root set to INFO
log4j: Parsing appender named "stdout".
log4j: Parsing layout options for "stdout".
log4j: Setting property [conversionPattern] to [%d{ABSOLUTE} %5p %c{1}:%L - %m%n].
log4j: End of parsing for "stdout".
log4j: Setting property [target] to [System.out].
log4j: Parsed "stdout" options.
log4j: Finished configuring.
15:46:01,445  INFO TestDemo:46 - Info message

log4j试图读取默认配置文件，但是没有找到。
程序输出符合预取。

5.2 设置环境变量

在org.apache.log4j.LogManager的静态块中，读取默认配置文件之前，会读取环境变量：

log4j.defaultInitOverride

如果其值为空，或者为"false"，则不会去读取默认配置文件。
那么，我们把这个环境变量的值设为“false”之外的任意非空值即可。
不幸的是，在笔者的Mac上，用java读取不到系统环境变量，google到了一个有点复杂的教程，让人望而却步。
最后笔者使用了一个比较取巧的方式，在java代码中手动设置环境变量。如下：

System.setProperty("log4j.defaultInitOverride", "1");

我们再来看一下输出：

log4j: Default initialization of overridden by log4j.defaultInitOverrideproperty.
log4j: Parsing for [root] with value=[info,stdout].
log4j: Level token is [info].
log4j: Category root set to INFO
log4j: Parsing appender named "stdout".
log4j: Parsing layout options for "stdout".
log4j: Setting property [conversionPattern] to [%d{ABSOLUTE} %5p %c{1}:%L - %m%n].
log4j: End of parsing for "stdout".
log4j: Setting property [target] to [System.out].
log4j: Parsed "stdout" options.
log4j: Finished configuring.
15:57:13,364  INFO TestDemo:49 - Info message

因为设置了环境变量，log4j不再试图读取默认配置文件。
程序输出符合预期。

最后编辑于 ：
©著作权归作者所有,转载或内容合作请联系作者
  • 人面猴
    序言：七十年代末，一起剥皮案震惊了整个滨河市，随后出现的几起案子，更是在滨河造成了极大的恐慌，老刑警刘岩，带你破解...
    沈念sama阅读 212,686评论 6赞 492
  • 死咒
    序言：滨河连续发生了三起死亡事件，死亡现场离奇诡异，居然都是意外死亡，警方通过查阅死者的电脑和手机，发现死者居然都...
    沈念sama阅读 90,668评论 3赞 385
  • 救了他两次的神仙让他今天三更去死
    文/潘晓璐 我一进店门，熙熙楼的掌柜王于贵愁眉苦脸地迎上来，“玉大人，你说我怎么就摊上这事。” “怎么了？”我有些...
    开封第一讲书人阅读 158,160评论 0赞 348
  • 道士缉凶录：失踪的卖姜人
    文/不坏的土叔 我叫张陵，是天一观的道长。 经常有香客问我，道长，这世上最难降的妖魔是什么？ 我笑而不...
    开封第一讲书人阅读 56,736评论 1赞 284
  • 港岛之恋（遗憾婚礼）
    正文 为了忘掉前任，我火速办了婚礼，结果婚礼上，老公的妹妹穿的比我还像新娘。我一直安慰自己，他们只是感情好，可当我...
    茶点故事阅读 65,847评论 6赞 386
  • 恶毒庶女顶嫁案：这布局不是一般人想出来的
    文/花漫 我一把揭开白布。 她就那样静静地躺着，像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上，一...
    开封第一讲书人阅读 50,043评论 1赞 291
  • 城市分裂传说
    那天，我揣着相机与录音，去河边找鬼。 笑死，一个胖子当着我的面吹牛，可吹牛的内容都是我干的。 我是一名探鬼主播，决...
    沈念sama阅读 39,129评论 3赞 410
  • 双鸳鸯连环套：你想象不到人心有多黑
    文/苍兰香墨 我猛地睁开眼，长吁一口气：“原来是场噩梦啊……” “哼！你这毒妇竟也来了？” 一声冷哼从身侧响起，我...
    开封第一讲书人阅读 37,872评论 0赞 268
  • 万荣杀人案实录
    序言：老挝万荣一对情侣失踪，失踪者是张志新（化名）和其女友刘颖，没想到半个月后，有当地人在树林里发现了一具尸体，经...
    沈念sama阅读 44,318评论 1赞 303
  • 护林员之死
    正文 独居荒郊野岭守林人离奇死亡，尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 36,645评论 2赞 327
  • 白月光启示录
    正文 我和宋清朗相恋三年，在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 38,777评论 1赞 341
  • 活死人
    序言：一个原本活蹦乱跳的男人离奇死亡，死状恐怖，灵堂内的尸体忽然破棺而出，到底是诈尸还是另有隐情，我是刑警宁泽，带...
    沈念sama阅读 34,470评论 4赞 333
  • 日本核电站爆炸内幕
    正文 年R本政府宣布，位于F岛的核电站，受9级特大地震影响，放射性物质发生泄漏。R本人自食恶果不足惜，却给世界环境...
    茶点故事阅读 40,126评论 3赞 317
  • 男人毒药：我在死后第九天来索命
    文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹，春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 30,861评论 0赞 21
  • 一桩弑父案，背后竟有这般阴谋
    文/苍兰香墨 我抬头看了看天上的太阳。三九已至，却和暖如春，着一层夹袄步出监牢的瞬间，已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 32,095评论 1赞 267
  • 情欲美人皮
    我被黑心中介骗来泰国打工， 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留，地道东北人。 一个月前我还...
    沈念sama阅读 46,589评论 2赞 362
  • 代替公主和亲
    正文 我出身青楼，却偏偏与公主长得像，于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子，可洞房花烛夜当晚...
    茶点故事阅读 43,687评论 2赞 351