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.

Sign up for GitHub

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

Jump to bottom

HttpClient infinite loop if null failure during SSL handshake #257

Closed
bclozel opened this issue Jan 9, 2018 · 1 comment
Closed

HttpClient infinite loop if null failure during SSL handshake #257

bclozel opened this issue Jan 9, 2018 · 1 comment
Labels
type/enhancement A general enhancement
Milestone
0.7.4.RELEASE

Comments

@bclozel
Copy link
Member

bclozel commented Jan 9, 2018

Expected behavior

When the server requires client SSL authentication - and HttpClient is not configured with a private key, the connection should fail with a javax.net.ssl.SSLException.

Actual behavior

This is working properly with Reactor Netty (server), Tomcat and Jetty, as they all fail with the following exception:

22:38:59.339 [reactor-http-nio-4] WARN io.netty.util.concurrent.DefaultPromise - An exception was thrown by reactor.ipc.netty.FutureMono$FutureSubscription.operationComplete()
reactor.core.Exceptions$BubblingException: javax.net.ssl.SSLException: Received fatal alert: bad_certificate
	at reactor.core.Exceptions.bubble(Exceptions.java:154)
	at reactor.core.publisher.Operators.onErrorDropped(Operators.java:256)
	at reactor.core.publisher.MonoCreate$DefaultMonoSink.error(MonoCreate.java:166)
	at reactor.ipc.netty.channel.ContextHandler.fireContextError(ContextHandler.java:272)
	at reactor.ipc.netty.http.client.HttpClientOperations.onOutboundError(HttpClientOperations.java:502)
	at reactor.ipc.netty.channel.ChannelOperations.onError(ChannelOperations.java:232)
	at reactor.core.publisher.Operators$MonoSubscriber.onError(Operators.java:1135)
	at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreInner.onError(MonoIgnoreThen.java:229)
	at reactor.ipc.netty.FutureMono$FutureSubscription.operationComplete(FutureMono.java:159)
	at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:507)
	at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:481)
	at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:420)
	at io.netty.util.concurrent.DefaultPromise.tryFailure(DefaultPromise.java:122)
	at io.netty.util.internal.PromiseNotificationUtil.tryFailure(PromiseNotificationUtil.java:64)
	at io.netty.channel.DelegatingChannelPromiseNotifier.operationComplete(DelegatingChannelPromiseNotifier.java:57)
	at io.netty.channel.DelegatingChannelPromiseNotifier.operationComplete(DelegatingChannelPromiseNotifier.java:31)
	at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:507)
	at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:481)
	at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:420)
	at io.netty.util.concurrent.DefaultPromise.tryFailure(DefaultPromise.java:122)
	at io.netty.util.internal.PromiseNotificationUtil.tryFailure(PromiseNotificationUtil.java:64)
	at io.netty.channel.DelegatingChannelPromiseNotifier.operationComplete(DelegatingChannelPromiseNotifier.java:57)
	at io.netty.channel.DelegatingChannelPromiseNotifier.operationComplete(DelegatingChannelPromiseNotifier.java:31)
	at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:507)
	at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:481)
	at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:420)
	at io.netty.util.concurrent.DefaultPromise.tryFailure(DefaultPromise.java:122)
	at io.netty.util.internal.PromiseNotificationUtil.tryFailure(PromiseNotificationUtil.java:64)
	at io.netty.channel.DelegatingChannelPromiseNotifier.operationComplete(DelegatingChannelPromiseNotifier.java:57)
	at io.netty.channel.DelegatingChannelPromiseNotifier.operationComplete(DelegatingChannelPromiseNotifier.java:31)
	at io.netty.channel.AbstractCoalescingBufferQueue.releaseAndCompleteAll(AbstractCoalescingBufferQueue.java:340)
	at io.netty.channel.AbstractCoalescingBufferQueue.releaseAndFailAll(AbstractCoalescingBufferQueue.java:207)
	at io.netty.handler.ssl.SslHandler.releaseAndFailAll(SslHandler.java:1530)
	at io.netty.handler.ssl.SslHandler.setHandshakeFailure(SslHandler.java:1524)
	at io.netty.handler.ssl.SslHandler.setHandshakeFailure(SslHandler.java:1493)
	at io.netty.handler.ssl.SslHandler.handleUnwrapThrowable(SslHandler.java:1186)
	at io.netty.handler.ssl.SslHandler.decodeJdkCompatible(SslHandler.java:1165)
	at io.netty.handler.ssl.SslHandler.decode(SslHandler.java:1194)
	at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:489)
	at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:428)
	at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:265)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340)
	at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1359)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
	at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:935)
	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:141)
	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:645)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:580)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:497)
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:459)
	at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:886)
	at java.lang.Thread.run(Thread.java:748)
Caused by: javax.net.ssl.SSLException: Received fatal alert: bad_certificate
	at sun.security.ssl.Alerts.getSSLException(Alerts.java:208)
	at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1666)
	at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1634)
	at sun.security.ssl.SSLEngineImpl.recvAlert(SSLEngineImpl.java:1800)
	at sun.security.ssl.SSLEngineImpl.readRecord(SSLEngineImpl.java:1083)
	at sun.security.ssl.SSLEngineImpl.readNetRecord(SSLEngineImpl.java:907)
	at sun.security.ssl.SSLEngineImpl.unwrap(SSLEngineImpl.java:781)
	at javax.net.ssl.SSLEngine.unwrap(SSLEngine.java:624)
	at io.netty.handler.ssl.SslHandler$SslEngineType$3.unwrap(SslHandler.java:292)
	at io.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:1248)
	at io.netty.handler.ssl.SslHandler.decodeJdkCompatible(SslHandler.java:1159)
	... 18 common frames omitted

With Undertow, it seems that the server abruptly closes the connection during the SSL handshake without providing a proper reason. Instead of failing, the client retries indefinitely until a timeout is hit:

22:27:46.251 [reactor-http-nio-2] DEBUG reactor.ipc.netty.channel.PooledClientContextHandler - Acquiring existing channel from pool: DefaultPromise@3eb7a938(incomplete) SimpleChannelPool{activeConnections=1}
22:27:46.251 [reactor-http-nio-2] DEBUG reactor.ipc.netty.http.client.HttpClient - [id: 0x91af679c, L:/127.0.0.1:56997 ! R:localhost/127.0.0.1:56195] USER_EVENT: [Handler Terminated]
22:27:46.251 [reactor-http-nio-2] DEBUG reactor.ipc.netty.channel.ChannelOperationsHandler - [id: 0x91af679c, L:/127.0.0.1:56997 ! R:localhost/127.0.0.1:56195] Disposing context reactor.ipc.netty.channel.PooledClientContextHandler@4ade9db1
22:27:46.251 [reactor-http-nio-2] DEBUG reactor.ipc.netty.channel.PooledClientContextHandler - Releasing channel: [id: 0x91af679c, L:/127.0.0.1:56997 ! R:localhost/127.0.0.1:56195]
22:27:46.251 [reactor-http-nio-2] DEBUG reactor.ipc.netty.resources.DefaultPoolResources - Released [id: 0x91af679c, L:/127.0.0.1:56997 ! R:localhost/127.0.0.1:56195], now 1 active connections
22:27:46.251 [reactor-http-nio-4] DEBUG reactor.ipc.netty.resources.DefaultPoolResources - Created [id: 0x0b1ffd65], now 1 active connections
22:27:46.251 [reactor-http-nio-2] DEBUG reactor.ipc.netty.http.client.HttpClient - [id: 0x91af679c, L:/127.0.0.1:56997 ! R:localhost/127.0.0.1:56195] USER_EVENT: SslCloseCompletionEvent(java.nio.channels.ClosedChannelException)
22:27:46.251 [reactor-http-nio-2] DEBUG reactor.ipc.netty.http.client.HttpClient - [id: 0x91af679c, L:/127.0.0.1:56997 ! R:localhost/127.0.0.1:56195] INACTIVE
22:27:46.251 [reactor-http-nio-2] DEBUG reactor.ipc.netty.http.client.HttpClient - [id: 0x91af679c, L:/127.0.0.1:56997 ! R:localhost/127.0.0.1:56195] UNREGISTERED
22:27:46.251 [reactor-http-nio-4] DEBUG reactor.ipc.netty.channel.ContextHandler - SSL enabled using engine SSLEngineImpl and SNI [localhost,56195]
22:27:46.251 [reactor-http-nio-4] DEBUG reactor.ipc.netty.channel.ContextHandler - After pipeline DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.loggingHandler = io.netty.handler.logging.LoggingHandler), (reactor.left.sslReader = reactor.ipc.netty.channel.SslReadHandler), (SimpleChannelPool$1#0 = io.netty.channel.pool.SimpleChannelPool$1), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (reactor.right.reactiveBridge = reactor.ipc.netty.channel.ChannelOperationsHandler)}
22:27:46.251 [reactor-http-nio-4] DEBUG reactor.ipc.netty.http.client.HttpClient - [id: 0x0b1ffd65] REGISTERED
22:27:46.251 [reactor-http-nio-4] DEBUG reactor.ipc.netty.http.client.HttpClient - [id: 0x0b1ffd65] CONNECT: localhost/127.0.0.1:56195
22:27:46.252 [reactor-http-nio-4] DEBUG reactor.ipc.netty.http.client.HttpClient - [id: 0x0b1ffd65, L:/127.0.0.1:56998 - R:localhost/127.0.0.1:56195] ACTIVE
22:27:46.252 [reactor-http-nio-4] DEBUG reactor.ipc.netty.channel.PooledClientContextHandler - Acquired active channel: [id: 0x0b1ffd65, L:/127.0.0.1:56998 - R:localhost/127.0.0.1:56195]
22:27:46.252 [reactor-http-nio-4] DEBUG reactor.ipc.netty.channel.ChannelOperations - [HttpClient] [id: 0x0b1ffd65, L:/127.0.0.1:56998 - R:localhost/127.0.0.1:56195] handler is being applied: HttpClientHandler{startURI=https://localhost:56195, method=POST, handler=org.springframework.boot.web.reactive.server.AbstractReactiveWebServerFactoryTests$$Lambda$15/749927456@180b7d87}
22:27:46.252 [reactor-http-nio-4] DEBUG reactor.ipc.netty.channel.ChannelOperationsHandler - [id: 0x0b1ffd65, L:/127.0.0.1:56998 - R:localhost/127.0.0.1:56195] Writing object DefaultHttpRequest(decodeResult: success, version: HTTP/1.1)
POST  HTTP/1.1
user-agent: ReactorNetty/0.7.2.RELEASE
transfer-encoding: chunked
host: localhost:56195
accept: */*
22:27:46.252 [reactor-http-nio-4] DEBUG reactor.ipc.netty.http.client.HttpClient - [id: 0x0b1ffd65, L:/127.0.0.1:56998 - R:localhost/127.0.0.1:56195] WRITE: 123B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 50 4f 53 54 20 2f 20 48 54 54 50 2f 31 2e 31 0d |POST / HTTP/1.1.|
|00000010| 0a 75 73 65 72 2d 61 67 65 6e 74 3a 20 52 65 61 |.user-agent: Rea|
|00000020| 63 74 6f 72 4e 65 74 74 79 2f 30 2e 37 2e 32 2e |ctorNetty/0.7.2.|
|00000030| 52 45 4c 45 41 53 45 0d 0a 74 72 61 6e 73 66 65 |RELEASE..transfe|
|00000040| 72 2d 65 6e 63 6f 64 69 6e 67 3a 20 63 68 75 6e |r-encoding: chun|
|00000050| 6b 65 64 0d 0a 68 6f 73 74 3a 20 6c 6f 63 61 6c |ked..host: local|
|00000060| 68 6f 73 74 3a 35 36 31 39 35 0d 0a 61 63 63 65 |host:56195..acce|
|00000070| 70 74 3a 20 2a 2f 2a 0d 0a 0d 0a                |pt: */*....     |
+--------+-------------------------------------------------+----------------+
22:27:46.252 [reactor-http-nio-4] DEBUG reactor.ipc.netty.http.client.HttpClient - [id: 0x0b1ffd65, L:/127.0.0.1:56998 - R:localhost/127.0.0.1:56195] FLUSH
22:27:46.256 [reactor-http-nio-4] DEBUG reactor.ipc.netty.http.client.HttpClient - [id: 0x0b1ffd65, L:/127.0.0.1:56998 - R:localhost/127.0.0.1:56195] READ COMPLETE
22:27:46.256 [reactor-http-nio-4] DEBUG io.netty.handler.ssl.util.InsecureTrustManagerFactory - Accepting a server certificate: CN=localhost, OU=Unknown, O=Unknown, L=Unknown, ST=Unknown, C=Unknown
22:27:46.259 [reactor-http-nio-4] DEBUG reactor.ipc.netty.http.client.HttpClient - [id: 0x0b1ffd65, L:/127.0.0.1:56998 - R:localhost/127.0.0.1:56195] READ COMPLETE
22:27:46.259 [reactor-http-nio-4] DEBUG reactor.ipc.netty.http.client.HttpClient - [id: 0x0b1ffd65, L:/127.0.0.1:56998 - R:localhost/127.0.0.1:56195] READ COMPLETE
22:27:46.260 [reactor-http-nio-4] DEBUG reactor.ipc.netty.http.client.HttpClient - [id: 0x0b1ffd65, L:/127.0.0.1:56998 ! R:localhost/127.0.0.1:56195] USER_EVENT: SslHandshakeCompletionEvent(java.nio.channels.ClosedChannelException)
22:27:46.260 [reactor-http-nio-4] ERROR reactor.ipc.netty.channel.ContextHandler - Connection closed remotely
java.nio.channels.ClosedChannelException: null
	at io.netty.handler.ssl.SslHandler.channelInactive(...)(Unknown Source)
22:27:46.260 [reactor-http-nio-4] DEBUG reactor.ipc.netty.channel.PooledClientContextHandler - Acquiring existing channel from pool: DefaultPromise@1fee429c(incomplete) SimpleChannelPool{activeConnections=1}
22:27:46.260 [reactor-http-nio-4] DEBUG reactor.ipc.netty.http.client.HttpClient - [id: 0x0b1ffd65, L:/127.0.0.1:56998 ! R:localhost/127.0.0.1:56195] USER_EVENT: [Handler Terminated]
22:27:46.260 [reactor-http-nio-6] DEBUG reactor.ipc.netty.resources.DefaultPoolResources - Created [id: 0x800ffb30], now 2 active connections
22:27:46.260 [reactor-http-nio-4] DEBUG reactor.ipc.netty.channel.ChannelOperationsHandler - [id: 0x0b1ffd65, L:/127.0.0.1:56998 ! R:localhost/127.0.0.1:56195] Disposing context reactor.ipc.netty.channel.PooledClientContextHandler@310a29bc
22:27:46.260 [reactor-http-nio-4] DEBUG reactor.ipc.netty.channel.PooledClientContextHandler - Releasing channel: [id: 0x0b1ffd65, L:/127.0.0.1:56998 ! R:localhost/127.0.0.1:56195]
22:27:46.260 [reactor-http-nio-4] DEBUG reactor.ipc.netty.resources.DefaultPoolResources - Released [id: 0x0b1ffd65, L:/127.0.0.1:56998 ! R:localhost/127.0.0.1:56195], now 1 active connections
22:27:46.260 [reactor-http-nio-4] DEBUG reactor.ipc.netty.http.client.HttpClient - [id: 0x0b1ffd65, L:/127.0.0.1:56998 ! R:localhost/127.0.0.1:56195] USER_EVENT: SslCloseCompletionEvent(java.nio.channels.ClosedChannelException)
22:27:46.260 [reactor-http-nio-4] DEBUG reactor.ipc.netty.http.client.HttpClient - [id: 0x0b1ffd65, L:/127.0.0.1:56998 ! R:localhost/127.0.0.1:56195] INACTIVE
22:27:46.260 [reactor-http-nio-4] DEBUG reactor.ipc.netty.http.client.HttpClient - [id: 0x0b1ffd65, L:/127.0.0.1:56998 ! R:localhost/127.0.0.1:56195] UNREGISTERED
22:27:46.260 [reactor-http-nio-6] DEBUG reactor.ipc.netty.channel.ContextHandler - SSL enabled using engine SSLEngineImpl and SNI [localhost,56195]
22:27:46.260 [reactor-http-nio-6] DEBUG reactor.ipc.netty.channel.ContextHandler - After pipeline DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.loggingHandler = io.netty.handler.logging.LoggingHandler), (reactor.left.sslReader = reactor.ipc.netty.channel.SslReadHandler), (SimpleChannelPool$1#0 = io.netty.channel.pool.SimpleChannelPool$1), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (reactor.right.reactiveBridge = reactor.ipc.netty.channel.ChannelOperationsHandler)}
22:27:46.260 [reactor-http-nio-6] DEBUG reactor.ipc.netty.http.client.HttpClient - [id: 0x800ffb30] REGISTERED
22:27:46.260 [reactor-http-nio-6] DEBUG reactor.ipc.netty.http.client.HttpClient - [id: 0x800ffb30] CONNECT: localhost/127.0.0.1:56195
22:27:46.261 [reactor-http-nio-6] DEBUG reactor.ipc.netty.http.client.HttpClient - [id: 0x800ffb30, L:/127.0.0.1:56999 - R:localhost/127.0.0.1:56195] ACTIVE
22:27:46.261 [reactor-http-nio-6] DEBUG reactor.ipc.netty.channel.PooledClientContextHandler - Acquired active channel: [id: 0x800ffb30, L:/127.0.0.1:56999 - R:localhost/127.0.0.1:56195]
22:27:46.261 [reactor-http-nio-6] DEBUG reactor.ipc.netty.channel.ChannelOperations - [HttpClient] [id: 0x800ffb30, L:/127.0.0.1:56999 - R:localhost/127.0.0.1:56195] handler is being applied: HttpClientHandler{startURI=https://localhost:56195, method=POST, handler=org.springframework.boot.web.reactive.server.AbstractReactiveWebServerFactoryTests$$Lambda$15/749927456@180b7d87}
22:27:46.261 [reactor-http-nio-6] DEBUG reactor.ipc.netty.channel.ChannelOperationsHandler - [id: 0x800ffb30, L:/127.0.0.1:56999 - R:localhost/127.0.0.1:56195] Writing object DefaultHttpRequest(decodeResult: success, version: HTTP/1.1)
POST  HTTP/1.1
user-agent: ReactorNetty/0.7.2.RELEASE
transfer-encoding: chunked
host: localhost:56195
accept: */*
22:27:46.261 [reactor-http-nio-6] DEBUG reactor.ipc.netty.http.client.HttpClient - [id: 0x800ffb30, L:/127.0.0.1:56999 - R:localhost/127.0.0.1:56195] WRITE: 123B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 50 4f 53 54 20 2f 20 48 54 54 50 2f 31 2e 31 0d |POST / HTTP/1.1.|
|00000010| 0a 75 73 65 72 2d 61 67 65 6e 74 3a 20 52 65 61 |.user-agent: Rea|
|00000020| 63 74 6f 72 4e 65 74 74 79 2f 30 2e 37 2e 32 2e |ctorNetty/0.7.2.|
|00000030| 52 45 4c 45 41 53 45 0d 0a 74 72 61 6e 73 66 65 |RELEASE..transfe|
|00000040| 72 2d 65 6e 63 6f 64 69 6e 67 3a 20 63 68 75 6e |r-encoding: chun|
|00000050| 6b 65 64 0d 0a 68 6f 73 74 3a 20 6c 6f 63 61 6c |ked..host: local|
|00000060| 68 6f 73 74 3a 35 36 31 39 35 0d 0a 61 63 63 65 |host:56195..acce|
|00000070| 70 74 3a 20 2a 2f 2a 0d 0a 0d 0a                |pt: */*....     |
+--------+-------------------------------------------------+----------------+
22:27:46.261 [reactor-http-nio-6] DEBUG reactor.ipc.netty.http.client.HttpClient - [id: 0x800ffb30, L:/127.0.0.1:56999 - R:localhost/127.0.0.1:56195] FLUSH
22:27:46.265 [reactor-http-nio-6] DEBUG reactor.ipc.netty.http.client.HttpClient - [id: 0x800ffb30, L:/127.0.0.1:56999 - R:localhost/127.0.0.1:56195] READ COMPLETE
22:27:46.265 [reactor-http-nio-6] DEBUG io.netty.handler.ssl.util.InsecureTrustManagerFactory - Accepting a server certificate: CN=localhost, OU=Unknown, O=Unknown, L=Unknown, ST=Unknown, C=Unknown
22:27:46.268 [reactor-http-nio-6] DEBUG reactor.ipc.netty.http.client.HttpClient - [id: 0x800ffb30, L:/127.0.0.1:56999 - R:localhost/127.0.0.1:56195] READ COMPLETE
22:27:46.269 [reactor-http-nio-6] DEBUG reactor.ipc.netty.http.client.HttpClient - [id: 0x800ffb30, L:/127.0.0.1:56999 - R:localhost/127.0.0.1:56195] READ COMPLETE
22:27:46.269 [reactor-http-nio-6] DEBUG reactor.ipc.netty.http.client.HttpClient - [id: 0x800ffb30, L:/127.0.0.1:56999 ! R:localhost/127.0.0.1:56195] USER_EVENT: SslHandshakeCompletionEvent(java.nio.channels.ClosedChannelException)
22:27:46.269 [reactor-http-nio-6] ERROR reactor.ipc.netty.channel.ContextHandler - Connection closed remotely
java.nio.channels.ClosedChannelException: null
	at io.netty.handler.ssl.SslHandler.channelInactive(...)(Unknown Source)
22:27:46.269 [reactor-http-nio-6] DEBUG reactor.ipc.netty.channel.PooledClientContextHandler - Acquiring existing channel from pool: DefaultPromise@5c41d4c0(incomplete) SimpleChannelPool{activeConnections=1}
22:27:46.269 [reactor-http-nio-6] DEBUG reactor.ipc.netty.http.client.HttpClient - [id: 0x800ffb30, L:/127.0.0.1:56999 ! R:localhost/127.0.0.1:56195] USER_EVENT: [Handler Terminated]
22:27:46.269 [reactor-http-nio-6] DEBUG reactor.ipc.netty.channel.ChannelOperationsHandler - [id: 0x800ffb30, L:/127.0.0.1:56999 ! R:localhost/127.0.0.1:56195] Disposing context reactor.ipc.netty.channel.PooledClientContextHandler@66214d8
22:27:46.269 [reactor-http-nio-6] DEBUG reactor.ipc.netty.channel.PooledClientContextHandler - Releasing channel: [id: 0x800ffb30, L:/127.0.0.1:56999 ! R:localhost/127.0.0.1:56195]
22:27:46.269 [reactor-http-nio-8] DEBUG reactor.ipc.netty.resources.DefaultPoolResources - Created [id: 0x1ddd87b8], now 2 active connections
22:27:46.269 [reactor-http-nio-6] DEBUG reactor.ipc.netty.resources.DefaultPoolResources - Released [id: 0x800ffb30, L:/127.0.0.1:56999 ! R:localhost/127.0.0.1:56195], now 1 active connections
22:27:46.269 [reactor-http-nio-6] DEBUG reactor.ipc.netty.http.client.HttpClient - [id: 0x800ffb30, L:/127.0.0.1:56999 ! R:localhost/127.0.0.1:56195] USER_EVENT: SslCloseCompletionEvent(java.nio.channels.ClosedChannelException)
22:27:46.269 [reactor-http-nio-6] DEBUG reactor.ipc.netty.http.client.HttpClient - [id: 0x800ffb30, L:/127.0.0.1:56999 ! R:localhost/127.0.0.1:56195] INACTIVE
22:27:46.269 [reactor-http-nio-6] DEBUG reactor.ipc.netty.http.client.HttpClient - [id: 0x800ffb30, L:/127.0.0.1:56999 ! R:localhost/127.0.0.1:56195] UNREGISTERED
22:27:46.269 [reactor-http-nio-8] DEBUG reactor.ipc.netty.channel.ContextHandler - SSL enabled using engine SSLEngineImpl and SNI [localhost,56195]
22:27:46.269 [reactor-http-nio-8] DEBUG reactor.ipc.netty.channel.ContextHandler - After pipeline DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.loggingHandler = io.netty.handler.logging.LoggingHandler), (reactor.left.sslReader = reactor.ipc.netty.channel.SslReadHandler), (SimpleChannelPool$1#0 = io.netty.channel.pool.SimpleChannelPool$1), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (reactor.right.reactiveBridge = reactor.ipc.netty.channel.ChannelOperationsHandler)}
22:27:46.269 [reactor-http-nio-8] DEBUG reactor.ipc.netty.http.client.HttpClient - [id: 0x1ddd87b8] REGISTERED
22:27:46.269 [reactor-http-nio-8] DEBUG reactor.ipc.netty.http.client.HttpClient - [id: 0x1ddd87b8] CONNECT: localhost/127.0.0.1:56195
22:27:46.270 [reactor-http-nio-8] DEBUG reactor.ipc.netty.http.client.HttpClient - [id: 0x1ddd87b8, L:/127.0.0.1:57000 - R:localhost/127.0.0.1:56195] ACTIVE
22:27:46.270 [reactor-http-nio-8] DEBUG reactor.ipc.netty.channel.PooledClientContextHandler - Acquired active channel: [id: 0x1ddd87b8, L:/127.0.0.1:57000 - R:localhost/127.0.0.1:56195]
22:27:46.270 [reactor-http-nio-8] DEBUG reactor.ipc.netty.channel.ChannelOperations - [HttpClient] [id: 0x1ddd87b8, L:/127.0.0.1:57000 - R:localhost/127.0.0.1:56195] handler is being applied: HttpClientHandler{startURI=https://localhost:56195, method=POST, handler=org.springframework.boot.web.reactive.server.AbstractReactiveWebServerFactoryTests$$Lambda$15/749927456@180b7d87}
22:27:46.271 [reactor-http-nio-8] DEBUG reactor.ipc.netty.channel.ChannelOperationsHandler - [id: 0x1ddd87b8, L:/127.0.0.1:57000 - R:localhost/127.0.0.1:56195] Writing object DefaultHttpRequest(decodeResult: success, version: HTTP/1.1)
POST  HTTP/1.1
user-agent: ReactorNetty/0.7.2.RELEASE
transfer-encoding: chunked
host: localhost:56195
accept: */*
22:27:46.271 [reactor-http-nio-8] DEBUG reactor.ipc.netty.http.client.HttpClient - [id: 0x1ddd87b8, L:/127.0.0.1:57000 - R:localhost/127.0.0.1:56195] WRITE: 123B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 50 4f 53 54 20 2f 20 48 54 54 50 2f 31 2e 31 0d |POST / HTTP/1.1.|
|00000010| 0a 75 73 65 72 2d 61 67 65 6e 74 3a 20 52 65 61 |.user-agent: Rea|
|00000020| 63 74 6f 72 4e 65 74 74 79 2f 30 2e 37 2e 32 2e |ctorNetty/0.7.2.|
|00000030| 52 45 4c 45 41 53 45 0d 0a 74 72 61 6e 73 66 65 |RELEASE..transfe|
|00000040| 72 2d 65 6e 63 6f 64 69 6e 67 3a 20 63 68 75 6e |r-encoding: chun|
|00000050| 6b 65 64 0d 0a 68 6f 73 74 3a 20 6c 6f 63 61 6c |ked..host: local|
|00000060| 68 6f 73 74 3a 35 36 31 39 35 0d 0a 61 63 63 65 |host:56195..acce|
|00000070| 70 74 3a 20 2a 2f 2a 0d 0a 0d 0a                |pt: */*....     |
+--------+-------------------------------------------------+----------------+
22:27:46.271 [reactor-http-nio-8] DEBUG reactor.ipc.netty.http.client.HttpClient - [id: 0x1ddd87b8, L:/127.0.0.1:57000 - R:localhost/127.0.0.1:56195] FLUSH
22:27:46.274 [reactor-http-nio-8] DEBUG reactor.ipc.netty.http.client.HttpClient - [id: 0x1ddd87b8, L:/127.0.0.1:57000 - R:localhost/127.0.0.1:56195] READ COMPLETE
22:27:46.275 [reactor-http-nio-8] DEBUG io.netty.handler.ssl.util.InsecureTrustManagerFactory - Accepting a server certificate: CN=localhost, OU=Unknown, O=Unknown, L=Unknown, ST=Unknown, C=Unknown
22:27:46.277 [reactor-http-nio-8] DEBUG reactor.ipc.netty.http.client.HttpClient - [id: 0x1ddd87b8, L:/127.0.0.1:57000 - R:localhost/127.0.0.1:56195] READ COMPLETE
22:27:46.278 [reactor-http-nio-8] DEBUG reactor.ipc.netty.http.client.HttpClient - [id: 0x1ddd87b8, L:/127.0.0.1:57000 - R:localhost/127.0.0.1:56195] READ COMPLETE
22:27:46.278 [reactor-http-nio-8] DEBUG reactor.ipc.netty.http.client.HttpClient - [id: 0x1ddd87b8, L:/127.0.0.1:57000 ! R:localhost/127.0.0.1:56195] USER_EVENT: SslHandshakeCompletionEvent(java.nio.channels.ClosedChannelException)
22:27:46.278 [reactor-http-nio-8] ERROR reactor.ipc.netty.channel.ContextHandler - Connection closed remotely
java.nio.channels.ClosedChannelException: null
	at io.netty.handler.ssl.SslHandler.channelInactive(...)(Unknown Source)
22:27:46.278 [reactor-http-nio-8] DEBUG reactor.ipc.netty.channel.PooledClientContextHandler - Acquiring existing channel from pool: DefaultPromise@7b49d812(incomplete) SimpleChannelPool{activeConnections=1}

Steps to reproduce

I can work on a full repro project - just wanted to check first if this was a configurable/epected behavior of HttpClient.

Reactor Netty version

"0.7.2.RELEASE" and "0.7.3.BUILD-SNAPSHOT"

JVM version (e.g. java -version)

java version "1.8.0_152-ea"
Java(TM) SE Runtime Environment (build 1.8.0_152-ea-b05)
Java HotSpot(TM) 64-Bit Server VM (build 25.152-b05, mixed mode)

OS version (e.g. uname -a)

17.3.0 Darwin Kernel Version 17.3.0: Thu Nov 9 18:09:22 PST 2017; root:xnu-4570.31.3~1/RELEASE_X86_64 x86_64
@bclozel
Copy link
Member Author

bclozel commented Jan 10, 2018

I've opened an issue Undertow for this behavior: UNDERTOW-1260.

On the other side, I'm wondering if Reactor Netty client could improve the situation. Does the client waits a bit between each try? Is it using some type of exponential backoff algorithm? Otherwise clients could overwhelm a server in case of issues.

@smaldini smaldini added this to the 0.8.0.RELEASE milestone Jan 20, 2018
@smaldini smaldini added type/bug A general bug type/enhancement A general enhancement and removed type/bug A general bug labels Jan 20, 2018
@smaldini smaldini modified the milestones: 0.8.0.RELEASE, 0.8.x Backlog Jan 20, 2018
@smaldini smaldini modified the milestones: 0.8.x Backlog, 0.7.4.RELEASE Feb 2, 2018
@smaldini smaldini mentioned this issue Feb 5, 2018
Closed
violetagg added a commit that referenced this issue Feb 6, 2018
@violetagg
fix #257: Add retry configurations - number of retries and backoff
860f89a 
Add HttpClient configurations for number of retries and backoff.
The delay between the retries will be current_retry * backoff.
violetagg added a commit that referenced this issue Feb 6, 2018
@violetagg
fix #257: Retry once in case of AbortedException/IOException
3dc12c2 
When HttpClient receives AbortedException/IOException, it will retry once
and then will return the exception so that the user can decide how many
retries to do and with what delay.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
type/enhancement A general enhancement
Projects
None yet
Milestone
0.7.4.RELEASE
Development

No branches or pull requests
2 participants
@smaldini @bclozel