bootstrap.yml配置丢失问题

1,411 阅读5分钟

问题现象

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

项目的结构是spring-boot项目,有引入spring-cloud组件。 image.png

日志相关配置放在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配置文件初始化的。 image.png 然后再初始化Application Context,可以看出它和Bootstrap Context确实是父子上下文。 image.png

再看下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的配置也被获取了两遍,一遍有值一遍没值。 image.png image.png 只知道是取不到配置值,但是不知道为什么,代码层次太深了,没有头绪了。

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

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

于是我回到上一步断点调试的地方,把去掉和不去掉的两种情况做一个比较,发现有个地方是不一样的: image.png image.png 这个defaultProperties一个有值一个没值,而bootstrap.yml的配置就在这里面。

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

继续走,发现这里会把父上下文的配置合并进来: image.png

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

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

解决方案

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

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

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

jasypt:
  encryptor:
    bootstrap: false