zoukankan      html  css  js  c++  java
  • 有趣的bug——Java静态变量的循环依赖

    背景

    是的,标题没有错误,不是Spring Bean的循环依赖,而是静态变量之间的循环依赖。
    近期的项目均是简单的Maven项目,通过K8S部署在阿里云上,其配置文件读取规则如下所示:

    (1) 优先读取应用部署同层目录下的配置文件;
    (2) 如果没有外部配置文件,则读取打包至jar包中的配置文件。

    在部署的过程中,发现应用无法争取读取外部配置文件中的配置信息,坚持不懈的读取打包文件中的。

    日志文件配置错误

    <?xml version="1.0" encoding="UTF-8"?>
    <configuration scan="true" scanPeriod="60 seconds" debug="false">
        <contextName>external-portal-inspector</contextName>
        <property name="LOG_PATH" value="./logs"/>
        <property resource="application.properties"/>
        <define name="application.system" class="com.eqos.network.config.LogSystemParamDefiner"/>
        <define name="application.region" class="com.eqos.network.config.LogRegionParamDefiner"/>
        <define name="application.platform" class="com.eqos.network.config.LogPlatformParamDefiner"/>
        <property name="log.pattern" value='{
                            "date":"%date{\"yyyy-MM-dd HH:mm:ss.SSS\",UTC}",
                            "level":"%level",
                            "system":"${application.system}",
                            "platform":"${application.platform}",
                            "region":"${application.region}",
                            "filepath":"%class:%line",
                            "msg":"%msg"
                            }'/>
        
        <!--输出到控制台-->
        <appender name="console" class="ch.qos.logback.core.ConsoleAppender">
            <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
                <level>
                    DEBUG
                </level>
            </filter>
            <encoder class="net.logstash.logback.encoder.LoggingEventCompositeJsonEncoder">
                <providers class="net.logstash.logback.composite.loggingevent.LoggingEventJsonProviders">
                    <pattern>
                        <pattern>
                            ${log.pattern}
                        </pattern>
                    </pattern>
                </providers>
                <charset>UTF-8</charset>
            </encoder>
        </appender>
    </configuration>
    

    截取部分日志配置,日志格式定义为json格式,其中system,level以及platform参数是在程序运行时进行获取的(通过logback.xml文件中定义的${application.system},${application.region},${application.platform},这几个参数后面定义了相关的类,应用在写日志时会调用相关类接口获取对应参数信息)。但是此时遇到问题,无论如何修改外部配置文件,日志均是读取Jar包中配置文件信息,在com.eqos.network.config.LogSystemParamDefiner类中打断点,发现程序未进入此类获取system信息。以下是application.properties文件中的配置信息。

    application.platform=chongqing
    application.region=HUADONG
    application.system=network
    

    生成日志信息如下所示:

    {"date":"2019-11-14 01:48:42.695","level":"INFO","system":"network","platform":"chongqing","region":"HUADONG","filepath":"com.eqos.network.service.TcpProbeService$1$1:78","msg":"{"tags":{"namespace":"oneNet.service.TCP.echo","metric.time-delay":24,"metric.correct":true}}"}
    

    简单对照一下配置文件,就会发现日志中使用${application.system},这与配置文件中的配置key值重名,会不会是日志程序在无法通过接口获取应用配置信息后,直接从Jar包内的配置文件中读取同名配置属性。针对此,修改logback.xml中的相关配置,如下所示:

        <define name="system" class="com.eqos.network.config.LogSystemParamDefiner"/>
        <define name="region" class="com.eqos.network.config.LogRegionParamDefiner"/>
        <define name="platform" class="com.eqos.network.config.LogPlatformParamDefiner"/>
        <property name="log.pattern" value='{
                            "date":"%date{\"yyyy-MM-dd HH:mm:ss.SSS\",UTC}",
                            "level":"%level",
                            "system":"${system}",
                            "platform":"${platform}",
                            "region":"${region}",
                            "filepath":"%class:%line",
                            "msg":"%msg"
                            }'/>
    

    修改如上所示,去除application前缀,重新启动程序:

    {"date":"2019-11-14 01:54:24.486","level":"INFO","system":"system_IS_UNDEFINED","platform":"platform_IS_UNDEFINED","region":"region_IS_UNDEFINED","filepath":"com.eqos.network.service.TcpProbeService$1$1:78","msg":"{"tags":{"namespace":"oneNet.service.TCP.echo","metric.time-delay":33,"metric.correct":true}}"}
    {"date":"2019-11-14 01:54:24.546","level":"INFO","system":"system_IS_UNDEFINED","platform":"platform_IS_UNDEFINED","region":"region_IS_UNDEFINED","filepath":"com.eqos.network.service.UdpProbeService$1:87","msg":"{"tags":{"namespace":"oneNet.service.UDP.echo","metric.time-delay":5,"metric.correct":true}}"}
    

    美妙的事情发生了,去除了前缀后,日志应用就无法从Jar包内的配置文件读取同名的属性信息了,日志中的system显示为system_IS_UNDEFINED,此处带上了_IS_UNDEFINED后缀,表明日志应用无法获取此属性对应的具体数值。
    进一步检查日志配置文件,发现从配置文件读取属性是因为配置了以下属性:<property resource="application.properties"/>
    后续的问题就集中于,为什么日志应用无法读取com.eqos.network.config.LogSystemParamDefiner通过接口提供的属性信息呢?

    静态变量循环依赖

    抽丝剥茧

    以下为com.eqos.network.config.LogSystemParamDefiner的相关代码,其继承于logabck提供的PropertyDefinerBase抽象类,当应用启动时,logback就会调用实现此抽象类的对象,获取属性的具体数值。

    public class LogSystemParamDefiner extends PropertyDefinerBase {
    
        @Override
        public String getPropertyValue() {
            return AppConfig.INSTANCE.getConfigInfoMap().getOrDefault("application.system", "UNKNOWN");
        }
    }
    
    @Slf4j
    public class AppConfig {
    
        public static final AppConfig INSTANCE = new AppConfig();
    
        private final ConcurrentHashMap<String, String> configInfoMap = new ConcurrentHashMap<>(16);
    
        private AppConfig() {
            // 读取配置文件中属性,相关代码非重点,因此省略
            initApplicationConfig();
        }
    
        public ConcurrentHashMap<String, String> getConfigInfoMap() {
            return configInfoMap;
        }
    }
    

    由以上代码可以看出,LogSystemParamDefiner类较为简单,其依赖于AppConfig类的单例对象。AppConfig类也很简单,通过静态变量实现单例(当前应用程序就不考虑反射或者序列化破坏单例了)。那就只能打断点跟进,看看究竟是什么原因 导致无法读取system属性,按理说此处就算无法正确读取到system属性值,也会使用UNKNOWN值进行替代。
    打断点进入程序,发现在启动阶段进入LogSystemParamDefiner.getPropertyValue方法,尴尬的事情发生了,此时AppConfig.INSTANCE为null(是的,java中的绝大多数问题都是NPE,此处就不计较为什么NPE被吞了)。这是为什么呢,按理说静态单例里应该在AppConfig类进行加载的时候,就创建相应的静态变量对象,不应该为空。

    探寻究竟

    现在问题很简单,就是为什么AppConfig的单例类初始化失败呢?通过有限的编程经验来说,应该是发生循环依赖了,而且这个循环依赖必然是发生在日志单例和AppConfig单例之间(logback的实现肯定是单例,我想不到它不是单例的理由)。
    检查AppConfig代码,其实主要就是检查import引入的依赖项,代码如下所示:

    import lombok.extern.slf4j.Slf4j;
    
    import java.io.File;
    import java.io.FileInputStream;
    import java.io.IOException;
    import java.io.InputStream;
    import java.util.Properties;
    import java.util.concurrent.ConcurrentHashMap;
    

    问题已很明显了,只有Slf4j与日志相关,应该就是它引入了对logback单例的依赖。检查AppConfig代码,发现虽然未使用到日志类,但是在类上存在@Slf4j注解。现在去除@Slf4j注解,再次进行试验发现,代码再次进入LogSystemParamDefiner.getPropertyValue方法时,AppConfig.INSTANCE已经完成了初始化操作,输出日志也正常加载外部配置文件的相关信息。

    举个例子

    class A
    {
        public static int X;
        static { X = B.Y + 1;}
    }
    public class B
    {
        public static int Y = A.X + 1;
        static {}
        public static void main(String[] args) {
            System.out.println("X = "+A.X+", Y = "+B.Y);
        }
    }
    

    讲原理大家可能不太容易理解,此处就通过stackoverflow上的例子进行讲解。这个代码如果写在实际的工程中,可能会被打的很惨(是的,前面的问题确实很愚蠢),不过很容易看出来类A与类B中的静态变量存在循环依赖。

    以下讲解此程序的执行顺序:

    (1) 主线程执行main函数吗,class loader加载类B;
    (2) 加载类B时,初始化静态变量B.Y;
    (3) B.Y依赖于A.X,因此class loader加载类A;
    (4) 加载类B时,初始化静态变量A.X,A.X依赖于B.Y;
    (5) 此时B尚未加载完全,因此B.Y数值为0(如果B.Y为Object,则对应数值为null),所以A.X数值为1;
    (6) 返回类B继续执行B.Y的初始化操作,因为A.X=1,因此B.Y数值为2;
    (7) 类A与类B的初始化完成,A.X=1,B.Y=2。

    以上代码能够得到具体数值,这是因为java对于基本类型以及对象类型均会赋予初始化数值。如果换成C++,在UB的指引下,会出现什么那就真的不得而知了。

    PS:
    如果您觉得我的文章对您有帮助,请关注我的微信公众号,谢谢!
    程序员打怪之路

  • 相关阅读:
    【结对编程收获】
    【第二次个人作业】结对作业Core第一组:四则运算生成PB16061082+PB16120517
    【第七周读书笔记】读《计算机系统详解》
    【第五周课堂作业】创新案例分析
    【第六周读书笔记】计算机体系结构读后感
    个人总结——马睿淳
    团队项目心得(6.15)
    团队项目心得
    《代码大全》读书笔记——第九周
    《我是一只IT小小鸟》(续)读书笔记——第八周
  • 原文地址:https://www.cnblogs.com/jason1990/p/11856296.html
Copyright © 2011-2022 走看看