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 <[email protected]> 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 <[email protected]> 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 <[email protected]> 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 >>> [email protected][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 >>> [email protected][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 >>> [email protected][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 >>> [email protected][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 <[email protected]> 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 <[email protected]> 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@[email protected].......... ....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> >>>>> [email protected].............. ..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 >>>>> [email protected] >>>>> https://dev.eclipse.org/mailman/listinfo/jetty-users >>>> _______________________________________________ >>>> jetty-users mailing list >>>> [email protected] >>>> https://dev.eclipse.org/mailman/listinfo/jetty-users >>> >>> _______________________________________________ >>> jetty-users mailing list >>> [email protected] >>> https://dev.eclipse.org/mailman/listinfo/jetty-users >>> >> _______________________________________________ >> jetty-users mailing list >> [email protected] >> https://dev.eclipse.org/mailman/listinfo/jetty-users > > _______________________________________________ > jetty-users mailing list > [email protected] > https://dev.eclipse.org/mailman/listinfo/jetty-users > _______________________________________________ jetty-users mailing list [email protected] https://dev.eclipse.org/mailman/listinfo/jetty-users
