[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index] [List Home]
Re: [jetty-users] Jetty client v8.0.4 - problem opening HTTPS connection through HTTP proxy server

Hi Gil,

Holidays are always just too darn short :)

Bingo, sounds like you're on the money. I missed that when I looked at
the tcpdumps you sent earlier. Looking again, I can see the
jetty-client is sending Proxy-Connection:keep-alive header, but the
Apache server is not responding with that header to signal that it is
prepared to do persistent connections, so according to the rules of
Http1.0 we have to close the connection after the response is
received. Perhaps you can find a way to configure the Apache instance
to do either 1.1 or obey the keep-alive header?

Jan

On 7 January 2012 03:11, Gilman Tolle <gilman.tolle@xxxxxxxxx> wrote:
> Hello Jan,
>
> Hope you had a good holiday.
>
> Just wanted to check in about this problem with HTTP CONNECT.
>
> After some recent experiments, I wonder if it has something to do with
> the fact that Apache is returning "HTTP/1.0" in response to the
> CONNECT, while the Jetty server CONNECT proxy returns "HTTP/1.1".
>
> Is it possible that the Jetty client requires a proxy server which
> supports HTTP/1.1, so that the client can send the proxied HTTP
> request as though it were the second request in a HTTP persistent
> connection? And, when the client receives a HTTP/1.0 response, the
> parser indicates that persistent connections aren't supported and
> requires the connection to be closed?
>
> Gil
>
> On Tue, Dec 20, 2011 at 8:47 PM, Gilman Tolle <gilman.tolle@xxxxxxxxx> wrote:
>> Hi Jan,
>>
>> Just downloaded jetty-distribution-8.1.0-20111221.035843-3.tar.gz from
>> that directory. It seemed like the newest snapshot there.
>>
>> Still seeing the problem.
>>
>> Logfile (plus SSL debug) and tcpdump attached.
>>
>> Thanks for looking into this. I'm curious - what kind of issues are you seeing?
>>
>> Gil
>>
>> On Tue, Dec 20, 2011 at 7:15 PM, Jan Bartel <janb@xxxxxxxxxxx> wrote:
>>> Hi Gil,
>>>
>>> Thanks for that info, we're getting closer to zeroing in on it.
>>>
>>> There have been a number of changes lately in trunk which may affect
>>> this. I've pushed a new snapshot distribution that you can download
>>> from here:
>>> https://oss.sonatype.org/content/groups/jetty/org/eclipse/jetty/jetty-distribution/8.1.0-SNAPSHOT/
>>>
>>> It would be great if you could try with that snapshot, again with the
>>> debug and ignore on (and also throw in some ssl debug too, see
>>> http://docs.oracle.com/javase/1.5.0/docs/guide/security/jsse/JSSERefGuide.html#Debug),
>>> and post the output here.
>>>
>>> thanks again,
>>> Jan
>>>
>>> On 20 December 2011 16:14, Gilman Tolle <gilman.tolle@xxxxxxxxx> wrote:
>>>> Hi Jan,
>>>>
>>>> I just downloaded 8.1.0.RC0 from http://download.eclipse.org/jetty/. I
>>>> didn't see a jetty-8.0.5 on that page.
>>>>
>>>> The new 8.1.0.RC0 version prints a lot more debug information to
>>>> stdout, but it looks like a similar problem is still happening.
>>>> Jetty-client keeps opening up connections to the proxy without waiting
>>>> for the response.
>>>>
>>>> I'm still running the same test code. Added
>>>> -Dorg.eclipse.jetty.util.log.IGNORED=true to the java commandline.
>>>>
>>>> Log excerpt and tcpdump file attached.
>>>>
>>>> Thanks,
>>>> Gil
>>>>
>>>> On Mon, Dec 19, 2011 at 8:51 PM, Jan Bartel <janb@xxxxxxxxxxx> wrote:
>>>>> Gilman,
>>>>>
>>>>> thanks for the tcpdump, much easier to work with.
>>>>>
>>>>> Could you please try jetty-8.1.0.RC0? We did a lot of work on the ssl
>>>>> and io layers recently, so that's the best version to try with. Also,
>>>>> FYI, if bug #298502 was marked as fixed for jetty 7.5, then that means
>>>>> that it would have been included in jetty-8.0.5 (as jetty-8 merges
>>>>> changes from 7), so your version doesn't include that change.
>>>>>
>>>>> So, please try with jetty-8.1.0.RC0 with debug enabled, and also throw
>>>>> in -Dorg.eclipse.jetty.util.log.IGNORED=true,  and again capture and
>>>>> attach the tcpdump please if its not working for you.
>>>>>
>>>>> thanks,
>>>>> Jan
>>>>>
>>>>>
>>>>>
>>>>> On 19 December 2011 16:53, Gilman Tolle <gilman.tolle@xxxxxxxxx> wrote:
>>>>>> Thanks for the followup.
>>>>>>
>>>>>> I've attached the tcpdump file.
>>>>>>
>>>>>> I've also included the debug output.
>>>>>>
>>>>>> I tried adding the handler methods you asked for, and none of them
>>>>>> were called during my test.
>>>>>>
>>>>>> Gil
>>>>>>
>>>>>> 2011-12-18 21:48:05.056:DBUG:oejuc.AbstractLifeCycle:starting
>>>>>> org.eclipse.jetty.client.HttpClient@18b753f8#STOPPED
>>>>>> 2011-12-18 21:48:05.063:DBUG:oejuc.AbstractLifeCycle:starting
>>>>>> HttpClient{8<=0<=0/16,-1}#STOPPED
>>>>>> 2011-12-18 21:48:05.073:DBUG:oejuc.AbstractLifeCycle:STARTED
>>>>>> HttpClient{8<=7<=8/16,0}#STARTED
>>>>>> 2011-12-18 21:48:05.073:DBUG:oejuc.AbstractLifeCycle:starting
>>>>>> org.eclipse.jetty.http.ssl.SslContextFactory@2b86c6b2#STOPPED
>>>>>> 2011-12-18 21:48:05.396:INFO:oejhs.SslContextFactory:Enabled Protocols
>>>>>> [SSLv2Hello, TLSv1, SSLv3] of [SSLv2Hello, SSLv3, TLSv1]
>>>>>> 2011-12-18 21:48:05.397:DBUG:oejuc.AbstractLifeCycle:STARTED
>>>>>> org.eclipse.jetty.http.ssl.SslContextFactory@2b86c6b2#STARTED
>>>>>> 2011-12-18 21:48:05.404:DBUG:oejuc.AbstractLifeCycle:starting
>>>>>> org.eclipse.jetty.client.SelectConnector@3f77b3cd#STOPPED
>>>>>> 2011-12-18 21:48:05.408:DBUG:oejuc.AbstractLifeCycle:starting
>>>>>> org.eclipse.jetty.client.SelectConnector$Manager@332611a7#STOPPED
>>>>>> 2011-12-18 21:48:05.415:DBUG:oeji.nio:Starting Thread[HttpClient-8
>>>>>> Selector0,5,main] on
>>>>>> org.eclipse.jetty.io.nio.SelectorManager$1@165973ea
>>>>>> 2011-12-18 21:48:05.416:DBUG:oejuc.AbstractLifeCycle:STARTED
>>>>>> org.eclipse.jetty.client.SelectConnector$Manager@332611a7#STARTED
>>>>>> 2011-12-18 21:48:05.416:DBUG:oejuc.AbstractLifeCycle:STARTED
>>>>>> org.eclipse.jetty.client.SelectConnector@3f77b3cd#STARTED
>>>>>> 2011-12-18 21:48:05.416:DBUG:oejuc.AbstractLifeCycle:STARTED
>>>>>> org.eclipse.jetty.client.HttpClient@18b753f8#STARTED
>>>>>> 2011-12-18 21:48:05.476:DBUG:oeji.nio:Required scheduleWrite
>>>>>> SSLSCEP@xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx[connected
>>>>>> local=/192.168.202.3:41729 remote=/192.168.201.6:9122][o=true
>>>>>> d=false,io=0,w=true,rb=false,wb=false],NEED_WRAP, in/out=0/0
>>>>>> bi/o=false/false null
>>>>>> 2011-12-18 21:48:05.485:DBUG:oejin.ssl:[Session-1,
>>>>>> SSL_NULL_WITH_NULL_NULL] close
>>>>>> 2011-12-18 21:48:05.485:DBUG:oejin.ssl:[Session-1,
>>>>>> SSL_NULL_WITH_NULL_NULL] flush
>>>>>> 2011-12-18 21:48:05.487:DBUG:oejin.ssl:[Session-1,
>>>>>> SSL_NULL_WITH_NULL_NULL] flush
>>>>>> 2011-12-18 21:48:05.487:DBUG:oejin.ssl:[Session-1,
>>>>>> SSL_NULL_WITH_NULL_NULL] flush
>>>>>> 2011-12-18 21:48:05.487:DBUG:oejin.ssl:[Session-1,
>>>>>> SSL_NULL_WITH_NULL_NULL] flush
>>>>>> 2011-12-18 21:48:05.488:DBUG:oeji.nio:destroyEndPoint
>>>>>> SSLSCEP@xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx[closed][o=false
>>>>>> d=false,io=1,w=true,rb=false,wb=false],NEED_UNWRAP, in/out=0/0
>>>>>> bi/o=false/false Status = CLOSED HandshakeStatus = NEED_UNWRAP
>>>>>> bytesConsumed = 0 bytesProduced = 7
>>>>>> 2011-12-18 21:48:05.490:DBUG:oeji.nio:Required scheduleWrite
>>>>>> SSLSCEP@xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx[connected
>>>>>> local=/192.168.202.3:41730 remote=/192.168.201.6:9122][o=true
>>>>>> d=false,io=0,w=true,rb=false,wb=false],NEED_WRAP, in/out=0/0
>>>>>> bi/o=false/false null
>>>>>> 2011-12-18 21:48:05.501:DBUG:oejin.ssl:[Session-1,
>>>>>> SSL_NULL_WITH_NULL_NULL] close
>>>>>> 2011-12-18 21:48:05.501:DBUG:oejin.ssl:[Session-1,
>>>>>> SSL_NULL_WITH_NULL_NULL] flush
>>>>>> 2011-12-18 21:48:05.501:DBUG:oejin.ssl:[Session-1,
>>>>>> SSL_NULL_WITH_NULL_NULL] flush
>>>>>> 2011-12-18 21:48:05.501:DBUG:oejin.ssl:[Session-1,
>>>>>> SSL_NULL_WITH_NULL_NULL] flush
>>>>>> 2011-12-18 21:48:05.501:DBUG:oejin.ssl:[Session-1,
>>>>>> SSL_NULL_WITH_NULL_NULL] flush
>>>>>> 2011-12-18 21:48:05.501:DBUG:oeji.nio:destroyEndPoint
>>>>>> SSLSCEP@xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx[closed][o=false
>>>>>> d=true,io=1,w=true,rb=false,wb=false],NEED_UNWRAP, in/out=0/0
>>>>>> bi/o=false/false Status = CLOSED HandshakeStatus = NEED_UNWRAP
>>>>>> bytesConsumed = 0 bytesProduced = 7
>>>>>>
>>>>>> ... repeats here ...
>>>>>>
>>>>>> On Sun, Dec 18, 2011 at 7:49 PM, Jan Bartel <janb@xxxxxxxxxxx> wrote:
>>>>>>> Hi Gilman,
>>>>>>>
>>>>>>> Could you attach the actual tcp dump file? If you cannot, then please open an
>>>>>>> issue and attach it. The issue tracker is at:
>>>>>>> https://bugs.eclipse.org/bugs/buglist.cgi?cmdtype=runnamed&namedcmd=jetty-bugs
>>>>>>>
>>>>>>> Also, have you turned on debug , and overridden the onException(),
>>>>>>> onConnectionFail(), onExpire() methods of ContentExchange?
>>>>>>>
>>>>>>> thanks
>>>>>>> Jan
>>>>>>>
>>>>>>> On 18 December 2011 11:58, Gilman Tolle <gilman.tolle@xxxxxxxxx> wrote:
>>>>>>>> Hello all,
>>>>>>>>
>>>>>>>> I'm having problems using jetty-client 8.0.4.v20111024 to open a HTTPS
>>>>>>>> connection through an Apache proxy server, using HTTP CONNECT.
>>>>>>>>
>>>>>>>> The Jetty client appears to open up new connections to the Apache
>>>>>>>> proxy then close them before any data has been returned, repeatedly.
>>>>>>>> I'm seeing many HTTP CONNECT requests being generated a few
>>>>>>>> milliseconds apart. The Apache proxy opens new connections to the real
>>>>>>>> end server and waits for responses, but these responses never make it
>>>>>>>> back to the Jetty client.
>>>>>>>>
>>>>>>>> Simple test code attached. Trimmed tcpdump output captured from the
>>>>>>>> proxy server also attached.
>>>>>>>>
>>>>>>>> I'm using Java SE 1.6.0_29 on RHEL 5.5 Linux.
>>>>>>>>
>>>>>>>> Using the commandline 'curl' client through this proxy server works correctly.
>>>>>>>>
>>>>>>>> This may be related to Bug 298502 - Https exchange through an http
>>>>>>>> proxy. This bug was fixed a few months ago, but I'm still seeing an
>>>>>>>> issue that seems similar.
>>>>>>>>
>>>>>>>> Thanks for any help you can offer.
>>>>>>>>
>>>>>>>> Gil
>>>>>>>>
>>>>>>>> Test code:
>>>>>>>>
>>>>>>>>        SslContextFactory factory = new SslContextFactory();
>>>>>>>>        ...
>>>>>>>>        HttpClient client = new HttpClient(factory);
>>>>>>>>        client.setProxy(new Address( "192.168.201.6", 9122 ));
>>>>>>>>        client.start();
>>>>>>>>
>>>>>>>>        ContentExchange exchange = new ContentExchange();
>>>>>>>>        exchange.setMethod("GET");
>>>>>>>>        exchange.setURL("https://192.168.201.4:8443/";);
>>>>>>>>        client.send(exchange);
>>>>>>>>        exchange.waitForDone();
>>>>>>>>
>>>>>>>> Tcpdump:
>>>>>>>>
>>>>>>>> 16:40:57.507852 IP 192.168.202.3.49006 > 192.168.201.6.9122: P
>>>>>>>> 1:122(121) ack 1 win 46 <nop,nop,timestamp 3391858150 440115033>
>>>>>>>> E...\.@.?............n#.?M.................
>>>>>>>> .+...;.YCONNECT 192.168.201.4:8443 HTTP/1.1
>>>>>>>> Host: 192.168.201.4:8443
>>>>>>>> Proxy-Connection: keep-alive
>>>>>>>> User-Agent: Jetty-Client
>>>>>>>>
>>>>>>>> 16:40:57.507867 IP 192.168.201.6.9122 > 192.168.202.3.49006: . ack 122
>>>>>>>> win 46 <nop,nop,timestamp 440115069 3391858150>
>>>>>>>> E..42.@.@...........#..n....?M.L.....d.....
>>>>>>>> .;.}.+..
>>>>>>>> 16:40:57.510653 IP 192.168.201.6.58887 > 192.168.201.4.8443: S
>>>>>>>> 3534877258:3534877258(0) win 5840 <mss 1460,sackOK,timestamp 440115070
>>>>>>>> 0,nop,wscale 7>
>>>>>>>> E..<m4@.@..+.......... ....J...................
>>>>>>>> .;.~........
>>>>>>>> 16:40:57.512062 IP 192.168.201.4.8443 > 192.168.201.6.58887: S
>>>>>>>> 873236234:873236234(0) ack 3534877259 win 22104 <mss
>>>>>>>> 1460,nop,nop,timestamp 2272020 440115070>
>>>>>>>> E..8.}..@........... ...4..
>>>>>>>> ...K..VX        C.........
>>>>>>>> ."...;.~
>>>>>>>> 16:40:57.512074 IP 192.168.201.6.58887 > 192.168.201.4.8443: . ack 1
>>>>>>>> win 5840 <nop,nop,timestamp 440115074 2272020>
>>>>>>>> E..4m5@.@..2.......... ....K4.......`......
>>>>>>>> .;..."..
>>>>>>>>
>>>>>>>> 16:40:57.512137 IP 192.168.201.6.9122 > 192.168.202.3.49006: P
>>>>>>>> 1:38(37) ack 122 win 46 <nop,nop,timestamp 440115074 3391858150>
>>>>>>>> E..Y2.@.@...........#..n....?M.L...........
>>>>>>>> .;...+..HTTP/1.0 200 Connection Established
>>>>>>>>
>>>>>>>> 16:40:57.512145 IP 192.168.201.6.9122 > 192.168.202.3.49006: P
>>>>>>>> 38:76(38) ack 122 win 46 <nop,nop,timestamp 440115074 3391858150>
>>>>>>>> E..Z2.@.@...........#..n....?M.L...........
>>>>>>>> .;...+..Proxy-agent: Apache/2.2.3 (CentOS)
>>>>>>>>
>>>>>>>> ... a few additional packet exchanges between the two servers here ...
>>>>>>>>
>>>>>>>> 16:40:57.518032 IP 192.168.202.3.49007 > 192.168.201.6.9122: P
>>>>>>>> 1:122(121) ack 1 win 46 <nop,nop,timestamp 3391858160 440115076>
>>>>>>>> E...%j@.?............o#.?M....u.....a......
>>>>>>>> .+...;..CONNECT 192.168.201.4:8443 HTTP/1.1
>>>>>>>> Host: 192.168.201.4:8443
>>>>>>>> Proxy-Connection: keep-alive
>>>>>>>> User-Agent: Jetty-Client
>>>>>>>>
>>>>>>>>
>>>>>>>> 16:40:57.518042 IP 192.168.201.6.9122 > 192.168.202.3.49007: . ack 122
>>>>>>>> win 46 <nop,nop,timestamp 440115080 3391858160>
>>>>>>>> E..4..@.@.<g........#..o..u.?M......LX.....
>>>>>>>> .;...+..
>>>>>>>> 16:40:57.518212 IP 192.168.201.6.58888 > 192.168.201.4.8443: S
>>>>>>>> 3534075867:3534075867(0) win 5840 <mss 1460,sackOK,timestamp 440115080
>>>>>>>> 0,nop,wscale 7>
>>>>>>>> E..<(S@.@............. ........................
>>>>>>>> .;..........
>>>>>>>> 16:40:57.519692 IP 192.168.201.4.8443 > 192.168.201.6.58888: S
>>>>>>>> 2941708955:2941708955(0) ack 3534075868 win 22104 <mss
>>>>>>>> 1460,nop,nop,timestamp 2272020 440115080>
>>>>>>>> E..8....@........... ....V........VXd..........
>>>>>>>> ."...;..
>>>>>>>> 16:40:57.519700 IP 192.168.201.6.58888 > 192.168.201.4.8443: . ack 1
>>>>>>>> win 5840 <nop,nop,timestamp 440115081 2272020>
>>>>>>>> E..4(T@.@............. ......V.............
>>>>>>>> .;..."..
>>>>>>>> 16:40:57.519717 IP 192.168.201.6.9122 > 192.168.202.3.49007: P
>>>>>>>> 1:38(37) ack 122 win 46 <nop,nop,timestamp 440115081 3391858160>
>>>>>>>> E..Y..@.@.<A........#..o..u.?M......l......
>>>>>>>> .;...+..HTTP/1.0 200 Connection Established
>>>>>>>>
>>>>>>>> 16:40:57.519728 IP 192.168.201.6.9122 > 192.168.202.3.49007: P
>>>>>>>> 38:76(38) ack 122 win 46 <nop,nop,timestamp 440115081 3391858160>
>>>>>>>> E..Z..@.@.<?........#..o..u.?M......w......
>>>>>>>> .;...+..Proxy-agent: Apache/2.2.3 (CentOS)
>>>>>>>>
>>>>>>>> 'curl' request:
>>>>>>>>
>>>>>>>> 16:56:23.123858 IP 192.168.202.3.37417 > 192.168.201.6.9122: P
>>>>>>>> 1:201(200) ack 1 win 46 <nop,nop,timestamp 3392783764 441040671>
>>>>>>>> }.K....0.............)#.yC..
>>>>>>>> .9...I..CONNECT 192.168.201.4:8443 HTTP/1.0
>>>>>>>> Host: 192.168.201.4:8443
>>>>>>>> User-Agent: curl/7.15.5 (x86_64-redhat-linux-gnu) libcurl/7.15.5
>>>>>>>> OpenSSL/0.9.8b zlib/1.2.3 libidn/0.6.5
>>>>>>>> Proxy-Connection: Keep-Alive
>>>>>>>>
>>>>>>>>
>>>>>>>> 16:56:23.123874 IP 192.168.201.6.9122 > 192.168.202.3.37417: . ack 201
>>>>>>>> win 54 <nop,nop,timestamp 441040671 3392783764>
>>>>>>>> }.KyC.....6,W.......#..)
>>>>>>>> .I...9..
>>>>>>>> 16:56:23.124141 IP 192.168.201.6.60481 > 192.168.201.4.8443: S
>>>>>>>> 226631487:226631487(0) win 5840 <mss 1460,sackOK,timestamp 441040671
>>>>>>>> 0,nop,wscale 7>
>>>>>>>> ..?........?.........A .
>>>>>>>> m.........
>>>>>>>> .I..........
>>>>>>>> 16:56:23.125682 IP 192.168.201.4.8443 > 192.168.201.6.60481: S
>>>>>>>> 1783422927:1783422927(0) ack 226631488 win 27016 <mss
>>>>>>>> 1460,nop,nop,timestamp 2280835 441040671>
>>>>>>>> ..@..i.............. ..AjL..
>>>>>>>> ."...I..
>>>>>>>> 16:56:23.125691 IP 192.168.201.6.60481 > 192.168.201.4.8443: . ack 1
>>>>>>>> win 5840 <nop,nop,timestamp 441040673 2280835>
>>>>>>>> ..@xxxxxxxx!d........A .
>>>>>>>> .I.!."..
>>>>>>>> 16:56:23.125748 IP 192.168.201.6.9122 > 192.168.202.3.37417: P
>>>>>>>> 1:38(37) ack 201 win 54 <nop,nop,timestamp 441040673 3392783764>
>>>>>>>> }.KyC.....6L}.......#..)
>>>>>>>> .I.!.9..HTTP/1.0 200 Connection Established
>>>>>>>>
>>>>>>>> 16:56:23.125757 IP 192.168.201.6.9122 > 192.168.202.3.37417: P
>>>>>>>> 38:76(38) ack 201 win 54 <nop,nop,timestamp 441040673 3392783764>
>>>>>>>> }.pyC.....6W........#..)
>>>>>>>> .I.!.9..Proxy-agent: Apache/2.2.3 (CentOS)
>>>>>>>> _______________________________________________
>>>>>>>> jetty-users mailing list
>>>>>>>> jetty-users@xxxxxxxxxxx
>>>>>>>> https://dev.eclipse.org/mailman/listinfo/jetty-users
>>>>>>> _______________________________________________
>>>>>>> jetty-users mailing list
>>>>>>> jetty-users@xxxxxxxxxxx
>>>>>>> https://dev.eclipse.org/mailman/listinfo/jetty-users
>>>>>>
>>>>>> _______________________________________________
>>>>>> jetty-users mailing list
>>>>>> jetty-users@xxxxxxxxxxx
>>>>>> https://dev.eclipse.org/mailman/listinfo/jetty-users
>>>>>>
>>>>> _______________________________________________
>>>>> jetty-users mailing list
>>>>> jetty-users@xxxxxxxxxxx
>>>>> https://dev.eclipse.org/mailman/listinfo/jetty-users
>>>>
>>>> _______________________________________________
>>>> jetty-users mailing list
>>>> jetty-users@xxxxxxxxxxx
>>>> https://dev.eclipse.org/mailman/listinfo/jetty-users
>>>>
>>> _______________________________________________
>>> jetty-users mailing list
>>> jetty-users@xxxxxxxxxxx
>>> https://dev.eclipse.org/mailman/listinfo/jetty-users
> _______________________________________________
> jetty-users mailing list
> jetty-users@xxxxxxxxxxx
> https://dev.eclipse.org/mailman/listinfo/jetty-users