Improve exception handling when application fails to start #42270

zakkak · 2024-08-01T12:56:20Z

Prevent the usage of the logger when the application has not started
regardless of the cause since it's most likely not configured yet.

Closes #42084

Prevent the usage of the logger when the application has not started regardless of the cause since it's most likely not configured yet. Closes quarkusio#42084

quarkus-bot · 2024-08-02T02:40:01Z

Status for workflow `Quarkus CI`

This is the status report for running Quarkus CI on commit 9091010.

Failing Jobs

Status	Name	Step	Failures	Logs	Raw logs	Build scan
✖	JVM Tests - JDK 17	`Build`	Failures	Logs	Raw logs	🔍
✖	JVM Tests - JDK 21	`Build`	Failures	Logs	Raw logs	🔍
✖	JVM Tests - JDK 17 Windows	`Build`	Failures	Logs	Raw logs	🔍

Full information is available in the Build summary check run.
You can consult the Develocity build scans.

Failures

⚙️ JVM Tests - JDK 17 #

- Failing: extensions/flyway/deployment 
! Skipped: integration-tests/flyway integration-tests/hibernate-orm-compatibility-5.6/mariadb integration-tests/hibernate-orm-compatibility-5.6/postgresql and 5 more

📦 extensions/flyway/deployment

✖ io.quarkus.flyway.test.FlywayExtensionRepairAtStartTest.testRepairUsingDevMode line 46 - History - More details - Source on GitHub

org.awaitility.core.ConditionTimeoutException: 
Assertion condition defined as a Lambda expression in io.quarkus.flyway.test.FlywayExtensionRepairAtStartTest 
Expecting any element of:
  [org.jboss.logmanager.ExtLogRecord@66c478e1,
    org.jboss.logmanager.ExtLogRecord@11556a41,
    org.jboss.logmanager.ExtLogRecord@5673548a,
    org.jboss.logmanager.ExtLogRecord@77f95488,
    org.jboss.logmanager.ExtLogRecord@323f39e6,

⚙️ JVM Tests - JDK 21 #

- Failing: extensions/flyway/deployment 
! Skipped: integration-tests/flyway integration-tests/hibernate-orm-compatibility-5.6/mariadb integration-tests/hibernate-orm-compatibility-5.6/postgresql and 5 more

📦 extensions/flyway/deployment

✖ io.quarkus.flyway.test.FlywayExtensionRepairAtStartTest.testRepairUsingDevMode line 46 - History - More details - Source on GitHub

org.awaitility.core.ConditionTimeoutException: 
Assertion condition defined as a Lambda expression in io.quarkus.flyway.test.FlywayExtensionRepairAtStartTest 
Expecting any element of:
  [org.jboss.logmanager.ExtLogRecord@1ff444d1,
    org.jboss.logmanager.ExtLogRecord@33e4a584,
    org.jboss.logmanager.ExtLogRecord@156af654,
    org.jboss.logmanager.ExtLogRecord@53d59dbf,
    org.jboss.logmanager.ExtLogRecord@6e3a99d8,

⚙️ JVM Tests - JDK 17 Windows #

- Failing: extensions/flyway/deployment 
! Skipped: integration-tests/flyway integration-tests/hibernate-orm-compatibility-5.6/mariadb integration-tests/hibernate-orm-compatibility-5.6/postgresql and 5 more

📦 extensions/flyway/deployment

✖ io.quarkus.flyway.test.FlywayExtensionRepairAtStartTest.testRepairUsingDevMode line 46 - History - More details - Source on GitHub

org.awaitility.core.ConditionTimeoutException: 
Assertion condition defined as a Lambda expression in io.quarkus.flyway.test.FlywayExtensionRepairAtStartTest 
Expecting any element of:
  [org.jboss.logmanager.ExtLogRecord@579abb47,
    org.jboss.logmanager.ExtLogRecord@7f19290b,
    org.jboss.logmanager.ExtLogRecord@919a797,
    org.jboss.logmanager.ExtLogRecord@683da236,
    org.jboss.logmanager.ExtLogRecord@6aff6cf5,

Flaky tests - Develocity

⚙️ JVM Tests - JDK 17

📦 extensions/smallrye-reactive-messaging/deployment

✖ io.quarkus.smallrye.reactivemessaging.hotreload.ConnectorChangeTest.testUpdatingConnector - History

Expecting actual: ["-4","-5","-6","-7","-8","-9","-10","-11"] to start with: ["-3", "-4", "-5", "-6"] - java.lang.AssertionError

java.lang.AssertionError: 

Expecting actual:
  ["-4","-5","-6","-7","-8","-9","-10","-11"]
to start with:
  ["-3", "-4", "-5", "-6"]

	at io.quarkus.smallrye.reactivemessaging.hotreload.ConnectorChangeTest.testUpdatingConnector(ConnectorChangeTest.java:36)

📦 integration-tests/opentelemetry

✖ io.quarkus.it.opentelemetry.OpenTelemetryInjectionsTest.testOTelInjections - History

Condition with Lambda expression in io.quarkus.it.opentelemetry.OpenTelemetryInjectionsTest was not fulfilled within 5 seconds. - org.awaitility.core.ConditionTimeoutException

org.awaitility.core.ConditionTimeoutException: Condition with Lambda expression in io.quarkus.it.opentelemetry.OpenTelemetryInjectionsTest was not fulfilled within 5 seconds.
	at org.awaitility.core.ConditionAwaiter.await(ConditionAwaiter.java:167)
	at org.awaitility.core.CallableCondition.await(CallableCondition.java:78)
	at org.awaitility.core.CallableCondition.await(CallableCondition.java:26)
	at org.awaitility.core.ConditionFactory.until(ConditionFactory.java:1006)
	at org.awaitility.core.ConditionFactory.until(ConditionFactory.java:975)
	at io.quarkus.it.opentelemetry.OpenTelemetryInjectionsTest.reset(OpenTelemetryInjectionsTest.java:26)
	at java.base/java.lang.reflect.Method.invoke(Method.java:568)

⚙️ JVM Tests - JDK 21

📦 extensions/smallrye-reactive-messaging/deployment

✖ io.quarkus.smallrye.reactivemessaging.hotreload.ConnectorChangeTest.testUpdatingConnector - History

Expecting actual: ["-4","-5","-6","-7","-8","-9","-10","-11"] to start with: ["-3", "-4", "-5", "-6"] - java.lang.AssertionError

java.lang.AssertionError: 

Expecting actual:
  ["-4","-5","-6","-7","-8","-9","-10","-11"]
to start with:
  ["-3", "-4", "-5", "-6"]

	at io.quarkus.smallrye.reactivemessaging.hotreload.ConnectorChangeTest.testUpdatingConnector(ConnectorChangeTest.java:36)

📦 integration-tests/opentelemetry

✖ io.quarkus.it.opentelemetry.OpenTelemetryInjectionsTest.testOTelInjections - History

Condition with Lambda expression in io.quarkus.it.opentelemetry.OpenTelemetryInjectionsTest was not fulfilled within 5 seconds. - org.awaitility.core.ConditionTimeoutException

org.awaitility.core.ConditionTimeoutException: Condition with Lambda expression in io.quarkus.it.opentelemetry.OpenTelemetryInjectionsTest was not fulfilled within 5 seconds.
	at org.awaitility.core.ConditionAwaiter.await(ConditionAwaiter.java:167)
	at org.awaitility.core.CallableCondition.await(CallableCondition.java:78)
	at org.awaitility.core.CallableCondition.await(CallableCondition.java:26)
	at org.awaitility.core.ConditionFactory.until(ConditionFactory.java:1006)
	at org.awaitility.core.ConditionFactory.until(ConditionFactory.java:975)
	at io.quarkus.it.opentelemetry.OpenTelemetryInjectionsTest.reset(OpenTelemetryInjectionsTest.java:26)
	at java.base/java.lang.reflect.Method.invoke(Method.java:580)

gsmet · 2024-08-08T13:12:27Z

The test failure is related because we don't have the log records to test anymore.

zakkak · 2024-08-21T14:07:02Z

core/runtime/src/main/java/io/quarkus/runtime/ApplicationLifecycleManager.java

@@ -201,6 +201,9 @@ public static void run(Application application, Class<? extends QuarkusApplicati
                } else if (rootCause instanceof PreventFurtherStepsException
                        && !StringUtil.isNullOrEmpty(rootCause.getMessage())) {
                    System.err.println(rootCause.getMessage());
+                } else if (!currentApplication.isStarted()) {


Looking again at this I realize that this check doesn't make any sense and it will essentially always be true.

@radcortez is there any way I can check if the configuration generation was successful or not (assuming that logging will only work if it was successful) other than checking for ConfigurationException or ConfigValidationException?

If not, I am thinking that we will need to patch SmallryeConfig to catch more exceptions (currently looking for IOExceptions) in https://github.com/smallrye/smallrye-config/blob/main/implementation/src/main/java/io/smallrye/config/AbstractLocationConfigSourceLoader.java to handle #42084

WDYT?

@radcortez is there any way I can check if the configuration generation was successful or not (assuming that logging will only work if it was successful) other than checking for ConfigurationException or ConfigValidationException?

Maybe by checking

quarkus/core/runtime/src/main/java/io/quarkus/runtime/configuration/QuarkusConfigFactory.java

Line 13 in 133cbd9

private static volatile SmallRyeConfig config;

, but there is no public API for that.

If not, I am thinking that we will need to patch SmallryeConfig to catch more exceptions (currently looking for IOExceptions) in https://github.com/smallrye/smallrye-config/blob/main/implementation/src/main/java/io/smallrye/config/AbstractLocationConfigSourceLoader.java to handle #42084

We can certainly improve AbstractLocationConfigSourceLoader, but from the SmallRyeConfig side, we only provide ConfigValidationException for validation errors that the user can fix. I'm not sure if should be wrapping IOException.

Alternatively, we can probably add some sort of flag into the runtime-generated config class that can tell us if the config was started successfully.

I tried checking QuarkusConfigFactory but that doesn't work either, since in native executables the config is always set (done at build time).

Hum, can you confirm the repro steps of #42084? I've tried the steps, but I couldn't reproduce it. Maybe I'm missing something?

Probably only for Mandrel?

@radcortez I can no longer reproduce the silent failure on main, but the exceptions I am getting are still hiding the actual root cause.

On linux I am getting:

Exception in thread "Shutdown thread" java.lang.NullPointerException at io.quarkus.runtime.ApplicationLifecycleManager$ShutdownHookThread.run(ApplicationLifecycleManager.java:455) at org.graalvm.nativeimage.builder/com.oracle.svm.core.thread.PlatformThreads.threadStartRoutine(PlatformThreads.java:896) at org.graalvm.nativeimage.builder/com.oracle.svm.core.thread.PlatformThreads.threadStartRoutine(PlatformThreads.java:872)

which gets fixed in #42794. If you try building Quarkus with this fix you will be able to reproduce #42084 on linux. Unfortunately on MacOS I am getting an NCDFE which I still didn't have the time to fix.

What is the output of the following in your case?

./mvnw -Dnative -pl integration-tests/picocli-native -Dnative.surefire.skip -Dformat.skip -Dno-descriptor-tests clean verify -Dquarkus.native.additional-build-args=-H:ThrowMissingRegistrationErrors= ./integration-tests/picocli-native/target/quarkus-integration-test-picocli-native-999-SNAPSHOT-runner -h

If the build succeeds and the binary invocation exits without any messages then that's the reproducer. The desired behaviour is to fail with an error message (and ideally with a stacktrace as well) not silently.

If it prints the help message then something is wrong with the reproducer and I will need more info about your setup.

Yes, I do get the NCDFE: Could not initialize class io.smallrye.common.net.HostName.

@radcortez I created #42810 to resolve the macOS issue but that requires graalvm/graalvm-community-jdk21u#9 being merged and released in the next Mandrel 23.1.x release to work.

Unfortunately with Mandrel 24.0.x and #42810 the issue is not reproducible on macOS (so you need to reproduce in linux)

zakkak requested a review from gsmet August 1, 2024 12:56

quarkus-bot bot added the area/core label Aug 1, 2024

This comment has been minimized.

Sign in to view

quarkus-bot bot added the triage/flaky-test label Aug 1, 2024

Improve exception handling when application fails to start

9091010

Prevent the usage of the logger when the application has not started regardless of the cause since it's most likely not configured yet. Closes quarkusio#42084

zakkak force-pushed the 2024-08-01-fix-42084 branch from 253b312 to 9091010 Compare August 1, 2024 21:14

zakkak commented Aug 21, 2024

View reviewed changes

zakkak marked this pull request as draft August 21, 2024 14:07

linghengqian mentioned this pull request Oct 10, 2024

Enable Safe Composition of Metadata for ShardingSphere Proxy Native apache/shardingsphere#33179

Merged

6 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Improve exception handling when application fails to start #42270

Improve exception handling when application fails to start #42270

zakkak commented Aug 1, 2024

This comment has been minimized.

quarkus-bot bot commented Aug 2, 2024 •

edited by github-actions bot

Loading

gsmet commented Aug 8, 2024

zakkak Aug 21, 2024

radcortez Aug 21, 2024

zakkak Aug 26, 2024

radcortez Aug 26, 2024

radcortez Aug 26, 2024

zakkak Aug 27, 2024

radcortez Aug 27, 2024

zakkak Aug 27, 2024 •

edited

Loading

Improve exception handling when application fails to start #42270

Are you sure you want to change the base?

Improve exception handling when application fails to start #42270

Conversation

zakkak commented Aug 1, 2024

This comment has been minimized.

quarkus-bot bot commented Aug 2, 2024 • edited by github-actions bot Loading

Status for workflow Quarkus CI

Failing Jobs

Failures

⚙️ JVM Tests - JDK 17 #

📦 extensions/flyway/deployment

⚙️ JVM Tests - JDK 21 #

📦 extensions/flyway/deployment

⚙️ JVM Tests - JDK 17 Windows #

📦 extensions/flyway/deployment

Flaky tests - Develocity

⚙️ JVM Tests - JDK 17

📦 extensions/smallrye-reactive-messaging/deployment

📦 integration-tests/opentelemetry

⚙️ JVM Tests - JDK 21

📦 extensions/smallrye-reactive-messaging/deployment

📦 integration-tests/opentelemetry

gsmet commented Aug 8, 2024

zakkak Aug 21, 2024

Choose a reason for hiding this comment

radcortez Aug 21, 2024

Choose a reason for hiding this comment

zakkak Aug 26, 2024

Choose a reason for hiding this comment

radcortez Aug 26, 2024

Choose a reason for hiding this comment

radcortez Aug 26, 2024

Choose a reason for hiding this comment

zakkak Aug 27, 2024

Choose a reason for hiding this comment

radcortez Aug 27, 2024

Choose a reason for hiding this comment

zakkak Aug 27, 2024 • edited Loading

Choose a reason for hiding this comment

quarkus-bot bot commented Aug 2, 2024 •

edited by github-actions bot

Loading

Status for workflow `Quarkus CI`

zakkak Aug 27, 2024 •

edited

Loading