一次日志配置未生效问题排查记录

某天排查业务问题时,在我司的日志收集平台上,未能发现相关业务服务接口访问日志。经过和相关同事确定,发现业务服务未能将接口访问日志吐到日志收集平台,由此开启一段有点漫长的排查之旅。

业务服务是典型的SpringBoot web应用，日志记录采用slf4j+log4j2组合。

通过application.propertis文件中logging.config配置项指定了日志配置文件log4j2.xml具体位置。

通过实现org.apache.logging.log4j.core.Appender接口实现自定义的HttpAppender,将接口访问记录发送到日志收集平台。在log4j2.xml配置文件里如下图

具体管理与日志收集平台服务连接,发送请求的是类HttpManager,HttpManager的属性url决定了接收日志信息的日志收集平台地址(来源是配置文件中HttpAppender的url属性)。

所有HttpAppender对象共享同一个HttpManager,按照单例模式创建,合理的做法应是每个HttpAppender有自己单独的HttpManager。

这会导致在有配置多个HttpAppender的情况下,只有在实例化第一个HttpAppender时，其配置的日志平台收集服务的地址会生效。其他的通通无效.

合理的办法是改动HttpAppender源代码,但是我没权限。只能从日志配置文件加载方面想办法,想办法让我们指定的日志配置文件生效。

基本情况介绍完毕,下面开始排查之旅。

在和同事确定之后没有讲日志信息发送到日志收集平台,凭直觉猜测日志收集平台地址是否正确。检查日志配置文件,发现地址配置正确。难道就这样结束了？不，你已经是一个成熟的程序员了，要学会自己排查问题了。

遇到这种情况时,我看了一下其他服务，相同的配置,却稳定正常的向日志收集平台在发送日志。那我就有理由猜测线上服务实际生效的日志收集平台地址不是我们想要的,但是如何验证了。

我们如何方便的可以查看线上服务某个类对象的字段值了,那就要亮出大杀器了，阿里巴巴开源的Arthas。使用arthas的vmtool命令查看jvm进程中的实例对象数据

看到的结果让人始料未及,线上服务使用的是日志收集平台的测试地址。现在问题变成了,是什么原因导致了线上加载了错误的配置。

在idea中全局搜索发现,在resources目录下的log4j2.xml中,含有相同的HtppAppender,url属性配置成了日志收集平台的测试地址，maven打包之后,业务jar中也会含有log4j2.xml文件。

那接下来要验证的是jar包里的log4j2.xml是否被加载,如果被加载,这样算下来就会有两份位置不同log42.xml文件被加载。

接下来就是如何进行验证了。

思路是如果加载了两份不同的位置的log4j2.xml,那么创建HttpAppender的方法就会被调用两次,如果能追踪到创建HttpAppender方法的被调用路径,那么排查起来就会轻松些了.

这次还是借助Arthas,通过其stack命令,可以查看指定方法被调用的调用路径。

因为SpringBoot应用一起动,便会在SpringApplication的prepareEnvironment方法里触发日志配置文件加载,等我通过Arthas attach到指定的jvm进程,执行stack命令的时候,日志配置加载已经结束了,为时已晚。

解决办法是通过在启动类的main方法里加上一行代码TimeUnit.SECONDS.sleep(30) 延迟应用的启动,以便有足够的时候通过Arthas attach到jvm进程,执行stack命令。结果如下两张图

通过上面这两张图得知,在LoggingApplicationListener正常加载日志配置文件之前，BootStrapApplicationListener触发LoggingApplicationListener做了一次日志配置文件加载。

接下来需要分析的是由BootStrapApplicationListener触发加载的是哪个日志配置文件。

通过分析BootStrapApplicationListener的bootstrapServiceContext方法,其新建的SpringApplication实例对象,读取的默认配置文件为bootstrap.yml。因为项目并没有配置bootstrap.yml,导致ConfigFileApplicationListener对Environment进行初始化时,没有设置logging.config。

没有设置logging.config 那ConfigFileApplicationListener是从哪里加载日志配置文件了。通过分析代码，默认的日志配置加载文件位置由org.springframework.boot.logging.AbstractLoggingSystem#getSelfInitializationConfig方法负责,如下图

通过上图可得知主要检测classpath里是否存在log4j2.xml，logj4j2.json这样的配置文件。不巧的是服务的jar里存在log4j2.xml,且配置的url是日志收集平台的测试地址。那要如何解决了这个问题了。

通过分析BootStrapApplicationListener源代码,通过在启动脚本里启动命令中添加-Dspring.cloud.bootstrap.enabled=false来禁止BootstrapApplicationListener运行.

修改完毕，再次执行vmtool命令检查日志收集平台url配置是否正确。结果显示的还是日志收集平台测试地址。那说明还有其他地方触发加载了jar包内的log4j2.xml文件。

此时瞥了一眼我们的启动类,那么大一个Logger在那杵着,之前愣是没注意。

启动类xxxApplication被加载的时候,此时会触发LOGGER的创建,虽然使用的是SLF4J,实际上创建的是log4j2的Logger,由此会触发针对日志配置文件的加载，经过google搜索,和针对log4j的源码分析,如果没有指定配置文件,默认是会加载classpath下的log4j2.xml文件。

 此时想到的简单办法是把LOGGER属性注释掉,那么就会避免发生记在jar包内的log4j2.xml文件,从而只加载服务目录下的log4j2.xml。

修改完毕,进行第二次验证。不巧的是，显示的还是日志收集平台测试地址,那说明还是有其他地方触发加载了jar包内的log4j2.xml文件。

此时我们的办法还是和第一次内似,这次我们用的是watch命令，关注的是org.slf4j.LoggerFactory getLogger方法的被调用的时候入参。

通过上图,发现工程依赖的公司封装的Apollo配置服务的jar包内的ApolloApplicationContextInitializer触发了Logger的创建，进而触发加载了jar包内的log4j2.xml。

那这个ApolloApplicationContextInitializer是因为什么原因被触发了class加载,导致了Logger的创建。通过查看源码,ApolloApplicationContextInitializer实现了ApplicationListener接口。SpringApplication在构造函数中会收集当前classpath的spring.factories文件中org.springframework.context.ApplicationListener配置项中的Listener,并实例化。因此导致了ApolloApplicationContextInitializer类的初始化。

到此我们可以做一下总结,业务程序的启动过程中,按先后顺序总共做了三次日志配置文件log4j2.xml的加载。

第一次：由程序启动类XXXApplication的静态属性LOGGER触发,加载的是业务jar包内log4j2.xml。

第二次:  由org.springframework.cloud.bootstrap.BootstrapApplicationListener触发,加载的是业务jar包内log4j2.xml

第三次:  由LoggingApplicationListener负载加载application.properties指定的服务目录下的logj42.xml。

---

至此，问题的分析与排查可暂时告一段落,接下来的就是如何修复问题,然后进行验证。办法就两条,

1.减少日志配置文件的加载的次数,

2.让log4j2框架第一次加载日志配置文件时，便加载到正确的日志配置文件。

办法1. 通过在服务启动脚本中加入-Dspring.cloud.bootstrap.enable=false,可以避免上面提到的第二次日志文件加载。

办法2. 通过分析lo4j2源代码,在org.apache.logging.log4j.core.config.ConfigurationFactory类中可以发现通过设置名为log4j.configurationFile的sytem property指定要加载的日志配置文件。

---

 方法都已找到,解决方法如下图所示,综合了前面提到的两条办法。

经过验证,问题得到解决,接口访问日志顺利吐到日志收集平台。一个问题的解决之旅也就此结束。

其实事后总结,还是基础不够扎实,对日志框架的了解掌握不够深入，排查分析问题不够仔细，对启动类存在的Logger熟视无睹,由此忽略了带来的日志配置加载问题。