Describe the bug

I’m trying out bugfix #1775 and it seems to work, but the log output is corrupted.
I have created a sample config server and client that can be used to reproduce the problem with log output.
The sample code is based on Spring Cloud 2020.0.1-SNAPSHOT and Spring Cloud Config 3.0.1-SNAPSHOT.

Sample

The issues with the log output can be reproduced by the following steps:

1. Get the code

git clone git@github.com:magnus-larsson/ml-spring-cloud-config.git
cd ml-spring-cloud-config

2. Start config client with config server running, works fine!

  1. Start the config server:
cd ml-config-server
./gradlew bootRun --args='--spring.profiles.active=native'
  1. Start config client 
cd ml-config-client
./gradlew bootRun --args='--spring.profiles.active=test'
  1. Expect the normal startup log output and in the end:
2020-12-26 15:38:32.376  INFO 7798 --- [           main] m.m.MlConfigClientApplication            : Started MlConfigClientApplication in 1.463 seconds (JVM running for 1.796)
2020-12-26 15:38:32.378  INFO 7798 --- [           main] m.m.MlConfigClientApplication            : Connected to MongoDb: mongotest
2020-12-26 15:38:32.379  INFO 7798 --- [           main] m.m.MlConfigClientApplication            : Connected to MongoDb: rabbittest

3. Start config client without the config server running. It results in incorrect log output

  1. Stop the config server and client

  2. Only start the config client as described above

No log output is shown until the retry mechanism gives up (after approximately 20 sec) and the log output looks very strange, missing the expecting the normal startup log + log output for each attempt to connect to the config server:

16:24:46.276 [main] DEBUG org.springframework.boot.diagnostics.FailureAnalyzers - FailureAnalyzer org.springframework.boot.autoconfigure.jdbc.HikariDriverConfigurationFailureAnalyzer@329dbdbf failed
.
.
.
Caused by: org.springframework.web.client.ResourceAccessException: I/O error on GET request for "http://localhost:8888/product/test": Connection refused (Connection refused); nested exception is java.net.ConnectException: Connection refused (Connection refused)

4. Start config client first and the config server after a few retries. It also results in incorrect log output

  1. Stop the config server and client

  2. First, start the config client as described above

  3. After a few retries (some 5 sec) start the config server as described above

Once the config client finds the config server it will connect and startup as expected.
Again, no log output is shown until the connection to the config server succeeds.
The timestamps for the retry attempts are all wrong reporting nearly the same millisecond:

2020-12-26 16:32:37.972  INFO 12053 --- [           main] o.s.b.context.config.ConfigDataLoader    : Fetching config from server at : http://localhost:8888
2020-12-26 16:32:37.972  INFO 12053 --- [           main] o.s.b.context.config.ConfigDataLoader    : Connect Timeout Exception on Url - http://localhost:8888. Will be trying the next url if available
2020-12-26 16:32:37.972  INFO 12053 --- [           main] o.s.b.context.config.ConfigDataLoader    : Fetching config from server at : http://localhost:8888
2020-12-26 16:32:37.972  INFO 12053 --- [           main] o.s.b.context.config.ConfigDataLoader    : Connect Timeout Exception on Url - http://localhost:8888. Will be trying the next url if available
2020-12-26 16:32:37.972  INFO 12053 --- [           main] o.s.b.context.config.ConfigDataLoader    : Fetching config from server at : http://localhost:8888
2020-12-26 16:32:37.972  INFO 12053 --- [           main] o.s.b.context.config.ConfigDataLoader    : Connect Timeout Exception on Url - http://localhost:8888. Will be trying the next url if available
2020-12-26 16:32:37.972  INFO 12053 --- [           main] o.s.b.context.config.ConfigDataLoader    : Fetching config from server at : http://localhost:8888
2020-12-26 16:32:37.972  INFO 12053 --- [           main] o.s.b.context.config.ConfigDataLoader    : Connect Timeout Exception on Url - http://localhost:8888. Will be trying the next url if available
2020-12-26 16:32:37.972  INFO 12053 --- [           main] o.s.b.context.config.ConfigDataLoader    : Fetching config from server at : http://localhost:8888
2020-12-26 16:32:37.972  INFO 12053 --- [           main] o.s.b.context.config.ConfigDataLoader    : Connect Timeout Exception on Url - http://localhost:8888. Will be trying the next url if available
2020-12-26 16:32:37.972  INFO 12053 --- [           main] o.s.b.context.config.ConfigDataLoader    : Fetching config from server at : http://localhost:8888
2020-12-26 16:32:37.972  INFO 12053 --- [           main] o.s.b.context.config.ConfigDataLoader    : Connect Timeout Exception on Url - http://localhost:8888. Will be trying the next url if available

I expect the log output to be written as the retries occur and with the correct timestamps.

Comment From: spencergibb

I'm afraid this is due to a chicken and egg problem. The "logging" that occurs in ConfigDataLoad is deferred since the logging may be configured by what it is reading. Maybe @philwebb has an idea on the boot side, but there's nothing to be done in spring cloud.