We have a Spring Boot 2.4.3 application that uses custom logging.level.pattern defined in a bootstrap.yml.
It works only for a few log lines until configuration is fetched from the config server and then it's overriden by the default pattern provided by Sleuth.
%5p [${spring.zipkin.service.name:" + "${spring.application.name:}},%X{traceId:-},%X{spanId:-}]
I have seen a similar issue here https://github.com/spring-projects/spring-boot/issues/24835, but upgrading our app to 2.4.3 didn't help with this.
This used to work in 2.4.1. The current workaround we found is to add the pattern override to application.yml instead or to have custom logback-spring.xml on the classpath.
Comment From: wilkinsona
Thanks for the report. Unless you are deploying multiple applications in the same JVM, #24835 shouldn't be related to this, although you may have been relying on the buggy behaviour that meant that the first context's pattern would be reused by every subsequent context.
To help us to investigate the cause, can you please provide a minimal sample that works with 2.4.1 and fails with 2.4.3?
Comment From: artemy
https://github.com/artemy/spring-logging-sleuth-override here it is
first start config-server app from dev/config-server module and then the application itself app from app
Example startup output with 2.4.1:
2021-02-25 18:15:49.442 INFO [traceid= spanid= parentspanid=] 52736 --- [ main] c.c.c.ConfigServicePropertySourceLocator : Fetching config from server at : http://localhost:8888
2021-02-25 18:15:49.751 INFO [traceid= spanid= parentspanid=] 52736 --- [ main] c.c.c.ConfigServicePropertySourceLocator : Located environment: name=spring-logging-sleuth-override, profiles=[default], label=null, version=null, state=null
2021-02-25 18:15:49.752 INFO [traceid= spanid= parentspanid=] 52736 --- [ main] b.c.PropertySourceBootstrapConfiguration : Located property source: [BootstrapPropertySource {name='bootstrapProperties-configClient'}, BootstrapPropertySource {name='bootstrapProperties-class path resource [spring-logging-sleuth-override.yml'}, BootstrapPropertySource {name='bootstrapProperties-Config resource 'class path resource [application.yml]' via location 'classpath:/' (document #0)'}]
2021-02-25 18:15:49.771 INFO [traceid= spanid= parentspanid=] 52736 --- [ main] c.g.a.s.app.MyAwesomeApplication : The following profiles are active: native
2021-02-25 18:15:52.187 INFO [traceid= spanid= parentspanid=] 52736 --- [ main] c.g.a.s.app.MyAwesomeApplication : Started MyAwesomeApplication in 3.791 seconds (JVM running for 4.226)
2021-02-25 18:15:55.493 INFO [traceid=dfea7f911bd82f20 spanid=dfea7f911bd82f20 parentspanid=] 52736 --- [nio-8080-exec-1] c.g.a.s.app.web.ExampleController : Received HTTP request
Output from 2.4.3:
2021-02-25 18:17:58.600 INFO [traceid= spanid= parentspanid=] 53061 --- [ main] c.c.c.ConfigServicePropertySourceLocator : Fetching config from server at : http://localhost:8888
2021-02-25 18:17:58.776 INFO [traceid= spanid= parentspanid=] 53061 --- [ main] c.c.c.ConfigServicePropertySourceLocator : Located environment: name=spring-logging-sleuth-override, profiles=[default], label=null, version=null, state=null
2021-02-25 18:17:58.777 INFO [traceid= spanid= parentspanid=] 53061 --- [ main] b.c.PropertySourceBootstrapConfiguration : Located property source: [BootstrapPropertySource {name='bootstrapProperties-configClient'}, BootstrapPropertySource {name='bootstrapProperties-class path resource [spring-logging-sleuth-override.yml'}, BootstrapPropertySource {name='bootstrapProperties-Config resource 'class path resource [application.yml]' via location 'classpath:/' (document #0)'}]
2021-02-25 18:17:58.803 INFO [spring-logging-sleuth-override,,] 53061 --- [ main] c.g.a.s.app.MyAwesomeApplication : The following profiles are active: native
2021-02-25 18:18:01.312 INFO [spring-logging-sleuth-override,,] 53061 --- [ main] c.g.a.s.app.MyAwesomeApplication : Started MyAwesomeApplication in 3.807 seconds (JVM running for 4.259)
2021-02-25 18:18:02.562 INFO [spring-logging-sleuth-override,37b744fc62641b99,37b744fc62641b99] 53061 --- [nio-8080-exec-1] c.g.a.s.app.web.ExampleController : Received HTTP request
Comment From: wilkinsona
Thanks, @artemy. I've reproduced the behaviour that you have described.
The behaviour that you preferred appears to be specific to 2.4.0 and 2.4.1. 2.3.x and 2.4.2+ all use the configuration from Sleuth. In other words, I think the bug introduced in 2.4.0 (https://github.com/spring-projects/spring-boot/issues/23767) and fixed in 2.4.2 (https://github.com/spring-projects/spring-boot/issues/24835) was advantageous to you. We'll need to see if there's something else that we can do here or on Sleuth to stop it from overriding your explicitly configured logging.pattern.level.
Comment From: wilkinsona
Adding the actuator to the app and looking at the config props endpoint, we can see that the property source that contains Sleuth's configuration has higher precedence than the source the contains the bootstrap configuration. The following output is from 2.4.2:
{
"activeProfiles": [
"native"
],
"property": {
"source": "defaultProperties",
"value": "%5p [spring-logging-sleuth-override,%X{traceId:-},%X{spanId:-}]"
},
"propertySources": [
{
"name": "server.ports"
},
{
"name": "bootstrapProperties-configClient"
},
{
"name": "bootstrapProperties-class path resource [spring-logging-sleuth-override.yml"
},
{
"name": "bootstrapProperties-Config resource 'class path resource [application.yml]' via location 'classpath:/' (document #0)"
},
{
"name": "servletConfigInitParams"
},
{
"name": "servletContextInitParams"
},
{
"name": "systemProperties"
},
{
"name": "systemEnvironment"
},
{
"name": "random"
},
{
"name": "springCloudClientHostInfo"
},
{
"name": "Config resource 'class path resource [application.properties]' via location 'optional:classpath:/'"
},
{
"name": "defaultProperties",
"property": {
"value": "%5p [spring-logging-sleuth-override,%X{traceId:-},%X{spanId:-}]"
}
},
{
"name": "Config resource 'class path resource [bootstrap.yml]' via location 'optional:classpath:/'",
"property": {
"origin": "class path resource [bootstrap.yml] - 3:24",
"value": "%clr(%5p) %clr([traceid=%X{traceId:-} spanid=%X{spanId:-} parentspanid=%X{parentId:-}]){green}"
}
},
{
"name": "springCloudDefaultProperties"
},
{
"name": "cachedrandom"
},
{
"name": "Management Server"
}
]
}
With 2.3.9.RELEASE, the behaviour is rather surprising. The configprops endpoint shows that the bootstrap property should be used:
{
"activeProfiles": [
"native"
],
"property": {
"source": "applicationConfig: [classpath:/bootstrap.yml]",
"value": "%clr(%5p) %clr([traceid=%X{traceId:-} spanid=%X{spanId:-} parentspanid=%X{parentId:-}]){green}"
},
"propertySources": [
{
"name": "server.ports"
},
{
"name": "bootstrapProperties-configClient"
},
{
"name": "bootstrapProperties-class path resource [spring-logging-sleuth-override.yml"
},
{
"name": "bootstrapProperties-Config resource 'class path resource [application.yml]' via location 'classpath:/' (document #0)"
},
{
"name": "servletConfigInitParams"
},
{
"name": "servletContextInitParams"
},
{
"name": "systemProperties"
},
{
"name": "systemEnvironment"
},
{
"name": "random"
},
{
"name": "springCloudClientHostInfo"
},
{
"name": "applicationConfig: [classpath:/application.properties]"
},
{
"name": "applicationConfig: [classpath:/bootstrap.yml]",
"property": {
"origin": "class path resource [bootstrap.yml]:3:24",
"value": "%clr(%5p) %clr([traceid=%X{traceId:-} spanid=%X{spanId:-} parentspanid=%X{parentId:-}]){green}"
}
},
{
"name": "springCloudDefaultProperties"
},
{
"name": "cachedrandom"
},
{
"name": "defaultProperties",
"property": {
"value": "%5p [spring-logging-sleuth-override,%X{traceId:-},%X{spanId:-}]"
}
},
{
"name": "Management Server"
}
]
}
But the log output shows that's not the case:
. ____ _ __ _ _
/\\ / ___'_ __ _ _(_)_ __ __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
\\/ ___)| |_)| | | | | || (_| | ) ) ) )
' |____| .__|_| |_|_| |_\__, | / / / /
=========|_|==============|___/=/_/_/_/
:: Spring Boot :: (v2.3.9.RELEASE)
2021-02-26 10:53:49.073 INFO [traceid= spanid= parentspanid=] 22239 --- [ main] c.c.c.ConfigServicePropertySourceLocator : Fetching config from server at : http://localhost:8888
2021-02-26 10:53:49.182 INFO [traceid= spanid= parentspanid=] 22239 --- [ main] c.c.c.ConfigServicePropertySourceLocator : Located environment: name=spring-logging-sleuth-override, profiles=[default], label=null, version=null, state=null
2021-02-26 10:53:49.183 INFO [traceid= spanid= parentspanid=] 22239 --- [ main] b.c.PropertySourceBootstrapConfiguration : Located property source: [BootstrapPropertySource {name='bootstrapProperties-configClient'}, BootstrapPropertySource {name='bootstrapProperties-class path resource [spring-logging-sleuth-override.yml'}, BootstrapPropertySource {name='bootstrapProperties-Config resource 'class path resource [application.yml]' via location 'classpath:/' (document #0)'}]
2021-02-26 10:53:49.192 INFO [spring-logging-sleuth-override,,] 22239 --- [ main] c.g.a.s.app.MyAwesomeApplication : The following profiles are active: native
2021-02-26 10:53:51.589 INFO [spring-logging-sleuth-override,,] 22239 --- [ main] c.g.a.s.app.MyAwesomeApplication : Started MyAwesomeApplication in 3.094 seconds (JVM running for 5.121)
Comment From: wilkinsona
In 2.3.9.RELEASE, logging.pattern.level is read in LogbackLoggingSystem.loadDefaults. This happens due to PropertySourceBootstrapConfiguration.reinitializeLoggingSystem(ConfigurableEnvironment, String, LogFile). At this point, the property sources are the following:
bootstrapProperties-configClientbootstrapProperties-class path resource [spring-logging-sleuth-override.ymlbootstrapProperties-Config resource 'class path resource [application.yml]' via location 'classpath:/' (document #0)servletConfigInitParamsservletContextInitParamssystemPropertiessystemEnvironmentrandomspringCloudClientHostInfoapplicationConfig: [classpath:/application.properties]defaultPropertiesapplicationConfig: [classpath:/bootstrap.yml]springCloudDefaultPropertiescachedrandom
Note that the ordering is different to that shown above via the config props endpoint. At this point in time, defaultProperties appears before applicationConfig: [classpath:/bootstrap.yml]. This causes Sleuth's default to be used rather than the value configured in bootstrap.yml.
This appears to be a Spring Cloud bug. I'm not sure if Sleuth is doing the wrong thing when it creates or replaces the defaultProperties or if this is a more general problem with the property source bootstrapping.
Comment From: wilkinsona
I've opened https://github.com/spring-cloud/spring-cloud-sleuth/issues/1863.
Comment From: artemy
right, I'll follow the issue there. Thanks a lot for the investigation 👍🏻