Logback logging.level.pattern is overriden by Sleuth

[artemy]

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 #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.

[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?

[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

[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 (#23767) and fixed in 2.4.2 (#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.

[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)

[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:

1. bootstrapProperties-configClient
2. bootstrapProperties-class path resource [spring-logging-sleuth-override.yml
3. bootstrapProperties-Config resource 'class path resource [application.yml]' via location 'classpath:/' (document #0)
4. servletConfigInitParams
5. servletContextInitParams
6. systemProperties
7. systemEnvironment
8. random
9. springCloudClientHostInfo
10. applicationConfig: [classpath:/application.properties]
11. defaultProperties
12. applicationConfig: [classpath:/bootstrap.yml]
13. springCloudDefaultProperties
14. cachedrandom

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.

[wilkinsona]

I've opened spring-cloud/spring-cloud-sleuth#1863.

[artemy]

right, I'll follow the issue there. Thanks a lot for the investigation 👍🏻