有趣的bug——Java静态变量的循环依赖

2022-10-19 16:40:41

背景

是的，标题没有错误，不是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.cmiot.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后缀，表明日志应用无法获取此属性对应的具体数值。后续的问题就集中于，为什么日志应用无法读取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);
    }
}

讲原理大家可能不太容易理解，此处就通过*上的例子进行讲解。这个代码如果写在实际的工程中，可能会被打的很惨(是的，前面的问题确实很愚蠢)，不过很容易看出来类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:
如果您觉得我的文章对您有帮助，请关注我的微信公众号，谢谢!
有趣的bug——Java静态变量的循环依赖

上一篇：Excel实现下拉筛选


下一篇：WPS合并单元格如何实现组内编号