hc-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Jose Dillet (JIRA)" <j...@apache.org>
Subject [jira] [Updated] (HTTPASYNC-86) Race condition in async client when a keep alive connection is reused in POST request method
Date Thu, 18 Dec 2014 09:56:13 GMT

     [ https://issues.apache.org/jira/browse/HTTPASYNC-86?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]

Jose Dillet updated HTTPASYNC-86:
---------------------------------
    Attachment: httpasyncclient-test-3req.log
                AsyncClientRaceCondition3RequestSample.java

I have another program which makes 3 requests:
1) Creates connection, makes request, returns connection to the pool
2) Takes connection from the pool, makes request, returns connection to the pool
3) Takes connection from the pool, makes request, returns connection to the pool

It can happen that request 2) fails with ConnectionClosedException and request 3 succeeds,
while all 3 requests use the same connection. I'm attaching the sample program and the log
with this failing scenario.

These are the relevant lines from the log (for request 2 and 3):

2014-12-18 11:35:10,230 AsyncClientRaceCondition3RequestSample [main] INFO AsyncClientRaceCondition3RequestSample
- Processing second request
2014-12-18 11:35:10,230 org.apache.http.impl.nio.client.MainClientExec [main] DEBUG org.apache.http.impl.nio.client.MainClientExec
- [exchange: 2] start execution
...
2014-12-18 11:35:10,232 org.apache.http.impl.nio.client.DefaultClientExchangeHandlerImpl [main]
DEBUG org.apache.http.impl.nio.client.InternalHttpAsyncClient - [exchange: 2] Connection allocated:
CPoolProxy{http-outgoing-0 [ACTIVE]}
...
2014-12-18 11:35:10,789 AsyncClientRaceCondition3RequestSample [main] ERROR AsyncClientRaceCondition3RequestSample
- Exception in second request
2014-12-18 11:35:10,796 AsyncClientRaceCondition3RequestSample [main] INFO AsyncClientRaceCondition3RequestSample
- Processing third request
2014-12-18 11:35:10,797 org.apache.http.impl.nio.client.MainClientExec [main] DEBUG org.apache.http.impl.nio.client.MainClientExec
- [exchange: 3] start execution
...
2014-12-18 11:35:10,799 org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager$InternalPoolEntryCallback
[main] DEBUG org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager - Connection
leased: [id: http-outgoing-0][route: {}->http://downloads.smartbear.com:80][total kept
alive: 0; route allocated: 1 of 2; total allocated: 1 of 20]
2014-12-18 11:35:10,799 org.apache.http.impl.nio.client.DefaultClientExchangeHandlerImpl [main]
DEBUG org.apache.http.impl.nio.client.InternalHttpAsyncClient - [exchange: 3] Connection allocated:
CPoolProxy{http-outgoing-0 [ACTIVE]}
2014-12-18 11:35:10,799 org.apache.http.impl.nio.conn.LoggingIOSession [main] DEBUG org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl
- http-outgoing-0 10.23.67.169:56762<->64.34.176.155:80[ACTIVE][r:r]: Set attribute
http.nio.exchange-handler
2014-12-18 11:35:10,799 org.apache.http.impl.nio.conn.LoggingIOSession [main] DEBUG org.apache.http.impl.nio.conn.ManagedNHttpClientConnectionImpl
- http-outgoing-0 10.23.67.169:56762<->64.34.176.155:80[ACTIVE][rw:r]: Event set [w]
2014-12-18 11:35:11,518 org.apache.http.impl.nio.client.LoggingAsyncRequestExecutor [I/O dispatcher
1] DEBUG org.apache.http.nio.protocol.HttpAsyncRequestExecutor - http-outgoing-0 [ACTIVE]
[content length: 362; pos: 362; completed: true]
2014-12-18 11:35:11,518 org.apache.http.impl.nio.client.LoggingAsyncRequestExecutor [I/O dispatcher
1] DEBUG org.apache.http.nio.protocol.HttpAsyncRequestExecutor - http-outgoing-0 [ACTIVE]
Request ready
2014-12-18 11:35:11,518 org.apache.http.impl.nio.client.MainClientExec [I/O dispatcher 1]
DEBUG org.apache.http.impl.nio.client.MainClientExec - Connection route already established
...
2014-12-18 11:35:13,878 org.apache.http.impl.nio.client.LoggingAsyncRequestExecutor [I/O dispatcher
1] DEBUG org.apache.http.nio.protocol.HttpAsyncRequestExecutor - http-outgoing-0 [ACTIVE]
[content length: 362; pos: 362; completed: true]
2014-12-18 11:35:14,038 AsyncClientRaceCondition3RequestSample [main] INFO AsyncClientRaceCondition3RequestSample
- Response: HTTP/1.1 200 OK

Third request completes successfully by using the same connection which failed for second
request (http-outgoing-0). I believe this happens because the connection was not really closed,
so second request shouldn't have failed with ConnectionClosedException.

Jose

> Race condition in async client when a keep alive connection is reused in POST request
method
> --------------------------------------------------------------------------------------------
>
>                 Key: HTTPASYNC-86
>                 URL: https://issues.apache.org/jira/browse/HTTPASYNC-86
>             Project: HttpComponents HttpAsyncClient
>          Issue Type: Bug
>    Affects Versions: 4.0.2, 4.1-beta1
>         Environment: Ubuntu 12.04 64 bits Kernel 3.2.0-74
>            Reporter: Jose Dillet
>         Attachments: AsyncClientRaceCondition3RequestSample.java, AsyncClientRaceConditionSample.java,
httpasyncclient-test-3req.log, httpasyncclient-test.log
>
>
> I have found a race condition in the async client when a POST request reuses a keep alive
connection. We have around 2%-4% of our runs in a Continuous Integration environment failing
because of this issue.
> I have found a consistent way of forcing the failure by using a debugger, so I can force
the events to happen in the order which uncovers the problem.
> I have tested it on httpasyncclient 4.0.2 / httpcore 4.3.2 and httpasyncclient 4.1-beta1
/ httpcore 4.4-beta1 and it happens in both versions (the lines provided in the steps to reproduce
are from version 4.0.2).
> How to reproduce:
> 1) Add these breakpoints:
> a - DefaultClientExchangeHandlerImpl:304
> b - DefaultClientExchangeHandlerImpl:168
> 2) Run AsyncClientRaceConditionSample sample program
> Processing first request:
> -  Program hits breakpoint a -> Resume
> -  Program hits breakpoint b -> Resume
> Processing second request:
> - Program hits breakpoints a and b (in different threads)
> - Resume a)
> - Resume b)
> (Probably adding a small sleep after DefaultClientExchangeHandlerImpl:303 only for the
testing would also uncover the issue).
> ConnectionClosedException is thrown with this stack trace:
> Exception in thread "main" java.util.concurrent.ExecutionException: org.apache.http.ConnectionClosedException:
Connection closed
> 	at org.apache.http.concurrent.BasicFuture.getResult(BasicFuture.java:68)
> 	at org.apache.http.concurrent.BasicFuture.get(BasicFuture.java:77)
> 	at AsyncClientRaceConditionSample.process(AsyncClientRaceConditionSample.java:81)
> 	at AsyncClientRaceConditionSample.main(AsyncClientRaceConditionSample.java:45)
> Caused by: org.apache.http.ConnectionClosedException: Connection closed
> 	at org.apache.http.impl.nio.client.DefaultClientExchangeHandlerImpl.connectionAllocated(DefaultClientExchangeHandlerImpl.java:305)
> 	at org.apache.http.impl.nio.client.DefaultClientExchangeHandlerImpl.access$000(DefaultClientExchangeHandlerImpl.java:63)
> 	at org.apache.http.impl.nio.client.DefaultClientExchangeHandlerImpl$1.completed(DefaultClientExchangeHandlerImpl.java:360)
> 	at org.apache.http.impl.nio.client.DefaultClientExchangeHandlerImpl$1.completed(DefaultClientExchangeHandlerImpl.java:357)
> 	at org.apache.http.concurrent.BasicFuture.completed(BasicFuture.java:115)
> 	at org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager$InternalPoolEntryCallback.completed(PoolingNHttpClientConnectionManager.java:465)
> 	at org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager$InternalPoolEntryCallback.completed(PoolingNHttpClientConnectionManager.java:449)
> 	at org.apache.http.concurrent.BasicFuture.completed(BasicFuture.java:115)
> 	at org.apache.http.nio.pool.AbstractNIOConnPool.fireCallbacks(AbstractNIOConnPool.java:443)
> 	at org.apache.http.nio.pool.AbstractNIOConnPool.lease(AbstractNIOConnPool.java:276)
> 	at org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager.requestConnection(PoolingNHttpClientConnectionManager.java:261)
> 	at org.apache.http.impl.nio.client.DefaultClientExchangeHandlerImpl.requestConnection(DefaultClientExchangeHandlerImpl.java:351)
> 	at org.apache.http.impl.nio.client.DefaultClientExchangeHandlerImpl.start(DefaultClientExchangeHandlerImpl.java:126)
> 	at org.apache.http.impl.nio.client.InternalHttpAsyncClient.execute(InternalHttpAsyncClient.java:129)
> 	at org.apache.http.impl.nio.client.CloseableHttpAsyncClient.execute(CloseableHttpAsyncClient.java:72)
> 	at org.apache.http.impl.nio.client.CloseableHttpAsyncClient.execute(CloseableHttpAsyncClient.java:102)
> 	at org.apache.http.impl.nio.client.CloseableHttpAsyncClient.execute(CloseableHttpAsyncClient.java:87)
> 	at AsyncClientRaceConditionSample.process(AsyncClientRaceConditionSample.java:80)
> 	... 1 more
> Some analysis from my side:
> 1 - When the first request is processed, this is the execution order of relevant lines
(and the thread where it is processed):
> a - (I/O dispatcher 1) DefaultClientExchangeHandlerImpl<T>.connectionAllocated(NHttpClientConnection)
line: 303
> b - (I/O dispatcher 1) DefaultClientExchangeHandlerImpl<T>.connectionAllocated(NHttpClientConnection)
line: 304
> c - (I/O dispatcher 1) CPoolProxy.detach() line: 60
> d - (I/O dispatcher 1) DefaultClientExchangeHandlerImpl<T>.responseCompleted()
line: 168
> 2 - When the second request is processed c) might happen before b) which leads to the
problem:
> a - (main) DefaultClientExchangeHandlerImpl<T>.connectionAllocated(NHttpClientConnection)
line: 303
> c - (I/O dispatcher 1) CPoolProxy.detach() line: 60
> b - (main) DefaultClientExchangeHandlerImpl<T>.connectionAllocated(NHttpClientConnection)
line: 304
> e - (main) BasicFuture<T>.failed(Exception) line: 122
> d - (I/O dispatcher 1) DefaultClientExchangeHandlerImpl<T>.responseCompleted()
line: 168
> The problem is that in case 2 the connection can be closed before request is completed
because a) is processed in main thread and c) is processed in I/O dispatcher thread, so the
ordering b < c is not guaranteed.
> However in case 1 because all the events are processed in I/O dispatcher thread, the
ordering b < c is guaranteed (this seems to be true even if there are several dispatcher
threads).



--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@hc.apache.org
For additional commands, e-mail: dev-help@hc.apache.org


Mime
View raw message