search

quarkusio / quarkus

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

Incorrect quarkus.http.ssl.certificate.key-store-password ends with misleading NSFE for the keystore #29589

Open rsvoboda opened 1 year ago

rsvoboda commented 1 year ago

Describe the bug

Incorrect quarkus.http.ssl.certificate.key-store-password ends with misleading NSFE for the keystore

When the app starts (in dev mode) I receive 5 errors with stacktraces, last two (stacktrace nr. 4 and 5) have Caused by: java.nio.file.NoSuchFileException: META-INF/resources/server.keystore

Stacktraces nr. 2 and 3 have the info Caused by: java.io.IOException: keystore password was incorrect so patient user can find the root cause. But my experience is that people often look at the last message/stacktrace and do not check all the the above messages.

AI: I think the case with incorrect password could have better user experience and less stacktraces.

The last stacktrace:

2022-11-30 18:15:20,083 ERROR [io.qua.dep.dev.IsolatedDevModeMain] (main) Failed to recover after failed start: java.lang.RuntimeException: java.nio.file.NoSuchFileException: META-INF/resources/server.keystore
    at io.quarkus.vertx.http.runtime.VertxHttpRecorder.startServerAfterFailedStart(VertxHttpRecorder.java:281)
    at io.quarkus.vertx.http.runtime.devmode.VertxHttpHotReplacementSetup.handleFailedInitialStart(VertxHttpHotReplacementSetup.java:61)
    at io.quarkus.deployment.dev.RuntimeUpdatesProcessor.startupFailed(RuntimeUpdatesProcessor.java:1139)
    at io.quarkus.deployment.dev.IsolatedDevModeMain.firstStart(IsolatedDevModeMain.java:175)
    at io.quarkus.deployment.dev.IsolatedDevModeMain.accept(IsolatedDevModeMain.java:447)
    at io.quarkus.deployment.dev.IsolatedDevModeMain.accept(IsolatedDevModeMain.java:59)
    at io.quarkus.bootstrap.app.CuratedApplication.runInCl(CuratedApplication.java:149)
    at io.quarkus.bootstrap.app.CuratedApplication.runInAugmentClassLoader(CuratedApplication.java:104)
    at io.quarkus.deployment.dev.DevModeMain.start(DevModeMain.java:131)
    at io.quarkus.deployment.dev.DevModeMain.main(DevModeMain.java:62)
Caused by: java.nio.file.NoSuchFileException: META-INF/resources/server.keystore
    at java.base/sun.nio.fs.UnixException.translateToIOException(UnixException.java:92)
    at java.base/sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:106)
    at java.base/sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:111)
    at java.base/sun.nio.fs.UnixFileSystemProvider.newByteChannel(UnixFileSystemProvider.java:219)
    at java.base/java.nio.file.Files.newByteChannel(Files.java:380)
    at java.base/java.nio.file.Files.newByteChannel(Files.java:432)
    at java.base/java.nio.file.spi.FileSystemProvider.newInputStream(FileSystemProvider.java:422)
    at java.base/java.nio.file.Files.newInputStream(Files.java:160)
    at io.quarkus.vertx.http.runtime.VertxHttpRecorder.getFileContent(VertxHttpRecorder.java:971)
    at io.quarkus.vertx.http.runtime.VertxHttpRecorder.createKeyStoreOptions(VertxHttpRecorder.java:951)
    at io.quarkus.vertx.http.runtime.VertxHttpRecorder.createSslOptions(VertxHttpRecorder.java:860)
    at io.quarkus.vertx.http.runtime.VertxHttpRecorder.doServerStart(VertxHttpRecorder.java:657)
    at io.quarkus.vertx.http.runtime.VertxHttpRecorder.startServerAfterFailedStart(VertxHttpRecorder.java:274)
    ... 9 more

Expected behavior

Not so many stacktraces + clear message about incorrect password at the end

Actual behavior

Long stack trace with misleading NSFE for the keystore

How to Reproduce?

Output of uname -a or ver

macOS

Output of java -version

Java 17

GraalVM version (if different from Java)

No response

Quarkus version or git rev

2.14.2.Final

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

No response

Additional information

No response

rsvoboda commented 1 year ago

Full log:

__  ____  __  _____   ___  __ ____  ______
 --/ __ \/ / / / _ | / _ \/ //_/ / / / __/
 -/ /_/ / /_/ / __ |/ , _/ ,< / /_/ /\ \
--\___\_\____/_/ |_/_/|_/_/|_|\____/___/
2022-11-30 18:15:19,532 WARN  [io.qua.config] (Quarkus Main Thread) Unrecognized configuration key "quarkus.datasource.password" was provided; it will be ignored; verify that the dependency extension for this configuration is set or that you did not make a typo

2022-11-30 18:15:20,028 ERROR [io.qua.run.Application] (Quarkus Main Thread) Failed to start application (with profile dev): java.security.UnrecoverableKeyException: failed to decrypt safe contents entry: javax.crypto.BadPaddingException: Given final block not properly padded. Such issues can arise if a bad key is used during decryption.
    at java.base/sun.security.pkcs12.PKCS12KeyStore.engineLoad(PKCS12KeyStore.java:2159)
    at java.base/sun.security.util.KeyStoreDelegator.engineLoad(KeyStoreDelegator.java:242)
    at java.base/java.security.KeyStore.load(KeyStore.java:1473)
    at io.vertx.core.net.impl.KeyStoreHelper.loadKeyStore(KeyStoreHelper.java:237)
    at io.vertx.core.net.KeyStoreOptionsBase.getHelper(KeyStoreOptionsBase.java:187)
    at io.vertx.core.net.KeyStoreOptionsBase.getKeyManagerFactory(KeyStoreOptionsBase.java:205)
    at io.vertx.core.net.impl.SSLHelper.getKeyMgrFactory(SSLHelper.java:363)
    at io.vertx.core.net.impl.SSLHelper.lambda$init$0(SSLHelper.java:205)
    at io.vertx.core.impl.ContextBase.lambda$null$0(ContextBase.java:137)
    at io.vertx.core.impl.ContextInternal.dispatch(ContextInternal.java:264)
    at io.vertx.core.impl.ContextBase.lambda$executeBlocking$1(ContextBase.java:135)
    at io.vertx.core.impl.TaskQueue.run(TaskQueue.java:76)
    at org.jboss.threads.ContextHandler$1.runWith(ContextHandler.java:18)
    at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2449)
    at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1452)
    at org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:29)
    at org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:29)
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
    at java.base/java.lang.Thread.run(Thread.java:833)

2022-11-30 18:15:20,029 INFO  [io.qua.dep.dev.IsolatedDevModeMain] (main) Attempting to start live reload endpoint to recover from previous Quarkus startup failure
2022-11-30 18:15:20,079 ERROR [io.qua.dep.dev.IsolatedDevModeMain] (main) Failed to start quarkus: io.quarkus.dev.appstate.ApplicationStartException: java.lang.RuntimeException: Failed to start quarkus
    at io.quarkus.dev.appstate.ApplicationStateNotification.waitForApplicationStart(ApplicationStateNotification.java:58)
    at io.quarkus.runner.bootstrap.StartupActionImpl.runMainClass(StartupActionImpl.java:123)
    at io.quarkus.deployment.dev.IsolatedDevModeMain.firstStart(IsolatedDevModeMain.java:137)
    at io.quarkus.deployment.dev.IsolatedDevModeMain.accept(IsolatedDevModeMain.java:447)
    at io.quarkus.deployment.dev.IsolatedDevModeMain.accept(IsolatedDevModeMain.java:59)
    at io.quarkus.bootstrap.app.CuratedApplication.runInCl(CuratedApplication.java:149)
    at io.quarkus.bootstrap.app.CuratedApplication.runInAugmentClassLoader(CuratedApplication.java:104)
    at io.quarkus.deployment.dev.DevModeMain.start(DevModeMain.java:131)
    at io.quarkus.deployment.dev.DevModeMain.main(DevModeMain.java:62)
Caused by: java.lang.RuntimeException: Failed to start quarkus
    at io.quarkus.runner.ApplicationImpl.doStart(Unknown Source)
    at io.quarkus.runtime.Application.start(Application.java:101)
    at io.quarkus.runtime.ApplicationLifecycleManager.run(ApplicationLifecycleManager.java:110)
    at io.quarkus.runtime.Quarkus.run(Quarkus.java:70)
    at io.quarkus.runtime.Quarkus.run(Quarkus.java:43)
    at io.quarkus.runtime.Quarkus.run(Quarkus.java:123)
    at io.quarkus.runner.GeneratedMain.main(Unknown Source)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.base/java.lang.reflect.Method.invoke(Method.java:568)
    at io.quarkus.runner.bootstrap.StartupActionImpl$1.run(StartupActionImpl.java:104)
    at java.base/java.lang.Thread.run(Thread.java:833)
Caused by: java.lang.RuntimeException: Unable to start HTTP server
    at io.quarkus.vertx.http.runtime.VertxHttpRecorder.doServerStart(VertxHttpRecorder.java:765)
    at io.quarkus.vertx.http.runtime.VertxHttpRecorder.startServer(VertxHttpRecorder.java:318)
    at io.quarkus.deployment.steps.VertxHttpProcessor$openSocket1866188241.deploy_0(Unknown Source)
    at io.quarkus.deployment.steps.VertxHttpProcessor$openSocket1866188241.deploy(Unknown Source)
    ... 13 more
Caused by: java.util.concurrent.ExecutionException: java.io.IOException: keystore password was incorrect
    at java.base/java.util.concurrent.CompletableFuture.reportGet(CompletableFuture.java:396)
    at java.base/java.util.concurrent.CompletableFuture.get(CompletableFuture.java:2073)
    at io.quarkus.vertx.http.runtime.VertxHttpRecorder.doServerStart(VertxHttpRecorder.java:731)
    ... 16 more
Caused by: java.io.IOException: keystore password was incorrect
    at java.base/sun.security.pkcs12.PKCS12KeyStore.engineLoad(PKCS12KeyStore.java:2159)
    at java.base/sun.security.util.KeyStoreDelegator.engineLoad(KeyStoreDelegator.java:242)
    at java.base/java.security.KeyStore.load(KeyStore.java:1473)
    at io.vertx.core.net.impl.KeyStoreHelper.loadKeyStore(KeyStoreHelper.java:237)
    at io.vertx.core.net.KeyStoreOptionsBase.getHelper(KeyStoreOptionsBase.java:187)
    at io.vertx.core.net.KeyStoreOptionsBase.getKeyManagerFactory(KeyStoreOptionsBase.java:205)
    at io.vertx.core.net.impl.SSLHelper.getKeyMgrFactory(SSLHelper.java:363)
    at io.vertx.core.net.impl.SSLHelper.lambda$init$0(SSLHelper.java:205)
    at io.vertx.core.impl.ContextBase.lambda$null$0(ContextBase.java:137)
    at io.vertx.core.impl.ContextInternal.dispatch(ContextInternal.java:264)
    at io.vertx.core.impl.ContextBase.lambda$executeBlocking$1(ContextBase.java:135)
    at io.vertx.core.impl.TaskQueue.run(TaskQueue.java:76)
    at org.jboss.threads.ContextHandler$1.runWith(ContextHandler.java:18)
    at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2449)
    at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1452)
    at org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:29)
    at org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:29)
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
    ... 1 more
Caused by: java.security.UnrecoverableKeyException: failed to decrypt safe contents entry: javax.crypto.BadPaddingException: Given final block not properly padded. Such issues can arise if a bad key is used during decryption.
    ... 19 more

2022-11-30 18:15:20,079 ERROR [io.qua.dep.dev.IsolatedDevModeMain] (main) Failed to start quarkus: io.quarkus.dev.appstate.ApplicationStartException: java.lang.RuntimeException: Failed to start quarkus
    at io.quarkus.dev.appstate.ApplicationStateNotification.waitForApplicationStart(ApplicationStateNotification.java:58)
    at io.quarkus.runner.bootstrap.StartupActionImpl.runMainClass(StartupActionImpl.java:123)
    at io.quarkus.deployment.dev.IsolatedDevModeMain.firstStart(IsolatedDevModeMain.java:137)
    at io.quarkus.deployment.dev.IsolatedDevModeMain.accept(IsolatedDevModeMain.java:447)
    at io.quarkus.deployment.dev.IsolatedDevModeMain.accept(IsolatedDevModeMain.java:59)
    at io.quarkus.bootstrap.app.CuratedApplication.runInCl(CuratedApplication.java:149)
    at io.quarkus.bootstrap.app.CuratedApplication.runInAugmentClassLoader(CuratedApplication.java:104)
    at io.quarkus.deployment.dev.DevModeMain.start(DevModeMain.java:131)
    at io.quarkus.deployment.dev.DevModeMain.main(DevModeMain.java:62)
Caused by: java.lang.RuntimeException: Failed to start quarkus
    at io.quarkus.runner.ApplicationImpl.doStart(Unknown Source)
    at io.quarkus.runtime.Application.start(Application.java:101)
    at io.quarkus.runtime.ApplicationLifecycleManager.run(ApplicationLifecycleManager.java:110)
    at io.quarkus.runtime.Quarkus.run(Quarkus.java:70)
    at io.quarkus.runtime.Quarkus.run(Quarkus.java:43)
    at io.quarkus.runtime.Quarkus.run(Quarkus.java:123)
    at io.quarkus.runner.GeneratedMain.main(Unknown Source)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.base/java.lang.reflect.Method.invoke(Method.java:568)
    at io.quarkus.runner.bootstrap.StartupActionImpl$1.run(StartupActionImpl.java:104)
    at java.base/java.lang.Thread.run(Thread.java:833)
Caused by: java.lang.RuntimeException: Unable to start HTTP server
    at io.quarkus.vertx.http.runtime.VertxHttpRecorder.doServerStart(VertxHttpRecorder.java:765)
    at io.quarkus.vertx.http.runtime.VertxHttpRecorder.startServer(VertxHttpRecorder.java:318)
    at io.quarkus.deployment.steps.VertxHttpProcessor$openSocket1866188241.deploy_0(Unknown Source)
    at io.quarkus.deployment.steps.VertxHttpProcessor$openSocket1866188241.deploy(Unknown Source)
    ... 13 more
Caused by: java.util.concurrent.ExecutionException: java.io.IOException: keystore password was incorrect
    at java.base/java.util.concurrent.CompletableFuture.reportGet(CompletableFuture.java:396)
    at java.base/java.util.concurrent.CompletableFuture.get(CompletableFuture.java:2073)
    at io.quarkus.vertx.http.runtime.VertxHttpRecorder.doServerStart(VertxHttpRecorder.java:731)
    ... 16 more
Caused by: java.io.IOException: keystore password was incorrect
    at java.base/sun.security.pkcs12.PKCS12KeyStore.engineLoad(PKCS12KeyStore.java:2159)
    at java.base/sun.security.util.KeyStoreDelegator.engineLoad(KeyStoreDelegator.java:242)
    at java.base/java.security.KeyStore.load(KeyStore.java:1473)
    at io.vertx.core.net.impl.KeyStoreHelper.loadKeyStore(KeyStoreHelper.java:237)
    at io.vertx.core.net.KeyStoreOptionsBase.getHelper(KeyStoreOptionsBase.java:187)
    at io.vertx.core.net.KeyStoreOptionsBase.getKeyManagerFactory(KeyStoreOptionsBase.java:205)
    at io.vertx.core.net.impl.SSLHelper.getKeyMgrFactory(SSLHelper.java:363)
    at io.vertx.core.net.impl.SSLHelper.lambda$init$0(SSLHelper.java:205)
    at io.vertx.core.impl.ContextBase.lambda$null$0(ContextBase.java:137)
    at io.vertx.core.impl.ContextInternal.dispatch(ContextInternal.java:264)
    at io.vertx.core.impl.ContextBase.lambda$executeBlocking$1(ContextBase.java:135)
    at io.vertx.core.impl.TaskQueue.run(TaskQueue.java:76)
    at org.jboss.threads.ContextHandler$1.runWith(ContextHandler.java:18)
    at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2449)
    at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1452)
    at org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:29)
    at org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:29)
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
    ... 1 more
Caused by: java.security.UnrecoverableKeyException: failed to decrypt safe contents entry: javax.crypto.BadPaddingException: Given final block not properly padded. Such issues can arise if a bad key is used during decryption.
    ... 19 more

2022-11-30 18:15:20,083 ERROR [io.qua.dep.dev.IsolatedDevModeMain] (main) Failed to recover after failed start: java.lang.RuntimeException: java.nio.file.NoSuchFileException: META-INF/resources/server.keystore
    at io.quarkus.vertx.http.runtime.VertxHttpRecorder.startServerAfterFailedStart(VertxHttpRecorder.java:281)
    at io.quarkus.vertx.http.runtime.devmode.VertxHttpHotReplacementSetup.handleFailedInitialStart(VertxHttpHotReplacementSetup.java:61)
    at io.quarkus.deployment.dev.RuntimeUpdatesProcessor.startupFailed(RuntimeUpdatesProcessor.java:1139)
    at io.quarkus.deployment.dev.IsolatedDevModeMain.firstStart(IsolatedDevModeMain.java:175)
    at io.quarkus.deployment.dev.IsolatedDevModeMain.accept(IsolatedDevModeMain.java:447)
    at io.quarkus.deployment.dev.IsolatedDevModeMain.accept(IsolatedDevModeMain.java:59)
    at io.quarkus.bootstrap.app.CuratedApplication.runInCl(CuratedApplication.java:149)
    at io.quarkus.bootstrap.app.CuratedApplication.runInAugmentClassLoader(CuratedApplication.java:104)
    at io.quarkus.deployment.dev.DevModeMain.start(DevModeMain.java:131)
    at io.quarkus.deployment.dev.DevModeMain.main(DevModeMain.java:62)
Caused by: java.nio.file.NoSuchFileException: META-INF/resources/server.keystore
    at java.base/sun.nio.fs.UnixException.translateToIOException(UnixException.java:92)
    at java.base/sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:106)
    at java.base/sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:111)
    at java.base/sun.nio.fs.UnixFileSystemProvider.newByteChannel(UnixFileSystemProvider.java:219)
    at java.base/java.nio.file.Files.newByteChannel(Files.java:380)
    at java.base/java.nio.file.Files.newByteChannel(Files.java:432)
    at java.base/java.nio.file.spi.FileSystemProvider.newInputStream(FileSystemProvider.java:422)
    at java.base/java.nio.file.Files.newInputStream(Files.java:160)
    at io.quarkus.vertx.http.runtime.VertxHttpRecorder.getFileContent(VertxHttpRecorder.java:971)
    at io.quarkus.vertx.http.runtime.VertxHttpRecorder.createKeyStoreOptions(VertxHttpRecorder.java:951)
    at io.quarkus.vertx.http.runtime.VertxHttpRecorder.createSslOptions(VertxHttpRecorder.java:860)
    at io.quarkus.vertx.http.runtime.VertxHttpRecorder.doServerStart(VertxHttpRecorder.java:657)
    at io.quarkus.vertx.http.runtime.VertxHttpRecorder.startServerAfterFailedStart(VertxHttpRecorder.java:274)
    ... 9 more

2022-11-30 18:15:20,083 ERROR [io.qua.dep.dev.IsolatedDevModeMain] (main) Failed to recover after failed start: java.lang.RuntimeException: java.nio.file.NoSuchFileException: META-INF/resources/server.keystore
    at io.quarkus.vertx.http.runtime.VertxHttpRecorder.startServerAfterFailedStart(VertxHttpRecorder.java:281)
    at io.quarkus.vertx.http.runtime.devmode.VertxHttpHotReplacementSetup.handleFailedInitialStart(VertxHttpHotReplacementSetup.java:61)
    at io.quarkus.deployment.dev.RuntimeUpdatesProcessor.startupFailed(RuntimeUpdatesProcessor.java:1139)
    at io.quarkus.deployment.dev.IsolatedDevModeMain.firstStart(IsolatedDevModeMain.java:175)
    at io.quarkus.deployment.dev.IsolatedDevModeMain.accept(IsolatedDevModeMain.java:447)
    at io.quarkus.deployment.dev.IsolatedDevModeMain.accept(IsolatedDevModeMain.java:59)
    at io.quarkus.bootstrap.app.CuratedApplication.runInCl(CuratedApplication.java:149)
    at io.quarkus.bootstrap.app.CuratedApplication.runInAugmentClassLoader(CuratedApplication.java:104)
    at io.quarkus.deployment.dev.DevModeMain.start(DevModeMain.java:131)
    at io.quarkus.deployment.dev.DevModeMain.main(DevModeMain.java:62)
Caused by: java.nio.file.NoSuchFileException: META-INF/resources/server.keystore
    at java.base/sun.nio.fs.UnixException.translateToIOException(UnixException.java:92)
    at java.base/sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:106)
    at java.base/sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:111)
    at java.base/sun.nio.fs.UnixFileSystemProvider.newByteChannel(UnixFileSystemProvider.java:219)
    at java.base/java.nio.file.Files.newByteChannel(Files.java:380)
    at java.base/java.nio.file.Files.newByteChannel(Files.java:432)
    at java.base/java.nio.file.spi.FileSystemProvider.newInputStream(FileSystemProvider.java:422)
    at java.base/java.nio.file.Files.newInputStream(Files.java:160)
    at io.quarkus.vertx.http.runtime.VertxHttpRecorder.getFileContent(VertxHttpRecorder.java:971)
    at io.quarkus.vertx.http.runtime.VertxHttpRecorder.createKeyStoreOptions(VertxHttpRecorder.java:951)
    at io.quarkus.vertx.http.runtime.VertxHttpRecorder.createSslOptions(VertxHttpRecorder.java:860)
    at io.quarkus.vertx.http.runtime.VertxHttpRecorder.doServerStart(VertxHttpRecorder.java:657)
    at io.quarkus.vertx.http.runtime.VertxHttpRecorder.startServerAfterFailedStart(VertxHttpRecorder.java:274)
    ... 9 more
quarkus-bot[bot] commented 1 year ago

/cc @sberyozkin