美文网首页
log4j外部配置文件失效问题

log4j外部配置文件失效问题

作者: EvilDjango | 来源:发表于2019-05-02 16:30 被阅读0次

    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不再试图读取默认配置文件。
    程序输出符合预期。

    相关文章

      网友评论

          本文标题：log4j外部配置文件失效问题

          本文链接：https://www.haomeiwen.com/subject/zpinnqtx.html

          延伸阅读

          深度阅读

          • 您也可以注册成为美文阅读网的作者，发表您的原创作品、分享您的心情！

          栏目导航

          热点阅读

          关于我们|服务条款|联系我们|log4j外部配置文件失效问题|投稿指南|网站地图|RSS订阅|排版工具|手机版

          提供经典美文摘抄,优美散文欣赏,现代诗歌精选,短篇小说,心情随笔,表白情书范文,故事会在线阅读欣赏

          Copyright © 2014-2023 Haomeiwen.com All Rights Reserved. 好美文阅读网 版权所有

          备案信息：桂公网安备 45052102000051号 · 桂ICP备13007215号-3

          本站所收录作品、热点评论等信息部分来源互联网，目的只是为了系统归纳学习和传递资讯

          所有作品版权归原创作者所有，与本站立场无关，如不慎侵犯了你的权益，请联系我们告知，我们将做删除处理！