You are viewing a plain text version of this content. The canonical link for it is here.
Posted to httpclient-users@hc.apache.org by Patrick Lightbody <pl...@gmail.com> on 2006/08/07 21:29:17 UTC
Lockup in XFire
I've tried using XFire 1.1.1 and 1.2-RC, combined with HttpClient 3.0
and 3.1-alpha1. I get the same result, outlined below, which causes a
complete lockup of a thread. I can't figure out what would cause this.
When making a call via XFire (ClientService.getAppLog()), the current
thread locks up just after printing the following out in the logs:
org.apache.commons.httpclient.HttpMethodBase writeRequest
100 (continue) read timeout. Resume sending the request
I see that this log comes from an InterruptedIOException here:
http://jakarta.apache.org/commons/httpclient/xref/org/apache/commons/
httpclient/HttpMethodBase.html#2004
The stack dump of the locked thread is:
"Thread-62" daemon prio=1 tid=0x082602c0 nid=0x51ca runnable
[0x79926000..0x79926e30]
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:129)
at java.io.BufferedInputStream.fill(BufferedInputStream.java:
218)
at java.io.BufferedInputStream.read(BufferedInputStream.java:
235)
- locked <0x830328c8> (a java.io.BufferedInputStream)
at org.apache.commons.httpclient.HttpParser.readRawLine
(HttpParser.java:77)
at org.apache.commons.httpclient.HttpParser.readLine
(HttpParser.java:105)
at org.apache.commons.httpclient.HttpConnection.readLine
(HttpConnection.java:1115)
at
org.apache.commons.httpclient.MultiThreadedHttpConnectionManager
$HttpConnectionAdapter.readLine
(MultiThreadedHttpConnectionManager.java:1373)
at org.apache.commons.httpclient.HttpMethodBase.readStatusLine
(HttpMethodBase.java:1832)
at org.apache.commons.httpclient.HttpMethodBase.readResponse
(HttpMethodBase.java:1590)
at org.apache.commons.httpclient.HttpMethodBase.execute
(HttpMethodBase.java:995)
at
org.apache.commons.httpclient.HttpMethodDirector.executeWithRetry
(HttpMethodDirector.java:397)
at
org.apache.commons.httpclient.HttpMethodDirector.executeMethod
(HttpMethodDirector.java:170)
at org.apache.commons.httpclient.HttpClient.executeMethod
(HttpClient.java:396)
at
org.codehaus.xfire.transport.http.CommonsHttpMessageSender.send
(CommonsHttpMessageSender.java:226)
at org.codehaus.xfire.transport.http.HttpChannel.sendViaClient
(HttpChannel.java:118)
at org.codehaus.xfire.transport.http.HttpChannel.send
(HttpChannel.java:48)
at org.codehaus.xfire.handler.OutMessageSender.invoke
(OutMessageSender.java:26)
at org.codehaus.xfire.handler.HandlerPipeline.invoke
(HandlerPipeline.java:130)
at org.codehaus.xfire.client.Invocation.invoke
(Invocation.java:75)
at org.codehaus.xfire.client.Client.invoke(Client.java:335)
at org.codehaus.xfire.client.XFireProxy.handleRequest
(XFireProxy.java:77)
at org.codehaus.xfire.client.XFireProxy.invoke
(XFireProxy.java:57)
at $Proxy5.getAppLog(Unknown Source)
at com.hostedqa.model.TestContextImpl.dispose
(TestContextImpl.java:83)
at com.hostedqa.model.Suite.playback(Suite.java:85)
at com.hostedqa.service.PlaybackService.runTest
(PlaybackService.java:83)
at com.hostedqa.service.PlaybackService.playSuite
(PlaybackService.java:48)
at com.hostedqa.action.project.suite.PlayAction$1.run
(PlayAction.java:25)
at java.lang.Thread.run(Thread.java:595)
What's very weird is that I am able to drop a JSP (test.jsp) that
makes the exact same call and it completes just fine. This tells me
that there is something environmental about _this_ thread that causes
HttpClient to do this. The call alone is not the issue.
Also, I might add that the XFire call never makes it to the other end
(ClientServiceImpl), as I have a print line there that never gets
invoked. I ran a stack dump on the other side as well, and nothing
stood out (though it is possible part of the request made it through
to XFire's Servlet, and then broke and was no longer in the active
thread dump by the time I forced the dump).
Finally, this request is running over HTTP. I'd really like to figure
out:
1) What that log from HttpMethodBase.writeRequest() is all about
2) Why there would be a perpetual "pause" in the native method, but
no actual visible deadlock.
3) How to fix this :)
Patrick
Patrick Lightbody
Autoriginate, Inc.
503-488-5402
http://www.autoriginate.com
patrick@autoriginate.com
"Intelligent testing made convenient"
---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-user-unsubscribe@jakarta.apache.org
For additional commands, e-mail: httpclient-user-help@jakarta.apache.org
Re: Lockup in XFire
Posted by Patrick Lightbody <pl...@gmail.com>.
Some additional DEBUG level logs, though they don't provide a whole
bunch of detail. As you can see, after "Getting application log", a
bit more happens with HttpClient and then it ultimately locks up, as
seen in the stack dump provided in the previous email.
Aug 7, 2006 4:13:05 PM com.hostedqa.utils.Log log
INFO: Stopping client...
2006-08-07 16:13:05,617 DEBUG [?:?] : enter
PostMethod.clearRequestBody()
2006-08-07 16:13:05,617 DEBUG [?:?] : enter
PostMethod.clearRequestBody()
2006-08-07 16:13:05,618 DEBUG [?:?] : enter
EntityEnclosingMethod.clearRequestBody()
2006-08-07 16:13:05,618 DEBUG [?:?] : enter
EntityEnclosingMethod.clearRequestBody()
2006-08-07 16:13:05,618 DEBUG [?:?] : enter HttpClient.executeMethod
(HostConfiguration,HttpMethod,HttpState)
2006-08-07 16:13:05,618 DEBUG [?:?] : enter HttpClient.executeMethod
(HostConfiguration,HttpMethod,HttpState)
2006-08-07 16:13:05,618 DEBUG [?:?] : enter
HttpConnectionManager.getConnectionWithTimeout(HostConfiguration, long)
2006-08-07 16:13:05,618 DEBUG [?:?] : enter
HttpConnectionManager.getConnectionWithTimeout(HostConfiguration, long)
2006-08-07 16:13:05,619 DEBUG [?:?] :
HttpConnectionManager.getConnection: config = HostConfiguration
[host=http://192.168.167.129:8081], timeout = 0
2006-08-07 16:13:05,619 DEBUG [?:?] :
HttpConnectionManager.getConnection: config = HostConfiguration
[host=http://192.168.167.129:8081], timeout = 0
2006-08-07 16:13:05,619 DEBUG [?:?] : enter
HttpConnectionManager.ConnectionPool.getHostPool(HostConfiguration)
2006-08-07 16:13:05,619 DEBUG [?:?] : enter
HttpConnectionManager.ConnectionPool.getHostPool(HostConfiguration)
2006-08-07 16:13:05,619 DEBUG [?:?] : enter
HttpConnectionManager.ConnectionPool.getHostPool(HostConfiguration)
2006-08-07 16:13:05,619 DEBUG [?:?] : enter
HttpConnectionManager.ConnectionPool.getHostPool(HostConfiguration)
2006-08-07 16:13:05,620 DEBUG [?:?] : Getting free connection,
hostConfig=HostConfiguration[host=http://192.168.167.129:8081]
2006-08-07 16:13:05,620 DEBUG [?:?] : Getting free connection,
hostConfig=HostConfiguration[host=http://192.168.167.129:8081]
2006-08-07 16:13:05,620 DEBUG [?:?] : Attempt number 1 to process
request
2006-08-07 16:13:05,620 DEBUG [?:?] : Attempt number 1 to process
request
2006-08-07 16:13:05,623 DEBUG [?:?] : enter HttpMethodBase.execute
(HttpState, HttpConnection)
2006-08-07 16:13:05,623 DEBUG [?:?] : enter HttpMethodBase.execute
(HttpState, HttpConnection)
2006-08-07 16:13:05,623 DEBUG [?:?] : enter
HttpMethodBase.writeRequest(HttpState, HttpConnection)
2006-08-07 16:13:05,623 DEBUG [?:?] : enter
HttpMethodBase.writeRequest(HttpState, HttpConnection)
2006-08-07 16:13:05,623 DEBUG [?:?] : enter
HttpMethodBase.writeRequestLine(HttpState, HttpConnection)
2006-08-07 16:13:05,623 DEBUG [?:?] : enter
HttpMethodBase.writeRequestLine(HttpState, HttpConnection)
2006-08-07 16:13:05,624 DEBUG [?:?] : enter
HttpMethodBase.generateRequestLine(HttpConnection, String, String,
String, String)
2006-08-07 16:13:05,624 DEBUG [?:?] : enter
HttpMethodBase.generateRequestLine(HttpConnection, String, String,
String, String)
2006-08-07 16:13:05,624 DEBUG [?:?] : enter HttpConnection.print(String)
2006-08-07 16:13:05,624 DEBUG [?:?] : enter HttpConnection.print(String)
2006-08-07 16:13:05,624 DEBUG [?:?] : enter HttpConnection.write(byte[])
2006-08-07 16:13:05,624 DEBUG [?:?] : enter HttpConnection.write(byte[])
2006-08-07 16:13:05,625 DEBUG [?:?] : enter HttpConnection.write(byte
[], int, int)
2006-08-07 16:13:05,625 DEBUG [?:?] : enter HttpConnection.write(byte
[], int, int)
2006-08-07 16:13:05,625 DEBUG [?:?] : enter
HttpMethodBase.writeRequestHeaders(HttpState,HttpConnection)
2006-08-07 16:13:05,625 DEBUG [?:?] : enter
HttpMethodBase.writeRequestHeaders(HttpState,HttpConnection)
2006-08-07 16:13:05,625 DEBUG [?:?] : enter
EntityEnclosingMethod.addRequestHeaders(HttpState, HttpConnection)
2006-08-07 16:13:05,625 DEBUG [?:?] : enter
EntityEnclosingMethod.addRequestHeaders(HttpState, HttpConnection)
2006-08-07 16:13:05,626 DEBUG [?:?] : enter
ExpectContinueMethod.addRequestHeaders(HttpState, HttpConnection)
2006-08-07 16:13:05,626 DEBUG [?:?] : enter
ExpectContinueMethod.addRequestHeaders(HttpState, HttpConnection)
2006-08-07 16:13:05,626 DEBUG [?:?] : enter
HttpMethodBase.addRequestHeaders(HttpState, HttpConnection)
2006-08-07 16:13:05,626 DEBUG [?:?] : enter
HttpMethodBase.addRequestHeaders(HttpState, HttpConnection)
2006-08-07 16:13:05,626 DEBUG [?:?] : enter
HttpMethodBase.addUserAgentRequestHeaders(HttpState, HttpConnection)
2006-08-07 16:13:05,626 DEBUG [?:?] : enter
HttpMethodBase.addUserAgentRequestHeaders(HttpState, HttpConnection)
2006-08-07 16:13:05,627 DEBUG [?:?] : enter
HttpMethodBase.addHostRequestHeader(HttpState, HttpConnection)
2006-08-07 16:13:05,627 DEBUG [?:?] : enter
HttpMethodBase.addHostRequestHeader(HttpState, HttpConnection)
2006-08-07 16:13:05,627 DEBUG [?:?] : Adding Host request header
2006-08-07 16:13:05,627 DEBUG [?:?] : Adding Host request header
2006-08-07 16:13:05,627 DEBUG [?:?] : enter
HttpMethodBase.addCookieRequestHeader(HttpState, HttpConnection)
2006-08-07 16:13:05,627 DEBUG [?:?] : enter
HttpMethodBase.addCookieRequestHeader(HttpState, HttpConnection)
2006-08-07 16:13:05,628 DEBUG [?:?] : enter HttpState.getCookies()
2006-08-07 16:13:05,628 DEBUG [?:?] : enter HttpState.getCookies()
2006-08-07 16:13:05,628 DEBUG [?:?] : enter CookieSpecBase.match
(String, int, String, boolean, Cookie[])
2006-08-07 16:13:05,628 DEBUG [?:?] : enter CookieSpecBase.match
(String, int, String, boolean, Cookie[])
2006-08-07 16:13:05,629 DEBUG [?:?] : enter
HttpMethodBase.addProxyConnectionHeader(HttpState, HttpConnection)
2006-08-07 16:13:05,629 DEBUG [?:?] : enter
HttpMethodBase.addProxyConnectionHeader(HttpState, HttpConnection)
2006-08-07 16:13:05,629 DEBUG [?:?] : enter
PostMethod.hasRequestContent()
2006-08-07 16:13:05,629 DEBUG [?:?] : enter
PostMethod.hasRequestContent()
2006-08-07 16:13:05,629 DEBUG [?:?] : enter
EntityEnclosingMethod.hasRequestContent()
2006-08-07 16:13:05,629 DEBUG [?:?] : enter
EntityEnclosingMethod.hasRequestContent()
2006-08-07 16:13:05,630 DEBUG [?:?] : enter
EntityEnclosingMethod.addContentLengthRequestHeader(HttpState,
HttpConnection)
2006-08-07 16:13:05,630 DEBUG [?:?] : enter
EntityEnclosingMethod.addContentLengthRequestHeader(HttpState,
HttpConnection)
2006-08-07 16:13:05,630 DEBUG [?:?] : enter
EntityEnclosingMethod.getRequestContentLength()
2006-08-07 16:13:05,630 DEBUG [?:?] : enter
EntityEnclosingMethod.getRequestContentLength()
2006-08-07 16:13:05,630 DEBUG [?:?] : enter
PostMethod.hasRequestContent()
2006-08-07 16:13:05,630 DEBUG [?:?] : enter
PostMethod.hasRequestContent()
2006-08-07 16:13:05,631 DEBUG [?:?] : enter
EntityEnclosingMethod.hasRequestContent()
2006-08-07 16:13:05,631 DEBUG [?:?] : enter
EntityEnclosingMethod.hasRequestContent()
2006-08-07 16:13:05,631 DEBUG [?:?] : HttpMethodBase.addRequestHeader
(Header)
2006-08-07 16:13:05,631 DEBUG [?:?] : HttpMethodBase.addRequestHeader
(Header)
2006-08-07 16:13:05,631 DEBUG [?:?] : enter HttpConnection.print(String)
2006-08-07 16:13:05,631 DEBUG [?:?] : enter HttpConnection.print(String)
2006-08-07 16:13:05,632 DEBUG [?:?] : enter HttpConnection.write(byte[])
2006-08-07 16:13:05,632 DEBUG [?:?] : enter HttpConnection.write(byte[])
2006-08-07 16:13:05,632 DEBUG [?:?] : enter HttpConnection.write(byte
[], int, int)
2006-08-07 16:13:05,632 DEBUG [?:?] : enter HttpConnection.write(byte
[], int, int)
2006-08-07 16:13:05,632 DEBUG [?:?] : enter HttpConnection.print(String)
2006-08-07 16:13:05,632 DEBUG [?:?] : enter HttpConnection.print(String)
2006-08-07 16:13:05,633 DEBUG [?:?] : enter HttpConnection.write(byte[])
2006-08-07 16:13:05,633 DEBUG [?:?] : enter HttpConnection.write(byte[])
2006-08-07 16:13:05,633 DEBUG [?:?] : enter HttpConnection.write(byte
[], int, int)
2006-08-07 16:13:05,633 DEBUG [?:?] : enter HttpConnection.write(byte
[], int, int)
2006-08-07 16:13:05,633 DEBUG [?:?] : enter HttpConnection.print(String)
2006-08-07 16:13:05,633 DEBUG [?:?] : enter HttpConnection.print(String)
2006-08-07 16:13:05,634 DEBUG [?:?] : enter HttpConnection.write(byte[])
2006-08-07 16:13:05,634 DEBUG [?:?] : enter HttpConnection.write(byte[])
2006-08-07 16:13:05,634 DEBUG [?:?] : enter HttpConnection.write(byte
[], int, int)
2006-08-07 16:13:05,634 DEBUG [?:?] : enter HttpConnection.write(byte
[], int, int)
2006-08-07 16:13:05,634 DEBUG [?:?] : enter HttpConnection.print(String)
2006-08-07 16:13:05,634 DEBUG [?:?] : enter HttpConnection.print(String)
2006-08-07 16:13:05,635 DEBUG [?:?] : enter HttpConnection.write(byte[])
2006-08-07 16:13:05,635 DEBUG [?:?] : enter HttpConnection.write(byte[])
2006-08-07 16:13:05,636 DEBUG [?:?] : enter HttpConnection.write(byte
[], int, int)
2006-08-07 16:13:05,636 DEBUG [?:?] : enter HttpConnection.write(byte
[], int, int)
2006-08-07 16:13:05,636 DEBUG [?:?] : enter HttpConnection.print(String)
2006-08-07 16:13:05,636 DEBUG [?:?] : enter HttpConnection.print(String)
2006-08-07 16:13:05,636 DEBUG [?:?] : enter HttpConnection.write(byte[])
2006-08-07 16:13:05,636 DEBUG [?:?] : enter HttpConnection.write(byte[])
2006-08-07 16:13:05,637 DEBUG [?:?] : enter HttpConnection.write(byte
[], int, int)
2006-08-07 16:13:05,637 DEBUG [?:?] : enter HttpConnection.write(byte
[], int, int)
2006-08-07 16:13:05,637 DEBUG [?:?] : enter HttpConnection.print(String)
2006-08-07 16:13:05,637 DEBUG [?:?] : enter HttpConnection.print(String)
2006-08-07 16:13:05,638 DEBUG [?:?] : enter HttpConnection.write(byte[])
2006-08-07 16:13:05,638 DEBUG [?:?] : enter HttpConnection.write(byte[])
2006-08-07 16:13:05,638 DEBUG [?:?] : enter HttpConnection.write(byte
[], int, int)
2006-08-07 16:13:05,638 DEBUG [?:?] : enter HttpConnection.write(byte
[], int, int)
2006-08-07 16:13:05,638 DEBUG [?:?] : enter HttpConnection.writeLine()
2006-08-07 16:13:05,638 DEBUG [?:?] : enter HttpConnection.writeLine()
2006-08-07 16:13:05,639 DEBUG [?:?] : enter HttpConnection.write(byte[])
2006-08-07 16:13:05,639 DEBUG [?:?] : enter HttpConnection.write(byte[])
2006-08-07 16:13:05,639 DEBUG [?:?] : enter HttpConnection.write(byte
[], int, int)
2006-08-07 16:13:05,639 DEBUG [?:?] : enter HttpConnection.write(byte
[], int, int)
2006-08-07 16:13:05,640 DEBUG [?:?] : enter
HttpConnection.flushRequestOutputStream()
2006-08-07 16:13:05,640 DEBUG [?:?] : enter
HttpConnection.flushRequestOutputStream()
2006-08-07 16:13:05,642 DEBUG [?:?] : enter
HttpMethodBase.readStatusLine(HttpState, HttpConnection)
2006-08-07 16:13:05,642 DEBUG [?:?] : enter
HttpMethodBase.readStatusLine(HttpState, HttpConnection)
2006-08-07 16:13:05,643 DEBUG [?:?] : enter HttpConnection.readLine()
2006-08-07 16:13:05,643 DEBUG [?:?] : enter HttpConnection.readLine()
2006-08-07 16:13:05,643 DEBUG [?:?] : enter HttpParser.readLine
(InputStream, String)
2006-08-07 16:13:05,643 DEBUG [?:?] : enter HttpParser.readLine
(InputStream, String)
2006-08-07 16:13:05,644 DEBUG [?:?] : enter HttpParser.readRawLine()
2006-08-07 16:13:05,644 DEBUG [?:?] : enter HttpParser.readRawLine()
2006-08-07 16:13:05,645 DEBUG [?:?] : enter
HttpMethodBase.readResponseHeaders(HttpState,HttpConnection)
2006-08-07 16:13:05,645 DEBUG [?:?] : enter
HttpMethodBase.readResponseHeaders(HttpState,HttpConnection)
2006-08-07 16:13:05,645 DEBUG [?:?] : enter
HttpConnection.getResponseInputStream()
2006-08-07 16:13:05,645 DEBUG [?:?] : enter
HttpConnection.getResponseInputStream()
2006-08-07 16:13:05,646 DEBUG [?:?] : enter HeaderParser.parseHeaders
(InputStream, String)
2006-08-07 16:13:05,646 DEBUG [?:?] : enter HeaderParser.parseHeaders
(InputStream, String)
2006-08-07 16:13:05,646 DEBUG [?:?] : enter HttpParser.readLine
(InputStream, String)
2006-08-07 16:13:05,646 DEBUG [?:?] : enter HttpParser.readLine
(InputStream, String)
2006-08-07 16:13:05,647 DEBUG [?:?] : enter HttpParser.readRawLine()
2006-08-07 16:13:05,647 DEBUG [?:?] : enter HttpParser.readRawLine()
2006-08-07 16:13:05,647 DEBUG [?:?] : enter
HttpMethodBase.processResponseHeaders(HttpState, HttpConnection)
2006-08-07 16:13:05,647 DEBUG [?:?] : enter
HttpMethodBase.processResponseHeaders(HttpState, HttpConnection)
2006-08-07 16:13:05,648 DEBUG [?:?] : enter
HttpMethodBase.processCookieHeaders(Header[], HttpState, HttpConnection)
2006-08-07 16:13:05,648 DEBUG [?:?] : enter
HttpMethodBase.processCookieHeaders(Header[], HttpState, HttpConnection)
2006-08-07 16:13:05,648 DEBUG [?:?] : OK to continue received
2006-08-07 16:13:05,648 DEBUG [?:?] : OK to continue received
2006-08-07 16:13:05,649 DEBUG [?:?] : enter
EntityEnclosingMethod.writeRequestBody(HttpState, HttpConnection)
2006-08-07 16:13:05,649 DEBUG [?:?] : enter
EntityEnclosingMethod.writeRequestBody(HttpState, HttpConnection)
2006-08-07 16:13:05,650 DEBUG [?:?] : enter
PostMethod.hasRequestContent()
2006-08-07 16:13:05,650 DEBUG [?:?] : enter
PostMethod.hasRequestContent()
2006-08-07 16:13:05,650 DEBUG [?:?] : enter
EntityEnclosingMethod.hasRequestContent()
2006-08-07 16:13:05,650 DEBUG [?:?] : enter
EntityEnclosingMethod.hasRequestContent()
2006-08-07 16:13:05,651 DEBUG [?:?] : enter
EntityEnclosingMethod.getRequestContentLength()
2006-08-07 16:13:05,651 DEBUG [?:?] : enter
EntityEnclosingMethod.getRequestContentLength()
2006-08-07 16:13:05,651 DEBUG [?:?] : enter
PostMethod.hasRequestContent()
2006-08-07 16:13:05,651 DEBUG [?:?] : enter
PostMethod.hasRequestContent()
2006-08-07 16:13:05,652 DEBUG [?:?] : enter
EntityEnclosingMethod.hasRequestContent()
2006-08-07 16:13:05,652 DEBUG [?:?] : enter
EntityEnclosingMethod.hasRequestContent()
2006-08-07 16:13:05,652 DEBUG [?:?] : enter
HttpConnection.getRequestOutputStream()
2006-08-07 16:13:05,652 DEBUG [?:?] : enter
HttpConnection.getRequestOutputStream()
2006-08-07 16:13:05,660 DEBUG [?:?] : Request body sent
2006-08-07 16:13:05,660 DEBUG [?:?] : Request body sent
2006-08-07 16:13:05,661 DEBUG [?:?] : enter
HttpConnection.flushRequestOutputStream()
2006-08-07 16:13:05,661 DEBUG [?:?] : enter
HttpConnection.flushRequestOutputStream()
2006-08-07 16:13:05,661 DEBUG [?:?] : enter
HttpMethodBase.readResponse(HttpState, HttpConnection)
2006-08-07 16:13:05,661 DEBUG [?:?] : enter
HttpMethodBase.readResponse(HttpState, HttpConnection)
2006-08-07 16:13:05,662 DEBUG [?:?] : enter
HttpMethodBase.readStatusLine(HttpState, HttpConnection)
2006-08-07 16:13:05,662 DEBUG [?:?] : enter
HttpMethodBase.readStatusLine(HttpState, HttpConnection)
2006-08-07 16:13:05,663 DEBUG [?:?] : enter HttpConnection.readLine()
2006-08-07 16:13:05,663 DEBUG [?:?] : enter HttpConnection.readLine()
2006-08-07 16:13:05,663 DEBUG [?:?] : enter HttpParser.readLine
(InputStream, String)
2006-08-07 16:13:05,663 DEBUG [?:?] : enter HttpParser.readLine
(InputStream, String)
2006-08-07 16:13:05,664 DEBUG [?:?] : enter HttpParser.readRawLine()
2006-08-07 16:13:05,664 DEBUG [?:?] : enter HttpParser.readRawLine()
2006-08-07 16:13:07,914 DEBUG [?:?] : enter
HttpMethodBase.readResponseHeaders(HttpState,HttpConnection)
2006-08-07 16:13:07,914 DEBUG [?:?] : enter
HttpMethodBase.readResponseHeaders(HttpState,HttpConnection)
2006-08-07 16:13:07,914 DEBUG [?:?] : enter
HttpConnection.getResponseInputStream()
2006-08-07 16:13:07,914 DEBUG [?:?] : enter
HttpConnection.getResponseInputStream()
2006-08-07 16:13:07,915 DEBUG [?:?] : enter HeaderParser.parseHeaders
(InputStream, String)
2006-08-07 16:13:07,915 DEBUG [?:?] : enter HeaderParser.parseHeaders
(InputStream, String)
2006-08-07 16:13:07,915 DEBUG [?:?] : enter HttpParser.readLine
(InputStream, String)
2006-08-07 16:13:07,915 DEBUG [?:?] : enter HttpParser.readLine
(InputStream, String)
2006-08-07 16:13:07,915 DEBUG [?:?] : enter HttpParser.readRawLine()
2006-08-07 16:13:07,915 DEBUG [?:?] : enter HttpParser.readRawLine()
2006-08-07 16:13:07,916 DEBUG [?:?] : enter HttpParser.readLine
(InputStream, String)
2006-08-07 16:13:07,916 DEBUG [?:?] : enter HttpParser.readLine
(InputStream, String)
2006-08-07 16:13:07,916 DEBUG [?:?] : enter HttpParser.readRawLine()
2006-08-07 16:13:07,916 DEBUG [?:?] : enter HttpParser.readRawLine()
2006-08-07 16:13:07,916 DEBUG [?:?] : enter HttpParser.readLine
(InputStream, String)
2006-08-07 16:13:07,916 DEBUG [?:?] : enter HttpParser.readLine
(InputStream, String)
2006-08-07 16:13:07,917 DEBUG [?:?] : enter HttpParser.readRawLine()
2006-08-07 16:13:07,917 DEBUG [?:?] : enter HttpParser.readRawLine()
2006-08-07 16:13:07,917 DEBUG [?:?] : enter HttpParser.readLine
(InputStream, String)
2006-08-07 16:13:07,917 DEBUG [?:?] : enter HttpParser.readLine
(InputStream, String)
2006-08-07 16:13:07,917 DEBUG [?:?] : enter HttpParser.readRawLine()
2006-08-07 16:13:07,917 DEBUG [?:?] : enter HttpParser.readRawLine()
2006-08-07 16:13:07,918 DEBUG [?:?] : enter HttpParser.readLine
(InputStream, String)
2006-08-07 16:13:07,918 DEBUG [?:?] : enter HttpParser.readLine
(InputStream, String)
2006-08-07 16:13:07,918 DEBUG [?:?] : enter HttpParser.readRawLine()
2006-08-07 16:13:07,918 DEBUG [?:?] : enter HttpParser.readRawLine()
2006-08-07 16:13:07,918 DEBUG [?:?] : enter HttpParser.readLine
(InputStream, String)
2006-08-07 16:13:07,918 DEBUG [?:?] : enter HttpParser.readLine
(InputStream, String)
2006-08-07 16:13:07,919 DEBUG [?:?] : enter HttpParser.readRawLine()
2006-08-07 16:13:07,919 DEBUG [?:?] : enter HttpParser.readRawLine()
2006-08-07 16:13:07,919 DEBUG [?:?] : enter
HttpMethodBase.processResponseHeaders(HttpState, HttpConnection)
2006-08-07 16:13:07,919 DEBUG [?:?] : enter
HttpMethodBase.processResponseHeaders(HttpState, HttpConnection)
2006-08-07 16:13:07,919 DEBUG [?:?] : enter
HttpMethodBase.processCookieHeaders(Header[], HttpState, HttpConnection)
2006-08-07 16:13:07,919 DEBUG [?:?] : enter
HttpMethodBase.processCookieHeaders(Header[], HttpState, HttpConnection)
2006-08-07 16:13:07,920 DEBUG [?:?] : enter
HttpMethodBase.readResponseBody(HttpState, HttpConnection)
2006-08-07 16:13:07,920 DEBUG [?:?] : enter
HttpMethodBase.readResponseBody(HttpState, HttpConnection)
2006-08-07 16:13:07,920 DEBUG [?:?] : enter
HttpMethodBase.readResponseBody(HttpConnection)
2006-08-07 16:13:07,920 DEBUG [?:?] : enter
HttpMethodBase.readResponseBody(HttpConnection)
2006-08-07 16:13:07,920 DEBUG [?:?] : enter
HttpConnection.getResponseInputStream()
2006-08-07 16:13:07,920 DEBUG [?:?] : enter
HttpConnection.getResponseInputStream()
2006-08-07 16:13:07,921 DEBUG [?:?] : enter
HttpMethodBase.canResponseHaveBody(int)
2006-08-07 16:13:07,921 DEBUG [?:?] : enter
HttpMethodBase.canResponseHaveBody(int)
2006-08-07 16:13:07,921 DEBUG [?:?] : enter
HeaderElement.parseElements(String)
2006-08-07 16:13:07,921 DEBUG [?:?] : enter
HeaderElement.parseElements(String)
2006-08-07 16:13:07,921 DEBUG [?:?] : enter
HeaderElement.parseElements(char[])
2006-08-07 16:13:07,921 DEBUG [?:?] : enter
HeaderElement.parseElements(char[])
2006-08-07 16:13:07,922 DEBUG [?:?] : enter
HttpConnection.isResponseAvailable(int)
2006-08-07 16:13:07,922 DEBUG [?:?] : enter
HttpConnection.isResponseAvailable(int)
2006-08-07 16:13:07,923 DEBUG [?:?] : enter HeaderParser.parseHeaders
(InputStream, String)
2006-08-07 16:13:07,923 DEBUG [?:?] : enter HeaderParser.parseHeaders
(InputStream, String)
2006-08-07 16:13:07,923 DEBUG [?:?] : enter HttpParser.readLine
(InputStream, String)
2006-08-07 16:13:07,923 DEBUG [?:?] : enter HttpParser.readLine
(InputStream, String)
2006-08-07 16:13:07,924 DEBUG [?:?] : enter HttpParser.readRawLine()
2006-08-07 16:13:07,924 DEBUG [?:?] : enter HttpParser.readRawLine()
2006-08-07 16:13:07,924 DEBUG [?:?] : Resorting to protocol version
default close connection policy
2006-08-07 16:13:07,924 DEBUG [?:?] : Resorting to protocol version
default close connection policy
2006-08-07 16:13:07,924 DEBUG [?:?] : Should NOT close connection,
using HTTP/1.1
2006-08-07 16:13:07,924 DEBUG [?:?] : Should NOT close connection,
using HTTP/1.1
2006-08-07 16:13:07,925 DEBUG [?:?] : enter
HttpConnection.isResponseAvailable()
2006-08-07 16:13:07,925 DEBUG [?:?] : enter
HttpConnection.isResponseAvailable()
2006-08-07 16:13:07,925 DEBUG [?:?] : enter
HttpConnection.releaseConnection()
2006-08-07 16:13:07,925 DEBUG [?:?] : enter
HttpConnection.releaseConnection()
2006-08-07 16:13:07,925 DEBUG [?:?] : Releasing connection back to
connection manager.
2006-08-07 16:13:07,925 DEBUG [?:?] : Releasing connection back to
connection manager.
2006-08-07 16:13:07,926 DEBUG [?:?] : enter
HttpConnectionManager.releaseConnection(HttpConnection)
2006-08-07 16:13:07,926 DEBUG [?:?] : enter
HttpConnectionManager.releaseConnection(HttpConnection)
2006-08-07 16:13:07,926 DEBUG [?:?] : Freeing connection,
hostConfig=HostConfiguration[host=http://192.168.167.129:8081]
2006-08-07 16:13:07,926 DEBUG [?:?] : Freeing connection,
hostConfig=HostConfiguration[host=http://192.168.167.129:8081]
2006-08-07 16:13:07,927 DEBUG [?:?] : enter
HttpConnectionManager.ConnectionPool.getHostPool(HostConfiguration)
2006-08-07 16:13:07,927 DEBUG [?:?] : enter
HttpConnectionManager.ConnectionPool.getHostPool(HostConfiguration)
2006-08-07 16:13:07,927 DEBUG [?:?] : Adding connection at:
1154985187927
2006-08-07 16:13:07,927 DEBUG [?:?] : Adding connection at:
1154985187927
2006-08-07 16:13:07,927 DEBUG [?:?] : Notifying no-one, there are no
waiting threads
2006-08-07 16:13:07,927 DEBUG [?:?] : Notifying no-one, there are no
waiting threads
Aug 7, 2006 4:13:07 PM com.hostedqa.utils.Log log
INFO: Getting application log...
2006-08-07 16:13:07,929 DEBUG [?:?] : enter
PostMethod.clearRequestBody()
2006-08-07 16:13:07,929 DEBUG [?:?] : enter
PostMethod.clearRequestBody()
2006-08-07 16:13:07,929 DEBUG [?:?] : enter
EntityEnclosingMethod.clearRequestBody()
2006-08-07 16:13:07,929 DEBUG [?:?] : enter
EntityEnclosingMethod.clearRequestBody()
2006-08-07 16:13:07,930 DEBUG [?:?] : enter HttpClient.executeMethod
(HostConfiguration,HttpMethod,HttpState)
2006-08-07 16:13:07,930 DEBUG [?:?] : enter HttpClient.executeMethod
(HostConfiguration,HttpMethod,HttpState)
2006-08-07 16:13:07,930 DEBUG [?:?] : enter
HttpConnectionManager.getConnectionWithTimeout(HostConfiguration, long)
2006-08-07 16:13:07,930 DEBUG [?:?] : enter
HttpConnectionManager.getConnectionWithTimeout(HostConfiguration, long)
2006-08-07 16:13:07,930 DEBUG [?:?] :
HttpConnectionManager.getConnection: config = HostConfiguration
[host=http://192.168.167.162:8081], timeout = 0
2006-08-07 16:13:07,930 DEBUG [?:?] :
HttpConnectionManager.getConnection: config = HostConfiguration
[host=http://192.168.167.162:8081], timeout = 0
2006-08-07 16:13:07,931 DEBUG [?:?] : enter
HttpConnectionManager.ConnectionPool.getHostPool(HostConfiguration)
2006-08-07 16:13:07,931 DEBUG [?:?] : enter
HttpConnectionManager.ConnectionPool.getHostPool(HostConfiguration)
2006-08-07 16:13:07,931 DEBUG [?:?] : enter
HttpConnectionManager.ConnectionPool.getHostPool(HostConfiguration)
2006-08-07 16:13:07,931 DEBUG [?:?] : enter
HttpConnectionManager.ConnectionPool.getHostPool(HostConfiguration)
2006-08-07 16:13:07,931 DEBUG [?:?] : Getting free connection,
hostConfig=HostConfiguration[host=http://192.168.167.162:8081]
2006-08-07 16:13:07,931 DEBUG [?:?] : Getting free connection,
hostConfig=HostConfiguration[host=http://192.168.167.162:8081]
2006-08-07 16:13:07,932 DEBUG [?:?] : Attempt number 1 to process
request
2006-08-07 16:13:07,932 DEBUG [?:?] : Attempt number 1 to process
request
2006-08-07 16:13:07,934 DEBUG [?:?] : enter HttpMethodBase.execute
(HttpState, HttpConnection)
2006-08-07 16:13:07,934 DEBUG [?:?] : enter HttpMethodBase.execute
(HttpState, HttpConnection)
2006-08-07 16:13:07,934 DEBUG [?:?] : enter
HttpMethodBase.writeRequest(HttpState, HttpConnection)
2006-08-07 16:13:07,934 DEBUG [?:?] : enter
HttpMethodBase.writeRequest(HttpState, HttpConnection)
2006-08-07 16:13:07,935 DEBUG [?:?] : enter
HttpMethodBase.writeRequestLine(HttpState, HttpConnection)
2006-08-07 16:13:07,935 DEBUG [?:?] : enter
HttpMethodBase.writeRequestLine(HttpState, HttpConnection)
2006-08-07 16:13:07,935 DEBUG [?:?] : enter
HttpMethodBase.generateRequestLine(HttpConnection, String, String,
String, String)
2006-08-07 16:13:07,935 DEBUG [?:?] : enter
HttpMethodBase.generateRequestLine(HttpConnection, String, String,
String, String)
2006-08-07 16:13:07,935 DEBUG [?:?] : enter HttpConnection.print(String)
2006-08-07 16:13:07,935 DEBUG [?:?] : enter HttpConnection.print(String)
2006-08-07 16:13:07,936 DEBUG [?:?] : enter HttpConnection.write(byte[])
2006-08-07 16:13:07,936 DEBUG [?:?] : enter HttpConnection.write(byte[])
2006-08-07 16:13:07,936 DEBUG [?:?] : enter HttpConnection.write(byte
[], int, int)
2006-08-07 16:13:07,936 DEBUG [?:?] : enter HttpConnection.write(byte
[], int, int)
2006-08-07 16:13:07,936 DEBUG [?:?] : enter
HttpMethodBase.writeRequestHeaders(HttpState,HttpConnection)
2006-08-07 16:13:07,936 DEBUG [?:?] : enter
HttpMethodBase.writeRequestHeaders(HttpState,HttpConnection)
2006-08-07 16:13:07,937 DEBUG [?:?] : enter
EntityEnclosingMethod.addRequestHeaders(HttpState, HttpConnection)
2006-08-07 16:13:07,937 DEBUG [?:?] : enter
EntityEnclosingMethod.addRequestHeaders(HttpState, HttpConnection)
2006-08-07 16:13:07,937 DEBUG [?:?] : enter
ExpectContinueMethod.addRequestHeaders(HttpState, HttpConnection)
2006-08-07 16:13:07,937 DEBUG [?:?] : enter
ExpectContinueMethod.addRequestHeaders(HttpState, HttpConnection)
2006-08-07 16:13:07,937 DEBUG [?:?] : enter
HttpMethodBase.addRequestHeaders(HttpState, HttpConnection)
2006-08-07 16:13:07,937 DEBUG [?:?] : enter
HttpMethodBase.addRequestHeaders(HttpState, HttpConnection)
2006-08-07 16:13:07,938 DEBUG [?:?] : enter
HttpMethodBase.addUserAgentRequestHeaders(HttpState, HttpConnection)
2006-08-07 16:13:07,938 DEBUG [?:?] : enter
HttpMethodBase.addUserAgentRequestHeaders(HttpState, HttpConnection)
2006-08-07 16:13:07,938 DEBUG [?:?] : enter
HttpMethodBase.addHostRequestHeader(HttpState, HttpConnection)
2006-08-07 16:13:07,938 DEBUG [?:?] : enter
HttpMethodBase.addHostRequestHeader(HttpState, HttpConnection)
2006-08-07 16:13:07,938 DEBUG [?:?] : Adding Host request header
2006-08-07 16:13:07,938 DEBUG [?:?] : Adding Host request header
2006-08-07 16:13:07,939 DEBUG [?:?] : enter
HttpMethodBase.addCookieRequestHeader(HttpState, HttpConnection)
2006-08-07 16:13:07,939 DEBUG [?:?] : enter
HttpMethodBase.addCookieRequestHeader(HttpState, HttpConnection)
2006-08-07 16:13:07,939 DEBUG [?:?] : enter HttpState.getCookies()
2006-08-07 16:13:07,939 DEBUG [?:?] : enter HttpState.getCookies()
2006-08-07 16:13:07,940 DEBUG [?:?] : enter CookieSpecBase.match
(String, int, String, boolean, Cookie[])
2006-08-07 16:13:07,940 DEBUG [?:?] : enter CookieSpecBase.match
(String, int, String, boolean, Cookie[])
2006-08-07 16:13:07,940 DEBUG [?:?] : enter
HttpMethodBase.addProxyConnectionHeader(HttpState, HttpConnection)
2006-08-07 16:13:07,940 DEBUG [?:?] : enter
HttpMethodBase.addProxyConnectionHeader(HttpState, HttpConnection)
2006-08-07 16:13:07,940 DEBUG [?:?] : enter
PostMethod.hasRequestContent()
2006-08-07 16:13:07,940 DEBUG [?:?] : enter
PostMethod.hasRequestContent()
2006-08-07 16:13:07,941 DEBUG [?:?] : enter
EntityEnclosingMethod.hasRequestContent()
2006-08-07 16:13:07,941 DEBUG [?:?] : enter
EntityEnclosingMethod.hasRequestContent()
2006-08-07 16:13:07,941 DEBUG [?:?] : enter
EntityEnclosingMethod.addContentLengthRequestHeader(HttpState,
HttpConnection)
2006-08-07 16:13:07,941 DEBUG [?:?] : enter
EntityEnclosingMethod.addContentLengthRequestHeader(HttpState,
HttpConnection)
2006-08-07 16:13:07,941 DEBUG [?:?] : enter
EntityEnclosingMethod.getRequestContentLength()
2006-08-07 16:13:07,941 DEBUG [?:?] : enter
EntityEnclosingMethod.getRequestContentLength()
2006-08-07 16:13:07,941 DEBUG [?:?] : enter
PostMethod.hasRequestContent()
2006-08-07 16:13:07,941 DEBUG [?:?] : enter
PostMethod.hasRequestContent()
2006-08-07 16:13:07,942 DEBUG [?:?] : enter
EntityEnclosingMethod.hasRequestContent()
2006-08-07 16:13:07,942 DEBUG [?:?] : enter
EntityEnclosingMethod.hasRequestContent()
2006-08-07 16:13:07,942 DEBUG [?:?] : HttpMethodBase.addRequestHeader
(Header)
2006-08-07 16:13:07,942 DEBUG [?:?] : HttpMethodBase.addRequestHeader
(Header)
2006-08-07 16:13:07,943 DEBUG [?:?] : enter HttpConnection.print(String)
2006-08-07 16:13:07,943 DEBUG [?:?] : enter HttpConnection.print(String)
2006-08-07 16:13:07,943 DEBUG [?:?] : enter HttpConnection.write(byte[])
2006-08-07 16:13:07,943 DEBUG [?:?] : enter HttpConnection.write(byte[])
2006-08-07 16:13:07,944 DEBUG [?:?] : enter HttpConnection.write(byte
[], int, int)
2006-08-07 16:13:07,944 DEBUG [?:?] : enter HttpConnection.write(byte
[], int, int)
2006-08-07 16:13:07,944 DEBUG [?:?] : enter HttpConnection.print(String)
2006-08-07 16:13:07,944 DEBUG [?:?] : enter HttpConnection.print(String)
2006-08-07 16:13:07,944 DEBUG [?:?] : enter HttpConnection.write(byte[])
2006-08-07 16:13:07,944 DEBUG [?:?] : enter HttpConnection.write(byte[])
2006-08-07 16:13:07,945 DEBUG [?:?] : enter HttpConnection.write(byte
[], int, int)
2006-08-07 16:13:07,945 DEBUG [?:?] : enter HttpConnection.write(byte
[], int, int)
2006-08-07 16:13:07,945 DEBUG [?:?] : enter HttpConnection.print(String)
2006-08-07 16:13:07,945 DEBUG [?:?] : enter HttpConnection.print(String)
2006-08-07 16:13:07,945 DEBUG [?:?] : enter HttpConnection.write(byte[])
2006-08-07 16:13:07,945 DEBUG [?:?] : enter HttpConnection.write(byte[])
2006-08-07 16:13:07,946 DEBUG [?:?] : enter HttpConnection.write(byte
[], int, int)
2006-08-07 16:13:07,946 DEBUG [?:?] : enter HttpConnection.write(byte
[], int, int)
2006-08-07 16:13:07,946 DEBUG [?:?] : enter HttpConnection.print(String)
2006-08-07 16:13:07,946 DEBUG [?:?] : enter HttpConnection.print(String)
2006-08-07 16:13:07,946 DEBUG [?:?] : enter HttpConnection.write(byte[])
2006-08-07 16:13:07,946 DEBUG [?:?] : enter HttpConnection.write(byte[])
2006-08-07 16:13:07,947 DEBUG [?:?] : enter HttpConnection.write(byte
[], int, int)
2006-08-07 16:13:07,947 DEBUG [?:?] : enter HttpConnection.write(byte
[], int, int)
2006-08-07 16:13:07,947 DEBUG [?:?] : enter HttpConnection.print(String)
2006-08-07 16:13:07,947 DEBUG [?:?] : enter HttpConnection.print(String)
2006-08-07 16:13:07,947 DEBUG [?:?] : enter HttpConnection.write(byte[])
2006-08-07 16:13:07,947 DEBUG [?:?] : enter HttpConnection.write(byte[])
2006-08-07 16:13:07,947 DEBUG [?:?] : enter HttpConnection.write(byte
[], int, int)
2006-08-07 16:13:07,947 DEBUG [?:?] : enter HttpConnection.write(byte
[], int, int)
2006-08-07 16:13:07,948 DEBUG [?:?] : enter HttpConnection.print(String)
2006-08-07 16:13:07,948 DEBUG [?:?] : enter HttpConnection.print(String)
2006-08-07 16:13:07,948 DEBUG [?:?] : enter HttpConnection.write(byte[])
2006-08-07 16:13:07,948 DEBUG [?:?] : enter HttpConnection.write(byte[])
2006-08-07 16:13:07,949 DEBUG [?:?] : enter HttpConnection.write(byte
[], int, int)
2006-08-07 16:13:07,949 DEBUG [?:?] : enter HttpConnection.write(byte
[], int, int)
2006-08-07 16:13:07,949 DEBUG [?:?] : enter HttpConnection.writeLine()
2006-08-07 16:13:07,949 DEBUG [?:?] : enter HttpConnection.writeLine()
2006-08-07 16:13:07,949 DEBUG [?:?] : enter HttpConnection.write(byte[])
2006-08-07 16:13:07,949 DEBUG [?:?] : enter HttpConnection.write(byte[])
2006-08-07 16:13:07,950 DEBUG [?:?] : enter HttpConnection.write(byte
[], int, int)
2006-08-07 16:13:07,950 DEBUG [?:?] : enter HttpConnection.write(byte
[], int, int)
2006-08-07 16:13:07,950 DEBUG [?:?] : enter
HttpConnection.flushRequestOutputStream()
2006-08-07 16:13:07,950 DEBUG [?:?] : enter
HttpConnection.flushRequestOutputStream()
2006-08-07 16:13:07,950 DEBUG [?:?] : enter
HttpMethodBase.readStatusLine(HttpState, HttpConnection)
2006-08-07 16:13:07,950 DEBUG [?:?] : enter
HttpMethodBase.readStatusLine(HttpState, HttpConnection)
2006-08-07 16:13:07,951 DEBUG [?:?] : enter HttpConnection.readLine()
2006-08-07 16:13:07,951 DEBUG [?:?] : enter HttpConnection.readLine()
2006-08-07 16:13:07,951 DEBUG [?:?] : enter HttpParser.readLine
(InputStream, String)
2006-08-07 16:13:07,951 DEBUG [?:?] : enter HttpParser.readLine
(InputStream, String)
2006-08-07 16:13:07,951 DEBUG [?:?] : enter HttpParser.readRawLine()
2006-08-07 16:13:07,951 DEBUG [?:?] : enter HttpParser.readRawLine()
2006-08-07 16:13:10,953 INFO [?:?] : 100 (continue) read timeout.
Resume sending the request
2006-08-07 16:13:10,953 INFO [?:?] : 100 (continue) read timeout.
Resume sending the request
2006-08-07 16:13:10,953 DEBUG [?:?] : enter
EntityEnclosingMethod.writeRequestBody(HttpState, HttpConnection)
2006-08-07 16:13:10,953 DEBUG [?:?] : enter
EntityEnclosingMethod.writeRequestBody(HttpState, HttpConnection)
2006-08-07 16:13:10,954 DEBUG [?:?] : enter
PostMethod.hasRequestContent()
2006-08-07 16:13:10,954 DEBUG [?:?] : enter
PostMethod.hasRequestContent()
2006-08-07 16:13:10,954 DEBUG [?:?] : enter
EntityEnclosingMethod.hasRequestContent()
2006-08-07 16:13:10,954 DEBUG [?:?] : enter
EntityEnclosingMethod.hasRequestContent()
2006-08-07 16:13:10,954 DEBUG [?:?] : enter
EntityEnclosingMethod.getRequestContentLength()
2006-08-07 16:13:10,954 DEBUG [?:?] : enter
EntityEnclosingMethod.getRequestContentLength()
2006-08-07 16:13:10,955 DEBUG [?:?] : enter
PostMethod.hasRequestContent()
2006-08-07 16:13:10,955 DEBUG [?:?] : enter
PostMethod.hasRequestContent()
2006-08-07 16:13:10,955 DEBUG [?:?] : enter
EntityEnclosingMethod.hasRequestContent()
2006-08-07 16:13:10,955 DEBUG [?:?] : enter
EntityEnclosingMethod.hasRequestContent()
2006-08-07 16:13:10,956 DEBUG [?:?] : enter
HttpConnection.getRequestOutputStream()
2006-08-07 16:13:10,956 DEBUG [?:?] : enter
HttpConnection.getRequestOutputStream()
2006-08-07 16:13:10,957 DEBUG [?:?] : Request body sent
2006-08-07 16:13:10,957 DEBUG [?:?] : Request body sent
2006-08-07 16:13:10,958 DEBUG [?:?] : enter
HttpConnection.flushRequestOutputStream()
2006-08-07 16:13:10,958 DEBUG [?:?] : enter
HttpConnection.flushRequestOutputStream()
2006-08-07 16:13:10,958 DEBUG [?:?] : enter
HttpMethodBase.readResponse(HttpState, HttpConnection)
2006-08-07 16:13:10,958 DEBUG [?:?] : enter
HttpMethodBase.readResponse(HttpState, HttpConnection)
2006-08-07 16:13:10,958 DEBUG [?:?] : enter
HttpMethodBase.readStatusLine(HttpState, HttpConnection)
2006-08-07 16:13:10,958 DEBUG [?:?] : enter
HttpMethodBase.readStatusLine(HttpState, HttpConnection)
2006-08-07 16:13:10,959 DEBUG [?:?] : enter HttpConnection.readLine()
2006-08-07 16:13:10,959 DEBUG [?:?] : enter HttpConnection.readLine()
2006-08-07 16:13:10,959 DEBUG [?:?] : enter HttpParser.readLine
(InputStream, String)
2006-08-07 16:13:10,959 DEBUG [?:?] : enter HttpParser.readLine
(InputStream, String)
2006-08-07 16:13:10,959 DEBUG [?:?] : enter HttpParser.readRawLine()
2006-08-07 16:13:10,959 DEBUG [?:?] : enter HttpParser.readRawLine()
Patrick Lightbody
Autoriginate, Inc.
503-488-5402
http://www.autoriginate.com
patrick@autoriginate.com
"Intelligent testing made convenient"
On Aug 7, 2006, at 12:29 PM, Patrick Lightbody wrote:
> I've tried using XFire 1.1.1 and 1.2-RC, combined with HttpClient
> 3.0 and 3.1-alpha1. I get the same result, outlined below, which
> causes a complete lockup of a thread. I can't figure out what would
> cause this.
>
> When making a call via XFire (ClientService.getAppLog()), the
> current thread locks up just after printing the following out in
> the logs:
>
> org.apache.commons.httpclient.HttpMethodBase writeRequest
> 100 (continue) read timeout. Resume sending the request
>
> I see that this log comes from an InterruptedIOException here:
>
> http://jakarta.apache.org/commons/httpclient/xref/org/apache/
> commons/httpclient/HttpMethodBase.html#2004
>
> The stack dump of the locked thread is:
>
> "Thread-62" daemon prio=1 tid=0x082602c0 nid=0x51ca runnable
> [0x79926000..0x79926e30]
> at java.net.SocketInputStream.socketRead0(Native Method)
> at java.net.SocketInputStream.read(SocketInputStream.java:129)
> at java.io.BufferedInputStream.fill(BufferedInputStream.java:
> 218)
> at java.io.BufferedInputStream.read(BufferedInputStream.java:
> 235)
> - locked <0x830328c8> (a java.io.BufferedInputStream)
> at org.apache.commons.httpclient.HttpParser.readRawLine
> (HttpParser.java:77)
> at org.apache.commons.httpclient.HttpParser.readLine
> (HttpParser.java:105)
> at org.apache.commons.httpclient.HttpConnection.readLine
> (HttpConnection.java:1115)
> at
> org.apache.commons.httpclient.MultiThreadedHttpConnectionManager
> $HttpConnectionAdapter.readLine
> (MultiThreadedHttpConnectionManager.java:1373)
> at
> org.apache.commons.httpclient.HttpMethodBase.readStatusLine
> (HttpMethodBase.java:1832)
> at org.apache.commons.httpclient.HttpMethodBase.readResponse
> (HttpMethodBase.java:1590)
> at org.apache.commons.httpclient.HttpMethodBase.execute
> (HttpMethodBase.java:995)
> at
> org.apache.commons.httpclient.HttpMethodDirector.executeWithRetry
> (HttpMethodDirector.java:397)
> at
> org.apache.commons.httpclient.HttpMethodDirector.executeMethod
> (HttpMethodDirector.java:170)
> at org.apache.commons.httpclient.HttpClient.executeMethod
> (HttpClient.java:396)
> at
> org.codehaus.xfire.transport.http.CommonsHttpMessageSender.send
> (CommonsHttpMessageSender.java:226)
> at
> org.codehaus.xfire.transport.http.HttpChannel.sendViaClient
> (HttpChannel.java:118)
> at org.codehaus.xfire.transport.http.HttpChannel.send
> (HttpChannel.java:48)
> at org.codehaus.xfire.handler.OutMessageSender.invoke
> (OutMessageSender.java:26)
> at org.codehaus.xfire.handler.HandlerPipeline.invoke
> (HandlerPipeline.java:130)
> at org.codehaus.xfire.client.Invocation.invoke
> (Invocation.java:75)
> at org.codehaus.xfire.client.Client.invoke(Client.java:335)
> at org.codehaus.xfire.client.XFireProxy.handleRequest
> (XFireProxy.java:77)
> at org.codehaus.xfire.client.XFireProxy.invoke
> (XFireProxy.java:57)
> at $Proxy5.getAppLog(Unknown Source)
> at com.hostedqa.model.TestContextImpl.dispose
> (TestContextImpl.java:83)
> at com.hostedqa.model.Suite.playback(Suite.java:85)
> at com.hostedqa.service.PlaybackService.runTest
> (PlaybackService.java:83)
> at com.hostedqa.service.PlaybackService.playSuite
> (PlaybackService.java:48)
> at com.hostedqa.action.project.suite.PlayAction$1.run
> (PlayAction.java:25)
> at java.lang.Thread.run(Thread.java:595)
>
> What's very weird is that I am able to drop a JSP (test.jsp) that
> makes the exact same call and it completes just fine. This tells me
> that there is something environmental about _this_ thread that
> causes HttpClient to do this. The call alone is not the issue.
>
> Also, I might add that the XFire call never makes it to the other
> end (ClientServiceImpl), as I have a print line there that never
> gets invoked. I ran a stack dump on the other side as well, and
> nothing stood out (though it is possible part of the request made
> it through to XFire's Servlet, and then broke and was no longer in
> the active thread dump by the time I forced the dump).
>
> Finally, this request is running over HTTP. I'd really like to
> figure out:
>
> 1) What that log from HttpMethodBase.writeRequest() is all about
> 2) Why there would be a perpetual "pause" in the native method, but
> no actual visible deadlock.
> 3) How to fix this :)
>
> Patrick
>
> Patrick Lightbody
> Autoriginate, Inc.
> 503-488-5402
> http://www.autoriginate.com
> patrick@autoriginate.com
>
> "Intelligent testing made convenient"
>
>
---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-user-unsubscribe@jakarta.apache.org
For additional commands, e-mail: httpclient-user-help@jakarta.apache.org
Re: Lockup in XFire
Posted by Patrick Lightbody <pl...@gmail.com>.
Oleg,
Thanks for the info.
1) I'm looking in to what XFire is doing. Where in HttpClient would
that be set (in case, I need to debug this myself).
2) For the server side, I'm using XFire's HTTP Server, which is
really just Jetty. Do you know if Jetty is supposed to support the
Expect header?
Also, in general, would you expect any firewall or VMware network
routing might cause issues? The environment has a firewall installed
and the connecting is going from the Linux host to a Windows VM
image, so it is going over a virtual network set up by VMware.
Patrick Lightbody
Autoriginate, Inc.
503-488-5402
http://www.autoriginate.com
patrick@autoriginate.com
"Intelligent testing made convenient"
On Aug 7, 2006, at 3:18 PM, Oleg Kalnichevski wrote:
> On Mon, 2006-08-07 at 14:40 -0700, Patrick Lightbody wrote:
>> Oleg,
>> Sure, I understand that the issue is due to a native timeout - but
>> the question is: why?
>>
>
> (1) The only reason for a native socket read to block indefinitely is
> the SO_TIMEOUT value set to zero. Does XFire explicitly set the socket
> timeout value to a positive value?
>
> (2) org.apache.commons.httpclient.HttpMethodBase writeRequest
> 100 (continue) read timeout. Resume sending the request
>
> This message is logged when the target server fails to properly
> respond
> to the "Expect: 100-continue" handshake. When the handshake is
> activated
> HttpClient sends the request header containing the "Expect:
> 100-continue" directive prior to sending the request body and expects
> the target server to respond with status code 100 indicating that
> it is
> okay to proceed with sending the request content. Apparently the
> server
> has issues with the "Expect: 100-continue" handshake or simply
> locks up
> while processing the request header.
>
> Hope this helps.
>
> Oleg
>
>> Like I reported in my initial email, subsequent requests in other
>> threads (coming from test.jsp) work fine.
>>
>> Patrick
>>
>> Patrick Lightbody
>> Autoriginate, Inc.
>> 503-488-5402
>> http://www.autoriginate.com
>> patrick@autoriginate.com
>>
>> "Intelligent testing made convenient"
>>
>>
>> On Aug 7, 2006, at 2:34 PM, Oleg Kalnichevski wrote:
>>
>>> On Mon, 2006-08-07 at 12:29 -0700, Patrick Lightbody wrote:
>>>> I've tried using XFire 1.1.1 and 1.2-RC, combined with
>>>> HttpClient 3.0
>>>> and 3.1-alpha1. I get the same result, outlined below, which
>>>> causes a
>>>> complete lockup of a thread. I can't figure out what would cause
>>>> this.
>>>>
>>>> When making a call via XFire (ClientService.getAppLog()), the
>>>> current
>>>> thread locks up just after printing the following out in the logs:
>>>>
>>>> org.apache.commons.httpclient.HttpMethodBase writeRequest
>>>> 100 (continue) read timeout. Resume sending the request
>>>>
>>>> I see that this log comes from an InterruptedIOException here:
>>>>
>>>> http://jakarta.apache.org/commons/httpclient/xref/org/apache/
>>>> commons/
>>>> httpclient/HttpMethodBase.html#2004
>>>>
>>>> The stack dump of the locked thread is:
>>>>
>>>> "Thread-62" daemon prio=1 tid=0x082602c0 nid=0x51ca runnable
>>>> [0x79926000..0x79926e30]
>>>
>>> Patrick,
>>> As you can see the thread gets blocked in the native socket read
>>> method,
>>> so this is very unlikely to be a threading dead-lock in the
>>> HttpClient
>>> code. Most likely the socket read operation blocks indefinitely
>>> because
>>> socket timeout is not set (SO_TIMEOUT value is set to zero).
>>>
>>> Hope this helps
>>>
>>> Oleg
>>>
>>>
>>>> at java.net.SocketInputStream.socketRead0(Native Method)
>>>> at java.net.SocketInputStream.read(SocketInputStream.java:
>>>> 129)
>>>> at java.io.BufferedInputStream.fill
>>>> (BufferedInputStream.java:
>>>> 218)
>>>> at java.io.BufferedInputStream.read
>>>> (BufferedInputStream.java:
>>>> 235)
>>>> - locked <0x830328c8> (a java.io.BufferedInputStream)
>>>> at org.apache.commons.httpclient.HttpParser.readRawLine
>>>> (HttpParser.java:77)
>>>> at org.apache.commons.httpclient.HttpParser.readLine
>>>> (HttpParser.java:105)
>>>> at org.apache.commons.httpclient.HttpConnection.readLine
>>>> (HttpConnection.java:1115)
>>>> at
>>>> org.apache.commons.httpclient.MultiThreadedHttpConnectionManager
>>>> $HttpConnectionAdapter.readLine
>>>> (MultiThreadedHttpConnectionManager.java:1373)
>>>> at
>>>> org.apache.commons.httpclient.HttpMethodBase.readStatusLine
>>>> (HttpMethodBase.java:1832)
>>>> at
>>>> org.apache.commons.httpclient.HttpMethodBase.readResponse
>>>> (HttpMethodBase.java:1590)
>>>> at org.apache.commons.httpclient.HttpMethodBase.execute
>>>> (HttpMethodBase.java:995)
>>>> at
>>>> org.apache.commons.httpclient.HttpMethodDirector.executeWithRetry
>>>> (HttpMethodDirector.java:397)
>>>> at
>>>> org.apache.commons.httpclient.HttpMethodDirector.executeMethod
>>>> (HttpMethodDirector.java:170)
>>>> at org.apache.commons.httpclient.HttpClient.executeMethod
>>>> (HttpClient.java:396)
>>>> at
>>>> org.codehaus.xfire.transport.http.CommonsHttpMessageSender.send
>>>> (CommonsHttpMessageSender.java:226)
>>>> at
>>>> org.codehaus.xfire.transport.http.HttpChannel.sendViaClient
>>>> (HttpChannel.java:118)
>>>> at org.codehaus.xfire.transport.http.HttpChannel.send
>>>> (HttpChannel.java:48)
>>>> at org.codehaus.xfire.handler.OutMessageSender.invoke
>>>> (OutMessageSender.java:26)
>>>> at org.codehaus.xfire.handler.HandlerPipeline.invoke
>>>> (HandlerPipeline.java:130)
>>>> at org.codehaus.xfire.client.Invocation.invoke
>>>> (Invocation.java:75)
>>>> at org.codehaus.xfire.client.Client.invoke(Client.java:335)
>>>> at org.codehaus.xfire.client.XFireProxy.handleRequest
>>>> (XFireProxy.java:77)
>>>> at org.codehaus.xfire.client.XFireProxy.invoke
>>>> (XFireProxy.java:57)
>>>> at $Proxy5.getAppLog(Unknown Source)
>>>> at com.hostedqa.model.TestContextImpl.dispose
>>>> (TestContextImpl.java:83)
>>>> at com.hostedqa.model.Suite.playback(Suite.java:85)
>>>> at com.hostedqa.service.PlaybackService.runTest
>>>> (PlaybackService.java:83)
>>>> at com.hostedqa.service.PlaybackService.playSuite
>>>> (PlaybackService.java:48)
>>>> at com.hostedqa.action.project.suite.PlayAction$1.run
>>>> (PlayAction.java:25)
>>>> at java.lang.Thread.run(Thread.java:595)
>>>>
>>>> What's very weird is that I am able to drop a JSP (test.jsp) that
>>>> makes the exact same call and it completes just fine. This tells me
>>>> that there is something environmental about _this_ thread that
>>>> causes
>>>> HttpClient to do this. The call alone is not the issue.
>>>>
>>>> Also, I might add that the XFire call never makes it to the
>>>> other end
>>>> (ClientServiceImpl), as I have a print line there that never gets
>>>> invoked. I ran a stack dump on the other side as well, and nothing
>>>> stood out (though it is possible part of the request made it
>>>> through
>>>> to XFire's Servlet, and then broke and was no longer in the active
>>>> thread dump by the time I forced the dump).
>>>>
>>>> Finally, this request is running over HTTP. I'd really like to
>>>> figure
>>>> out:
>>>>
>>>> 1) What that log from HttpMethodBase.writeRequest() is all about
>>>> 2) Why there would be a perpetual "pause" in the native method, but
>>>> no actual visible deadlock.
>>>> 3) How to fix this :)
>>>>
>>>> Patrick
>>>>
>>>> Patrick Lightbody
>>>> Autoriginate, Inc.
>>>> 503-488-5402
>>>> http://www.autoriginate.com
>>>> patrick@autoriginate.com
>>>>
>>>> "Intelligent testing made convenient"
>>>>
>>>>
>>>>
>>>> -------------------------------------------------------------------
>>>> --
>>>> To unsubscribe, e-mail: httpclient-user-
>>>> unsubscribe@jakarta.apache.org
>>>> For additional commands, e-mail: httpclient-user-
>>>> help@jakarta.apache.org
>>>>
>>>>
>>>
>>>
>>> --------------------------------------------------------------------
>>> -
>>> To unsubscribe, e-mail: httpclient-user-
>>> unsubscribe@jakarta.apache.org
>>> For additional commands, e-mail: httpclient-user-
>>> help@jakarta.apache.org
>>>
>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: httpclient-user-
>> unsubscribe@jakarta.apache.org
>> For additional commands, e-mail: httpclient-user-
>> help@jakarta.apache.org
>>
>>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: httpclient-user-unsubscribe@jakarta.apache.org
> For additional commands, e-mail: httpclient-user-
> help@jakarta.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-user-unsubscribe@jakarta.apache.org
For additional commands, e-mail: httpclient-user-help@jakarta.apache.org
Re: Lockup in XFire
Posted by Patrick Lightbody <pl...@gmail.com>.
Oleg, Roland,
As suggested by Roland, Connection: Close fixed the problem. It had
the same effect on the wire communication as if a new HttpClient were
used for each request. So, I'm not sure what the issue was exactly,
but keep-alive isn't that important for me right now, so I've got a
solution. I'll talk to the Jetty guys to see if we can figure the
root cause out later.
Thanks for the tips!
Patrick Lightbody
Autoriginate, Inc.
503-488-5402
http://www.autoriginate.com
patrick@autoriginate.com
"Intelligent testing made convenient"
On Aug 8, 2006, at 3:28 PM, Oleg Kalnichevski wrote:
> On Tue, 2006-08-08 at 10:23 -0700, Patrick Lightbody wrote:
>> More info:
>>
>> netstat on the client that is making the HttpClient call:
>>
>> tcp 0 0 ::ffff:192.168.167.1:48990 ::ffff:
>> 192.168.167.133:8081 ESTABLISHED
>>
>> netstat on the server that is accepting the call:
>>
>> TCP node-x:8081 192.168.167.1:48990 ESTABLISHED
>>
>> Complete stack dump of the JVM that is accepting the call (I see no
>> active socket connection here):
>>
>
> Patrick,
> This goes to support my suspicion that the problem is on the server
> side, as the server is not blocked expecting data from the client but
> rather appears to be blocked/busy doing something else.
>
> ...
>
>> And finally, XFire reuses HttpClient objects. When I forced it not
>> to, everything worked fine. What does that mean?
>>
>
> Feel free to post wire logs of both sessions (one with connection
> reuse
> and one without) and I'll try to see if I can spot anything unusual
>
> Oleg
>
>> Patrick
>>
>>
>> Patrick Lightbody
>> Autoriginate, Inc.
>> 503-488-5402
>> http://www.autoriginate.com
>> patrick@autoriginate.com
>>
>> "Intelligent testing made convenient"
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: httpclient-user-unsubscribe@jakarta.apache.org
> For additional commands, e-mail: httpclient-user-
> help@jakarta.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-user-unsubscribe@jakarta.apache.org
For additional commands, e-mail: httpclient-user-help@jakarta.apache.org
Re: Lockup in XFire
Posted by Oleg Kalnichevski <ol...@apache.org>.
On Tue, 2006-08-08 at 10:23 -0700, Patrick Lightbody wrote:
> More info:
>
> netstat on the client that is making the HttpClient call:
>
> tcp 0 0 ::ffff:192.168.167.1:48990 ::ffff:
> 192.168.167.133:8081 ESTABLISHED
>
> netstat on the server that is accepting the call:
>
> TCP node-x:8081 192.168.167.1:48990 ESTABLISHED
>
> Complete stack dump of the JVM that is accepting the call (I see no
> active socket connection here):
>
Patrick,
This goes to support my suspicion that the problem is on the server
side, as the server is not blocked expecting data from the client but
rather appears to be blocked/busy doing something else.
...
> And finally, XFire reuses HttpClient objects. When I forced it not
> to, everything worked fine. What does that mean?
>
Feel free to post wire logs of both sessions (one with connection reuse
and one without) and I'll try to see if I can spot anything unusual
Oleg
> Patrick
>
>
> Patrick Lightbody
> Autoriginate, Inc.
> 503-488-5402
> http://www.autoriginate.com
> patrick@autoriginate.com
>
> "Intelligent testing made convenient"
---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-user-unsubscribe@jakarta.apache.org
For additional commands, e-mail: httpclient-user-help@jakarta.apache.org
Re: Lockup in XFire
Posted by Patrick Lightbody <pl...@gmail.com>.
Roland,
Thanks, I'll try that. Also might be worth showing the socket logs (I
put a tunnnel in place):
001-input: http://rafb.net/paste/results/Fygxg326.html
001-output: http://rafb.net/paste/results/8hfEo568.html
002-input: http://rafb.net/paste/results/PI9BQU45.html
002-output: empty :P
Any clue what that could mean? Perhaps a buffer overflow?
Patrick Lightbody
Autoriginate, Inc.
503-488-5402
http://www.autoriginate.com
patrick@autoriginate.com
"Intelligent testing made convenient"
On Aug 8, 2006, at 10:51 AM, Roland Weber wrote:
> Hello Patrick,
>
>> And finally, XFire reuses HttpClient objects. When I forced it
>> not to,
>> everything worked fine. What does that mean?
>
> Could be a problem with the server's implementation of connection
> keep-alive.
> By default, HttpClient tries to keep connections open and sends the
> next
> request over the same connection. If the server replies with HTTP/1.1,
> doesn't send a "Connection: close" header, and doesn't close the
> connection,
> the next request will go over that very same connection. But if the
> server
> doesn't read there anymore, you'll see HttpClient just lock up.
>
> If you managed to force XFire into not reusing HttpClient objects,
> maybe
> you can force it to send a "Connection: close" header with the
> request?
> That would disable keep-alive.
>
> cheers,
> Roland
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: httpclient-user-unsubscribe@jakarta.apache.org
> For additional commands, e-mail: httpclient-user-
> help@jakarta.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-user-unsubscribe@jakarta.apache.org
For additional commands, e-mail: httpclient-user-help@jakarta.apache.org
Re: Lockup in XFire
Posted by Roland Weber <ht...@dubioso.net>.
Hello Patrick,
> And finally, XFire reuses HttpClient objects. When I forced it not to,
> everything worked fine. What does that mean?
Could be a problem with the server's implementation of connection keep-alive.
By default, HttpClient tries to keep connections open and sends the next
request over the same connection. If the server replies with HTTP/1.1,
doesn't send a "Connection: close" header, and doesn't close the connection,
the next request will go over that very same connection. But if the server
doesn't read there anymore, you'll see HttpClient just lock up.
If you managed to force XFire into not reusing HttpClient objects, maybe
you can force it to send a "Connection: close" header with the request?
That would disable keep-alive.
cheers,
Roland
---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-user-unsubscribe@jakarta.apache.org
For additional commands, e-mail: httpclient-user-help@jakarta.apache.org
Re: Lockup in XFire
Posted by Patrick Lightbody <pl...@gmail.com>.
I should provide the full netstat, actually. That way you can see the
ESTABLISHED connection and the LISTENING connection, and see that
only the listening one (port 8081) is visible in the stack dump.
Active Connections
Proto Local Address Foreign Address State
TCP node-x:epmap node-x:0 LISTENING
TCP node-x:microsoft-ds node-x:0 LISTENING
TCP node-x:3306 node-x:0 LISTENING
TCP node-x:8081 node-x:0 LISTENING
TCP node-x:9090 node-x:0 LISTENING
TCP node-x:1032 node-x:0 LISTENING
TCP node-x:1038 localhost:1039 ESTABLISHED
TCP node-x:1039 localhost:1038 ESTABLISHED
TCP node-x:5432 node-x:0 LISTENING
TCP node-x:8205 node-x:0 LISTENING
TCP node-x:netbios-ssn node-x:0 LISTENING
TCP node-x:8081 192.168.167.1:48990 ESTABLISHED
UDP node-x:microsoft-ds *:*
UDP node-x:isakmp *:*
UDP node-x:1025 *:*
UDP node-x:4500 *:*
UDP node-x:ntp *:*
UDP node-x:1036 *:*
UDP node-x:1900 *:*
UDP node-x:ntp *:*
UDP node-x:netbios-ns *:*
UDP node-x:netbios-dgm *:*
UDP node-x:1900 *:*
Patrick Lightbody
Autoriginate, Inc.
503-488-5402
http://www.autoriginate.com
patrick@autoriginate.com
"Intelligent testing made convenient"
On Aug 8, 2006, at 10:23 AM, Patrick Lightbody wrote:
> More info:
>
> netstat on the client that is making the HttpClient call:
>
> tcp 0 0 ::ffff:192.168.167.1:48990 ::ffff:
> 192.168.167.133:8081 ESTABLISHED
>
> netstat on the server that is accepting the call:
>
> TCP node-x:8081 192.168.167.1:48990 ESTABLISHED
>
> Complete stack dump of the JVM that is accepting the call (I see no
> active socket connection here):
>
> ---> SocketListener0-0
> java.lang.Object.wait(Native Method)
> org.mortbay.util.ThreadPool$PoolThread.run(ThreadPool.java:522)
>
> ---> Signal Dispatcher
>
> ---> SessionScavenger
> java.lang.Thread.sleep(Native Method)
> org.mortbay.jetty.servlet.AbstractSessionManager
> $SessionScavenger.run(Abstra
> ctSessionManager.java:587)
>
> ---> Thread-9
> java.io.FileInputStream.readBytes(Native Method)
> java.io.FileInputStream.read(FileInputStream.java:177)
> org.apache.tools.ant.taskdefs.StreamPumper.run
> (StreamPumper.java:90)
> java.lang.Thread.run(Thread.java:595)
>
> ---> Finalizer
> java.lang.Object.wait(Native Method)
> java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:116)
> java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:132)
> java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)
>
> ---> Reference Handler
> java.lang.Object.wait(Native Method)
> java.lang.Object.wait(Object.java:474)
> java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
>
> ---> Thread-8
> java.io.FileInputStream.readBytes(Native Method)
> java.io.FileInputStream.read(FileInputStream.java:194)
> java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
> java.io.BufferedInputStream.read1(BufferedInputStream.java:256)
> java.io.BufferedInputStream.read(BufferedInputStream.java:313)
> java.io.FilterInputStream.read(FilterInputStream.java:90)
> org.apache.tools.ant.taskdefs.StreamPumper.run
> (StreamPumper.java:90)
> java.lang.Thread.run(Thread.java:595)
>
> ---> Acceptor ServerSocket[addr=0.0.0.0/0.0.0.0,port=0,localport=8081]
> java.net.PlainSocketImpl.socketAccept(Native Method)
> java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384)
> java.net.ServerSocket.implAccept(ServerSocket.java:450)
> java.net.ServerSocket.accept(ServerSocket.java:421)
> org.mortbay.util.ThreadedServer.acceptSocket
> (ThreadedServer.java:432)
> org.mortbay.util.ThreadedServer$Acceptor.run
> (ThreadedServer.java:634)
>
> ---> Thread-7
> java.lang.ProcessImpl.waitFor(Native Method)
> org.apache.tools.ant.taskdefs.Execute.waitFor(Execute.java:539)
> org.apache.tools.ant.taskdefs.Execute.execute(Execute.java:471)
> org.apache.tools.ant.taskdefs.Java.fork(Java.java:751)
> org.apache.tools.ant.taskdefs.Java.executeJava(Java.java:171)
> org.apache.tools.ant.taskdefs.Java.execute(Java.java:84)
>
> org.codehaus.cargo.container.internal.AntContainerExecutorThread.run
> (AntCont
> ainerExecutorThread.java:50)
>
> ---> DestroyJavaVM
>
> ---> MultiThreadedHttpConnectionManager cleanup
> java.lang.Object.wait(Native Method)
> java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:116)
> org.apache.commons.httpclient.MultiThreadedHttpConnectionManager
> $ReferenceQu
> eueThread.run(Unknown Source)
>
> ---> Thread-1
> java.lang.Thread.dumpThreads(Native Method)
> java.lang.Thread.getAllStackTraces(Thread.java:1434)
> com.hostedqa.utils.ThreadUtils.stackDump(ThreadUtils.java:29)
> com.hostedqa.client.App$1.run(App.java:43)
> java.lang.Thread.run(Thread.java:595)
>
> ---> SocketListener0-1
> java.lang.Object.wait(Native Method)
> org.mortbay.util.ThreadPool$PoolThread.run(ThreadPool.java:522)
>
> And finally, XFire reuses HttpClient objects. When I forced it not
> to, everything worked fine. What does that mean?
>
> Patrick
>
>
> Patrick Lightbody
> Autoriginate, Inc.
> 503-488-5402
> http://www.autoriginate.com
> patrick@autoriginate.com
>
> "Intelligent testing made convenient"
>
>
> On Aug 8, 2006, at 1:43 AM, Oleg Kalnichevski wrote:
>
>> On Mon, 2006-08-07 at 18:10 -0700, Patrick Lightbody wrote:
>>> On Aug 7, 2006, at 3:18 PM, Oleg Kalnichevski wrote:
>>>
>>>> On Mon, 2006-08-07 at 14:40 -0700, Patrick Lightbody wrote:
>>>>> Oleg,
>>>>> Sure, I understand that the issue is due to a native timeout - but
>>>>> the question is: why?
>>>>>
>>>>
>>>> (1) The only reason for a native socket read to block
>>>> indefinitely is
>>>> the SO_TIMEOUT value set to zero. Does XFire explicitly set the
>>>> socket
>>>> timeout value to a positive value?
>>>
>>> No, XFire does not. I tried setting it and that didn't produce the
>>> desireable affect, as I have several requests that I want to take up
>>> to several minutes to respond. I think an indefinite time is fine
>>> (which the default, which is what I was using). My issue isn't that
>>> the timeout is set to 0, but that the connection isn't proceeding
>>> like it should be.
>>
>> The connection is not proceeding because apparently the server is not
>> sending any data.
>>
>>> Specifically, on the server side, I have done a
>>> stack dump and the only thing related to sockets there is this:
>>>
>>> ---> Acceptor ServerSocket
>>> [addr=0.0.0.0/0.0.0.0,port=0,localport=8081]
>>> java.net.PlainSocketImpl.socketAccept(Native Method)
>>> java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384)
>>> java.net.ServerSocket.implAccept(ServerSocket.java:450)
>>> java.net.ServerSocket.accept(ServerSocket.java:421)
>>> org.mortbay.util.ThreadedServer.acceptSocket
>>> (ThreadedServer.java:
>>> 432)
>>> org.mortbay.util.ThreadedServer$Acceptor.run
>>> (ThreadedServer.java:
>>> 634)
>>>
>>> Which clearly is not related to the other open socket.
>>>
>>
>> Are there any other threads not related to sockets? The server may
>> stop
>> responding on a connection if the connection thread gets dead-
>> locked on
>> a mutex or enters an infinite loop.
>>
>>> So I'm back to my original problem: why is the client stuck in the
>>> native state while the server has no record of it? And why does it
>>> only happen for that one request in those exact steps that I
>>> execute.
>>> I should also add that I have done a netstat call at the time, and
>>> got back:
>>>
>>> [hostedqa-j2ee@autoriginate01 webapps]$ netstat -a --numeric-port |
>>> grep 8081
>>> tcp 1 0 ::ffff:192.168.167.1:58125 ::ffff:
>>> 192.168.167.129:8081 CLOSE_WAIT
>>>
>>> Any other ideas? I'm really at a loss here :(
>>>
>>
>> As far as I am concerned there's nothing wrong in how HttpClient is
>> behaving. It blocks indefinitely in the native socket read because
>> this
>> is precisely what it has been instructed to do. In my opinion the
>> problem is on the server side.
>>
>> Just in case consider upgrading the JVM you are using both client and
>> server side to the latest patch level, and consider using a different
>> version of Jetty or a different servlet engine to see if that
>> makes any
>> difference
>>
>> Oleg
>>
>>
>>> Patrick
>>>
>>>
>>>> (2) org.apache.commons.httpclient.HttpMethodBase writeRequest
>>>> 100 (continue) read timeout. Resume sending the request
>>>>
>>>> This message is logged when the target server fails to properly
>>>> respond
>>>> to the "Expect: 100-continue" handshake. When the handshake is
>>>> activated
>>>> HttpClient sends the request header containing the "Expect:
>>>> 100-continue" directive prior to sending the request body and
>>>> expects
>>>> the target server to respond with status code 100 indicating that
>>>> it is
>>>> okay to proceed with sending the request content. Apparently the
>>>> server
>>>> has issues with the "Expect: 100-continue" handshake or simply
>>>> locks up
>>>> while processing the request header.
>>>>
>>>
>>> I turned off this feature and the INFO log goes away, but the
>>> lock up
>>> still occurs. So I don't think this is related.
>>>
>>>> Hope this helps.
>>>>
>>>> Oleg
>>>>
>>>>> Like I reported in my initial email, subsequent requests in other
>>>>> threads (coming from test.jsp) work fine.
>>>>>
>>>>> Patrick
>>>>>
>>>>> Patrick Lightbody
>>>>> Autoriginate, Inc.
>>>>> 503-488-5402
>>>>> http://www.autoriginate.com
>>>>> patrick@autoriginate.com
>>>>>
>>>>> "Intelligent testing made convenient"
>>>>>
>>>>>
>>>>> On Aug 7, 2006, at 2:34 PM, Oleg Kalnichevski wrote:
>>>>>
>>>>>> On Mon, 2006-08-07 at 12:29 -0700, Patrick Lightbody wrote:
>>>>>>> I've tried using XFire 1.1.1 and 1.2-RC, combined with
>>>>>>> HttpClient 3.0
>>>>>>> and 3.1-alpha1. I get the same result, outlined below, which
>>>>>>> causes a
>>>>>>> complete lockup of a thread. I can't figure out what would cause
>>>>>>> this.
>>>>>>>
>>>>>>> When making a call via XFire (ClientService.getAppLog()), the
>>>>>>> current
>>>>>>> thread locks up just after printing the following out in the
>>>>>>> logs:
>>>>>>>
>>>>>>> org.apache.commons.httpclient.HttpMethodBase writeRequest
>>>>>>> 100 (continue) read timeout. Resume sending the request
>>>>>>>
>>>>>>> I see that this log comes from an InterruptedIOException here:
>>>>>>>
>>>>>>> http://jakarta.apache.org/commons/httpclient/xref/org/apache/
>>>>>>> commons/
>>>>>>> httpclient/HttpMethodBase.html#2004
>>>>>>>
>>>>>>> The stack dump of the locked thread is:
>>>>>>>
>>>>>>> "Thread-62" daemon prio=1 tid=0x082602c0 nid=0x51ca runnable
>>>>>>> [0x79926000..0x79926e30]
>>>>>>
>>>>>> Patrick,
>>>>>> As you can see the thread gets blocked in the native socket read
>>>>>> method,
>>>>>> so this is very unlikely to be a threading dead-lock in the
>>>>>> HttpClient
>>>>>> code. Most likely the socket read operation blocks indefinitely
>>>>>> because
>>>>>> socket timeout is not set (SO_TIMEOUT value is set to zero).
>>>>>>
>>>>>> Hope this helps
>>>>>>
>>>>>> Oleg
>>>>>>
>>>>>>
>>>>>>> at java.net.SocketInputStream.socketRead0(Native Method)
>>>>>>> at java.net.SocketInputStream.read
>>>>>>> (SocketInputStream.java:
>>>>>>> 129)
>>>>>>> at java.io.BufferedInputStream.fill
>>>>>>> (BufferedInputStream.java:
>>>>>>> 218)
>>>>>>> at java.io.BufferedInputStream.read
>>>>>>> (BufferedInputStream.java:
>>>>>>> 235)
>>>>>>> - locked <0x830328c8> (a java.io.BufferedInputStream)
>>>>>>> at org.apache.commons.httpclient.HttpParser.readRawLine
>>>>>>> (HttpParser.java:77)
>>>>>>> at org.apache.commons.httpclient.HttpParser.readLine
>>>>>>> (HttpParser.java:105)
>>>>>>> at org.apache.commons.httpclient.HttpConnection.readLine
>>>>>>> (HttpConnection.java:1115)
>>>>>>> at
>>>>>>> org.apache.commons.httpclient.MultiThreadedHttpConnectionManager
>>>>>>> $HttpConnectionAdapter.readLine
>>>>>>> (MultiThreadedHttpConnectionManager.java:1373)
>>>>>>> at
>>>>>>> org.apache.commons.httpclient.HttpMethodBase.readStatusLine
>>>>>>> (HttpMethodBase.java:1832)
>>>>>>> at
>>>>>>> org.apache.commons.httpclient.HttpMethodBase.readResponse
>>>>>>> (HttpMethodBase.java:1590)
>>>>>>> at org.apache.commons.httpclient.HttpMethodBase.execute
>>>>>>> (HttpMethodBase.java:995)
>>>>>>> at
>>>>>>> org.apache.commons.httpclient.HttpMethodDirector.executeWithRetr
>>>>>>> y
>>>>>>> (HttpMethodDirector.java:397)
>>>>>>> at
>>>>>>> org.apache.commons.httpclient.HttpMethodDirector.executeMethod
>>>>>>> (HttpMethodDirector.java:170)
>>>>>>> at
>>>>>>> org.apache.commons.httpclient.HttpClient.executeMethod
>>>>>>> (HttpClient.java:396)
>>>>>>> at
>>>>>>> org.codehaus.xfire.transport.http.CommonsHttpMessageSender.send
>>>>>>> (CommonsHttpMessageSender.java:226)
>>>>>>> at
>>>>>>> org.codehaus.xfire.transport.http.HttpChannel.sendViaClient
>>>>>>> (HttpChannel.java:118)
>>>>>>> at org.codehaus.xfire.transport.http.HttpChannel.send
>>>>>>> (HttpChannel.java:48)
>>>>>>> at org.codehaus.xfire.handler.OutMessageSender.invoke
>>>>>>> (OutMessageSender.java:26)
>>>>>>> at org.codehaus.xfire.handler.HandlerPipeline.invoke
>>>>>>> (HandlerPipeline.java:130)
>>>>>>> at org.codehaus.xfire.client.Invocation.invoke
>>>>>>> (Invocation.java:75)
>>>>>>> at org.codehaus.xfire.client.Client.invoke
>>>>>>> (Client.java:335)
>>>>>>> at org.codehaus.xfire.client.XFireProxy.handleRequest
>>>>>>> (XFireProxy.java:77)
>>>>>>> at org.codehaus.xfire.client.XFireProxy.invoke
>>>>>>> (XFireProxy.java:57)
>>>>>>> at $Proxy5.getAppLog(Unknown Source)
>>>>>>> at com.hostedqa.model.TestContextImpl.dispose
>>>>>>> (TestContextImpl.java:83)
>>>>>>> at com.hostedqa.model.Suite.playback(Suite.java:85)
>>>>>>> at com.hostedqa.service.PlaybackService.runTest
>>>>>>> (PlaybackService.java:83)
>>>>>>> at com.hostedqa.service.PlaybackService.playSuite
>>>>>>> (PlaybackService.java:48)
>>>>>>> at com.hostedqa.action.project.suite.PlayAction$1.run
>>>>>>> (PlayAction.java:25)
>>>>>>> at java.lang.Thread.run(Thread.java:595)
>>>>>>>
>>>>>>> What's very weird is that I am able to drop a JSP (test.jsp)
>>>>>>> that
>>>>>>> makes the exact same call and it completes just fine. This
>>>>>>> tells me
>>>>>>> that there is something environmental about _this_ thread that
>>>>>>> causes
>>>>>>> HttpClient to do this. The call alone is not the issue.
>>>>>>>
>>>>>>> Also, I might add that the XFire call never makes it to the
>>>>>>> other end
>>>>>>> (ClientServiceImpl), as I have a print line there that never
>>>>>>> gets
>>>>>>> invoked. I ran a stack dump on the other side as well, and
>>>>>>> nothing
>>>>>>> stood out (though it is possible part of the request made it
>>>>>>> through
>>>>>>> to XFire's Servlet, and then broke and was no longer in the
>>>>>>> active
>>>>>>> thread dump by the time I forced the dump).
>>>>>>>
>>>>>>> Finally, this request is running over HTTP. I'd really like to
>>>>>>> figure
>>>>>>> out:
>>>>>>>
>>>>>>> 1) What that log from HttpMethodBase.writeRequest() is all about
>>>>>>> 2) Why there would be a perpetual "pause" in the native
>>>>>>> method, but
>>>>>>> no actual visible deadlock.
>>>>>>> 3) How to fix this :)
>>>>>>>
>>>>>>> Patrick
>>>>>>>
>>>>>>> Patrick Lightbody
>>>>>>> Autoriginate, Inc.
>>>>>>> 503-488-5402
>>>>>>> http://www.autoriginate.com
>>>>>>> patrick@autoriginate.com
>>>>>>>
>>>>>>> "Intelligent testing made convenient"
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>> ----------------------------------------------------------------
>>>>>>> ---
>>>>>>> --
>>>>>>> To unsubscribe, e-mail: httpclient-user-
>>>>>>> unsubscribe@jakarta.apache.org
>>>>>>> For additional commands, e-mail: httpclient-user-
>>>>>>> help@jakarta.apache.org
>>>>>>>
>>>>>>>
>>>>>>
>>>>>>
>>>>>> -----------------------------------------------------------------
>>>>>> ---
>>>>>> -
>>>>>> To unsubscribe, e-mail: httpclient-user-
>>>>>> unsubscribe@jakarta.apache.org
>>>>>> For additional commands, e-mail: httpclient-user-
>>>>>> help@jakarta.apache.org
>>>>>>
>>>>>
>>>>>
>>>>> ------------------------------------------------------------------
>>>>> ---
>>>>> To unsubscribe, e-mail: httpclient-user-
>>>>> unsubscribe@jakarta.apache.org
>>>>> For additional commands, e-mail: httpclient-user-
>>>>> help@jakarta.apache.org
>>>>>
>>>>>
>>>>
>>>>
>>>> -------------------------------------------------------------------
>>>> --
>>>> To unsubscribe, e-mail: httpclient-user-
>>>> unsubscribe@jakarta.apache.org
>>>> For additional commands, e-mail: httpclient-user-
>>>> help@jakarta.apache.org
>>>>
>>>
>>>
>>> --------------------------------------------------------------------
>>> -
>>> To unsubscribe, e-mail: httpclient-user-
>>> unsubscribe@jakarta.apache.org
>>> For additional commands, e-mail: httpclient-user-
>>> help@jakarta.apache.org
>>>
>>>
>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: httpclient-user-
>> unsubscribe@jakarta.apache.org
>> For additional commands, e-mail: httpclient-user-
>> help@jakarta.apache.org
>>
>
---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-user-unsubscribe@jakarta.apache.org
For additional commands, e-mail: httpclient-user-help@jakarta.apache.org
Re: Lockup in XFire
Posted by Patrick Lightbody <pl...@gmail.com>.
More info:
netstat on the client that is making the HttpClient call:
tcp 0 0 ::ffff:192.168.167.1:48990 ::ffff:
192.168.167.133:8081 ESTABLISHED
netstat on the server that is accepting the call:
TCP node-x:8081 192.168.167.1:48990 ESTABLISHED
Complete stack dump of the JVM that is accepting the call (I see no
active socket connection here):
---> SocketListener0-0
java.lang.Object.wait(Native Method)
org.mortbay.util.ThreadPool$PoolThread.run(ThreadPool.java:522)
---> Signal Dispatcher
---> SessionScavenger
java.lang.Thread.sleep(Native Method)
org.mortbay.jetty.servlet.AbstractSessionManager
$SessionScavenger.run(Abstra
ctSessionManager.java:587)
---> Thread-9
java.io.FileInputStream.readBytes(Native Method)
java.io.FileInputStream.read(FileInputStream.java:177)
org.apache.tools.ant.taskdefs.StreamPumper.run(StreamPumper.java:
90)
java.lang.Thread.run(Thread.java:595)
---> Finalizer
java.lang.Object.wait(Native Method)
java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:116)
java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:132)
java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)
---> Reference Handler
java.lang.Object.wait(Native Method)
java.lang.Object.wait(Object.java:474)
java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
---> Thread-8
java.io.FileInputStream.readBytes(Native Method)
java.io.FileInputStream.read(FileInputStream.java:194)
java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
java.io.BufferedInputStream.read1(BufferedInputStream.java:256)
java.io.BufferedInputStream.read(BufferedInputStream.java:313)
java.io.FilterInputStream.read(FilterInputStream.java:90)
org.apache.tools.ant.taskdefs.StreamPumper.run(StreamPumper.java:
90)
java.lang.Thread.run(Thread.java:595)
---> Acceptor ServerSocket[addr=0.0.0.0/0.0.0.0,port=0,localport=8081]
java.net.PlainSocketImpl.socketAccept(Native Method)
java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384)
java.net.ServerSocket.implAccept(ServerSocket.java:450)
java.net.ServerSocket.accept(ServerSocket.java:421)
org.mortbay.util.ThreadedServer.acceptSocket(ThreadedServer.java:
432)
org.mortbay.util.ThreadedServer$Acceptor.run(ThreadedServer.java:
634)
---> Thread-7
java.lang.ProcessImpl.waitFor(Native Method)
org.apache.tools.ant.taskdefs.Execute.waitFor(Execute.java:539)
org.apache.tools.ant.taskdefs.Execute.execute(Execute.java:471)
org.apache.tools.ant.taskdefs.Java.fork(Java.java:751)
org.apache.tools.ant.taskdefs.Java.executeJava(Java.java:171)
org.apache.tools.ant.taskdefs.Java.execute(Java.java:84)
org.codehaus.cargo.container.internal.AntContainerExecutorThread.run
(AntCont
ainerExecutorThread.java:50)
---> DestroyJavaVM
---> MultiThreadedHttpConnectionManager cleanup
java.lang.Object.wait(Native Method)
java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:116)
org.apache.commons.httpclient.MultiThreadedHttpConnectionManager
$ReferenceQu
eueThread.run(Unknown Source)
---> Thread-1
java.lang.Thread.dumpThreads(Native Method)
java.lang.Thread.getAllStackTraces(Thread.java:1434)
com.hostedqa.utils.ThreadUtils.stackDump(ThreadUtils.java:29)
com.hostedqa.client.App$1.run(App.java:43)
java.lang.Thread.run(Thread.java:595)
---> SocketListener0-1
java.lang.Object.wait(Native Method)
org.mortbay.util.ThreadPool$PoolThread.run(ThreadPool.java:522)
And finally, XFire reuses HttpClient objects. When I forced it not
to, everything worked fine. What does that mean?
Patrick
Patrick Lightbody
Autoriginate, Inc.
503-488-5402
http://www.autoriginate.com
patrick@autoriginate.com
"Intelligent testing made convenient"
On Aug 8, 2006, at 1:43 AM, Oleg Kalnichevski wrote:
> On Mon, 2006-08-07 at 18:10 -0700, Patrick Lightbody wrote:
>> On Aug 7, 2006, at 3:18 PM, Oleg Kalnichevski wrote:
>>
>>> On Mon, 2006-08-07 at 14:40 -0700, Patrick Lightbody wrote:
>>>> Oleg,
>>>> Sure, I understand that the issue is due to a native timeout - but
>>>> the question is: why?
>>>>
>>>
>>> (1) The only reason for a native socket read to block
>>> indefinitely is
>>> the SO_TIMEOUT value set to zero. Does XFire explicitly set the
>>> socket
>>> timeout value to a positive value?
>>
>> No, XFire does not. I tried setting it and that didn't produce the
>> desireable affect, as I have several requests that I want to take up
>> to several minutes to respond. I think an indefinite time is fine
>> (which the default, which is what I was using). My issue isn't that
>> the timeout is set to 0, but that the connection isn't proceeding
>> like it should be.
>
> The connection is not proceeding because apparently the server is not
> sending any data.
>
>> Specifically, on the server side, I have done a
>> stack dump and the only thing related to sockets there is this:
>>
>> ---> Acceptor ServerSocket
>> [addr=0.0.0.0/0.0.0.0,port=0,localport=8081]
>> java.net.PlainSocketImpl.socketAccept(Native Method)
>> java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384)
>> java.net.ServerSocket.implAccept(ServerSocket.java:450)
>> java.net.ServerSocket.accept(ServerSocket.java:421)
>> org.mortbay.util.ThreadedServer.acceptSocket
>> (ThreadedServer.java:
>> 432)
>> org.mortbay.util.ThreadedServer$Acceptor.run
>> (ThreadedServer.java:
>> 634)
>>
>> Which clearly is not related to the other open socket.
>>
>
> Are there any other threads not related to sockets? The server may
> stop
> responding on a connection if the connection thread gets dead-
> locked on
> a mutex or enters an infinite loop.
>
>> So I'm back to my original problem: why is the client stuck in the
>> native state while the server has no record of it? And why does it
>> only happen for that one request in those exact steps that I execute.
>> I should also add that I have done a netstat call at the time, and
>> got back:
>>
>> [hostedqa-j2ee@autoriginate01 webapps]$ netstat -a --numeric-port |
>> grep 8081
>> tcp 1 0 ::ffff:192.168.167.1:58125 ::ffff:
>> 192.168.167.129:8081 CLOSE_WAIT
>>
>> Any other ideas? I'm really at a loss here :(
>>
>
> As far as I am concerned there's nothing wrong in how HttpClient is
> behaving. It blocks indefinitely in the native socket read because
> this
> is precisely what it has been instructed to do. In my opinion the
> problem is on the server side.
>
> Just in case consider upgrading the JVM you are using both client and
> server side to the latest patch level, and consider using a different
> version of Jetty or a different servlet engine to see if that makes
> any
> difference
>
> Oleg
>
>
>> Patrick
>>
>>
>>> (2) org.apache.commons.httpclient.HttpMethodBase writeRequest
>>> 100 (continue) read timeout. Resume sending the request
>>>
>>> This message is logged when the target server fails to properly
>>> respond
>>> to the "Expect: 100-continue" handshake. When the handshake is
>>> activated
>>> HttpClient sends the request header containing the "Expect:
>>> 100-continue" directive prior to sending the request body and
>>> expects
>>> the target server to respond with status code 100 indicating that
>>> it is
>>> okay to proceed with sending the request content. Apparently the
>>> server
>>> has issues with the "Expect: 100-continue" handshake or simply
>>> locks up
>>> while processing the request header.
>>>
>>
>> I turned off this feature and the INFO log goes away, but the lock up
>> still occurs. So I don't think this is related.
>>
>>> Hope this helps.
>>>
>>> Oleg
>>>
>>>> Like I reported in my initial email, subsequent requests in other
>>>> threads (coming from test.jsp) work fine.
>>>>
>>>> Patrick
>>>>
>>>> Patrick Lightbody
>>>> Autoriginate, Inc.
>>>> 503-488-5402
>>>> http://www.autoriginate.com
>>>> patrick@autoriginate.com
>>>>
>>>> "Intelligent testing made convenient"
>>>>
>>>>
>>>> On Aug 7, 2006, at 2:34 PM, Oleg Kalnichevski wrote:
>>>>
>>>>> On Mon, 2006-08-07 at 12:29 -0700, Patrick Lightbody wrote:
>>>>>> I've tried using XFire 1.1.1 and 1.2-RC, combined with
>>>>>> HttpClient 3.0
>>>>>> and 3.1-alpha1. I get the same result, outlined below, which
>>>>>> causes a
>>>>>> complete lockup of a thread. I can't figure out what would cause
>>>>>> this.
>>>>>>
>>>>>> When making a call via XFire (ClientService.getAppLog()), the
>>>>>> current
>>>>>> thread locks up just after printing the following out in the
>>>>>> logs:
>>>>>>
>>>>>> org.apache.commons.httpclient.HttpMethodBase writeRequest
>>>>>> 100 (continue) read timeout. Resume sending the request
>>>>>>
>>>>>> I see that this log comes from an InterruptedIOException here:
>>>>>>
>>>>>> http://jakarta.apache.org/commons/httpclient/xref/org/apache/
>>>>>> commons/
>>>>>> httpclient/HttpMethodBase.html#2004
>>>>>>
>>>>>> The stack dump of the locked thread is:
>>>>>>
>>>>>> "Thread-62" daemon prio=1 tid=0x082602c0 nid=0x51ca runnable
>>>>>> [0x79926000..0x79926e30]
>>>>>
>>>>> Patrick,
>>>>> As you can see the thread gets blocked in the native socket read
>>>>> method,
>>>>> so this is very unlikely to be a threading dead-lock in the
>>>>> HttpClient
>>>>> code. Most likely the socket read operation blocks indefinitely
>>>>> because
>>>>> socket timeout is not set (SO_TIMEOUT value is set to zero).
>>>>>
>>>>> Hope this helps
>>>>>
>>>>> Oleg
>>>>>
>>>>>
>>>>>> at java.net.SocketInputStream.socketRead0(Native Method)
>>>>>> at java.net.SocketInputStream.read
>>>>>> (SocketInputStream.java:
>>>>>> 129)
>>>>>> at java.io.BufferedInputStream.fill
>>>>>> (BufferedInputStream.java:
>>>>>> 218)
>>>>>> at java.io.BufferedInputStream.read
>>>>>> (BufferedInputStream.java:
>>>>>> 235)
>>>>>> - locked <0x830328c8> (a java.io.BufferedInputStream)
>>>>>> at org.apache.commons.httpclient.HttpParser.readRawLine
>>>>>> (HttpParser.java:77)
>>>>>> at org.apache.commons.httpclient.HttpParser.readLine
>>>>>> (HttpParser.java:105)
>>>>>> at org.apache.commons.httpclient.HttpConnection.readLine
>>>>>> (HttpConnection.java:1115)
>>>>>> at
>>>>>> org.apache.commons.httpclient.MultiThreadedHttpConnectionManager
>>>>>> $HttpConnectionAdapter.readLine
>>>>>> (MultiThreadedHttpConnectionManager.java:1373)
>>>>>> at
>>>>>> org.apache.commons.httpclient.HttpMethodBase.readStatusLine
>>>>>> (HttpMethodBase.java:1832)
>>>>>> at
>>>>>> org.apache.commons.httpclient.HttpMethodBase.readResponse
>>>>>> (HttpMethodBase.java:1590)
>>>>>> at org.apache.commons.httpclient.HttpMethodBase.execute
>>>>>> (HttpMethodBase.java:995)
>>>>>> at
>>>>>> org.apache.commons.httpclient.HttpMethodDirector.executeWithRetry
>>>>>> (HttpMethodDirector.java:397)
>>>>>> at
>>>>>> org.apache.commons.httpclient.HttpMethodDirector.executeMethod
>>>>>> (HttpMethodDirector.java:170)
>>>>>> at org.apache.commons.httpclient.HttpClient.executeMethod
>>>>>> (HttpClient.java:396)
>>>>>> at
>>>>>> org.codehaus.xfire.transport.http.CommonsHttpMessageSender.send
>>>>>> (CommonsHttpMessageSender.java:226)
>>>>>> at
>>>>>> org.codehaus.xfire.transport.http.HttpChannel.sendViaClient
>>>>>> (HttpChannel.java:118)
>>>>>> at org.codehaus.xfire.transport.http.HttpChannel.send
>>>>>> (HttpChannel.java:48)
>>>>>> at org.codehaus.xfire.handler.OutMessageSender.invoke
>>>>>> (OutMessageSender.java:26)
>>>>>> at org.codehaus.xfire.handler.HandlerPipeline.invoke
>>>>>> (HandlerPipeline.java:130)
>>>>>> at org.codehaus.xfire.client.Invocation.invoke
>>>>>> (Invocation.java:75)
>>>>>> at org.codehaus.xfire.client.Client.invoke(Client.java:
>>>>>> 335)
>>>>>> at org.codehaus.xfire.client.XFireProxy.handleRequest
>>>>>> (XFireProxy.java:77)
>>>>>> at org.codehaus.xfire.client.XFireProxy.invoke
>>>>>> (XFireProxy.java:57)
>>>>>> at $Proxy5.getAppLog(Unknown Source)
>>>>>> at com.hostedqa.model.TestContextImpl.dispose
>>>>>> (TestContextImpl.java:83)
>>>>>> at com.hostedqa.model.Suite.playback(Suite.java:85)
>>>>>> at com.hostedqa.service.PlaybackService.runTest
>>>>>> (PlaybackService.java:83)
>>>>>> at com.hostedqa.service.PlaybackService.playSuite
>>>>>> (PlaybackService.java:48)
>>>>>> at com.hostedqa.action.project.suite.PlayAction$1.run
>>>>>> (PlayAction.java:25)
>>>>>> at java.lang.Thread.run(Thread.java:595)
>>>>>>
>>>>>> What's very weird is that I am able to drop a JSP (test.jsp) that
>>>>>> makes the exact same call and it completes just fine. This
>>>>>> tells me
>>>>>> that there is something environmental about _this_ thread that
>>>>>> causes
>>>>>> HttpClient to do this. The call alone is not the issue.
>>>>>>
>>>>>> Also, I might add that the XFire call never makes it to the
>>>>>> other end
>>>>>> (ClientServiceImpl), as I have a print line there that never gets
>>>>>> invoked. I ran a stack dump on the other side as well, and
>>>>>> nothing
>>>>>> stood out (though it is possible part of the request made it
>>>>>> through
>>>>>> to XFire's Servlet, and then broke and was no longer in the
>>>>>> active
>>>>>> thread dump by the time I forced the dump).
>>>>>>
>>>>>> Finally, this request is running over HTTP. I'd really like to
>>>>>> figure
>>>>>> out:
>>>>>>
>>>>>> 1) What that log from HttpMethodBase.writeRequest() is all about
>>>>>> 2) Why there would be a perpetual "pause" in the native
>>>>>> method, but
>>>>>> no actual visible deadlock.
>>>>>> 3) How to fix this :)
>>>>>>
>>>>>> Patrick
>>>>>>
>>>>>> Patrick Lightbody
>>>>>> Autoriginate, Inc.
>>>>>> 503-488-5402
>>>>>> http://www.autoriginate.com
>>>>>> patrick@autoriginate.com
>>>>>>
>>>>>> "Intelligent testing made convenient"
>>>>>>
>>>>>>
>>>>>>
>>>>>> -----------------------------------------------------------------
>>>>>> --
>>>>>> --
>>>>>> To unsubscribe, e-mail: httpclient-user-
>>>>>> unsubscribe@jakarta.apache.org
>>>>>> For additional commands, e-mail: httpclient-user-
>>>>>> help@jakarta.apache.org
>>>>>>
>>>>>>
>>>>>
>>>>>
>>>>> ------------------------------------------------------------------
>>>>> --
>>>>> -
>>>>> To unsubscribe, e-mail: httpclient-user-
>>>>> unsubscribe@jakarta.apache.org
>>>>> For additional commands, e-mail: httpclient-user-
>>>>> help@jakarta.apache.org
>>>>>
>>>>
>>>>
>>>> -------------------------------------------------------------------
>>>> --
>>>> To unsubscribe, e-mail: httpclient-user-
>>>> unsubscribe@jakarta.apache.org
>>>> For additional commands, e-mail: httpclient-user-
>>>> help@jakarta.apache.org
>>>>
>>>>
>>>
>>>
>>> --------------------------------------------------------------------
>>> -
>>> To unsubscribe, e-mail: httpclient-user-
>>> unsubscribe@jakarta.apache.org
>>> For additional commands, e-mail: httpclient-user-
>>> help@jakarta.apache.org
>>>
>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: httpclient-user-
>> unsubscribe@jakarta.apache.org
>> For additional commands, e-mail: httpclient-user-
>> help@jakarta.apache.org
>>
>>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: httpclient-user-unsubscribe@jakarta.apache.org
> For additional commands, e-mail: httpclient-user-
> help@jakarta.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-user-unsubscribe@jakarta.apache.org
For additional commands, e-mail: httpclient-user-help@jakarta.apache.org
Re: Lockup in XFire
Posted by Patrick Lightbody <pl...@gmail.com>.
>> Specifically, on the server side, I have done a
>> stack dump and the only thing related to sockets there is this:
>>
>> ---> Acceptor ServerSocket
>> [addr=0.0.0.0/0.0.0.0,port=0,localport=8081]
>> java.net.PlainSocketImpl.socketAccept(Native Method)
>> java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384)
>> java.net.ServerSocket.implAccept(ServerSocket.java:450)
>> java.net.ServerSocket.accept(ServerSocket.java:421)
>> org.mortbay.util.ThreadedServer.acceptSocket
>> (ThreadedServer.java:
>> 432)
>> org.mortbay.util.ThreadedServer$Acceptor.run
>> (ThreadedServer.java:
>> 634)
>>
>> Which clearly is not related to the other open socket.
>>
>
> Are there any other threads not related to sockets? The server may
> stop
> responding on a connection if the connection thread gets dead-
> locked on
> a mutex or enters an infinite loop.
>
There are a few other threads, but nothing that seems to tell me
much. I'll get the full stack dump anyway, but I don't have a lot of
hope there is some good info in there.
>> So I'm back to my original problem: why is the client stuck in the
>> native state while the server has no record of it? And why does it
>> only happen for that one request in those exact steps that I execute.
>> I should also add that I have done a netstat call at the time, and
>> got back:
>>
>> [hostedqa-j2ee@autoriginate01 webapps]$ netstat -a --numeric-port |
>> grep 8081
>> tcp 1 0 ::ffff:192.168.167.1:58125 ::ffff:
>> 192.168.167.129:8081 CLOSE_WAIT
>>
>> Any other ideas? I'm really at a loss here :(
>>
>
> As far as I am concerned there's nothing wrong in how HttpClient is
> behaving. It blocks indefinitely in the native socket read because
> this
> is precisely what it has been instructed to do. In my opinion the
> problem is on the server side.
>
> Just in case consider upgrading the JVM you are using both client and
> server side to the latest patch level, and consider using a different
> version of Jetty or a different servlet engine to see if that makes
> any
> difference
I understand that HttpClient is not at "fault" here. But the problem
remains and it is very closely related to HttpClient. So I'm hoping
you can suggest some steps I can follow to track this down.
Re: the JVM versions - both sides are running the latest JDK 1.5
releases from Sun. Something other than Jetty isn't really an option,
but I'll try a different version and see if that helps.
>
> Oleg
>
>
>> Patrick
>>
>>
>>> (2) org.apache.commons.httpclient.HttpMethodBase writeRequest
>>> 100 (continue) read timeout. Resume sending the request
>>>
>>> This message is logged when the target server fails to properly
>>> respond
>>> to the "Expect: 100-continue" handshake. When the handshake is
>>> activated
>>> HttpClient sends the request header containing the "Expect:
>>> 100-continue" directive prior to sending the request body and
>>> expects
>>> the target server to respond with status code 100 indicating that
>>> it is
>>> okay to proceed with sending the request content. Apparently the
>>> server
>>> has issues with the "Expect: 100-continue" handshake or simply
>>> locks up
>>> while processing the request header.
>>>
>>
>> I turned off this feature and the INFO log goes away, but the lock up
>> still occurs. So I don't think this is related.
>>
>>> Hope this helps.
>>>
>>> Oleg
>>>
>>>> Like I reported in my initial email, subsequent requests in other
>>>> threads (coming from test.jsp) work fine.
>>>>
>>>> Patrick
>>>>
>>>> Patrick Lightbody
>>>> Autoriginate, Inc.
>>>> 503-488-5402
>>>> http://www.autoriginate.com
>>>> patrick@autoriginate.com
>>>>
>>>> "Intelligent testing made convenient"
>>>>
>>>>
>>>> On Aug 7, 2006, at 2:34 PM, Oleg Kalnichevski wrote:
>>>>
>>>>> On Mon, 2006-08-07 at 12:29 -0700, Patrick Lightbody wrote:
>>>>>> I've tried using XFire 1.1.1 and 1.2-RC, combined with
>>>>>> HttpClient 3.0
>>>>>> and 3.1-alpha1. I get the same result, outlined below, which
>>>>>> causes a
>>>>>> complete lockup of a thread. I can't figure out what would cause
>>>>>> this.
>>>>>>
>>>>>> When making a call via XFire (ClientService.getAppLog()), the
>>>>>> current
>>>>>> thread locks up just after printing the following out in the
>>>>>> logs:
>>>>>>
>>>>>> org.apache.commons.httpclient.HttpMethodBase writeRequest
>>>>>> 100 (continue) read timeout. Resume sending the request
>>>>>>
>>>>>> I see that this log comes from an InterruptedIOException here:
>>>>>>
>>>>>> http://jakarta.apache.org/commons/httpclient/xref/org/apache/
>>>>>> commons/
>>>>>> httpclient/HttpMethodBase.html#2004
>>>>>>
>>>>>> The stack dump of the locked thread is:
>>>>>>
>>>>>> "Thread-62" daemon prio=1 tid=0x082602c0 nid=0x51ca runnable
>>>>>> [0x79926000..0x79926e30]
>>>>>
>>>>> Patrick,
>>>>> As you can see the thread gets blocked in the native socket read
>>>>> method,
>>>>> so this is very unlikely to be a threading dead-lock in the
>>>>> HttpClient
>>>>> code. Most likely the socket read operation blocks indefinitely
>>>>> because
>>>>> socket timeout is not set (SO_TIMEOUT value is set to zero).
>>>>>
>>>>> Hope this helps
>>>>>
>>>>> Oleg
>>>>>
>>>>>
>>>>>> at java.net.SocketInputStream.socketRead0(Native Method)
>>>>>> at java.net.SocketInputStream.read
>>>>>> (SocketInputStream.java:
>>>>>> 129)
>>>>>> at java.io.BufferedInputStream.fill
>>>>>> (BufferedInputStream.java:
>>>>>> 218)
>>>>>> at java.io.BufferedInputStream.read
>>>>>> (BufferedInputStream.java:
>>>>>> 235)
>>>>>> - locked <0x830328c8> (a java.io.BufferedInputStream)
>>>>>> at org.apache.commons.httpclient.HttpParser.readRawLine
>>>>>> (HttpParser.java:77)
>>>>>> at org.apache.commons.httpclient.HttpParser.readLine
>>>>>> (HttpParser.java:105)
>>>>>> at org.apache.commons.httpclient.HttpConnection.readLine
>>>>>> (HttpConnection.java:1115)
>>>>>> at
>>>>>> org.apache.commons.httpclient.MultiThreadedHttpConnectionManager
>>>>>> $HttpConnectionAdapter.readLine
>>>>>> (MultiThreadedHttpConnectionManager.java:1373)
>>>>>> at
>>>>>> org.apache.commons.httpclient.HttpMethodBase.readStatusLine
>>>>>> (HttpMethodBase.java:1832)
>>>>>> at
>>>>>> org.apache.commons.httpclient.HttpMethodBase.readResponse
>>>>>> (HttpMethodBase.java:1590)
>>>>>> at org.apache.commons.httpclient.HttpMethodBase.execute
>>>>>> (HttpMethodBase.java:995)
>>>>>> at
>>>>>> org.apache.commons.httpclient.HttpMethodDirector.executeWithRetry
>>>>>> (HttpMethodDirector.java:397)
>>>>>> at
>>>>>> org.apache.commons.httpclient.HttpMethodDirector.executeMethod
>>>>>> (HttpMethodDirector.java:170)
>>>>>> at org.apache.commons.httpclient.HttpClient.executeMethod
>>>>>> (HttpClient.java:396)
>>>>>> at
>>>>>> org.codehaus.xfire.transport.http.CommonsHttpMessageSender.send
>>>>>> (CommonsHttpMessageSender.java:226)
>>>>>> at
>>>>>> org.codehaus.xfire.transport.http.HttpChannel.sendViaClient
>>>>>> (HttpChannel.java:118)
>>>>>> at org.codehaus.xfire.transport.http.HttpChannel.send
>>>>>> (HttpChannel.java:48)
>>>>>> at org.codehaus.xfire.handler.OutMessageSender.invoke
>>>>>> (OutMessageSender.java:26)
>>>>>> at org.codehaus.xfire.handler.HandlerPipeline.invoke
>>>>>> (HandlerPipeline.java:130)
>>>>>> at org.codehaus.xfire.client.Invocation.invoke
>>>>>> (Invocation.java:75)
>>>>>> at org.codehaus.xfire.client.Client.invoke(Client.java:
>>>>>> 335)
>>>>>> at org.codehaus.xfire.client.XFireProxy.handleRequest
>>>>>> (XFireProxy.java:77)
>>>>>> at org.codehaus.xfire.client.XFireProxy.invoke
>>>>>> (XFireProxy.java:57)
>>>>>> at $Proxy5.getAppLog(Unknown Source)
>>>>>> at com.hostedqa.model.TestContextImpl.dispose
>>>>>> (TestContextImpl.java:83)
>>>>>> at com.hostedqa.model.Suite.playback(Suite.java:85)
>>>>>> at com.hostedqa.service.PlaybackService.runTest
>>>>>> (PlaybackService.java:83)
>>>>>> at com.hostedqa.service.PlaybackService.playSuite
>>>>>> (PlaybackService.java:48)
>>>>>> at com.hostedqa.action.project.suite.PlayAction$1.run
>>>>>> (PlayAction.java:25)
>>>>>> at java.lang.Thread.run(Thread.java:595)
>>>>>>
>>>>>> What's very weird is that I am able to drop a JSP (test.jsp) that
>>>>>> makes the exact same call and it completes just fine. This
>>>>>> tells me
>>>>>> that there is something environmental about _this_ thread that
>>>>>> causes
>>>>>> HttpClient to do this. The call alone is not the issue.
>>>>>>
>>>>>> Also, I might add that the XFire call never makes it to the
>>>>>> other end
>>>>>> (ClientServiceImpl), as I have a print line there that never gets
>>>>>> invoked. I ran a stack dump on the other side as well, and
>>>>>> nothing
>>>>>> stood out (though it is possible part of the request made it
>>>>>> through
>>>>>> to XFire's Servlet, and then broke and was no longer in the
>>>>>> active
>>>>>> thread dump by the time I forced the dump).
>>>>>>
>>>>>> Finally, this request is running over HTTP. I'd really like to
>>>>>> figure
>>>>>> out:
>>>>>>
>>>>>> 1) What that log from HttpMethodBase.writeRequest() is all about
>>>>>> 2) Why there would be a perpetual "pause" in the native
>>>>>> method, but
>>>>>> no actual visible deadlock.
>>>>>> 3) How to fix this :)
>>>>>>
>>>>>> Patrick
>>>>>>
>>>>>> Patrick Lightbody
>>>>>> Autoriginate, Inc.
>>>>>> 503-488-5402
>>>>>> http://www.autoriginate.com
>>>>>> patrick@autoriginate.com
>>>>>>
>>>>>> "Intelligent testing made convenient"
>>>>>>
>>>>>>
>>>>>>
>>>>>> -----------------------------------------------------------------
>>>>>> --
>>>>>> --
>>>>>> To unsubscribe, e-mail: httpclient-user-
>>>>>> unsubscribe@jakarta.apache.org
>>>>>> For additional commands, e-mail: httpclient-user-
>>>>>> help@jakarta.apache.org
>>>>>>
>>>>>>
>>>>>
>>>>>
>>>>> ------------------------------------------------------------------
>>>>> --
>>>>> -
>>>>> To unsubscribe, e-mail: httpclient-user-
>>>>> unsubscribe@jakarta.apache.org
>>>>> For additional commands, e-mail: httpclient-user-
>>>>> help@jakarta.apache.org
>>>>>
>>>>
>>>>
>>>> -------------------------------------------------------------------
>>>> --
>>>> To unsubscribe, e-mail: httpclient-user-
>>>> unsubscribe@jakarta.apache.org
>>>> For additional commands, e-mail: httpclient-user-
>>>> help@jakarta.apache.org
>>>>
>>>>
>>>
>>>
>>> --------------------------------------------------------------------
>>> -
>>> To unsubscribe, e-mail: httpclient-user-
>>> unsubscribe@jakarta.apache.org
>>> For additional commands, e-mail: httpclient-user-
>>> help@jakarta.apache.org
>>>
>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: httpclient-user-
>> unsubscribe@jakarta.apache.org
>> For additional commands, e-mail: httpclient-user-
>> help@jakarta.apache.org
>>
>>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: httpclient-user-unsubscribe@jakarta.apache.org
> For additional commands, e-mail: httpclient-user-
> help@jakarta.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-user-unsubscribe@jakarta.apache.org
For additional commands, e-mail: httpclient-user-help@jakarta.apache.org
Re: Lockup in XFire
Posted by Oleg Kalnichevski <ol...@apache.org>.
On Mon, 2006-08-07 at 18:10 -0700, Patrick Lightbody wrote:
> On Aug 7, 2006, at 3:18 PM, Oleg Kalnichevski wrote:
>
> > On Mon, 2006-08-07 at 14:40 -0700, Patrick Lightbody wrote:
> >> Oleg,
> >> Sure, I understand that the issue is due to a native timeout - but
> >> the question is: why?
> >>
> >
> > (1) The only reason for a native socket read to block indefinitely is
> > the SO_TIMEOUT value set to zero. Does XFire explicitly set the socket
> > timeout value to a positive value?
>
> No, XFire does not. I tried setting it and that didn't produce the
> desireable affect, as I have several requests that I want to take up
> to several minutes to respond. I think an indefinite time is fine
> (which the default, which is what I was using). My issue isn't that
> the timeout is set to 0, but that the connection isn't proceeding
> like it should be.
The connection is not proceeding because apparently the server is not
sending any data.
> Specifically, on the server side, I have done a
> stack dump and the only thing related to sockets there is this:
>
> ---> Acceptor ServerSocket[addr=0.0.0.0/0.0.0.0,port=0,localport=8081]
> java.net.PlainSocketImpl.socketAccept(Native Method)
> java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384)
> java.net.ServerSocket.implAccept(ServerSocket.java:450)
> java.net.ServerSocket.accept(ServerSocket.java:421)
> org.mortbay.util.ThreadedServer.acceptSocket(ThreadedServer.java:
> 432)
> org.mortbay.util.ThreadedServer$Acceptor.run(ThreadedServer.java:
> 634)
>
> Which clearly is not related to the other open socket.
>
Are there any other threads not related to sockets? The server may stop
responding on a connection if the connection thread gets dead-locked on
a mutex or enters an infinite loop.
> So I'm back to my original problem: why is the client stuck in the
> native state while the server has no record of it? And why does it
> only happen for that one request in those exact steps that I execute.
> I should also add that I have done a netstat call at the time, and
> got back:
>
> [hostedqa-j2ee@autoriginate01 webapps]$ netstat -a --numeric-port |
> grep 8081
> tcp 1 0 ::ffff:192.168.167.1:58125 ::ffff:
> 192.168.167.129:8081 CLOSE_WAIT
>
> Any other ideas? I'm really at a loss here :(
>
As far as I am concerned there's nothing wrong in how HttpClient is
behaving. It blocks indefinitely in the native socket read because this
is precisely what it has been instructed to do. In my opinion the
problem is on the server side.
Just in case consider upgrading the JVM you are using both client and
server side to the latest patch level, and consider using a different
version of Jetty or a different servlet engine to see if that makes any
difference
Oleg
> Patrick
>
>
> > (2) org.apache.commons.httpclient.HttpMethodBase writeRequest
> > 100 (continue) read timeout. Resume sending the request
> >
> > This message is logged when the target server fails to properly
> > respond
> > to the "Expect: 100-continue" handshake. When the handshake is
> > activated
> > HttpClient sends the request header containing the "Expect:
> > 100-continue" directive prior to sending the request body and expects
> > the target server to respond with status code 100 indicating that
> > it is
> > okay to proceed with sending the request content. Apparently the
> > server
> > has issues with the "Expect: 100-continue" handshake or simply
> > locks up
> > while processing the request header.
> >
>
> I turned off this feature and the INFO log goes away, but the lock up
> still occurs. So I don't think this is related.
>
> > Hope this helps.
> >
> > Oleg
> >
> >> Like I reported in my initial email, subsequent requests in other
> >> threads (coming from test.jsp) work fine.
> >>
> >> Patrick
> >>
> >> Patrick Lightbody
> >> Autoriginate, Inc.
> >> 503-488-5402
> >> http://www.autoriginate.com
> >> patrick@autoriginate.com
> >>
> >> "Intelligent testing made convenient"
> >>
> >>
> >> On Aug 7, 2006, at 2:34 PM, Oleg Kalnichevski wrote:
> >>
> >>> On Mon, 2006-08-07 at 12:29 -0700, Patrick Lightbody wrote:
> >>>> I've tried using XFire 1.1.1 and 1.2-RC, combined with
> >>>> HttpClient 3.0
> >>>> and 3.1-alpha1. I get the same result, outlined below, which
> >>>> causes a
> >>>> complete lockup of a thread. I can't figure out what would cause
> >>>> this.
> >>>>
> >>>> When making a call via XFire (ClientService.getAppLog()), the
> >>>> current
> >>>> thread locks up just after printing the following out in the logs:
> >>>>
> >>>> org.apache.commons.httpclient.HttpMethodBase writeRequest
> >>>> 100 (continue) read timeout. Resume sending the request
> >>>>
> >>>> I see that this log comes from an InterruptedIOException here:
> >>>>
> >>>> http://jakarta.apache.org/commons/httpclient/xref/org/apache/
> >>>> commons/
> >>>> httpclient/HttpMethodBase.html#2004
> >>>>
> >>>> The stack dump of the locked thread is:
> >>>>
> >>>> "Thread-62" daemon prio=1 tid=0x082602c0 nid=0x51ca runnable
> >>>> [0x79926000..0x79926e30]
> >>>
> >>> Patrick,
> >>> As you can see the thread gets blocked in the native socket read
> >>> method,
> >>> so this is very unlikely to be a threading dead-lock in the
> >>> HttpClient
> >>> code. Most likely the socket read operation blocks indefinitely
> >>> because
> >>> socket timeout is not set (SO_TIMEOUT value is set to zero).
> >>>
> >>> Hope this helps
> >>>
> >>> Oleg
> >>>
> >>>
> >>>> at java.net.SocketInputStream.socketRead0(Native Method)
> >>>> at java.net.SocketInputStream.read(SocketInputStream.java:
> >>>> 129)
> >>>> at java.io.BufferedInputStream.fill
> >>>> (BufferedInputStream.java:
> >>>> 218)
> >>>> at java.io.BufferedInputStream.read
> >>>> (BufferedInputStream.java:
> >>>> 235)
> >>>> - locked <0x830328c8> (a java.io.BufferedInputStream)
> >>>> at org.apache.commons.httpclient.HttpParser.readRawLine
> >>>> (HttpParser.java:77)
> >>>> at org.apache.commons.httpclient.HttpParser.readLine
> >>>> (HttpParser.java:105)
> >>>> at org.apache.commons.httpclient.HttpConnection.readLine
> >>>> (HttpConnection.java:1115)
> >>>> at
> >>>> org.apache.commons.httpclient.MultiThreadedHttpConnectionManager
> >>>> $HttpConnectionAdapter.readLine
> >>>> (MultiThreadedHttpConnectionManager.java:1373)
> >>>> at
> >>>> org.apache.commons.httpclient.HttpMethodBase.readStatusLine
> >>>> (HttpMethodBase.java:1832)
> >>>> at
> >>>> org.apache.commons.httpclient.HttpMethodBase.readResponse
> >>>> (HttpMethodBase.java:1590)
> >>>> at org.apache.commons.httpclient.HttpMethodBase.execute
> >>>> (HttpMethodBase.java:995)
> >>>> at
> >>>> org.apache.commons.httpclient.HttpMethodDirector.executeWithRetry
> >>>> (HttpMethodDirector.java:397)
> >>>> at
> >>>> org.apache.commons.httpclient.HttpMethodDirector.executeMethod
> >>>> (HttpMethodDirector.java:170)
> >>>> at org.apache.commons.httpclient.HttpClient.executeMethod
> >>>> (HttpClient.java:396)
> >>>> at
> >>>> org.codehaus.xfire.transport.http.CommonsHttpMessageSender.send
> >>>> (CommonsHttpMessageSender.java:226)
> >>>> at
> >>>> org.codehaus.xfire.transport.http.HttpChannel.sendViaClient
> >>>> (HttpChannel.java:118)
> >>>> at org.codehaus.xfire.transport.http.HttpChannel.send
> >>>> (HttpChannel.java:48)
> >>>> at org.codehaus.xfire.handler.OutMessageSender.invoke
> >>>> (OutMessageSender.java:26)
> >>>> at org.codehaus.xfire.handler.HandlerPipeline.invoke
> >>>> (HandlerPipeline.java:130)
> >>>> at org.codehaus.xfire.client.Invocation.invoke
> >>>> (Invocation.java:75)
> >>>> at org.codehaus.xfire.client.Client.invoke(Client.java:335)
> >>>> at org.codehaus.xfire.client.XFireProxy.handleRequest
> >>>> (XFireProxy.java:77)
> >>>> at org.codehaus.xfire.client.XFireProxy.invoke
> >>>> (XFireProxy.java:57)
> >>>> at $Proxy5.getAppLog(Unknown Source)
> >>>> at com.hostedqa.model.TestContextImpl.dispose
> >>>> (TestContextImpl.java:83)
> >>>> at com.hostedqa.model.Suite.playback(Suite.java:85)
> >>>> at com.hostedqa.service.PlaybackService.runTest
> >>>> (PlaybackService.java:83)
> >>>> at com.hostedqa.service.PlaybackService.playSuite
> >>>> (PlaybackService.java:48)
> >>>> at com.hostedqa.action.project.suite.PlayAction$1.run
> >>>> (PlayAction.java:25)
> >>>> at java.lang.Thread.run(Thread.java:595)
> >>>>
> >>>> What's very weird is that I am able to drop a JSP (test.jsp) that
> >>>> makes the exact same call and it completes just fine. This tells me
> >>>> that there is something environmental about _this_ thread that
> >>>> causes
> >>>> HttpClient to do this. The call alone is not the issue.
> >>>>
> >>>> Also, I might add that the XFire call never makes it to the
> >>>> other end
> >>>> (ClientServiceImpl), as I have a print line there that never gets
> >>>> invoked. I ran a stack dump on the other side as well, and nothing
> >>>> stood out (though it is possible part of the request made it
> >>>> through
> >>>> to XFire's Servlet, and then broke and was no longer in the active
> >>>> thread dump by the time I forced the dump).
> >>>>
> >>>> Finally, this request is running over HTTP. I'd really like to
> >>>> figure
> >>>> out:
> >>>>
> >>>> 1) What that log from HttpMethodBase.writeRequest() is all about
> >>>> 2) Why there would be a perpetual "pause" in the native method, but
> >>>> no actual visible deadlock.
> >>>> 3) How to fix this :)
> >>>>
> >>>> Patrick
> >>>>
> >>>> Patrick Lightbody
> >>>> Autoriginate, Inc.
> >>>> 503-488-5402
> >>>> http://www.autoriginate.com
> >>>> patrick@autoriginate.com
> >>>>
> >>>> "Intelligent testing made convenient"
> >>>>
> >>>>
> >>>>
> >>>> -------------------------------------------------------------------
> >>>> --
> >>>> To unsubscribe, e-mail: httpclient-user-
> >>>> unsubscribe@jakarta.apache.org
> >>>> For additional commands, e-mail: httpclient-user-
> >>>> help@jakarta.apache.org
> >>>>
> >>>>
> >>>
> >>>
> >>> --------------------------------------------------------------------
> >>> -
> >>> To unsubscribe, e-mail: httpclient-user-
> >>> unsubscribe@jakarta.apache.org
> >>> For additional commands, e-mail: httpclient-user-
> >>> help@jakarta.apache.org
> >>>
> >>
> >>
> >> ---------------------------------------------------------------------
> >> To unsubscribe, e-mail: httpclient-user-
> >> unsubscribe@jakarta.apache.org
> >> For additional commands, e-mail: httpclient-user-
> >> help@jakarta.apache.org
> >>
> >>
> >
> >
> > ---------------------------------------------------------------------
> > To unsubscribe, e-mail: httpclient-user-unsubscribe@jakarta.apache.org
> > For additional commands, e-mail: httpclient-user-
> > help@jakarta.apache.org
> >
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: httpclient-user-unsubscribe@jakarta.apache.org
> For additional commands, e-mail: httpclient-user-help@jakarta.apache.org
>
>
---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-user-unsubscribe@jakarta.apache.org
For additional commands, e-mail: httpclient-user-help@jakarta.apache.org
Re: Lockup in XFire
Posted by Patrick Lightbody <pl...@gmail.com>.
On Aug 7, 2006, at 3:18 PM, Oleg Kalnichevski wrote:
> On Mon, 2006-08-07 at 14:40 -0700, Patrick Lightbody wrote:
>> Oleg,
>> Sure, I understand that the issue is due to a native timeout - but
>> the question is: why?
>>
>
> (1) The only reason for a native socket read to block indefinitely is
> the SO_TIMEOUT value set to zero. Does XFire explicitly set the socket
> timeout value to a positive value?
No, XFire does not. I tried setting it and that didn't produce the
desireable affect, as I have several requests that I want to take up
to several minutes to respond. I think an indefinite time is fine
(which the default, which is what I was using). My issue isn't that
the timeout is set to 0, but that the connection isn't proceeding
like it should be. Specifically, on the server side, I have done a
stack dump and the only thing related to sockets there is this:
---> Acceptor ServerSocket[addr=0.0.0.0/0.0.0.0,port=0,localport=8081]
java.net.PlainSocketImpl.socketAccept(Native Method)
java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384)
java.net.ServerSocket.implAccept(ServerSocket.java:450)
java.net.ServerSocket.accept(ServerSocket.java:421)
org.mortbay.util.ThreadedServer.acceptSocket(ThreadedServer.java:
432)
org.mortbay.util.ThreadedServer$Acceptor.run(ThreadedServer.java:
634)
Which clearly is not related to the other open socket.
So I'm back to my original problem: why is the client stuck in the
native state while the server has no record of it? And why does it
only happen for that one request in those exact steps that I execute.
I should also add that I have done a netstat call at the time, and
got back:
[hostedqa-j2ee@autoriginate01 webapps]$ netstat -a --numeric-port |
grep 8081
tcp 1 0 ::ffff:192.168.167.1:58125 ::ffff:
192.168.167.129:8081 CLOSE_WAIT
Any other ideas? I'm really at a loss here :(
Patrick
> (2) org.apache.commons.httpclient.HttpMethodBase writeRequest
> 100 (continue) read timeout. Resume sending the request
>
> This message is logged when the target server fails to properly
> respond
> to the "Expect: 100-continue" handshake. When the handshake is
> activated
> HttpClient sends the request header containing the "Expect:
> 100-continue" directive prior to sending the request body and expects
> the target server to respond with status code 100 indicating that
> it is
> okay to proceed with sending the request content. Apparently the
> server
> has issues with the "Expect: 100-continue" handshake or simply
> locks up
> while processing the request header.
>
I turned off this feature and the INFO log goes away, but the lock up
still occurs. So I don't think this is related.
> Hope this helps.
>
> Oleg
>
>> Like I reported in my initial email, subsequent requests in other
>> threads (coming from test.jsp) work fine.
>>
>> Patrick
>>
>> Patrick Lightbody
>> Autoriginate, Inc.
>> 503-488-5402
>> http://www.autoriginate.com
>> patrick@autoriginate.com
>>
>> "Intelligent testing made convenient"
>>
>>
>> On Aug 7, 2006, at 2:34 PM, Oleg Kalnichevski wrote:
>>
>>> On Mon, 2006-08-07 at 12:29 -0700, Patrick Lightbody wrote:
>>>> I've tried using XFire 1.1.1 and 1.2-RC, combined with
>>>> HttpClient 3.0
>>>> and 3.1-alpha1. I get the same result, outlined below, which
>>>> causes a
>>>> complete lockup of a thread. I can't figure out what would cause
>>>> this.
>>>>
>>>> When making a call via XFire (ClientService.getAppLog()), the
>>>> current
>>>> thread locks up just after printing the following out in the logs:
>>>>
>>>> org.apache.commons.httpclient.HttpMethodBase writeRequest
>>>> 100 (continue) read timeout. Resume sending the request
>>>>
>>>> I see that this log comes from an InterruptedIOException here:
>>>>
>>>> http://jakarta.apache.org/commons/httpclient/xref/org/apache/
>>>> commons/
>>>> httpclient/HttpMethodBase.html#2004
>>>>
>>>> The stack dump of the locked thread is:
>>>>
>>>> "Thread-62" daemon prio=1 tid=0x082602c0 nid=0x51ca runnable
>>>> [0x79926000..0x79926e30]
>>>
>>> Patrick,
>>> As you can see the thread gets blocked in the native socket read
>>> method,
>>> so this is very unlikely to be a threading dead-lock in the
>>> HttpClient
>>> code. Most likely the socket read operation blocks indefinitely
>>> because
>>> socket timeout is not set (SO_TIMEOUT value is set to zero).
>>>
>>> Hope this helps
>>>
>>> Oleg
>>>
>>>
>>>> at java.net.SocketInputStream.socketRead0(Native Method)
>>>> at java.net.SocketInputStream.read(SocketInputStream.java:
>>>> 129)
>>>> at java.io.BufferedInputStream.fill
>>>> (BufferedInputStream.java:
>>>> 218)
>>>> at java.io.BufferedInputStream.read
>>>> (BufferedInputStream.java:
>>>> 235)
>>>> - locked <0x830328c8> (a java.io.BufferedInputStream)
>>>> at org.apache.commons.httpclient.HttpParser.readRawLine
>>>> (HttpParser.java:77)
>>>> at org.apache.commons.httpclient.HttpParser.readLine
>>>> (HttpParser.java:105)
>>>> at org.apache.commons.httpclient.HttpConnection.readLine
>>>> (HttpConnection.java:1115)
>>>> at
>>>> org.apache.commons.httpclient.MultiThreadedHttpConnectionManager
>>>> $HttpConnectionAdapter.readLine
>>>> (MultiThreadedHttpConnectionManager.java:1373)
>>>> at
>>>> org.apache.commons.httpclient.HttpMethodBase.readStatusLine
>>>> (HttpMethodBase.java:1832)
>>>> at
>>>> org.apache.commons.httpclient.HttpMethodBase.readResponse
>>>> (HttpMethodBase.java:1590)
>>>> at org.apache.commons.httpclient.HttpMethodBase.execute
>>>> (HttpMethodBase.java:995)
>>>> at
>>>> org.apache.commons.httpclient.HttpMethodDirector.executeWithRetry
>>>> (HttpMethodDirector.java:397)
>>>> at
>>>> org.apache.commons.httpclient.HttpMethodDirector.executeMethod
>>>> (HttpMethodDirector.java:170)
>>>> at org.apache.commons.httpclient.HttpClient.executeMethod
>>>> (HttpClient.java:396)
>>>> at
>>>> org.codehaus.xfire.transport.http.CommonsHttpMessageSender.send
>>>> (CommonsHttpMessageSender.java:226)
>>>> at
>>>> org.codehaus.xfire.transport.http.HttpChannel.sendViaClient
>>>> (HttpChannel.java:118)
>>>> at org.codehaus.xfire.transport.http.HttpChannel.send
>>>> (HttpChannel.java:48)
>>>> at org.codehaus.xfire.handler.OutMessageSender.invoke
>>>> (OutMessageSender.java:26)
>>>> at org.codehaus.xfire.handler.HandlerPipeline.invoke
>>>> (HandlerPipeline.java:130)
>>>> at org.codehaus.xfire.client.Invocation.invoke
>>>> (Invocation.java:75)
>>>> at org.codehaus.xfire.client.Client.invoke(Client.java:335)
>>>> at org.codehaus.xfire.client.XFireProxy.handleRequest
>>>> (XFireProxy.java:77)
>>>> at org.codehaus.xfire.client.XFireProxy.invoke
>>>> (XFireProxy.java:57)
>>>> at $Proxy5.getAppLog(Unknown Source)
>>>> at com.hostedqa.model.TestContextImpl.dispose
>>>> (TestContextImpl.java:83)
>>>> at com.hostedqa.model.Suite.playback(Suite.java:85)
>>>> at com.hostedqa.service.PlaybackService.runTest
>>>> (PlaybackService.java:83)
>>>> at com.hostedqa.service.PlaybackService.playSuite
>>>> (PlaybackService.java:48)
>>>> at com.hostedqa.action.project.suite.PlayAction$1.run
>>>> (PlayAction.java:25)
>>>> at java.lang.Thread.run(Thread.java:595)
>>>>
>>>> What's very weird is that I am able to drop a JSP (test.jsp) that
>>>> makes the exact same call and it completes just fine. This tells me
>>>> that there is something environmental about _this_ thread that
>>>> causes
>>>> HttpClient to do this. The call alone is not the issue.
>>>>
>>>> Also, I might add that the XFire call never makes it to the
>>>> other end
>>>> (ClientServiceImpl), as I have a print line there that never gets
>>>> invoked. I ran a stack dump on the other side as well, and nothing
>>>> stood out (though it is possible part of the request made it
>>>> through
>>>> to XFire's Servlet, and then broke and was no longer in the active
>>>> thread dump by the time I forced the dump).
>>>>
>>>> Finally, this request is running over HTTP. I'd really like to
>>>> figure
>>>> out:
>>>>
>>>> 1) What that log from HttpMethodBase.writeRequest() is all about
>>>> 2) Why there would be a perpetual "pause" in the native method, but
>>>> no actual visible deadlock.
>>>> 3) How to fix this :)
>>>>
>>>> Patrick
>>>>
>>>> Patrick Lightbody
>>>> Autoriginate, Inc.
>>>> 503-488-5402
>>>> http://www.autoriginate.com
>>>> patrick@autoriginate.com
>>>>
>>>> "Intelligent testing made convenient"
>>>>
>>>>
>>>>
>>>> -------------------------------------------------------------------
>>>> --
>>>> To unsubscribe, e-mail: httpclient-user-
>>>> unsubscribe@jakarta.apache.org
>>>> For additional commands, e-mail: httpclient-user-
>>>> help@jakarta.apache.org
>>>>
>>>>
>>>
>>>
>>> --------------------------------------------------------------------
>>> -
>>> To unsubscribe, e-mail: httpclient-user-
>>> unsubscribe@jakarta.apache.org
>>> For additional commands, e-mail: httpclient-user-
>>> help@jakarta.apache.org
>>>
>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: httpclient-user-
>> unsubscribe@jakarta.apache.org
>> For additional commands, e-mail: httpclient-user-
>> help@jakarta.apache.org
>>
>>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: httpclient-user-unsubscribe@jakarta.apache.org
> For additional commands, e-mail: httpclient-user-
> help@jakarta.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-user-unsubscribe@jakarta.apache.org
For additional commands, e-mail: httpclient-user-help@jakarta.apache.org
Re: Lockup in XFire
Posted by Oleg Kalnichevski <ol...@apache.org>.
On Mon, 2006-08-07 at 14:40 -0700, Patrick Lightbody wrote:
> Oleg,
> Sure, I understand that the issue is due to a native timeout - but
> the question is: why?
>
(1) The only reason for a native socket read to block indefinitely is
the SO_TIMEOUT value set to zero. Does XFire explicitly set the socket
timeout value to a positive value?
(2) org.apache.commons.httpclient.HttpMethodBase writeRequest
100 (continue) read timeout. Resume sending the request
This message is logged when the target server fails to properly respond
to the "Expect: 100-continue" handshake. When the handshake is activated
HttpClient sends the request header containing the "Expect:
100-continue" directive prior to sending the request body and expects
the target server to respond with status code 100 indicating that it is
okay to proceed with sending the request content. Apparently the server
has issues with the "Expect: 100-continue" handshake or simply locks up
while processing the request header.
Hope this helps.
Oleg
> Like I reported in my initial email, subsequent requests in other
> threads (coming from test.jsp) work fine.
>
> Patrick
>
> Patrick Lightbody
> Autoriginate, Inc.
> 503-488-5402
> http://www.autoriginate.com
> patrick@autoriginate.com
>
> "Intelligent testing made convenient"
>
>
> On Aug 7, 2006, at 2:34 PM, Oleg Kalnichevski wrote:
>
> > On Mon, 2006-08-07 at 12:29 -0700, Patrick Lightbody wrote:
> >> I've tried using XFire 1.1.1 and 1.2-RC, combined with HttpClient 3.0
> >> and 3.1-alpha1. I get the same result, outlined below, which causes a
> >> complete lockup of a thread. I can't figure out what would cause
> >> this.
> >>
> >> When making a call via XFire (ClientService.getAppLog()), the current
> >> thread locks up just after printing the following out in the logs:
> >>
> >> org.apache.commons.httpclient.HttpMethodBase writeRequest
> >> 100 (continue) read timeout. Resume sending the request
> >>
> >> I see that this log comes from an InterruptedIOException here:
> >>
> >> http://jakarta.apache.org/commons/httpclient/xref/org/apache/commons/
> >> httpclient/HttpMethodBase.html#2004
> >>
> >> The stack dump of the locked thread is:
> >>
> >> "Thread-62" daemon prio=1 tid=0x082602c0 nid=0x51ca runnable
> >> [0x79926000..0x79926e30]
> >
> > Patrick,
> > As you can see the thread gets blocked in the native socket read
> > method,
> > so this is very unlikely to be a threading dead-lock in the HttpClient
> > code. Most likely the socket read operation blocks indefinitely
> > because
> > socket timeout is not set (SO_TIMEOUT value is set to zero).
> >
> > Hope this helps
> >
> > Oleg
> >
> >
> >> at java.net.SocketInputStream.socketRead0(Native Method)
> >> at java.net.SocketInputStream.read(SocketInputStream.java:
> >> 129)
> >> at java.io.BufferedInputStream.fill(BufferedInputStream.java:
> >> 218)
> >> at java.io.BufferedInputStream.read(BufferedInputStream.java:
> >> 235)
> >> - locked <0x830328c8> (a java.io.BufferedInputStream)
> >> at org.apache.commons.httpclient.HttpParser.readRawLine
> >> (HttpParser.java:77)
> >> at org.apache.commons.httpclient.HttpParser.readLine
> >> (HttpParser.java:105)
> >> at org.apache.commons.httpclient.HttpConnection.readLine
> >> (HttpConnection.java:1115)
> >> at
> >> org.apache.commons.httpclient.MultiThreadedHttpConnectionManager
> >> $HttpConnectionAdapter.readLine
> >> (MultiThreadedHttpConnectionManager.java:1373)
> >> at
> >> org.apache.commons.httpclient.HttpMethodBase.readStatusLine
> >> (HttpMethodBase.java:1832)
> >> at org.apache.commons.httpclient.HttpMethodBase.readResponse
> >> (HttpMethodBase.java:1590)
> >> at org.apache.commons.httpclient.HttpMethodBase.execute
> >> (HttpMethodBase.java:995)
> >> at
> >> org.apache.commons.httpclient.HttpMethodDirector.executeWithRetry
> >> (HttpMethodDirector.java:397)
> >> at
> >> org.apache.commons.httpclient.HttpMethodDirector.executeMethod
> >> (HttpMethodDirector.java:170)
> >> at org.apache.commons.httpclient.HttpClient.executeMethod
> >> (HttpClient.java:396)
> >> at
> >> org.codehaus.xfire.transport.http.CommonsHttpMessageSender.send
> >> (CommonsHttpMessageSender.java:226)
> >> at
> >> org.codehaus.xfire.transport.http.HttpChannel.sendViaClient
> >> (HttpChannel.java:118)
> >> at org.codehaus.xfire.transport.http.HttpChannel.send
> >> (HttpChannel.java:48)
> >> at org.codehaus.xfire.handler.OutMessageSender.invoke
> >> (OutMessageSender.java:26)
> >> at org.codehaus.xfire.handler.HandlerPipeline.invoke
> >> (HandlerPipeline.java:130)
> >> at org.codehaus.xfire.client.Invocation.invoke
> >> (Invocation.java:75)
> >> at org.codehaus.xfire.client.Client.invoke(Client.java:335)
> >> at org.codehaus.xfire.client.XFireProxy.handleRequest
> >> (XFireProxy.java:77)
> >> at org.codehaus.xfire.client.XFireProxy.invoke
> >> (XFireProxy.java:57)
> >> at $Proxy5.getAppLog(Unknown Source)
> >> at com.hostedqa.model.TestContextImpl.dispose
> >> (TestContextImpl.java:83)
> >> at com.hostedqa.model.Suite.playback(Suite.java:85)
> >> at com.hostedqa.service.PlaybackService.runTest
> >> (PlaybackService.java:83)
> >> at com.hostedqa.service.PlaybackService.playSuite
> >> (PlaybackService.java:48)
> >> at com.hostedqa.action.project.suite.PlayAction$1.run
> >> (PlayAction.java:25)
> >> at java.lang.Thread.run(Thread.java:595)
> >>
> >> What's very weird is that I am able to drop a JSP (test.jsp) that
> >> makes the exact same call and it completes just fine. This tells me
> >> that there is something environmental about _this_ thread that causes
> >> HttpClient to do this. The call alone is not the issue.
> >>
> >> Also, I might add that the XFire call never makes it to the other end
> >> (ClientServiceImpl), as I have a print line there that never gets
> >> invoked. I ran a stack dump on the other side as well, and nothing
> >> stood out (though it is possible part of the request made it through
> >> to XFire's Servlet, and then broke and was no longer in the active
> >> thread dump by the time I forced the dump).
> >>
> >> Finally, this request is running over HTTP. I'd really like to figure
> >> out:
> >>
> >> 1) What that log from HttpMethodBase.writeRequest() is all about
> >> 2) Why there would be a perpetual "pause" in the native method, but
> >> no actual visible deadlock.
> >> 3) How to fix this :)
> >>
> >> Patrick
> >>
> >> Patrick Lightbody
> >> Autoriginate, Inc.
> >> 503-488-5402
> >> http://www.autoriginate.com
> >> patrick@autoriginate.com
> >>
> >> "Intelligent testing made convenient"
> >>
> >>
> >>
> >> ---------------------------------------------------------------------
> >> To unsubscribe, e-mail: httpclient-user-
> >> unsubscribe@jakarta.apache.org
> >> For additional commands, e-mail: httpclient-user-
> >> help@jakarta.apache.org
> >>
> >>
> >
> >
> > ---------------------------------------------------------------------
> > To unsubscribe, e-mail: httpclient-user-unsubscribe@jakarta.apache.org
> > For additional commands, e-mail: httpclient-user-
> > help@jakarta.apache.org
> >
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: httpclient-user-unsubscribe@jakarta.apache.org
> For additional commands, e-mail: httpclient-user-help@jakarta.apache.org
>
>
---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-user-unsubscribe@jakarta.apache.org
For additional commands, e-mail: httpclient-user-help@jakarta.apache.org
Re: Lockup in XFire
Posted by Patrick Lightbody <pl...@gmail.com>.
Oleg,
Sure, I understand that the issue is due to a native timeout - but
the question is: why?
Like I reported in my initial email, subsequent requests in other
threads (coming from test.jsp) work fine.
Patrick
Patrick Lightbody
Autoriginate, Inc.
503-488-5402
http://www.autoriginate.com
patrick@autoriginate.com
"Intelligent testing made convenient"
On Aug 7, 2006, at 2:34 PM, Oleg Kalnichevski wrote:
> On Mon, 2006-08-07 at 12:29 -0700, Patrick Lightbody wrote:
>> I've tried using XFire 1.1.1 and 1.2-RC, combined with HttpClient 3.0
>> and 3.1-alpha1. I get the same result, outlined below, which causes a
>> complete lockup of a thread. I can't figure out what would cause
>> this.
>>
>> When making a call via XFire (ClientService.getAppLog()), the current
>> thread locks up just after printing the following out in the logs:
>>
>> org.apache.commons.httpclient.HttpMethodBase writeRequest
>> 100 (continue) read timeout. Resume sending the request
>>
>> I see that this log comes from an InterruptedIOException here:
>>
>> http://jakarta.apache.org/commons/httpclient/xref/org/apache/commons/
>> httpclient/HttpMethodBase.html#2004
>>
>> The stack dump of the locked thread is:
>>
>> "Thread-62" daemon prio=1 tid=0x082602c0 nid=0x51ca runnable
>> [0x79926000..0x79926e30]
>
> Patrick,
> As you can see the thread gets blocked in the native socket read
> method,
> so this is very unlikely to be a threading dead-lock in the HttpClient
> code. Most likely the socket read operation blocks indefinitely
> because
> socket timeout is not set (SO_TIMEOUT value is set to zero).
>
> Hope this helps
>
> Oleg
>
>
>> at java.net.SocketInputStream.socketRead0(Native Method)
>> at java.net.SocketInputStream.read(SocketInputStream.java:
>> 129)
>> at java.io.BufferedInputStream.fill(BufferedInputStream.java:
>> 218)
>> at java.io.BufferedInputStream.read(BufferedInputStream.java:
>> 235)
>> - locked <0x830328c8> (a java.io.BufferedInputStream)
>> at org.apache.commons.httpclient.HttpParser.readRawLine
>> (HttpParser.java:77)
>> at org.apache.commons.httpclient.HttpParser.readLine
>> (HttpParser.java:105)
>> at org.apache.commons.httpclient.HttpConnection.readLine
>> (HttpConnection.java:1115)
>> at
>> org.apache.commons.httpclient.MultiThreadedHttpConnectionManager
>> $HttpConnectionAdapter.readLine
>> (MultiThreadedHttpConnectionManager.java:1373)
>> at
>> org.apache.commons.httpclient.HttpMethodBase.readStatusLine
>> (HttpMethodBase.java:1832)
>> at org.apache.commons.httpclient.HttpMethodBase.readResponse
>> (HttpMethodBase.java:1590)
>> at org.apache.commons.httpclient.HttpMethodBase.execute
>> (HttpMethodBase.java:995)
>> at
>> org.apache.commons.httpclient.HttpMethodDirector.executeWithRetry
>> (HttpMethodDirector.java:397)
>> at
>> org.apache.commons.httpclient.HttpMethodDirector.executeMethod
>> (HttpMethodDirector.java:170)
>> at org.apache.commons.httpclient.HttpClient.executeMethod
>> (HttpClient.java:396)
>> at
>> org.codehaus.xfire.transport.http.CommonsHttpMessageSender.send
>> (CommonsHttpMessageSender.java:226)
>> at
>> org.codehaus.xfire.transport.http.HttpChannel.sendViaClient
>> (HttpChannel.java:118)
>> at org.codehaus.xfire.transport.http.HttpChannel.send
>> (HttpChannel.java:48)
>> at org.codehaus.xfire.handler.OutMessageSender.invoke
>> (OutMessageSender.java:26)
>> at org.codehaus.xfire.handler.HandlerPipeline.invoke
>> (HandlerPipeline.java:130)
>> at org.codehaus.xfire.client.Invocation.invoke
>> (Invocation.java:75)
>> at org.codehaus.xfire.client.Client.invoke(Client.java:335)
>> at org.codehaus.xfire.client.XFireProxy.handleRequest
>> (XFireProxy.java:77)
>> at org.codehaus.xfire.client.XFireProxy.invoke
>> (XFireProxy.java:57)
>> at $Proxy5.getAppLog(Unknown Source)
>> at com.hostedqa.model.TestContextImpl.dispose
>> (TestContextImpl.java:83)
>> at com.hostedqa.model.Suite.playback(Suite.java:85)
>> at com.hostedqa.service.PlaybackService.runTest
>> (PlaybackService.java:83)
>> at com.hostedqa.service.PlaybackService.playSuite
>> (PlaybackService.java:48)
>> at com.hostedqa.action.project.suite.PlayAction$1.run
>> (PlayAction.java:25)
>> at java.lang.Thread.run(Thread.java:595)
>>
>> What's very weird is that I am able to drop a JSP (test.jsp) that
>> makes the exact same call and it completes just fine. This tells me
>> that there is something environmental about _this_ thread that causes
>> HttpClient to do this. The call alone is not the issue.
>>
>> Also, I might add that the XFire call never makes it to the other end
>> (ClientServiceImpl), as I have a print line there that never gets
>> invoked. I ran a stack dump on the other side as well, and nothing
>> stood out (though it is possible part of the request made it through
>> to XFire's Servlet, and then broke and was no longer in the active
>> thread dump by the time I forced the dump).
>>
>> Finally, this request is running over HTTP. I'd really like to figure
>> out:
>>
>> 1) What that log from HttpMethodBase.writeRequest() is all about
>> 2) Why there would be a perpetual "pause" in the native method, but
>> no actual visible deadlock.
>> 3) How to fix this :)
>>
>> Patrick
>>
>> Patrick Lightbody
>> Autoriginate, Inc.
>> 503-488-5402
>> http://www.autoriginate.com
>> patrick@autoriginate.com
>>
>> "Intelligent testing made convenient"
>>
>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: httpclient-user-
>> unsubscribe@jakarta.apache.org
>> For additional commands, e-mail: httpclient-user-
>> help@jakarta.apache.org
>>
>>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: httpclient-user-unsubscribe@jakarta.apache.org
> For additional commands, e-mail: httpclient-user-
> help@jakarta.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-user-unsubscribe@jakarta.apache.org
For additional commands, e-mail: httpclient-user-help@jakarta.apache.org
Re: Lockup in XFire
Posted by Oleg Kalnichevski <ol...@apache.org>.
On Mon, 2006-08-07 at 12:29 -0700, Patrick Lightbody wrote:
> I've tried using XFire 1.1.1 and 1.2-RC, combined with HttpClient 3.0
> and 3.1-alpha1. I get the same result, outlined below, which causes a
> complete lockup of a thread. I can't figure out what would cause this.
>
> When making a call via XFire (ClientService.getAppLog()), the current
> thread locks up just after printing the following out in the logs:
>
> org.apache.commons.httpclient.HttpMethodBase writeRequest
> 100 (continue) read timeout. Resume sending the request
>
> I see that this log comes from an InterruptedIOException here:
>
> http://jakarta.apache.org/commons/httpclient/xref/org/apache/commons/
> httpclient/HttpMethodBase.html#2004
>
> The stack dump of the locked thread is:
>
> "Thread-62" daemon prio=1 tid=0x082602c0 nid=0x51ca runnable
> [0x79926000..0x79926e30]
Patrick,
As you can see the thread gets blocked in the native socket read method,
so this is very unlikely to be a threading dead-lock in the HttpClient
code. Most likely the socket read operation blocks indefinitely because
socket timeout is not set (SO_TIMEOUT value is set to zero).
Hope this helps
Oleg
> at java.net.SocketInputStream.socketRead0(Native Method)
> at java.net.SocketInputStream.read(SocketInputStream.java:129)
> at java.io.BufferedInputStream.fill(BufferedInputStream.java:
> 218)
> at java.io.BufferedInputStream.read(BufferedInputStream.java:
> 235)
> - locked <0x830328c8> (a java.io.BufferedInputStream)
> at org.apache.commons.httpclient.HttpParser.readRawLine
> (HttpParser.java:77)
> at org.apache.commons.httpclient.HttpParser.readLine
> (HttpParser.java:105)
> at org.apache.commons.httpclient.HttpConnection.readLine
> (HttpConnection.java:1115)
> at
> org.apache.commons.httpclient.MultiThreadedHttpConnectionManager
> $HttpConnectionAdapter.readLine
> (MultiThreadedHttpConnectionManager.java:1373)
> at org.apache.commons.httpclient.HttpMethodBase.readStatusLine
> (HttpMethodBase.java:1832)
> at org.apache.commons.httpclient.HttpMethodBase.readResponse
> (HttpMethodBase.java:1590)
> at org.apache.commons.httpclient.HttpMethodBase.execute
> (HttpMethodBase.java:995)
> at
> org.apache.commons.httpclient.HttpMethodDirector.executeWithRetry
> (HttpMethodDirector.java:397)
> at
> org.apache.commons.httpclient.HttpMethodDirector.executeMethod
> (HttpMethodDirector.java:170)
> at org.apache.commons.httpclient.HttpClient.executeMethod
> (HttpClient.java:396)
> at
> org.codehaus.xfire.transport.http.CommonsHttpMessageSender.send
> (CommonsHttpMessageSender.java:226)
> at org.codehaus.xfire.transport.http.HttpChannel.sendViaClient
> (HttpChannel.java:118)
> at org.codehaus.xfire.transport.http.HttpChannel.send
> (HttpChannel.java:48)
> at org.codehaus.xfire.handler.OutMessageSender.invoke
> (OutMessageSender.java:26)
> at org.codehaus.xfire.handler.HandlerPipeline.invoke
> (HandlerPipeline.java:130)
> at org.codehaus.xfire.client.Invocation.invoke
> (Invocation.java:75)
> at org.codehaus.xfire.client.Client.invoke(Client.java:335)
> at org.codehaus.xfire.client.XFireProxy.handleRequest
> (XFireProxy.java:77)
> at org.codehaus.xfire.client.XFireProxy.invoke
> (XFireProxy.java:57)
> at $Proxy5.getAppLog(Unknown Source)
> at com.hostedqa.model.TestContextImpl.dispose
> (TestContextImpl.java:83)
> at com.hostedqa.model.Suite.playback(Suite.java:85)
> at com.hostedqa.service.PlaybackService.runTest
> (PlaybackService.java:83)
> at com.hostedqa.service.PlaybackService.playSuite
> (PlaybackService.java:48)
> at com.hostedqa.action.project.suite.PlayAction$1.run
> (PlayAction.java:25)
> at java.lang.Thread.run(Thread.java:595)
>
> What's very weird is that I am able to drop a JSP (test.jsp) that
> makes the exact same call and it completes just fine. This tells me
> that there is something environmental about _this_ thread that causes
> HttpClient to do this. The call alone is not the issue.
>
> Also, I might add that the XFire call never makes it to the other end
> (ClientServiceImpl), as I have a print line there that never gets
> invoked. I ran a stack dump on the other side as well, and nothing
> stood out (though it is possible part of the request made it through
> to XFire's Servlet, and then broke and was no longer in the active
> thread dump by the time I forced the dump).
>
> Finally, this request is running over HTTP. I'd really like to figure
> out:
>
> 1) What that log from HttpMethodBase.writeRequest() is all about
> 2) Why there would be a perpetual "pause" in the native method, but
> no actual visible deadlock.
> 3) How to fix this :)
>
> Patrick
>
> Patrick Lightbody
> Autoriginate, Inc.
> 503-488-5402
> http://www.autoriginate.com
> patrick@autoriginate.com
>
> "Intelligent testing made convenient"
>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: httpclient-user-unsubscribe@jakarta.apache.org
> For additional commands, e-mail: httpclient-user-help@jakarta.apache.org
>
>
---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-user-unsubscribe@jakarta.apache.org
For additional commands, e-mail: httpclient-user-help@jakarta.apache.org