Re: Why client connection's port changed always when server support Keep-alive?

Oleg Kalnichevski Thu, 25 Dec 2008 07:10:41 -0800

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.defaulthttpmethodretryhand...@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&timestamp=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&timestamp=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-unsubscr...@hc.apache.org
For additional commands, e-mail: httpclient-users-h...@hc.apache.org

Re: Why client connection's port changed always when server support Keep-alive?

Reply via email to