ConfigValidationException not visible in production mode

[cubi666]

After updating from Quarkus 3.15.1 to Quarkus 3.20.1 I have observed a strange behavior: In the case of a wrong configuration of my application the logger no longer prints the log message as it did before, but the application just terminates.

I debugged into the Quarkus code and ended up in the io.quarkus.bootstrap.logging.QuarkusDelayedHandler which adds the message to it's queue, but apparently never gets activated, so the queued messages do not get published.

Did anyone run into the same problem? Downgrading to 3.15.1 seems to fix the issue.

[cescoffier]

CC @dmlloyd @gsmet

[gsmet]

Any chance you could prepare a small Maven reproducer?

[cubi666]

I tried to create a minimal reproducer but the error shows up in production mode as excepted.

From some more debugging I discovered the following: The working reproducer fails in a different way than my actual project.

The reproducer fails on Quarkus.run(...) invoking ApplicationLifecycleManager.run(application, quarkusApplication, exitHandler, args);. ApplicationLifecycleManager uses System.err to log the exception, and that's what I see.

io.smallrye.config.SmallRyeConfig,buildMappings,SmallRyeConfig.java,141
io.smallrye.config.SmallRyeConfig,,SmallRyeConfig.java,95
io.smallrye.config.SmallRyeConfigBuilder,build,SmallRyeConfigBuilder.java,773
io.quarkus.runtime.generated.Config,readConfig,null,-1
io.quarkus.runtime.generated.Config,createRunTimeConfig,null,-1
io.quarkus.deployment.steps.RuntimeConfigSetup,deploy,null,-1
io.quarkus.runner.ApplicationImpl,doStart,null,-1
io.quarkus.runtime.Application,start,Application.java,101
io.quarkus.runtime.ApplicationLifecycleManager,run,ApplicationLifecycleManager.java,121
io.quarkus.runtime.Quarkus,run,Quarkus.java,77
io.quarkus.runtime.Quarkus,run,Quarkus.java,48
io.quarkus.runtime.Quarkus,run,Quarkus.java,137
org.acme.Main,main,Main.java,30
io.quarkus.bootstrap.runner.QuarkusEntryPoint,doRun,QuarkusEntryPoint.java,68
io.quarkus.bootstrap.runner.QuarkusEntryPoint,main,QuarkusEntryPoint.java,36

The actual application fails one line earlier in Quarkus.run(...) when instantiating the generated ApplicationImpl on Application application = (Application) constructor.invoke();
Therefor the ConfigurationException is handeled differently and is not printed via System.err and so I don't see it.

io.smallrye.config.SmallRyeConfig,buildMappings,SmallRyeConfig.java,141,0
io.smallrye.config.SmallRyeConfig,,SmallRyeConfig.java,95,0
io.smallrye.config.SmallRyeConfigBuilder,build,SmallRyeConfigBuilder.java,773,0
io.quarkus.runtime.generated.Config,,null,-1,0
io.quarkus.runner.ApplicationImpl,,null,-1,0
21.0.4,jdk.internal.misc.Unsafe,allocateInstance,Unsafe.java,-2,2
21.0.4,java.lang.invoke.DirectMethodHandle,allocateInstance,DirectMethodHandle.java,501,2
io.quarkus.runtime.Quarkus,run,Quarkus.java,76,0
io.quarkus.runtime.Quarkus,run,Quarkus.java,48,0
io.quarkus.runtime.Quarkus,run,Quarkus.java,137,0
my.project.core.Main,main,Main.java,31,0
io.quarkus.bootstrap.runner.QuarkusEntryPoint,doRun,QuarkusEntryPoint.java,68,1
io.quarkus.bootstrap.runner.QuarkusEntryPoint,main,QuarkusEntryPoint.java,36,1

[radcortez]

Can you send us the reproducer? Thank you!

[dmlloyd]

cc @radcortez... maybe there's a problem assembling the mappings?

[gsmet]

In any case, we need to also catch this and dump the logs.

[radcortez]

I'll have a look

[cubi666]

The reproducer (that does not reproduce the problem...) also hits ConfigMappingContext upon static initialisation, but my TestConfig is not yet part of the config mappings. That's why the missing config is not an issue at this point.

Later, on the second hit it's present and signaled by System.err.

The actual application is structured with sub-projects and libraries, so hard to say for me why the config error is reported earlier in this case.

I attached the reproducer (which does, as I mentioned, not reproduce the problem). It's a Gradle project, since I'm not really familiar with Maven, sorry.
log-issue.zip

[radcortez]

Starting from 3.18, errors caused by static init config were not being reported correctly in the console when running in production mode.

Caused by #45218 and fixed by #47104 in 3.21.2.

[radcortez]

@gsmet I think we need to backport #47104 to 3.20

[radcortez]

Separate but related discussion:

It seems we are setting up a logger for static init errors, but we use System.err for runtime config errors. We discussed this a long time ago at https://quarkusio.zulipchat.com/#narrow/channel/187038-dev/topic/Logging.20broken.20when.20mandatory.20config.20property.20missing.

The issue here is that you get inconsistent output depending on where the errors occurs:

Static Init

17:29:58,546 ERROR [io.qua.run.Quarkus] Error running Quarkus: java.lang.ExceptionInInitializerError
	at io.quarkus.runner.ApplicationImpl.<clinit>(Unknown Source)
	at java.base/jdk.internal.misc.Unsafe.allocateInstance(Native Method)
	at java.base/java.lang.invoke.DirectMethodHandle.allocateInstance(DirectMethodHandle.java:520)
	at io.quarkus.runtime.Quarkus.run(Quarkus.java:79)
	at io.quarkus.runtime.Quarkus.run(Quarkus.java:51)
	at io.quarkus.runtime.Quarkus.run(Quarkus.java:144)
	at com.radcortez.quarkus.config.Main.main(Main.java:9)
	at io.quarkus.bootstrap.runner.QuarkusEntryPoint.doRun(QuarkusEntryPoint.java:68)
	at io.quarkus.bootstrap.runner.QuarkusEntryPoint.main(QuarkusEntryPoint.java:36)
Caused by: io.smallrye.config.ConfigValidationException: Configuration validation failed:
	java.util.NoSuchElementException: SRCFG00014: The config property test.value2 is required but it could not be found in any config source
	java.util.NoSuchElementException: SRCFG00014: The config property test.value1 is required but it could not be found in any config source
	at io.smallrye.config.SmallRyeConfig.buildMappings(SmallRyeConfig.java:141)
	at io.smallrye.config.SmallRyeConfig.<init>(SmallRyeConfig.java:95)
	at io.smallrye.config.SmallRyeConfigBuilder.build(SmallRyeConfigBuilder.java:772)
	at io.quarkus.runtime.generated.Config.<clinit>(Unknown Source)
	... 9 more

Runtime

Configuration validation failed:
	java.util.NoSuchElementException: SRCFG00014: The config property test.value2 is required but it could not be found in any config source
	java.util.NoSuchElementException: SRCFG00014: The config property test.value1 is required, but it could not be found in any config source

The only difference in the application is the config being static init or runtime. Maybe we need to revisit this?