Can't receive response except the first request while sending https request multiple times via the same proxy server

[cngddflzw]

Hi

I've sent some https requests to https://www.google.com.hk via an apache proxy server. But It coundn't receive any response after receiving the first https request.

My code:

    public static void main(String[] args) throws InterruptedException, IOException, ExecutionException, URISyntaxException {
        AsyncHttpClientConfig.Builder builder = new AsyncHttpClientConfig.Builder();
        builder.setAllowPoolingConnection(true);
        builder.setMaximumConnectionsTotal(100);
        builder.setMaximumConnectionsPerHost(50);
        builder.setConnectionTimeoutInMs(60000);
        builder.setRequestTimeoutInMs(99999999);
        AsyncHttpClient client = new AsyncHttpClient(builder.build());
        String url = "https://www.google.com.hk";
        ProxyServer proxy = new ProxyServer("localhost", 8088);
        for (int i = 0; i < 10; i++) {
            ListenableFuture<Response> f = client.prepareGet(url).setProxyServer(proxy).execute();
//            ListenableFuture<Response> f = client.prepareGet(url).execute(handler); // this work fine
            f.get();
            System.err.println("Request finished: " + i);
        }
        client.close();
    }

Log:

//16:28:16.173 [main] DEBUG c.n.h.c.p.n.NettyAsyncHttpProvider - Number of application's worker threads is 8
//16:28:18.819 [main] DEBUG c.n.h.c.p.n.NettyAsyncHttpProvider - 
Non cached request 
DefaultHttpRequest(chunked: false)
CONNECT www.google.com.hk:443 HTTP/1.0
Host: www.google.com.hk
Connection: keep-alive
Proxy-Connection: keep-alive
Accept: */*
User-Agent: NING/1.0

using Channel 
[id: 0x9e685a7d, /127.0.0.1:49337 => localhost/127.0.0.1:8088]

//16:28:18.877 [New I/O worker #1] DEBUG c.n.h.c.p.n.NettyAsyncHttpProvider - 

Request DefaultHttpRequest(chunked: false)
CONNECT www.google.com.hk:443 HTTP/1.0
Host: www.google.com.hk
Connection: keep-alive
Proxy-Connection: keep-alive
Accept: */*
User-Agent: NING/1.0

Response DefaultHttpResponse(chunked: false)
HTTP/1.0 200 Connection Established
Proxy-agent: Apache/2.2.25 (Win32) PHP/5.4.21

//16:28:18.878 [New I/O worker #1] DEBUG c.n.h.c.p.n.NettyAsyncHttpProvider - Connected to localhost:8088
//16:28:18.878 [New I/O worker #1] DEBUG c.n.h.c.p.n.NettyAsyncHttpProvider - Connecting to proxy http://localhost:8088 for scheme https://www.google.com.hk
//16:28:19.089 [New I/O worker #1] DEBUG c.n.h.c.p.n.NettyAsyncHttpProvider - 
Using cached Channel [id: 0x9e685a7d, /127.0.0.1:49337 => localhost/127.0.0.1:8088]
 for request 
DefaultHttpRequest(chunked: false)
GET https://www.google.com.hk/ HTTP/1.1
Host: www.google.com.hk
Connection: keep-alive
Proxy-Connection: keep-alive
Accept: */*
User-Agent: NING/1.0

//16:28:19.298 [New I/O worker #1] DEBUG c.n.h.c.p.n.NettyAsyncHttpProvider - 

Request DefaultHttpRequest(chunked: false)
GET https://www.google.com.hk/ HTTP/1.1
Host: www.google.com.hk
Connection: keep-alive
Proxy-Connection: keep-alive
Accept: */*
User-Agent: NING/1.0

Response DefaultHttpResponse(chunked: true)
HTTP/1.1 200 OK
Date: Sun, 08 Dec 2013 08:28:19 GMT
Expires: -1
Cache-Control: private, max-age=0
Content-Type: text/html; charset=Big5
Set-Cookie: PREF=ID=2d1dcf1f850cd87a:FF=0:NW=1:TM=1386491299:LM=1386491299:S=NxWKWfhikQY7aRIO; expires=Tue, 08-Dec-2015 08:28:19 GMT; path=/; domain=.google.com.hk
Set-Cookie: NID=67=ceKGSI6qnfzCNXqPUIhVP6Iql1XQ7JwGs2S6AF7GReM4TAR9gKS5PBvQ7G2OKKTW_wmkcKLqoA48OuihbBJuixBpgruauE0WIKj5XukU42oi7uiTq0kjM5nH4_odMm0z; expires=Mon, 09-Jun-2014 08:28:19 GMT; path=/; domain=.google.com.hk; HttpOnly
P3P: CP="This is not a P3P policy! See http://www.google.com/support/accounts/bin/answer.py?hl=en&answer=151657 for more info."
Server: gws
X-XSS-Protection: 1; mode=block
X-Frame-Options: SAMEORIGIN
Alternate-Protocol: 443:quic
Transfer-Encoding: chunked

//16:28:19.305 [New I/O worker #1] DEBUG c.n.h.c.p.netty.NettyConnectionsPool - Adding uri: http://localhost:8088 for channel [id: 0x9e685a7d, /127.0.0.1:49337 => localhost/127.0.0.1:8088]
//16:28:19.308 [main] DEBUG c.n.h.c.p.n.NettyAsyncHttpProvider - Using cached Channel [id: 0x9e685a7d, /127.0.0.1:49337 => localhost/127.0.0.1:8088]
 for uri http://localhost:8088/

//16:28:19.308 [main] DEBUG c.n.h.c.p.n.NettyAsyncHttpProvider - 
Using cached Channel [id: 0x9e685a7d, /127.0.0.1:49337 => localhost/127.0.0.1:8088]
 for request 
DefaultHttpRequest(chunked: false)
GET https://www.google.com.hk/ HTTP/1.1
Host: www.google.com.hk
Connection: keep-alive
Proxy-Connection: keep-alive
Accept: */*
User-Agent: NING/1.0

Request finished: 0

I think the problem is that it sent CONNECT request to the proxy server just for once. It sent the GET request to the proxy server directly after finishing the first request.

Related code in NettyAsyncHttpProvider line 923 to 932

        if (channel != null && channel.isOpen() && channel.isConnected()) {
            HttpRequest nettyRequest = null;

            if (f == null) {
                nettyRequest = buildRequest(config, request, uri, false, bufferedBytes, proxyServer);
                f = newFuture(uri, request, asyncHandler, nettyRequest, config, this, proxyServer);
            } else {
                nettyRequest = buildRequest(config, request, uri, f.isConnectAllowed(), bufferedBytes, proxyServer);
                f.setNettyRequest(nettyRequest);
            }

channel is not null since it uses the cached channel, and the future f is null, so it invoked buildRequest(config, request, uri, false, bufferedBytes, proxyServer); so

protected static final HttpRequest buildRequest(AsyncHttpClientConfig config,
                                                Request request,
                                                URI uri,
                                                boolean allowConnect,
                                                ChannelBuffer buffer,
                                                ProxyServer proxyServer)
                                        throws IOException

allowConnect is always false
I don't if this is the problem or I use it in a wrong way?

---

I've changed the proxy server form apache to squid and found that It will received an exception if reuse the channel connected to the proxy server. In such case, it still won't send CONNECT request first, but sent the GET request directly:

//20:31:30.477 [main] DEBUG c.n.h.c.p.n.NettyAsyncHttpProvider - 
Using cached Channel [id: 0xd51c5912, /127.0.0.1:59555 => localhost/127.0.0.1:8087]
 for request 
DefaultHttpRequest(chunked: false)
GET https://www.google.com.hk/ HTTP/1.1
Host: www.google.com.hk
Connection: keep-alive
Proxy-Connection: keep-alive
Accept: */*
User-Agent: NING/1.0

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:435) ~[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$Worker.runTask(ThreadPoolExecutor.java:895) [na:1.6.0_45]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918) [na:1.6.0_45]
    at java.lang.Thread.run(Thread.java:662) [na:1.6.0_45]

Sometimes the channel can't be reused, ahc works fine in this case:

//20:31:30.077 [New I/O worker #7] DEBUG c.n.h.c.p.netty.NettyConnectionsPool - Adding uri: http://localhost:8087 for channel [id: 0x26b731ee, /127.0.0.1:59550 => localhost/127.0.0.1:8087]
//20:31:30.077 [main] DEBUG c.n.h.c.p.n.NettyAsyncHttpProvider - Using cached Channel [id: 0x26b731ee, /127.0.0.1:59550 => localhost/127.0.0.1:8087]
 for uri http://localhost:8087/

//20:31:30.077 [main] DEBUG c.n.h.c.p.n.NettyAsyncHttpProvider - 
Using cached Channel [id: 0x26b731ee, /127.0.0.1:59550 => localhost/127.0.0.1:8087]
 for request 
DefaultHttpRequest(chunked: false)
GET https://www.google.com.hk/ HTTP/1.1
Host: www.google.com.hk
Connection: keep-alive
Proxy-Connection: keep-alive
Accept: */*
User-Agent: NING/1.0

//20:31:30.145 [New I/O worker #7] DEBUG c.n.h.c.p.n.NettyAsyncHttpProvider - Channel Closed: [id: 0x26b731ee, /127.0.0.1:59550 :> localhost/127.0.0.1:8087] with attachment NettyResponseFuture{currentRetry=0,
    isDone=false,
    isCancelled=false,
    asyncHandler=com.ning.http.client.AsyncCompletionHandlerBase@1b19753,
    requestTimeoutInMs=120000,
    nettyRequest=DefaultHttpRequest(chunked: false)
GET https://www.google.com.hk/ HTTP/1.1
Host: www.google.com.hk
Connection: keep-alive
Proxy-Connection: keep-alive
Accept: */*
User-Agent: NING/1.0,
    content=null,
    uri=https://www.google.com.hk/,
    keepAlive=true,
    httpResponse=null,
    exEx=null,
    redirectCount=0,
    reaperFuture=com.ning.http.client.providers.netty.NettyAsyncHttpProvider$ReaperFuture@45ce17,
    inAuth=false,
    statusReceived=false,
    touch=33316068}
//20:31:30.145 [New I/O worker #7] DEBUG c.n.h.c.p.n.NettyAsyncHttpProvider - Trying to recover request DefaultHttpRequest(chunked: false)
GET https://www.google.com.hk/ HTTP/1.1
Host: www.google.com.hk
Connection: keep-alive
Proxy-Connection: keep-alive
Accept: */*
User-Agent: NING/1.0

//20:31:30.145 [New I/O worker #7] DEBUG c.n.h.c.p.n.NettyAsyncHttpProvider - 
Non cached request 
DefaultHttpRequest(chunked: false)
CONNECT www.google.com.hk:443 HTTP/1.0
Host: www.google.com.hk
Connection: keep-alive
Proxy-Connection: keep-alive
Accept: */*
User-Agent: NING/1.0

using Channel 
[id: 0xd51c5912]

//20:31:30.147 [New I/O worker #8] DEBUG c.n.h.c.p.n.NettyAsyncHttpProvider - 

Request DefaultHttpRequest(chunked: false)
CONNECT www.google.com.hk:443 HTTP/1.0
Host: www.google.com.hk
Connection: keep-alive
Proxy-Connection: keep-alive
Accept: */*
User-Agent: NING/1.0

Response DefaultHttpResponse(chunked: false)
HTTP/1.1 200 OK

//20:31:30.147 [New I/O worker #8] DEBUG c.n.h.c.p.n.NettyAsyncHttpProvider - Connected to localhost:8087
//20:31:30.147 [New I/O worker #8] DEBUG c.n.h.c.p.n.NettyAsyncHttpProvider - Connecting to proxy http://localhost:8087 for scheme https://www.google.com.hk
//20:31:30.147 [New I/O worker #8] DEBUG c.n.h.c.p.n.NettyAsyncHttpProvider - 
Using cached Channel [id: 0xd51c5912, /127.0.0.1:59555 => localhost/127.0.0.1:8087]
 for request 
DefaultHttpRequest(chunked: false)
GET https://www.google.com.hk/ HTTP/1.1
Host: www.google.com.hk
Connection: keep-alive
Proxy-Connection: keep-alive
Accept: */*
User-Agent: NING/1.0

//20:31:30.456 [New I/O worker #8] DEBUG c.n.h.c.p.n.NettyAsyncHttpProvider - 

Request DefaultHttpRequest(chunked: false)
GET https://www.google.com.hk/ HTTP/1.1
Host: www.google.com.hk
Connection: keep-alive
Proxy-Connection: keep-alive
Accept: */*
User-Agent: NING/1.0

Response DefaultHttpResponse(chunked: true)
HTTP/1.1 200 OK
Date: Sun, 08 Dec 2013 12:31:30 GMT
Expires: -1
Cache-Control: private, max-age=0
Content-Type: text/html; charset=Big5
Set-Cookie: PREF=ID=d9f00012c282a1eb:FF=0:NW=1:TM=1386505890:LM=1386505890:S=gzoKtlvElpKpP9FG; expires=Tue, 08-Dec-2015 12:31:30 GMT; path=/; domain=.google.com.hk
Set-Cookie: NID=67=Aj4lCbPhh3KGM93pO_ABt5dsVVmQB14UhCUxkAu0-wH7ITuPd9i_vuLB_5-3YnRxYSHdP4sf-0Pt1etYdDx6pRF0mq4-Ac-xQX8oUUy5uos-qTDcTg44wNwoN4oUPOlm; expires=Mon, 09-Jun-2014 12:31:30 GMT; path=/; domain=.google.com.hk; HttpOnly
P3P: CP="This is not a P3P policy! See http://www.google.com/support/accounts/bin/answer.py?hl=en&answer=151657 for more info."
Server: gws
X-XSS-Protection: 1; mode=block
X-Frame-Options: SAMEORIGIN
Alternate-Protocol: 443:quic
Transfer-Encoding: chunked

In short, it works fine when the log shows Trying to recover request DefaultHttpRequest(chunked: false).

What shoud do to make every https request successful?

---

I set the "Connection" and "Proxy-Connection" to "close", and now It works fine.
But it will not reuse a channel now.
Is there a way to implement https request and reuse the channel?

[slandelle]

@cngddflzw CONNECT is supposed to be sent only once per connection, not for every request. Anyway, there's indeed a bug with the Netty provider. The Grizzly one seems to be working fine, could you switch?

@jfarcand Could you help on this, please?

[slandelle]

@jfarcand It seems like the connection gets closed for no reason, and then AHC can't properly reconnect. I can't reproduce with raw Netty. Please help.

[jfarcand]

@slandelle Not today, maybe tomorrow PM. Do you see from where the connection is getting closed?

[slandelle]

@jfarcand No :(

[cngddflzw]

Hi. @slandelle I've switched to Grizzly, but I found that the PerRequestConfig timeout does not work after my switch.
Is the bug you mentioned above solved?

[cngddflzw]

Sorry , it's my fault, PerRequestConfig works fine

[slandelle]

Investigating right now. Getting kind of ssl exceptions?!
For the record, I can't reproduce with master/AHC2.

[slandelle]

@cngddflzw Ha ha ha! Finally understood what happens!

You execute an HTTPS request, yet you set up a proxy for HTTP!

I agree, it's tricky, the API could be better designed, and there's a complex mechanism at work that I don't fully understand yet...

So:

// default constructor, using default protocol, ie HTTP
// ProxyServer proxy = new ProxyServer("localhost", 8088);

// proper proxy for HTTPS
ProxyServer proxy = new ProxyServer(Protocol.HTTPS, "localhost", 8088)

[slandelle]

@jfarcand Couldn't we deduce the proxy protocol from the request one? Or, as I think i understand from your comment on verifyChannelPipeline, one can set up an HTTPS proxy on a HTTP request that would force upgrading?

[cngddflzw]

hi. @slandelle , but where is the filed "protocol" used? I just can't find a word about proxyServer.getProtocol() in NettyAsyncHttpProvider.

[slandelle]

That's proxyServer.getURI that's being used.

[cngddflzw]

@slandelle ... great... solved a problem confused me for a long long time ... : )

[slandelle]

Great! Let's close this, and see if we can improve this in a dedicated issue.