Return-Path: Delivered-To: apmail-hc-httpclient-users-archive@www.apache.org Received: (qmail 73490 invoked from network); 25 Dec 2008 15:10:42 -0000 Received: from hermes.apache.org (HELO mail.apache.org) (140.211.11.2) by minotaur.apache.org with SMTP; 25 Dec 2008 15:10:42 -0000 Received: (qmail 26017 invoked by uid 500); 25 Dec 2008 15:10:41 -0000 Delivered-To: apmail-hc-httpclient-users-archive@hc.apache.org Received: (qmail 25988 invoked by uid 500); 25 Dec 2008 15:10:41 -0000 Mailing-List: contact httpclient-users-help@hc.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: "HttpClient User Discussion" Delivered-To: mailing list httpclient-users@hc.apache.org Received: (qmail 25977 invoked by uid 99); 25 Dec 2008 15:10:41 -0000 Received: from athena.apache.org (HELO athena.apache.org) (140.211.11.136) by apache.org (qpsmtpd/0.29) with ESMTP; Thu, 25 Dec 2008 07:10:41 -0800 X-ASF-Spam-Status: No, hits=1.2 required=10.0 tests=NORMAL_HTTP_TO_IP,SPF_NEUTRAL X-Spam-Check-By: apache.org Received-SPF: neutral (athena.apache.org: local policy) Received: from [217.150.250.44] (HELO ok2consulting.nine.ch) (217.150.250.44) by apache.org (qpsmtpd/0.29) with ESMTP; Thu, 25 Dec 2008 15:10:34 +0000 Received: by ok2consulting.nine.ch (Postfix, from userid 1002) id 0884919855B; Thu, 25 Dec 2008 16:10:09 +0100 (CET) Received: from [192.168.1.104] (84-75-130-83.dclient.hispeed.ch [84.75.130.83]) by ok2consulting.nine.ch (Postfix) with ESMTP id 19271198558 for ; Thu, 25 Dec 2008 16:09:51 +0100 (CET) Message-ID: <4953A233.6010607@apache.org> Date: Thu, 25 Dec 2008 16:09:39 +0100 From: Oleg Kalnichevski User-Agent: Thunderbird 2.0.0.18 (Windows/20081105) MIME-Version: 1.0 To: HttpClient User Discussion Subject: Re: Why client connection's port changed always when server support Keep-alive? References: <1230043917.5702.18.camel@ubuntu> <1230123420.9634.5.camel@ubuntu> In-Reply-To: Content-Type: text/plain; charset=ISO-2022-JP Content-Transfer-Encoding: 7bit X-Spam-Checker-Version: SpamAssassin 3.0.3 (2005-04-27) on ok2consulting.nine.ch X-Spam-Level: X-Virus-Checked: Checked by ClamAV on apache.org X-Old-Spam-Status: No, score=-1.9 required=5.0 tests=AWL,BAYES_00, NORMAL_HTTP_TO_IP autolearn=ham version=3.0.3 alin(王霖) wrote: > Dear Oleg: > > Thank you very much for the help. > Here is the total trace level log of two httpclient requests and responses, > split with "--------- finish first send ------------" . > > httpclient4 log: > 10:27:29,478 DEBUG DefaultHttpParams:150 - Set parameter http.useragent = > Jakarta Commons-HttpClient/3.0.1 > 10:27:29,478 DEBUG DefaultHttpParams:150 - Set parameter > http.protocol.version = HTTP/1.1 > 10:27:29,478 DEBUG DefaultHttpParams:150 - Set parameter > http.connection-manager.class = class > org.apache.commons.httpclient.SimpleHttpConnectionManager > 10:27:29,478 DEBUG DefaultHttpParams:150 - Set parameter > http.protocol.cookie-policy = rfc2109 > 10:27:29,478 DEBUG DefaultHttpParams:150 - Set parameter > http.protocol.element-charset = US-ASCII > 10:27:29,478 DEBUG DefaultHttpParams:150 - Set parameter > http.protocol.content-charset = ISO-8859-1 > 10:27:29,478 DEBUG DefaultHttpParams:150 - Set parameter > http.method.retry-handler = > org.apache.commons.httpclient.DefaultHttpMethodRetryHandler@1a73d3c > 10:27:29,494 DEBUG DefaultHttpParams:150 - Set parameter > http.dateparser.patterns = [EEE, dd MMM yyyy HH:mm:ss zzz, EEEE, dd-MMM-yy > HH:mm:ss zzz, EEE MMM d HH:mm:ss yyyy, EEE, dd-MMM-yyyy HH:mm:ss z, EEE, > dd-MMM-yyyy HH-mm-ss z, EEE, dd MMM yy HH:mm:ss z, EEE dd-MMM-yyyy HH:mm:ss > z, EEE dd MMM yyyy HH:mm:ss z, EEE dd-MMM-yyyy HH-mm-ss z, EEE dd-MMM-yy > HH:mm:ss z, EEE dd MMM yy HH:mm:ss z, EEE,dd-MMM-yy HH:mm:ss z, > EEE,dd-MMM-yyyy HH:mm:ss z, EEE, dd-MM-yyyy HH:mm:ss z] > 10:27:29,494 DEBUG DefaultHttpParams:150 - Set parameter > http.connection-manager.max-total = 1000 > 10:27:29,494 DEBUG DefaultHttpParams:150 - Set parameter > http.connection-manager.max-per-host = {HostConfiguration[]=2} > 10:27:29,494 DEBUG DefaultHttpParams:150 - Set parameter > http.connection.timeout = 5000 > 10:27:29,510 DEBUG DefaultHttpParams:150 - Set parameter http.socket.timeout > = 5000 > 10:27:29,510 DEBUG DefaultHttpParams:150 - Set parameter > http.connection.stalecheck = true > 10:27:29,510 DEBUG HttpClient:71 - Java version: 1.5.0 > 10:27:29,510 DEBUG HttpClient:72 - Java vendor: Sun Microsystems Inc. > 10:27:29,510 DEBUG HttpClient:73 - Java class path: > D:\workspace\top-java-client\trunk\target\test-classes;D:\workspace\top-java-client\trunk\target\classes;D:\setup\program\m2\commons-codec\commons-codec\1.2\commons-codec-1.2.jar;D:\setup\program\m2\commons-httpclient\commons-httpclient\3.0.1\commons-httpclient-3.0.1.jar;D:\setup\program\m2\commons-lang\commons-lang\2.3\commons-lang-2.3.jar;D:\setup\program\m2\commons-logging\commons-logging\1.1.1\commons-logging-1.1.1.jar;D:\setup\program\m2\org\apache\httpcomponents\httpclient\4.0-beta2\httpclient-4.0-beta2.jar;D:\setup\program\m2\org\apache\httpcomponents\httpcore\4.0-beta3\httpcore-4.0-beta3.jar;D:\setup\program\m2\junit\junit\4.4\junit-4.4.jar;D:\setup\program\m2\log4j\log4j\1.2.12\log4j-1.2.12.jar > 10:27:29,510 DEBUG HttpClient:74 - Operating system name: Windows XP > 10:27:29,510 DEBUG HttpClient:75 - Operating system architecture: x86 > 10:27:29,510 DEBUG HttpClient:76 - Operating system version: 5.1 > 10:27:29,572 DEBUG HttpClient:81 - SUN 1.5: SUN (DSA key/parameter > generation; DSA signing; SHA-1, MD5 digests; SecureRandom; X.509 > certificates; JKS keystore; PKIX CertPathValidator; PKIX CertPathBuilder; > LDAP, Collection CertStores) > 10:27:29,572 DEBUG HttpClient:81 - SunRsaSign 1.5: Sun RSA signature > provider > 10:27:29,572 DEBUG HttpClient:81 - SunJSSE 1.5: Sun JSSE provider(PKCS12, > SunX509 key/trust factories, SSLv3, TLSv1) > 10:27:29,588 DEBUG HttpClient:81 - SunJCE 1.5: SunJCE Provider (implements > RSA, DES, Triple DES, AES, Blowfish, ARCFOUR, RC2, PBE, Diffie-Hellman, > HMAC) > 10:27:29,588 DEBUG HttpClient:81 - SunJGSS 1.0: Sun (Kerberos v5) > 10:27:29,588 DEBUG HttpClient:81 - SunSASL 1.5: Sun SASL provider(implements > client mechanisms for: DIGEST-MD5, GSSAPI, EXTERNAL, PLAIN, CRAM-MD5; server > mechanisms for: DIGEST-MD5, GSSAPI, CRAM-MD5) > 10:27:29,588 DEBUG DefaultHttpParams:150 - Set parameter > http.connection.timeout = 1000 > 10:27:29,588 DEBUG DefaultHttpParams:150 - Set parameter http.socket.timeout > = 1000 > 10:27:29,744 DEBUG ClientParamsStack:219 - 'http.conn-manager.timeout': 5000 > 10:27:29,744 DEBUG ThreadSafeClientConnManager:171 - > ThreadSafeClientConnManager.getConnection: HttpRoute[{}-> > http://192.168.208.110], timeout = 5000 > 10:27:29,744 DEBUG ConnPoolByRoute:289 - Total connections kept alive: 0 > 10:27:29,744 DEBUG ConnPoolByRoute:290 - Total issued connections: 0 > 10:27:29,744 DEBUG ConnPoolByRoute:291 - Total allocated connection: 0 out > of 1000 > 10:27:29,744 DEBUG ConnPoolByRoute:462 - No free connections [HttpRoute[{}-> > http://192.168.208.110]][null] > 10:27:29,744 DEBUG ConnPoolByRoute:308 - Available capacity: 2 out of 2 > [HttpRoute[{}->http://192.168.208.110]][null] > 10:27:29,744 DEBUG ConnPoolByRoute:489 - Creating new connection > [HttpRoute[{}->http://192.168.208.110]] > 10:27:29,822 DEBUG ClientParamsStack:219 - 'http.protocol.version': HTTP/1.1 > 10:27:29,822 DEBUG RequestAddCookies:125 - CookieSpec selected: best-match > 10:27:29,838 DEBUG DefaultRequestDirector:408 - Attempt 1 to execute request > 10:27:29,838 DEBUG wire:78 - >> "POST /router/rest HTTP/1.1[EOL]" > 10:27:29,853 DEBUG wire:78 - >> "Content-Length: 188[EOL]" > 10:27:29,853 DEBUG wire:78 - >> "Content-Type: > application/x-www-form-urlencoded[EOL]" > 10:27:29,853 DEBUG wire:78 - >> "Host: 192.168.208.110[EOL]" > 10:27:29,853 DEBUG wire:78 - >> "Connection: Keep-Alive[EOL]" > 10:27:29,853 DEBUG wire:78 - >> "[EOL]" > 10:27:29,853 DEBUG headers:251 - >> POST /router/rest HTTP/1.1 > 10:27:29,853 DEBUG headers:254 - >> Content-Length: 188 > 10:27:29,853 DEBUG headers:254 - >> Content-Type: > application/x-www-form-urlencoded > 10:27:29,853 DEBUG headers:254 - >> Host: 192.168.208.110 > 10:27:29,853 DEBUG headers:254 - >> Connection: Keep-Alive > 10:27:29,853 DEBUG wire:78 - >> > "fields=name%2Cbuyer_credit%2Cphone%2Creal_name×tamp=2008-12-25+10%3A27%3A29&api_key=suibian&nick=tbtest5&method=taobao.user.get&sign=82D375615F2EC704D9DAD60992359B3A&format=json&v=1.0" > 10:27:29,869 DEBUG wire:78 - << "HTTP/1.1 200 OK[EOL]" > 10:27:29,869 DEBUG wire:78 - << "Date: Thu, 25 Dec 2008 02:26:40 GMT[EOL]" > 10:27:29,869 DEBUG wire:78 - << "Server: Apache-Coyote/1.1[EOL]" > 10:27:29,869 DEBUG wire:78 - << "X-Powered-By: Servlet 2.4; > JBoss-4.2.2.GA(build: SVNTag=JBoss_4_2_2_GA > date=200710221139)/Tomcat-5.5[EOL]" > 10:27:29,869 DEBUG wire:78 - << "Content-Type: > text/javascript;charset=UTF-8[EOL]" > 10:27:29,869 DEBUG wire:78 - << "Content-Length: 85[EOL]" > 10:27:29,885 DEBUG wire:78 - << "Vary: Accept-Encoding[EOL]" > 10:27:29,885 DEBUG wire:78 - << "Keep-Alive: timeout=15, max=100[EOL]" > 10:27:29,885 DEBUG wire:78 - << "Connection: Keep-Alive[EOL]" > 10:27:29,885 DEBUG headers:237 - << HTTP/1.1 200 OK > 10:27:29,885 DEBUG headers:240 - << Date: Thu, 25 Dec 2008 02:26:40 GMT > 10:27:29,885 DEBUG headers:240 - << Server: Apache-Coyote/1.1 > 10:27:29,885 DEBUG headers:240 - << X-Powered-By: Servlet 2.4; > JBoss-4.2.2.GA (build: SVNTag=JBoss_4_2_2_GA date=200710221139)/Tomcat-5.5 > 10:27:29,885 DEBUG headers:240 - << Content-Type: > text/javascript;charset=UTF-8 > 10:27:29,885 DEBUG headers:240 - << Content-Length: 85 > 10:27:29,885 DEBUG headers:240 - << Vary: Accept-Encoding > 10:27:29,885 DEBUG headers:240 - << Keep-Alive: timeout=15, max=100 > 10:27:29,885 DEBUG headers:240 - << Connection: Keep-Alive > 10:27:29,900 DEBUG DefaultRequestDirector:463 - Connection can be kept alive > for 15000 ms > 10:27:29,900 DEBUG wire:78 - << > "{"rsp":{"users":[{"buyer_credit":{"good_num":1,"level":0,"score":1,"total_num":1}}]}}" > 10:27:29,900 DEBUG ThreadSafeClientConnManager:221 - Released connection is > reusable. > 10:27:29,900 DEBUG ConnPoolByRoute:374 - Releasing connection > [HttpRoute[{}->http://192.168.208.110]][null] > 10:27:29,900 DEBUG ConnPoolByRoute:394 - Pooling connection [HttpRoute[{}-> > http://192.168.208.110]][null]; keep alive for 15000 MILLISECONDS > 10:27:29,900 DEBUG IdleConnectionHandler:78 - Adding connection at: > 1230172049900 > 10:27:29,900 DEBUG ConnPoolByRoute:631 - Notifying no-one, there are no > waiting threads > --------- finish first send ------------ > 10:27:29,916 DEBUG ClientParamsStack:219 - 'http.conn-manager.timeout': 5000 > 10:27:29,916 DEBUG ThreadSafeClientConnManager:171 - > ThreadSafeClientConnManager.getConnection: HttpRoute[{}-> > http://192.168.208.110], timeout = 5000 > 10:27:29,916 DEBUG ConnPoolByRoute:289 - Total connections kept alive: 1 > 10:27:29,916 DEBUG ConnPoolByRoute:290 - Total issued connections: 0 > 10:27:29,916 DEBUG ConnPoolByRoute:291 - Total allocated connection: 1 out > of 1000 > 10:27:29,916 DEBUG ConnPoolByRoute:436 - Getting free connection > [HttpRoute[{}->http://192.168.208.110]][null] > 10:27:29,916 DEBUG DefaultRequestDirector:334 - Stale connection check > 10:27:29,932 DEBUG ClientParamsStack:219 - 'http.protocol.version': HTTP/1.1 > 10:27:29,932 DEBUG RequestAddCookies:125 - CookieSpec selected: best-match > 10:27:29,932 DEBUG DefaultRequestDirector:408 - Attempt 1 to execute request > 10:27:29,932 DEBUG wire:78 - >> "POST /router/rest HTTP/1.1[EOL]" > 10:27:29,932 DEBUG wire:78 - >> "Content-Length: 188[EOL]" > 10:27:29,932 DEBUG wire:78 - >> "Content-Type: > application/x-www-form-urlencoded[EOL]" > 10:27:29,932 DEBUG wire:78 - >> "Host: 192.168.208.110[EOL]" > 10:27:29,932 DEBUG wire:78 - >> "Connection: Keep-Alive[EOL]" > 10:27:29,932 DEBUG wire:78 - >> "[EOL]" > 10:27:29,932 DEBUG headers:251 - >> POST /router/rest HTTP/1.1 > 10:27:29,932 DEBUG headers:254 - >> Content-Length: 188 > 10:27:29,932 DEBUG headers:254 - >> Content-Type: > application/x-www-form-urlencoded > 10:27:29,932 DEBUG headers:254 - >> Host: 192.168.208.110 > 10:27:29,932 DEBUG headers:254 - >> Connection: Keep-Alive > 10:27:29,932 DEBUG wire:78 - >> > "fields=name%2Cbuyer_credit%2Cphone%2Creal_name×tamp=2008-12-25+10%3A27%3A29&api_key=suibian&nick=tbtest5&method=taobao.user.get&sign=82D375615F2EC704D9DAD60992359B3A&format=json&v=1.0" > 10:27:29,963 DEBUG wire:78 - << "HTTP/1.1 200 OK[EOL]" > 10:27:29,963 DEBUG wire:78 - << "Date: Thu, 25 Dec 2008 02:26:40 GMT[EOL]" > 10:27:29,963 DEBUG wire:78 - << "Server: Apache-Coyote/1.1[EOL]" > 10:27:29,963 DEBUG wire:78 - << "X-Powered-By: Servlet 2.4; > JBoss-4.2.2.GA(build: SVNTag=JBoss_4_2_2_GA > date=200710221139)/Tomcat-5.5[EOL]" > 10:27:29,963 DEBUG wire:78 - << "Content-Type: > text/javascript;charset=UTF-8[EOL]" > 10:27:29,963 DEBUG wire:78 - << "Content-Length: 85[EOL]" > 10:27:29,963 DEBUG wire:78 - << "Vary: Accept-Encoding[EOL]" > 10:27:29,963 DEBUG wire:78 - << "Keep-Alive: timeout=15, max=99[EOL]" > 10:27:29,963 DEBUG wire:78 - << "Connection: Keep-Alive[EOL]" > 10:27:29,963 DEBUG headers:237 - << HTTP/1.1 200 OK > 10:27:29,963 DEBUG headers:240 - << Date: Thu, 25 Dec 2008 02:26:40 GMT > 10:27:29,963 DEBUG headers:240 - << Server: Apache-Coyote/1.1 > 10:27:29,963 DEBUG headers:240 - << X-Powered-By: Servlet 2.4; > JBoss-4.2.2.GA (build: SVNTag=JBoss_4_2_2_GA date=200710221139)/Tomcat-5.5 > 10:27:29,963 DEBUG headers:240 - << Content-Type: > text/javascript;charset=UTF-8 > 10:27:29,963 DEBUG headers:240 - << Content-Length: 85 > 10:27:29,963 DEBUG headers:240 - << Vary: Accept-Encoding > 10:27:29,963 DEBUG headers:240 - << Keep-Alive: timeout=15, max=99 > 10:27:29,963 DEBUG headers:240 - << Connection: Keep-Alive > 10:27:29,963 DEBUG DefaultRequestDirector:463 - Connection can be kept alive > for 15000 ms > 10:27:29,963 DEBUG wire:78 - << > "{"rsp":{"users":[{"buyer_credit":{"good_num":1,"level":0,"score":1,"total_num":1}}]}}" > 10:27:29,963 DEBUG ThreadSafeClientConnManager:221 - Released connection is > reusable. > 10:27:29,963 DEBUG ConnPoolByRoute:374 - Releasing connection > [HttpRoute[{}->http://192.168.208.110]][null] > 10:27:29,963 DEBUG ConnPoolByRoute:394 - Pooling connection [HttpRoute[{}-> > http://192.168.208.110]][null]; keep alive for 15000 MILLISECONDS > 10:27:29,963 DEBUG IdleConnectionHandler:78 - Adding connection at: > 1230172049963 > 10:27:29,963 DEBUG ConnPoolByRoute:631 - Notifying no-one, there are no > waiting threads > > total duration:328 > httpclient4.x0-->firstDuration:281 > httpclient4.x0-->successDuration:47,successTimes:1 > > As far as I can tell from the log, persistent connections get correctly re-used Oleg --------------------------------------------------------------------- To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org For additional commands, e-mail: httpclient-users-help@hc.apache.org