Skip to main content

[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

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@xxxxxxxxxxxxxxxxxx.channels.SocketChannel[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@xxxxxxxxxxxxxxxxxx.channels.SocketChannel[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@xxxxxxxxxxxxxxxxx.channels.SocketChannel[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@xxxxxxxxxxxxxxxxx.channels.SocketChannel[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>
>>>>>>> ..@jL......!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


Back to the top