search

quarkusio / quarkus

Quarkus: Supersonic Subatomic Java.
https://quarkus.io
Apache License 2.0
13.56k stars 2.62k forks source link

Quarkus 2.x has java.lang.NoClassDefFoundError: Could not initialize class javax.crypto.JceSecurity #19265

Open dhoffer opened 3 years ago

dhoffer commented 3 years ago

Describe the bug

After upgrading from 1.13.7.Final to any of the 2.x versions we get this error at startup.

I retested with 2.1.1.Final and it has the same behavior.

We are using JDK 11.0.11+9. Code and JDK work fine with pre 2.x Quarkus.

This code is just trying to decrypt a password in the io.quarkus.credentials.CredentialsProvider implementation used to connect to the database.

2021-08-05 15:21:21,296 ERROR [io.qua.run.Application] (main) Failed to start application (with profile prod): java.lang.NoClassDefFoundError: Could not initialize class javax.crypto.JceSecurity at java.base/javax.crypto.Cipher.getInstance(Cipher.java:540) at com.bs.util.encryption.AESEncryptDecrypt.getInitializedCipher(AESEncryptDecrypt.java:151) at com.bs.util.encryption.AESEncryptDecrypt.decrypt(AESEncryptDecrypt.java:127) at com.bs.util.encryption.AESEncryptDecryptProxy.decrypt(AESEncryptDecryptProxy.java:44) at com.bs.util.BSDataSourceCredentialsProvider.getCredentials(BSDataSourceCredentialsProvider.java:33) at com.bs.util.BSDataSourceCredentialsProvider_ClientProxy.getCredentials(BSDataSourceCredentialsProvider_ClientProxy.zig:157) at io.quarkus.agroal.runtime.AgroalVaultCredentialsProviderPassword.asProperties(AgroalVaultCredentialsProviderPassword.java:21) at io.agroal.api.security.AgroalDefaultSecurityProvider.getSecurityProperties(AgroalDefaultSecurityProvider.java:23) at io.agroal.pool.ConnectionFactory.securityProperties(ConnectionFactory.java:190) at io.agroal.pool.ConnectionFactory.securityProperties(ConnectionFactory.java:179) at io.agroal.pool.ConnectionFactory.jdbcProperties(ConnectionFactory.java:160) at io.agroal.pool.ConnectionFactory.createConnection(ConnectionFactory.java:204) at io.agroal.pool.ConnectionPool$CreateConnectionTask.call(ConnectionPool.java:470) at io.agroal.pool.ConnectionPool$CreateConnectionTask.call(ConnectionPool.java:452) at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) at io.agroal.pool.util.PriorityScheduledExecutor.beforeExecute(PriorityScheduledExecutor.java:68) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1126) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) at java.base/java.lang.Thread.run(Thread.java:829)

Expected behavior

Quarkus should be able to load the JDK class javax.crypto.JceSecurity.

Actual behavior

See stacktrace in description.

How to Reproduce?

No response

Output of uname -a or ver

No response

Output of java -version

openjdk 11.0.11 2021-04-20 OpenJDK Runtime Environment AdoptOpenJDK-11.0.11+9 (build 11.0.11+9) OpenJDK 64-Bit Server VM AdoptOpenJDK-11.0.11+9 (build 11.0.11+9, mixed mode)

GraalVM version (if different from Java)

No response

Quarkus version or git rev

2.1.1.Final

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

No response

Additional information

No response

quarkus-bot[bot] commented 3 years ago

/cc @sberyozkin

stuartwdouglas commented 3 years ago

How can I reproduce this? I can load the class fine using Class.forName().

That error is also an initializion error, which means the static init block in JceSecurity is throwing an exception. Attaching a debugger to see what is actually throwing the exception would also be really helpful if you can't provide a reproducer.

dhoffer commented 3 years ago

Yeah our code project is huge, posting it is not practical.

I can say that the code that uses this is annotated with @Singleton and it is used very early in the Quarkus framework code to decrypt the DB password. Our app.yml has 3 data sources but only one of them uses the Quarkus CredentialsProvider to decrypt the password, that is the usage that is failing.

I can try to attach a debugger to see what error is given.

I never like to use static blocks as they have too many bad behaviors. But since you say it's thrown there I would say there was a change in Quarkus 2.x such that whatever is needed there is not available yet as it works fine in Quarkus 1.x.

-Dave

On Sun, Aug 8, 2021 at 8:59 PM Stuart Douglas @.***> wrote:

How can I reproduce this? I can load the class fine using Class.forName().

That error is also an initializion error, which means the static init block in JceSecurity is throwing an exception. Attaching a debugger to see what is actually throwing the exception would also be really helpful if you can't provide a reproducer.

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub https://github.com/quarkusio/quarkus/issues/19265#issuecomment-894919866, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAL7BL6YAA4VVKP4JZ2SMADT35AA5ANCNFSM5BUVWYZQ . Triage notifications on the go with GitHub Mobile for iOS https://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675 or Android https://play.google.com/store/apps/details?id=com.github.android&utm_campaign=notification-email .

stuartwdouglas commented 3 years ago

The static block is in the JDK itself, not much we can do about it. I tried with pretty much the exact same code and it worked.

Looking through the source code of JceSecurity I don't see how anything Quarkus was doing could actually affect it, so I am really not sure what is going on. You are going to need to attach a debugger to see what is actually throwing the exception (Java makes it really hard to debug these kinds of errors, as the cause is lost and turned into NoClassDefFoundError instead).

dhoffer commented 3 years ago

Understood, I will do this as soon as possible.

-Dave

On Mon, Aug 9, 2021 at 4:57 PM Stuart Douglas @.***> wrote:

The static block is in the JDK itself, not much we can do about it. I tried with pretty much the exact same code and it worked.

Looking through the source code of JceSecurity I don't see how anything Quarkus was doing could actually affect it, so I am really not sure what is going on. You are going to need to attach a debugger to see what is actually throwing the exception (Java makes it really hard to debug these kinds of errors, as the cause is lost and turned into NoClassDefFoundError instead).

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub https://github.com/quarkusio/quarkus/issues/19265#issuecomment-895604695, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAL7BL47AEYNH6VIAWPGT5TT4BMOXANCNFSM5BUVWYZQ . Triage notifications on the go with GitHub Mobile for iOS https://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675 or Android https://play.google.com/store/apps/details?id=com.github.android&utm_campaign=notification-email .

dhoffer commented 3 years ago

I am having a hard time getting more details as I debug this. Here is the full stack trace.

2021-08-19 15:34:14,891 ERROR [io.qua.run.Application] (main) Failed to start application (with profile prod): java.lang.NoClassDefFoundError: Could not initialize class javax.crypto.JceSecurity at java.base/javax.crypto.Cipher.getInstance(Cipher.java:540) at com.bs.util.encryption.AESEncryptDecrypt.getInitializedCipher(AESEncryptDecrypt.java:151) at com.bs.util.encryption.AESEncryptDecrypt.decrypt(AESEncryptDecrypt.java:127) at com.bs.util.encryption.AESEncryptDecryptProxy.decrypt(AESEncryptDecryptProxy.java:50) at com.bs.util.DataSourceCredentialsProvider.getCredentials(DataSourceCredentialsProvider.java:33) at com.bs.util.DataSourceCredentialsProvider_ClientProxy.getCredentials(DataSourceCredentialsProvider_ClientProxy.zig:157) at io.quarkus.agroal.runtime.AgroalVaultCredentialsProviderPassword.asProperties(AgroalVaultCredentialsProviderPassword.java:21) at io.agroal.api.security.AgroalDefaultSecurityProvider.getSecurityProperties(AgroalDefaultSecurityProvider.java:23) at io.agroal.pool.ConnectionFactory.securityProperties(ConnectionFactory.java:190) at io.agroal.pool.ConnectionFactory.securityProperties(ConnectionFactory.java:179) at io.agroal.pool.ConnectionFactory.jdbcProperties(ConnectionFactory.java:160) at io.agroal.pool.ConnectionFactory.createConnection(ConnectionFactory.java:204) at io.agroal.pool.ConnectionPool$CreateConnectionTask.call(ConnectionPool.java:470) at io.agroal.pool.ConnectionPool$CreateConnectionTask.call(ConnectionPool.java:452) at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) at io.agroal.pool.util.PriorityScheduledExecutor.beforeExecute(PriorityScheduledExecutor.java:68) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1126) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) at java.base/java.lang.Thread.run(Thread.java:829)

The line in java.base/javax.crypto.Cipher.getInstance where it is failing is on this line: JceSecurity.canUseProvider(s.getProvider()) (line 540)

However my IDE will never go into that method it throws the NoClassDefFoundError exception.

The strange part is when I debug this the code lands on 540 about 20 times in a loop, giving an error each time. Then it just quits with the above stack trace.

Note our app has 3 data sources and two of them use the DataSourceCredentialsProvider. The third data source is not available in our DEV environment so that one just fails...but we expect that one to fail. With Quarkus 2.x all of them fail with this new NoClassDefFoundError error.

I have verified this fails with the new 2.1.3.Final version as well.

So in summary fails with all Quarkus 2.x Works with all Quarkus 1.x Same JDK 11 Same code base.

Here is my Java: C:\projects\app>java --version openjdk 11.0.11 2021-04-20 OpenJDK Runtime Environment AdoptOpenJDK-11.0.11+9 (build 11.0.11+9) OpenJDK 64-Bit Server VM AdoptOpenJDK-11.0.11+9 (build 11.0.11+9, mixed mode)

Note this is very early code in application startup. Agroal is trying to get the password for our DB and to do that it has to use our AES decryption that is used in the CredentialsProvider implementation.

stuartwdouglas commented 3 years ago

It looks like the static init block has the following:

        } catch (Exception e) {
            throw new SecurityException(
                    "Can not initialize cryptographic mechanism", e);
        }

Can you set a breakpoint for SecurityException, and try and figure out what the underlying exception is?

Also what mode is this, is it prod, dev or both? If it is prod using fast-jar is it still a problem with legacy-jar or uber-jar?

dhoffer commented 3 years ago

Its not throwing in the static block, all good there. We are running in prod using an uber-jar.

stuartwdouglas commented 3 years ago

Can you make a reproducer? It seems like this is all in the database startup code so I am assuming a small project with the same config would have the same issue?

dhoffer commented 3 years ago

I doubt that will be possible. If no one else is having any troubles with their 2.x apps my new simple one will likely work as well. I'll keep investigating but not getting far on this.

stuartwdouglas commented 3 years ago

Is there something specific in your datasource config that is triggering this code path?

It's really weird because I don't really see how Quarkus can affect a JDK class like this, especially given we don't do anything special with ClassLoading in an Uber Jar.

dhoffer commented 3 years ago

Nothing special. Just using quarkus.datasource.credentials-provider config so Quarkus uses CredentialsProvider to get DB credentials. Quarkus calls this very early as it needs the DB credentials early.

jaikiran commented 3 years ago

So I tried something outside of Quarkus in a standalone trivial Java code. 2 classes Foo and Bar. Foo just keeps calling a static method on Bar in a loop and catches any exception, prints it and the continues calling that method on Bar for the next time. This it does for 5 times. Bar has a static (class) initialization block and intentionally throws an exception from that block everytime. Here's what these classes look like:

Foo.java

public class Foo {
    public static void main(final String[] args) throws Exception {
        for (int i = 0; i < 5; i++) {
            try {
                Bar.doSomething();
            } catch(Throwable t) {
                System.err.println("Got error " + i);
                t.printStackTrace();
            }

        }

    }
}

Bar.java

public class Bar {

    static {
        System.out.println("Hi");
        if (true) {
            throw new SecurityException("intentional");
        }
    }

    public static void doSomething() {
        System.err.println("Done");
    }
}

I then run this code with Java 11 and here's what I get as the output:

Hi
Got error 0
java.lang.ExceptionInInitializerError
    at Foo.main(Foo.java:5)
Caused by: java.lang.SecurityException: intentional
    at Bar.<clinit>(Bar.java:6)
    ... 1 more
Got error 1
java.lang.NoClassDefFoundError: Could not initialize class Bar
    at Foo.main(Foo.java:5)
Got error 2
java.lang.NoClassDefFoundError: Could not initialize class Bar
    at Foo.main(Foo.java:5)
Got error 3
java.lang.NoClassDefFoundError: Could not initialize class Bar
    at Foo.main(Foo.java:5)
Got error 4
java.lang.NoClassDefFoundError: Could not initialize class Bar
    at Foo.main(Foo.java:5)

Notice that the first attempt that called the static method Bar.doSomething which triggered the static initializer of Bar class fails and contains the full details including the underlying root cause of why it failed in its exception stacktrace:

Hi
Got error 0
java.lang.ExceptionInInitializerError
    at Foo.main(Foo.java:5)
Caused by: java.lang.SecurityException: intentional
    at Bar.<clinit>(Bar.java:6)
    ... 1 more

However, the subsequent attempts on Bar.doSomething() just throw a NoClassDefFoundError without any underlying cause, like this next attempt:

Got error 1
java.lang.NoClassDefFoundError: Could not initialize class Bar
    at Foo.main(Foo.java:5)

This detail is crucial, because in one of your comment you said:

The strange part is when I debug this the code lands on 540 about 20 times in a loop, giving an error each time. Then it just quits with the above stack trace.

So it looks like somewhere in your code in this flow you have a catch block which catches the exception (actually I think some part of your code is catching Throwable and not just Exception) but then does something else which again triggers the code which leads to this JceSecurity class. This it perhaps does in a loop maybe? Perhaps 20 times and then when all 20 attempts fail, it throws the last exception, which of course as seen in that above sample code will not contain the root cause.

So what you could do is, in the following flow/classes:

at java.base/javax.crypto.Cipher.getInstance(Cipher.java:540) at com.bs.util.encryption.AESEncryptDecrypt.getInitializedCipher(AESEncryptDecrypt.java:151) at com.bs.util.encryption.AESEncryptDecrypt.decrypt(AESEncryptDecrypt.java:127) at com.bs.util.encryption.AESEncryptDecryptProxy.decrypt(AESEncryptDecryptProxy.java:50) at com.bs.util.DataSourceCredentialsProvider.getCredentials(DataSourceCredentialsProvider.java:33)

Find out where such a loop or try/catch block exists. See what's it's doing and if needs to be fixed. Since you are able to debug this code, I think if you can add a breakpoint in this catch block and inspect the first thrown exception, then it's likely that it will have a cause hierarchy which shows what the root cause is. If you need help understanding that root cause you can paste that exception hierarchy here (you can get it while debugger is attached by executing a e.printStackTrace() against that exception that you are inspecting, the stacktrace will get printed in the console of Quarkus app). It's crucial that you inspect the first exception that is thrown out of those 20 exceptions in a loop.

stuartwdouglas commented 3 years ago

I would also try adding a breakpoint for ExceptionInInitializerError and see if that helps

dhoffer commented 3 years ago

Thanks for the detailed reply and ideas, I will try to track this down.

I do have some initial feedback though. We no NOT have any retries or loops in our code regarding this issue. We make ONE call to Cipher.getInstance(cryptoModePadding) for every ONE call of Quarkus/Agroal to CredentialsProvider#getCredentials(String credentialsProviderName)

I believe the loop of 20 I mentioned is in the JDK here:

public static final Cipher getInstance(String transformation){ ... Iterator t = services.iterator(); Exception failure = null; while (t.hasNext()) { Service s = t.next(); if (JceSecurity.canUseProvider(s.getProvider()) == false) { continue; } ...

jaikiran commented 3 years ago

I believe the loop of 20 I mentioned is in the JDK here:

public static final Cipher getInstance(String transformation){ ... Iterator t = services.iterator(); Exception failure = null; while (t.hasNext()) { Service s = t.next(); if (JceSecurity.canUseProvider(s.getProvider()) == false) { continue; }

That however doesn't explain why the thrown exception is not getting propagated out of the loop and method, the very first instance. I don't see any catch block around that call to JceSecurity.canUseProvider, unless I'm not looking at the right JDK version/implementation?

We are using JDK 11.0.11+9

Where did you download and install this from?

dhoffer commented 3 years ago

I agree, the errors just are not making sense to me.

I don't recall the site where I got the JDK but here is what is in the release file: IMPLEMENTOR="AdoptOpenJDK" IMPLEMENTOR_VERSION="AdoptOpenJDK-11.0.11+9" JAVA_VERSION="11.0.11" JAVA_VERSION_DATE="2021-04-20" MODULES="java.base java.compiler java.datatransfer java.xml java.prefs java.desktop java.instrument java.logging java.management java.security.sasl java.naming java.rmi java.management.rmi java.net.http java.scripting java.security.jgss java.transaction.xa java.sql java.sql.rowset java.xml.crypto java.se java.smartcardio jdk.accessibility jdk.internal.vm.ci jdk.management jdk.unsupported jdk.internal.vm.compiler jdk.aot jdk.internal.jvmstat jdk.attach jdk.charsets jdk.compiler jdk.crypto.ec jdk.crypto.cryptoki jdk.crypto.mscapi jdk.dynalink jdk.internal.ed jdk.editpad jdk.hotspot.agent jdk.httpserver jdk.internal.le jdk.internal.opt jdk.internal.vm.compiler.management jdk.jartool jdk.javadoc jdk.jcmd jdk.management.agent jdk.jconsole jdk.jdeps jdk.jdwp.agent jdk.jdi jdk.jfr jdk.jlink jdk.jshell jdk.jsobject jdk.jstatd jdk.localedata jdk.management.jfr jdk.naming.dns jdk.naming.ldap jdk.naming.rmi jdk.net jdk.pack jdk.rmic jdk.scripting.nashorn jdk.scripting.nashorn.shell jdk.sctp jdk.security.auth jdk.security.jgss jdk.unsupported.desktop jdk.xml.dom jdk.zipfs" OS_ARCH="x86_64" OS_NAME="Windows" SOURCE=".:git:9a5c368512c6" BUILD_SOURCE="git:4ad15fd" FULL_VERSION="11.0.11+9" SEMANTIC_VERSION="11.0.11+9" BUILD_INFO="OS: Windows Server 2012 R2 Version: 6.3" JVM_VARIANT="Hotspot" JVM_VERSION="11.0.11+9" IMAGE_TYPE="JDK"

Yesterday I also installed a later JDK 11 to see if it made any difference but I got the same error, here is its release file contents from openjdk-11+28_windows-x64_bin.zip

IMPLEMENTOR="Oracle Corporation" IMPLEMENTOR_VERSION="18.9" JAVA_VERSION="11" JAVA_VERSION_DATE="2018-09-25" MODULES="java.base java.compiler java.datatransfer java.xml java.prefs java.desktop java.instrument java.logging java.management java.security.sasl java.naming java.rmi java.management.rmi java.net.http java.scripting java.security.jgss java.transaction.xa java.sql java.sql.rowset java.xml.crypto java.se java.smartcardio jdk.accessibility jdk.internal.vm.ci jdk.management jdk.unsupported jdk.internal.vm.compiler jdk.aot jdk.internal.jvmstat jdk.attach jdk.charsets jdk.compiler jdk.crypto.ec jdk.crypto.cryptoki jdk.crypto.mscapi jdk.dynalink jdk.internal.ed jdk.editpad jdk.hotspot.agent jdk.httpserver jdk.internal.le jdk.internal.opt jdk.internal.vm.compiler.management jdk.jartool jdk.javadoc jdk.jcmd jdk.management.agent jdk.jconsole jdk.jdeps jdk.jdwp.agent jdk.jdi jdk.jfr jdk.jlink jdk.jshell jdk.jsobject jdk.jstatd jdk.localedata jdk.management.jfr jdk.naming.dns jdk.naming.rmi jdk.net jdk.pack jdk.rmic jdk.scripting.nashorn jdk.scripting.nashorn.shell jdk.sctp jdk.security.auth jdk.security.jgss jdk.unsupported.desktop jdk.xml.dom jdk.zipfs" OS_ARCH="x86_64" OS_NAME="Windows" SOURCE=".:76072a077ee1"

On Wed, Aug 25, 2021 at 9:07 AM Jaikiran @.***> wrote:

I believe the loop of 20 I mentioned is in the JDK here:

public static final Cipher getInstance(String transformation){ ... Iterator t = services.iterator(); Exception failure = null; while (t.hasNext()) { Service s = t.next(); if (JceSecurity.canUseProvider(s.getProvider()) == false) { continue; }

That however doesn't explain why the thrown exception is not getting propagated out of the loop and method, the very first instance. I don't see any catch block around that call to JceSecurity.canUseProvider, unless I'm not looking at the right JDK version/implementation?

We are using JDK 11.0.11+9

Where did you download and install this from?

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub https://github.com/quarkusio/quarkus/issues/19265#issuecomment-905590516, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAL7BLZU25US6WCSOEUMQBDT6UBM7ANCNFSM5BUVWYZQ . Triage notifications on the go with GitHub Mobile for iOS https://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675 or Android https://play.google.com/store/apps/details?id=com.github.android&utm_campaign=notification-email .

jaikiran commented 3 years ago

If the "easier" path of debugging doesn't solve this, then I think the last resort is the Byteman approach. In that case, please follow these steps:

RULE ExceptionInInitializerError throwable-arg CLASS java.lang.ExceptionInInitializerError METHOD (Throwable) AT EXIT IF TRUE DO traceStack("*** ExceptionInInitializerError called with a cause"); $1.printStackTrace(); ENDRULE

RULE ExceptionInInitializerError string-arg CLASS java.lang.ExceptionInInitializerError METHOD (String) AT EXIT IF TRUE DO traceStack("*** ExceptionInInitializerError with message called") ENDRULE

RULE JceSecurity exception exit CLASS javax.crypto.JceSecurity METHOD AT EXCEPTION EXIT IF TRUE DO traceStack("*** JceSecurity failed with exception"); $^.printStackTrace(); ENDRULE


- Assuming that location you saved these files is "C:\projects\udl\byteman\", the launch your Quarkus application using:

java -javaagent:"C:\projects\udl\byteman\byteman-4.0.16.jar=script:C:\projects\udl\byteman\byteman-rules.btm,boot:C:\projects\udl\byteman\byteman-4.0.16.jar,prop:org.jboss.byteman.verbose=true,prop:org.jboss.byteman.transform.all=true" -jar 



(you might have to fiddle with the java launch command. Essentially you just need to additionally add the javaagent option as noted above in addition to whatever you are currently using to launch your application)

This should generate (hopefully) enough exception stacktrace/output on the console when the JceSecurity class initialization errors out.

P.S: Long back, I had wondered whether Quarkus should have a much more seamless integration with Byteman to help with issues like these. I think it's time to experiment a bit and see how to make debugging Quarkus in cases like these easier with Byteman. I'll see if I can try a PoC to make this easier.
jaikiran commented 3 years ago

@stuartwdouglas, @mkouba, any chance the dynamic bytecode that we generate[1] in this com.bs.util.BSDataSourceCredentialsProvider_ClientProxy.zig:

com.bs.util.BSDataSourceCredentialsProvider.getCredentials(BSDataSourceCredentialsProvider.java:33)
at com.bs.util.BSDataSourceCredentialsProvider_ClientProxy.getCredentials(BSDataSourceCredentialsProvider_ClientProxy.zig:157)
at io.quarkus.agroal.runtime.AgroalVaultCredentialsProviderPassword.asProperties(AgroalVaultCredentialsProviderPassword.java:21)

might have swallowed the exception/throwable from JceSecurity at some point in its usage and yet allowed the call on that proxy to move forward? That's the last thing I can think of, before I call it a day. The bytecode generation code isn't very intuitive to understand at a quick glance (for obvious reasons), so I can't confirm this myself right now.

[1] https://github.com/quarkusio/quarkus/blob/main/independent-projects/arc/processor/src/main/java/io/quarkus/arc/processor/ClientProxyGenerator.java#L45

dhoffer commented 3 years ago

Fyi...I tried 2.1.3.Final in 3 more Quarkus apps, all much smaller then the first one. Two did not have this error but one does so 2 in total have this error and 2 do not. And just as a reminder this is with 2.x only, 1.x is fine.

stuartwdouglas commented 3 years ago

Is there any obvious similarities between the ones that don't work?

Stuart

On Thu, 26 Aug 2021, 2:24 am David Hoffer, @.***> wrote:

Fyi...I tried 2.1.3.Final in 3 more Quarkus apps, all much smaller then the first one. Two did not have this error but one does so 2 in total have this error and 2 do not. And just as a reminder this is with 2.x only, 1.x is fine.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/quarkusio/quarkus/issues/19265#issuecomment-905685369, or unsubscribe https://github.com/notifications/unsubscribe-auth/AACQG6ZKQQ65X2HC4ZWKVSTT6UKKRANCNFSM5BUVWYZQ . Triage notifications on the go with GitHub Mobile for iOS https://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675 or Android https://play.google.com/store/apps/details?id=com.github.android&utm_campaign=notification-email .

dhoffer commented 3 years ago

I finally have good news to report. The tips provided by @jaikiran were incredibly helpful.

I added Byteman just as described and the logs immediately reported:

java.util.ServiceConfigurationError: java.net.spi.URLStreamHandlerProvider: Provider org.infinispan.commons.jdkspecific.ClasspathURLStreamHandlerProvider not found at java.base/java.util.ServiceLoader.fail(ServiceLoader.java:589)

So then a quick Google query brought me here:

https://github.com/infinispan/infinispan-quarkus/issues/55

It turns out that in the two apps that fail we had a dependency on this component. But it turns out it's OBE as it builds/runs with out the infinispan-quarkus dependency.

So some observations/questions/suggestions.

  1. Why does Quarkus 2.x fail with this but 1.x was fine?
  2. Why does Quarkus hide the real error? IDK but suspect that what @jaikiran said regarding com.bs.util.BSDataSourceCredentialsProvider_ClientProxy.zig is likely the cause.
  3. I really like the suggestion that @jaikiran had about integrating Byteman with Quarkus. That tool brought the error from complete obscurity to front and center.

I am good on this issue but Quarkus might want to evaluate the above and see if there is a way to help others when they have strange issues like this one.

Many thanks to @jaikiran on this one!

-Dave

stuartwdouglas commented 3 years ago

The client proxy should not be hiding anything.

What was the full stack trace? It should shed some light on what hid the exception.

There is an issue for a byteman extension, although it was mostly in reference to native: https://github.com/quarkusio/quarkus/issues/2263

jaikiran commented 3 years ago

Thank you for continuing to investigate this.

I added Byteman just as described and the logs immediately reported:

java.util.ServiceConfigurationError: java.net.spi.URLStreamHandlerProvider: Provider org.infinispan.commons.jdkspecific.ClasspathURLStreamHandlerProvider not found at java.base/java.util.ServiceLoader.fail(ServiceLoader.java:589)

So I suspect, it's this[1] static block in JceSecurity which is triggering that URLStreamHandler lookup. So like Stuart says, if you can show us the entire exception stacktrace, that will help us understand where this exception is getting swallowed and we can provide a fix if relevant.

[1] https://github.com/openjdk/jdk11u-dev/blob/master/src/java.base/share/classes/javax/crypto/JceSecurity.java.template#L237

dhoffer commented 3 years ago

Do you mean you want to see all that Byteman reported? If so I can try to do that test first thing tomorrow. I did not capture all of it.

-Dave

On Wed, Aug 25, 2021 at 7:51 PM Jaikiran @.***> wrote:

Thank you for continuing to investigate this.

I added Byteman just as described and the logs immediately reported:

java.util.ServiceConfigurationError: java.net.spi.URLStreamHandlerProvider: Provider org.infinispan.commons.jdkspecific.ClasspathURLStreamHandlerProvider not found at java.base/java.util.ServiceLoader.fail(ServiceLoader.java:589)

So I suspect, it's this[1] static block in JceSecurity which is triggering that URLStreamHandler lookup. So like Stuart says, if you can show us the entire exception stacktrace, that will help us understand where this exception is getting swallowed and we can provide a fix if relevant.

[1] https://github.com/openjdk/jdk11u-dev/blob/master/src/java.base/share/classes/javax/crypto/JceSecurity.java.template#L237

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub https://github.com/quarkusio/quarkus/issues/19265#issuecomment-906011379, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAL7BL6INQHPKRKQIONMQF3T6WMYNANCNFSM5BUVWYZQ . Triage notifications on the go with GitHub Mobile for iOS https://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675 or Android https://play.google.com/store/apps/details?id=com.github.android&utm_campaign=notification-email .

jaikiran commented 3 years ago

Do you mean you want to see all that Byteman reported? If so I can try to do that test first thing tomorrow. I did not capture all of it.

Yes, please. That will be crucial for us (Quarkus) to solve this properly, if at all this turns out to be something that needs to be solved in Quarkus.

dhoffer commented 3 years ago

Here is the full log with Byteman. Please ignore the use of google cache in our part of the code that is new and has nothing to do with this issue, the cache just means we only have to get the user/password once per datasource.

org.jboss.byteman.agent.Transformer : possible trigger for rule JceSecurity exception exit in class javax.crypto.JceSecurity RuleTriggerMethodAdapter.injectTriggerPoint : inserting trigger into javax.crypto.JceSecurity.() void for rule JceSecurity exception exit org.jboss.byteman.agent.Transformer : inserted trigger for JceSecurity exception exit in class javax.crypto.JceSecurity Rule.execute called for JceSecurity exception exit_3:0 HelperManager.install for helper class org.jboss.byteman.rule.helper.Helper calling activated() for helper class org.jboss.byteman.rule.helper.Helper Default helper activated calling installed(JceSecurity exception exit) for helper classorg.jboss.byteman.rule.helper.Helper Installed rule using default helper : JceSecurity exception exit JceSecurity exception exit execute *** JceSecurity failed with exceptionjavax.crypto.JceSecurity.(JceSecurity.java:246) javax.crypto.Cipher.getInstance(Cipher.java:540) com.bs.util.encryption.AESEncryptDecrypt.getInitializedCipher(AESEncryptDecrypt.java:151) com.bs.util.encryption.AESEncryptDecrypt.decrypt(AESEncryptDecrypt.java:127) com.bs.util.encryption.AESEncryptDecryptProxy.decrypt(AESEncryptDecryptProxy.java:44) com.bs.util.DataSourceCredentialsProvider.getEmrCredentials(DataSourceCredentialsProvider.java:108) com.bs.util.DataSourceCredentialsProvider$1.load(DataSourceCredentialsProvider.java:59) com.bs.util.DataSourceCredentialsProvider$1.load(DataSourceCredentialsProvider.java:49) com.google.common.cache.LocalCache$LoadingValueReference.loadFuture(LocalCache.java:3529) com.google.common.cache.LocalCache$Segment.loadSync(LocalCache.java:2278) com.google.common.cache.LocalCache$Segment.lockedGetOrLoad(LocalCache.java:2155) com.google.common.cache.LocalCache$Segment.get(LocalCache.java:2045) com.google.common.cache.LocalCache.get(LocalCache.java:3953) com.google.common.cache.LocalCache.getOrLoad(LocalCache.java:3976) com.google.common.cache.LocalCache$LocalLoadingCache.get(LocalCache.java:4960) com.bs.util.DataSourceCredentialsProvider.getCredentials(DataSourceCredentialsProvider.java:82) com.bs.util.DataSourceCredentialsProvider_ClientProxy.getCredentials(DataSourceCredentialsProvider_ClientProxy.zig:186) io.quarkus.agroal.runtime.AgroalVaultCredentialsProviderPassword.asProperties(AgroalVaultCredentialsProviderPassword.java:21) io.agroal.api.security.AgroalDefaultSecurityProvider.getSecurityProperties(AgroalDefaultSecurityProvider.java:23) io.agroal.pool.ConnectionFactory.securityProperties(ConnectionFactory.java:190) io.agroal.pool.ConnectionFactory.securityProperties(ConnectionFactory.java:179) io.agroal.pool.ConnectionFactory.jdbcProperties(ConnectionFactory.java:160) io.agroal.pool.ConnectionFactory.createConnection(ConnectionFactory.java:204) io.agroal.pool.ConnectionPool$CreateConnectionTask.call(ConnectionPool.java:470) io.agroal.pool.ConnectionPool$CreateConnectionTask.call(ConnectionPool.java:452) java.util.concurrent.FutureTask.run(FutureTask.java:264) io.agroal.pool.util.PriorityScheduledExecutor.beforeExecute(PriorityScheduledExecutor.java:68) java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1126) java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) java.lang.Thread.run(Thread.java:829) java.util.ServiceConfigurationError: java.net.spi.URLStreamHandlerProvider: Provider org.infinispan.commons.jdkspecific.ClasspathURLStreamHandlerProvider not found at java.base/java.util.ServiceLoader.fail(ServiceLoader.java:589) at java.base/java.util.ServiceLoader$LazyClassPathLookupIterator.nextProviderClass(ServiceLoader.java:1212) at java.base/java.util.ServiceLoader$LazyClassPathLookupIterator.hasNextService(ServiceLoader.java:1221) at java.base/java.util.ServiceLoader$LazyClassPathLookupIterator.hasNext(ServiceLoader.java:1265) at java.base/java.util.ServiceLoader$2.hasNext(ServiceLoader.java:1300) at java.base/java.util.ServiceLoader$3.hasNext(ServiceLoader.java:1385) at java.base/java.net.URL$1.getNext(URL.java:1314) at java.base/java.net.URL$1.hasNext(URL.java:1329) at java.base/java.net.URL$2.run(URL.java:1355) at java.base/java.net.URL$2.run(URL.java:1352) at java.base/java.security.AccessController.doPrivileged(Native Method) at java.base/java.net.URL.lookupViaProviders(URL.java:1351) at java.base/java.net.URL.getURLStreamHandler(URL.java:1437) at java.base/java.net.URL.(URL.java:651) at java.base/java.net.URL.(URL.java:541) at java.base/java.net.URL.(URL.java:488) at java.base/javax.crypto.JceSecurity.(JceSecurity.java:239) at java.base/javax.crypto.Cipher.getInstance(Cipher.java:540) at com.bs.util.encryption.AESEncryptDecrypt.getInitializedCipher(AESEncryptDecrypt.java:151) at com.bs.util.encryption.AESEncryptDecrypt.decrypt(AESEncryptDecrypt.java:127) at com.bs.util.encryption.AESEncryptDecryptProxy.decrypt(AESEncryptDecryptProxy.java:44) at com.bs.util.DataSourceCredentialsProvider.getEmrCredentials(DataSourceCredentialsProvider.java:108) at com.bs.util.DataSourceCredentialsProvider$1.load(DataSourceCredentialsProvider.java:59) at com.bs.util.DataSourceCredentialsProvider$1.load(DataSourceCredentialsProvider.java:49) at com.google.common.cache.LocalCache$LoadingValueReference.loadFuture(LocalCache.java:3529) at com.google.common.cache.LocalCache$Segment.loadSync(LocalCache.java:2278) at com.google.common.cache.LocalCache$Segment.lockedGetOrLoad(LocalCache.java:2155) at com.google.common.cache.LocalCache$Segment.get(LocalCache.java:2045) at com.google.common.cache.LocalCache.get(LocalCache.java:3953) at com.google.common.cache.LocalCache.getOrLoad(LocalCache.java:3976) at com.google.common.cache.LocalCache$LocalLoadingCache.get(LocalCache.java:4960) at com.bs.util.DataSourceCredentialsProvider.getCredentials(DataSourceCredentialsProvider.java:82) at com.bs.util.DataSourceCredentialsProvider_ClientProxy.getCredentials(DataSourceCredentialsProvider_ClientProxy.zig:186) at io.quarkus.agroal.runtime.AgroalVaultCredentialsProviderPassword.asProperties(AgroalVaultCredentialsProviderPassword.java:21) at io.agroal.api.security.AgroalDefaultSecurityProvider.getSecurityProperties(AgroalDefaultSecurityProvider.java:23) at io.agroal.pool.ConnectionFactory.securityProperties(ConnectionFactory.java:190) at io.agroal.pool.ConnectionFactory.securityProperties(ConnectionFactory.java:179) at io.agroal.pool.ConnectionFactory.jdbcProperties(ConnectionFactory.java:160) at io.agroal.pool.ConnectionFactory.createConnection(ConnectionFactory.java:204) at io.agroal.pool.ConnectionPool$CreateConnectionTask.call(ConnectionPool.java:470) at io.agroal.pool.ConnectionPool$CreateConnectionTask.call(ConnectionPool.java:452) at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) at io.agroal.pool.util.PriorityScheduledExecutor.beforeExecute(PriorityScheduledExecutor.java:68) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1126) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) at java.base/java.lang.Thread.run(Thread.java:829)

And here is the log w/o Byteman.

2021-08-26 08:38:41,374 ERROR [io.qua.run.Application] (main) Failed to start application (with profile prod): java.lang.NoClassDefFoundError: Could not initialize class javax.crypto.JceSecurity at java.base/javax.crypto.Cipher.getInstance(Cipher.java:540) at com.bs.util.encryption.AESEncryptDecrypt.getInitializedCipher(AESEncryptDecrypt.java:151) at com.bs.util.encryption.AESEncryptDecrypt.decrypt(AESEncryptDecrypt.java:127) at com.bs.util.encryption.AESEncryptDecryptProxy.decrypt(AESEncryptDecryptProxy.java:44) at com.bs.util.DataSourceCredentialsProvider.getEmrCredentials(DataSourceCredentialsProvider.java:108) at com.bs.util.DataSourceCredentialsProvider$1.load(DataSourceCredentialsProvider.java:59) at com.bs.util.DataSourceCredentialsProvider$1.load(DataSourceCredentialsProvider.java:49) at com.google.common.cache.LocalCache$LoadingValueReference.loadFuture(LocalCache.java:3529) at com.google.common.cache.LocalCache$Segment.loadSync(LocalCache.java:2278) at com.google.common.cache.LocalCache$Segment.lockedGetOrLoad(LocalCache.java:2155) at com.google.common.cache.LocalCache$Segment.get(LocalCache.java:2045) at com.google.common.cache.LocalCache.get(LocalCache.java:3953) at com.google.common.cache.LocalCache.getOrLoad(LocalCache.java:3976) at com.google.common.cache.LocalCache$LocalLoadingCache.get(LocalCache.java:4960) at com.bs.util.DataSourceCredentialsProvider.getCredentials(DataSourceCredentialsProvider.java:82) at com.bs.util.DataSourceCredentialsProvider_ClientProxy.getCredentials(DataSourceCredentialsProvider_ClientProxy.zig:186) at io.quarkus.agroal.runtime.AgroalVaultCredentialsProviderPassword.asProperties(AgroalVaultCredentialsProviderPassword.java:21) at io.agroal.api.security.AgroalDefaultSecurityProvider.getSecurityProperties(AgroalDefaultSecurityProvider.java:23) at io.agroal.pool.ConnectionFactory.securityProperties(ConnectionFactory.java:190) at io.agroal.pool.ConnectionFactory.securityProperties(ConnectionFactory.java:179) at io.agroal.pool.ConnectionFactory.jdbcProperties(ConnectionFactory.java:160) at io.agroal.pool.ConnectionFactory.createConnection(ConnectionFactory.java:204) at io.agroal.pool.ConnectionPool$CreateConnectionTask.call(ConnectionPool.java:470) at io.agroal.pool.ConnectionPool$CreateConnectionTask.call(ConnectionPool.java:452) at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) at io.agroal.pool.util.PriorityScheduledExecutor.beforeExecute(PriorityScheduledExecutor.java:68) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1126) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) at java.base/java.lang.Thread.run(Thread.java:829)

Notice that w/o Byteman everything that happens inside of Cipher.getInstance(Cipher.java:540) is lost.

jaikiran commented 3 years ago

Thank you very much for that stacktrace. That's very useful. So here's the relevant one from your post:

org.jboss.byteman.agent.Transformer : possible trigger for rule JceSecurity exception exit in class javax.crypto.JceSecurity RuleTriggerMethodAdapter.injectTriggerPoint : inserting trigger into javax.crypto.JceSecurity.() void for rule JceSecurity exception exit org.jboss.byteman.agent.Transformer : inserted trigger for JceSecurity exception exit in class javax.crypto.JceSecurity Rule.execute called for JceSecurity exception exit_3:0 HelperManager.install for helper class org.jboss.byteman.rule.helper.Helper calling activated() for helper class org.jboss.byteman.rule.helper.Helper Default helper activated calling installed(JceSecurity exception exit) for helper classorg.jboss.byteman.rule.helper.Helper Installed rule using default helper : JceSecurity exception exit JceSecurity exception exit execute *** JceSecurity failed with exceptionjavax.crypto.JceSecurity.(JceSecurity.java:246) javax.crypto.Cipher.getInstance(Cipher.java:540) com.bs.util.encryption.AESEncryptDecrypt.getInitializedCipher(AESEncryptDecrypt.java:151) com.bs.util.encryption.AESEncryptDecrypt.decrypt(AESEncryptDecrypt.java:127) com.bs.util.encryption.AESEncryptDecryptProxy.decrypt(AESEncryptDecryptProxy.java:44) com.bs.util.DataSourceCredentialsProvider.getEmrCredentials(DataSourceCredentialsProvider.java:108) com.bs.util.DataSourceCredentialsProvider$1.load(DataSourceCredentialsProvider.java:59) com.bs.util.DataSourceCredentialsProvider$1.load(DataSourceCredentialsProvider.java:49) com.google.common.cache.LocalCache$LoadingValueReference.loadFuture(LocalCache.java:3529) com.google.common.cache.LocalCache$Segment.loadSync(LocalCache.java:2278) com.google.common.cache.LocalCache$Segment.lockedGetOrLoad(LocalCache.java:2155) com.google.common.cache.LocalCache$Segment.get(LocalCache.java:2045) com.google.common.cache.LocalCache.get(LocalCache.java:3953) com.google.common.cache.LocalCache.getOrLoad(LocalCache.java:3976) com.google.common.cache.LocalCache$LocalLoadingCache.get(LocalCache.java:4960) com.bs.util.DataSourceCredentialsProvider.getCredentials(DataSourceCredentialsProvider.java:82) com.bs.util.DataSourceCredentialsProvider_ClientProxy.getCredentials(DataSourceCredentialsProvider_ClientProxy.zig:186) io.quarkus.agroal.runtime.AgroalVaultCredentialsProviderPassword.asProperties(AgroalVaultCredentialsProviderPassword.java:21) io.agroal.api.security.AgroalDefaultSecurityProvider.getSecurityProperties(AgroalDefaultSecurityProvider.java:23) io.agroal.pool.ConnectionFactory.securityProperties(ConnectionFactory.java:190) io.agroal.pool.ConnectionFactory.securityProperties(ConnectionFactory.java:179) io.agroal.pool.ConnectionFactory.jdbcProperties(ConnectionFactory.java:160) io.agroal.pool.ConnectionFactory.createConnection(ConnectionFactory.java:204) io.agroal.pool.ConnectionPool$CreateConnectionTask.call(ConnectionPool.java:470) io.agroal.pool.ConnectionPool$CreateConnectionTask.call(ConnectionPool.java:452) java.util.concurrent.FutureTask.run(FutureTask.java:264) io.agroal.pool.util.PriorityScheduledExecutor.beforeExecute(PriorityScheduledExecutor.java:68) java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1126) java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) java.lang.Thread.run(Thread.java:829) java.util.ServiceConfigurationError: java.net.spi.URLStreamHandlerProvider: Provider org.infinispan.commons.jdkspecific.ClasspathURLStreamHandlerProvider not found at java.base/java.util.ServiceLoader.fail(ServiceLoader.java:589) at java.base/java.util.ServiceLoader$LazyClassPathLookupIterator.nextProviderClass(ServiceLoader.java:1212) at java.base/java.util.ServiceLoader$LazyClassPathLookupIterator.hasNextService(ServiceLoader.java:1221) at java.base/java.util.ServiceLoader$LazyClassPathLookupIterator.hasNext(ServiceLoader.java:1265) at java.base/java.util.ServiceLoader$2.hasNext(ServiceLoader.java:1300) at java.base/java.util.ServiceLoader$3.hasNext(ServiceLoader.java:1385) at java.base/java.net.URL$1.getNext(URL.java:1314) at java.base/java.net.URL$1.hasNext(URL.java:1329) at java.base/java.net.URL$2.run(URL.java:1355) at java.base/java.net.URL$2.run(URL.java:1352) at java.base/java.security.AccessController.doPrivileged(Native Method) at java.base/java.net.URL.lookupViaProviders(URL.java:1351) at java.base/java.net.URL.getURLStreamHandler(URL.java:1437) at java.base/java.net.URL.(URL.java:651) at java.base/java.net.URL.(URL.java:541) at java.base/java.net.URL.(URL.java:488) at java.base/javax.crypto.JceSecurity.(JceSecurity.java:239) at java.base/javax.crypto.Cipher.getInstance(Cipher.java:540) at com.bs.util.encryption.AESEncryptDecrypt.getInitializedCipher(AESEncryptDecrypt.java:151) at com.bs.util.encryption.AESEncryptDecrypt.decrypt(AESEncryptDecrypt.java:127) at com.bs.util.encryption.AESEncryptDecryptProxy.decrypt(AESEncryptDecryptProxy.java:44) at com.bs.util.DataSourceCredentialsProvider.getEmrCredentials(DataSourceCredentialsProvider.java:108) at com.bs.util.DataSourceCredentialsProvider$1.load(DataSourceCredentialsProvider.java:59) at com.bs.util.DataSourceCredentialsProvider$1.load(DataSourceCredentialsProvider.java:49) at com.google.common.cache.LocalCache$LoadingValueReference.loadFuture(LocalCache.java:3529) at com.google.common.cache.LocalCache$Segment.loadSync(LocalCache.java:2278) at com.google.common.cache.LocalCache$Segment.lockedGetOrLoad(LocalCache.java:2155) at com.google.common.cache.LocalCache$Segment.get(LocalCache.java:2045) at com.google.common.cache.LocalCache.get(LocalCache.java:3953) at com.google.common.cache.LocalCache.getOrLoad(LocalCache.java:3976) at com.google.common.cache.LocalCache$LocalLoadingCache.get(LocalCache.java:4960) at com.bs.util.DataSourceCredentialsProvider.getCredentials(DataSourceCredentialsProvider.java:82) at com.bs.util.DataSourceCredentialsProvider_ClientProxy.getCredentials(DataSourceCredentialsProvider_ClientProxy.zig:186) at io.quarkus.agroal.runtime.AgroalVaultCredentialsProviderPassword.asProperties(AgroalVaultCredentialsProviderPassword.java:21) at io.agroal.api.security.AgroalDefaultSecurityProvider.getSecurityProperties(AgroalDefaultSecurityProvider.java:23) at io.agroal.pool.ConnectionFactory.securityProperties(ConnectionFactory.java:190) at io.agroal.pool.ConnectionFactory.securityProperties(ConnectionFactory.java:179) at io.agroal.pool.ConnectionFactory.jdbcProperties(ConnectionFactory.java:160) at io.agroal.pool.ConnectionFactory.createConnection(ConnectionFactory.java:204) at io.agroal.pool.ConnectionPool$CreateConnectionTask.call(ConnectionPool.java:470) at io.agroal.pool.ConnectionPool$CreateConnectionTask.call(ConnectionPool.java:452) at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) at io.agroal.pool.util.PriorityScheduledExecutor.beforeExecute(PriorityScheduledExecutor.java:68) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1126) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) at java.base/java.lang.Thread.run(Thread.java:829)

There are at least 3 or 4 interesting points here:

  1. The call to a URL constructor is resulting into a java.lang.Error instead of an java.lang.Exception type. The javadoc of that constructor makes no mention of that. So this probably needs to be raised and discussed with the JDK team.

  2. A java.lang.Error that gets thrown from a static initialization block of a class doesn't seem to raise a ExceptionInInitializerError. Instead it just throws back the Error. This is unlike the case where an java.lang.Exception gets thrown from a static initialization block, where such exceptions are wrapped into ExceptionInInitializerError. I actually tried this again in that trivial Java code I pasted previously and threw an Error from Bar instead of an Exception and running it I see that it just throws the original Error and doesn't wrap it into a ExceptionInInitializerError. So that explains why the ExceptionInInitializerError byteman rule didn't get triggered in this flow. The javadoc of ExceptionInInitializerError makes no distinction between these 2 cases, so again this needs some inputs from the JDK team.

  3. Finally, the mysterious part that we have been trying to understand - who is eating this exception. From that stacktrace, it looks to me that the the Error, just "falls off" the thread. What I mean is, this looks like an "uncaught exception/error" that happens in a thread created by the io.agroal.pool.util.PriorityScheduledExecutor$PriorityExecutorThreadFactory and run by the io.agroal.pool.util.PriorityScheduledExecutor. This Error goes uncaught and the thread dies (as expected) and this error/exception never gets reported. Then certain other thread tries to use that JceSecurity class which has already failed in its class definition and thus runs into the NoClassDefFoundError. @stuartwdouglas, do you think we should add a UncaughtExceptionHandler to the Thread created in PriorityExecutorThreadFactory[1] and log any uncaught errors?

  4. The new mystery - Now if the previous Error isn't being reported/logged, then how come the NoClassDefFoundError which too is a Error type gets logged, from the exact same flow like this:

    2021-08-26 08:38:41,374 ERROR [io.qua.run.Application] (main) Failed to start application (with profile prod): java.lang.NoClassDefFoundError: Could not initialize class javax.crypto.JceSecurity at java.base/javax.crypto.Cipher.getInstance(Cipher.java:540) at com.bs.util.encryption.AESEncryptDecrypt.getInitializedCipher(AESEncryptDecrypt.java:151) ... at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) at io.agroal.pool.util.PriorityScheduledExecutor.beforeExecute(PriorityScheduledExecutor.java:68) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1126) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) at java.base/java.lang.Thread.run(Thread.java:829)

Looking at the place where that log message is coming from, it's this catch block[2] in io.quarkus.runtime.ApplicationLifecycleManager. However that catch block is catching Exception type and not Error type. So it appears like there's some code somewhere which is catching, not all, but very specific Error types and wrapping them into an Exception and throwing it, in that flow. I'm not 100% certain about this. I don't remember seeing code which only deals with certain Error types and wraps them into Exception, in Quarkus. Unfortunately, that context is lost in that stacktrace, because we in that same catch block only log the rootCause[3] instead of the whole contextual stacktrace. @stuartwdouglas, do you think, in this else block (where we are done checking for specific root causes) we should log the whole exception stacktrace instead of just the root cause, to help in issues like these?

[1] https://github.com/agroal/agroal/blob/master/agroal-pool/src/main/java/io/agroal/pool/util/PriorityScheduledExecutor.java#L109 [2] https://github.com/quarkusio/quarkus/blob/main/core/runtime/src/main/java/io/quarkus/runtime/ApplicationLifecycleManager.java#L149 [3] https://github.com/quarkusio/quarkus/blob/main/core/runtime/src/main/java/io/quarkus/runtime/ApplicationLifecycleManager.java#L206

stuartwdouglas commented 3 years ago

I have opened https://github.com/agroal/agroal/pull/39

jaikiran commented 3 years ago

The call to a URL constructor is resulting into a java.lang.Error instead of an java.lang.Exception type. The javadoc of that constructor makes no mention of that. So this probably needs to be raised and discussed with the JDK team.

I read up the docs in detail today and as per[2]:

If no URLStreamHandlerFactory has yet been set up, or if the factory's createURLStreamHandler method returns null, then the ServiceLoader mechanism is used to locate URLStreamHandlerProvider implementations using the system class loader. The order that providers are located is implementation specific, and an implementation is free to cache the located providers. A ServiceConfigurationError, Error or RuntimeException thrown from the createURLStreamHandler, if encountered, will be propagated to the calling thread

So that API is behaving fine as per what it states in its javadocs.

[2] https://docs.oracle.com/en/java/javase/11/docs/api/java.base/java/net/URL.html#%3Cinit%3E(java.lang.String,java.lang.String,int,java.lang.String)

jaikiran commented 3 years ago

A java.lang.Error that gets thrown from a static initialization block of a class doesn't seem to raise a ExceptionInInitializerError. Instead it just throws back the Error. This is unlike the case where an java.lang.Exception gets thrown from a static initialization block, where such exceptions are wrapped into ExceptionInInitializerError. I actually tried this again in that trivial Java code I pasted previously and threw an Error from Bar instead of an Exception and running it I see that it just throws the original Error and doesn't wrap it into a ExceptionInInitializerError. So that explains why the ExceptionInInitializerError byteman rule didn't get triggered in this flow. The javadoc of ExceptionInInitializerError makes no distinction between these 2 cases, so again this needs some inputs from the JDK team.

I read up the JLS and section 12.4.2[1] states:

Otherwise, the initializers must have completed abruptly by throwing some exception E. If the class of E is not Error or one of its subclasses, then create a new instance of the class ExceptionInInitializerError, with E as the argument, and use this object in place of E in the following step

So the current behaviour is as per the spec, so there's no issue in this area.

I see that Stuart has opened a PR to fix agroal to log these exceptions that fall off the thread execution. So that should sort out the major part of this issue. The only final question is, should we improve the ApplicationLifeCycleManager to log the whole exception stacktrace instead of just the rootCause.

[1] https://docs.oracle.com/javase/specs/jls/se16/html/jls-12.html#jls-12.4.2