Got an 'invalid version format: <HTML>'

1,166 views
Skip to first unread message

Brice Dutheil

unread,
Nov 20, 2012, 10:05:19 AM11/20/12
to asyncht...@googlegroups.com
Hi,

AsyncHttpClient is working quite well. However there is some corner cases that we have not yet troubleshooted, are we doing something wrong ? I believe there is a bug, but I fail to see where.


Currently we have experience a TimeoutException thrown from the NettyResponseFuture.get (when the CountDownLatch is expired).

However in the log I discovered a strange 'invalid version format: <HTML>' that happens before the timeout :

15:11:32.310 [New I/O  worker #1] [DEBUG NettyConnectionsPool - Adding uri: https://someurl.com:443 for channel [id: 0x7539c30e, /192.168.1.100:51656 => someurl.com/84.84.84.84:443]
15:11:32.316 [New I/O  worker #1] [DEBUG NettyAsyncHttpProvider - Unexpected I/O exception on channel [id: 0x7539c30e, /192.168.1.100:51656 => someurl.com/84.84.84.84:443]
java.lang.IllegalArgumentException: invalid version format: <HTML>
at org.jboss.netty.handler.codec.http.HttpVersion.<init>(HttpVersion.java:102) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.handler.codec.http.HttpVersion.valueOf(HttpVersion.java:62) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.handler.codec.http.HttpResponseDecoder.createMessage(HttpResponseDecoder.java:105) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.handler.codec.http.HttpMessageDecoder.decode(HttpMessageDecoder.java:187) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.handler.codec.http.HttpClientCodec$Decoder.decode(HttpClientCodec.java:140) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.handler.codec.http.HttpClientCodec$Decoder.decode(HttpClientCodec.java:128) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.handler.codec.replay.ReplayingDecoder.callDecode(ReplayingDecoder.java:548) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.handler.codec.replay.ReplayingDecoder.messageReceived(ReplayingDecoder.java:445) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.handler.codec.http.HttpClientCodec.handleUpstream(HttpClientCodec.java:92) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:296) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.handler.codec.frame.FrameDecoder.unfoldAndFireMessageReceived(FrameDecoder.java:352) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.handler.codec.frame.FrameDecoder.callDecode(FrameDecoder.java:334) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.handler.codec.frame.FrameDecoder.messageReceived(FrameDecoder.java:245) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:268) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:255) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.channel.socket.nio.NioWorker.read(NioWorker.java:94) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.channel.socket.nio.AbstractNioWorker.processSelectedKeys(AbstractNioWorker.java:372) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.channel.socket.nio.AbstractNioWorker.run(AbstractNioWorker.java:246) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.channel.socket.nio.NioWorker.run(NioWorker.java:38) ~[netty-3.4.4.Final.jar:na]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110) [na:1.7.0_09]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603) [na:1.7.0_09]
at java.lang.Thread.run(Thread.java:722) [na:1.7.0_09]
15:11:32.320 [New I/O  worker #1] [DEBUG NettyAsyncHttpProvider - Closing Channel [id: 0x7539c30e, /192.168.1.100:51656 => someurl.com/84.84.84.84:443] 
15:11:32.325 [New I/O  worker #1] [DEBUG NettyAsyncHttpProvider - Unexpected I/O exception on channel [id: 0x7539c30e, /192.168.1.100:51656 :> someurl.com/84.84.84.84:443]
java.lang.IllegalArgumentException: invalid version format: </HTML>
at org.jboss.netty.handler.codec.http.HttpVersion.<init>(HttpVersion.java:102) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.handler.codec.http.HttpVersion.valueOf(HttpVersion.java:62) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.handler.codec.http.HttpResponseDecoder.createMessage(HttpResponseDecoder.java:105) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.handler.codec.http.HttpMessageDecoder.decode(HttpMessageDecoder.java:187) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.handler.codec.http.HttpClientCodec$Decoder.decode(HttpClientCodec.java:140) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.handler.codec.http.HttpClientCodec$Decoder.decode(HttpClientCodec.java:128) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.handler.codec.replay.ReplayingDecoder.callDecode(ReplayingDecoder.java:548) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.handler.codec.replay.ReplayingDecoder.cleanup(ReplayingDecoder.java:622) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.handler.codec.replay.ReplayingDecoder.channelDisconnected(ReplayingDecoder.java:527) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.handler.codec.http.HttpClientCodec.handleUpstream(HttpClientCodec.java:92) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.handler.codec.frame.FrameDecoder.cleanup(FrameDecoder.java:379) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.handler.codec.frame.FrameDecoder.channelDisconnected(FrameDecoder.java:261) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.handler.ssl.SslHandler.channelDisconnected(SslHandler.java:523) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.channel.Channels.fireChannelDisconnected(Channels.java:399) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.channel.socket.nio.AbstractNioWorker.close(AbstractNioWorker.java:616) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.channel.socket.nio.NioClientSocketPipelineSink.eventSunk(NioClientSocketPipelineSink.java:90) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.channel.Channels.close(Channels.java:837) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.handler.ssl.SslHandler$ClosingChannelFutureListener.operationComplete(SslHandler.java:1206) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.channel.DefaultChannelFuture.notifyListener(DefaultChannelFuture.java:399) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.channel.DefaultChannelFuture.addListener(DefaultChannelFuture.java:145) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.handler.ssl.SslHandler.closeOutboundAndChannel(SslHandler.java:1164) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.handler.ssl.SslHandler.handleDownstream(SslHandler.java:470) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.handler.codec.oneone.OneToOneEncoder.handleDownstream(OneToOneEncoder.java:55) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.handler.codec.http.HttpClientCodec.handleDownstream(HttpClientCodec.java:97) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.handler.stream.ChunkedWriteHandler.handleDownstream(ChunkedWriteHandler.java:108) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.channel.Channels.close(Channels.java:821) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.channel.AbstractChannel.close(AbstractChannel.java:194) ~[netty-3.4.4.Final.jar:na]
at com.ning.http.client.providers.netty.NettyAsyncHttpProvider.finishChannel(NettyAsyncHttpProvider.java:1133) ~[async-http-client-1.7.6-fix-157.jar:na]
at com.ning.http.client.providers.netty.NettyAsyncHttpProvider.closeChannel(NettyAsyncHttpProvider.java:1118) ~[async-http-client-1.7.6-fix-157.jar:na]
at com.ning.http.client.providers.netty.NettyAsyncHttpProvider.exceptionCaught(NettyAsyncHttpProvider.java:1612) ~[async-http-client-1.7.6-fix-157.jar:na]
at org.jboss.netty.handler.stream.ChunkedWriteHandler.handleUpstream(ChunkedWriteHandler.java:141) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.handler.codec.replay.ReplayingDecoder.exceptionCaught(ReplayingDecoder.java:539) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.handler.codec.http.HttpClientCodec.handleUpstream(HttpClientCodec.java:92) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.handler.ssl.SslHandler.exceptionCaught(SslHandler.java:578) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.channel.Channels.fireExceptionCaught(Channels.java:533) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.channel.AbstractChannelSink.exceptionCaught(AbstractChannelSink.java:49) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:296) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.handler.codec.frame.FrameDecoder.unfoldAndFireMessageReceived(FrameDecoder.java:352) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.handler.codec.frame.FrameDecoder.callDecode(FrameDecoder.java:334) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.handler.codec.frame.FrameDecoder.messageReceived(FrameDecoder.java:245) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:268) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:255) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.channel.socket.nio.NioWorker.read(NioWorker.java:94) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.channel.socket.nio.AbstractNioWorker.processSelectedKeys(AbstractNioWorker.java:372) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.channel.socket.nio.AbstractNioWorker.run(AbstractNioWorker.java:246) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.channel.socket.nio.NioWorker.run(NioWorker.java:38) ~[netty-3.4.4.Final.jar:na]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110) [na:1.7.0_09]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603) [na:1.7.0_09]
at java.lang.Thread.run(Thread.java:722) [na:1.7.0_09]


The issue arises when doing successive multipart request with code such as :

     Request uploadRequest1 = new RequestBuilder("POST").setUrl("https://someurl.com/image/upload")
        .addBodyPart(new StringPart("tags", "art,oeuvre,leonardo,da vinci"))
        .addBodyPart(new StringPart("title", "Joconde"))
        .addBodyPart(new StringPart("sha1Digest", "22e2eb75e6da333f9d842ff09bd5c15c080134b5"))
        .addBodyPart(new FilePart("imageFile", jocondeThumb.getAbsolutePath(), jocondeThumb)).build();

    Response uploadResponse1 = asyncHttpClient.prepareRequest(uploadRequest1).execute( new AsyncCompletionHandlerBase()).get();

    Request uploadRequest1 = new RequestBuilder("POST").setUrl("https://someurl.com/image/upload")
        .addBodyPart(new StringPart("tags", "art,oeuvre,van gogh"))
        .addBodyPart(new StringPart("title", "La Nuit étoilée"))
        .addBodyPart(new StringPart("sha1Digest", "22e2eb75e6da333f9d842ff09bd5c15c080134b5"))
        .addBodyPart(new FilePart("imageFile", nuitEtoileeThumb.getAbsolutePath(), nuitEtoileeThumb)).build();

    Response uploadResponse1 = asyncHttpClient.prepareRequest(uploadRequest1).execute( new AsyncCompletionHandlerBase()).get();


Note we are using SSL connections, the server usually closes the channel after each request. And we are developing with Oracle JDK 7 (on update 5 or 9, on OSX, Linux (unknown distribution) and Windows 7).



Also here's a single thread dump of the last worker thread alive :

java.lang.Thread.State: RUNNABLE
at com.ning.http.client.providers.netty.BodyChunkedInput.peekNextChuck(BodyChunkedInput.java:48)
at com.ning.http.client.providers.netty.BodyChunkedInput.isEndOfInput(BodyChunkedInput.java:75)
at org.jboss.netty.handler.stream.ChunkedWriteHandler.flush(ChunkedWriteHandler.java:221)
at org.jboss.netty.handler.stream.ChunkedWriteHandler.handleDownstream(ChunkedWriteHandler.java:120)
at org.jboss.netty.channel.DefaultChannelPipeline.sendDownstream(DefaultChannelPipeline.java:591)
at org.jboss.netty.channel.DefaultChannelPipeline.sendDownstream(DefaultChannelPipeline.java:582)
at org.jboss.netty.channel.Channels.write(Channels.java:712)
at org.jboss.netty.channel.Channels.write(Channels.java:679)
at org.jboss.netty.channel.AbstractChannel.write(AbstractChannel.java:245)
at com.ning.http.client.providers.netty.NettyAsyncHttpProvider.writeRequest(NettyAsyncHttpProvider.java:540)
at com.ning.http.client.providers.netty.NettyConnectListener.operationComplete(NettyConnectListener.java:82)
at org.jboss.netty.channel.DefaultChannelFuture.notifyListener(DefaultChannelFuture.java:399)
at org.jboss.netty.channel.DefaultChannelFuture.notifyListeners(DefaultChannelFuture.java:385)
at org.jboss.netty.channel.DefaultChannelFuture.setSuccess(DefaultChannelFuture.java:334)
at org.jboss.netty.handler.ssl.SslHandler.setHandshakeSuccess(SslHandler.java:1107)
at org.jboss.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:980)
at org.jboss.netty.handler.ssl.SslHandler.decode(SslHandler.java:673)
at org.jboss.netty.handler.codec.frame.FrameDecoder.callDecode(FrameDecoder.java:317)
at org.jboss.netty.handler.codec.frame.FrameDecoder.messageReceived(FrameDecoder.java:207)
at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:75)
at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564)
at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:559)
at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:268)
at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:255)
at org.jboss.netty.channel.socket.nio.NioWorker.read(NioWorker.java:94)
at org.jboss.netty.channel.socket.nio.AbstractNioWorker.processSelectedKeys(AbstractNioWorker.java:372)
at org.jboss.netty.channel.socket.nio.AbstractNioWorker.run(AbstractNioWorker.java:246)
at org.jboss.netty.channel.socket.nio.NioWorker.run(NioWorker.java:38)
at org.jboss.netty.util.ThreadRenamingRunnable.run(ThreadRenamingRunnable.java:102)
at org.jboss.netty.util.internal.DeadLockProofWorker$1.run(DeadLockProofWorker.java:42)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
at java.lang.Thread.run(Thread.java:722)



Many thanks in advance

Cheers,
-- Brice

Brice Dutheil

unread,
Nov 20, 2012, 10:15:07 AM11/20/12
to asyncht...@googlegroups.com
Forgot to mention that we are using a custom version 1.7.6 with a fix for the issue 157 (about headers).

In the meantime I google a bit and found an old issue : https://issues.sonatype.org/browse/AHC-24
That looks the same as we experience. I'll continue investigating.

Brice Dutheil

unread,
Nov 21, 2012, 9:13:06 AM11/21/12
to asyncht...@googlegroups.com
I've continued the investigation a bit I confirmed that using other HTTP providers than Netty was working in my case.

JDKAsyncHttpProvider => ok, but it uses blocking io
GrizzlyAsyncHttpProvider => ok, though I needed to use version 2.3-beta8 , as version 2.2.9 is wierdly missing the method CookieBuilder.ServerCookieBuilder.build()

I cannot yet bet on wether the issue is in AHC Netty Provider or Netty itself.


Cheers,
Brice


On Tuesday, November 20, 2012 4:05:19 PM UTC+1, Brice Dutheil wrote:

Stéphane Landelle

unread,
Nov 21, 2012, 9:18:04 AM11/21/12
to asyncht...@googlegroups.com
Hi Brice,

Have you tried upgrading Netty? You seem to use 3.4.4 while latest is 3.5.10 and I think I've seen some SSL bug fixes lately.

Stéphane

2012/11/21 Brice Dutheil <brice....@gmail.com>
netty-3.4.4.Final

Brice Dutheil

unread,
Nov 21, 2012, 9:38:37 AM11/21/12
to asyncht...@googlegroups.com
Hi Stéphane,

Thx for the info I didn't try that as it was a runtime dependency.
However I got the same behavior with netty 3.5.10.Final, the AHC client just hang.

The logger trace reveals the same raised exceptions in the workers. Not sure if it's relevant at this point but it doesn't matter wether netty uses blocking or non-blocking IO.


Cheers,
-- Brice



--
You received this message because you are subscribed to the Google Groups "asynchttpclient" group.
To post to this group, send email to asyncht...@googlegroups.com.
To unsubscribe from this group, send email to asynchttpclie...@googlegroups.com.
For more options, visit this group at http://groups.google.com/group/asynchttpclient?hl=en.

Jeanfrancois Arcand

unread,
Nov 21, 2012, 10:45:06 AM11/21/12
to asyncht...@googlegroups.com
Salut,

can you send me a test case at jfar...@apache.org? I'm unable to reproduce it locally so I want to save time and make sure I do it properly.

Thanks

-- Jeanfrancois

Brice Dutheil

unread,
Nov 21, 2012, 11:02:41 AM11/21/12
to asynchttpclient
Hi,

I'll try to work something out in my scarce free time, though it might not be in the near time, as we are experiencing this only with a third party server that is only available in the private network. We could only reproduce the issue with this server and with Netty + AHC.

Also note that AHC is only hanging to read the response, while the request is sent and received as expected.

Cheers,
-- Brice

Brice Dutheil

unread,
Dec 4, 2012, 6:15:52 AM12/4/12
to asyncht...@googlegroups.com
Interesting issue there : https://github.com/AsyncHttpClient/async-http-client/issues/173
The stack trace differ, but the symptoms are similar.

I'll need to try a new build with the included pull request in branch 1.7.x : https://github.com/AsyncHttpClient/async-http-client/issues/174

Cheers,
Brice
-- Brice



Cheers,
-- Brice



To post to this group, send email to asynchttpclient@googlegroups.com.
To unsubscribe from this group, send email to asynchttpclient+unsubscribe@googlegroups.com.

For more options, visit this group at http://groups.google.com/group/asynchttpclient?hl=en.
--
You received this message because you are subscribed to the Google Groups "asynchttpclient" group.
To post to this group, send email to asynchttpclient@googlegroups.com.
To unsubscribe from this group, send email to asynchttpclient+unsubscribe@googlegroups.com.

For more options, visit this group at http://groups.google.com/group/asynchttpclient?hl=en.

--
You received this message because you are subscribed to the Google Groups "asynchttpclient" group.
To post to this group, send email to asynchttpclient@googlegroups.com.
To unsubscribe from this group, send email to asynchttpclient+unsubscribe@googlegroups.com.

Brice Dutheil

unread,
Jan 15, 2013, 11:34:44 AM1/15/13
to asyncht...@googlegroups.com
Little update, I'm still experiencing the issue with Netty 3.6.1 and AHC 1.7.9. And still I cannot reproduce the issue with a different HTTPS server than our private one.

I have tried with blocking IO and non blocking IO.

36mNettyAsyncHttpProvider.java:1383 [0;39m - invalid version format: <HTML>
java.lang.IllegalArgumentException: invalid version format: <HTML>
at org.jboss.netty.handler.codec.http.HttpVersion.<init>(HttpVersion.java:102) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.handler.codec.http.HttpVersion.valueOf(HttpVersion.java:62) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.handler.codec.http.HttpResponseDecoder.createMessage(HttpResponseDecoder.java:105) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.handler.codec.http.HttpMessageDecoder.decode(HttpMessageDecoder.java:187) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.handler.codec.http.HttpClientCodec$Decoder.decode(HttpClientCodec.java:140) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.handler.codec.http.HttpClientCodec$Decoder.decode(HttpClientCodec.java:128) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.handler.codec.replay.ReplayingDecoder.callDecode(ReplayingDecoder.java:548) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.handler.codec.replay.ReplayingDecoder.messageReceived(ReplayingDecoder.java:445) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.handler.codec.http.HttpClientCodec.handleUpstream(HttpClientCodec.java:92) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:296) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.handler.codec.frame.FrameDecoder.unfoldAndFireMessageReceived(FrameDecoder.java:352) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.handler.codec.frame.FrameDecoder.callDecode(FrameDecoder.java:334) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.handler.codec.frame.FrameDecoder.messageReceived(FrameDecoder.java:245) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:268) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:255) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.channel.socket.nio.NioWorker.read(NioWorker.java:94) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.channel.socket.nio.AbstractNioWorker.processSelectedKeys(AbstractNioWorker.java:372) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.channel.socket.nio.AbstractNioWorker.run(AbstractNioWorker.java:246) ~[netty-3.4.4.Final.jar:na]
at org.jboss.netty.channel.socket.nio.NioWorker.run(NioWorker.java:38) ~[netty-3.4.4.Final.jar:na]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110) [na:1.7.0_09]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603) [na:1.7.0_09]
at java.lang.Thread.run(Thread.java:722) [na:1.7.0_09]

At least is doesn't hang, and the stack looks like it's related to netty.

Sorry I cannot set up a reproducible test.

Cheers,
-- brice

Jeanfrancois Arcand

unread,
Jan 15, 2013, 11:39:49 AM1/15/13
to asyncht...@googlegroups.com
Salut,

it seems the server is sending a response without the header being added. If you can snoop the network for a couple of days (I know, it's a pain) and see if you can catch when this happens, that would help a lot.

Thanks

-- Jeanfrancois
To view this discussion on the web visit https://groups.google.com/d/msg/asynchttpclient/-/Uai9VPmtiZoJ.
To post to this group, send email to asyncht...@googlegroups.com.
To unsubscribe from this group, send email to asynchttpclie...@googlegroups.com.

Brice Dutheil

unread,
Jan 15, 2013, 1:35:30 PM1/15/13
to asyncht...@googlegroups.com
Hi,

Unfortunately the trafic is in SSL. Though it might be noteworthy to say this server is using many many headers to express statuses, parameters etc, except for the real payload.

At the moment Grizzly behaves a bit better with this server, but we are seeing a lot of memory consumption due to this high level of headers. (Even an uncanny IndexOutOfBoundsException in their HeapBuffer).

-- Brice



Cheers,
-- Brice



To post to this group, send email to asyncht...@googlegroups.com.
To unsubscribe from this group, send email to asynchttpclie...@googlegroups.com.
For more options, visit this group at http://groups.google.com/group/asynchttpclient?hl=en.
--
You received this message because you are subscribed to the Google Groups "asynchttpclient" group.
To post to this group, send email to asyncht...@googlegroups.com.
To unsubscribe from this group, send email to asynchttpclie...@googlegroups.com.
For more options, visit this group at http://groups.google.com/group/asynchttpclient?hl=en.
--
You received this message because you are subscribed to the Google Groups "asynchttpclient" group.
To post to this group, send email to asyncht...@googlegroups.com.
To unsubscribe from this group, send email to asynchttpclie...@googlegroups.com.
For more options, visit this group at http://groups.google.com/group/asynchttpclient?hl=en.

Alexey S

unread,
Jan 15, 2013, 3:27:10 PM1/15/13
to asyncht...@googlegroups.com
Hi,

>
> At the moment Grizzly behaves a bit better with this server, but we are
> seeing a lot of memory consumption due to this high level of headers. (Even
> an uncanny IndexOutOfBoundsException in their HeapBuffer).
If it's possible, can you pls. share the entire
IndexOutOfBoundsException w/ a stacktrace?

Thanks.

WBR,
Alexey.
> https://groups.google.com/d/msg/asynchttpclient/-/F44eOnrC17oJ.

Brice Dutheil

unread,
Jan 16, 2013, 6:18:40 AM1/16/13
to asynchttpclient
Hi Alexey,

Here's a truncated stacktrace, cannot expose more.

Caused by: java.lang.IndexOutOfBoundsException
        at org.glassfish.grizzly.memory.HeapBuffer.get(HeapBuffer.java:343)
        at org.glassfish.grizzly.memory.BuffersBuffer.get(BuffersBuffer.java:702)
        at org.glassfish.grizzly.http.util.BufferChunk.equalsIgnoreCase(BufferChunk.java:274)
        at org.glassfish.grizzly.http.util.DataChunk.equalsIgnoreCase(DataChunk.java:545)
        at org.glassfish.grizzly.http.util.ValuesIterator.findNext(MimeHeaders.java:689)
        at org.glassfish.grizzly.http.util.ValuesIterator.<init>(MimeHeaders.java:682)
        at org.glassfish.grizzly.http.util.MimeHeaders$2.iterator(MimeHeaders.java:308)
        at com.ning.http.client.providers.grizzly.GrizzlyResponseHeaders.getHeaders(GrizzlyResponseHeaders.java:67)
        at com.ning.http.client.providers.grizzly.GrizzlyResponse.getHeader(GrizzlyResponse.java:205)
        <our code that want to read the value of 2 specific headers ( response.getHeader("HEADER_NAME"); )>

We are also seeing huge heap usage (hundreds of Megabytes) when we call this HTTP API. If we don't our app only uses around 50 mb while processing thousands of items. During the processing it will be discussing with that third-party server that is mostly based on HTTP headers and some API can returns also thousand of HTTP headers (99% of headers line is actually very short).


Where the code is thrown, we found that the index is not in the range, for some reason we don't yet understand, as we are not familiar with grizzly : 

    public byte get(int index) {
        if (index < 0 || index >= lim) {
            throw new IndexOutOfBoundsException();
        }
        return heap[offset + index];
    }

Before that the index is transformed in a toActiveBufferPos method, I don't have access to the real numbers anymore, but the index value is around 800 and activeBufferLowerBound to 40000 at some point in time.

    private int toActiveBufferPos(final int index) {
        return index - activeBufferLowerBound;
    }

Sorry that's the only thing I can disclose at the moment.


-- Brice

llirik

unread,
Jul 30, 2013, 4:31:44 AM7/30/13
to asyncht...@googlegroups.com

Hi All,

I also came across invalid version exception in my application.
java.lang.IllegalArgumentException: invalid version format: ?
at org.jboss.netty.handler.codec.http.HttpVersion.<init>(HttpVersion.java:102)
at org.jboss.netty.handler.codec.http.HttpVersion.valueOf(HttpVersion.java:62)
at org.jboss.netty.handler.codec.http.HttpResponseDecoder.createMessage(HttpResponseDecoder.java:104)
at org.jboss.netty.handler.codec.http.HttpMessageDecoder.decode(HttpMessageDecoder.java:189)
at org.jboss.netty.handler.codec.http.HttpClientCodec$Decoder.decode(HttpClientCodec.java:143)
at org.jboss.netty.handler.codec.http.HttpClientCodec$Decoder.decode(HttpClientCodec.java:127)
at org.jboss.netty.handler.codec.replay.ReplayingDecoder.callDecode(ReplayingDecoder.java:500)

I`m using "com.ning" % "async-http-client" % "1.7.18" and "io.netty" % "netty" % "3.6.6.Final" for testing.

My testing scenario is to fetch review from target server using https.

Actually I tried several scenarios to see what can be wrong:
1. fetch review from target server via http - works OK
2. fetch review from target server via https - works OK
3. fetch review from target server via http via proxy - works OK
4. fetch review from target server via https via proxy - not working 

In 4th scenario first request for review is successful, but subsequent request when AHC tries to reuse cached channel is failing, failing in 2 different ways - return invalid version or request takes too long (AHC tries to use cache channel, after 5s close it and tries next cached channel from the pool, until AHC decides to create fresh new channel which works). Debug logs attached for both cases.

I made further investigation and I think issue with invalid version is related to protocol to proxy which was used to create connection.

In my code I was using builder.setProxyServer(new ProxyServer(host, port)) to set proxy, which is using HTTP protocol, changing it to builder.setProxyServer(new ProxyServer(HTTPS, host, port)) solved the problem with invalid version and with request took to long.

Now I have http/https connection pooling working. 

Hope it helps.

Kyrylo




cached_channel_closed.txt
invalid_version_debug_log.txt

Greg Pendlebury

unread,
Jan 29, 2014, 6:08:31 PM1/29/14
to asyncht...@googlegroups.com
I ended up in this thread from a Google search, so apologies if there is a better location.

I'm experiencing the same error consistently when our application starts up. It poll a web service looking for work to do and always on the third attempt we get this crash. After turning DEBUG and TRACE logging for both AHC and Netty I took a stab at the only difference I could see... the failed requests are always on re-used connection and return null content:

09:56:50.214 [indexer-dispatchers.high-priority-14] DEBUG c.n.h.c.p.n.NettyAsyncHttpProvider - Using cached Channel [id: 0x2837ac25, /0:0:0:0:0:0:0:0:49738 => <snip>:8083]
 for uri http://<snip>:8083/indexer/article/checkForIndexRequired?rows=30

09:56:50.214 [indexer-dispatchers.high-priority-14] DEBUG c.n.h.c.p.n.NettyAsyncHttpProvider -
Using cached Channel [id: 0x2837ac25, /0:0:0:0:0:0:0:0:49738 => <snip>:8083]
 for request
DefaultHttpRequest(chunked: false)
GET /indexer/article/checkForIndexRequired?rows=30 HTTP/1.1
Host: <snip>:8083
Connection: keep-alive
Accept: */*
User-Agent: NING/1.0

09:56:50.224 [New I/O worker #3] DEBUG c.n.h.c.p.n.NettyAsyncHttpProvider - Unexpected I/O exception on channel [id: 0x2837ac25, /0:0:0:0:0:0:0:0:49738 => <snip>:8083]
java.lang.IllegalArgumentException: invalid version format: [
    at org.jboss.netty.handler.codec.http.HttpVersion.<init>(HttpVersion.java:102) ~[netty-3.6.6.Final.jar:na]
    at org.jboss.netty.handler.codec.http.HttpVersion.valueOf(HttpVersion.java:62) ~[netty-3.6.6.Final.jar:na]
    at org.jboss.netty.handler.codec.http.HttpResponseDecoder.createMessage(HttpResponseDecoder.java:104) ~[netty-3.6.6.Final.jar:na]
    at org.jboss.netty.handler.codec.http.HttpMessageDecoder.decode(HttpMessageDecoder.java:189) ~[netty-3.6.6.Final.jar:na]
    at org.jboss.netty.handler.codec.http.HttpClientCodec$Decoder.decode(HttpClientCodec.java:143) ~[netty-3.6.6.Final.jar:na]
    at org.jboss.netty.handler.codec.http.HttpClientCodec$Decoder.decode(HttpClientCodec.java:127) ~[netty-3.6.6.Final.jar:na]
    at org.jboss.netty.handler.codec.replay.ReplayingDecoder.callDecode(ReplayingDecoder.java:500) ~[netty-3.6.6.Final.jar:na]
    at org.jboss.netty.handler.codec.replay.ReplayingDecoder.messageReceived(ReplayingDecoder.java:485) ~[netty-3.6.6.Final.jar:na]
    at org.jboss.netty.handler.codec.http.HttpClientCodec.handleUpstream(HttpClientCodec.java:92) ~[netty-3.6.6.Final.jar:na]
    at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:268) ~[netty-3.6.6.Final.jar:na]
    at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:255) ~[netty-3.6.6.Final.jar:na]
    at org.jboss.netty.channel.socket.nio.NioWorker.read(NioWorker.java:88) ~[netty-3.6.6.Final.jar:na]
    at org.jboss.netty.channel.socket.nio.AbstractNioWorker.process(AbstractNioWorker.java:109) ~[netty-3.6.6.Final.jar:na]
    at org.jboss.netty.channel.socket.nio.AbstractNioSelector.run(AbstractNioSelector.java:312) ~[netty-3.6.6.Final.jar:na]
    at org.jboss.netty.channel.socket.nio.AbstractNioWorker.run(AbstractNioWorker.java:90) ~[netty-3.6.6.Final.jar:na]
    at org.jboss.netty.channel.socket.nio.NioWorker.run(NioWorker.java:178) ~[netty-3.6.6.Final.jar:na]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110) [na:1.7.0_04]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603) [na:1.7.0_04]
    at java.lang.Thread.run(Thread.java:722) [na:1.7.0_04]
09:56:50.225 [New I/O worker #3] DEBUG c.n.h.c.p.n.NettyAsyncHttpProvider - Was unable to recover Future: NettyResponseFuture{currentRetry=0,
    isDone=false,
    isCancelled=false,
    asyncHandler=au.gov.nla.newspapers.indexer.util.async.AsyncActorCallbackJson@1597ec49,
    requestTimeoutInMs=60000,
    nettyRequest=DefaultHttpRequest(chunked: false)
GET /indexer/article/checkForIndexRequired?rows=30 HTTP/1.1
Host: <snip>:8083
Connection: keep-alive
Accept: */*
User-Agent: NING/1.0,
    content=null,
    uri=http://<snip>:8083/indexer/article/checkForIndexRequired?rows=30,
    keepAlive=true,
    httpResponse=null,
    exEx=null,
    redirectCount=0,
    reaperFuture=com.ning.http.client.providers.netty.NettyAsyncHttpProvider$ReaperFuture@576b1c32,
    inAuth=false,
    statusReceived=false,
    touch=580693775}
09:56:50.225 [New I/O worker #3] DEBUG c.n.h.c.p.n.NettyAsyncHttpProvider - Aborting Future NettyResponseFuture{currentRetry=0,
    isDone=false,
    isCancelled=false,
    asyncHandler=au.gov.nla.newspapers.indexer.util.async.AsyncActorCallbackJson@1597ec49,
    requestTimeoutInMs=60000,
    nettyRequest=DefaultHttpRequest(chunked: false)
GET /indexer/article/checkForIndexRequired?rows=30 HTTP/1.1
Host: <snip>:8083
Connection: keep-alive
Accept: */*
User-Agent: NING/1.0,
    content=null,
    uri=http://<snip>:8083/indexer/article/checkForIndexRequired?rows=30,
    keepAlive=true,
    httpResponse=null,
    exEx=null,
    redirectCount=0,
    reaperFuture=com.ning.http.client.providers.netty.NettyAsyncHttpProvider$ReaperFuture@576b1c32,
    inAuth=false,
    statusReceived=false,
    touch=580693775}

Disabling connection pooling made the problem go away:
    AsyncHttpClientConfig.Builder builder = new AsyncHttpClientConfig.Builder();
    builder.setAllowPoolingConnection(false);

Ta,
Greg

Jeanfrancois Arcand

unread,
Jan 29, 2014, 6:16:31 PM1/29/14
to asyncht...@googlegroups.com
Salut,

which version of AHC are you using? If you remote server is available, I would like to give it a try. I've never been able to reproduce the issue, but clearly the issue happens because the connection is getting cached but the server still send some bytes.

Thanks

-- Jeanfrancois
--
You received this message because you are subscribed to the Google Groups "asynchttpclient" group.
To unsubscribe from this group and stop receiving emails from it, send an email to asynchttpclie...@googlegroups.com.

To post to this group, send email to asyncht...@googlegroups.com.

Greg Pendlebury

unread,
Jan 29, 2014, 6:22:33 PM1/29/14
to asyncht...@googlegroups.com
It was fairly recent, but I updated to 1.7.24 today and the problem is still there.

The server is an internal dev server, but it is a basic spring mvc app that responds like so when no work is pending:

[gpendleb@<snip> ~]$ curl -i http://<snip>:8083/indexer/article/checkForIndexRequired?rows=30
HTTP/1.1 204 No Content
Content-Type: application/json;charset=UTF-8
Server: Jetty(9.0.2.v20130417)



Maga Abdurakhmanov

unread,
Mar 26, 2014, 2:36:23 PM3/26/14
to asyncht...@googlegroups.com
Hi! 

I have similar problem and it's difficult to investigate deeper because i'm getting this problem with Play (WS) which uses asynchttpclient.
I've took a look at how WS library uses asynchttpclient, and here is how it's instantiated and then that variable instance is shared between all threads in Play:


val asyncHttpConfig = new AsyncHttpClientConfig.Builder()
      .setConnectionTimeoutInMs(getMilliseconds("ws.timeout.connection").orElse(wsTimeout).getOrElse(120000L).toInt)
      .setIdleConnectionTimeoutInMs(getMilliseconds("ws.timeout.idle").orElse(wsTimeout).getOrElse(120000L).toInt)
      .setRequestTimeoutInMs(getMilliseconds("ws.timeout.request").getOrElse(120000L).toInt)
      .setFollowRedirects(playConfig.flatMap(_.getBoolean("ws.followRedirects")).getOrElse(true))
      .setUseProxyProperties(playConfig.flatMap(_.getBoolean("ws.useProxyProperties")).getOrElse(true))

    playConfig.flatMap(_.getString("ws.useragent")).map { useragent =>
      asyncHttpConfig.setUserAgent(useragent)
    }
    if (!playConfig.flatMap(_.getBoolean("ws.acceptAnyCertificate")).getOrElse(false)) {
      asyncHttpConfig.setSSLContext(SSLContext.getDefault)
    }

    new AsyncHttpClient(asyncHttpConfig.build())


Stack trace of what i got:
 

[trace] application - fb ===> REQ: https://graph.facebook.com/me?fields=name,first_name,last_name,picture,email,birthday,gender&return_ssl_resources=true&access_token=...

java.lang.IllegalArgumentException: invalid version format: ﾨﾅ￀ￂ

at org.jboss.netty.handler.codec.http.HttpVersion.<init>(HttpVersion.java:102)

at org.jboss.netty.handler.codec.http.HttpVersion.valueOf(HttpVersion.java:62)

at org.jboss.netty.handler.codec.http.HttpResponseDecoder.createMessage(HttpResponseDecoder.java:104)

at org.jboss.netty.handler.codec.http.HttpMessageDecoder.decode(HttpMessageDecoder.java:189)

at org.jboss.netty.handler.codec.http.HttpClientCodec$Decoder.decode(HttpClientCodec.java:143)

at org.jboss.netty.handler.codec.http.HttpClientCodec$Decoder.decode(HttpClientCodec.java:127)

at org.jboss.netty.handler.codec.replay.ReplayingDecoder.callDecode(ReplayingDecoder.java:500)

at org.jboss.netty.handler.codec.replay.ReplayingDecoder.messageReceived(ReplayingDecoder.java:435)

at org.jboss.netty.handler.codec.http.HttpClientCodec.handleUpstream(HttpClientCodec.java:92)

at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:268)

at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:255)

at org.jboss.netty.channel.socket.nio.NioWorker.read(NioWorker.java:88)

at org.jboss.netty.channel.socket.nio.AbstractNioWorker.process(AbstractNioWorker.java:109)

at org.jboss.netty.channel.socket.nio.AbstractNioSelector.run(AbstractNioSelector.java:312)

at org.jboss.netty.channel.socket.nio.AbstractNioWorker.run(AbstractNioWorker.java:90)

at org.jboss.netty.channel.socket.nio.NioWorker.run(NioWorker.java:178)

at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)

at java.lang.Thread.run(Thread.java:724) 

Maga Abdurakhmanov

unread,
Mar 26, 2014, 2:37:00 PM3/26/14
to asyncht...@googlegroups.com
Play 2.2.2 and it uses async-http-client 1.7.18

Maga Abdurakhmanov

unread,
Mar 26, 2014, 3:17:54 PM3/26/14
to asyncht...@googlegroups.com
Just tried this with async-http-client 1.8.4 and looks like it solved my problem. Also request time now is much better (was ~1sec vs 100ms with new version).

For those who will find this thread regarding play 2.2.2 this is the solution to problem:

("com.ning" % "async-http-client" % "1.8.4").exclude("org.jboss.netty", "netty")

Stéphane Landelle

unread,
Mar 26, 2014, 3:19:07 PM3/26/14
to asyncht...@googlegroups.com
Glad to hear.

You probably should open an issue against Play so they upgrade the versions of AHC and Netty they ship.

Cheers,

Stéphane


--
You received this message because you are subscribed to the Google Groups "asynchttpclient" group.
To unsubscribe from this group and stop receiving emails from it, send an email to asynchttpclie...@googlegroups.com.
To post to this group, send email to asyncht...@googlegroups.com.
Visit this group at http://groups.google.com/group/asynchttpclient.
For more options, visit https://groups.google.com/d/optout.

Will Sargent

unread,
Mar 26, 2014, 3:23:53 PM3/26/14
to asyncht...@googlegroups.com
Already done.

Will Sargent
Consultant, Professional Services
Typesafe, the company behind Play Framework, Akka and Scala

Stéphane Landelle

unread,
Mar 26, 2014, 3:26:45 PM3/26/14
to asyncht...@googlegroups.com
That's what's called "reactive"! :)

Will Sargent

unread,
Mar 26, 2014, 3:31:29 PM3/26/14
to asyncht...@googlegroups.com
Hi Maga,

Do you have a reproducible unit test you can add to the bug?


Will.

Greg Pendlebury

unread,
Jun 25, 2014, 6:31:59 AM6/25/14
to asyncht...@googlegroups.com
Not sure if it matters anymore, but one of my colleagues noticed the root cause of our problem the other day. The 'No Content' responses from the Spring MVC app were actually returning content. An empty Java List passes through the Jackson serializer and turns into '[]'. The crash occurs on the next attempt to reuse that connection.


--
You received this message because you are subscribed to the Google Groups "asynchttpclient" group.
To unsubscribe from this group and stop receiving emails from it, send an email to asynchttpclie...@googlegroups.com.
To post to this group, send email to asyncht...@googlegroups.com.
Visit this group at http://groups.google.com/group/asynchttpclient.
For more options, visit https://groups.google.com/d/optout.

Reply all
Reply to author
Forward
0 new messages