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.

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

PropertiesLauncher fails to load PBKDF-OpenSSL of bcprov-jdk15on-1.64.jar #23165

Closed
ziqianggeoffreychen opened this issue Sep 2, 2020 · 20 comments
Assignees
Labels
type: regression A regression from a previous release
Milestone

Comments

@ziqianggeoffreychen
Copy link

ziqianggeoffreychen commented Sep 2, 2020

Spring Boot version: 2.3.1.RELEASE

The bouncy castle jar is embedded into spring boot fat jar, while JarLauncher can load the exactly same PBKDF-OpenSSL algorithm, PropertiesLauncher fails to load. Below is the exception:

Caused by: java.security.NoSuchAlgorithmException: PBKDF-OpenSSL SecretKeyFactory not available
	at javax.crypto.SecretKeyFactory.<init>(SecretKeyFactory.java:122)
	at javax.crypto.SecretKeyFactory.getInstance(SecretKeyFactory.java:160)
	at org.bouncycastle.jcajce.util.DefaultJcaJceHelper.createSecretKeyFactory(Unknown Source)
	... 72 common frames omitted

After troubleshooting into javax.crypto.SecretKeyFactory, below eaten exception is identified as the root cause:

private void ensureOpen() {
if (this.closed) {
throw new IllegalStateException("zip file closed");
}
}

Why would it behave differently between JarLauncher and PropertiesLauncher on this SecretKeyFactory?

Full "zip file closed" exception stack trace by IntelliJ IDEA:

<init>(String):-1, IllegalStateException (java.lang), Unknown Source
ensureOpen():365, JarFile (org.springframework.boot.loader.jar), JarFile.java
getEntry(String):266, JarFile (org.springframework.boot.loader.jar), JarFile.java
getJarEntry(String):257, JarFile (org.springframework.boot.loader.jar), JarFile.java
setupEntryCertificates(JarEntry):420, JarFile (org.springframework.boot.loader.jar), JarFile.java
getCertificates():91, JarEntry (org.springframework.boot.loader.jar), JarEntry.java
verifySingleJar(URL):497, JarVerifier (javax.crypto), JarVerifier.java
verifyJars(URL, List):363, JarVerifier (javax.crypto), JarVerifier.java
verify():289, JarVerifier (javax.crypto), JarVerifier.java
verifyProviderJar(URL):164, JceSecurity (javax.crypto), JceSecurity.java
getVerificationResult(Provider):190, JceSecurity (javax.crypto), JceSecurity.java
canUseProvider(Provider):204, JceSecurity (javax.crypto), JceSecurity.java
nextSpi(SecretKeyFactorySpi):295, SecretKeyFactory (javax.crypto), SecretKeyFactory.java
<init>(String):121, SecretKeyFactory (javax.crypto), SecretKeyFactory.java
getInstance(String):160, SecretKeyFactory (javax.crypto), SecretKeyFactory.java
createSecretKeyFactory(String):-1, DefaultJcaJceHelper (org.bouncycastle.jcajce.util), Unknown Source
getKey(JcaJceHelper, char[], String, int, byte[], boolean):-1, PEMUtilities (org.bouncycastle.openssl.jcajce), Unknown Source
getKey(JcaJceHelper, char[], String, int, byte[]):-1, PEMUtilities (org.bouncycastle.openssl.jcajce), Unknown Source
crypt(boolean, JcaJceHelper, byte[], char[], String, byte[]):-1, PEMUtilities (org.bouncycastle.openssl.jcajce), Unknown Source
decrypt(byte[], byte[]):-1, JcePEMDecryptorProviderBuilder$1$1 (org.bouncycastle.openssl.jcajce), Unknown Source
decryptKeyPair(PEMDecryptorProvider):-1, PEMEncryptedKeyPair (org.bouncycastle.openssl), Unknown Source
convertEncryptedPrivateKey(String, String):135, SignKeyProviderPemImpl (com.ericsson.jee.iam.saml.keyprovider), SignKeyProviderPemImpl.java
@spring-projects-issues spring-projects-issues added the status: waiting-for-triage An issue we've not yet triaged label Sep 2, 2020
@wilkinsona
Copy link
Member

Why would it behave differently between JarLauncher and PropertiesLauncher on this SecretKeyFactory?

That will depend on how you have created and configured the PropertiesLauncher. If you would like us to spend some more time investigating, please spend some time providing a complete yet minimal sample that reproduces the problem. You can share it with us by pushing it to a separate repository on GitHub or by zipping it up and attaching it to this issue.

@wilkinsona wilkinsona added the status: waiting-for-feedback We need additional information before we can continue label Sep 2, 2020
@ziqianggeoffreychen
Copy link
Author

Hi Andy,

Thanks for your prompt response and beautify my initial post. Please clone my reproduction code from this repo and refer to the Readme document if needed: https://github.com/ziqianggeoffreychen/spring-boot-properties-launcher-with-broken-bcp

@spring-projects-issues spring-projects-issues added status: feedback-provided Feedback has been provided and removed status: waiting-for-feedback We need additional information before we can continue labels Sep 2, 2020
@wilkinsona
Copy link
Member

Thanks for the sample, @ziqianggeoffreychen. Unfortunately, it does fail for me but with a different error. This is the failure that I get when launching the application with java -jar on macOS:

2020-09-02 17:06:06.216 ERROR 80131 --- [           main] c.e.restservice.RestServiceApplication   : Failed to convert private key
Exception in thread "main" java.lang.reflect.InvocationTargetException
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.springframework.boot.loader.MainMethodRunner.run(MainMethodRunner.java:49)
	at org.springframework.boot.loader.Launcher.launch(Launcher.java:109)
	at org.springframework.boot.loader.Launcher.launch(Launcher.java:58)
	at org.springframework.boot.loader.PropertiesLauncher.main(PropertiesLauncher.java:466)
Caused by: java.lang.RuntimeException: Failed to convert private key
	at com.example.restservice.RestServiceApplication.convertEncryptedPrivateKey(RestServiceApplication.java:70)
	at com.example.restservice.RestServiceApplication.main(RestServiceApplication.java:38)
	... 8 more
Caused by: org.bouncycastle.openssl.EncryptionException: exception using cipher - please check password and data.
	at org.bouncycastle.openssl.jcajce.PEMUtilities.crypt(Unknown Source)
	at org.bouncycastle.openssl.jcajce.JcePEMDecryptorProviderBuilder$1$1.decrypt(Unknown Source)
	at org.bouncycastle.openssl.PEMEncryptedKeyPair.decryptKeyPair(Unknown Source)
	at com.example.restservice.RestServiceApplication.convertEncryptedPrivateKey(RestServiceApplication.java:63)
	... 9 more
Caused by: javax.crypto.BadPaddingException: Given final block not properly padded. Such issues can arise if a bad key is used during decryption.
	at com.sun.crypto.provider.CipherCore.unpad(CipherCore.java:975)
	at com.sun.crypto.provider.CipherCore.fillOutputBuffer(CipherCore.java:1056)
	at com.sun.crypto.provider.CipherCore.doFinal(CipherCore.java:853)
	at com.sun.crypto.provider.AESCipher.engineDoFinal(AESCipher.java:446)
	at javax.crypto.Cipher.doFinal(Cipher.java:2168)
	... 13 more

I see the same problem when launching the application in my IDE (having removed the classpath: prefix when accessing the resources as streams). Can you please update the sample so that it reproduces the behaviour that's specific to PropertiesLauncher?

@wilkinsona wilkinsona added status: waiting-for-feedback We need additional information before we can continue and removed status: feedback-provided Feedback has been provided labels Sep 2, 2020
@ziqianggeoffreychen
Copy link
Author

ziqianggeoffreychen commented Sep 3, 2020

Hi @wilkinsona, I have git clone the code in Linux (RHEL 7.6) and get the same error. I will find a macOS to verify if the result will change. At the same time, I would like to know your Java version. I am using Oracle JDK 1.8.0. On Windows 10, it is 1.8.0_251, while on RHEL it is 1.8.0_241. If it is caused by compatible issue between macOS and Windows, I will figure out a way to generate the PEM files from scratch. Thanks and regards.

@spring-projects-issues spring-projects-issues added status: feedback-provided Feedback has been provided and removed status: waiting-for-feedback We need additional information before we can continue labels Sep 3, 2020
@ziqianggeoffreychen
Copy link
Author

I verified macOS (10.14.6), and reproduced the issue. The point here is Java version should be 1.8.0. I used maven 3.6.3 but I guess that's not the key factor. @wilkinsona, I updated the project to compare ZIP and JAR layout: ZIP layout (PropertiesLauncher) results in NoSuchAlgorithmException, on the other hand, JAR layout (JarLauncher) is normal. Could you git pull and try again? Thanks.

@wilkinsona
Copy link
Member

Thanks for the updates, @ziqianggeoffreychen. Unfortunately, I'm still unable to reproduce the problem. I'm using Java 8:

$ java -version
openjdk version "1.8.0_252"
OpenJDK Runtime Environment (AdoptOpenJDK)(build 1.8.0_252-b09)
OpenJDK 64-Bit Server VM (AdoptOpenJDK)(build 25.252-b09, mixed mode)

The application runs successfully:

$ java -jar target/spring-boot-properties-launcher-with-broken-bcp-0.0.1-SNAPSHOT.jar

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::        (v2.3.1.RELEASE)

2020-09-03 09:49:02.632  INFO 21819 --- [           main] c.e.restservice.RestServiceApplication   : Starting RestServiceApplication v0.0.1-SNAPSHOT on wilkinsona-a01.vmware.com with PID 21819 (/Users/awilkinson/dev/temp/spring-boot-properties-launcher-with-broken-bcp/target/spring-boot-properties-launcher-with-broken-bcp-0.0.1-SNAPSHOT.jar started by awilkinson in /Users/awilkinson/dev/temp/spring-boot-properties-launcher-with-broken-bcp)
2020-09-03 09:49:02.635  INFO 21819 --- [           main] c.e.restservice.RestServiceApplication   : No active profile set, falling back to default profiles: default
2020-09-03 09:49:03.398  INFO 21819 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat initialized with port(s): 8080 (http)
2020-09-03 09:49:03.405  INFO 21819 --- [           main] o.apache.catalina.core.StandardService   : Starting service [Tomcat]
2020-09-03 09:49:03.406  INFO 21819 --- [           main] org.apache.catalina.core.StandardEngine  : Starting Servlet engine: [Apache Tomcat/9.0.36]
2020-09-03 09:49:03.449  INFO 21819 --- [           main] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring embedded WebApplicationContext
2020-09-03 09:49:03.449  INFO 21819 --- [           main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 766 ms
2020-09-03 09:49:03.576  INFO 21819 --- [           main] o.s.s.concurrent.ThreadPoolTaskExecutor  : Initializing ExecutorService 'applicationTaskExecutor'
2020-09-03 09:49:03.706  INFO 21819 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat started on port(s): 8080 (http) with context path ''
2020-09-03 09:49:03.716  INFO 21819 --- [           main] c.e.restservice.RestServiceApplication   : Started RestServiceApplication in 1.463 seconds (JVM running for 2.314)
2020-09-03 09:49:03.736  INFO 21819 --- [           main] o.s.s.concurrent.ThreadPoolTaskExecutor  : Shutting down ExecutorService 'applicationTaskExecutor'
2020-09-03 09:49:03.736  INFO 21819 --- [           main] c.e.restservice.RestServiceApplication   : Start to get certificate
2020-09-03 09:49:03.883  INFO 21819 --- [           main] c.e.restservice.RestServiceApplication   : Successfully get certificate:   [0]         Version: 3
         SerialNumber: 4098
             IssuerDN: C=CN,ST=IDP,O=IDP,OU=IDP,CN=IDP
           Start Date: Mon Jan 13 07:00:28 GMT 2020
           Final Date: Thu Jan 10 07:00:28 GMT 2030
            SubjectDN: C=CN,ST=IDP,O=IDP,OU=IDP,CN=IDP
           Public Key: RSA Public Key [eb:30:b4:21:24:d1:f7:a4:7b:0b:29:73:d7:1c:ca:d5:60:33:26:6b],[56:66:d1:a4]
        modulus: cd198475b2aae40a2c664b03e37ca01939a066a2f0056cbf374bb6b8467bbcc4505a7bb812edcf9de1f3cfae2fbfb536597482fc477b954bed5d8177a1f33806b050b4d63df7f36c67cb140be77dc1208563461a8b654627536b0533806b3977c671ce06e08013babc0353307e1d450befb474f92f161922f333e99f560db29d16b7fddb6a7e86998421aeff5da03351e43ff62ee1b4dfd725971adf97a60f4be4400783c74553d14d094cb920c87179a823745af9e43551d2022d95a9e522c48e38d9c3292d997447db380bfa842ea92219b1c107649af8f7640d062bcdd950ed5c080786d41f96ed667463d7858e9e889b6b81efc1ddca771759a238cccff9
public exponent: 10001

  Signature Algorithm: SHA256WITHRSA
            Signature: 72ee82487d59132cfcbb91c7029a3c80451f204b
                       870b8bac450013bf4018b301ed6869849e74b234
                       8a1d44744e28fdcd233f7bf54f0471ca3d805354
                       ffbda5e1d84b35024861c604de7e820788b1133b
                       959f6f2722bcc8ce3b1adbf420635150412df98c
                       e0763e344906181af8a560336a8bca6df4285a69
                       8a6e1d9fb5b8f059aca43b1af5ce4152bb68b3be
                       683535edd325554c6b2806e8201909f21e86e9b8
                       9185859ecbed96e0e5f69d2147d21687f2e25fef
                       de1236e63ae94db983cbe8f6d0fd4238e7b08449
                       9fba16b0d8502abeec51d4040dbc1ee58fa46cf3
                       4eabe26c66c60f856f3780d9cbaabffce1714e57
                       1a11226cc4dc1efd0d2ea53b15262016
       Extensions: 
                       critical(false) BasicConstraints: isCa(false)
                       critical(false) 2.16.840.1.113730.1.13 value = IA5String(OpenSSL Generated Certificate) 

                       critical(false) 2.5.29.14 value = DER Octet String[20] 

                       critical(false) 2.5.29.35 value = Sequence
    Tagged [0] IMPLICIT 
        DER Octet String[20] 


2020-09-03 09:49:03.885  INFO 21819 --- [           main] c.e.restservice.RestServiceApplication   : Try to get RSA private key via PEM:

-----BEGIN RSA PRIVATE KEY-----
Proc-Type: 4,ENCRYPTED
DEK-Info: AES-128-CBC,6400DD952EEE60C4CDE60B6C5C11C026

DzdbEOz0XX56xAPagw5mIqmW5gPoGYaC+IPAqtwUZhO7RYQcA1tgE4N+aALZg0Q/
y97fQ0q1ww5RBDMKj8CzZacpVLJaJEQw/TZhUIPOGYRWfLIxZZ4Q4KdzbuWolt2P
yI9ZL/sFDfTJXnSOHN9kKX3hnuyW0EVZzaoL45SFbnJ2pu8elx4jy7VcT8FIcD4o
aERx89IB9rUXGPYcVtLGqziPg8fMV+YkKvM7qV/0LTSIRqwisZm6pxvUIPUVudTb
/hmIvr0ZGCTZwVFJBUmt81v2CovVUd83UaPmLiDbmCq4askfWGCIcWAeooQZj66f
6c7vgrk98SrL27h1qLUjdVVP29CU1u+qG9+3cCaEc7ufalZ+LihyTHe8rJFzBpwb
hbdUT4VWQXoiUBlMZrpzPaoLTSywfu+8gymIogy2l4udj943YeFEWgJQPxIQZISX
uKhVZ92jbYZYd+fogDIgvPUrUJBr0YrsCwik1o5IfEBFClgFDHkfKZkF1F7BwL4o
a9KswjmZpgIPDkqauVdTf9zwmFgcKC7ojc9lVdl4HXi+mDt0UcGfeH9Vahv1I16y
okLh60OC4+rGNtyVP/nhXoilCpYpq5F4HDZ8+6DFdi6i3BQgGF73nRa+ngfsgoPz
m1LM/vbz507pLns69PxTvxPVyLXpKbJdNV+OodR4tSNjsrCWbxIZPayNIfp23QC6
YctnhQNaGuJz3tSz/YwaSn7aN7aV+LBSoUf+c5Rj9OLh69lXkpyBAhRZudU185an
LMCMR6el6g4NkGG+gEYpz7Ux73ScIB9TTu3rzSxZPY+VCKeL7jm2gFN+lZpzO0p5
3pXTHQ1jOn8Wn21MK03PaBHkaNJu92v7zhsTi1fW6szOuLJtHzo+q6mNpp/G5cuM
oAx6Zjb88YE+iEfuo2+MG0j8oIlhtG5CC4ZuoB05Am9FRQmbZBg4pGgBld8Wq5bk
i84mV20eZ4iZg8IKFaIif+rNKBG0DTLzgTLTHKCP1x7YtyDh37DkiIqE62y+QNhd
DrVCFY2hH0Kw27LWSCmZt3gv5jgctofDMi3FEz/Uq5/ZFZVnTYeSvjDsBLObwoIC
21jKAVZoOgsRyK898A2Xni1DVWAxTafCkyxSuzGoVxnPkBGvgy33grZzOpE8/9Pl
2Z2nVZhhUMeeviIFyrfJ7vhuTyRLwxOntk0AfNT/tUqe/3JBJ4hFmyvqvBYtT7Jl
d9DApc10dFIFYQYNiBMXnqsqQmmocHujRU3QMFqDDcUDsepTmuTYfL+gr9fDwQQ9
Qaz/f3/+fHFYKn0XGdjDQOZ7ZQrZhdRnwBJAju0CBrwWD9K8SnySZ3I9qxWP2ASo
0FPmJmeD2hyx34N4WFpUfVJUQ4bm1czC/I8NNHD2azpURc9LqhARCtwTYJzsDE4G
igm0MSOnwoEv/oSm0xbbAcNAQhVxfbmdn43mw8FmXYZAbiWExBDS6QtNdTyJMbCt
izlEq5hZRQPYQwhKsQF6+ikSdMsFmoaz5YjXadgI9LEBn+oz6L7HU7RXEkaKOalA
zS3BdF3YytMqqxp6bPfohVLJ/w/F3w60/qKHkeTiHMbjDeDdWMVnf+xHcwXnU3on
-----END RSA PRIVATE KEY-----

2020-09-03 09:49:03.937  INFO 21819 --- [           main] c.e.restservice.RestServiceApplication   : Successfully get private keyRSA Private CRT Key [eb:30:b4:21:24:d1:f7:a4:7b:0b:29:73:d7:1c:ca:d5:60:33:26:6b],[56:66:d1:a4]
             modulus: cd198475b2aae40a2c664b03e37ca01939a066a2f0056cbf374bb6b8467bbcc4505a7bb812edcf9de1f3cfae2fbfb536597482fc477b954bed5d8177a1f33806b050b4d63df7f36c67cb140be77dc1208563461a8b654627536b0533806b3977c671ce06e08013babc0353307e1d450befb474f92f161922f333e99f560db29d16b7fddb6a7e86998421aeff5da03351e43ff62ee1b4dfd725971adf97a60f4be4400783c74553d14d094cb920c87179a823745af9e43551d2022d95a9e522c48e38d9c3292d997447db380bfa842ea92219b1c107649af8f7640d062bcdd950ed5c080786d41f96ed667463d7858e9e889b6b81efc1ddca771759a238cccff9
     public exponent: 10001

2020-09-03 09:49:03.937  INFO 21819 --- [           main] c.e.restservice.RestServiceApplication   : Test is done. Now exit.

@wilkinsona
Copy link
Member

I've just tried in a Windows 10 VM and it works there too. Unfortunately, I don't think we're going to be able to make any progress on this one without a sample that reproduces the problem.

@wilkinsona wilkinsona added status: waiting-for-feedback We need additional information before we can continue and removed status: feedback-provided Feedback has been provided labels Sep 3, 2020
@ziqianggeoffreychen
Copy link
Author

ziqianggeoffreychen commented Sep 3, 2020

@wilkinsona I realized that you are using OpenJDK while I am using Oracle JDK. Could you try Oracle JDK 1.8.0_251/261? I will try OpenJDK 1.8.0_252 as well. Thanks.

$ mvn -v
Apache Maven 3.6.3 (cecedd343002696d0abb50b32b541b8a6ba2883f)
Maven home: C:\software\apache-maven-3.6.3
Java version: 1.8.0_251, vendor: Oracle Corporation, runtime: C:\Program Files\Java\jdk1.8.0_251\jre
Default locale: en_US, platform encoding: Cp1252
OS name: "windows 10", version: "10.0", arch: "amd64", family: "windows"

@spring-projects-issues spring-projects-issues added status: feedback-provided Feedback has been provided and removed status: waiting-for-feedback We need additional information before we can continue labels Sep 3, 2020
@ziqianggeoffreychen
Copy link
Author

I confirm that when I change to OpenJDK, the issue disappears. Could you consider fully support on Oracle JDK? Our production is running on Oracle JDK. Thank you.

$ java -version
openjdk version "1.8.0_212"
OpenJDK Runtime Environment (build 1.8.0_212-b04)
OpenJDK 64-Bit Server VM (build 25.212-b04, mixed mode)

@wilkinsona
Copy link
Member

I've just tried with 1.8.0_261 from Oracle and have been able to reproduce the problem. I'll see if I can figure out why it behaves differently, but you may need to raise this with Oracle given that their JVM's behaviour has diverged from the behaviour of the OpenJDK upon which it is based.

@ziqianggeoffreychen
Copy link
Author

That's great! I also changed Spring Boot version to 2.3.3-RELEASE, v2.3.0.RELEASE, no difference. But when I downgrade it to v2.2.9.RELEASE (the nearest version to v2.3), the NoSuchAlgorithmException disappears. So I guess it is not an issue of Oracle JDK. Could you have a try and compare? Thanks.

@wilkinsona
Copy link
Member

The problem occurs with 2.3.0.RC1 but does not occur with 2.3.0.M4. #21072 seems to be the most likely culprit for that, however I don't yet understand the difference in behaviour between JarLauncher and PropertiesLauncher.

@wilkinsona wilkinsona added type: regression A regression from a previous release and removed status: feedback-provided Feedback has been provided status: waiting-for-triage An issue we've not yet triaged labels Sep 3, 2020
@wilkinsona wilkinsona added this to the 2.3.x milestone Sep 3, 2020
@wilkinsona
Copy link
Member

Here's a minimal reproduction of the problem:

package com.example;

import java.io.IOException;
import java.net.JarURLConnection;
import java.net.URL;
import java.security.cert.Certificate;
import java.util.Arrays;

import org.bouncycastle.jce.provider.BouncyCastleProvider;

public class Gh23165Application {

    public static void main(String[] args) throws IOException {
    	URL location = BouncyCastleProvider.class.getProtectionDomain().getCodeSource().getLocation();
    	JarURLConnection connection = (JarURLConnection)location.openConnection();
		Certificate[] certificates = connection.getJarFile().getJarEntry("org/bouncycastle/jce/provider/BouncyCastleProvider.class").getCertificates();
    	System.out.println(Arrays.toString(certificates));
    }

}

A dependency on org.bouncycastle:bcprov-jdk15on:1.64 is required. Using PropertiesLauncher, it fails with an exception:

Exception in thread "main" java.lang.reflect.InvocationTargetException
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.springframework.boot.loader.MainMethodRunner.run(MainMethodRunner.java:49)
	at org.springframework.boot.loader.Launcher.launch(Launcher.java:109)
	at org.springframework.boot.loader.Launcher.launch(Launcher.java:58)
	at org.springframework.boot.loader.PropertiesLauncher.main(PropertiesLauncher.java:466)
Caused by: java.lang.IllegalStateException: zip file closed
	at org.springframework.boot.loader.jar.JarFile.ensureOpen(JarFile.java:365)
	at org.springframework.boot.loader.jar.JarFile.getEntry(JarFile.java:266)
	at org.springframework.boot.loader.jar.JarFile.getJarEntry(JarFile.java:257)
	at org.springframework.boot.loader.jar.JarFile.setupEntryCertificates(JarFile.java:420)
	at org.springframework.boot.loader.jar.JarEntry.getCertificates(JarEntry.java:91)
	at com.example.Gh23165Application.main(Gh23165Application.java:16)
	... 8 more

Using JarLauncher it successfully prints the certificates from the JarEntry.

@wilkinsona
Copy link
Member

The failure occurs even earlier with 2.3.4 snapshots, happening when an attempt is made to load the application's main class:

Exception in thread "main" java.lang.IllegalStateException: zip file closed
	at org.springframework.boot.loader.jar.JarFile.ensureOpen(JarFile.java:349)
	at org.springframework.boot.loader.jar.JarFile.getEntry(JarFile.java:246)
	at org.springframework.boot.loader.jar.JarFileWrapper.getEntry(JarFileWrapper.java:77)
	at org.springframework.boot.loader.LaunchedURLClassLoader.lambda$definePackage$0(LaunchedURLClassLoader.java:225)
	at java.security.AccessController.doPrivileged(Native Method)
	at org.springframework.boot.loader.LaunchedURLClassLoader.definePackage(LaunchedURLClassLoader.java:217)
	at org.springframework.boot.loader.LaunchedURLClassLoader.definePackageIfNecessary(LaunchedURLClassLoader.java:199)
	at org.springframework.boot.loader.LaunchedURLClassLoader.loadClass(LaunchedURLClassLoader.java:140)
	at java.lang.ClassLoader.loadClass(ClassLoader.java:351)
	at java.lang.Class.forName0(Native Method)
	at java.lang.Class.forName(Class.java:348)
	at org.springframework.boot.loader.MainMethodRunner.run(MainMethodRunner.java:46)
	at org.springframework.boot.loader.Launcher.launch(Launcher.java:109)
	at org.springframework.boot.loader.Launcher.launch(Launcher.java:58)
	at org.springframework.boot.loader.PropertiesLauncher.main(PropertiesLauncher.java:466)

@wilkinsona
Copy link
Member

The behaviour difference with PropertiesLauncher is due to the archives being closed while the class loader's being created:

protected ClassLoader createClassLoader(Iterator<Archive> archives) throws Exception {
List<URL> urls = new ArrayList<>(50);
while (archives.hasNext()) {
Archive archive = archives.next();
urls.add(archive.getUrl());
archive.close();
}
return createClassLoader(urls.toArray(new URL[0]));
}

This doesn't happen with JarLauncher as ExecutableArchiveLauncher overrides the method and doesn't close the archives:

@Override
protected ClassLoader createClassLoader(Iterator<Archive> archives) throws Exception {
List<URL> urls = new ArrayList<>(guessClassPathSize());
while (archives.hasNext()) {
urls.add(archives.next().getUrl());
}
if (this.classPathIndex != null) {
urls.addAll(this.classPathIndex.getUrls());
}
return createClassLoader(urls.toArray(new URL[0]));
}

The close was added in ad72f86 but I can't tell why.

@wilkinsona wilkinsona added the for: team-attention An issue we'd like other members of the team to review label Sep 3, 2020
@philwebb
Copy link
Member

philwebb commented Sep 3, 2020

I wrote that polish commit, but I'm not sure why close was called explicitly. This might be related to #17126, but I'm having a hard time finding where we actually closed the archives in 2.2.

@ziqianggeoffreychen
Copy link
Author

ziqianggeoffreychen commented Sep 7, 2020

Hi @wilkinsona @philwebb , I added below tracing code to locate the root cause:

diff --git a/spring-boot-project/spring-boot-tools/spring-boot-loader/src/main/java/org/springframework/boot/loader/jar/JarFile.java b/spring-boot-project/spring-boot-tools/spring-boot-loade
r/src/main/java/org/springframework/boot/loader/jar/JarFile.java
index 53977396b9..730793d5fa 100644
--- a/spring-boot-project/spring-boot-tools/spring-boot-loader/src/main/java/org/springframework/boot/loader/jar/JarFile.java
+++ b/spring-boot-project/spring-boot-tools/spring-boot-loader/src/main/java/org/springframework/boot/loader/jar/JarFile.java
@@ -119,6 +119,12 @@ public class JarFile extends java.util.jar.JarFile implements Iterable<java.util
                this.parent = parent;
                this.rootFile = parent.rootFile;
                this.pathFromRoot = parent.pathFromRoot;
+               if (pathFromRoot.contains("bcpro")) {
+                       System.out.println("New JarFile " + pathFromRoot + " @ " + this.hashCode() +
+                                       ", from parent: " + parent.pathFromRoot + " @ " + parent.hashCode() +
+                                       ", with entries: " + parent.entries.hashCode());
+                       //Thread.dumpStack();
+               }
                this.data = parent.data;
                this.type = parent.type;
                this.url = parent.url;
@@ -151,6 +157,10 @@ public class JarFile extends java.util.jar.JarFile implements Iterable<java.util
                this.parent = parent;
                this.rootFile = rootFile;
                this.pathFromRoot = pathFromRoot;
+               if (pathFromRoot.contains("bcpro")) {
+                       System.out.println("New JarFile " + pathFromRoot + " @ " + this.hashCode());
+                       Thread.dumpStack();
+               }
                CentralDirectoryParser parser = new CentralDirectoryParser();
                this.entries = parser.addVisitor(new JarFileEntries(this, filter));
                this.type = type;
@@ -354,6 +364,10 @@ public class JarFile extends java.util.jar.JarFile implements Iterable<java.util
                if (this.closed) {
                        return;
                }
+               if (pathFromRoot.contains("bcpro")) {
+                       System.out.println("Closing " + pathFromRoot + " @ " + this.hashCode());
+                       //Thread.dumpStack();
+               }
                this.closed = true;
                if (this.type == JarFileType.DIRECT && this.parent == null) {
                        this.rootFile.close();
@@ -362,6 +376,8 @@ public class JarFile extends java.util.jar.JarFile implements Iterable<java.util

        private void ensureOpen() {
                if (this.closed) {
+                       System.out.println("In ensureOpen(): " + this.pathFromRoot + " @ " + this.hashCode());
+                       //Thread.dumpStack();
                        throw new IllegalStateException("zip file closed");
                }
        }
diff --git a/spring-boot-project/spring-boot-tools/spring-boot-loader/src/main/java/org/springframework/boot/loader/jar/JarFileEntries.java b/spring-boot-project/spring-boot-tools/spring-boo
t-loader/src/main/java/org/springframework/boot/loader/jar/JarFileEntries.java
index 40207fa2a7..e7038348d7 100644
--- a/spring-boot-project/spring-boot-tools/spring-boot-loader/src/main/java/org/springframework/boot/loader/jar/JarFileEntries.java
+++ b/spring-boot-project/spring-boot-tools/spring-boot-loader/src/main/java/org/springframework/boot/loader/jar/JarFileEntries.java
@@ -113,6 +113,7 @@ class JarFileEntries implements CentralDirectoryVisitor, Iterable<JarEntry> {
                if (RUNTIME_VERSION == BASE_VERSION) {
                        this.multiReleaseJar = false;
                }
+               System.out.println("New JarFileEntries [" + this.hashCode() + "] for " + jarFile.getPathFromRoot() + " @ " + jarFile.hashCode());
        }

        @Override

The JarFile for bcprov is instantiated once and then quickly closed by the above mentioned code archive.close(). The following JarFile instances are all based upon the very first instance as the parent thus share the same JarFileEntries collection. Within the JarFileEntries instance, the very first instance is associated as the back reference but it has been explicitly closed by archive.close(). Whenever this kind of new JarFile's entry is accessed, the real JarFile will be its closed parent rather than the new instance itself. Eventually we get "zip file closed" illegal state exception.

IDE step by step trace will be helpful to show the inconsistency between newly opened JarFile instance and the closed JarFile instance referenced by its JarFileEntries member. Below highlighted related logs:

New JarFile !/BOOT-INF/lib/bcprov-jdk15on-1.64.jar @ 1458849419
java.lang.Exception: Stack trace
	at java.lang.Thread.dumpStack(Unknown Source)
	at org.springframework.boot.loader.jar.JarFile.<init>(JarFile.java:162)
	at org.springframework.boot.loader.jar.JarFile.<init>(JarFile.java:150)
	at org.springframework.boot.loader.jar.JarFile.createJarFileFromFileEntry(JarFile.java:346)
	at org.springframework.boot.loader.jar.JarFile.createJarFileFromEntry(JarFile.java:322)
	at org.springframework.boot.loader.jar.JarFile.getNestedJarFile(JarFile.java:311)
	at org.springframework.boot.loader.jar.JarFile.getNestedJarFile(JarFile.java:300)
	at org.springframework.boot.loader.archive.JarFileArchive.getNestedArchive(JarFileArchive.java:99)
	at org.springframework.boot.loader.archive.JarFileArchive$NestedArchiveIterator.adapt(JarFileArchive.java:236)
	at org.springframework.boot.loader.archive.JarFileArchive$NestedArchiveIterator.adapt(JarFileArchive.java:227)
	at org.springframework.boot.loader.archive.JarFileArchive$AbstractIterator.next(JarFileArchive.java:188)
	at org.springframework.boot.loader.PropertiesLauncher$ClassPathArchives.addNestedEntries(PropertiesLauncher.java:650)
	at org.springframework.boot.loader.PropertiesLauncher$ClassPathArchives.<init>(PropertiesLauncher.java:541)
	at org.springframework.boot.loader.PropertiesLauncher.getClassPathArchivesIterator(PropertiesLauncher.java:457)
	at org.springframework.boot.loader.Launcher.launch(Launcher.java:55)
	at org.springframework.boot.loader.PropertiesLauncher.main(PropertiesLauncher.java:466)
New JarFileEntries [1828757853] for !/BOOT-INF/lib/bcprov-jdk15on-1.64.jar @ 1458849419
Closing !/BOOT-INF/lib/bcprov-jdk15on-1.64.jar @ 1458849419
New JarFile !/BOOT-INF/lib/bcprov-jdk15on-1.64.jar @ 267760927, from parent: !/BOOT-INF/lib/bcprov-jdk15on-1.64.jar @ 1458849419, with entries: 1828757853
New JarFile !/BOOT-INF/lib/bcprov-jdk15on-1.64.jar @ 846238611, from parent: !/BOOT-INF/lib/bcprov-jdk15on-1.64.jar @ 1458849419, with entries: 1828757853
New JarFile !/BOOT-INF/lib/bcprov-jdk15on-1.64.jar @ 1033490990, from parent: !/BOOT-INF/lib/bcprov-jdk15on-1.64.jar @ 1458849419, with entries: 1828757853
New JarFile !/BOOT-INF/lib/bcprov-jdk15on-1.64.jar @ 1675763772, from parent: !/BOOT-INF/lib/bcprov-jdk15on-1.64.jar @ 1458849419, with entries: 1828757853
New JarFile !/BOOT-INF/lib/bcprov-jdk15on-1.64.jar @ 762227630, from parent: !/BOOT-INF/lib/bcprov-jdk15on-1.64.jar @ 1458849419, with entries: 1828757853
New JarFile !/BOOT-INF/lib/bcprov-jdk15on-1.64.jar @ 1316864772, from parent: !/BOOT-INF/lib/bcprov-jdk15on-1.64.jar @ 1458849419, with entries: 1828757853
New JarFile !/BOOT-INF/lib/bcprov-jdk15on-1.64.jar @ 1685232414, from parent: !/BOOT-INF/lib/bcprov-jdk15on-1.64.jar @ 1458849419, with entries: 1828757853
New JarFile !/BOOT-INF/lib/bcprov-jdk15on-1.64.jar @ 615634843, from parent: !/BOOT-INF/lib/bcprov-jdk15on-1.64.jar @ 1458849419, with entries: 1828757853
New JarFile !/BOOT-INF/lib/bcprov-jdk15on-1.64.jar @ 1157058691, from parent: !/BOOT-INF/lib/bcprov-jdk15on-1.64.jar @ 1458849419, with entries: 1828757853
New JarFile !/BOOT-INF/lib/bcprov-jdk15on-1.64.jar @ 40472007, from parent: !/BOOT-INF/lib/bcprov-jdk15on-1.64.jar @ 1458849419, with entries: 1828757853
New JarFile !/BOOT-INF/lib/bcprov-jdk15on-1.64.jar @ 1822383117, from parent: !/BOOT-INF/lib/bcprov-jdk15on-1.64.jar @ 1458849419, with entries: 1828757853
New JarFile !/BOOT-INF/lib/bcprov-jdk15on-1.64.jar @ 477289012, from parent: !/BOOT-INF/lib/bcprov-jdk15on-1.64.jar @ 1458849419, with entries: 1828757853
New JarFile !/BOOT-INF/lib/bcprov-jdk15on-1.64.jar @ 1795960102, from parent: !/BOOT-INF/lib/bcprov-jdk15on-1.64.jar @ 1458849419, with entries: 1828757853
......
New JarFile !/BOOT-INF/lib/bcprov-jdk15on-1.64.jar @ 1021565761, from parent: !/BOOT-INF/lib/bcprov-jdk15on-1.64.jar @ 1458849419, with entries: 1828757853
In ensureOpen(): !/BOOT-INF/lib/bcprov-jdk15on-1.64.jar @ 1458849419
Exception in thread "main" java.lang.reflect.InvocationTargetException
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
	at java.lang.reflect.Method.invoke(Unknown Source)
	at org.springframework.boot.loader.MainMethodRunner.run(MainMethodRunner.java:49)
	at org.springframework.boot.loader.Launcher.launch(Launcher.java:109)
	at org.springframework.boot.loader.Launcher.launch(Launcher.java:58)
	at org.springframework.boot.loader.PropertiesLauncher.main(PropertiesLauncher.java:466)
Caused by: java.lang.IllegalStateException: zip file closed
	at org.springframework.boot.loader.jar.JarFile.ensureOpen(JarFile.java:381)
	at org.springframework.boot.loader.jar.JarFile.getEntry(JarFile.java:276)
	at org.springframework.boot.loader.jar.JarFile.getJarEntry(JarFile.java:267)
	at org.springframework.boot.loader.jar.JarFile.setupEntryCertificates(JarFile.java:436)
	at org.springframework.boot.loader.jar.JarEntry.getCertificates(JarEntry.java:91)
	at com.example.restservice.RestServiceApplication.main(RestServiceApplication.java:20)
	... 8 more

@ziqianggeoffreychen
Copy link
Author

Hi @wilkinsona @philwebb , in my humble opinion, the fix is to stop share JarFileEntries with its parent, which means new JarFileEntries every time. The JarFileEntries is just some indexes, not a big deal to have many copies of them.

@philwebb philwebb removed the for: team-attention An issue we'd like other members of the team to review label Sep 9, 2020
@ziqianggeoffreychen
Copy link
Author

Hi @wilkinsona @philwebb , hope you are doing well. I verified below code delta can fix the issue. Could you review and evaluate the feasibility? Thanks.

$ git diff
diff --git a/spring-boot-project/spring-boot-tools/spring-boot-loader/src/main/java/org/springframework/boot/loader/jar/JarFile.java b/spring-boot-project/spring-boot-tools/spring-boot-loade
r/src/main/java/org/springframework/boot/loader/jar/JarFile.java
index 53977396b9..a6c32780d1 100644
--- a/spring-boot-project/spring-boot-tools/spring-boot-loader/src/main/java/org/springframework/boot/loader/jar/JarFile.java
+++ b/spring-boot-project/spring-boot-tools/spring-boot-loader/src/main/java/org/springframework/boot/loader/jar/JarFile.java
@@ -119,11 +119,18 @@ public class JarFile extends java.util.jar.JarFile implements Iterable<java.util
                this.parent = parent;
                this.rootFile = parent.rootFile;
                this.pathFromRoot = parent.pathFromRoot;
                this.data = parent.data;
                this.type = parent.type;
                this.url = parent.url;
                this.urlString = parent.urlString;
                this.entries = parent.entries;
+               this.entries.setJarFile(this);
                this.manifestSupplier = parent.manifestSupplier;
                this.manifest = parent.manifest;
                this.signed = parent.signed;

diff --git a/spring-boot-project/spring-boot-tools/spring-boot-loader/src/main/java/org/springframework/boot/loader/jar/JarFileEntries.java b/spring-boot-project/spring-boot-tools/spring-boo
t-loader/src/main/java/org/springframework/boot/loader/jar/JarFileEntries.java
index 40207fa2a7..a12848e97f 100644
--- a/spring-boot-project/spring-boot-tools/spring-boot-loader/src/main/java/org/springframework/boot/loader/jar/JarFileEntries.java
+++ b/spring-boot-project/spring-boot-tools/spring-boot-loader/src/main/java/org/springframework/boot/loader/jar/JarFileEntries.java
@@ -78,7 +78,7 @@ class JarFileEntries implements CentralDirectoryVisitor, Iterable<JarEntry> {

        protected static final int ENTRY_CACHE_SIZE = 25;

-       private final JarFile jarFile;
+       private JarFile jarFile;

        private final JarEntryFilter filter;

@@ -153,6 +156,11 @@ class JarFileEntries implements CentralDirectoryVisitor, Iterable<JarEntry> {
                return this.size;
        }

+       // package private setter to update the JarFile back reference.
+       void setJarFile(JarFile jarFile) {
+               this.jarFile = jarFile;
+       }
+
        private void sort(int left, int right) {
                // Quick sort algorithm, uses hashCodes as the source but sorts all arrays
                if (left < right) {

@wilkinsona wilkinsona self-assigned this Sep 10, 2020
@wilkinsona
Copy link
Member

wilkinsona commented Sep 10, 2020

The for the suggestion, but I don't think that's the right way for fix this one. PropertiesLauncher and JarLauncher are currently inconsistent in the way that they handle and close their archives. That inconsistency is unintentional and I think we should fix this by removing it. All being well, I'll push something shortly that aligns the behaviour.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
type: regression A regression from a previous release
Projects
None yet
Development

No branches or pull requests

4 participants