Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

ClassNotFound during static init build step corrupts delayed logging #45650

Open
shawkins opened this issue Jan 16, 2025 · 6 comments · May be fixed by #45713
Open

ClassNotFound during static init build step corrupts delayed logging #45650

shawkins opened this issue Jan 16, 2025 · 6 comments · May be fixed by #45713
Labels
area/logging kind/bug Something isn't working

Comments

@shawkins
Copy link
Contributor

shawkins commented Jan 16, 2025 •
edited
Loading

Describe the bug

An underlying classnotfound exception during a static init build step is causing the delayed logging handling to fail with a NullPointerException and the delayed logging is incomplete.

Expected behavior

The delayed logging should work and/or the underlying exception should be propogated to the caller of QuarkusEntryPoint.main().

Actual behavior

With an underlying class not found exception during a static init build step (captured via a debug session):

java.util.ServiceConfigurationError: org.keycloak.authentication.AuthenticatorFactory: Provider org.keycloak.examples.authenticator.SecretQuestionAuthenticatorFactory could not be instantiated
	at java.base/java.util.ServiceLoader.fail(ServiceLoader.java:586)
	at java.base/java.util.ServiceLoader$ProviderImpl.newInstance(ServiceLoader.java:813)
	at java.base/java.util.ServiceLoader$ProviderImpl.get(ServiceLoader.java:729)
	at java.base/java.util.ServiceLoader$3.next(ServiceLoader.java:1403)
	at org.keycloak.provider.DefaultProviderLoader.load(DefaultProviderLoader.java:60)
	at org.keycloak.provider.ProviderManager.load(ProviderManager.java:107)
	at org.keycloak.quarkus.deployment.KeycloakProcessor.loadFactories(KeycloakProcessor.java:705)
	at org.keycloak.quarkus.deployment.KeycloakProcessor.configureKeycloakSessionFactory(KeycloakProcessor.java:468)
	at java.base/java.lang.invoke.MethodHandle.invokeWithArguments(MethodHandle.java:733)
	at io.quarkus.deployment.ExtensionLoader$3.execute(ExtensionLoader.java:856)
	at io.quarkus.builder.BuildContext.run(BuildContext.java:256)
	at org.jboss.threads.ContextHandler$1.runWith(ContextHandler.java:18)
	at org.jboss.threads.EnhancedQueueExecutor$Task.doRunWith(EnhancedQueueExecutor.java:2516)
	at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2495)
	at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1521)
	at java.base/java.lang.Thread.run(Thread.java:1583)
	at org.jboss.threads.JBossThread.run(JBossThread.java:483)
Caused by: java.lang.NoClassDefFoundError: org/keycloak/examples/authenticator/SecretQuestionAuthenticator
	at org.keycloak.examples.authenticator.SecretQuestionAuthenticatorFactory.<clinit>(SecretQuestionAuthenticatorFactory.java:39)
	at java.base/jdk.internal.misc.Unsafe.ensureClassInitialized0(Native Method)
	at java.base/jdk.internal.misc.Unsafe.ensureClassInitialized(Unsafe.java:1160)
	at java.base/jdk.internal.reflect.MethodHandleAccessorFactory.ensureClassInitialized(MethodHandleAccessorFactory.java:300)
	at java.base/jdk.internal.reflect.MethodHandleAccessorFactory.newConstructorAccessor(MethodHandleAccessorFactory.java:103)
	at java.base/jdk.internal.reflect.ReflectionFactory.newConstructorAccessor(ReflectionFactory.java:200)
	at java.base/java.lang.reflect.Constructor.acquireConstructorAccessor(Constructor.java:549)
	at java.base/java.lang.reflect.Constructor.newInstanceWithCaller(Constructor.java:499)
	at java.base/java.lang.reflect.Constructor.newInstance(Constructor.java:486)
	at java.base/java.util.ServiceLoader$ProviderImpl.newInstance(ServiceLoader.java:789)
	... 15 more
Caused by: java.lang.ClassNotFoundException: org.keycloak.examples.authenticator.SecretQuestionAuthenticator
	at io.quarkus.bootstrap.classloading.QuarkusClassLoader.loadClass(QuarkusClassLoader.java:535)
	at io.quarkus.bootstrap.classloading.QuarkusClassLoader.loadClass(QuarkusClassLoader.java:481)
	at io.quarkus.bootstrap.classloading.QuarkusClassLoader.loadClass(QuarkusClassLoader.java:533)
	at io.quarkus.bootstrap.classloading.QuarkusClassLoader.loadClass(QuarkusClassLoader.java:481)
	... 25 more

There is then an attempt to purge the delayed logging entries:

The DelayedHandler was closed before any children handlers were configured. Messages will be written to stderr.
2025-01-16 09:59:07,623 DEBUG [org.jboss.logging] (main) Logging Provider: org.jboss.logging.JBossLogManagerProvider

... more log entries

However that triggers a NullPointerException, so that Keycloak shows:

java.lang.NullPointerException
	at java.base/java.util.Objects.requireNonNull(Objects.java:233)
	at java.base/java.util.ImmutableCollections$List12.<init>(ImmutableCollections.java:563)
	at java.base/java.util.List.of(List.java:937)
	at io.quarkus.paths.OpenContainerPathTree.getRoots(OpenContainerPathTree.java:96)
	at io.quarkus.paths.SharedArchivePathTree$CallerOpenPathTree.getRoots(SharedArchivePathTree.java:142)
	at io.quarkus.bootstrap.classloading.PathTreeClassPathElement.toString(PathTreeClassPathElement.java:214)
	at java.base/java.util.Formatter$FormatSpecifier.printString(Formatter.java:3158)
	at java.base/java.util.Formatter$FormatSpecifier.print(Formatter.java:3036)
	at java.base/java.util.Formatter.format(Formatter.java:2791)
	at java.base/java.util.Formatter.format(Formatter.java:2728)
	at java.base/java.lang.String.format(String.java:4390)
	at org.jboss.logmanager.ExtFormatter.formatMessagePrintf(ExtFormatter.java:144)
	at org.jboss.logmanager.ExtFormatter.formatMessage(ExtFormatter.java:91)
	at org.jboss.logmanager.formatters.Formatters$16.renderRaw(Formatters.java:832)
	at org.jboss.logmanager.formatters.Formatters$JustifyingFormatStep.render(Formatters.java:227)
	at org.jboss.logmanager.formatters.MultistepFormatter.format(MultistepFormatter.java:90)
	at org.jboss.logmanager.ExtFormatter.format(ExtFormatter.java:58)
	at io.quarkus.bootstrap.logging.QuarkusDelayedHandler.close(QuarkusDelayedHandler.java:157)
	at io.quarkus.bootstrap.runner.QuarkusEntryPoint.main(QuarkusEntryPoint.java:35)
	at org.keycloak.quarkus.runtime.cli.Picocli.build(Picocli.java:945)
	at org.keycloak.quarkus.runtime.cli.command.Build.run(Build.java:91)
	at picocli.CommandLine.executeUserObject(CommandLine.java:2030)
	...
	at org.keycloak.quarkus.runtime.KeycloakMain.main(KeycloakMain.java:68)
	at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
	at java.base/java.lang.reflect.Method.invoke(Method.java:580)
	at io.quarkus.bootstrap.runner.QuarkusEntryPoint.doRun(QuarkusEntryPoint.java:62)
	at io.quarkus.bootstrap.runner.QuarkusEntryPoint.main(QuarkusEntryPoint.java:33)

How to Reproduce?

Add a jar to the provider directory with a missing class - I used https://github.com/keycloak/keycloak-quickstarts/tree/main/extension/authenticator and remove the Provider classes referenced by the Factories, see also keycloak/keycloak#36482

Run a build

I can also try to isolate this to a non-Keycloak quarkus project if needed.

Output of uname -a or ver

No response

Output of java -version

No response

Quarkus version or git rev

3.15.2

Build tool (ie. output of mvnw --version or gradlew --version)

No response

Additional information

The Keycloak user reported that this behavior did not occur with Keycloak based upon Quarkus 3.8.5.
@shawkins shawkins added the kind/bug Something isn't working label Jan 16, 2025
@quarkus-bot quarkus-bot
Copy link

quarkus-bot bot commented Jan 17, 2025

/cc @dmlloyd (logging)

@geoand
Copy link
Contributor

geoand commented Jan 20, 2025

I can also try to isolate this to a non-Keycloak quarkus project if needed.

That would indeed make it much easier for us to verify any potential fixes

geoand added a commit to geoand/quarkus that referenced this issue Jan 20, 2025
@geoand
Try to recover from logging errors when closing application
ef1aaaa 
Closes: quarkusio#45650
@geoand geoand linked a pull request Jan 20, 2025 that will close this issue
Draft
@geoand
Copy link
Contributor

geoand commented Jan 20, 2025

A basic attempt of doing a little better can be found in #45713

@shawkins
Copy link
Contributor Author

@geoand @dmlloyd the sequence here:

  • AugmentationAction.createProductionApplication() - in a try / finally closes the QuarkusClassLoader, causing the ArchivePathTree entries to null out the rootPath.

  • QuarkusDelayedHandler.close() is called after that, and there is a format that is trying to print the classpath which causes the NPE.

@geoand I think your solution will work, or a better close ordering could be attempted, or a more graceful handling of getRoot/getRoots after closure could be used.

@dmlloyd
Copy link
Member

dmlloyd commented Jan 20, 2025

I think the main bug to fix here would be that OpenContainerPathTree (and the call stack leading up to it) should not produce an NPE under any circumstance. Secondarily, the delayed queue handler should produce a error handler record if formatting fails instead of propagating the exception.

@gsmet
Copy link
Member

gsmet commented Jan 20, 2025

The idea of nulling things is that we should avoid loading classes from closed class loaders. In the end, we would have liked throwing an error when it happens.

So ideally I would prefer if we dumped the logs before we close the CL. But I haven’t looked at the code at all.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
area/logging kind/bug Something isn't working
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Try to recover from logging errors when closing application geoand/quarkus
4 participants
@dmlloyd @gsmet @shawkins @geoand