bootstrap.yml配置丢失问题

问题现象

同事反馈他的工程启动的时候会建两个日志目录，其中一个名称是log.base_IS_UNDEFINED

项目的结构是spring-boot项目，有引入spring-cloud组件。

日志相关配置放在bootstrap.yml中

logging:
  appLevel: info
  path: ${LOG_PATH:logs/}
复制代码

logback-spring.xml配置如下

<configuration scan="true" scanPeriod="30 seconds">
    <include resource="org/springframework/boot/logging/logback/defaults.xml"/>
    <include resource="org/springframework/boot/logging/logback/console-appender.xml"/>

    <springProperty scope="context" name="log.base" source="logging.path"/>
    <springProperty scope="context" name="logLevel" source="logging.appLevel"/>
    <springProperty scope="context" name="log.additivity" source="logging.additivity"/>

    <include resource="logback-core.xml" />

    <root level="${logLevel}">
        <appender-ref ref="other"/>
    </root>
</configuration>
复制代码

原因分析

一、初步分析

之前遇到过几次类似的问题，一种情况是日志配置放在application.yml里，由于引入了spring-cloud，spring-cloud会创建一个Bootstrap Context，作为Spring应用的Application Context的父上下文。

Bootstrap Context读取的是写在bootstrap.yml中的配置，由于日志配置被写到application.yml里，所以无法读取到相关配置，这种情况只需要把配置移到bootstrap.yml里就行了。使用logback莫名出现 IS_UNDEFINED 日志目录

现在遇到的是第二种情况，日志配置已经放到了bootstrap.yml里，这种无论配置放哪边都不行。但是经过测试，两个配置文件同时配置上可以解决这个问题。但是这样的处理方式不优雅，掩盖了实际问题。

二、详细分析

初步怀疑是spring-cloud上下文影响，所以我尝试把spring-cloud去掉看看效果。pom.xml中跟spring-cloud相关的组件只有这个，把它注释掉。

<dependency>
    <groupId>org.springframework.cloud</groupId>
    <artifactId>spring-cloud-context</artifactId>
</dependency>
复制代码

由于去掉了spring-cloud组件，bootstrap.yml的配置不会被读取，把里面的配置移到application.yml，启动后确实不会产生log.base_IS_UNDEFINED。

根据spring上下文的设计，子上下文是可以读到父上下文的配置，所以写在bootstral.yml的配置，应该都能获取到的，先看下它们到底是不是父子上下文。参考：Spring Cloud 中的 Bootstrap 上下文

找到SpringApplication类调试run方法，查看spring上下文初始化过程：

首先是初始化Bootstrap Context，是通过读取bootstrap.yml配置文件初始化的。

然后再初始化Application Context，可以看出它和Bootstrap Context确实是父子上下文。

再看下logback为什么没有获取到配置。

为了方便排查，把logback的调试模式打开：

<configuration scan="true" scanPeriod="30 seconds" debug="true">
    ...
</configuration>
复制代码

从logback调试日志可以看出，logback初始化了两次，一次是可以取到配置值，一次是取不到。这是因为两套spring上下文各自初始化日志组件，这是正常现象，现在看看第二次为什么没有取到配置值。

-- 第一次加载
10:02:10,904 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [access]
10:02:10,912 |-INFO in c.q.l.core.rolling.TimeBasedRollingPolicy@1115420993 - No compression will be used
10:02:10,914 |-INFO in c.q.l.core.rolling.TimeBasedRollingPolicy@1115420993 - Will use the pattern logs//access/access.log.%d{yyyy-MM-dd-HH}.%i for the active file
10:02:10,915 |-INFO in ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP@26b1ded0 - The date pattern is 'yyyy-MM-dd-HH' from file name pattern 'logs//access/access.log.%d{yyyy-MM-dd-HH}.%i'.
10:02:10,915 |-INFO in ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP@26b1ded0 - Roll-over at the top of every hour.
10:02:10,917 |-INFO in ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP@26b1ded0 - Setting initial period to Fri May 14 09:50:35 CST 2021
10:02:10,918 |-WARN in ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP@26b1ded0 - SizeAndTimeBasedFNATP is deprecated. Use SizeAndTimeBasedRollingPolicy instead
10:02:10,918 |-WARN in ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP@26b1ded0 - For more information see http://logback.qos.ch/manual/appenders.html#SizeAndTimeBasedRollingPolicy
10:02:10,919 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
10:02:10,921 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[access] - Active log file name: logs//access/access.log
10:02:10,921 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[access] - File property is set to [logs//access/access.log]
 
-- 第二次加载 
10:02:11,325 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [access]
10:02:11,325 |-INFO in c.q.l.core.rolling.TimeBasedRollingPolicy@620091520 - No compression will be used
10:02:11,326 |-INFO in c.q.l.core.rolling.TimeBasedRollingPolicy@620091520 - Will use the pattern log.base_IS_UNDEFINED/access/access.log.%d{yyyy-MM-dd-HH}.%i for the active file
10:02:11,326 |-INFO in ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP@7d573a89 - The date pattern is 'yyyy-MM-dd-HH' from file name pattern 'log.base_IS_UNDEFINED/access/access.log.%d{yyyy-MM-dd-HH}.%i'.
10:02:11,326 |-INFO in ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP@7d573a89 - Roll-over at the top of every hour.
10:02:11,326 |-INFO in ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP@7d573a89 - Setting initial period to Fri May 14 09:51:52 CST 2021
10:02:11,326 |-WARN in ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP@7d573a89 - SizeAndTimeBasedFNATP is deprecated. Use SizeAndTimeBasedRollingPolicy instead
10:02:11,326 |-WARN in ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP@7d573a89 - For more information see http://logback.qos.ch/manual/appenders.html#SizeAndTimeBasedRollingPolicy
10:02:11,326 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
10:02:11,327 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[access] - Active log file name: log.base_IS_UNDEFINED/access/access.log
10:02:11,327 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[access] - File property is set to [log.base_IS_UNDEFINED/access/access.log]
复制代码

根据这行日志10:02:11,327 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[access] - Active log file name: log.base_IS_UNDEFINED/access/access.log

找到TimeBasedRollingPolicy类，打上断点调试，跟踪到是在SpringPropertyAction类里获取配置的，同样的，logback的配置也被获取了两遍，一遍有值一遍没值。


只知道是取不到配置值，但是不知道为什么，代码层次太深了，没有头绪了。

这个时候同事发现把jasypt-spring-boot-starter的引用去掉就没问题了。

<dependency>
    <groupId>com.github.ulisesbocchio</groupId>
    <artifactId>jasypt-spring-boot-starter</artifactId>
    <version>2.1.1</version>
</dependency>
复制代码

于是我回到上一步断点调试的地方，把去掉和不去掉的两种情况做一个比较，发现有个地方是不一样的：


这个defaultProperties一个有值一个没值，而bootstrap.yml的配置就在这里面。

继续跟踪代码，发现走到这个类BootstrapApplicationListener的mergeDefaultProperties方法，看方法名应该跟上面defaultProperties没有值相关。

继续走，发现这里会把父上下文的配置合并进来：

继续看result.add()里的一个判断条件，引用jasypt-spring-boot-starter后判断是false，没有引用则是true。

所以可以判断出是jasypt-spring-boot-starter包改变了PropertySource的类型，导致配置合并失败。

解决方案

这个问题其实引用jasypt-spring-boot-starter导致bootstrap.yml配置被清除，表现虽然只是多创建了日志目录，但是可能会产生更大的问题，因为bootstrap.yml中的配置在应用上下文中无法获取，如果里面有关键配置，要排查问题将会变得很困难。

github有相关问题的解决方案：通过starter集成后bootstrap里的配置会被清除

在bootstrap.yml中加入以下配置：

jasypt:
  encryptor:
    bootstrap: false
复制代码