Signed jar dependency performance problem when repackaged in a single jar

[mathieufortin01]

Issue

Some 3rd party jars verify their own signature and makes sure it is signed by a specific signer, calling JarEntry.getCertificates() in the process. When these jars are handled by the Spring Boot Loader (as is the case when the jar is repackaged into a single jar), a long time can be spent searching for the certificates in the original jar entry and setting them in the loader's own entries. We have a case where it takes up to 5 min, delaying the startup of the Spring boot application.

Workaround

The current workaround is to not use Spring Boot maven plugin to generate an executable jar, and use the classic way of launching the jar with a classpath entry.

Fix

The fix is to filter out the entries we know won't be signed, ie directory entries and META-INF entries. It seems that specifically processing a directory messes up the "find & set certificate" routines, ending up being what it seems to be quadratic.

The test for this (JarFileTests.verifySignedJar) hid this problem by pre-filtering unsigned entries. If the test is modified to call getCertificates on all entries, the current jar used in the test (bouncy castle) takes close to 7 sec, which is too much.

I fiexd the issue by filtering out the unsigned entries. I also modified the test to detect this issue by setting up a maximum amount of time it should take for a jar to load.

[philwebb]

We'd like to have another look at JarFile.setupEntryCertificates to see if there are better ways to deal with loading the certs.

[mathieufortin01]

I changed JarFile.setupEntryCertificates(JarEntry) to JarFile.setupEntryCertificates(), as I didnt see the reasoning behind setting the certs for a single entry, and then for every entries. They now get set for all entries as soon as getCertificates is called on a signable entry in a signed jar.

I also enabled caching of the entries when JarFileEntries.EntryIterator.next is used, as it was set to false, leading to a bunch of unnecessary JarEntry creation (and it may have been related to the quadratic performance I was experiencing). I am not sure right now what triggers the cache clearing, but it looks like it gets cleared when running as a single jar.

I will update the pull request tomorrow.

[gjd6640]

Hello. I just ran into this same thing so am glad to see that a fix is in the works. Keep up the good work!

This OpenJDK bug fix is old news but I thought that its description of a lack of caching of metafiles and the resulting quadratic increase in read volumes sounded spookily similar to your diagnosis: https://bugs.openjdk.java.net/browse/JDK-6354728

I hope that you find this info helpful.

[chrismathews]

Any recent movement on this issue? We recently hit this problem when upgrading Bouncy Castle from 1.65 to 1.66 in our applications. When running the Spring Boot Plugin created uber jar we started to see a 20 - 30 second hit to our startup time when initializing Bouncy Castle. If we do a "classic" -cp style execution of the same application then there is no startup performance problems. We also noticed this only occurs on Java 11 and the problem did not exist if we ran against Java 8 (we didn't try any non-LTS releases of Java).

Nothing in the Bouncy Castle 1.66 release notes really jumped out at us as a potential cause and then we stumbled upon this PR. We did notice that the bcprov-jdk15on-1.65.jar was ~4.25MB in size vs the bcprov-jdk15on-1.66.jar which is ~5.61MB. Looking into a bit more and the META-INF for 1.66 is significantly larger than 1.65. So if this problem is anything like the bug referenced by @gjd6640 above then the steep increase in initialization time would make sense.

For the time being we are going to downgrade to Bouncy Castle 1.65 but that is obviously not a long-term solution. We are willing to help test or validate any proposed solution here.

[philwebb]

@mathieufortin01 Thanks very much for the PR and for the detailed issue report. I'm sorry it has taken us so long to get to this one. I've revised the fix quite a bit in commit c6a9696 (the commit message has some more details). Since this is actually quite a nasty issue I've applied the changes to 2.1.x forwards.

[philwebb]

@chrismathews Thanks for the additional info about Bouncy Castle 1.66.

We are willing to help test or validate any proposed solution here

Once CI build 871 has completed would you be able to try the latest SNAPSHOT of whatever branch you're on (assuming it's 2.1 or higher) to let us know if the fix has made a difference? We're planning to do a set of releases this week on Sep 17th.

[ShravanGottimukula]

@philwebb I work with @chrismathews. Tested the above changes with Bouncy Castle 1.66 and Spring Boot 2.3.4.BUILD-SNAPSHOT and we are now running into the below ClassCastException when running the spring boot plugin generated uber jar using java -jar. Attached the sample project to replicate the issue and the output.

bouncycastle-spring-boot-test.zip
output.txt

Caused by: java.lang.ClassCastException: class org.springframework.boot.loader.jar.JarEntry cannot be cast to class org.springframework.boot.loader.jar.CentralDirectoryFileHeader (org.springframework.boot.loader.jar.JarEntry and org.springframework.boot.loader.jar.CentralDirectoryFileHeader are in unnamed module of loader 'app')
	at org.springframework.boot.loader.jar.JarFileEntries.getEntryIndex(JarFileEntries.java:380) ~[bouncycastle-spring-boot-test-0.0.1-SNAPSHOT.jar:0.0.1-SNAPSHOT]

Please let us know if you need any more info.

Environment:
Java 11.0.8
Maven 3.6.3

[philwebb]

@ShravanGottimukula Thanks very much for testing the snapshot. I see the issue and I've pushed a fix but unfortunately I can't get the sample to fail in the same way on my local box. Perhaps it's due to a different Java build or a different OS.

When build 1384 has finished, could you please try the sample again on your side. If you run mvn with -U it should force a fresh of the SNAPSHOT dependencies.

[ShravanGottimukula]

@philwebb Now running into the below error with the latest snapshot build

Environment:
Windows 10
Oracle Java 11.0.8
Maven 3.6.3
Spring Boot 2.3.4.BUILD-SNAPSHOT

Caused by: java.util.jar.JarException: jar:file:/C:/workspaces/bouncycastle-spring-boot-test/target/bouncycastle-spring-boot-test-0.0.1-SNAPSHOT.jar!/BOOT-INF/lib/bcprov-jdk15on-1.66.jar!/ has unsigned entries - META-INF/services/java.security.Provider at java.base/javax.crypto.JarVerifier.verifySingleJar(JarVerifier.java:459) ~[na:na] at java.base/javax.crypto.JarVerifier.verifyJars(JarVerifier.java:314) ~[na:na] at java.base/javax.crypto.JarVerifier.verify(JarVerifier.java:257) ~[na:na] at java.base/javax.crypto.ProviderVerifier.verify(ProviderVerifier.java:129) ~[na:na] at java.base/javax.crypto.JceSecurity.verifyProvider(JceSecurity.java:191) ~[na:na] at java.base/javax.crypto.JceSecurity.getVerificationResult(JceSecurity.java:217) ~[na:na] at java.base/javax.crypto.JceSecurity.getInstance(JceSecurity.java:141) ~[na:na] ... 43 common frames omitted

[philwebb]

Thanks @ShravanGottimukula. I've now managed to replicate this on a Windows box using the Oracle JVM

[philwebb]

Third time's a charm. I made a stupid mistake by not closing the entry before reading the certificates.

@ShravanGottimukula the sample now works for me, can you try it and your original application to see if things work and if the performance is better?

[ShravanGottimukula]

@philwebb Looks good now. Tested with 2.3.4.BUILD-SNAPSHOT, 2.2.10.BUILD-SNAPSHOT and 2.1.17.BUILD-SNAPSHOT and all of them work and the signed jar verification is much faster now with no noticeable slowness at all.

[philwebb]

@ShravanGottimukula Thanks very much for testing it again. 👍