search

AsyncHttpClient / async-http-client

Asynchronous Http and WebSocket Client library for Java
Other
6.28k stars 1.59k forks source link

BasicHttpsTest#multipleSequentialPostRequestsOverHttps failure #1179

Closed slandelle closed 8 years ago

slandelle commented 8 years ago 
Request DefaultFullHttpRequest(decodeResult: success, version: HTTP/1.1, content: UnpooledHeapByteBuf(freed))
POST /foo/bar HTTP/1.1
Content-Type: text/html
Content-Length: 11
Host: localhost:57799
Accept: */*
User-Agent: AHC/2.0

Response DefaultHttpResponse(decodeResult: success, version: HTTP/1.1)
HTTP/1.1 200 OK
Date: Mon, 06 Jun 2016 08:50:04 GMT
Content-Type: text/html;charset=utf-8
X-ClientPort: 47200
X-PathInfo: /foo/bar
X-User-Agent: AHC/2.0
X-Host: localhost:57799
X-Content-Length: 11
X-Accept: */*
X-Content-Type: text/html
Transfer-Encoding: chunked
Server: Jetty(9.3.9.v20160517)

2016-06-06 08:50:04,125 [AsyncHttpClient-54-1] DEBUG org.asynchttpclient.netty.channel.ChannelManager - Adding key: https://localhost:57799 for channel [id: 0xbec905ab, L:/127.0.0.1:47200 - R:localhost/127.0.0.1:57799]
2016-06-06 08:50:04,125 [main] DEBUG org.asynchttpclient.netty.request.NettyRequestSender - Using polled Channel [id: 0xbec905ab, L:/127.0.0.1:47200 - R:localhost/127.0.0.1:57799]
 for uri https://localhost:57799/foo/bar

2016-06-06 08:50:04,125 [main] DEBUG org.asynchttpclient.netty.request.NettyRequestSender - Using open Channel [id: 0xbec905ab, L:/127.0.0.1:47200 - R:localhost/127.0.0.1:57799] for POST '/foo/bar'
2016-06-06 08:50:04,136 [AsyncHttpClient-54-1] DEBUG org.asynchttpclient.netty.handler.HttpHandler - 

Request DefaultFullHttpRequest(decodeResult: success, version: HTTP/1.1, content: UnpooledHeapByteBuf(freed))
POST /foo/bar HTTP/1.1
Content-Type: text/html
Content-Length: 11
Host: localhost:57799
Accept: */*
User-Agent: AHC/2.0

Response DefaultHttpResponse(decodeResult: success, version: HTTP/1.1)
HTTP/1.1 500 No handler enqueued
Date: Mon, 06 Jun 2016 08:50:04 GMT
Cache-Control: must-revalidate,no-cache,no-store
Content-Type: text/html;charset=iso-8859-1
Content-Length: 333
Server: Jetty(9.3.9.v20160517)
slandelle commented 8 years ago 
Request DefaultFullHttpRequest(decodeResult: success, version: HTTP/1.1, content: UnpooledHeapByteBuf(freed))
POST /foo/bar HTTP/1.1
Content-Type: text/html
Content-Length: 11
Host: localhost:57799
Accept: */*
User-Agent: AHC/2.0

Response DefaultHttpResponse(decodeResult: success, version: HTTP/1.1)
HTTP/1.1 200 OK
Date: Mon, 06 Jun 2016 08:50:03 GMT
Content-Type: text/html;charset=utf-8
X-ClientPort: 47187
X-PathInfo: /foo/bar
X-User-Agent: AHC/2.0
X-Host: localhost:57799
X-Content-Length: 11
X-Accept: */*
X-Content-Type: text/html
Transfer-Encoding: chunked
Server: Jetty(9.3.9.v20160517)

2016-06-06 08:50:03,967 [AsyncHttpClient-53-3] DEBUG org.asynchttpclient.netty.channel.ChannelManager - Closing Channel [id: 0x1d52e57c, L:/127.0.0.1:47187 - R:localhost/127.0.0.1:57799] 
2016-06-06 08:50:03,972 [AsyncHttpClient-53-1] DEBUG org.asynchttpclient.netty.channel.NettyConnectListener - Trying to recover from failing to connect channel [id: 0x3cedd3f7, L:0.0.0.0/0.0.0.0:47185 ! R:localhost/127.0.0.1:57799] with a retry value of true 
2016-06-06 08:50:03,972 [AsyncHttpClient-53-1] DEBUG org.asynchttpclient.netty.channel.NettyConnectListener - Failed to recover from connect exception: java.nio.channels.ClosedChannelException with channel [id: 0x3cedd3f7, L:0.0.0.0/0.0.0.0:47185 ! R:localhost/127.0.0.1:57799]
2016-06-06 08:50:04,039 [AsyncHttpClient-53-2] DEBUG org.asynchttpclient.netty.channel.NettyConnectListener - Using non-cached Channel [id: 0x662c4dff, L:/127.0.0.1:47186 - R:localhost/127.0.0.1:57799] for POST '/foo/bar'
2016-06-06 08:50:04,040 [AsyncHttpClient-53-2] ERROR org.asynchttpclient.netty.request.NettyRequestSender - Can't write request
java.lang.IllegalStateException: cannot be started once stopped
    at io.netty.util.HashedWheelTimer.start(HashedWheelTimer.java:269)
    at io.netty.util.HashedWheelTimer.newTimeout(HashedWheelTimer.java:332)
    at org.asynchttpclient.netty.timeout.TimeoutsHolder.newTimeout(TimeoutsHolder.java:103)
    at org.asynchttpclient.netty.timeout.TimeoutsHolder.startReadTimeout(TimeoutsHolder.java:80)
    at org.asynchttpclient.netty.timeout.TimeoutsHolder.startReadTimeout(TimeoutsHolder.java:69)
    at org.asynchttpclient.netty.request.NettyRequestSender.scheduleReadTimeout(NettyRequestSender.java:379)
    at org.asynchttpclient.netty.request.NettyRequestSender.writeRequest(NettyRequestSender.java:354)
    at org.asynchttpclient.netty.channel.NettyConnectListener.writeRequest(NettyConnectListener.java:78)
    at org.asynchttpclient.netty.channel.NettyConnectListener.access$000(NettyConnectListener.java:37)
    at org.asynchttpclient.netty.channel.NettyConnectListener$1.onSuccess(NettyConnectListener.java:102)
    at org.asynchttpclient.netty.channel.NettyConnectListener$1.onSuccess(NettyConnectListener.java:96)
    at org.asynchttpclient.netty.SimpleFutureListener.operationComplete(SimpleFutureListener.java:24)
    at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:683)
    at io.netty.util.concurrent.DefaultPromise.notifyListeners0(DefaultPromise.java:604)
    at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:564)
    at io.netty.util.concurrent.DefaultPromise.trySuccess(DefaultPromise.java:407)
    at io.netty.handler.ssl.SslHandler.setHandshakeSuccess(SslHandler.java:1192)
    at io.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:1012)
    at io.netty.handler.ssl.SslHandler.decode(SslHandler.java:904)
    at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:387)
    at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:245)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:292)
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:278)
    at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:962)
    at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:131)
    at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:528)
    at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:485)
    at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:399)
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:371)
    at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112)
    at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:137)
    at java.lang.Thread.run(Thread.java:745)
2016-06-06 08:50:04,041 [AsyncHttpClient-53-2] DEBUG org.asynchttpclient.netty.channel.ChannelManager - Closing Channel [id: 0x662c4dff, L:/127.0.0.1:47186 - R:localhost/127.0.0.1:57799] 
2016-06-06 08:50:04,041 [AsyncHttpClient-53-2] DEBUG org.asynchttpclient.netty.request.NettyRequestSender - Aborting Future NettyResponseFuture{currentRetry=0,
    isDone=false,
    isCancelled=false,
    asyncHandler=org.asynchttpclient.AsyncCompletionHandlerBase@2680e8be,
    nettyRequest=org.asynchttpclient.netty.request.NettyRequest@22bf68b6,
    content=null,
    uri=https://localhost:57799/foo/bar,
    keepAlive=true,
    exEx=null,
    redirectCount=0,
    timeoutsHolder=org.asynchttpclient.netty.timeout.TimeoutsHolder@67bde285,
    inAuth=false,
    statusReceived=false,
    touch=1465203004040}

2016-06-06 08:50:04,041 [AsyncHttpClient-53-2] DEBUG org.asynchttpclient.netty.request.NettyRequestSender - cannot be started once stopped
java.lang.IllegalStateException: cannot be started once stopped
    at io.netty.util.HashedWheelTimer.start(HashedWheelTimer.java:269)
    at io.netty.util.HashedWheelTimer.newTimeout(HashedWheelTimer.java:332)
    at org.asynchttpclient.netty.timeout.TimeoutsHolder.newTimeout(TimeoutsHolder.java:103)
    at org.asynchttpclient.netty.timeout.TimeoutsHolder.startReadTimeout(TimeoutsHolder.java:80)
    at org.asynchttpclient.netty.timeout.TimeoutsHolder.startReadTimeout(TimeoutsHolder.java:69)
    at org.asynchttpclient.netty.request.NettyRequestSender.scheduleReadTimeout(NettyRequestSender.java:379)
    at org.asynchttpclient.netty.request.NettyRequestSender.writeRequest(NettyRequestSender.java:354)
    at org.asynchttpclient.netty.channel.NettyConnectListener.writeRequest(NettyConnectListener.java:78)
    at org.asynchttpclient.netty.channel.NettyConnectListener.access$000(NettyConnectListener.java:37)
    at org.asynchttpclient.netty.channel.NettyConnectListener$1.onSuccess(NettyConnectListener.java:102)
    at org.asynchttpclient.netty.channel.NettyConnectListener$1.onSuccess(NettyConnectListener.java:96)
    at org.asynchttpclient.netty.SimpleFutureListener.operationComplete(SimpleFutureListener.java:24)
    at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:683)
    at io.netty.util.concurrent.DefaultPromise.notifyListeners0(DefaultPromise.java:604)
    at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:564)
    at io.netty.util.concurrent.DefaultPromise.trySuccess(DefaultPromise.java:407)
    at io.netty.handler.ssl.SslHandler.setHandshakeSuccess(SslHandler.java:1192)
    at io.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:1012)
    at io.netty.handler.ssl.SslHandler.decode(SslHandler.java:904)
    at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:387)
    at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:245)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:292)
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:278)
    at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:962)
    at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:131)
    at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:528)
    at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:485)
    at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:399)
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:371)
    at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112)
    at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:137)
    at java.lang.Thread.run(Thread.java:745)
2016-06-06 08:50:04,042 [AsyncHttpClient-53-2] DEBUG org.asynchttpclient.AsyncCompletionHandler - cannot be started once stopped
java.lang.IllegalStateException: cannot be started once stopped
    at io.netty.util.HashedWheelTimer.start(HashedWheelTimer.java:269)
    at io.netty.util.HashedWheelTimer.newTimeout(HashedWheelTimer.java:332)
    at org.asynchttpclient.netty.timeout.TimeoutsHolder.newTimeout(TimeoutsHolder.java:103)
    at org.asynchttpclient.netty.timeout.TimeoutsHolder.startReadTimeout(TimeoutsHolder.java:80)
    at org.asynchttpclient.netty.timeout.TimeoutsHolder.startReadTimeout(TimeoutsHolder.java:69)
    at org.asynchttpclient.netty.request.NettyRequestSender.scheduleReadTimeout(NettyRequestSender.java:379)
    at org.asynchttpclient.netty.request.NettyRequestSender.writeRequest(NettyRequestSender.java:354)
    at org.asynchttpclient.netty.channel.NettyConnectListener.writeRequest(NettyConnectListener.java:78)
    at org.asynchttpclient.netty.channel.NettyConnectListener.access$000(NettyConnectListener.java:37)
    at org.asynchttpclient.netty.channel.NettyConnectListener$1.onSuccess(NettyConnectListener.java:102)
    at org.asynchttpclient.netty.channel.NettyConnectListener$1.onSuccess(NettyConnectListener.java:96)
    at org.asynchttpclient.netty.SimpleFutureListener.operationComplete(SimpleFutureListener.java:24)
    at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:683)
    at io.netty.util.concurrent.DefaultPromise.notifyListeners0(DefaultPromise.java:604)
    at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:564)
    at io.netty.util.concurrent.DefaultPromise.trySuccess(DefaultPromise.java:407)
    at io.netty.handler.ssl.SslHandler.setHandshakeSuccess(SslHandler.java:1192)
    at io.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:1012)
    at io.netty.handler.ssl.SslHandler.decode(SslHandler.java:904)
    at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:387)
    at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:245)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:292)
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:278)
    at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:962)
    at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:131)
    at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:528)
    at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:485)
    at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:399)
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:371)
    at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112)
    at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:137)
    at java.lang.Thread.run(Thread.java:745)
2016-06-06 08:50:04,042 [AsyncHttpClient-53-1] DEBUG org.asynchttpclient.AsyncCompletionHandler - https://localhost:57799
java.net.ConnectException: https://localhost:57799
    at org.asynchttpclient.netty.channel.NettyConnectListener.onFailure(NettyConnectListener.java:138)
    at org.asynchttpclient.netty.channel.NettyConnectListener$1.onFailure(NettyConnectListener.java:109)
    at org.asynchttpclient.netty.SimpleFutureListener.operationComplete(SimpleFutureListener.java:26)
    at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:683)
    at io.netty.util.concurrent.DefaultPromise.notifyListeners0(DefaultPromise.java:604)
    at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:564)
    at io.netty.util.concurrent.DefaultPromise.tryFailure(DefaultPromise.java:425)
    at io.netty.handler.ssl.SslHandler.notifyHandshakeFailure(SslHandler.java:1239)
    at io.netty.handler.ssl.SslHandler.setHandshakeFailure(SslHandler.java:1234)
    at io.netty.handler.ssl.SslHandler.channelInactive(SslHandler.java:726)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:193)
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:179)
    at io.netty.channel.DefaultChannelPipeline.fireChannelInactive(DefaultChannelPipeline.java:944)
    at io.netty.channel.AbstractChannel$AbstractUnsafe$7.run(AbstractChannel.java:687)
    at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:329)
    at io.netty.util.concurrent.SingleThreadEventExecutor.confirmShutdown(SingleThreadEventExecutor.java:628)
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:379)
    at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112)
    at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:137)
    at java.lang.Thread.run(Thread.java:745)
Caused by: java.nio.channels.ClosedChannelException: null
2016-06-06 08:50:04,044 [AsyncHttpClient-53-2] DEBUG io.netty.handler.ssl.SslHandler - [id: 0x662c4dff, L:/127.0.0.1:47186 ! R:localhost/127.0.0.1:57799] HANDSHAKEN: TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA256
2016-06-06 08:50:04,114 [AsyncHttpClient-54-1] DEBUG org.asynchttpclient.netty.channel.NettyConnectListener - Using non-cached Channel [id: 0xbec905ab, L:/127.0.0.1:47200 - R:localhost/127.0.0.1:57799] for POST '/foo/bar'
2016-06-06 08:50:04,115 [AsyncHttpClient-54-1] DEBUG io.netty.handler.ssl.SslHandler - [id: 0xbec905ab, L:/127.0.0.1:47200 - R:localhost/127.0.0.1:57799] HANDSHAKEN: TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA256
slandelle commented 8 years ago

How could we fail on connecting on a local server via loopback?! The only sane explanations I see are:

slandelle commented 8 years ago

Was probably caused by file descriptors starvation on CI, before proper tuning. Closing for now.