search

quarkiverse / quarkus-cxf

Quarkus CXF Extension to support SOAP based web services.
Apache License 2.0
72 stars 57 forks source link

`MutualTlsTest.noKeystore()` sometimes fails with `StacklessClosedChannelException` #1429

Open ppalaga opened 1 month ago

ppalaga commented 1 month ago

In MutualTlsTest.noKeystore() a CXF client is tested that has no keystore set and therefore it is expected that the connection to a server requiring mTLS fails.

However the expected exception is an exception with root cause javax.net.ssl.SSLHandshakeException: Received fatal alert: bad_certificate like the following.

[INFO] [stdout] 2024-07-03 11:31:40,635 WARN  [org.apa.cxf.pha.PhaseInterceptorChain] (executor-thread-1) Interceptor for {http://mtls.auth.it.cxf.quarkiverse.io/}HelloService#{http://mtls.auth.it.cxf.quarkiverse.io/}hello has thrown exception, unwinding now: org.apache.cxf.interceptor.Fault: Could not send Message.
[INFO] [stdout]         at org.apache.cxf.interceptor.MessageSenderInterceptor$MessageSenderEndingInterceptor.handleMessage(MessageSenderInterceptor.java:67)
[INFO] [stdout]         at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:307)
[INFO] [stdout]         at org.apache.cxf.endpoint.ClientImpl.doInvoke(ClientImpl.java:530)
[INFO] [stdout]         at org.apache.cxf.endpoint.ClientImpl.invoke(ClientImpl.java:441)
[INFO] [stdout]         at org.apache.cxf.endpoint.ClientImpl.invoke(ClientImpl.java:356)
[INFO] [stdout]         at org.apache.cxf.endpoint.ClientImpl.invoke(ClientImpl.java:314)
[INFO] [stdout]         at org.apache.cxf.frontend.ClientProxy.invokeSync(ClientProxy.java:96)
[INFO] [stdout]         at org.apache.cxf.jaxws.JaxWsClientProxy.invoke(JaxWsClientProxy.java:140)
[INFO] [stdout]         at jdk.proxy4/jdk.proxy4.$Proxy115.hello(Unknown Source)
[INFO] [stdout]         at io.quarkiverse.cxf.it.auth.mtls.SecurityPolicyResource.hello(SecurityPolicyResource.java:40)
[INFO] [stdout]         at java.base@21.0.3/java.lang.reflect.Method.invoke(Method.java:580)
[INFO] [stdout]         at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:154)
[INFO] [stdout]         at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:118)
[INFO] [stdout]         at org.jboss.resteasy.core.ResourceMethodInvoker.internalInvokeOnTarget(ResourceMethodInvoker.java:560)
[INFO] [stdout]         at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTargetAfterFilter(ResourceMethodInvoker.java:452)
[INFO] [stdout]         at org.jboss.resteasy.core.ResourceMethodInvoker.lambda$invokeOnTarget$2(ResourceMethodInvoker.java:413)
[INFO] [stdout]         at org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:321)
[INFO] [stdout]         at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:415)
[INFO] [stdout]         at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:378)
[INFO] [stdout]         at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:356)
[INFO] [stdout]         at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:70)
[INFO] [stdout]         at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:429)
[INFO] [stdout]         at org.jboss.resteasy.core.SynchronousDispatcher.lambda$invokePropagateNotFound$6(SynchronousDispatcher.java:275)
[INFO] [stdout]         at org.jboss.resteasy.core.SynchronousDispatcher.lambda$preprocess$0(SynchronousDispatcher.java:154)
[INFO] [stdout]         at org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:321)
[INFO] [stdout]         at org.jboss.resteasy.core.SynchronousDispatcher.preprocess(SynchronousDispatcher.java:157)
[INFO] [stdout]         at org.jboss.resteasy.core.SynchronousDispatcher.invokePropagateNotFound(SynchronousDispatcher.java:260)
[INFO] [stdout]         at io.quarkus.resteasy.runtime.standalone.RequestDispatcher.service(RequestDispatcher.java:84)
[INFO] [stdout]         at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.dispatch(VertxRequestHandler.java:151)
[INFO] [stdout]         at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler$1.run(VertxRequestHandler.java:97)
[INFO] [stdout]         at io.quarkus.vertx.core.runtime.VertxCoreRecorder$14.runWith(VertxCoreRecorder.java:599)
[INFO] [stdout]         at org.jboss.threads.EnhancedQueueExecutor$Task.doRunWith(EnhancedQueueExecutor.java:2516)
[INFO] [stdout]         at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2495)
[INFO] [stdout]         at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1521)
[INFO] [stdout]         at org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:11)
[INFO] [stdout]         at org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:11)
[INFO] [stdout]         at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
[INFO] [stdout]         at java.base@21.0.3/java.lang.Thread.runWith(Thread.java:1596)
[INFO] [stdout]         at java.base@21.0.3/java.lang.Thread.run(Thread.java:1583)
[INFO] [stdout]         at org.graalvm.nativeimage.builder/com.oracle.svm.core.thread.PlatformThreads.threadStartRoutine(PlatformThreads.java:896)
[INFO] [stdout]         at org.graalvm.nativeimage.builder/com.oracle.svm.core.thread.PlatformThreads.threadStartRoutine(PlatformThreads.java:872)
[INFO] [stdout] Caused by: java.io.IOException: Unable to receive HTTP response from https://localhost:8444/services/mTls
[INFO] [stdout]         at io.quarkiverse.cxf.vertx.http.client.VertxHttpClientHTTPConduit$RequestBodyHandler.awaitResponse(VertxHttpClientHTTPConduit.java:610)
[INFO] [stdout]         at io.quarkiverse.cxf.vertx.http.client.VertxHttpClientHTTPConduit$RequestBodyHandler.handle(VertxHttpClientHTTPConduit.java:457)
[INFO] [stdout]         at io.quarkiverse.cxf.vertx.http.client.VertxHttpClientHTTPConduit$RequestBodyHandler.handle(VertxHttpClientHTTPConduit.java:342)
[INFO] [stdout]         at io.quarkiverse.cxf.vertx.http.client.VertxHttpClientHTTPConduit$RequestBodyOutputStream.close(VertxHttpClientHTTPConduit.java:337)
[INFO] [stdout]         at org.apache.cxf.transport.AbstractConduit.close(AbstractConduit.java:56)
[INFO] [stdout]         at org.apache.cxf.transport.http.HTTPConduit.close(HTTPConduit.java:717)
[INFO] [stdout]         at org.apache.cxf.interceptor.MessageSenderInterceptor$MessageSenderEndingInterceptor.handleMessage(MessageSenderInterceptor.java:63)
[INFO] [stdout]         ... 40 more
[INFO] [stdout] Caused by: io.netty.handler.codec.DecoderException: javax.net.ssl.SSLHandshakeException: Received fatal alert: bad_certificate
[INFO] [stdout]         at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:500)
[INFO] [stdout]         at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:290)
[INFO] [stdout]         at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444)
[INFO] [stdout]         at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
[INFO] [stdout]         at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
[INFO] [stdout]         at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
[INFO] [stdout]         at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:440)
[INFO] [stdout]         at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
[INFO] [stdout]         at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
[INFO] [stdout]         at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166)
[INFO] [stdout]         at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:788)
[INFO] [stdout]         at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:724)
[INFO] [stdout]         at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:650)
[INFO] [stdout]         at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:562)
[INFO] [stdout]         at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)
[INFO] [stdout]         at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
[INFO] [stdout]         ... 5 more
[INFO] [stdout] Caused by: javax.net.ssl.SSLHandshakeException: Received fatal alert: bad_certificate
[INFO] [stdout]         at java.base@21.0.3/sun.security.ssl.Alert.createSSLException(Alert.java:130)
[INFO] [stdout]         at java.base@21.0.3/sun.security.ssl.Alert.createSSLException(Alert.java:117)
[INFO] [stdout]         at java.base@21.0.3/sun.security.ssl.TransportContext.fatal(TransportContext.java:365)
[INFO] [stdout]         at java.base@21.0.3/sun.security.ssl.Alert$AlertConsumer.consume(Alert.java:287)
[INFO] [stdout]         at java.base@21.0.3/sun.security.ssl.TransportContext.dispatch(TransportContext.java:204)
[INFO] [stdout]         at java.base@21.0.3/sun.security.ssl.SSLTransport.decode(SSLTransport.java:172)
[INFO] [stdout]         at java.base@21.0.3/sun.security.ssl.SSLEngineImpl.decode(SSLEngineImpl.java:736)
[INFO] [stdout]         at java.base@21.0.3/sun.security.ssl.SSLEngineImpl.readRecord(SSLEngineImpl.java:691)
[INFO] [stdout]         at java.base@21.0.3/sun.security.ssl.SSLEngineImpl.unwrap(SSLEngineImpl.java:506)
[INFO] [stdout]         at java.base@21.0.3/sun.security.ssl.SSLEngineImpl.unwrap(SSLEngineImpl.java:482)
[INFO] [stdout]         at java.base@21.0.3/javax.net.ssl.SSLEngine.unwrap(SSLEngine.java:679)
[INFO] [stdout]         at io.netty.handler.ssl.SslHandler$SslEngineType$3.unwrap(SslHandler.java:310)
[INFO] [stdout]         at io.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:1445)
[INFO] [stdout]         at io.netty.handler.ssl.SslHandler.decodeJdkCompatible(SslHandler.java:1338)
[INFO] [stdout]         at io.netty.handler.ssl.SslHandler.decode(SslHandler.java:1387)
[INFO] [stdout]         at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:530)
[INFO] [stdout]         at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:469)
[INFO] [stdout]         ... 20 more

I have once spotted a different unexpected exception once on GH Actions in native mode:

[INFO] Running io.quarkiverse.cxf.it.auth.mtls.MutualTlsIT
2024-07-03 08:21:41,376 WARN  [io.qua.con.build] (main) The 'quarkus.http.ssl.certificate.key-store-key-password' config property is deprecated and should not be used anymore
2024-07-03 08:21:41,381 WARN  [io.qua.con.build] (main) The 'quarkus.http.ssl.certificate.key-store-key-alias' config property is deprecated and should not be used anymore
2024-07-03 08:21:43,120 WARN  [io.qua.con.build] (main) The 'quarkus.http.ssl.certificate.key-store-key-password' config property is deprecated and should not be used anymore
2024-07-03 08:21:43,121 WARN  [io.qua.con.build] (main) The 'quarkus.http.ssl.certificate.key-store-key-alias' config property is deprecated and should not be used anymore
Executing "/home/runner/work/quarkus-cxf/quarkus-cxf/integration-tests/mtls/target/quarkus-cxf-integration-test-mtls-3.12.1-SNAPSHOT-runner -Dquarkus.http.port=8081 -Dquarkus.http.ssl-port=8444 -Dtest.url=http://localhost:8081 -Dquarkus.log.file.path=/home/runner/work/quarkus-cxf/quarkus-cxf/integration-tests/mtls/target/quarkus.log -Dquarkus.log.file.enable=true -Dquarkus.log.category."io.quarkus".level=INFO -Dquarkus.native.container-build=true"
__  ____  __  _____   ___  __ ____  ______ 
 --/ __ \/ / / / _ | / _ \/ //_/ / / / __/ 
 -/ /_/ / /_/ / __ |/ , _/ ,< / /_/ /\ \   
--\___\_\____/_/ |_/_/|_/_/|_|\____/___/   
2024-07-03 08:21:43,406 WARN  [io.qua.run.con.DeprecatedRuntimePropertiesRecorder] (main) The 'quarkus.http.ssl.certificate.key-store-key-password' config property is deprecated and should not be used anymore
2024-07-03 08:21:43,406 WARN  [io.qua.run.con.DeprecatedRuntimePropertiesRecorder] (main) The 'quarkus.http.ssl.certificate.key-store-key-alias' config property is deprecated and should not be used anymore
2024-07-03 08:21:43,446 INFO  [org.apa.cxf.end.ServerImpl] (main) Setting the server's publish address to be /mTls
2024-07-03 08:21:43,446 INFO  [io.qua.cxf.tra.CxfHandler] (main) Web Service io.quarkiverse.cxf.it.auth.mtls.MTlsHelloServiceImpl on /services available.
2024-07-03 08:21:43,447 INFO  [io.qua.ver.htt.run.opt.HttpServerOptionsUtils] (main) TLS client authentication is required, thus disabling insecure requests. You can switch to `redirect` by setting `quarkus.http.insecure-requests=redirect`.
2024-07-03 08:21:43,550 INFO  [io.quarkus] (main) quarkus-cxf-integration-test-mtls 3.12.1-SNAPSHOT native (powered by Quarkus 3.12.0) started in 0.145s. Listening on: https://0.0.0.0:8444
2024-07-03 08:21:43,550 INFO  [io.quarkus] (main) Profile prod activated. 
2024-07-03 08:21:43,550 INFO  [io.quarkus] (main) Installed features: [cdi, cxf, resteasy, smallrye-context-propagation, vertx]
2024-07-03 08:21:45,249 ERROR [io.ver.cor.net.imp.ConnectionBase] (vert.x-eventloop-thread-2) javax.net.ssl.SSLHandshakeException: Received fatal alert: bad_certificate
2024-07-03 08:21:45,249 ERROR [io.ver.cor.htt.imp.HttpClientRequestImpl] (vert.x-eventloop-thread-2) javax.net.ssl.SSLHandshakeException: Received fatal alert: bad_certificate
2024-07-03 08:21:45,250 WARN  [org.apa.cxf.pha.PhaseInterceptorChain] (executor-thread-1) Interceptor for {http://mtls.auth.it.cxf.quarkiverse.io/}HelloService#{http://mtls.auth.it.cxf.quarkiverse.io/}hello has thrown exception, unwinding now: org.apache.cxf.interceptor.Fault: Could not send Message.
    at org.apache.cxf.interceptor.MessageSenderInterceptor$MessageSenderEndingInterceptor.handleMessage(MessageSenderInterceptor.java:67)
    at org.apache.cxf.transport.http.HTTPConduit.close(HTTPConduit.java:717)
    at org.apache.cxf.interceptor.MessageSenderInterceptor$MessageSenderEndingInterceptor.handleMessage(MessageSenderInterceptor.java:63)
    at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:307)
    at org.apache.cxf.endpoint.ClientImpl.doInvoke(ClientImpl.java:530)
    at org.apache.cxf.endpoint.ClientImpl.invoke(ClientImpl.java:441)
    at org.apache.cxf.endpoint.ClientImpl.invoke(ClientImpl.java:356)
    at org.apache.cxf.endpoint.ClientImpl.invoke(ClientImpl.java:314)
    at org.apache.cxf.frontend.ClientProxy.invokeSync(ClientProxy.java:96)
    at org.apache.cxf.jaxws.JaxWsClientProxy.invoke(JaxWsClientProxy.java:140)
    ... 33 more
Caused by: io.netty.channel.StacklessClosedChannelException
    at io.netty.channel.AbstractChannel$AbstractUnsafe.write(Object, ChannelPromise)(Unknown Source)

    at java.base/java.lang.reflect.Constructor.newInstanceWithCaller(Constructor.java:499)
    at java.base/java.lang.reflect.Constructor.newInstance(Constructor.java:480)
    at org.codehaus.groovy.reflection.CachedConstructor.invoke(CachedConstructor.java:73)
    at org.codehaus.groovy.runtime.callsite.ConstructorSite$ConstructorSiteNoUnwrapNoCoerce.callConstructor(ConstructorSite.java:108)
    at org.codehaus.groovy.runtime.callsite.CallSiteArray.defaultCallConstructor(CallSiteArray.java:57)
    at org.codehaus.groovy.runtime.callsite.AbstractCallSite.callConstructor(AbstractCallSite.java:263)
    at org.codehaus.groovy.runtime.callsite.AbstractCallSite.callConstructor(AbstractCallSite.java:277)
    at io.restassured.internal.ResponseSpecificationImpl$HamcrestAssertionClosure.validate(ResponseSpecificationImpl.groovy:512)
    at io.restassured.internal.ResponseSpecificationImpl$HamcrestAssertionClosure$validate$1.call(Unknown Source)
    at io.restassured.internal.ResponseSpecificationImpl.validateResponseIfRequired(ResponseSpecificationImpl.groovy:696)
    at io.restassured.internal.ResponseSpecificationImpl.this$2$validateResponseIfRequired(ResponseSpecificationImpl.groovy)
    at java.base/java.lang.reflect.Method.invoke(Method.java:[568](https://github.com/quarkiverse/quarkus-cxf/actions/runs/9774173756/job/26982308163?pr=1422#step:3:583))
    at org.codehaus.groovy.runtime.callsite.PlainObjectMetaMethodSite.doInvoke(PlainObjectMetaMethodSite.java:43)
    at org.codehaus.groovy.runtime.callsite.PogoMetaMethodSite$PogoCachedMethodSiteNoUnwrapNoCoerce.invoke(PogoMetaMethodSite.java:198)
    at org.codehaus.groovy.runtime.callsite.PogoMetaMethodSite.callCurrent(PogoMetaMethodSite.java:62)
    at org.codehaus.groovy.runtime.callsite.CallSiteArray.defaultCallCurrent(CallSiteArray.java:49)
    at org.codehaus.groovy.runtime.callsite.AbstractCallSite.callCurrent(AbstractCallSite.java:171)
    at org.codehaus.groovy.runtime.callsite.AbstractCallSite.callCurrent(AbstractCallSite.java:185)
    at io.restassured.internal.ResponseSpecificationImpl.body(ResponseSpecificationImpl.groovy:107)
    at io.restassured.internal.ValidatableResponseOptionsImpl.body(ValidatableResponseOptionsImpl.java:238)
    at io.quarkiverse.cxf.it.auth.mtls.MutualTlsTest.noKeystore(MutualTlsTest.java:71)
    at java.base/java.lang.reflect.Method.invoke(Method.java:568)
    at io.quarkus.test.junit.QuarkusTestExtension.interceptTestMethod(QuarkusTestExtension.java:820)
    at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
    at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)

This happened with the code available in this tag: https://github.com/ppalaga/quarkus-cxf/commits/i1429/

ppalaga commented 1 month ago

It would be nice if some Vert.x/Netty expert could help me to decide which of the follwing is the case here:

cescoffier commented 1 month ago

If I'm understand correctly you do not have a keystone in the client and request one. Thus, the handshake fails. The bad certificate is not a great exception but it's a valid one. You did not send a certificate, failing the handshake.

ppalaga commented 1 month ago

Yes, javax.net.ssl.SSLHandshakeException: Received fatal alert: bad_certificate is what I get on most executions of the test and I consider it correct and expected given that the client does not send its cert.

The question is whether the fact that I am rarely getting a different exception, namely StacklessClosedChannelException, is a problem I need to investigate or rather another legal outcome (to which I need to adapt my test)?

ppalaga commented 1 month ago

For the record, here it happened again: https://github.com/quarkiverse/quarkus-cxf/actions/runs/9789305617/job/27030196603?pr=1422#step:3:1210