sometimes I call AsyncHttpClient.execute but no response on the handler

[cplu]

I've post this problem on https://issues.sonatype.org/browse/AHC-120. Since no comments there I want to ask for help here.
I'm working on Android platform and I try to use this http client. The detail about this problem is below. I wonder if it is only exposed on Android.

I do sth like:
m_asyncHttpClient.prepareGet(http_url).setPerRequestConfig(request_config) .setHeader("Connection", "Keep-Alive")
.setHeader("Accept-Language" , ...)
.execute(...)

with a AsyncHandler given as param.

If I do the above repeatly (several times) within a connected network situation, and a few times afterwards within a connected-less (no cable is connected) situation, then there's no callback function triggered.

I trace to the code and found that NettyAsyncHttpProvider's doConnect will create or get a future with a NettyConnectListener, whose operationComplete is called and "if (f.isSuccess())" is true, then "future.provider().writeRequest" is called.
in NettyAsyncHttpProvider's writeRequest,
"if (!channel.isOpen() || !channel.isConnected())" returns true, so it returns and no handler callback is triggered.

I use a ning of version 1.6.5. is it a known issue?

[jfarcand]

Sound likes an issue. Can you add in your code a Thread.dumpStack inside the "if (!channel.isOpen() || !channel.isConnected())" and paste it here when the issue occurs? Thanks!

[cplu]

sure.
I had added some code near "if (!channel.isOpen() || !channel.isConnected())" in writeRequest to log sth ，so the line number may diff from the souce.

02-10 17:50:34.644: W/System.err(24665): java.lang.Throwable: stack dump
02-10 17:50:34.651: W/System.err(24665): at java.lang.Thread.dumpStack(Thread.java:612)
02-10 17:50:34.651: W/System.err(24665): at com.ning.http.client.providers.netty.NettyAsyncHttpProvider.writeRequest(NettyAsyncHttpProvider.java:358)
02-10 17:50:34.651: W/System.err(24665): at com.ning.http.client.providers.netty.NettyConnectListener.operationComplete(NettyConnectListener.java:78)
02-10 17:50:34.651: W/System.err(24665): at org.jboss.netty.channel.DefaultChannelFuture.notifyListener(DefaultChannelFuture.java:381)
02-10 17:50:34.651: W/System.err(24665): at org.jboss.netty.channel.DefaultChannelFuture.addListener(DefaultChannelFuture.java:148)
02-10 17:50:34.651: W/System.err(24665): at com.ning.http.client.providers.netty.NettyAsyncHttpProvider.doConnect(NettyAsyncHttpProvider.java:951)
02-10 17:50:34.651: W/System.err(24665): at com.ning.http.client.providers.netty.NettyAsyncHttpProvider.execute(NettyAsyncHttpProvider.java:782)
02-10 17:50:34.651: W/System.err(24665): at com.ning.http.client.AsyncHttpClient.executeRequest(AsyncHttpClient.java:484)
02-10 17:50:34.651: W/System.err(24665): at com.ning.http.client.AsyncHttpClient$BoundRequestBuilder.execute(AsyncHttpClient.java:227)
02-10 17:50:34.651: W/System.err(24665): at com.jwtech.ppclassclient.httpclientwrapper.NingHttpClientWrapper$3.run(NingHttpClientWrapper.java:142)
02-10 17:50:34.651: W/System.err(24665): at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1068)
02-10 17:50:34.659: W/System.err(24665): at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:561)
02-10 17:50:34.659: W/System.err(24665): at java.lang.Thread.run(Thread.java:1096)

[jfarcand]

Ok lost track of that issue and doesn't have the env. to test. Can you attach a diff of your patch that works? Thanks!

[cplu]

My ning version is 1.6.5.
The only logical difference I made to source code is in NettyAsyncHttpProvider.java, method writeRequest

here's several lines in this method

protected final void writeRequest(final Channel channel,
final AsyncHttpClientConfig config,
final NettyResponseFuture future,
final HttpRequest nettyRequest) {
try {
/**
* If the channel is dead because it was pooled and the remote server decided to close it,
* we just let it go and the closeChannel do it's work.
*/
if (!channel.isOpen() || !channel.isConnected()) {
throw new ChannelException("channel is not open or is not connected!");
}
......
The "throw new ChannelException" statement is the only diff from source code, where there's a "return" at the same line.

[cplu]

From what I've tested, The diff I made seems to work correctly in kinds of network environment.

[jfarcand]

The fix make sense, but I'm nerveous to put it in 1.7.3. I will cut 1.7.3 and then add it so it is included in 1.8.0. Would that works?

[cplu]

Sure.
Further tests are necessary.

[technocoreai]

Any updates? We're sometimes experiencing issues very similar to this (no handler methods called, but no exceptions or anything) and master branch doesn't include the fix.

[jfarcand]

@technocoreai I need a test case to reproduce. Do you have one you can share?

[technocoreai]

I'll see what I can do. It's very hard to produce on demand (it usually breaks after several hours of polling every 5-10 seconds), but one httpd/polling frequency makes it occur much more often than the rest, so I'll try building a test case out of it.

[azubkov]

Able to reproduce this with load test.
Reproducible on 1.6.5-1.7.16 and on trunk code from Github.

Put this test into async-http-client-netty-provider test directory:
http://pastie.org/8000590#121

And run this server on 50051 and 50056 ports:
http://pastie.org/8000636

Test description : test makes 1000 http request with uuid in each.
Special server answers back with received uuid.
In this way test collects uuid into 3 sets (all, responses, errors) and then gives your feedback if all 1000 were received.
Lets run main from test.

If we use setAllowPoolingConnection(true). , number of responses are missed :
(I have wait all the timeouts and have profiled VM memory with JProfiler to make sure that my Handlers were lost.)

2013-06-03 16:54:48,504 [Timer-1] ERROR org.asynchttpclient.NngMissedResponsesTest - Http requests statistics
requestUuids size : 1000
uuidsReceived size : 941
uuidsReceivedAsResponse size : 940
uuidsReceivedAsError size : 1

without caching setAllowPoolingConnection(false). all works :

2013-06-03 17:24:46,884 [Timer-0] ERROR org.asynchttpclient.NngMissedResponsesTest - Http requests statistics
requestUuids size : 1000
uuidsReceived size : 1000
uuidsReceivedAsResponse size : 1000
uuidsReceivedAsError size : 0
Missed uuids :

With described exception from NettyAsyncHttpProvider and setAllowPoolingConnection(true). all works too :

2013-06-03 16:59:13,221 [Timer-1] ERROR org.asynchttpclient.NngMissedResponsesTest - Http requests statistics
requestUuids size : 1000
uuidsReceived size : 1000
uuidsReceivedAsResponse size : 951
uuidsReceivedAsError size : 49

[slandelle]

That's something I planned on investigating someday... Just busy with Parts at the moment...

[slandelle]

Looks like a duplicate of #415