有趣的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:
如果您觉得我的文章对您有帮助，请关注我的微信公众号，谢谢!
