No logs during Spring Boot config import

[aritzbastida]

As of Spring Boot 2.4, the default (preferred) way to import additional configuration is using spring.config.import property. However, I have noticed some logging issues since then.

The configuration is loaded before the environment is set up, and that incudes logging properties. Although ConfigDataLocationResolver and ConfigDataLoaderclasses accept a DeferredLoginstance in their constructors, this logger can only be used by the config import "plugin" itself, and not so easily when this plugin uses third-party libraries to achieve the task.

For example, spring-cloud-zookeeper-config uses Zookeeper client to retrieve configuration. This library uses log4j, and cannot be replaced by Apache Commons Log. Even if using SLF4J bridge, that is not yet configured by the time the import is taking place. The consequence is that we do not have logs related to Zookeeper (which can make troubleshooting more difficult). If the connection string is not correct or the server is down, the import phase will happily last until some timeout expires, with no logs in the meantime. You can try that out specifying an invalid port:

spring.config.import: zookeeper:localhost:8888

The application startup hangs for 1 minute, and then fails:

********************* 2021-11-15T09:28:48.483Z:  org.springframework.boot.context.event.ApplicationStartingEvent
********************* 2021-11-15T09:29:35.471Z: org.springframework.boot.context.event.ApplicationFailedEvent
10:29:35.519 [main] DEBUG org.springframework.boot.diagnostics.LoggingFailureAnalysisReporter - Application failed to start due to an exception
org.springframework.boot.context.config.ConfigDataResourceNotFoundException: Config data resource '[ZookeeperConfigDataResource@28d18df5 context = 'config/srv-nuc-jee-Bank-v4,dev', optional = false, profile = 'dev']' via location 'zookeeper:localhost:8888' cannot be found
    at org.springframework.boot.context.config.ConfigDataResourceNotFoundException.withLocation(ConfigDataResourceNotFoundException.java:97)
    at org.springframework.boot.context.config.ConfigDataImporter.handle(ConfigDataImporter.java:145)
...
Caused by: org.apache.zookeeper.KeeperException$ConnectionLossException: KeeperErrorCode = ConnectionLoss for /config/srv-nuc-jee-Bank-v4,dev
    at org.apache.zookeeper.KeeperException.create(KeeperException.java:102)
    at org.apache.zookeeper.KeeperException.create(KeeperException.java:54)

Note that this problem is not specific to this Zookeeper loader; it will affect to any loader using third-party libraries.

As an enhancement, please consider enabling some initial logging config during the bootstrap phase. That config could then be overriden by the properties imported from the remote source.

[wilkinsona]

please consider enabling some initial logging config during the bootstrap phase

This is really what DeferredLog is intended to do and loaders are expected to work within its limitations. For example, they should provide their own logging to enable diagnosis of any problems with third-party libraries that they use.

I'll flag this for team attention, but my feeling is that it's unlikely that we'll be able to do much more here. Routing all logging into the DeferredLog could be one option, but I suspect it will be prohibitively complex to do so.

[aritzbastida]

Thanks for the quick response, @wilkinsona, and thanks for even considering this.

I agree: the loader should wrap up any third-library it uses and can use DeferredLog to log any information that helps diagnosis. But in practice, many libraries are designed as "black box", and internal logs are the only way to "see" what's happening inside. For example, thanks to logging we learnt that disabling SASL authentication made connections to Zookeeper server much faster (in our setup).

The current Spring Boot design does not allow to see those (internal) logs any more. I'm not suggesting to route all logging into the DeferredLog; but instead having an initial, maybe optional, SLF4J-compliant logging config during bootstrap, which can be overriden after ApplicationEnvironmentPreparedEvent. It could be similar to the bootstrap phase in Spring Cloud Config (spring.cloud.bootstrap.enabled=true), but, of course, without that extra application context... ;)

[m31collision]

I think that I'm facing with the same issue. I'm trying to attach config server to my application, and I don't see debug log from org.springframework.cloud.config when logging.level.org.springframework.cloud.config is set to DEBUG in application config or via system properties. I have found that org.springframework.boot.env.EnvironmentPostProcessorApplicationListener#finish calls org.springframework.boot.logging.DeferredLog#switchOver which just switches to real logger but not any of org.springframework.boot.logging.DeferredLog#replayTo/switchTo which writes all saved log lines to real logger and then makes switch. I'm right?

[DanielLiu1123]

I think that I'm facing with the same issue. I'm trying to attach config server to my application, and I don't see debug log from org.springframework.cloud.config when logging.level.org.springframework.cloud.config is set to DEBUG in application config or via system properties.

Same issue, is there a good solution?

[rhosman]

@wilkinsona Should spring-cloud-config-client be providing it's own logging to enable diagnostics that we can all turn on so that we can confirm ConfigServerConfigDataLoader is trying to load the environment as it is trying to connect to the config server again and again?

I think it is reasonable to expect these attempts to connect to log with valid timestamps instead of having them all get logged in the same millisecond after the whole process has either failed or succeeded.