Re: [jetty-users] Jetty client v8.0.4 - problem opening HTTPS connection

[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

From: Jan Bartel <janb@xxxxxxxxxxx>
Date: Wed, 21 Dec 2011 14:15:21 +1100
Delivered-to: jetty-users@xxxxxxxxxxx
List-archive: <https://dev.eclipse.org/mailman/private/jetty-users>
List-help: <mailto:jetty-users-request@eclipse.org?subject=help>
List-subscribe: <https://dev.eclipse.org/mailman/listinfo/jetty-users>, <mailto:jetty-users-request@eclipse.org?subject=subscribe>
List-unsubscribe: <https://dev.eclipse.org/mailman/options/jetty-users>, <mailto:jetty-users-request@eclipse.org?subject=unsubscribe>

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
>

Follow-Ups:
- Re: [jetty-users] Jetty client v8.0.4 - problem opening HTTPS connection through HTTP proxy server
  - From: Gilman Tolle

References:
- [jetty-users] Jetty client v8.0.4 - problem opening HTTPS connection through HTTP proxy server
  - From: Gilman Tolle
- Re: [jetty-users] Jetty client v8.0.4 - problem opening HTTPS connection through HTTP proxy server
  - From: Jan Bartel
- Re: [jetty-users] Jetty client v8.0.4 - problem opening HTTPS connection through HTTP proxy server
  - From: Gilman Tolle
- Re: [jetty-users] Jetty client v8.0.4 - problem opening HTTPS connection through HTTP proxy server
  - From: Jan Bartel
- Re: [jetty-users] Jetty client v8.0.4 - problem opening HTTPS connection through HTTP proxy server
  - From: Gilman Tolle

Prev by Date: Re: [jetty-users] Jetty HTTP client and gzip
Next by Date: Re: [jetty-users] Jetty client v8.0.4 - problem opening HTTPS connection through HTTP proxy server
Previous by thread: Re: [jetty-users] Jetty client v8.0.4 - problem opening HTTPS connection through HTTP proxy server
Next by thread: Re: [jetty-users] Jetty client v8.0.4 - problem opening HTTPS connection through HTTP proxy server
Index(es):
- Date
- Thread

Breadcrumbs