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 ke...@chase.com on 2009/11/19 04:30:04 UTC

Infinite loop in ChunkedInputStream.close

We are using httpclient 3.1 to send a post and get back serialized java
objects (think of something analogous to Spring Remoting).
We deploy this client code to many client machines talking thru
loadbalancers communicating with Weblogic 10MP1 servers.
The clients in this test are on windows, running jdk5 thru mercury
loadrunner (performance testing software).

We've been testing anywhere between 45 and 90tps and the vast majority
of the transactions are successful.

About 1 transaction every half hour ends up with a
java.net.SocketException: Connection reset.
The loadbalancer will close the socket after 60 seconds.
The reason we get that exception (and not a different one) is that we
have the client timeout set up higher than 60 seconds (just for trying
to expose this issue) and the loadbalancer has a 60 second timeout.

Here is what we have learned so far.

We get the response body as stream:
            InputStream responseBody =
postMethod.getResponseBodyAsStream();

We then send it thru a custom deserializer, we know that the object in
the response is being read because the log right after it is being
printed out:
However we have a close on that input stream in the finally. I'm
probably going to remove that close (since I read elsewhere that its
taken care of by the postMethod.releaseConnection().
        try {
            Object object = ois.readObject();
            LOG.debug(METHOD_NAME + "ois.readObject completed");
            return object;
        } finally {
            ois.close();
            LOG.debug(METHOD_NAME + "ois.close completed");
        }

The ois.close() is calling AutoCloseInputStream.close, calling
ChunkedInputStream.close which is trying to exhaust the stream by
calling exhaustInputStream which eventually calls SocketInputStream.read
and just sits there until the connection reset happens.

Any clue as to what would cause it to hang there?

The confusing factors are that the object seems to be fully read (so I
would assume there is nothing left in the stream) and we average a
couple thousand good transactions for every 1 occurrence of a bad one.

Let me know if I need the full headers and wire. We have only the
header, not the content turned on because the volume of logging just
kills the clients when turned up to trace.
Also, we will be looking to migrate eventually to httpclient 4, but that
requires jdk5 and right now we have clients that are still
(unfortunately) jdk1.4 so we can't quite make that leap yet.
I have network captures as well, if you think you know what I should
look for please advise and I will do so.

Thanks,
Ken

Here is the pertinent httpclient log.
Notice the 1 minute gap in log statements between 15:54:25:723 EST and
15:55:25:756 EST
Also be aware that the reason you see logs in between the issue and the
time you see the stacktrace is that the postMethod.releaseConnection()
is in a finally, so of course it will complete before the exception is
propogated.

System.err: 2009/11/17 15:54:25:707 EST [TRACE] PostMethod - enter
PostMethod.clearRequestBody()
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] EntityEnclosingMethod -
enter EntityEnclosingMethod.clearRequestBody()
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [DEBUG]
RemoteServiceExecutorImpl - executeRequest calling
httpClient.ExecuteMethod
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpClient - enter
HttpClient.executeMethod(HttpMethod)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpClient - enter
HttpClient.executeMethod(HostConfiguration,HttpMethod,HttpState)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE]
MultiThreadedHttpConnectionManager - enter
HttpConnectionManager.getConnectionWithTimeout(HostConfiguration, long)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [DEBUG]
MultiThreadedHttpConnectionManager -
HttpConnectionManager.getConnection:  config =
HostConfiguration[host=http://my-loadbalancer:9810], timeout = 0
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE]
MultiThreadedHttpConnectionManager - enter
HttpConnectionManager.ConnectionPool.getHostPool(HostConfiguration)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE]
MultiThreadedHttpConnectionManager - enter
HttpConnectionManager.ConnectionPool.getHostPool(HostConfiguration)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [DEBUG]
MultiThreadedHttpConnectionManager - Allocating new connection,
hostConfig=HostConfiguration[host=http://my-loadbalancer:9810]
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpMethodDirector -
Attempt number 1 to process request
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
HttpConnection.open()
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [DEBUG] HttpConnection - Open
connection to my-loadbalancer:9810
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpMethodBase - enter
HttpMethodBase.execute(HttpState, HttpConnection)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpMethodBase - enter
HttpMethodBase.writeRequest(HttpState, HttpConnection)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpMethodBase - enter
HttpMethodBase.writeRequestLine(HttpState, HttpConnection)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpMethodBase - enter
HttpMethodBase.generateRequestLine(HttpConnection, String, String,
String, String)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [DEBUG] header - >> "POST
/cms.rcts/2009.9.1.006/ccs/prf.lr/2008.8.1/CDC/essd-remote/
HTTP/1.1[\r][\n]"
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
HttpConnection.print(String)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
HttpConnection.write(byte[])
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
HttpConnection.write(byte[], int, int)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpMethodBase - enter
HttpMethodBase.writeRequestHeaders(HttpState,HttpConnection)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] EntityEnclosingMethod -
enter EntityEnclosingMethod.addRequestHeaders(HttpState, HttpConnection)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] ExpectContinueMethod -
enter ExpectContinueMethod.addRequestHeaders(HttpState, HttpConnection)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpMethodBase - enter
HttpMethodBase.addRequestHeaders(HttpState, HttpConnection)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpMethodBase - enter
HttpMethodBase.addUserAgentRequestHeaders(HttpState, HttpConnection)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpMethodBase - enter
HttpMethodBase.addHostRequestHeader(HttpState, HttpConnection)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [DEBUG] HttpMethodBase - Adding
Host request header
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpMethodBase - enter
HttpMethodBase.addCookieRequestHeader(HttpState, HttpConnection)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpState - enter
HttpState.getCookies()
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpMethodBase - enter
HttpMethodBase.addProxyConnectionHeader(HttpState, HttpConnection)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] EntityEnclosingMethod -
enter EntityEnclosingMethod.addContentLengthRequestHeader(HttpState,
HttpConnection)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] EntityEnclosingMethod -
enter EntityEnclosingMethod.getRequestContentLength()
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] PostMethod - enter
PostMethod.hasRequestContent()
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] EntityEnclosingMethod -
enter EntityEnclosingMethod.hasRequestContent()
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpMethodBase -
HttpMethodBase.addRequestHeader(Header)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [DEBUG] header - >>
"Content-Type: application/x-java-serialized-object[\r][\n]"
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
HttpConnection.print(String)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
HttpConnection.write(byte[])
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
HttpConnection.write(byte[], int, int)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [DEBUG] header - >>
"Content-Encoding: none[\r][\n]"
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
HttpConnection.print(String)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
HttpConnection.write(byte[])
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
HttpConnection.write(byte[], int, int)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [DEBUG] header - >>
"Serialization-Type: java[\r][\n]"
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
HttpConnection.print(String)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
HttpConnection.write(byte[])
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
HttpConnection.write(byte[], int, int)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [DEBUG] header - >> "User-Agent:
Jakarta Commons-HttpClient/3.1[\r][\n]"
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
HttpConnection.print(String)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
HttpConnection.write(byte[])
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
HttpConnection.write(byte[], int, int)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [DEBUG] header - >> "Host:
my-loadbalancer:9810[\r][\n]"
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
HttpConnection.print(String)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
HttpConnection.write(byte[])
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
HttpConnection.write(byte[], int, int)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [DEBUG] header - >>
"Content-Length: 3051[\r][\n]"
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
HttpConnection.print(String)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
HttpConnection.write(byte[])
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
HttpConnection.write(byte[], int, int)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
HttpConnection.writeLine()
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
HttpConnection.write(byte[])
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
HttpConnection.write(byte[], int, int)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [DEBUG] header - >> "[\r][\n]"
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] EntityEnclosingMethod -
enter EntityEnclosingMethod.writeRequestBody(HttpState, HttpConnection)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] PostMethod - enter
PostMethod.hasRequestContent()
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] EntityEnclosingMethod -
enter EntityEnclosingMethod.hasRequestContent()
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] EntityEnclosingMethod -
enter EntityEnclosingMethod.getRequestContentLength()
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] PostMethod - enter
PostMethod.hasRequestContent()
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] EntityEnclosingMethod -
enter EntityEnclosingMethod.hasRequestContent()
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpConnection - enter
HttpConnection.getRequestOutputStream()
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [DEBUG] EntityEnclosingMethod -
Request body sent
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpConnection - enter
HttpConnection.flushRequestOutputStream()
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpMethodBase - enter
HttpMethodBase.readResponse(HttpState, HttpConnection)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpMethodBase - enter
HttpMethodBase.readStatusLine(HttpState, HttpConnection)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpConnection - enter
HttpConnection.readLine()
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpParser - enter
HttpParser.readLine(InputStream, String)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpParser - enter
HttpParser.readRawLine()
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [DEBUG] header - << "HTTP/1.1
200 OK[\r][\n]"
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [DEBUG] header - << "HTTP/1.1
200 OK[\r][\n]"
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpMethodBase - enter
HttpMethodBase.readResponseHeaders(HttpState,HttpConnection)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpConnection - enter
HttpConnection.getResponseInputStream()
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpParser - enter
HeaderParser.parseHeaders(InputStream, String)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpParser - enter
HttpParser.readLine(InputStream, String)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpParser - enter
HttpParser.readRawLine()
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [DEBUG] header - << "Date: Tue,
17 Nov 2009 20:54:25 GMT[\r][\n]"
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpParser - enter
HttpParser.readLine(InputStream, String)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpParser - enter
HttpParser.readRawLine()
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [DEBUG] header - <<
"Transfer-Encoding: chunked[\r][\n]"
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpParser - enter
HttpParser.readLine(InputStream, String)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpParser - enter
HttpParser.readRawLine()
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [DEBUG] header - <<
"Content-Type: application/x-java-serialized-object[\r][\n]"
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpParser - enter
HttpParser.readLine(InputStream, String)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpParser - enter
HttpParser.readRawLine()
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [DEBUG] header - <<
"Content-Encoding: none[\r][\n]"
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpParser - enter
HttpParser.readLine(InputStream, String)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpParser - enter
HttpParser.readRawLine()
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [DEBUG] header - <<
"Serialization-Type: java[\r][\n]"
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpParser - enter
HttpParser.readLine(InputStream, String)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpParser - enter
HttpParser.readRawLine()
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [DEBUG] header - << "[\r][\n]"
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpMethodBase - enter
HttpMethodBase.processResponseHeaders(HttpState, HttpConnection)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpMethodBase - enter
HttpMethodBase.processCookieHeaders(Header[], HttpState, HttpConnection)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpMethodBase - enter
HttpMethodBase.readResponseBody(HttpState, HttpConnection)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpMethodBase - enter
HttpMethodBase.readResponseBody(HttpConnection)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpConnection - enter
HttpConnection.getResponseInputStream()
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpMethodBase - enter
HttpMethodBase.canResponseHaveBody(int)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [TRACE] HeaderElement - enter
HeaderElement.parseElements(String)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [TRACE] HeaderElement - enter
HeaderElement.parseElements(char[])
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpConnection - enter
HttpConnection.isResponseAvailable(int)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [DEBUG]
RemoteServiceExecutorImpl - executeRequesthttpClient.ExecuteMethod
completed
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [DEBUG]
RemoteServiceExecutorImpl -
executeRequestpostMethod.getResponseBodyAsStream completed
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:55:25:756 EST [TRACE] HttpConnection - enter
HttpConnection.releaseConnection()
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:55:25:756 EST [DEBUG] HttpConnection -
Releasing connection back to connection manager.
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:55:25:756 EST [TRACE]
MultiThreadedHttpConnectionManager - enter
HttpConnectionManager.releaseConnection(HttpConnection)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:55:25:756 EST [DEBUG]
MultiThreadedHttpConnectionManager - Freeing connection,
hostConfig=HostConfiguration[host=http://my-loadbalancer:9810]
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:55:25:756 EST [TRACE]
MultiThreadedHttpConnectionManager - enter
HttpConnectionManager.ConnectionPool.getHostPool(HostConfiguration)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:55:25:756 EST [DEBUG] IdleConnectionHandler -
Adding connection at: 1258491325756
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:55:25:756 EST [DEBUG]
MultiThreadedHttpConnectionManager - Notifying no-one, there are no
waiting threads
Error	[MsgId: MMSG-17999]
Error: Failed to end Transaction "callTrackingService_insertWorkFlow"
(by name). Please check that you made a call to start transaction
operation.	[MsgId: MERR-16985]
Error: System.err: com.fusa.ssg.SystemException: Error making call[Error
executing Remote Method=[getCallSeqId] for Service
Url=[http://my-loadbalancer:9810/cms.rcts/2009.9.1.006/ccs/prf.lr/2008.8
.1/CDC] Exception=[java.net.SocketException: Connection reset
	at java.net.SocketInputStream.read(SocketInputStream.java:168)
	at
java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
	at
java.io.BufferedInputStream.read(BufferedInputStream.java:235)
	at
org.apache.commons.httpclient.ChunkedInputStream.getChunkSizeFromInputSt
ream(ChunkedInputStream.java:250)
	at
org.apache.commons.httpclient.ChunkedInputStream.nextChunk(ChunkedInputS
tream.java:221)
	at
org.apache.commons.httpclient.ChunkedInputStream.read(ChunkedInputStream
.java:176)
	at
org.apache.commons.httpclient.ChunkedInputStream.read(ChunkedInputStream
.java:196)
	at
org.apache.commons.httpclient.ChunkedInputStream.exhaustInputStream(Chun
kedInputStream.java:369)
	at
org.apache.commons.httpclient.ChunkedInputStream.close(ChunkedInputStrea
m.java:346)
	at java.io.FilterInputStream.close(FilterInputStream.java:159)
	at
org.apache.commons.httpclient.AutoCloseInputStream.notifyWatcher(AutoClo
seInputStream.java:194)
	at
org.apache.commons.httpclient.AutoCloseInputStream.close(AutoCloseInputS
tream.java:158)
	at
java.io.ObjectInputStream$PeekInputStream.close(ObjectInputStream.java:2
252)
	at
java.io.ObjectInputStream$BlockDataInputStream.close(ObjectInputStream.j
ava:2587)
	at java.io.ObjectInputStream.close(ObjectInputStream.java:853)
	at
com.fusa.ssg.infra.remoting.common.io.StandardJavaSerializer.readObject(
StandardJavaSerializer.java:41)
	at
com.fusa.ssg.infra.remoting.client.service.RemoteServiceExecutorImpl.des
erializeServiceResponse(RemoteServiceExecutorImpl.java:153)
	at
com.fusa.ssg.infra.remoting.client.service.RemoteServiceExecutorImpl.exe
cuteRequest(RemoteServiceExecutorImpl.java:111)
	at
com.fusa.ssg.infra.remoting.client.service.RemoteServiceProxy.invoke(Rem
oteServiceProxy.java:54)
	at $Proxy5.getCallSeqId(Unknown Source)
	at
com.ccs.cco.cms.rcts.client.calltracking.CallTrackingRemotingDelegate.ge
tCallSeqId(CallTrackingRemotingDelegate.java:66)
	at Actions.action(Actions.java:2327)
]]
Error	[MsgId: MERR-17999]
System.err: 	at
com.ccs.cco.cms.rcts.client.calltracking.CallTrackingRemotingDelegate.ge
tCallSeqId(CallTrackingRemotingDelegate.java:81)
Error	[MsgId: MMSG-17999]
System.err: 	at Actions.action(Actions.java:2327)
Error	[MsgId: MMSG-17999]
Error: System.err: ------------Wrapped Exception-----------
Error	[MsgId: MERR-17999]
Error: System.err:
com.fusa.ssg.infra.remoting.common.RemoteServiceException: Error
executing Remote Method=[getCallSeqId] for Service
Url=[http://my-loadbalancer:9810/cms.rcts/2009.9.1.006/ccs/prf.lr/2008.8
.1/CDC] Exception=[java.net.SocketException: Connection reset
	at java.net.SocketInputStream.read(SocketInputStream.java:168)
	at
java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
	at
java.io.BufferedInputStream.read(BufferedInputStream.java:235)
	at
org.apache.commons.httpclient.ChunkedInputStream.getChunkSizeFromInputSt
ream(ChunkedInputStream.java:250)
	at
org.apache.commons.httpclient.ChunkedInputStream.nextChunk(ChunkedInputS
tream.java:221)
	at
org.apache.commons.httpclient.ChunkedInputStream.read(ChunkedInputStream
.java:176)
	at
org.apache.commons.httpclient.ChunkedInputStream.read(ChunkedInputStream
.java:196)
	at
org.apache.commons.httpclient.ChunkedInputStream.exhaustInputStream(Chun
kedInputStream.java:369)
	at
org.apache.commons.httpclient.ChunkedInputStream.close(ChunkedInputStrea
m.java:346)
	at java.io.FilterInputStream.close(FilterInputStream.java:159)
	at
org.apache.commons.httpclient.AutoCloseInputStream.notifyWatcher(AutoClo
seInputStream.java:194)
	at
org.apache.commons.httpclient.AutoCloseInputStream.close(AutoCloseInputS
tream.java:158)
	at
java.io.ObjectInputStream$PeekInputStream.close(ObjectInputStream.java:2
252)
	at
java.io.ObjectInputStream$BlockDataInputStream.close(ObjectInputStream.j
ava:2587)
	at java.io.ObjectInputStream.close(ObjectInputStream.java:853)
	at
com.fusa.ssg.infra.remoting.common.io.StandardJavaSerializer.readObject(
StandardJavaSerializer.java:41)
	at
com.fusa.ssg.infra.remoting.client.service.RemoteServiceExecutorImpl.des
erializeServiceResponse(RemoteServiceExecutorImpl.java:153)
	at
com.fusa.ssg.infra.remoting.client.service.RemoteServiceExecutorImpl.exe
cuteRequest(RemoteServiceExecutorImpl.java:111)
	at
com.fusa.ssg.infra.remoting.client.service.RemoteServiceProxy.invoke(Rem
oteServiceProxy.java:54)
	at $Proxy5.getCallSeqId(Unknown Source)
	at
com.ccs.cco.cms.rcts.client.calltracking.CallTrackingRemotingDelegate.ge
tCallSeqId(CallTrackingRemotingDelegate.java:66)
	at Actions.action(Actions.java:2327)
]
Error	[MsgId: MERR-17999]
System.err: 	at
com.fusa.ssg.infra.remoting.client.service.RemoteServiceProxy.invoke(Rem
oteServiceProxy.java:58)
Error	[MsgId: MMSG-17999]
System.err: 	at $Proxy5.getCallSeqId(Unknown Source)
Error	[MsgId: MMSG-17999]
System.err: 	at
com.ccs.cco.cms.rcts.client.calltracking.CallTrackingRemotingDelegate.ge
tCallSeqId(CallTrackingRemotingDelegate.java:66)
Error	[MsgId: MMSG-17999]
System.err: 	at Actions.action(Actions.java:2327)
Error	[MsgId: MMSG-17999]
Error: System.err: -----------Wrapped Exception-----------
Error	[MsgId: MERR-17999]
Error: System.err:
com.fusa.ssg.infra.remoting.common.RemoteServiceException: Error
executing Remote Method=[getCallSeqId] for Service
Url=[http://my-loadbalancer:9810/cms.rcts/2009.9.1.006/ccs/prf.lr/2008.8
.1/CDC] Exception=[java.net.SocketException: Connection reset
	at java.net.SocketInputStream.read(SocketInputStream.java:168)
	at
java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
	at
java.io.BufferedInputStream.read(BufferedInputStream.java:235)
	at
org.apache.commons.httpclient.ChunkedInputStream.getChunkSizeFromInputSt
ream(ChunkedInputStream.java:250)
	at
org.apache.commons.httpclient.ChunkedInputStream.nextChunk(ChunkedInputS
tream.java:221)
	at
org.apache.commons.httpclient.ChunkedInputStream.read(ChunkedInputStream
.java:176)
	at
org.apache.commons.httpclient.ChunkedInputStream.read(ChunkedInputStream
.java:196)
	at
org.apache.commons.httpclient.ChunkedInputStream.exhaustInputStream(Chun
kedInputStream.java:369)
	at
org.apache.commons.httpclient.ChunkedInputStream.close(ChunkedInputStrea
m.java:346)
	at java.io.FilterInputStream.close(FilterInputStream.java:159)
	at
org.apache.commons.httpclient.AutoCloseInputStream.notifyWatcher(AutoClo
seInputStream.java:194)
	at
org.apache.commons.httpclient.AutoCloseInputStream.close(AutoCloseInputS
tream.java:158)
	at
java.io.ObjectInputStream$PeekInputStream.close(ObjectInputStream.java:2
252)
	at
java.io.ObjectInputStream$BlockDataInputStream.close(ObjectInputStream.j
ava:2587)
	at java.io.ObjectInputStream.close(ObjectInputStream.java:853)
	at
com.fusa.ssg.infra.remoting.common.io.StandardJavaSerializer.readObject(
StandardJavaSerializer.java:41)
	at
com.fusa.ssg.infra.remoting.client.service.RemoteServiceExecutorImpl.des
erializeServiceResponse(RemoteServiceExecutorImpl.java:153)
	at
com.fusa.ssg.infra.remoting.client.service.RemoteServiceExecutorImpl.exe
cuteRequest(RemoteServiceExecutorImpl.java:111)
	at
com.fusa.ssg.infra.remoting.client.service.RemoteServiceProxy.invoke(Rem
oteServiceProxy.java:54)
	at $Proxy5.getCallSeqId(Unknown Source)
	at
com.ccs.cco.cms.rcts.client.calltracking.CallTrackingRemotingDelegate.ge
tCallSeqId(CallTrackingRemotingDelegate.java:66)
	at Actions.action(Actions.java:2327)
]
Error	[MsgId: MERR-17999]
System.err: 	at
com.fusa.ssg.infra.remoting.client.service.RemoteServiceProxy.invoke(Rem
oteServiceProxy.java:58)
Error	[MsgId: MMSG-17999]
System.err: 	at $Proxy5.getCallSeqId(Unknown Source)
Error	[MsgId: MMSG-17999]
System.err: 	at
com.ccs.cco.cms.rcts.client.calltracking.CallTrackingRemotingDelegate.ge
tCallSeqId(CallTrackingRemotingDelegate.java:66)
Error	[MsgId: MMSG-17999]
System.err: 	at Actions.action(Actions.java:2327)
Error	[MsgId: MMSG-17999]










This transmission may contain information that is privileged,
confidential, legally privileged, and/or exempt from disclosure
under applicable law.  If you are not the intended recipient, you
are hereby notified that any disclosure, copying, distribution, or
use of the information contained herein (including any reliance
thereon) is STRICTLY PROHIBITED.  Although this transmission and
any attachments are believed to be free of any virus or other
defect that might affect any computer system into which it is
received and opened, it is the responsibility of the recipient to
ensure that it is virus free and no responsibility is accepted by
JPMorgan Chase & Co., its subsidiaries and affiliates, as
applicable, for any loss or damage arising in any way from its use.
 If you received this transmission in error, please immediately
contact the sender and destroy the material in its entirety,
whether in electronic or hard copy format. Thank you.

RE: HttpConnection.isResponseAvailable

Posted by ke...@chase.com.
Thanks again for the confirmation and input.

-ken

-----Original Message-----
From: Oleg Kalnichevski [mailto:olegk@apache.org] 
Sent: Thursday, November 26, 2009 3:48 PM
To: HttpClient User Discussion
Subject: Re: HttpConnection.isResponseAvailable

kenneth.s.brooks@chase.com wrote:
> Please validate this statement.
> 
> The IdleConnectionHandler kept firing past 20 seconds (my configured
> timeout value) because that connection was still active and waiting
for
> data.
> So it wasn't the IdleConnectionHandler that closed the socket,
otherwise
> I would have seen the following message "Closing connection,
connection
> time:".
> 
> 

Sounds about right.

As far as HttpClient is concerned any connection that is being used for 
transmitting messages is considered active. Connections are considered 
idle only when returned to the pool and not used for a certain period of

time.

Oleg


> 
> 
> That makes sense now looking at the source, because it looks like
> HttpMethodDirector caught an exception because that is where the stack
> is reporting it.. 
> 
>                 } catch (IOException e) {
>                     LOG.debug("Closing the connection.");
>                     this.conn.close();
> 
> and then just a little past that we see it saying that it did not
retry
> (I'm using a default retry handler) and throws the exception back to
the
> client.. which logged the Connection Reset.
>                     if (!handler.retryMethod(method, e, execCount)) {
>                         LOG.debug("Method retry handler returned
false.
> "
>                                 + "Automatic recovery will not be
> attempted");
>                         throw e;
>                     }
> 
> 
> Thanks for all of your input Oleg.. It is much appreciated.
> 
> 
> 
> -----Original Message-----
> From: Oleg Kalnichevski [mailto:olegk@apache.org] 
> Sent: Wednesday, November 25, 2009 5:12 PM
> To: HttpClient User Discussion
> Subject: Re: HttpConnection.isResponseAvailable
> 
> kenneth.s.brooks@chase.com wrote:
>> Related to previous post: Infinite loop in ChunkedInputStream.close
>>
>> Oleg,
>>
>> Last week I posted about an issue where we got the request body, and
>> when close is called on the input stream it gets to the underlying
>> InputStream.read and just sits there.
>> We ran some more tests with httpclient wire logging on and we
captured
> a
>> slightly different issue but stemming from the same apparent
> underlying
>> call.
>>
>> Both the previous issue and this one are both sitting idle at a call
> to
>> SocketInputStream.read (see the 'Client Log' further down this post
>> showing the stack trace where it is sitting).
>>
>> From what I see below it looks like the reply started to come, we get
>> the headers.. but it is sitting idle while checking for the response
>> body.
>> The VM isn't paused tho because the IdleConnectionHandler is
> continuing
>> to fire and (I think) eventually is responsible for closing the
>> connection. That is why we aren't getting a connection reset from the
>> loadbalancer in this case.
>>
>> So what in the world would would cause it to sit there?
>>  
> 
> The method blocks because the server is not sending any data whereas
it 
> clearly should be sending at least the closing chunk.
> 
> I do not see anything that could suggest there is a problem on the 
> client side.
> 
> Oleg
> 
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
> For additional commands, e-mail: httpclient-users-help@hc.apache.org
> 
> This transmission may contain information that is privileged,
> confidential, legally privileged, and/or exempt from disclosure
> under applicable law.  If you are not the intended recipient, you
> are hereby notified that any disclosure, copying, distribution, or
> use of the information contained herein (including any reliance
> thereon) is STRICTLY PROHIBITED.  Although this transmission and
> any attachments are believed to be free of any virus or other
> defect that might affect any computer system into which it is
> received and opened, it is the responsibility of the recipient to
> ensure that it is virus free and no responsibility is accepted by
> JPMorgan Chase & Co., its subsidiaries and affiliates, as
> applicable, for any loss or damage arising in any way from its use.
>  If you received this transmission in error, please immediately
> contact the sender and destroy the material in its entirety,
> whether in electronic or hard copy format. Thank you.
> 
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
> For additional commands, e-mail: httpclient-users-help@hc.apache.org
> 


---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
For additional commands, e-mail: httpclient-users-help@hc.apache.org


---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
For additional commands, e-mail: httpclient-users-help@hc.apache.org


Re: HttpConnection.isResponseAvailable

Posted by Oleg Kalnichevski <ol...@apache.org>.
kenneth.s.brooks@chase.com wrote:
> Please validate this statement.
> 
> The IdleConnectionHandler kept firing past 20 seconds (my configured
> timeout value) because that connection was still active and waiting for
> data.
> So it wasn't the IdleConnectionHandler that closed the socket, otherwise
> I would have seen the following message "Closing connection, connection
> time:".
> 
> 

Sounds about right.

As far as HttpClient is concerned any connection that is being used for 
transmitting messages is considered active. Connections are considered 
idle only when returned to the pool and not used for a certain period of 
time.

Oleg


> 
> 
> That makes sense now looking at the source, because it looks like
> HttpMethodDirector caught an exception because that is where the stack
> is reporting it.. 
> 
>                 } catch (IOException e) {
>                     LOG.debug("Closing the connection.");
>                     this.conn.close();
> 
> and then just a little past that we see it saying that it did not retry
> (I'm using a default retry handler) and throws the exception back to the
> client.. which logged the Connection Reset.
>                     if (!handler.retryMethod(method, e, execCount)) {
>                         LOG.debug("Method retry handler returned false.
> "
>                                 + "Automatic recovery will not be
> attempted");
>                         throw e;
>                     }
> 
> 
> Thanks for all of your input Oleg.. It is much appreciated.
> 
> 
> 
> -----Original Message-----
> From: Oleg Kalnichevski [mailto:olegk@apache.org] 
> Sent: Wednesday, November 25, 2009 5:12 PM
> To: HttpClient User Discussion
> Subject: Re: HttpConnection.isResponseAvailable
> 
> kenneth.s.brooks@chase.com wrote:
>> Related to previous post: Infinite loop in ChunkedInputStream.close
>>
>> Oleg,
>>
>> Last week I posted about an issue where we got the request body, and
>> when close is called on the input stream it gets to the underlying
>> InputStream.read and just sits there.
>> We ran some more tests with httpclient wire logging on and we captured
> a
>> slightly different issue but stemming from the same apparent
> underlying
>> call.
>>
>> Both the previous issue and this one are both sitting idle at a call
> to
>> SocketInputStream.read (see the 'Client Log' further down this post
>> showing the stack trace where it is sitting).
>>
>> From what I see below it looks like the reply started to come, we get
>> the headers.. but it is sitting idle while checking for the response
>> body.
>> The VM isn't paused tho because the IdleConnectionHandler is
> continuing
>> to fire and (I think) eventually is responsible for closing the
>> connection. That is why we aren't getting a connection reset from the
>> loadbalancer in this case.
>>
>> So what in the world would would cause it to sit there?
>>  
> 
> The method blocks because the server is not sending any data whereas it 
> clearly should be sending at least the closing chunk.
> 
> I do not see anything that could suggest there is a problem on the 
> client side.
> 
> Oleg
> 
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
> For additional commands, e-mail: httpclient-users-help@hc.apache.org
> 
> This transmission may contain information that is privileged,
> confidential, legally privileged, and/or exempt from disclosure
> under applicable law.  If you are not the intended recipient, you
> are hereby notified that any disclosure, copying, distribution, or
> use of the information contained herein (including any reliance
> thereon) is STRICTLY PROHIBITED.  Although this transmission and
> any attachments are believed to be free of any virus or other
> defect that might affect any computer system into which it is
> received and opened, it is the responsibility of the recipient to
> ensure that it is virus free and no responsibility is accepted by
> JPMorgan Chase & Co., its subsidiaries and affiliates, as
> applicable, for any loss or damage arising in any way from its use.
>  If you received this transmission in error, please immediately
> contact the sender and destroy the material in its entirety,
> whether in electronic or hard copy format. Thank you.
> 
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
> For additional commands, e-mail: httpclient-users-help@hc.apache.org
> 


---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
For additional commands, e-mail: httpclient-users-help@hc.apache.org


RE: HttpConnection.isResponseAvailable

Posted by ke...@chase.com.
Please validate this statement.

The IdleConnectionHandler kept firing past 20 seconds (my configured
timeout value) because that connection was still active and waiting for
data.
So it wasn't the IdleConnectionHandler that closed the socket, otherwise
I would have seen the following message "Closing connection, connection
time:".




That makes sense now looking at the source, because it looks like
HttpMethodDirector caught an exception because that is where the stack
is reporting it.. 

                } catch (IOException e) {
                    LOG.debug("Closing the connection.");
                    this.conn.close();

and then just a little past that we see it saying that it did not retry
(I'm using a default retry handler) and throws the exception back to the
client.. which logged the Connection Reset.
                    if (!handler.retryMethod(method, e, execCount)) {
                        LOG.debug("Method retry handler returned false.
"
                                + "Automatic recovery will not be
attempted");
                        throw e;
                    }


Thanks for all of your input Oleg.. It is much appreciated.



-----Original Message-----
From: Oleg Kalnichevski [mailto:olegk@apache.org] 
Sent: Wednesday, November 25, 2009 5:12 PM
To: HttpClient User Discussion
Subject: Re: HttpConnection.isResponseAvailable

kenneth.s.brooks@chase.com wrote:
> Related to previous post: Infinite loop in ChunkedInputStream.close
> 
> Oleg,
> 
> Last week I posted about an issue where we got the request body, and
> when close is called on the input stream it gets to the underlying
> InputStream.read and just sits there.
> We ran some more tests with httpclient wire logging on and we captured
a
> slightly different issue but stemming from the same apparent
underlying
> call.
> 
> Both the previous issue and this one are both sitting idle at a call
to
> SocketInputStream.read (see the 'Client Log' further down this post
> showing the stack trace where it is sitting).
> 
> From what I see below it looks like the reply started to come, we get
> the headers.. but it is sitting idle while checking for the response
> body.
> The VM isn't paused tho because the IdleConnectionHandler is
continuing
> to fire and (I think) eventually is responsible for closing the
> connection. That is why we aren't getting a connection reset from the
> loadbalancer in this case.
> 
> So what in the world would would cause it to sit there?
>  

The method blocks because the server is not sending any data whereas it 
clearly should be sending at least the closing chunk.

I do not see anything that could suggest there is a problem on the 
client side.

Oleg

---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
For additional commands, e-mail: httpclient-users-help@hc.apache.org

This transmission may contain information that is privileged,
confidential, legally privileged, and/or exempt from disclosure
under applicable law.  If you are not the intended recipient, you
are hereby notified that any disclosure, copying, distribution, or
use of the information contained herein (including any reliance
thereon) is STRICTLY PROHIBITED.  Although this transmission and
any attachments are believed to be free of any virus or other
defect that might affect any computer system into which it is
received and opened, it is the responsibility of the recipient to
ensure that it is virus free and no responsibility is accepted by
JPMorgan Chase & Co., its subsidiaries and affiliates, as
applicable, for any loss or damage arising in any way from its use.
 If you received this transmission in error, please immediately
contact the sender and destroy the material in its entirety,
whether in electronic or hard copy format. Thank you.

---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
For additional commands, e-mail: httpclient-users-help@hc.apache.org


Re: HttpConnection.isResponseAvailable

Posted by Oleg Kalnichevski <ol...@apache.org>.
kenneth.s.brooks@chase.com wrote:
> Related to previous post: Infinite loop in ChunkedInputStream.close
> 
> Oleg,
> 
> Last week I posted about an issue where we got the request body, and
> when close is called on the input stream it gets to the underlying
> InputStream.read and just sits there.
> We ran some more tests with httpclient wire logging on and we captured a
> slightly different issue but stemming from the same apparent underlying
> call.
> 
> Both the previous issue and this one are both sitting idle at a call to
> SocketInputStream.read (see the 'Client Log' further down this post
> showing the stack trace where it is sitting).
> 
> From what I see below it looks like the reply started to come, we get
> the headers.. but it is sitting idle while checking for the response
> body.
> The VM isn't paused tho because the IdleConnectionHandler is continuing
> to fire and (I think) eventually is responsible for closing the
> connection. That is why we aren't getting a connection reset from the
> loadbalancer in this case.
> 
> So what in the world would would cause it to sit there?
>  

The method blocks because the server is not sending any data whereas it 
clearly should be sending at least the closing chunk.

I do not see anything that could suggest there is a problem on the 
client side.

Oleg

---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
For additional commands, e-mail: httpclient-users-help@hc.apache.org


HttpConnection.isResponseAvailable

Posted by ke...@chase.com.
Related to previous post: Infinite loop in ChunkedInputStream.close

Oleg,

Last week I posted about an issue where we got the request body, and
when close is called on the input stream it gets to the underlying
InputStream.read and just sits there.
We ran some more tests with httpclient wire logging on and we captured a
slightly different issue but stemming from the same apparent underlying
call.

Both the previous issue and this one are both sitting idle at a call to
SocketInputStream.read (see the 'Client Log' further down this post
showing the stack trace where it is sitting).

From what I see below it looks like the reply started to come, we get
the headers.. but it is sitting idle while checking for the response
body.
The VM isn't paused tho because the IdleConnectionHandler is continuing
to fire and (I think) eventually is responsible for closing the
connection. That is why we aren't getting a connection reset from the
loadbalancer in this case.

So what in the world would would cause it to sit there?


As a little bit of a sidenote, we set the idleconnectiontimeout to 20
seconds.
        DEFAULT_PROPERTIES.setProperty(HTTP_IDLE_CONNECTION_TIMEOUT,
"20000");
 
DEFAULT_PROPERTIES.setProperty(HTTP_IDLE_CONNECTION_CHECK_INTERVAL,
"1000");

        IdleConnectionTimeoutThread idleConnectionTimeoutThread = new
IdleConnectionTimeoutThread();
 
idleConnectionTimeoutThread.setConnectionTimeout(ClientPropertyLocator.g
etInstance().getIntProperty(ClientPropertyLocator.HTTP_IDLE_CONNECTION_T
IMEOUT));
 
idleConnectionTimeoutThread.setTimeoutInterval(ClientPropertyLocator.get
Instance().getIntProperty(ClientPropertyLocator.HTTP_IDLE_CONNECTION_CHE
CK_INTERVAL));
 
idleConnectionTimeoutThread.addConnectionManager(connectionManager);
        idleConnectionTimeoutThread.start();
I'm a little confused as to why it waited 60 seconds. Only bringing it
up in case it is somehow relevant.


Thanks,
ken




==============
= HttpClient Wire log
==============


2009-11-25 01:58:25,714 DEBUG methods.PostMethod (PostMethod.java:152)
- enter PostMethod.clearRequestBody()
2009-11-25 01:58:25,714 DEBUG methods.EntityEnclosingMethod
(EntityEnclosingMethod.java:150)    - enter
EntityEnclosingMethod.clearRequestBody()
2009-11-25 01:58:25,714 DEBUG httpclient.HttpClient
(HttpClient.java:321)    - enter HttpClient.executeMethod(HttpMethod)
2009-11-25 01:58:25,714 DEBUG httpclient.HttpClient
(HttpClient.java:374)    - enter
HttpClient.executeMethod(HostConfiguration,HttpMethod,HttpState)
2009-11-25 01:58:25,714 DEBUG
httpclient.MultiThreadedHttpConnectionManager
(MultiThreadedHttpConnectionManager.java:405)    - enter
HttpConnectionManager.getConnectionWithTimeout(HostConfiguration, long)
2009-11-25 01:58:25,714 DEBUG
httpclient.MultiThreadedHttpConnectionManager
(MultiThreadedHttpConnectionManager.java:412)    -
HttpConnectionManager.getConnection:  config =
HostConfiguration[host=http://prf-services.mycompany.net:9810], timeout
= 0
2009-11-25 01:58:25,714 DEBUG
httpclient.MultiThreadedHttpConnectionManager
(MultiThreadedHttpConnectionManager.java:805)    - enter
HttpConnectionManager.ConnectionPool.getHostPool(HostConfiguration)
2009-11-25 01:58:25,714 DEBUG
httpclient.MultiThreadedHttpConnectionManager
(MultiThreadedHttpConnectionManager.java:805)    - enter
HttpConnectionManager.ConnectionPool.getHostPool(HostConfiguration)
2009-11-25 01:58:25,714 DEBUG
httpclient.MultiThreadedHttpConnectionManager
(MultiThreadedHttpConnectionManager.java:839)    - Getting free
connection,
hostConfig=HostConfiguration[host=http://prf-services.mycompany.net:9810
]
2009-11-25 01:58:25,714 DEBUG httpclient.HttpMethodDirector
(HttpMethodDirector.java:379)    - Attempt number 1 to process request
2009-11-25 01:58:25,714 DEBUG httpclient.HttpMethodBase
(HttpMethodBase.java:1079)    - enter HttpMethodBase.execute(HttpState,
HttpConnection)
2009-11-25 01:58:25,714 DEBUG httpclient.HttpMethodBase
(HttpMethodBase.java:2057)    - enter
HttpMethodBase.writeRequest(HttpState, HttpConnection)
2009-11-25 01:58:25,714 DEBUG httpclient.HttpMethodBase
(HttpMethodBase.java:2212)    - enter
HttpMethodBase.writeRequestLine(HttpState, HttpConnection)
2009-11-25 01:58:25,714 DEBUG httpclient.HttpMethodBase
(HttpMethodBase.java:1496)    - enter
HttpMethodBase.generateRequestLine(HttpConnection, String, String,
String, String)
2009-11-25 01:58:25,714 DEBUG wire.header       (Wire.java:70)    - >>
"POST /cms.rcts/2009.9.1.006/ccs/prf.lr/2008.8.1/CDC/essd-remote/
HTTP/1.1[\r][\n]"
2009-11-25 01:58:25,714 DEBUG httpclient.HttpConnection
(HttpConnection.java:1032)    - enter HttpConnection.print(String)
2009-11-25 01:58:25,714 DEBUG httpclient.HttpConnection
(HttpConnection.java:942)    - enter HttpConnection.write(byte[])
2009-11-25 01:58:25,714 DEBUG httpclient.HttpConnection
(HttpConnection.java:963)    - enter HttpConnection.write(byte[], int,
int)
2009-11-25 01:58:25,714 DEBUG httpclient.HttpMethodBase
(HttpMethodBase.java:2175)    - enter
HttpMethodBase.writeRequestHeaders(HttpState,HttpConnection)
2009-11-25 01:58:25,714 DEBUG methods.EntityEnclosingMethod
(EntityEnclosingMethod.java:370)    - enter
EntityEnclosingMethod.addRequestHeaders(HttpState, HttpConnection)
2009-11-25 01:58:25,714 DEBUG methods.ExpectContinueMethod
(ExpectContinueMethod.java:183)    - enter
ExpectContinueMethod.addRequestHeaders(HttpState, HttpConnection)
2009-11-25 01:58:25,714 DEBUG httpclient.HttpMethodBase
(HttpMethodBase.java:1417)    - enter
HttpMethodBase.addRequestHeaders(HttpState, HttpConnection)
2009-11-25 01:58:25,714 DEBUG httpclient.HttpMethodBase
(HttpMethodBase.java:1442)    - enter
HttpMethodBase.addUserAgentRequestHeaders(HttpState, HttpConnection)
2009-11-25 01:58:25,714 DEBUG httpclient.HttpMethodBase
(HttpMethodBase.java:1328)    - enter
HttpMethodBase.addHostRequestHeader(HttpState, HttpConnection)
2009-11-25 01:58:25,714 DEBUG httpclient.HttpMethodBase
(HttpMethodBase.java:1352)    - Adding Host request header
2009-11-25 01:58:25,714 DEBUG httpclient.HttpMethodBase
(HttpMethodBase.java:1266)    - enter
HttpMethodBase.addCookieRequestHeader(HttpState, HttpConnection)
2009-11-25 01:58:25,714 DEBUG httpclient.HttpState (HttpState.java:173)
- enter HttpState.getCookies()
2009-11-25 01:58:25,714 DEBUG httpclient.HttpMethodBase
(HttpMethodBase.java:1379)    - enter
HttpMethodBase.addProxyConnectionHeader(HttpState, HttpConnection)
2009-11-25 01:58:25,714 DEBUG methods.EntityEnclosingMethod
(EntityEnclosingMethod.java:401)    - enter
EntityEnclosingMethod.addContentLengthRequestHeader(HttpState,
HttpConnection)
2009-11-25 01:58:25,714 DEBUG methods.EntityEnclosingMethod
(EntityEnclosingMethod.java:325)    - enter
EntityEnclosingMethod.getRequestContentLength()
2009-11-25 01:58:25,714 DEBUG methods.PostMethod (PostMethod.java:135)
- enter PostMethod.hasRequestContent()
2009-11-25 01:58:25,714 DEBUG methods.EntityEnclosingMethod
(EntityEnclosingMethod.java:135)    - enter
EntityEnclosingMethod.hasRequestContent()
2009-11-25 01:58:25,730 DEBUG httpclient.HttpMethodBase
(HttpMethodBase.java:386)    - HttpMethodBase.addRequestHeader(Header)
2009-11-25 01:58:25,730 DEBUG wire.header       (Wire.java:70)    - >>
"Content-Type: application/x-java-serialized-object[\r][\n]"
2009-11-25 01:58:25,730 DEBUG httpclient.HttpConnection
(HttpConnection.java:1032)    - enter HttpConnection.print(String)
2009-11-25 01:58:25,730 DEBUG httpclient.HttpConnection
(HttpConnection.java:942)    - enter HttpConnection.write(byte[])
2009-11-25 01:58:25,730 DEBUG httpclient.HttpConnection
(HttpConnection.java:963)    - enter HttpConnection.write(byte[], int,
int)
2009-11-25 01:58:25,730 DEBUG wire.header       (Wire.java:70)    - >>
"Content-Encoding: none[\r][\n]"
2009-11-25 01:58:25,730 DEBUG httpclient.HttpConnection
(HttpConnection.java:1032)    - enter HttpConnection.print(String)
2009-11-25 01:58:25,730 DEBUG httpclient.HttpConnection
(HttpConnection.java:942)    - enter HttpConnection.write(byte[])
2009-11-25 01:58:25,730 DEBUG httpclient.HttpConnection
(HttpConnection.java:963)    - enter HttpConnection.write(byte[], int,
int)
2009-11-25 01:58:25,730 DEBUG wire.header       (Wire.java:70)    - >>
"Serialization-Type: java[\r][\n]"
2009-11-25 01:58:25,730 DEBUG httpclient.HttpConnection
(HttpConnection.java:1032)    - enter HttpConnection.print(String)
2009-11-25 01:58:25,730 DEBUG httpclient.HttpConnection
(HttpConnection.java:942)    - enter HttpConnection.write(byte[])
2009-11-25 01:58:25,730 DEBUG httpclient.HttpConnection
(HttpConnection.java:963)    - enter HttpConnection.write(byte[], int,
int)
2009-11-25 01:58:25,730 DEBUG wire.header       (Wire.java:70)    - >>
"User-Agent: Jakarta Commons-HttpClient/3.1[\r][\n]"
2009-11-25 01:58:25,730 DEBUG httpclient.HttpConnection
(HttpConnection.java:1032)    - enter HttpConnection.print(String)
2009-11-25 01:58:25,730 DEBUG httpclient.HttpConnection
(HttpConnection.java:942)    - enter HttpConnection.write(byte[])
2009-11-25 01:58:25,730 DEBUG httpclient.HttpConnection
(HttpConnection.java:963)    - enter HttpConnection.write(byte[], int,
int)
2009-11-25 01:58:25,730 DEBUG wire.header       (Wire.java:70)    - >>
"Host: prf-services.mycompany.net:9810[\r][\n]"
2009-11-25 01:58:25,730 DEBUG httpclient.HttpConnection
(HttpConnection.java:1032)    - enter HttpConnection.print(String)
2009-11-25 01:58:25,730 DEBUG httpclient.HttpConnection
(HttpConnection.java:942)    - enter HttpConnection.write(byte[])
2009-11-25 01:58:25,730 DEBUG httpclient.HttpConnection
(HttpConnection.java:963)    - enter HttpConnection.write(byte[], int,
int)
2009-11-25 01:58:25,730 DEBUG wire.header       (Wire.java:70)    - >>
"Content-Length: 5179[\r][\n]"
2009-11-25 01:58:25,730 DEBUG httpclient.HttpConnection
(HttpConnection.java:1032)    - enter HttpConnection.print(String)
2009-11-25 01:58:25,730 DEBUG httpclient.HttpConnection
(HttpConnection.java:942)    - enter HttpConnection.write(byte[])
2009-11-25 01:58:25,730 DEBUG httpclient.HttpConnection
(HttpConnection.java:963)    - enter HttpConnection.write(byte[], int,
int)
2009-11-25 01:58:25,730 DEBUG httpclient.HttpConnection
(HttpConnection.java:1001)    - enter HttpConnection.writeLine()
2009-11-25 01:58:25,730 DEBUG httpclient.HttpConnection
(HttpConnection.java:942)    - enter HttpConnection.write(byte[])
2009-11-25 01:58:25,730 DEBUG httpclient.HttpConnection
(HttpConnection.java:963)    - enter HttpConnection.write(byte[], int,
int)
2009-11-25 01:58:25,730 DEBUG wire.header       (Wire.java:70)    - >>
"[\r][\n]"
2009-11-25 01:58:25,730 DEBUG methods.EntityEnclosingMethod
(EntityEnclosingMethod.java:469)    - enter
EntityEnclosingMethod.writeRequestBody(HttpState, HttpConnection)
2009-11-25 01:58:25,730 DEBUG methods.PostMethod (PostMethod.java:135)
- enter PostMethod.hasRequestContent()
2009-11-25 01:58:25,730 DEBUG methods.EntityEnclosingMethod
(EntityEnclosingMethod.java:135)    - enter
EntityEnclosingMethod.hasRequestContent()
2009-11-25 01:58:25,730 DEBUG methods.EntityEnclosingMethod
(EntityEnclosingMethod.java:325)    - enter
EntityEnclosingMethod.getRequestContentLength()
2009-11-25 01:58:25,730 DEBUG methods.PostMethod (PostMethod.java:135)
- enter PostMethod.hasRequestContent()
2009-11-25 01:58:25,730 DEBUG methods.EntityEnclosingMethod
(EntityEnclosingMethod.java:135)    - enter
EntityEnclosingMethod.hasRequestContent()
2009-11-25 01:58:25,730 DEBUG httpclient.HttpConnection
(HttpConnection.java:840)    - enter
HttpConnection.getRequestOutputStream()
2009-11-25 01:58:25,730 DEBUG wire.content      (Wire.java:70)    - >>
"[0xac][0xed][0x0][0x5]sr[0x0]?com.fusa.ssg.infra.remoting.common.suppor
t.RemoteServiceRequest
[0x1b][0xcb][0xf7][0xe2].[0x14]o[0x2][0x0][0x5][[0x0][0x9]argumentst[0x0
][0x13][Ljava/lang/Object;L[0x0][\n]"
2009-11-25 01:58:25,730 DEBUG wire.content      (Wire.java:70)    - >>
"methodNamet[0x0][0x12]Ljava/lang/String;[[0x0][0xe]parameterTypest[0x0]
[0x12][Ljava/lang/Class;L[0x0][\r]securityTokenq[0x0]~[0x0][0x2]L[0x0][0
x10]serviceInterfacet[0x0][0x11]Ljava/lang/Class;xr[0x0]:com.fusa.ssg.in
fra.remoting.common.support.AttributeHolder[0xd6]][0xd8][0xc0][0xce]N[0x
85][0xa4][0x2][0x0][0x1]L[0x0][\n]"
2009-11-25 01:58:25,730 DEBUG wire.content      (Wire.java:70)    - >>
"attributest[0x0][0xf]Ljava/util/Map;xpsr[0x0][0x11]java.util.HashMap[0x
5][0x7][0xda][0xc1][0xc3][0x16]`[0xd1][0x3][0x0][0x2]F[0x0][\n]"
2009-11-25 01:58:25,730 DEBUG wire.content      (Wire.java:70)    - >>
"loadFactorI[0x0][0x9]thresholdxp?@[0x0][0x0][0x0][0x0][0x0][0xc]w[0x8][
0x0][0x0][0x0][0x10][0x0][0x0][0x0][0x1]t[0x0][0x9]auditInfosr[0x0][0x1f
]com.fusa.ssg.datatype.AuditInfo[0xa2][0xa9]5[0xc3][0xba]x@[0x93][0x2][0
x0][0x7]L[0x0][\r]correlationIdq[0x0]~[0x0][0x2]L[0x0][0x8]mChannelq[0x0
]~[0x0][0x2]L[0x0][0xc]mClientEvtIdq[0x0]~[0x0][0x2]L[0x0][0xe]mParentAu
ditIdt[0x0][0x10]Ljava/lang/Long;L[0x0][0xb]mPropertiesq[0x0]~[0x0][0x6]
L[0x0][0x7]mUserIdq[0x0]~[0x0][0x2]L[0x0][\n]"
2009-11-25 01:58:25,745 DEBUG wire.content      (Wire.java:70)    - >>
"operatorIdq[0x0]~[0x0][0x2]xpt[0x0]-ltu068_scd2nts044_-77fec0ce:125299e
cace:-7e72t[0x0][0x4]testppsr[0x0]%java.util.Collections$SynchronizedMap
[0x1b]s[0xf9][0x9]KK9{[0x3][0x0][0x2]L[0x0][0x1]mq[0x0]~[0x0][0x6]L[0x0]
[0x5]mutext[0x0][0x12]Ljava/lang/Object;xpsq[0x0]~[0x0][0x8]?@[0x0][0x0]
[0x0][0x0][0x0][0xc]w[0x8][0x0][0x0][0x0][0x10][0x0][0x0][0x0][0x5]t[0x0
][0xe]client-versiont[0x0][0xc]2009.9.1.006t[0x0][0x10]weblogic-versiont
[0x0][0x8]10.0.1.0t[0x0][\r]infra-versiont[0x0][0x9]4.3.PERF4t[0x0][0xc]
java-versiont[0x0][0x8]1.5.0_11t[0x0][0x7]machinet[0x0][0x1a]scd2nts044.
svr.bankone.netxq[0x0]~[0x0][0x12]xt[0x0][0x6]ltu068pxur[0x0][0x13][Ljav
a.lang.Object;[0x90][0xce]X[0x9f][0x10]s)l[0x2][0x0][0x0]xp[0x0][0x0][0x
0][0x3]sr[0x0][0xe]java.lang.Long;[0x8b][0xe4][0x90][0xcc][0x8f]#[0xdf][
0x2][0x0][0x1]J[0x0][0x5]valuexr[0x0][0x10]java.lang.Number[0x86][0xac][
0x95][0x1d][0xb][0x94][0xe0][0x8b][0x2][0x0][0x0]xp[0x0][0x0][0x0][0x0]D
yT[0xc6]sq[0x0]~[0x0]![0x0][0x0][0x0][0x0][0x0][0x0][0x3][0xe8]sr[0x0]*c
om.ccs.cco.cms.rcts.calltracking.WorkFlow[0xfe][0x99][0x15][0x2]&iy[0xf]
[0x2][0x0][0x2][[0x0][0x7]actionst[0x0]+[Lcom/ccs/cco/cms/rcts/calltrack
ing/Action;L[0x0][0xe]workFlowRecordt[0x0]2Lcom/ccs/cco/cms/rcts/calltra
cking/WorkFlowRecord;xpur[0x0]+[Lcom.ccs.cco.cms.rcts.calltracking.Actio
n;k[0xc6][[0xf4]2tY[0xd1][0x2][0x0][0x0]xp[0x0][0x0][0x0][0x1]sr[0x0](co
m.ccs.cco.cms.rcts.calltracking.Action[0xc][\r]$'D[0xaa][0x88]8[0x2][0x0
][0x5]L[0x0][0xc]actionRecordt[0x0]0Lcom/ccs/cco/cms/rcts/calltracking/A
ctionRecord;[[0x0][0xb]charRecordst[0x0]/[Lcom/ccs/cco/cms/rcts/calltrac
king/CharRecord;[[0x0][0xb]flagRecordst[0x0]/[Lcom/ccs/cco/cms/rcts/call
tracking/FlagRecord;[[0x0][0xc]floatRecordst[0x0]0[Lcom/ccs/cco/cms/rcts
/calltracking/FloatRecord;[[0x0][\n]"
2009-11-25 01:58:25,745 DEBUG wire.content      (Wire.java:70)    - >>
"intRecordst[0x0].[Lcom/ccs/cco/cms/rcts/calltracking/IntRecord;xpsr[0x0
].com.ccs.cco.cms.rcts.calltracking.ActionRecord[0xa7]Z[0x85][0xb3]/[0x9
e][0xdd][0x8d][0x2][0x0][0x8]L[0x0][0x11]callActnRsnTypeCdq[0x0]~[0x0][0
x2]L[0x0][0xe]callActnTypeCdq[0x0]~[0x0][0x2]L[0x0][\r]failureReasonq[0x
0]~[0x0][0x2]L[0x0][0xc]failutreTypeq[0x0]~[0x0][0x2]L[0x0][0xe]override
Reasonq[0x0]~[0x0][0x2]L[0x0][0xc]overrideTypeq[0x0]~[0x0][0x2]L[0x0][0x
8]passFailq[0x0]~[0x0][0x2]L[0x0][0xe]requrestorTypeq[0x0]~[0x0][0x2]xpt
[0x0][0x3]000t[0x0][0x3]300t[0x0][0x3]Perq[0x0]~[0x0]6q[0x0]~[0x0]6q[0x0
]~[0x0]4t[0x0][0x1]Yt[0x0][0x1]0ur[0x0]/[Lcom.ccs.cco.cms.rcts.calltrack
ing.CharRecord;][0xa3]f9[0xb6][0xca][0x91][0x88][0x2][0x0][0x0]xp[0x0][0
x0][0x0][0x1]sr[0x0],com.ccs.cco.cms.rcts.calltracking.CharRecord~[0xc0]
[0xba][0x83][0x91][0xe9][0xe9]f[0x2][0x0][0x4]L[0x0][0x5]char1q[0x0]~[0x
0][0x2]L[0x0][0x9]char1Typeq[0x0]~[0x0][0x2]L[0x0][0x5]char2q[0x0]~[0x0]
[0x2]L[0x0][0x9]char2Typeq[0x0]~[0x0][0x2]xpt[0x0][0xb]Perf
Authort[0x0][0x3]226q[0x0]~[0x0]=q[0x0]~[0x0]>ur[0x0]/[Lcom.ccs.cco.cms.
rcts.calltracking.FlagRecord;[0x19][0xed][0xc4][0xaa][0x9c]%s[0xe8][0x2]
[0x0][0x0]xp[0x0][0x0][0x0][0x1]sr[0x0],com.ccs.cco.cms.rcts.calltrackin
g.FlagRecord[0x17][0xb9][0xca]$[0x93][\r][0x12]^[0x2][0x0][0x4]L[0x0][0x
5]flag1q[0x0]~[0x0][0x2]L[0x0][0x9]flag1Typeq[0x0]~[0x0][0x2]L[0x0][0x5]
flag2q[0x0]~[0x0][0x2]L[0x0][0x9]flag2Typeq[0x0]~[0x0][0x2]xpt[0x0][0x1]
Ct[0x0][0x3]024t[0x0][0x1]Pq[0x0]~[0x0]4ur[0x0]0[Lcom.ccs.cco.cms.rcts.c
alltracking.FloatRecord;[0x84]W]k[0xe4][0x16][0x93]C[0x2][0x0][0x0]xp[0x
0][0x0][0x0][0x1]sr[0x0]-com.ccs.cco.cms.rcts.calltracking.FloatRecord"[
0xc6]}[0xdf][0xf0]![0xfb][0xd7][0x2][0x0][0x4]D[0x0][0x6]float1D[0x0][0x
6]float2L[0x0][\n]"
2009-11-25 01:58:25,745 DEBUG wire.content      (Wire.java:70)    - >>
"float1Typeq[0x0]~[0x0][0x2]L[0x0][\n]"
2009-11-25 01:58:25,745 DEBUG wire.content      (Wire.java:70)    - >>
"float2Typeq[0x0]~[0x0][0x2]xp@([0x0][0x0][0x0][0x0][0x0][0x0][0x0][0x0]
[0x0][0x0][0x0][0x0][0x0][0x0]t[0x0][0x3]050q[0x0]~[0x0]4ur[0x0].[Lcom.c
cs.cco.cms.rcts.calltracking.IntRecord;[0xbe][0xb1][0x97][0xe3][0xe0][0x
9]jw[0x2][0x0][0x0]xp[0x0][0x0][0x0][0x1]sr[0x0]+com.ccs.cco.cms.rcts.ca
lltracking.IntRecordz[0xea]>[0x8f]A[0xcd][0x8d][0xe2][0x2][0x0][0x4]J[0x
0][0x4]int1J[0x0][0x4]int2L[0x0][0x8]int1Typeq[0x0]~[0x0][0x2]L[0x0][0x8
]int2Typeq[0x0]~[0x0][0x2]xp[0x0][0x0][0x0][0x0][0x0][0x0][0x0][0x0][0x0
][0x0][0x0][0x0][0x0][0x0][0x0][0x0]t[0x0][0x3]004q[0x0]~[0x0]4sr[0x0]0c
om.ccs.cco.cms.rcts.calltracking.WorkFlowRecord[0xac][0x9a][0x81][0xcf][
0xeb][0x80][0xb7]&[0x2][0x0][0x7]I[0x0][\n]"
2009-11-25 01:58:25,745 DEBUG wire.content      (Wire.java:70)    - >>
"wfIntFlag1I[0x0][\n]"
2009-11-25 01:58:25,745 DEBUG wire.content      (Wire.java:84)    - >>
"wfIntFlag2J[0x0][0xf]wrkFlowDurationL[0x0][0xb]wfCharFlag1q[0x0]~[0x0][
0x2]L[0x0][0xb]wfCharFlag2q[0x0]~[0x0][0x2]L[0x0][\r]wfPreventableq[0x0]
~[0x0][0x2]L[0x0][\r]wrkFlowTypeCdq[0x0]~[0x0][0x2]xp[0x0][0x0][0x0][0x0
][0x0][0x0][0x0][0x0][0x0][0x0][0x0][0x0][0x0][0x0][0x0][0x3]t[0x0][0x1]
Nq[0x0]~[0x0]Rq[0x0]~[0x0]Rt[0x0][0x2]CCt[0x0][0xe]insertWorkFlowur[0x0]
[0x12][Ljava.lang.Class;[0xab][0x16][0xd7][0xae][0xcb][0xcd]Z[0x99][0x2]
[0x0][0x0]xp[0x0][0x0][0x0][0x3]vr[0x0][0x4]long[0x0][0x0][0x0][0x0][0x0
][0x0][0x0][0x0][0x0][0x0][0x0]xpq[0x0]~[0x0]Xvq[0x0]~[0x0]%t[0x7][0x94]
rO0ABXNyABtqYXZheC5zZWN1cml0eS5hdXRoLlN1YmplY3SMsjKTADP6aAMAAloACHJlYWRP
bmx5TAAKcHJpbmNpcGFsc3QAD0xqYXZhL3V0aWwvU2V0O3hwAHNyACVqYXZhLnV0aWwuQ29s
bGVjdGlvbnMkU3luY2hyb25pemVkU2V0BsPCeQLu3zwCAAB4cgAsamF2YS51dGlsLkNvbGxl
Y3Rpb25zJFN5bmNocm9uaXplZENvbGxlY3Rpb24qYfhNCZyZtQMAAkwAAWN0ABZMamF2YS91
dGlsL0NvbGxlY3Rpb247TAAFbXV0ZXh0ABJMamF2YS9sYW5nL09iamVjdDt4cHNyACVqYXZh
eC5zZWN1cml0eS5hdXRoLlN1YmplY3QkU2VjdXJlU2V0bcwygBdVficDAANJAAV3aGljaEwA
CGVsZW1lbnRzdAAWTGphdmEvdXRpbC9MaW5rZWRMaXN0O0wABnRoaXMkMHQAHUxqYXZheC9z
ZWN1cml0eS9hdXRoL1N1YmplY3Q7eHAAAAABc3IAFGphdmEudXRpbC5MaW5rZWRMaXN0DClT
XUpgiCIDAAB4cHcEAAAAAXN9AAAAAwAdd2VibG9naWMuc2VjdXJpdHkuc3BpLldMU1VzZXIA
KHdlYmxvZ2ljLnNlY3VyaXR5LnByaW5jaXBhbC5XTFNQcmluY2lwYWwAK2NvbS5mdXNhLnNz
Zy5pbmZyYS5zZWN1cml0eS5QcmluY2lwYWxIb2xkZXJ4cgAXamF2YS5sYW5nLnJlZmxlY3Qu
UHJveHnhJ9ogzBBDywIAAUwAAWh0ACVMamF2YS9sYW5nL3JlZmxlY3QvSW52b2NhdGlvbkhh
bmRsZXI7eHBzcgAuY29tLmZ1c2Euc3NnLmluZnJhLnNlY3VyaXR5LndsczgxLkNoYXNlV0xT
VXNlcg75OGXwolXPAgABTAAJY2hhc2VVc2VydAAtTGNvbS9mdXNhL3NzZy9pbmZyYS9zZWN1
cml0eS93bHM4MS9DaGFzZVVzZXI7eHIAL2NvbS5mdXNhLnNzZy5pbmZyYS5zZWN1cml0eS53
bHM4MS5CYXNlRGVjb3JhdG9ygZrIJ67g9dACAAFMAA13cmFwcGVkT2JqZWN0cQB+AAZ4cHNy
ACd3ZWJsb2dpYy5zZWN1cml0eS5wcmluY2lwYWwuV0xTVXNlckltcGy+Djjr39dsVQIAAHhy
ADB3ZWJsb2dpYy5zZWN1cml0eS5wcmluY2lwYWwuV0xTQWJzdHJhY3RQcmluY2lwYWyv/kb+
QWV+/AIAA0wABG5hbWV0ABJMamF2YS9sYW5nL1N0cmluZztbAARzYWx0dAACW0JbAAlzaWdu
YXR1cmVxAH4AGXhwdAAtbHR1MDY4L0N1c3RvbWVycmVwL1JlYXNvbl9Ob25lL0xUVTA2OC9T
TS90ZXN0dXIAAltCrPMX+AYIVOACAAB4cAAAAA0xMjU5MTIzNjkxMTI3dXEAfgAcAAAAEIxW
t0XEyA0po8iKakip1xZzcgArY29tLmZ1c2Euc3NnLmluZnJhLnNlY3VyaXR5LndsczgxLkNo
YXNlVXNlcsAgWGdf7AYfAgACTAAIdXNlck5hbWVxAH4AGEwACXVzZXJQcm9wc3QAFkxqYXZh
L3V0aWwvUHJvcGVydGllczt4cHQALWx0dTA2OC9DdXN0b21lcnJlcC9SZWFzb25fTm9uZS9M
VFUwNjgvU00vdGVzdHNyABRqYXZhLnV0aWwuUHJvcGVydGllczkS0HpwNj6YAgABTAAIZGVm
YXVsdHNxAH4AIHhyABNqYXZhLnV0aWwuSGFzaHRhYmxlE7sPJSFK5LgDAAJGAApsb2FkRmFj
dG9ySQAJdGhyZXNob2xkeHA/QAAAAAAACHcIAAAACwAAAAB4cHhxAH4AAnhxAH4AB3h4vr[0
x0]6com.ccs.cco.cms.rcts.calltracking.ICallTrackingService[0x0][0x0][0x0
][0x0][0x0][0x0][0x0][0x0][0x0][0x0][0x0]xp"
2009-11-25 01:58:25,745 DEBUG methods.EntityEnclosingMethod
(EntityEnclosingMethod.java:508)    - Request body sent
2009-11-25 01:58:25,745 DEBUG httpclient.HttpConnection
(HttpConnection.java:826)    - enter
HttpConnection.flushRequestOutputStream()
2009-11-25 01:58:25,745 DEBUG httpclient.HttpMethodBase
(HttpMethodBase.java:1730)    - enter
HttpMethodBase.readResponse(HttpState, HttpConnection)
2009-11-25 01:58:25,745 DEBUG httpclient.HttpMethodBase
(HttpMethodBase.java:1964)    - enter
HttpMethodBase.readStatusLine(HttpState, HttpConnection)
2009-11-25 01:58:25,745 DEBUG httpclient.HttpConnection
(HttpConnection.java:1113)    - enter HttpConnection.readLine()
2009-11-25 01:58:25,745 DEBUG httpclient.HttpParser
(HttpParser.java:105)    - enter HttpParser.readLine(InputStream,
String)
2009-11-25 01:58:25,745 DEBUG httpclient.HttpParser (HttpParser.java:74)
- enter HttpParser.readRawLine()
2009-11-25 01:58:25,761 DEBUG wire.header       (Wire.java:70)    - <<
"HTTP/1.1 200 OK[\r][\n]"
2009-11-25 01:58:25,761 DEBUG wire.header       (Wire.java:70)    - <<
"HTTP/1.1 200 OK[\r][\n]"
2009-11-25 01:58:25,761 DEBUG httpclient.HttpMethodBase
(HttpMethodBase.java:1930)    - enter
HttpMethodBase.readResponseHeaders(HttpState,HttpConnection)
2009-11-25 01:58:25,761 DEBUG httpclient.HttpConnection
(HttpConnection.java:857)    - enter
HttpConnection.getResponseInputStream()
2009-11-25 01:58:25,761 DEBUG httpclient.HttpParser
(HttpParser.java:170)    - enter HeaderParser.parseHeaders(InputStream,
String)
2009-11-25 01:58:25,761 DEBUG httpclient.HttpParser
(HttpParser.java:105)    - enter HttpParser.readLine(InputStream,
String)
2009-11-25 01:58:25,761 DEBUG httpclient.HttpParser (HttpParser.java:74)
- enter HttpParser.readRawLine()
2009-11-25 01:58:25,761 DEBUG wire.header       (Wire.java:70)    - <<
"Date: Wed, 25 Nov 2009 06:58:27 GMT[\r][\n]"
2009-11-25 01:58:25,761 DEBUG httpclient.HttpParser
(HttpParser.java:105)    - enter HttpParser.readLine(InputStream,
String)
2009-11-25 01:58:25,761 DEBUG httpclient.HttpParser (HttpParser.java:74)
- enter HttpParser.readRawLine()
2009-11-25 01:58:25,761 DEBUG wire.header       (Wire.java:70)    - <<
"Transfer-Encoding: chunked[\r][\n]"
2009-11-25 01:58:25,761 DEBUG httpclient.HttpParser
(HttpParser.java:105)    - enter HttpParser.readLine(InputStream,
String)
2009-11-25 01:58:25,761 DEBUG httpclient.HttpParser (HttpParser.java:74)
- enter HttpParser.readRawLine()
2009-11-25 01:58:25,761 DEBUG wire.header       (Wire.java:70)    - <<
"Content-Type: application/x-java-serialized-object[\r][\n]"
2009-11-25 01:58:25,761 DEBUG httpclient.HttpParser
(HttpParser.java:105)    - enter HttpParser.readLine(InputStream,
String)
2009-11-25 01:58:25,761 DEBUG httpclient.HttpParser (HttpParser.java:74)
- enter HttpParser.readRawLine()
2009-11-25 01:58:25,761 DEBUG wire.header       (Wire.java:70)    - <<
"Content-Encoding: none[\r][\n]"
2009-11-25 01:58:25,761 DEBUG httpclient.HttpParser
(HttpParser.java:105)    - enter HttpParser.readLine(InputStream,
String)
2009-11-25 01:58:25,761 DEBUG httpclient.HttpParser (HttpParser.java:74)
- enter HttpParser.readRawLine()
2009-11-25 01:58:25,761 DEBUG wire.header       (Wire.java:70)    - <<
"Serialization-Type: java[\r][\n]"
2009-11-25 01:58:25,761 DEBUG httpclient.HttpParser
(HttpParser.java:105)    - enter HttpParser.readLine(InputStream,
String)
2009-11-25 01:58:25,761 DEBUG httpclient.HttpParser (HttpParser.java:74)
- enter HttpParser.readRawLine()
2009-11-25 01:58:25,761 DEBUG wire.header       (Wire.java:70)    - <<
"[\r][\n]"
2009-11-25 01:58:25,761 DEBUG httpclient.HttpMethodBase
(HttpMethodBase.java:1579)    - enter
HttpMethodBase.processResponseHeaders(HttpState, HttpConnection)
2009-11-25 01:58:25,761 DEBUG httpclient.HttpMethodBase
(HttpMethodBase.java:1615)    - enter
HttpMethodBase.processCookieHeaders(Header[], HttpState, HttpConnection)
2009-11-25 01:58:25,761 DEBUG httpclient.HttpMethodBase
(HttpMethodBase.java:1781)    - enter
HttpMethodBase.readResponseBody(HttpState, HttpConnection)
2009-11-25 01:58:25,761 DEBUG httpclient.HttpMethodBase
(HttpMethodBase.java:1816)    - enter
HttpMethodBase.readResponseBody(HttpConnection)
2009-11-25 01:58:25,761 DEBUG httpclient.HttpConnection
(HttpConnection.java:857)    - enter
HttpConnection.getResponseInputStream()
2009-11-25 01:58:25,761 DEBUG httpclient.HttpMethodBase
(HttpMethodBase.java:2281)    - enter
HttpMethodBase.canResponseHaveBody(int)
2009-11-25 01:58:25,761 DEBUG httpclient.HeaderElement
(HeaderElement.java:238)    - enter HeaderElement.parseElements(String)
2009-11-25 01:58:25,761 DEBUG httpclient.HeaderElement
(HeaderElement.java:194)    - enter HeaderElement.parseElements(char[])
2009-11-25 01:58:25,761 DEBUG httpclient.HttpConnection
(HttpConnection.java:894)    - enter
HttpConnection.isResponseAvailable(int)
2009-11-25 01:58:26,355 DEBUG util.IdleConnectionHandler
(IdleConnectionHandler.java:108)    - Checking for connections,
idleTimeout: 1259132286355
2009-11-25 01:58:27,355 DEBUG util.IdleConnectionHandler
(IdleConnectionHandler.java:108)    - Checking for connections,
idleTimeout: 1259132287355
2009-11-25 01:58:28,355 DEBUG util.IdleConnectionHandler
(IdleConnectionHandler.java:108)    - Checking for connections,
idleTimeout: 1259132288355
2009-11-25 01:58:29,355 DEBUG util.IdleConnectionHandler
(IdleConnectionHandler.java:108)    - Checking for connections,
idleTimeout: 1259132289355
2009-11-25 01:58:30,355 DEBUG util.IdleConnectionHandler
(IdleConnectionHandler.java:108)    - Checking for connections,
idleTimeout: 1259132290355
2009-11-25 01:58:31,355 DEBUG util.IdleConnectionHandler
(IdleConnectionHandler.java:108)    - Checking for connections,
idleTimeout: 1259132291355
2009-11-25 01:58:32,355 DEBUG util.IdleConnectionHandler
(IdleConnectionHandler.java:108)    - Checking for connections,
idleTimeout: 1259132292355
2009-11-25 01:58:33,355 DEBUG util.IdleConnectionHandler
(IdleConnectionHandler.java:108)    - Checking for connections,
idleTimeout: 1259132293355
2009-11-25 01:58:34,355 DEBUG util.IdleConnectionHandler
(IdleConnectionHandler.java:108)    - Checking for connections,
idleTimeout: 1259132294355
2009-11-25 01:58:35,355 DEBUG util.IdleConnectionHandler
(IdleConnectionHandler.java:108)    - Checking for connections,
idleTimeout: 1259132295355
2009-11-25 01:58:36,355 DEBUG util.IdleConnectionHandler
(IdleConnectionHandler.java:108)    - Checking for connections,
idleTimeout: 1259132296355
2009-11-25 01:58:37,355 DEBUG util.IdleConnectionHandler
(IdleConnectionHandler.java:108)    - Checking for connections,
idleTimeout: 1259132297355
2009-11-25 01:58:38,355 DEBUG util.IdleConnectionHandler
(IdleConnectionHandler.java:108)    - Checking for connections,
idleTimeout: 1259132298355
2009-11-25 01:58:39,355 DEBUG util.IdleConnectionHandler
(IdleConnectionHandler.java:108)    - Checking for connections,
idleTimeout: 1259132299355
2009-11-25 01:58:40,355 DEBUG util.IdleConnectionHandler
(IdleConnectionHandler.java:108)    - Checking for connections,
idleTimeout: 1259132300355
2009-11-25 01:58:41,355 DEBUG util.IdleConnectionHandler
(IdleConnectionHandler.java:108)    - Checking for connections,
idleTimeout: 1259132301355
2009-11-25 01:58:42,355 DEBUG util.IdleConnectionHandler
(IdleConnectionHandler.java:108)    - Checking for connections,
idleTimeout: 1259132302355
2009-11-25 01:58:43,355 DEBUG util.IdleConnectionHandler
(IdleConnectionHandler.java:108)    - Checking for connections,
idleTimeout: 1259132303355
2009-11-25 01:58:44,355 DEBUG util.IdleConnectionHandler
(IdleConnectionHandler.java:108)    - Checking for connections,
idleTimeout: 1259132304355
2009-11-25 01:58:45,355 DEBUG util.IdleConnectionHandler
(IdleConnectionHandler.java:108)    - Checking for connections,
idleTimeout: 1259132305355
2009-11-25 01:58:46,355 DEBUG util.IdleConnectionHandler
(IdleConnectionHandler.java:108)    - Checking for connections,
idleTimeout: 1259132306355
2009-11-25 01:58:47,355 DEBUG util.IdleConnectionHandler
(IdleConnectionHandler.java:108)    - Checking for connections,
idleTimeout: 1259132307355
2009-11-25 01:58:48,355 DEBUG util.IdleConnectionHandler
(IdleConnectionHandler.java:108)    - Checking for connections,
idleTimeout: 1259132308355
2009-11-25 01:58:49,355 DEBUG util.IdleConnectionHandler
(IdleConnectionHandler.java:108)    - Checking for connections,
idleTimeout: 1259132309355
2009-11-25 01:58:50,355 DEBUG util.IdleConnectionHandler
(IdleConnectionHandler.java:108)    - Checking for connections,
idleTimeout: 1259132310355
2009-11-25 01:58:51,355 DEBUG util.IdleConnectionHandler
(IdleConnectionHandler.java:108)    - Checking for connections,
idleTimeout: 1259132311355
2009-11-25 01:58:52,355 DEBUG util.IdleConnectionHandler
(IdleConnectionHandler.java:108)    - Checking for connections,
idleTimeout: 1259132312355
2009-11-25 01:58:53,355 DEBUG util.IdleConnectionHandler
(IdleConnectionHandler.java:108)    - Checking for connections,
idleTimeout: 1259132313355
2009-11-25 01:58:54,355 DEBUG util.IdleConnectionHandler
(IdleConnectionHandler.java:108)    - Checking for connections,
idleTimeout: 1259132314355
2009-11-25 01:58:55,355 DEBUG util.IdleConnectionHandler
(IdleConnectionHandler.java:108)    - Checking for connections,
idleTimeout: 1259132315355
2009-11-25 01:58:56,355 DEBUG util.IdleConnectionHandler
(IdleConnectionHandler.java:108)    - Checking for connections,
idleTimeout: 1259132316355
2009-11-25 01:58:57,355 DEBUG util.IdleConnectionHandler
(IdleConnectionHandler.java:108)    - Checking for connections,
idleTimeout: 1259132317355
2009-11-25 01:58:58,355 DEBUG util.IdleConnectionHandler
(IdleConnectionHandler.java:108)    - Checking for connections,
idleTimeout: 1259132318355
2009-11-25 01:58:59,355 DEBUG util.IdleConnectionHandler
(IdleConnectionHandler.java:108)    - Checking for connections,
idleTimeout: 1259132319355
2009-11-25 01:59:00,355 DEBUG util.IdleConnectionHandler
(IdleConnectionHandler.java:108)    - Checking for connections,
idleTimeout: 1259132320355
2009-11-25 01:59:01,355 DEBUG util.IdleConnectionHandler
(IdleConnectionHandler.java:108)    - Checking for connections,
idleTimeout: 1259132321355
2009-11-25 01:59:02,355 DEBUG util.IdleConnectionHandler
(IdleConnectionHandler.java:108)    - Checking for connections,
idleTimeout: 1259132322355
2009-11-25 01:59:03,355 DEBUG util.IdleConnectionHandler
(IdleConnectionHandler.java:108)    - Checking for connections,
idleTimeout: 1259132323355
2009-11-25 01:59:04,355 DEBUG util.IdleConnectionHandler
(IdleConnectionHandler.java:108)    - Checking for connections,
idleTimeout: 1259132324355
2009-11-25 01:59:05,355 DEBUG util.IdleConnectionHandler
(IdleConnectionHandler.java:108)    - Checking for connections,
idleTimeout: 1259132325355
2009-11-25 01:59:06,355 DEBUG util.IdleConnectionHandler
(IdleConnectionHandler.java:108)    - Checking for connections,
idleTimeout: 1259132326355
2009-11-25 01:59:07,355 DEBUG util.IdleConnectionHandler
(IdleConnectionHandler.java:108)    - Checking for connections,
idleTimeout: 1259132327355
2009-11-25 01:59:08,355 DEBUG util.IdleConnectionHandler
(IdleConnectionHandler.java:108)    - Checking for connections,
idleTimeout: 1259132328355
2009-11-25 01:59:09,355 DEBUG util.IdleConnectionHandler
(IdleConnectionHandler.java:108)    - Checking for connections,
idleTimeout: 1259132329355
2009-11-25 01:59:10,355 DEBUG util.IdleConnectionHandler
(IdleConnectionHandler.java:108)    - Checking for connections,
idleTimeout: 1259132330355
2009-11-25 01:59:11,355 DEBUG util.IdleConnectionHandler
(IdleConnectionHandler.java:108)    - Checking for connections,
idleTimeout: 1259132331355
2009-11-25 01:59:12,355 DEBUG util.IdleConnectionHandler
(IdleConnectionHandler.java:108)    - Checking for connections,
idleTimeout: 1259132332355
2009-11-25 01:59:13,355 DEBUG util.IdleConnectionHandler
(IdleConnectionHandler.java:108)    - Checking for connections,
idleTimeout: 1259132333355
2009-11-25 01:59:14,355 DEBUG util.IdleConnectionHandler
(IdleConnectionHandler.java:108)    - Checking for connections,
idleTimeout: 1259132334355
2009-11-25 01:59:15,355 DEBUG util.IdleConnectionHandler
(IdleConnectionHandler.java:108)    - Checking for connections,
idleTimeout: 1259132335355
2009-11-25 01:59:16,355 DEBUG util.IdleConnectionHandler
(IdleConnectionHandler.java:108)    - Checking for connections,
idleTimeout: 1259132336355
2009-11-25 01:59:17,355 DEBUG util.IdleConnectionHandler
(IdleConnectionHandler.java:108)    - Checking for connections,
idleTimeout: 1259132337355
2009-11-25 01:59:18,355 DEBUG util.IdleConnectionHandler
(IdleConnectionHandler.java:108)    - Checking for connections,
idleTimeout: 1259132338355
2009-11-25 01:59:19,355 DEBUG util.IdleConnectionHandler
(IdleConnectionHandler.java:108)    - Checking for connections,
idleTimeout: 1259132339355
2009-11-25 01:59:20,355 DEBUG util.IdleConnectionHandler
(IdleConnectionHandler.java:108)    - Checking for connections,
idleTimeout: 1259132340355
2009-11-25 01:59:21,355 DEBUG util.IdleConnectionHandler
(IdleConnectionHandler.java:108)    - Checking for connections,
idleTimeout: 1259132341355
2009-11-25 01:59:22,355 DEBUG util.IdleConnectionHandler
(IdleConnectionHandler.java:108)    - Checking for connections,
idleTimeout: 1259132342355
2009-11-25 01:59:23,355 DEBUG util.IdleConnectionHandler
(IdleConnectionHandler.java:108)    - Checking for connections,
idleTimeout: 1259132343355
2009-11-25 01:59:24,355 DEBUG util.IdleConnectionHandler
(IdleConnectionHandler.java:108)    - Checking for connections,
idleTimeout: 1259132344355
2009-11-25 01:59:25,355 DEBUG util.IdleConnectionHandler
(IdleConnectionHandler.java:108)    - Checking for connections,
idleTimeout: 1259132345355
2009-11-25 01:59:25,792 DEBUG httpclient.HttpMethodDirector
(HttpMethodDirector.java:404)    - Closing the connection.
2009-11-25 01:59:25,792 DEBUG httpclient.HttpConnection
(HttpConnection.java:1148)    - enter HttpConnection.close()
2009-11-25 01:59:25,792 DEBUG httpclient.HttpConnection
(HttpConnection.java:1215)    - enter
HttpConnection.closeSockedAndStreams()
2009-11-25 01:59:25,792 DEBUG httpclient.HttpMethodDirector
(HttpMethodDirector.java:434)    - Method retry handler returned false.
Automatic recovery will not be attempted
2009-11-25 01:59:25,792 DEBUG httpclient.HttpConnection
(HttpConnection.java:1174)    - enter HttpConnection.releaseConnection()
2009-11-25 01:59:25,792 DEBUG httpclient.HttpConnection
(HttpConnection.java:1178)    - Releasing connection back to connection
manager.
2009-11-25 01:59:25,792 DEBUG
httpclient.MultiThreadedHttpConnectionManager
(MultiThreadedHttpConnectionManager.java:630)    - enter
HttpConnectionManager.releaseConnection(HttpConnection)
2009-11-25 01:59:25,792 DEBUG
httpclient.MultiThreadedHttpConnectionManager
(MultiThreadedHttpConnectionManager.java:979)    - Freeing connection,
hostConfig=HostConfiguration[host=http://prf-services.mycompany.net:9810
]
2009-11-25 01:59:25,792 DEBUG
httpclient.MultiThreadedHttpConnectionManager
(MultiThreadedHttpConnectionManager.java:805)    - enter
HttpConnectionManager.ConnectionPool.getHostPool(HostConfiguration)
2009-11-25 01:59:25,792 DEBUG util.IdleConnectionHandler
(IdleConnectionHandler.java:76)    - Adding connection at: 1259132365792
2009-11-25 01:59:25,792 DEBUG
httpclient.MultiThreadedHttpConnectionManager
(MultiThreadedHttpConnectionManager.java:961)    - Notifying no-one,
there are no waiting threads
2009-11-25 01:59:26,355 DEBUG util.IdleConnectionHandler
(IdleConnectionHandler.java:108)    - Checking for connections,
idleTimeout: 1259132346355
2009-11-25 01:59:26,355 DEBUG
httpclient.MultiThreadedHttpConnectionManager
(MultiThreadedHttpConnectionManager.java:889)    - Reclaiming
connection,
hostConfig=HostConfiguration[host=http://prf-services.mycompany.net:9810
]
2009-11-25 01:59:26,355 DEBUG httpclient.HttpConnection
(HttpConnection.java:1148)    - enter HttpConnection.close()
2009-11-25 01:59:26,355 DEBUG httpclient.HttpConnection
(HttpConnection.java:1215)    - enter
HttpConnection.closeSockedAndStreams()
2009-11-25 01:59:26,355 DEBUG
httpclient.MultiThreadedHttpConnectionManager
(MultiThreadedHttpConnectionManager.java:805)    - enter
HttpConnectionManager.ConnectionPool.getHostPool(HostConfiguration)




==========
= Client Log - Shows that the request was sent and 1 minute later the
connection was reset.
==========

25-Nov-2009:01:58:25.714	scd2nts044	main	INFO
ICallTrackingService.createAuditInfo()		NA	Created
correlation id[ltu068_scd2nts044_-77fec0ce:125299ecace:-7e72] for
mChannel=test;mUserId=ltu068;mParentAuditId=null;correlationId=null;oper
atorId=null
25-Nov-2009:01:59:25.792	scd2nts044	main	EXCEPTION
ICallTrackingService.insertWorkFlow	callId = 1148802246, wfIndex =
1000, workFlow_in = com.ccs.cco.cms.rcts.calltracking.WorkFlow@9578c1
ltu068_scd2nts044_-77fec0ce:125299ecace:-7e72	SYSTEM_EXCEPTION[Error
making call[Error executing Remote Method=[insertWorkFlow] for Service
Url=[http://prf-services.mycompany.net:9810/cms.rcts/2009.9.1.006/ccs/pr
f.lr/2008.8.1/CDC] Exception=[java.net.SocketException: Connection reset
	at java.net.SocketInputStream.read(SocketInputStream.java:168)
	at
java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
	at
java.io.BufferedInputStream.read(BufferedInputStream.java:235)
	at
org.apache.commons.httpclient.HttpConnection.isResponseAvailable(HttpCon
nection.java:903)
	at
org.apache.commons.httpclient.MultiThreadedHttpConnectionManager$HttpCon
nectionAdapter.isResponseAvailable(MultiThreadedHttpConnectionManager.ja
va:1337)
	at
org.apache.commons.httpclient.HttpMethodBase.readResponseBody(HttpMethod
Base.java:1843)
	at
org.apache.commons.httpclient.HttpMethodBase.readResponseBody(HttpMethod
Base.java:1785)
	at
org.apache.commons.httpclient.HttpMethodBase.readResponse(HttpMethodBase
.java:1748)
	at
org.apache.commons.httpclient.HttpMethodBase.execute(HttpMethodBase.java
:1098)
	at
org.apache.commons.httpclient.HttpMethodDirector.executeWithRetry(HttpMe
thodDirector.java:398)
	at
org.apache.commons.httpclient.HttpMethodDirector.executeMethod(HttpMetho
dDirector.java:171)
	at
org.apache.commons.httpclient.HttpClient.executeMethod(HttpClient.java:3
97)
	at
org.apache.commons.httpclient.HttpClient.executeMethod(HttpClient.java:3
23)
	at
com.fusa.ssg.infra.remoting.client.service.RemoteServiceExecutorImpl.exe
cuteRequest(RemoteServiceExecutorImpl.java:99)
	at
com.fusa.ssg.infra.remoting.client.service.RemoteServiceProxy.invoke(Rem
oteServiceProxy.java:54)
	at $Proxy1.insertWorkFlow(Unknown Source)
	at
com.ccs.cco.cms.rcts.client.calltracking.CallTrackingRemotingDelegate.in
sertWorkFlow(CallTrackingRemotingDelegate.java:210)
	at Actions.action(Actions.java:2344)
]]]
com.fusa.ssg.SystemException: Error making call[Error executing Remote
Method=[insertWorkFlow] for Service
Url=[http://prf-services.mycompany.net:9810/cms.rcts/2009.9.1.006/ccs/pr
f.lr/2008.8.1/CDC] Exception=[java.net.SocketException: Connection reset
	at java.net.SocketInputStream.read(SocketInputStream.java:168)
	at
java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
	at
java.io.BufferedInputStream.read(BufferedInputStream.java:235)
	at
org.apache.commons.httpclient.HttpConnection.isResponseAvailable(HttpCon
nection.java:903)
	at
org.apache.commons.httpclient.MultiThreadedHttpConnectionManager$HttpCon
nectionAdapter.isResponseAvailable(MultiThreadedHttpConnectionManager.ja
va:1337)
	at
org.apache.commons.httpclient.HttpMethodBase.readResponseBody(HttpMethod
Base.java:1843)
	at
org.apache.commons.httpclient.HttpMethodBase.readResponseBody(HttpMethod
Base.java:1785)
	at
org.apache.commons.httpclient.HttpMethodBase.readResponse(HttpMethodBase
.java:1748)
	at
org.apache.commons.httpclient.HttpMethodBase.execute(HttpMethodBase.java
:1098)
	at
org.apache.commons.httpclient.HttpMethodDirector.executeWithRetry(HttpMe
thodDirector.java:398)
	at
org.apache.commons.httpclient.HttpMethodDirector.executeMethod(HttpMetho
dDirector.java:171)
	at
org.apache.commons.httpclient.HttpClient.executeMethod(HttpClient.java:3
97)
	at
org.apache.commons.httpclient.HttpClient.executeMethod(HttpClient.java:3
23)
	at
com.fusa.ssg.infra.remoting.client.service.RemoteServiceExecutorImpl.exe
cuteRequest(RemoteServiceExecutorImpl.java:99)
	at
com.fusa.ssg.infra.remoting.client.service.RemoteServiceProxy.invoke(Rem
oteServiceProxy.java:54)
	at $Proxy1.insertWorkFlow(Unknown Source)
	at
com.ccs.cco.cms.rcts.client.calltracking.CallTrackingRemotingDelegate.in
sertWorkFlow(CallTrackingRemotingDelegate.java:210)
	at Actions.action(Actions.java:2344)
]]
	at
com.ccs.cco.cms.rcts.client.calltracking.CallTrackingRemotingDelegate.in
sertWorkFlow(CallTrackingRemotingDelegate.java:222)
	at Actions.action(Actions.java:2344)
------------Wrapped Exception-----------
com.fusa.ssg.infra.remoting.common.RemoteServiceException: Error
executing Remote Method=[insertWorkFlow] for Service
Url=[http://prf-services.mycompany.net:9810/cms.rcts/2009.9.1.006/ccs/pr
f.lr/2008.8.1/CDC] Exception=[java.net.SocketException: Connection reset
	at java.net.SocketInputStream.read(SocketInputStream.java:168)
	at
java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
	at
java.io.BufferedInputStream.read(BufferedInputStream.java:235)
	at
org.apache.commons.httpclient.HttpConnection.isResponseAvailable(HttpCon
nection.java:903)
	at
org.apache.commons.httpclient.MultiThreadedHttpConnectionManager$HttpCon
nectionAdapter.isResponseAvailable(MultiThreadedHttpConnectionManager.ja
va:1337)
	at
org.apache.commons.httpclient.HttpMethodBase.readResponseBody(HttpMethod
Base.java:1843)
	at
org.apache.commons.httpclient.HttpMethodBase.readResponseBody(HttpMethod
Base.java:1785)
	at
org.apache.commons.httpclient.HttpMethodBase.readResponse(HttpMethodBase
.java:1748)
	at
org.apache.commons.httpclient.HttpMethodBase.execute(HttpMethodBase.java
:1098)
	at
org.apache.commons.httpclient.HttpMethodDirector.executeWithRetry(HttpMe
thodDirector.java:398)
	at
org.apache.commons.httpclient.HttpMethodDirector.executeMethod(HttpMetho
dDirector.java:171)
	at
org.apache.commons.httpclient.HttpClient.executeMethod(HttpClient.java:3
97)
	at
org.apache.commons.httpclient.HttpClient.executeMethod(HttpClient.java:3
23)
	at
com.fusa.ssg.infra.remoting.client.service.RemoteServiceExecutorImpl.exe
cuteRequest(RemoteServiceExecutorImpl.java:99)
	at
com.fusa.ssg.infra.remoting.client.service.RemoteServiceProxy.invoke(Rem
oteServiceProxy.java:54)
	at $Proxy1.insertWorkFlow(Unknown Source)
	at
com.ccs.cco.cms.rcts.client.calltracking.CallTrackingRemotingDelegate.in
sertWorkFlow(CallTrackingRemotingDelegate.java:210)
	at Actions.action(Actions.java:2344)
]
	at
com.fusa.ssg.infra.remoting.client.service.RemoteServiceProxy.invoke(Rem
oteServiceProxy.java:58)
	at $Proxy1.insertWorkFlow(Unknown Source)
	at
com.ccs.cco.cms.rcts.client.calltracking.CallTrackingRemotingDelegate.in
sertWorkFlow(CallTrackingRemotingDelegate.java:210)
	at Actions.action(Actions.java:2344)
25-Nov-2009:01:59:25.792	scd2nts044	main
PERFORMANCEMONITOR	ICallTrackingService.insertWorkFlow
ClientId=test_2009.9.1.006 insertWorkFlow call.
ltu068_scd2nts044_-77fec0ce:125299ecace:-7e72	60078




=======
= Server log - Shows that the response took 7ms to send back out
=======

RetentionCallTrackingServiceFile123.log:25-Nov-2009:06:58:27.091
pfwls3  ExecuteThread: '32' for queue: 'default'
PERFORMANCEMONITOR      CallTrackingCore.insertWorkFlow
ClientId=test_2009.9.1.006 insertWorkFlow call.
ltu068_scd2nts044_-77fec0ce:125299ecace:-7e72   7
This transmission may contain information that is privileged,
confidential, legally privileged, and/or exempt from disclosure
under applicable law.  If you are not the intended recipient, you
are hereby notified that any disclosure, copying, distribution, or
use of the information contained herein (including any reliance
thereon) is STRICTLY PROHIBITED.  Although this transmission and
any attachments are believed to be free of any virus or other
defect that might affect any computer system into which it is
received and opened, it is the responsibility of the recipient to
ensure that it is virus free and no responsibility is accepted by
JPMorgan Chase & Co., its subsidiaries and affiliates, as
applicable, for any loss or damage arising in any way from its use.
 If you received this transmission in error, please immediately
contact the sender and destroy the material in its entirety,
whether in electronic or hard copy format. Thank you.

---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
For additional commands, e-mail: httpclient-users-help@hc.apache.org


RE: Infinite loop in ChunkedInputStream.close

Posted by ke...@chase.com.
Perfect, thanks.

I was hoping that I would see a missing final chunk that would explain
it but no such luck.
Again, that was from Loadbalancer to server so my only hope left is that
from client to LB shows something different.

-k

-----Original Message-----
From: Oleg Kalnichevski [mailto:olegk@apache.org] 
Sent: Thursday, November 19, 2009 4:29 PM
To: HttpClient User Discussion
Subject: Re: Infinite loop in ChunkedInputStream.close

kenneth.s.brooks@chase.com wrote:
> Oleg,
> 
> I have a network capture from a week or so ago.
> This is between the loadbalancer and the server. (We're working on
> getting the capture from the client to the loadbalancer).
> 
> It shows that we are getting one packet back with data and ending with
> 0d 0a.
> The next packet ends with 30 30 30 30 0d 0a 0d 0a. 
> 
> So at least from the server to the loadbalancer it appears that we are
> getting the same closing chunk for good and bad requests.
> 
> You said that it should end with <CR><LF>0<CR><LF>, but on all of our
> requests it ends with 30 30 30 30 0d 0a 0d 0a (which is 0 0 0 0 CR LF
CR
> LF).
> Is that what you would expect?
> 

RFC 2616
3.6.1 Chunked Transfer Coding

---
last-chunk     = 1*("0") [ chunk-extension ] CRLF
---

There appears to be an extra CR LF pair at the end but this should not 
cause a major problem. Otherwise looks all right.

Oleg

---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
For additional commands, e-mail: httpclient-users-help@hc.apache.org

This transmission may contain information that is privileged,
confidential, legally privileged, and/or exempt from disclosure
under applicable law.  If you are not the intended recipient, you
are hereby notified that any disclosure, copying, distribution, or
use of the information contained herein (including any reliance
thereon) is STRICTLY PROHIBITED.  Although this transmission and
any attachments are believed to be free of any virus or other
defect that might affect any computer system into which it is
received and opened, it is the responsibility of the recipient to
ensure that it is virus free and no responsibility is accepted by
JPMorgan Chase & Co., its subsidiaries and affiliates, as
applicable, for any loss or damage arising in any way from its use.
 If you received this transmission in error, please immediately
contact the sender and destroy the material in its entirety,
whether in electronic or hard copy format. Thank you.

---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
For additional commands, e-mail: httpclient-users-help@hc.apache.org


Re: Infinite loop in ChunkedInputStream.close

Posted by Oleg Kalnichevski <ol...@apache.org>.
kenneth.s.brooks@chase.com wrote:
> Oleg,
> 
> I have a network capture from a week or so ago.
> This is between the loadbalancer and the server. (We're working on
> getting the capture from the client to the loadbalancer).
> 
> It shows that we are getting one packet back with data and ending with
> 0d 0a.
> The next packet ends with 30 30 30 30 0d 0a 0d 0a. 
> 
> So at least from the server to the loadbalancer it appears that we are
> getting the same closing chunk for good and bad requests.
> 
> You said that it should end with <CR><LF>0<CR><LF>, but on all of our
> requests it ends with 30 30 30 30 0d 0a 0d 0a (which is 0 0 0 0 CR LF CR
> LF).
> Is that what you would expect?
> 

RFC 2616
3.6.1 Chunked Transfer Coding

---
last-chunk     = 1*("0") [ chunk-extension ] CRLF
---

There appears to be an extra CR LF pair at the end but this should not 
cause a major problem. Otherwise looks all right.

Oleg

---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
For additional commands, e-mail: httpclient-users-help@hc.apache.org


RE: Infinite loop in ChunkedInputStream.close

Posted by ke...@chase.com.
Oleg,

I have a network capture from a week or so ago.
This is between the loadbalancer and the server. (We're working on
getting the capture from the client to the loadbalancer).

It shows that we are getting one packet back with data and ending with
0d 0a.
The next packet ends with 30 30 30 30 0d 0a 0d 0a. 

So at least from the server to the loadbalancer it appears that we are
getting the same closing chunk for good and bad requests.

You said that it should end with <CR><LF>0<CR><LF>, but on all of our
requests it ends with 30 30 30 30 0d 0a 0d 0a (which is 0 0 0 0 CR LF CR
LF).
Is that what you would expect?

-ken


-----Original Message-----
From: Oleg Kalnichevski [mailto:olegk@apache.org] 
Sent: Thursday, November 19, 2009 3:35 PM
To: HttpClient User Discussion
Subject: Re: Infinite loop in ChunkedInputStream.close

kenneth.s.brooks@chase.com wrote:
> Will do.
> Not saying it will necessarily make a difference, just more of a 'what
> is the proper usage' type of question.
> 

Closing streams when done using them is basically a good java practice, 
so the proper usage would be to close the stream _and_ to release the 
connection. This will also make the migration to version 4.0 somewhat 
easier.

Cheers

Oleg

> Thanks again,
> -k
> 
> -----Original Message-----
> From: Oleg Kalnichevski [mailto:olegk@apache.org] 
> Sent: Thursday, November 19, 2009 3:15 PM
> To: HttpClient User Discussion
> Subject: Re: Infinite loop in ChunkedInputStream.close
> 
> kenneth.s.brooks@chase.com wrote:
>> Oleg,
>>
>> Thanks for the response.
>>
>> I agree that it doesn't necessarily appear to be HttpClient code
>> itself.. because you are just calling to the jdk inputstream.read.
>>
>> I did some research and saw that we are sending back
> Transfer-Encoding:
>> chunked and am able to spot (in a network capture) on all the good
> calls
>> the following:
>> 30 0D 0A 0D 0A  (which is 0 and the CRLF). We haven't reproduced the
>> error yet while doing a network capture so I'll respond with an
update
>> as soon as we do.
>>
>> In the mean time, am I correct in removing the ois.close() from my
> code
>> and letting httpclient close it with the AutoCloseInputStream when I
>> call releaseConnection?
>>
> 
> I do not think this should make any difference but you certainly can 
> give it a try.
> 
> Oleg
> 
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
> For additional commands, e-mail: httpclient-users-help@hc.apache.org
> 
> This transmission may contain information that is privileged,
> confidential, legally privileged, and/or exempt from disclosure
> under applicable law.  If you are not the intended recipient, you
> are hereby notified that any disclosure, copying, distribution, or
> use of the information contained herein (including any reliance
> thereon) is STRICTLY PROHIBITED.  Although this transmission and
> any attachments are believed to be free of any virus or other
> defect that might affect any computer system into which it is
> received and opened, it is the responsibility of the recipient to
> ensure that it is virus free and no responsibility is accepted by
> JPMorgan Chase & Co., its subsidiaries and affiliates, as
> applicable, for any loss or damage arising in any way from its use.
>  If you received this transmission in error, please immediately
> contact the sender and destroy the material in its entirety,
> whether in electronic or hard copy format. Thank you.
> 
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
> For additional commands, e-mail: httpclient-users-help@hc.apache.org
> 


---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
For additional commands, e-mail: httpclient-users-help@hc.apache.org


---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
For additional commands, e-mail: httpclient-users-help@hc.apache.org


Re: Infinite loop in ChunkedInputStream.close

Posted by Oleg Kalnichevski <ol...@apache.org>.
kenneth.s.brooks@chase.com wrote:
> Will do.
> Not saying it will necessarily make a difference, just more of a 'what
> is the proper usage' type of question.
> 

Closing streams when done using them is basically a good java practice, 
so the proper usage would be to close the stream _and_ to release the 
connection. This will also make the migration to version 4.0 somewhat 
easier.

Cheers

Oleg

> Thanks again,
> -k
> 
> -----Original Message-----
> From: Oleg Kalnichevski [mailto:olegk@apache.org] 
> Sent: Thursday, November 19, 2009 3:15 PM
> To: HttpClient User Discussion
> Subject: Re: Infinite loop in ChunkedInputStream.close
> 
> kenneth.s.brooks@chase.com wrote:
>> Oleg,
>>
>> Thanks for the response.
>>
>> I agree that it doesn't necessarily appear to be HttpClient code
>> itself.. because you are just calling to the jdk inputstream.read.
>>
>> I did some research and saw that we are sending back
> Transfer-Encoding:
>> chunked and am able to spot (in a network capture) on all the good
> calls
>> the following:
>> 30 0D 0A 0D 0A  (which is 0 and the CRLF). We haven't reproduced the
>> error yet while doing a network capture so I'll respond with an update
>> as soon as we do.
>>
>> In the mean time, am I correct in removing the ois.close() from my
> code
>> and letting httpclient close it with the AutoCloseInputStream when I
>> call releaseConnection?
>>
> 
> I do not think this should make any difference but you certainly can 
> give it a try.
> 
> Oleg
> 
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
> For additional commands, e-mail: httpclient-users-help@hc.apache.org
> 
> This transmission may contain information that is privileged,
> confidential, legally privileged, and/or exempt from disclosure
> under applicable law.  If you are not the intended recipient, you
> are hereby notified that any disclosure, copying, distribution, or
> use of the information contained herein (including any reliance
> thereon) is STRICTLY PROHIBITED.  Although this transmission and
> any attachments are believed to be free of any virus or other
> defect that might affect any computer system into which it is
> received and opened, it is the responsibility of the recipient to
> ensure that it is virus free and no responsibility is accepted by
> JPMorgan Chase & Co., its subsidiaries and affiliates, as
> applicable, for any loss or damage arising in any way from its use.
>  If you received this transmission in error, please immediately
> contact the sender and destroy the material in its entirety,
> whether in electronic or hard copy format. Thank you.
> 
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
> For additional commands, e-mail: httpclient-users-help@hc.apache.org
> 


---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
For additional commands, e-mail: httpclient-users-help@hc.apache.org


RE: Infinite loop in ChunkedInputStream.close

Posted by ke...@chase.com.
Will do.
Not saying it will necessarily make a difference, just more of a 'what
is the proper usage' type of question.

Thanks again,
-k

-----Original Message-----
From: Oleg Kalnichevski [mailto:olegk@apache.org] 
Sent: Thursday, November 19, 2009 3:15 PM
To: HttpClient User Discussion
Subject: Re: Infinite loop in ChunkedInputStream.close

kenneth.s.brooks@chase.com wrote:
> Oleg,
> 
> Thanks for the response.
> 
> I agree that it doesn't necessarily appear to be HttpClient code
> itself.. because you are just calling to the jdk inputstream.read.
> 
> I did some research and saw that we are sending back
Transfer-Encoding:
> chunked and am able to spot (in a network capture) on all the good
calls
> the following:
> 30 0D 0A 0D 0A  (which is 0 and the CRLF). We haven't reproduced the
> error yet while doing a network capture so I'll respond with an update
> as soon as we do.
> 
> In the mean time, am I correct in removing the ois.close() from my
code
> and letting httpclient close it with the AutoCloseInputStream when I
> call releaseConnection?
> 

I do not think this should make any difference but you certainly can 
give it a try.

Oleg

---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
For additional commands, e-mail: httpclient-users-help@hc.apache.org

This transmission may contain information that is privileged,
confidential, legally privileged, and/or exempt from disclosure
under applicable law.  If you are not the intended recipient, you
are hereby notified that any disclosure, copying, distribution, or
use of the information contained herein (including any reliance
thereon) is STRICTLY PROHIBITED.  Although this transmission and
any attachments are believed to be free of any virus or other
defect that might affect any computer system into which it is
received and opened, it is the responsibility of the recipient to
ensure that it is virus free and no responsibility is accepted by
JPMorgan Chase & Co., its subsidiaries and affiliates, as
applicable, for any loss or damage arising in any way from its use.
 If you received this transmission in error, please immediately
contact the sender and destroy the material in its entirety,
whether in electronic or hard copy format. Thank you.

---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
For additional commands, e-mail: httpclient-users-help@hc.apache.org


Re: Infinite loop in ChunkedInputStream.close

Posted by Oleg Kalnichevski <ol...@apache.org>.
kenneth.s.brooks@chase.com wrote:
> Oleg,
> 
> Thanks for the response.
> 
> I agree that it doesn't necessarily appear to be HttpClient code
> itself.. because you are just calling to the jdk inputstream.read.
> 
> I did some research and saw that we are sending back Transfer-Encoding:
> chunked and am able to spot (in a network capture) on all the good calls
> the following:
> 30 0D 0A 0D 0A  (which is 0 and the CRLF). We haven't reproduced the
> error yet while doing a network capture so I'll respond with an update
> as soon as we do.
> 
> In the mean time, am I correct in removing the ois.close() from my code
> and letting httpclient close it with the AutoCloseInputStream when I
> call releaseConnection?
> 

I do not think this should make any difference but you certainly can 
give it a try.

Oleg

---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
For additional commands, e-mail: httpclient-users-help@hc.apache.org


RE: Infinite loop in ChunkedInputStream.close

Posted by ke...@chase.com.
Oleg,

Thanks for the response.

I agree that it doesn't necessarily appear to be HttpClient code
itself.. because you are just calling to the jdk inputstream.read.

I did some research and saw that we are sending back Transfer-Encoding:
chunked and am able to spot (in a network capture) on all the good calls
the following:
30 0D 0A 0D 0A  (which is 0 and the CRLF). We haven't reproduced the
error yet while doing a network capture so I'll respond with an update
as soon as we do.

In the mean time, am I correct in removing the ois.close() from my code
and letting httpclient close it with the AutoCloseInputStream when I
call releaseConnection?

Thanks,
Ken

-----Original Message-----
From: Oleg Kalnichevski [mailto:olegk@apache.org] 
Sent: Thursday, November 19, 2009 2:50 PM
To: HttpClient User Discussion
Subject: Re: Infinite loop in ChunkedInputStream.close

kenneth.s.brooks@chase.com wrote:
> We are using httpclient 3.1 to send a post and get back serialized
java
> objects (think of something analogous to Spring Remoting).
> We deploy this client code to many client machines talking thru
> loadbalancers communicating with Weblogic 10MP1 servers.
> The clients in this test are on windows, running jdk5 thru mercury
> loadrunner (performance testing software).
> 
> We've been testing anywhere between 45 and 90tps and the vast majority
> of the transactions are successful.
> 
> About 1 transaction every half hour ends up with a
> java.net.SocketException: Connection reset.
> The loadbalancer will close the socket after 60 seconds.
> The reason we get that exception (and not a different one) is that we
> have the client timeout set up higher than 60 seconds (just for trying
> to expose this issue) and the loadbalancer has a 60 second timeout.
> 
> Here is what we have learned so far.
> 
> We get the response body as stream:
>             InputStream responseBody =
> postMethod.getResponseBodyAsStream();
> 
> We then send it thru a custom deserializer, we know that the object in
> the response is being read because the log right after it is being
> printed out:
> However we have a close on that input stream in the finally. I'm
> probably going to remove that close (since I read elsewhere that its
> taken care of by the postMethod.releaseConnection().
>         try {
>             Object object = ois.readObject();
>             LOG.debug(METHOD_NAME + "ois.readObject completed");
>             return object;
>         } finally {
>             ois.close();
>             LOG.debug(METHOD_NAME + "ois.close completed");
>         }
> 
> The ois.close() is calling AutoCloseInputStream.close, calling
> ChunkedInputStream.close which is trying to exhaust the stream by
> calling exhaustInputStream which eventually calls
SocketInputStream.read
> and just sits there until the connection reset happens.
> 
> Any clue as to what would cause it to hang there?
> 

I seriously doubt this has anything to do with a tight loop in 
HttpClient code. Most likely the server fails to send the closing chunk,

which causes the input stream to get blocked in a read operation.

> The confusing factors are that the object seems to be fully read (so I
> would assume there is nothing left in the stream) and we average a
> couple thousand good transactions for every 1 occurrence of a bad one.
> 
> Let me know if I need the full headers and wire. We have only the
> header, not the content turned on because the volume of logging just
> kills the clients when turned up to trace.

I am afraid the only reliable way of establishing the cause would be 
getting a complete wire log.

> Also, we will be looking to migrate eventually to httpclient 4, but
that
> requires jdk5 and right now we have clients that are still
> (unfortunately) jdk1.4 so we can't quite make that leap yet.
> I have network captures as well, if you think you know what I should
> look for please advise and I will do so.
>

If you can find out where the session gets stuck see if the server sends

the closing chunk back to the client. The chunk should look like 
<CR><LF>0<CR><LF>

Oleg

> Thanks,
> Ken
> 
> Here is the pertinent httpclient log.
> Notice the 1 minute gap in log statements between 15:54:25:723 EST and
> 15:55:25:756 EST
> Also be aware that the reason you see logs in between the issue and
the
> time you see the stacktrace is that the postMethod.releaseConnection()
> is in a finally, so of course it will complete before the exception is
> propogated.
> 
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] PostMethod - enter
> PostMethod.clearRequestBody()
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] EntityEnclosingMethod
-
> enter EntityEnclosingMethod.clearRequestBody()
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [DEBUG]
> RemoteServiceExecutorImpl - executeRequest calling
> httpClient.ExecuteMethod
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpClient - enter
> HttpClient.executeMethod(HttpMethod)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpClient - enter
> HttpClient.executeMethod(HostConfiguration,HttpMethod,HttpState)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE]
> MultiThreadedHttpConnectionManager - enter
> HttpConnectionManager.getConnectionWithTimeout(HostConfiguration,
long)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [DEBUG]
> MultiThreadedHttpConnectionManager -
> HttpConnectionManager.getConnection:  config =
> HostConfiguration[host=http://my-loadbalancer:9810], timeout = 0
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE]
> MultiThreadedHttpConnectionManager - enter
> HttpConnectionManager.ConnectionPool.getHostPool(HostConfiguration)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE]
> MultiThreadedHttpConnectionManager - enter
> HttpConnectionManager.ConnectionPool.getHostPool(HostConfiguration)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [DEBUG]
> MultiThreadedHttpConnectionManager - Allocating new connection,
> hostConfig=HostConfiguration[host=http://my-loadbalancer:9810]
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpMethodDirector -
> Attempt number 1 to process request
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
> HttpConnection.open()
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [DEBUG] HttpConnection - Open
> connection to my-loadbalancer:9810
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpMethodBase - enter
> HttpMethodBase.execute(HttpState, HttpConnection)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpMethodBase - enter
> HttpMethodBase.writeRequest(HttpState, HttpConnection)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpMethodBase - enter
> HttpMethodBase.writeRequestLine(HttpState, HttpConnection)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpMethodBase - enter
> HttpMethodBase.generateRequestLine(HttpConnection, String, String,
> String, String)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [DEBUG] header - >> "POST
> /cms.rcts/2009.9.1.006/ccs/prf.lr/2008.8.1/CDC/essd-remote/
> HTTP/1.1[\r][\n]"
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
> HttpConnection.print(String)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
> HttpConnection.write(byte[])
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
> HttpConnection.write(byte[], int, int)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpMethodBase - enter
> HttpMethodBase.writeRequestHeaders(HttpState,HttpConnection)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] EntityEnclosingMethod
-
> enter EntityEnclosingMethod.addRequestHeaders(HttpState,
HttpConnection)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] ExpectContinueMethod -
> enter ExpectContinueMethod.addRequestHeaders(HttpState,
HttpConnection)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpMethodBase - enter
> HttpMethodBase.addRequestHeaders(HttpState, HttpConnection)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpMethodBase - enter
> HttpMethodBase.addUserAgentRequestHeaders(HttpState, HttpConnection)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpMethodBase - enter
> HttpMethodBase.addHostRequestHeader(HttpState, HttpConnection)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [DEBUG] HttpMethodBase -
Adding
> Host request header
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpMethodBase - enter
> HttpMethodBase.addCookieRequestHeader(HttpState, HttpConnection)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpState - enter
> HttpState.getCookies()
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpMethodBase - enter
> HttpMethodBase.addProxyConnectionHeader(HttpState, HttpConnection)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] EntityEnclosingMethod
-
> enter EntityEnclosingMethod.addContentLengthRequestHeader(HttpState,
> HttpConnection)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] EntityEnclosingMethod
-
> enter EntityEnclosingMethod.getRequestContentLength()
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] PostMethod - enter
> PostMethod.hasRequestContent()
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] EntityEnclosingMethod
-
> enter EntityEnclosingMethod.hasRequestContent()
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpMethodBase -
> HttpMethodBase.addRequestHeader(Header)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [DEBUG] header - >>
> "Content-Type: application/x-java-serialized-object[\r][\n]"
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
> HttpConnection.print(String)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
> HttpConnection.write(byte[])
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
> HttpConnection.write(byte[], int, int)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [DEBUG] header - >>
> "Content-Encoding: none[\r][\n]"
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
> HttpConnection.print(String)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
> HttpConnection.write(byte[])
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
> HttpConnection.write(byte[], int, int)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [DEBUG] header - >>
> "Serialization-Type: java[\r][\n]"
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
> HttpConnection.print(String)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
> HttpConnection.write(byte[])
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
> HttpConnection.write(byte[], int, int)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [DEBUG] header - >>
"User-Agent:
> Jakarta Commons-HttpClient/3.1[\r][\n]"
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
> HttpConnection.print(String)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
> HttpConnection.write(byte[])
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
> HttpConnection.write(byte[], int, int)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [DEBUG] header - >> "Host:
> my-loadbalancer:9810[\r][\n]"
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
> HttpConnection.print(String)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
> HttpConnection.write(byte[])
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
> HttpConnection.write(byte[], int, int)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [DEBUG] header - >>
> "Content-Length: 3051[\r][\n]"
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
> HttpConnection.print(String)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
> HttpConnection.write(byte[])
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
> HttpConnection.write(byte[], int, int)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
> HttpConnection.writeLine()
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
> HttpConnection.write(byte[])
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
> HttpConnection.write(byte[], int, int)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [DEBUG] header - >> "[\r][\n]"
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] EntityEnclosingMethod
-
> enter EntityEnclosingMethod.writeRequestBody(HttpState,
HttpConnection)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] PostMethod - enter
> PostMethod.hasRequestContent()
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] EntityEnclosingMethod
-
> enter EntityEnclosingMethod.hasRequestContent()
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] EntityEnclosingMethod
-
> enter EntityEnclosingMethod.getRequestContentLength()
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] PostMethod - enter
> PostMethod.hasRequestContent()
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] EntityEnclosingMethod
-
> enter EntityEnclosingMethod.hasRequestContent()
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpConnection - enter
> HttpConnection.getRequestOutputStream()
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [DEBUG] EntityEnclosingMethod
-
> Request body sent
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpConnection - enter
> HttpConnection.flushRequestOutputStream()
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpMethodBase - enter
> HttpMethodBase.readResponse(HttpState, HttpConnection)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpMethodBase - enter
> HttpMethodBase.readStatusLine(HttpState, HttpConnection)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpConnection - enter
> HttpConnection.readLine()
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpParser - enter
> HttpParser.readLine(InputStream, String)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpParser - enter
> HttpParser.readRawLine()
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [DEBUG] header - << "HTTP/1.1
> 200 OK[\r][\n]"
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [DEBUG] header - << "HTTP/1.1
> 200 OK[\r][\n]"
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpMethodBase - enter
> HttpMethodBase.readResponseHeaders(HttpState,HttpConnection)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpConnection - enter
> HttpConnection.getResponseInputStream()
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpParser - enter
> HeaderParser.parseHeaders(InputStream, String)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpParser - enter
> HttpParser.readLine(InputStream, String)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpParser - enter
> HttpParser.readRawLine()
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [DEBUG] header - << "Date:
Tue,
> 17 Nov 2009 20:54:25 GMT[\r][\n]"
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpParser - enter
> HttpParser.readLine(InputStream, String)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpParser - enter
> HttpParser.readRawLine()
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [DEBUG] header - <<
> "Transfer-Encoding: chunked[\r][\n]"
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpParser - enter
> HttpParser.readLine(InputStream, String)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpParser - enter
> HttpParser.readRawLine()
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [DEBUG] header - <<
> "Content-Type: application/x-java-serialized-object[\r][\n]"
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpParser - enter
> HttpParser.readLine(InputStream, String)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpParser - enter
> HttpParser.readRawLine()
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [DEBUG] header - <<
> "Content-Encoding: none[\r][\n]"
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpParser - enter
> HttpParser.readLine(InputStream, String)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpParser - enter
> HttpParser.readRawLine()
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [DEBUG] header - <<
> "Serialization-Type: java[\r][\n]"
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpParser - enter
> HttpParser.readLine(InputStream, String)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpParser - enter
> HttpParser.readRawLine()
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [DEBUG] header - << "[\r][\n]"
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpMethodBase - enter
> HttpMethodBase.processResponseHeaders(HttpState, HttpConnection)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpMethodBase - enter
> HttpMethodBase.processCookieHeaders(Header[], HttpState,
HttpConnection)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpMethodBase - enter
> HttpMethodBase.readResponseBody(HttpState, HttpConnection)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpMethodBase - enter
> HttpMethodBase.readResponseBody(HttpConnection)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpConnection - enter
> HttpConnection.getResponseInputStream()
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpMethodBase - enter
> HttpMethodBase.canResponseHaveBody(int)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [TRACE] HeaderElement - enter
> HeaderElement.parseElements(String)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [TRACE] HeaderElement - enter
> HeaderElement.parseElements(char[])
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpConnection - enter
> HttpConnection.isResponseAvailable(int)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [DEBUG]
> RemoteServiceExecutorImpl - executeRequesthttpClient.ExecuteMethod
> completed
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [DEBUG]
> RemoteServiceExecutorImpl -
> executeRequestpostMethod.getResponseBodyAsStream completed
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:55:25:756 EST [TRACE] HttpConnection - enter
> HttpConnection.releaseConnection()
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:55:25:756 EST [DEBUG] HttpConnection -
> Releasing connection back to connection manager.
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:55:25:756 EST [TRACE]
> MultiThreadedHttpConnectionManager - enter
> HttpConnectionManager.releaseConnection(HttpConnection)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:55:25:756 EST [DEBUG]
> MultiThreadedHttpConnectionManager - Freeing connection,
> hostConfig=HostConfiguration[host=http://my-loadbalancer:9810]
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:55:25:756 EST [TRACE]
> MultiThreadedHttpConnectionManager - enter
> HttpConnectionManager.ConnectionPool.getHostPool(HostConfiguration)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:55:25:756 EST [DEBUG] IdleConnectionHandler
-
> Adding connection at: 1258491325756
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:55:25:756 EST [DEBUG]
> MultiThreadedHttpConnectionManager - Notifying no-one, there are no
> waiting threads
> Error	[MsgId: MMSG-17999]
> Error: Failed to end Transaction "callTrackingService_insertWorkFlow"
> (by name). Please check that you made a call to start transaction
> operation.	[MsgId: MERR-16985]
> Error: System.err: com.fusa.ssg.SystemException: Error making
call[Error
> executing Remote Method=[getCallSeqId] for Service
>
Url=[http://my-loadbalancer:9810/cms.rcts/2009.9.1.006/ccs/prf.lr/2008.8
> .1/CDC] Exception=[java.net.SocketException: Connection reset
> 	at java.net.SocketInputStream.read(SocketInputStream.java:168)
> 	at
> java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
> 	at
> java.io.BufferedInputStream.read(BufferedInputStream.java:235)
> 	at
>
org.apache.commons.httpclient.ChunkedInputStream.getChunkSizeFromInputSt
> ream(ChunkedInputStream.java:250)
> 	at
>
org.apache.commons.httpclient.ChunkedInputStream.nextChunk(ChunkedInputS
> tream.java:221)
> 	at
>
org.apache.commons.httpclient.ChunkedInputStream.read(ChunkedInputStream
> .java:176)
> 	at
>
org.apache.commons.httpclient.ChunkedInputStream.read(ChunkedInputStream
> .java:196)
> 	at
>
org.apache.commons.httpclient.ChunkedInputStream.exhaustInputStream(Chun
> kedInputStream.java:369)
> 	at
>
org.apache.commons.httpclient.ChunkedInputStream.close(ChunkedInputStrea
> m.java:346)
> 	at java.io.FilterInputStream.close(FilterInputStream.java:159)
> 	at
>
org.apache.commons.httpclient.AutoCloseInputStream.notifyWatcher(AutoClo
> seInputStream.java:194)
> 	at
>
org.apache.commons.httpclient.AutoCloseInputStream.close(AutoCloseInputS
> tream.java:158)
> 	at
>
java.io.ObjectInputStream$PeekInputStream.close(ObjectInputStream.java:2
> 252)
> 	at
>
java.io.ObjectInputStream$BlockDataInputStream.close(ObjectInputStream.j
> ava:2587)
> 	at java.io.ObjectInputStream.close(ObjectInputStream.java:853)
> 	at
>
com.fusa.ssg.infra.remoting.common.io.StandardJavaSerializer.readObject(
> StandardJavaSerializer.java:41)
> 	at
>
com.fusa.ssg.infra.remoting.client.service.RemoteServiceExecutorImpl.des
> erializeServiceResponse(RemoteServiceExecutorImpl.java:153)
> 	at
>
com.fusa.ssg.infra.remoting.client.service.RemoteServiceExecutorImpl.exe
> cuteRequest(RemoteServiceExecutorImpl.java:111)
> 	at
>
com.fusa.ssg.infra.remoting.client.service.RemoteServiceProxy.invoke(Rem
> oteServiceProxy.java:54)
> 	at $Proxy5.getCallSeqId(Unknown Source)
> 	at
>
com.ccs.cco.cms.rcts.client.calltracking.CallTrackingRemotingDelegate.ge
> tCallSeqId(CallTrackingRemotingDelegate.java:66)
> 	at Actions.action(Actions.java:2327)
> ]]
> Error	[MsgId: MERR-17999]
> System.err: 	at
>
com.ccs.cco.cms.rcts.client.calltracking.CallTrackingRemotingDelegate.ge
> tCallSeqId(CallTrackingRemotingDelegate.java:81)
> Error	[MsgId: MMSG-17999]
> System.err: 	at Actions.action(Actions.java:2327)
> Error	[MsgId: MMSG-17999]
> Error: System.err: ------------Wrapped Exception-----------
> Error	[MsgId: MERR-17999]
> Error: System.err:
> com.fusa.ssg.infra.remoting.common.RemoteServiceException: Error
> executing Remote Method=[getCallSeqId] for Service
>
Url=[http://my-loadbalancer:9810/cms.rcts/2009.9.1.006/ccs/prf.lr/2008.8
> .1/CDC] Exception=[java.net.SocketException: Connection reset
> 	at java.net.SocketInputStream.read(SocketInputStream.java:168)
> 	at
> java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
> 	at
> java.io.BufferedInputStream.read(BufferedInputStream.java:235)
> 	at
>
org.apache.commons.httpclient.ChunkedInputStream.getChunkSizeFromInputSt
> ream(ChunkedInputStream.java:250)
> 	at
>
org.apache.commons.httpclient.ChunkedInputStream.nextChunk(ChunkedInputS
> tream.java:221)
> 	at
>
org.apache.commons.httpclient.ChunkedInputStream.read(ChunkedInputStream
> .java:176)
> 	at
>
org.apache.commons.httpclient.ChunkedInputStream.read(ChunkedInputStream
> .java:196)
> 	at
>
org.apache.commons.httpclient.ChunkedInputStream.exhaustInputStream(Chun
> kedInputStream.java:369)
> 	at
>
org.apache.commons.httpclient.ChunkedInputStream.close(ChunkedInputStrea
> m.java:346)
> 	at java.io.FilterInputStream.close(FilterInputStream.java:159)
> 	at
>
org.apache.commons.httpclient.AutoCloseInputStream.notifyWatcher(AutoClo
> seInputStream.java:194)
> 	at
>
org.apache.commons.httpclient.AutoCloseInputStream.close(AutoCloseInputS
> tream.java:158)
> 	at
>
java.io.ObjectInputStream$PeekInputStream.close(ObjectInputStream.java:2
> 252)
> 	at
>
java.io.ObjectInputStream$BlockDataInputStream.close(ObjectInputStream.j
> ava:2587)
> 	at java.io.ObjectInputStream.close(ObjectInputStream.java:853)
> 	at
>
com.fusa.ssg.infra.remoting.common.io.StandardJavaSerializer.readObject(
> StandardJavaSerializer.java:41)
> 	at
>
com.fusa.ssg.infra.remoting.client.service.RemoteServiceExecutorImpl.des
> erializeServiceResponse(RemoteServiceExecutorImpl.java:153)
> 	at
>
com.fusa.ssg.infra.remoting.client.service.RemoteServiceExecutorImpl.exe
> cuteRequest(RemoteServiceExecutorImpl.java:111)
> 	at
>
com.fusa.ssg.infra.remoting.client.service.RemoteServiceProxy.invoke(Rem
> oteServiceProxy.java:54)
> 	at $Proxy5.getCallSeqId(Unknown Source)
> 	at
>
com.ccs.cco.cms.rcts.client.calltracking.CallTrackingRemotingDelegate.ge
> tCallSeqId(CallTrackingRemotingDelegate.java:66)
> 	at Actions.action(Actions.java:2327)
> ]
> Error	[MsgId: MERR-17999]
> System.err: 	at
>
com.fusa.ssg.infra.remoting.client.service.RemoteServiceProxy.invoke(Rem
> oteServiceProxy.java:58)
> Error	[MsgId: MMSG-17999]
> System.err: 	at $Proxy5.getCallSeqId(Unknown Source)
> Error	[MsgId: MMSG-17999]
> System.err: 	at
>
com.ccs.cco.cms.rcts.client.calltracking.CallTrackingRemotingDelegate.ge
> tCallSeqId(CallTrackingRemotingDelegate.java:66)
> Error	[MsgId: MMSG-17999]
> System.err: 	at Actions.action(Actions.java:2327)
> Error	[MsgId: MMSG-17999]
> Error: System.err: -----------Wrapped Exception-----------
> Error	[MsgId: MERR-17999]
> Error: System.err:
> com.fusa.ssg.infra.remoting.common.RemoteServiceException: Error
> executing Remote Method=[getCallSeqId] for Service
>
Url=[http://my-loadbalancer:9810/cms.rcts/2009.9.1.006/ccs/prf.lr/2008.8
> .1/CDC] Exception=[java.net.SocketException: Connection reset
> 	at java.net.SocketInputStream.read(SocketInputStream.java:168)
> 	at
> java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
> 	at
> java.io.BufferedInputStream.read(BufferedInputStream.java:235)
> 	at
>
org.apache.commons.httpclient.ChunkedInputStream.getChunkSizeFromInputSt
> ream(ChunkedInputStream.java:250)
> 	at
>
org.apache.commons.httpclient.ChunkedInputStream.nextChunk(ChunkedInputS
> tream.java:221)
> 	at
>
org.apache.commons.httpclient.ChunkedInputStream.read(ChunkedInputStream
> .java:176)
> 	at
>
org.apache.commons.httpclient.ChunkedInputStream.read(ChunkedInputStream
> .java:196)
> 	at
>
org.apache.commons.httpclient.ChunkedInputStream.exhaustInputStream(Chun
> kedInputStream.java:369)
> 	at
>
org.apache.commons.httpclient.ChunkedInputStream.close(ChunkedInputStrea
> m.java:346)
> 	at java.io.FilterInputStream.close(FilterInputStream.java:159)
> 	at
>
org.apache.commons.httpclient.AutoCloseInputStream.notifyWatcher(AutoClo
> seInputStream.java:194)
> 	at
>
org.apache.commons.httpclient.AutoCloseInputStream.close(AutoCloseInputS
> tream.java:158)
> 	at
>
java.io.ObjectInputStream$PeekInputStream.close(ObjectInputStream.java:2
> 252)
> 	at
>
java.io.ObjectInputStream$BlockDataInputStream.close(ObjectInputStream.j
> ava:2587)
> 	at java.io.ObjectInputStream.close(ObjectInputStream.java:853)
> 	at
>
com.fusa.ssg.infra.remoting.common.io.StandardJavaSerializer.readObject(
> StandardJavaSerializer.java:41)
> 	at
>
com.fusa.ssg.infra.remoting.client.service.RemoteServiceExecutorImpl.des
> erializeServiceResponse(RemoteServiceExecutorImpl.java:153)
> 	at
>
com.fusa.ssg.infra.remoting.client.service.RemoteServiceExecutorImpl.exe
> cuteRequest(RemoteServiceExecutorImpl.java:111)
> 	at
>
com.fusa.ssg.infra.remoting.client.service.RemoteServiceProxy.invoke(Rem
> oteServiceProxy.java:54)
> 	at $Proxy5.getCallSeqId(Unknown Source)
> 	at
>
com.ccs.cco.cms.rcts.client.calltracking.CallTrackingRemotingDelegate.ge
> tCallSeqId(CallTrackingRemotingDelegate.java:66)
> 	at Actions.action(Actions.java:2327)
> ]
> Error	[MsgId: MERR-17999]
> System.err: 	at
>
com.fusa.ssg.infra.remoting.client.service.RemoteServiceProxy.invoke(Rem
> oteServiceProxy.java:58)
> Error	[MsgId: MMSG-17999]
> System.err: 	at $Proxy5.getCallSeqId(Unknown Source)
> Error	[MsgId: MMSG-17999]
> System.err: 	at
>
com.ccs.cco.cms.rcts.client.calltracking.CallTrackingRemotingDelegate.ge
> tCallSeqId(CallTrackingRemotingDelegate.java:66)
> Error	[MsgId: MMSG-17999]
> System.err: 	at Actions.action(Actions.java:2327)
> Error	[MsgId: MMSG-17999]
> 
> 
> 
> 
> 
> 
> 
> 
> 
> 
> This transmission may contain information that is privileged,
> confidential, legally privileged, and/or exempt from disclosure
> under applicable law.  If you are not the intended recipient, you
> are hereby notified that any disclosure, copying, distribution, or
> use of the information contained herein (including any reliance
> thereon) is STRICTLY PROHIBITED.  Although this transmission and
> any attachments are believed to be free of any virus or other
> defect that might affect any computer system into which it is
> received and opened, it is the responsibility of the recipient to
> ensure that it is virus free and no responsibility is accepted by
> JPMorgan Chase & Co., its subsidiaries and affiliates, as
> applicable, for any loss or damage arising in any way from its use.
>  If you received this transmission in error, please immediately
> contact the sender and destroy the material in its entirety,
> whether in electronic or hard copy format. Thank you.


---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
For additional commands, e-mail: httpclient-users-help@hc.apache.org


---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
For additional commands, e-mail: httpclient-users-help@hc.apache.org


Re: Infinite loop in ChunkedInputStream.close

Posted by Oleg Kalnichevski <ol...@apache.org>.
kenneth.s.brooks@chase.com wrote:
> We are using httpclient 3.1 to send a post and get back serialized java
> objects (think of something analogous to Spring Remoting).
> We deploy this client code to many client machines talking thru
> loadbalancers communicating with Weblogic 10MP1 servers.
> The clients in this test are on windows, running jdk5 thru mercury
> loadrunner (performance testing software).
> 
> We've been testing anywhere between 45 and 90tps and the vast majority
> of the transactions are successful.
> 
> About 1 transaction every half hour ends up with a
> java.net.SocketException: Connection reset.
> The loadbalancer will close the socket after 60 seconds.
> The reason we get that exception (and not a different one) is that we
> have the client timeout set up higher than 60 seconds (just for trying
> to expose this issue) and the loadbalancer has a 60 second timeout.
> 
> Here is what we have learned so far.
> 
> We get the response body as stream:
>             InputStream responseBody =
> postMethod.getResponseBodyAsStream();
> 
> We then send it thru a custom deserializer, we know that the object in
> the response is being read because the log right after it is being
> printed out:
> However we have a close on that input stream in the finally. I'm
> probably going to remove that close (since I read elsewhere that its
> taken care of by the postMethod.releaseConnection().
>         try {
>             Object object = ois.readObject();
>             LOG.debug(METHOD_NAME + "ois.readObject completed");
>             return object;
>         } finally {
>             ois.close();
>             LOG.debug(METHOD_NAME + "ois.close completed");
>         }
> 
> The ois.close() is calling AutoCloseInputStream.close, calling
> ChunkedInputStream.close which is trying to exhaust the stream by
> calling exhaustInputStream which eventually calls SocketInputStream.read
> and just sits there until the connection reset happens.
> 
> Any clue as to what would cause it to hang there?
> 

I seriously doubt this has anything to do with a tight loop in 
HttpClient code. Most likely the server fails to send the closing chunk, 
which causes the input stream to get blocked in a read operation.

> The confusing factors are that the object seems to be fully read (so I
> would assume there is nothing left in the stream) and we average a
> couple thousand good transactions for every 1 occurrence of a bad one.
> 
> Let me know if I need the full headers and wire. We have only the
> header, not the content turned on because the volume of logging just
> kills the clients when turned up to trace.

I am afraid the only reliable way of establishing the cause would be 
getting a complete wire log.

> Also, we will be looking to migrate eventually to httpclient 4, but that
> requires jdk5 and right now we have clients that are still
> (unfortunately) jdk1.4 so we can't quite make that leap yet.
> I have network captures as well, if you think you know what I should
> look for please advise and I will do so.
>

If you can find out where the session gets stuck see if the server sends 
the closing chunk back to the client. The chunk should look like 
<CR><LF>0<CR><LF>

Oleg

> Thanks,
> Ken
> 
> Here is the pertinent httpclient log.
> Notice the 1 minute gap in log statements between 15:54:25:723 EST and
> 15:55:25:756 EST
> Also be aware that the reason you see logs in between the issue and the
> time you see the stacktrace is that the postMethod.releaseConnection()
> is in a finally, so of course it will complete before the exception is
> propogated.
> 
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] PostMethod - enter
> PostMethod.clearRequestBody()
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] EntityEnclosingMethod -
> enter EntityEnclosingMethod.clearRequestBody()
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [DEBUG]
> RemoteServiceExecutorImpl - executeRequest calling
> httpClient.ExecuteMethod
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpClient - enter
> HttpClient.executeMethod(HttpMethod)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpClient - enter
> HttpClient.executeMethod(HostConfiguration,HttpMethod,HttpState)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE]
> MultiThreadedHttpConnectionManager - enter
> HttpConnectionManager.getConnectionWithTimeout(HostConfiguration, long)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [DEBUG]
> MultiThreadedHttpConnectionManager -
> HttpConnectionManager.getConnection:  config =
> HostConfiguration[host=http://my-loadbalancer:9810], timeout = 0
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE]
> MultiThreadedHttpConnectionManager - enter
> HttpConnectionManager.ConnectionPool.getHostPool(HostConfiguration)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE]
> MultiThreadedHttpConnectionManager - enter
> HttpConnectionManager.ConnectionPool.getHostPool(HostConfiguration)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [DEBUG]
> MultiThreadedHttpConnectionManager - Allocating new connection,
> hostConfig=HostConfiguration[host=http://my-loadbalancer:9810]
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpMethodDirector -
> Attempt number 1 to process request
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
> HttpConnection.open()
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [DEBUG] HttpConnection - Open
> connection to my-loadbalancer:9810
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpMethodBase - enter
> HttpMethodBase.execute(HttpState, HttpConnection)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpMethodBase - enter
> HttpMethodBase.writeRequest(HttpState, HttpConnection)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpMethodBase - enter
> HttpMethodBase.writeRequestLine(HttpState, HttpConnection)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpMethodBase - enter
> HttpMethodBase.generateRequestLine(HttpConnection, String, String,
> String, String)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [DEBUG] header - >> "POST
> /cms.rcts/2009.9.1.006/ccs/prf.lr/2008.8.1/CDC/essd-remote/
> HTTP/1.1[\r][\n]"
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
> HttpConnection.print(String)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
> HttpConnection.write(byte[])
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
> HttpConnection.write(byte[], int, int)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpMethodBase - enter
> HttpMethodBase.writeRequestHeaders(HttpState,HttpConnection)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] EntityEnclosingMethod -
> enter EntityEnclosingMethod.addRequestHeaders(HttpState, HttpConnection)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] ExpectContinueMethod -
> enter ExpectContinueMethod.addRequestHeaders(HttpState, HttpConnection)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpMethodBase - enter
> HttpMethodBase.addRequestHeaders(HttpState, HttpConnection)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpMethodBase - enter
> HttpMethodBase.addUserAgentRequestHeaders(HttpState, HttpConnection)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpMethodBase - enter
> HttpMethodBase.addHostRequestHeader(HttpState, HttpConnection)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [DEBUG] HttpMethodBase - Adding
> Host request header
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpMethodBase - enter
> HttpMethodBase.addCookieRequestHeader(HttpState, HttpConnection)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpState - enter
> HttpState.getCookies()
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpMethodBase - enter
> HttpMethodBase.addProxyConnectionHeader(HttpState, HttpConnection)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] EntityEnclosingMethod -
> enter EntityEnclosingMethod.addContentLengthRequestHeader(HttpState,
> HttpConnection)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] EntityEnclosingMethod -
> enter EntityEnclosingMethod.getRequestContentLength()
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] PostMethod - enter
> PostMethod.hasRequestContent()
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] EntityEnclosingMethod -
> enter EntityEnclosingMethod.hasRequestContent()
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpMethodBase -
> HttpMethodBase.addRequestHeader(Header)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [DEBUG] header - >>
> "Content-Type: application/x-java-serialized-object[\r][\n]"
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
> HttpConnection.print(String)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
> HttpConnection.write(byte[])
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
> HttpConnection.write(byte[], int, int)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [DEBUG] header - >>
> "Content-Encoding: none[\r][\n]"
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
> HttpConnection.print(String)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
> HttpConnection.write(byte[])
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
> HttpConnection.write(byte[], int, int)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [DEBUG] header - >>
> "Serialization-Type: java[\r][\n]"
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
> HttpConnection.print(String)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
> HttpConnection.write(byte[])
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
> HttpConnection.write(byte[], int, int)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [DEBUG] header - >> "User-Agent:
> Jakarta Commons-HttpClient/3.1[\r][\n]"
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
> HttpConnection.print(String)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
> HttpConnection.write(byte[])
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
> HttpConnection.write(byte[], int, int)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [DEBUG] header - >> "Host:
> my-loadbalancer:9810[\r][\n]"
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
> HttpConnection.print(String)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
> HttpConnection.write(byte[])
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
> HttpConnection.write(byte[], int, int)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [DEBUG] header - >>
> "Content-Length: 3051[\r][\n]"
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
> HttpConnection.print(String)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
> HttpConnection.write(byte[])
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
> HttpConnection.write(byte[], int, int)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
> HttpConnection.writeLine()
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
> HttpConnection.write(byte[])
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
> HttpConnection.write(byte[], int, int)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [DEBUG] header - >> "[\r][\n]"
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] EntityEnclosingMethod -
> enter EntityEnclosingMethod.writeRequestBody(HttpState, HttpConnection)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] PostMethod - enter
> PostMethod.hasRequestContent()
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] EntityEnclosingMethod -
> enter EntityEnclosingMethod.hasRequestContent()
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] EntityEnclosingMethod -
> enter EntityEnclosingMethod.getRequestContentLength()
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] PostMethod - enter
> PostMethod.hasRequestContent()
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:707 EST [TRACE] EntityEnclosingMethod -
> enter EntityEnclosingMethod.hasRequestContent()
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpConnection - enter
> HttpConnection.getRequestOutputStream()
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [DEBUG] EntityEnclosingMethod -
> Request body sent
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpConnection - enter
> HttpConnection.flushRequestOutputStream()
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpMethodBase - enter
> HttpMethodBase.readResponse(HttpState, HttpConnection)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpMethodBase - enter
> HttpMethodBase.readStatusLine(HttpState, HttpConnection)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpConnection - enter
> HttpConnection.readLine()
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpParser - enter
> HttpParser.readLine(InputStream, String)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpParser - enter
> HttpParser.readRawLine()
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [DEBUG] header - << "HTTP/1.1
> 200 OK[\r][\n]"
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [DEBUG] header - << "HTTP/1.1
> 200 OK[\r][\n]"
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpMethodBase - enter
> HttpMethodBase.readResponseHeaders(HttpState,HttpConnection)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpConnection - enter
> HttpConnection.getResponseInputStream()
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpParser - enter
> HeaderParser.parseHeaders(InputStream, String)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpParser - enter
> HttpParser.readLine(InputStream, String)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpParser - enter
> HttpParser.readRawLine()
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [DEBUG] header - << "Date: Tue,
> 17 Nov 2009 20:54:25 GMT[\r][\n]"
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpParser - enter
> HttpParser.readLine(InputStream, String)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpParser - enter
> HttpParser.readRawLine()
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [DEBUG] header - <<
> "Transfer-Encoding: chunked[\r][\n]"
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpParser - enter
> HttpParser.readLine(InputStream, String)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpParser - enter
> HttpParser.readRawLine()
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [DEBUG] header - <<
> "Content-Type: application/x-java-serialized-object[\r][\n]"
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpParser - enter
> HttpParser.readLine(InputStream, String)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpParser - enter
> HttpParser.readRawLine()
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [DEBUG] header - <<
> "Content-Encoding: none[\r][\n]"
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpParser - enter
> HttpParser.readLine(InputStream, String)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpParser - enter
> HttpParser.readRawLine()
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [DEBUG] header - <<
> "Serialization-Type: java[\r][\n]"
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpParser - enter
> HttpParser.readLine(InputStream, String)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpParser - enter
> HttpParser.readRawLine()
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [DEBUG] header - << "[\r][\n]"
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpMethodBase - enter
> HttpMethodBase.processResponseHeaders(HttpState, HttpConnection)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpMethodBase - enter
> HttpMethodBase.processCookieHeaders(Header[], HttpState, HttpConnection)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpMethodBase - enter
> HttpMethodBase.readResponseBody(HttpState, HttpConnection)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpMethodBase - enter
> HttpMethodBase.readResponseBody(HttpConnection)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpConnection - enter
> HttpConnection.getResponseInputStream()
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpMethodBase - enter
> HttpMethodBase.canResponseHaveBody(int)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [TRACE] HeaderElement - enter
> HeaderElement.parseElements(String)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [TRACE] HeaderElement - enter
> HeaderElement.parseElements(char[])
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpConnection - enter
> HttpConnection.isResponseAvailable(int)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [DEBUG]
> RemoteServiceExecutorImpl - executeRequesthttpClient.ExecuteMethod
> completed
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:54:25:723 EST [DEBUG]
> RemoteServiceExecutorImpl -
> executeRequestpostMethod.getResponseBodyAsStream completed
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:55:25:756 EST [TRACE] HttpConnection - enter
> HttpConnection.releaseConnection()
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:55:25:756 EST [DEBUG] HttpConnection -
> Releasing connection back to connection manager.
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:55:25:756 EST [TRACE]
> MultiThreadedHttpConnectionManager - enter
> HttpConnectionManager.releaseConnection(HttpConnection)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:55:25:756 EST [DEBUG]
> MultiThreadedHttpConnectionManager - Freeing connection,
> hostConfig=HostConfiguration[host=http://my-loadbalancer:9810]
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:55:25:756 EST [TRACE]
> MultiThreadedHttpConnectionManager - enter
> HttpConnectionManager.ConnectionPool.getHostPool(HostConfiguration)
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:55:25:756 EST [DEBUG] IdleConnectionHandler -
> Adding connection at: 1258491325756
> Error	[MsgId: MMSG-17999]
> System.err: 2009/11/17 15:55:25:756 EST [DEBUG]
> MultiThreadedHttpConnectionManager - Notifying no-one, there are no
> waiting threads
> Error	[MsgId: MMSG-17999]
> Error: Failed to end Transaction "callTrackingService_insertWorkFlow"
> (by name). Please check that you made a call to start transaction
> operation.	[MsgId: MERR-16985]
> Error: System.err: com.fusa.ssg.SystemException: Error making call[Error
> executing Remote Method=[getCallSeqId] for Service
> Url=[http://my-loadbalancer:9810/cms.rcts/2009.9.1.006/ccs/prf.lr/2008.8
> .1/CDC] Exception=[java.net.SocketException: Connection reset
> 	at java.net.SocketInputStream.read(SocketInputStream.java:168)
> 	at
> java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
> 	at
> java.io.BufferedInputStream.read(BufferedInputStream.java:235)
> 	at
> org.apache.commons.httpclient.ChunkedInputStream.getChunkSizeFromInputSt
> ream(ChunkedInputStream.java:250)
> 	at
> org.apache.commons.httpclient.ChunkedInputStream.nextChunk(ChunkedInputS
> tream.java:221)
> 	at
> org.apache.commons.httpclient.ChunkedInputStream.read(ChunkedInputStream
> .java:176)
> 	at
> org.apache.commons.httpclient.ChunkedInputStream.read(ChunkedInputStream
> .java:196)
> 	at
> org.apache.commons.httpclient.ChunkedInputStream.exhaustInputStream(Chun
> kedInputStream.java:369)
> 	at
> org.apache.commons.httpclient.ChunkedInputStream.close(ChunkedInputStrea
> m.java:346)
> 	at java.io.FilterInputStream.close(FilterInputStream.java:159)
> 	at
> org.apache.commons.httpclient.AutoCloseInputStream.notifyWatcher(AutoClo
> seInputStream.java:194)
> 	at
> org.apache.commons.httpclient.AutoCloseInputStream.close(AutoCloseInputS
> tream.java:158)
> 	at
> java.io.ObjectInputStream$PeekInputStream.close(ObjectInputStream.java:2
> 252)
> 	at
> java.io.ObjectInputStream$BlockDataInputStream.close(ObjectInputStream.j
> ava:2587)
> 	at java.io.ObjectInputStream.close(ObjectInputStream.java:853)
> 	at
> com.fusa.ssg.infra.remoting.common.io.StandardJavaSerializer.readObject(
> StandardJavaSerializer.java:41)
> 	at
> com.fusa.ssg.infra.remoting.client.service.RemoteServiceExecutorImpl.des
> erializeServiceResponse(RemoteServiceExecutorImpl.java:153)
> 	at
> com.fusa.ssg.infra.remoting.client.service.RemoteServiceExecutorImpl.exe
> cuteRequest(RemoteServiceExecutorImpl.java:111)
> 	at
> com.fusa.ssg.infra.remoting.client.service.RemoteServiceProxy.invoke(Rem
> oteServiceProxy.java:54)
> 	at $Proxy5.getCallSeqId(Unknown Source)
> 	at
> com.ccs.cco.cms.rcts.client.calltracking.CallTrackingRemotingDelegate.ge
> tCallSeqId(CallTrackingRemotingDelegate.java:66)
> 	at Actions.action(Actions.java:2327)
> ]]
> Error	[MsgId: MERR-17999]
> System.err: 	at
> com.ccs.cco.cms.rcts.client.calltracking.CallTrackingRemotingDelegate.ge
> tCallSeqId(CallTrackingRemotingDelegate.java:81)
> Error	[MsgId: MMSG-17999]
> System.err: 	at Actions.action(Actions.java:2327)
> Error	[MsgId: MMSG-17999]
> Error: System.err: ------------Wrapped Exception-----------
> Error	[MsgId: MERR-17999]
> Error: System.err:
> com.fusa.ssg.infra.remoting.common.RemoteServiceException: Error
> executing Remote Method=[getCallSeqId] for Service
> Url=[http://my-loadbalancer:9810/cms.rcts/2009.9.1.006/ccs/prf.lr/2008.8
> .1/CDC] Exception=[java.net.SocketException: Connection reset
> 	at java.net.SocketInputStream.read(SocketInputStream.java:168)
> 	at
> java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
> 	at
> java.io.BufferedInputStream.read(BufferedInputStream.java:235)
> 	at
> org.apache.commons.httpclient.ChunkedInputStream.getChunkSizeFromInputSt
> ream(ChunkedInputStream.java:250)
> 	at
> org.apache.commons.httpclient.ChunkedInputStream.nextChunk(ChunkedInputS
> tream.java:221)
> 	at
> org.apache.commons.httpclient.ChunkedInputStream.read(ChunkedInputStream
> .java:176)
> 	at
> org.apache.commons.httpclient.ChunkedInputStream.read(ChunkedInputStream
> .java:196)
> 	at
> org.apache.commons.httpclient.ChunkedInputStream.exhaustInputStream(Chun
> kedInputStream.java:369)
> 	at
> org.apache.commons.httpclient.ChunkedInputStream.close(ChunkedInputStrea
> m.java:346)
> 	at java.io.FilterInputStream.close(FilterInputStream.java:159)
> 	at
> org.apache.commons.httpclient.AutoCloseInputStream.notifyWatcher(AutoClo
> seInputStream.java:194)
> 	at
> org.apache.commons.httpclient.AutoCloseInputStream.close(AutoCloseInputS
> tream.java:158)
> 	at
> java.io.ObjectInputStream$PeekInputStream.close(ObjectInputStream.java:2
> 252)
> 	at
> java.io.ObjectInputStream$BlockDataInputStream.close(ObjectInputStream.j
> ava:2587)
> 	at java.io.ObjectInputStream.close(ObjectInputStream.java:853)
> 	at
> com.fusa.ssg.infra.remoting.common.io.StandardJavaSerializer.readObject(
> StandardJavaSerializer.java:41)
> 	at
> com.fusa.ssg.infra.remoting.client.service.RemoteServiceExecutorImpl.des
> erializeServiceResponse(RemoteServiceExecutorImpl.java:153)
> 	at
> com.fusa.ssg.infra.remoting.client.service.RemoteServiceExecutorImpl.exe
> cuteRequest(RemoteServiceExecutorImpl.java:111)
> 	at
> com.fusa.ssg.infra.remoting.client.service.RemoteServiceProxy.invoke(Rem
> oteServiceProxy.java:54)
> 	at $Proxy5.getCallSeqId(Unknown Source)
> 	at
> com.ccs.cco.cms.rcts.client.calltracking.CallTrackingRemotingDelegate.ge
> tCallSeqId(CallTrackingRemotingDelegate.java:66)
> 	at Actions.action(Actions.java:2327)
> ]
> Error	[MsgId: MERR-17999]
> System.err: 	at
> com.fusa.ssg.infra.remoting.client.service.RemoteServiceProxy.invoke(Rem
> oteServiceProxy.java:58)
> Error	[MsgId: MMSG-17999]
> System.err: 	at $Proxy5.getCallSeqId(Unknown Source)
> Error	[MsgId: MMSG-17999]
> System.err: 	at
> com.ccs.cco.cms.rcts.client.calltracking.CallTrackingRemotingDelegate.ge
> tCallSeqId(CallTrackingRemotingDelegate.java:66)
> Error	[MsgId: MMSG-17999]
> System.err: 	at Actions.action(Actions.java:2327)
> Error	[MsgId: MMSG-17999]
> Error: System.err: -----------Wrapped Exception-----------
> Error	[MsgId: MERR-17999]
> Error: System.err:
> com.fusa.ssg.infra.remoting.common.RemoteServiceException: Error
> executing Remote Method=[getCallSeqId] for Service
> Url=[http://my-loadbalancer:9810/cms.rcts/2009.9.1.006/ccs/prf.lr/2008.8
> .1/CDC] Exception=[java.net.SocketException: Connection reset
> 	at java.net.SocketInputStream.read(SocketInputStream.java:168)
> 	at
> java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
> 	at
> java.io.BufferedInputStream.read(BufferedInputStream.java:235)
> 	at
> org.apache.commons.httpclient.ChunkedInputStream.getChunkSizeFromInputSt
> ream(ChunkedInputStream.java:250)
> 	at
> org.apache.commons.httpclient.ChunkedInputStream.nextChunk(ChunkedInputS
> tream.java:221)
> 	at
> org.apache.commons.httpclient.ChunkedInputStream.read(ChunkedInputStream
> .java:176)
> 	at
> org.apache.commons.httpclient.ChunkedInputStream.read(ChunkedInputStream
> .java:196)
> 	at
> org.apache.commons.httpclient.ChunkedInputStream.exhaustInputStream(Chun
> kedInputStream.java:369)
> 	at
> org.apache.commons.httpclient.ChunkedInputStream.close(ChunkedInputStrea
> m.java:346)
> 	at java.io.FilterInputStream.close(FilterInputStream.java:159)
> 	at
> org.apache.commons.httpclient.AutoCloseInputStream.notifyWatcher(AutoClo
> seInputStream.java:194)
> 	at
> org.apache.commons.httpclient.AutoCloseInputStream.close(AutoCloseInputS
> tream.java:158)
> 	at
> java.io.ObjectInputStream$PeekInputStream.close(ObjectInputStream.java:2
> 252)
> 	at
> java.io.ObjectInputStream$BlockDataInputStream.close(ObjectInputStream.j
> ava:2587)
> 	at java.io.ObjectInputStream.close(ObjectInputStream.java:853)
> 	at
> com.fusa.ssg.infra.remoting.common.io.StandardJavaSerializer.readObject(
> StandardJavaSerializer.java:41)
> 	at
> com.fusa.ssg.infra.remoting.client.service.RemoteServiceExecutorImpl.des
> erializeServiceResponse(RemoteServiceExecutorImpl.java:153)
> 	at
> com.fusa.ssg.infra.remoting.client.service.RemoteServiceExecutorImpl.exe
> cuteRequest(RemoteServiceExecutorImpl.java:111)
> 	at
> com.fusa.ssg.infra.remoting.client.service.RemoteServiceProxy.invoke(Rem
> oteServiceProxy.java:54)
> 	at $Proxy5.getCallSeqId(Unknown Source)
> 	at
> com.ccs.cco.cms.rcts.client.calltracking.CallTrackingRemotingDelegate.ge
> tCallSeqId(CallTrackingRemotingDelegate.java:66)
> 	at Actions.action(Actions.java:2327)
> ]
> Error	[MsgId: MERR-17999]
> System.err: 	at
> com.fusa.ssg.infra.remoting.client.service.RemoteServiceProxy.invoke(Rem
> oteServiceProxy.java:58)
> Error	[MsgId: MMSG-17999]
> System.err: 	at $Proxy5.getCallSeqId(Unknown Source)
> Error	[MsgId: MMSG-17999]
> System.err: 	at
> com.ccs.cco.cms.rcts.client.calltracking.CallTrackingRemotingDelegate.ge
> tCallSeqId(CallTrackingRemotingDelegate.java:66)
> Error	[MsgId: MMSG-17999]
> System.err: 	at Actions.action(Actions.java:2327)
> Error	[MsgId: MMSG-17999]
> 
> 
> 
> 
> 
> 
> 
> 
> 
> 
> This transmission may contain information that is privileged,
> confidential, legally privileged, and/or exempt from disclosure
> under applicable law.  If you are not the intended recipient, you
> are hereby notified that any disclosure, copying, distribution, or
> use of the information contained herein (including any reliance
> thereon) is STRICTLY PROHIBITED.  Although this transmission and
> any attachments are believed to be free of any virus or other
> defect that might affect any computer system into which it is
> received and opened, it is the responsibility of the recipient to
> ensure that it is virus free and no responsibility is accepted by
> JPMorgan Chase & Co., its subsidiaries and affiliates, as
> applicable, for any loss or damage arising in any way from its use.
>  If you received this transmission in error, please immediately
> contact the sender and destroy the material in its entirety,
> whether in electronic or hard copy format. Thank you.


---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
For additional commands, e-mail: httpclient-users-help@hc.apache.org


RE: Infinite loop in ChunkedInputStream.close

Posted by ke...@chase.com.
One other thing to mention, the server always gets the request and
responds in milliseconds so its not an issue of the server just not
responding for over 60 seconds.

The client even shows that as I updated the logging to spit out that log
after the ois.readObject and here are those log statements.
It shows that we were able to fully read the object inside the input
stream and that the delay is only happening in the close call.
System.err: 2009/11/18 16:30:46:721 EST [DEBUG] StandardJavaSerializer -
readObjectois.readObject completed      Error	[MsgId: MMSG-17999]
System.err: 2009/11/18 16:31:46:753 EST [TRACE] HttpConnection - enter
HttpConnection.releaseConnection()        Error	[MsgId: MMSG-17999]

-ken

-----Original Message-----
From: kenneth.s.brooks@chase.com [mailto:kenneth.s.brooks@chase.com] 
Sent: Wednesday, November 18, 2009 10:30 PM
To: httpclient-users@hc.apache.org
Subject: Infinite loop in ChunkedInputStream.close

We are using httpclient 3.1 to send a post and get back serialized java
objects (think of something analogous to Spring Remoting).
We deploy this client code to many client machines talking thru
loadbalancers communicating with Weblogic 10MP1 servers.
The clients in this test are on windows, running jdk5 thru mercury
loadrunner (performance testing software).

We've been testing anywhere between 45 and 90tps and the vast majority
of the transactions are successful.

About 1 transaction every half hour ends up with a
java.net.SocketException: Connection reset.
The loadbalancer will close the socket after 60 seconds.
The reason we get that exception (and not a different one) is that we
have the client timeout set up higher than 60 seconds (just for trying
to expose this issue) and the loadbalancer has a 60 second timeout.

Here is what we have learned so far.

We get the response body as stream:
            InputStream responseBody =
postMethod.getResponseBodyAsStream();

We then send it thru a custom deserializer, we know that the object in
the response is being read because the log right after it is being
printed out:
However we have a close on that input stream in the finally. I'm
probably going to remove that close (since I read elsewhere that its
taken care of by the postMethod.releaseConnection().
        try {
            Object object = ois.readObject();
            LOG.debug(METHOD_NAME + "ois.readObject completed");
            return object;
        } finally {
            ois.close();
            LOG.debug(METHOD_NAME + "ois.close completed");
        }

The ois.close() is calling AutoCloseInputStream.close, calling
ChunkedInputStream.close which is trying to exhaust the stream by
calling exhaustInputStream which eventually calls SocketInputStream.read
and just sits there until the connection reset happens.

Any clue as to what would cause it to hang there?

The confusing factors are that the object seems to be fully read (so I
would assume there is nothing left in the stream) and we average a
couple thousand good transactions for every 1 occurrence of a bad one.

Let me know if I need the full headers and wire. We have only the
header, not the content turned on because the volume of logging just
kills the clients when turned up to trace.
Also, we will be looking to migrate eventually to httpclient 4, but that
requires jdk5 and right now we have clients that are still
(unfortunately) jdk1.4 so we can't quite make that leap yet.
I have network captures as well, if you think you know what I should
look for please advise and I will do so.

Thanks,
Ken

Here is the pertinent httpclient log.
Notice the 1 minute gap in log statements between 15:54:25:723 EST and
15:55:25:756 EST
Also be aware that the reason you see logs in between the issue and the
time you see the stacktrace is that the postMethod.releaseConnection()
is in a finally, so of course it will complete before the exception is
propogated.

System.err: 2009/11/17 15:54:25:707 EST [TRACE] PostMethod - enter
PostMethod.clearRequestBody()
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] EntityEnclosingMethod -
enter EntityEnclosingMethod.clearRequestBody()
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [DEBUG]
RemoteServiceExecutorImpl - executeRequest calling
httpClient.ExecuteMethod
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpClient - enter
HttpClient.executeMethod(HttpMethod)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpClient - enter
HttpClient.executeMethod(HostConfiguration,HttpMethod,HttpState)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE]
MultiThreadedHttpConnectionManager - enter
HttpConnectionManager.getConnectionWithTimeout(HostConfiguration, long)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [DEBUG]
MultiThreadedHttpConnectionManager -
HttpConnectionManager.getConnection:  config =
HostConfiguration[host=http://my-loadbalancer:9810], timeout = 0
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE]
MultiThreadedHttpConnectionManager - enter
HttpConnectionManager.ConnectionPool.getHostPool(HostConfiguration)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE]
MultiThreadedHttpConnectionManager - enter
HttpConnectionManager.ConnectionPool.getHostPool(HostConfiguration)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [DEBUG]
MultiThreadedHttpConnectionManager - Allocating new connection,
hostConfig=HostConfiguration[host=http://my-loadbalancer:9810]
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpMethodDirector -
Attempt number 1 to process request
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
HttpConnection.open()
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [DEBUG] HttpConnection - Open
connection to my-loadbalancer:9810
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpMethodBase - enter
HttpMethodBase.execute(HttpState, HttpConnection)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpMethodBase - enter
HttpMethodBase.writeRequest(HttpState, HttpConnection)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpMethodBase - enter
HttpMethodBase.writeRequestLine(HttpState, HttpConnection)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpMethodBase - enter
HttpMethodBase.generateRequestLine(HttpConnection, String, String,
String, String)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [DEBUG] header - >> "POST
/cms.rcts/2009.9.1.006/ccs/prf.lr/2008.8.1/CDC/essd-remote/
HTTP/1.1[\r][\n]"
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
HttpConnection.print(String)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
HttpConnection.write(byte[])
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
HttpConnection.write(byte[], int, int)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpMethodBase - enter
HttpMethodBase.writeRequestHeaders(HttpState,HttpConnection)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] EntityEnclosingMethod -
enter EntityEnclosingMethod.addRequestHeaders(HttpState, HttpConnection)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] ExpectContinueMethod -
enter ExpectContinueMethod.addRequestHeaders(HttpState, HttpConnection)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpMethodBase - enter
HttpMethodBase.addRequestHeaders(HttpState, HttpConnection)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpMethodBase - enter
HttpMethodBase.addUserAgentRequestHeaders(HttpState, HttpConnection)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpMethodBase - enter
HttpMethodBase.addHostRequestHeader(HttpState, HttpConnection)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [DEBUG] HttpMethodBase - Adding
Host request header
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpMethodBase - enter
HttpMethodBase.addCookieRequestHeader(HttpState, HttpConnection)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpState - enter
HttpState.getCookies()
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpMethodBase - enter
HttpMethodBase.addProxyConnectionHeader(HttpState, HttpConnection)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] EntityEnclosingMethod -
enter EntityEnclosingMethod.addContentLengthRequestHeader(HttpState,
HttpConnection)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] EntityEnclosingMethod -
enter EntityEnclosingMethod.getRequestContentLength()
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] PostMethod - enter
PostMethod.hasRequestContent()
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] EntityEnclosingMethod -
enter EntityEnclosingMethod.hasRequestContent()
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpMethodBase -
HttpMethodBase.addRequestHeader(Header)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [DEBUG] header - >>
"Content-Type: application/x-java-serialized-object[\r][\n]"
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
HttpConnection.print(String)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
HttpConnection.write(byte[])
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
HttpConnection.write(byte[], int, int)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [DEBUG] header - >>
"Content-Encoding: none[\r][\n]"
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
HttpConnection.print(String)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
HttpConnection.write(byte[])
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
HttpConnection.write(byte[], int, int)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [DEBUG] header - >>
"Serialization-Type: java[\r][\n]"
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
HttpConnection.print(String)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
HttpConnection.write(byte[])
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
HttpConnection.write(byte[], int, int)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [DEBUG] header - >> "User-Agent:
Jakarta Commons-HttpClient/3.1[\r][\n]"
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
HttpConnection.print(String)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
HttpConnection.write(byte[])
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
HttpConnection.write(byte[], int, int)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [DEBUG] header - >> "Host:
my-loadbalancer:9810[\r][\n]"
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
HttpConnection.print(String)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
HttpConnection.write(byte[])
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
HttpConnection.write(byte[], int, int)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [DEBUG] header - >>
"Content-Length: 3051[\r][\n]"
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
HttpConnection.print(String)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
HttpConnection.write(byte[])
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
HttpConnection.write(byte[], int, int)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
HttpConnection.writeLine()
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
HttpConnection.write(byte[])
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] HttpConnection - enter
HttpConnection.write(byte[], int, int)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [DEBUG] header - >> "[\r][\n]"
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] EntityEnclosingMethod -
enter EntityEnclosingMethod.writeRequestBody(HttpState, HttpConnection)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] PostMethod - enter
PostMethod.hasRequestContent()
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] EntityEnclosingMethod -
enter EntityEnclosingMethod.hasRequestContent()
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] EntityEnclosingMethod -
enter EntityEnclosingMethod.getRequestContentLength()
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] PostMethod - enter
PostMethod.hasRequestContent()
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:707 EST [TRACE] EntityEnclosingMethod -
enter EntityEnclosingMethod.hasRequestContent()
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpConnection - enter
HttpConnection.getRequestOutputStream()
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [DEBUG] EntityEnclosingMethod -
Request body sent
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpConnection - enter
HttpConnection.flushRequestOutputStream()
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpMethodBase - enter
HttpMethodBase.readResponse(HttpState, HttpConnection)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpMethodBase - enter
HttpMethodBase.readStatusLine(HttpState, HttpConnection)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpConnection - enter
HttpConnection.readLine()
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpParser - enter
HttpParser.readLine(InputStream, String)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpParser - enter
HttpParser.readRawLine()
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [DEBUG] header - << "HTTP/1.1
200 OK[\r][\n]"
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [DEBUG] header - << "HTTP/1.1
200 OK[\r][\n]"
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpMethodBase - enter
HttpMethodBase.readResponseHeaders(HttpState,HttpConnection)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpConnection - enter
HttpConnection.getResponseInputStream()
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpParser - enter
HeaderParser.parseHeaders(InputStream, String)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpParser - enter
HttpParser.readLine(InputStream, String)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpParser - enter
HttpParser.readRawLine()
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [DEBUG] header - << "Date: Tue,
17 Nov 2009 20:54:25 GMT[\r][\n]"
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpParser - enter
HttpParser.readLine(InputStream, String)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpParser - enter
HttpParser.readRawLine()
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [DEBUG] header - <<
"Transfer-Encoding: chunked[\r][\n]"
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpParser - enter
HttpParser.readLine(InputStream, String)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpParser - enter
HttpParser.readRawLine()
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [DEBUG] header - <<
"Content-Type: application/x-java-serialized-object[\r][\n]"
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpParser - enter
HttpParser.readLine(InputStream, String)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpParser - enter
HttpParser.readRawLine()
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [DEBUG] header - <<
"Content-Encoding: none[\r][\n]"
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpParser - enter
HttpParser.readLine(InputStream, String)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpParser - enter
HttpParser.readRawLine()
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [DEBUG] header - <<
"Serialization-Type: java[\r][\n]"
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpParser - enter
HttpParser.readLine(InputStream, String)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpParser - enter
HttpParser.readRawLine()
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [DEBUG] header - << "[\r][\n]"
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpMethodBase - enter
HttpMethodBase.processResponseHeaders(HttpState, HttpConnection)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpMethodBase - enter
HttpMethodBase.processCookieHeaders(Header[], HttpState, HttpConnection)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpMethodBase - enter
HttpMethodBase.readResponseBody(HttpState, HttpConnection)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpMethodBase - enter
HttpMethodBase.readResponseBody(HttpConnection)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpConnection - enter
HttpConnection.getResponseInputStream()
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpMethodBase - enter
HttpMethodBase.canResponseHaveBody(int)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [TRACE] HeaderElement - enter
HeaderElement.parseElements(String)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [TRACE] HeaderElement - enter
HeaderElement.parseElements(char[])
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [TRACE] HttpConnection - enter
HttpConnection.isResponseAvailable(int)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [DEBUG]
RemoteServiceExecutorImpl - executeRequesthttpClient.ExecuteMethod
completed
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:54:25:723 EST [DEBUG]
RemoteServiceExecutorImpl -
executeRequestpostMethod.getResponseBodyAsStream completed
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:55:25:756 EST [TRACE] HttpConnection - enter
HttpConnection.releaseConnection()
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:55:25:756 EST [DEBUG] HttpConnection -
Releasing connection back to connection manager.
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:55:25:756 EST [TRACE]
MultiThreadedHttpConnectionManager - enter
HttpConnectionManager.releaseConnection(HttpConnection)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:55:25:756 EST [DEBUG]
MultiThreadedHttpConnectionManager - Freeing connection,
hostConfig=HostConfiguration[host=http://my-loadbalancer:9810]
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:55:25:756 EST [TRACE]
MultiThreadedHttpConnectionManager - enter
HttpConnectionManager.ConnectionPool.getHostPool(HostConfiguration)
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:55:25:756 EST [DEBUG] IdleConnectionHandler -
Adding connection at: 1258491325756
Error	[MsgId: MMSG-17999]
System.err: 2009/11/17 15:55:25:756 EST [DEBUG]
MultiThreadedHttpConnectionManager - Notifying no-one, there are no
waiting threads
Error	[MsgId: MMSG-17999]
Error: Failed to end Transaction "callTrackingService_insertWorkFlow"
(by name). Please check that you made a call to start transaction
operation.	[MsgId: MERR-16985]
Error: System.err: com.fusa.ssg.SystemException: Error making call[Error
executing Remote Method=[getCallSeqId] for Service
Url=[http://my-loadbalancer:9810/cms.rcts/2009.9.1.006/ccs/prf.lr/2008.8
.1/CDC] Exception=[java.net.SocketException: Connection reset
	at java.net.SocketInputStream.read(SocketInputStream.java:168)
	at
java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
	at
java.io.BufferedInputStream.read(BufferedInputStream.java:235)
	at
org.apache.commons.httpclient.ChunkedInputStream.getChunkSizeFromInputSt
ream(ChunkedInputStream.java:250)
	at
org.apache.commons.httpclient.ChunkedInputStream.nextChunk(ChunkedInputS
tream.java:221)
	at
org.apache.commons.httpclient.ChunkedInputStream.read(ChunkedInputStream
.java:176)
	at
org.apache.commons.httpclient.ChunkedInputStream.read(ChunkedInputStream
.java:196)
	at
org.apache.commons.httpclient.ChunkedInputStream.exhaustInputStream(Chun
kedInputStream.java:369)
	at
org.apache.commons.httpclient.ChunkedInputStream.close(ChunkedInputStrea
m.java:346)
	at java.io.FilterInputStream.close(FilterInputStream.java:159)
	at
org.apache.commons.httpclient.AutoCloseInputStream.notifyWatcher(AutoClo
seInputStream.java:194)
	at
org.apache.commons.httpclient.AutoCloseInputStream.close(AutoCloseInputS
tream.java:158)
	at
java.io.ObjectInputStream$PeekInputStream.close(ObjectInputStream.java:2
252)
	at
java.io.ObjectInputStream$BlockDataInputStream.close(ObjectInputStream.j
ava:2587)
	at java.io.ObjectInputStream.close(ObjectInputStream.java:853)
	at
com.fusa.ssg.infra.remoting.common.io.StandardJavaSerializer.readObject(
StandardJavaSerializer.java:41)
	at
com.fusa.ssg.infra.remoting.client.service.RemoteServiceExecutorImpl.des
erializeServiceResponse(RemoteServiceExecutorImpl.java:153)
	at
com.fusa.ssg.infra.remoting.client.service.RemoteServiceExecutorImpl.exe
cuteRequest(RemoteServiceExecutorImpl.java:111)
	at
com.fusa.ssg.infra.remoting.client.service.RemoteServiceProxy.invoke(Rem
oteServiceProxy.java:54)
	at $Proxy5.getCallSeqId(Unknown Source)
	at
com.ccs.cco.cms.rcts.client.calltracking.CallTrackingRemotingDelegate.ge
tCallSeqId(CallTrackingRemotingDelegate.java:66)
	at Actions.action(Actions.java:2327)
]]
Error	[MsgId: MERR-17999]
System.err: 	at
com.ccs.cco.cms.rcts.client.calltracking.CallTrackingRemotingDelegate.ge
tCallSeqId(CallTrackingRemotingDelegate.java:81)
Error	[MsgId: MMSG-17999]
System.err: 	at Actions.action(Actions.java:2327)
Error	[MsgId: MMSG-17999]
Error: System.err: ------------Wrapped Exception-----------
Error	[MsgId: MERR-17999]
Error: System.err:
com.fusa.ssg.infra.remoting.common.RemoteServiceException: Error
executing Remote Method=[getCallSeqId] for Service
Url=[http://my-loadbalancer:9810/cms.rcts/2009.9.1.006/ccs/prf.lr/2008.8
.1/CDC] Exception=[java.net.SocketException: Connection reset
	at java.net.SocketInputStream.read(SocketInputStream.java:168)
	at
java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
	at
java.io.BufferedInputStream.read(BufferedInputStream.java:235)
	at
org.apache.commons.httpclient.ChunkedInputStream.getChunkSizeFromInputSt
ream(ChunkedInputStream.java:250)
	at
org.apache.commons.httpclient.ChunkedInputStream.nextChunk(ChunkedInputS
tream.java:221)
	at
org.apache.commons.httpclient.ChunkedInputStream.read(ChunkedInputStream
.java:176)
	at
org.apache.commons.httpclient.ChunkedInputStream.read(ChunkedInputStream
.java:196)
	at
org.apache.commons.httpclient.ChunkedInputStream.exhaustInputStream(Chun
kedInputStream.java:369)
	at
org.apache.commons.httpclient.ChunkedInputStream.close(ChunkedInputStrea
m.java:346)
	at java.io.FilterInputStream.close(FilterInputStream.java:159)
	at
org.apache.commons.httpclient.AutoCloseInputStream.notifyWatcher(AutoClo
seInputStream.java:194)
	at
org.apache.commons.httpclient.AutoCloseInputStream.close(AutoCloseInputS
tream.java:158)
	at
java.io.ObjectInputStream$PeekInputStream.close(ObjectInputStream.java:2
252)
	at
java.io.ObjectInputStream$BlockDataInputStream.close(ObjectInputStream.j
ava:2587)
	at java.io.ObjectInputStream.close(ObjectInputStream.java:853)
	at
com.fusa.ssg.infra.remoting.common.io.StandardJavaSerializer.readObject(
StandardJavaSerializer.java:41)
	at
com.fusa.ssg.infra.remoting.client.service.RemoteServiceExecutorImpl.des
erializeServiceResponse(RemoteServiceExecutorImpl.java:153)
	at
com.fusa.ssg.infra.remoting.client.service.RemoteServiceExecutorImpl.exe
cuteRequest(RemoteServiceExecutorImpl.java:111)
	at
com.fusa.ssg.infra.remoting.client.service.RemoteServiceProxy.invoke(Rem
oteServiceProxy.java:54)
	at $Proxy5.getCallSeqId(Unknown Source)
	at
com.ccs.cco.cms.rcts.client.calltracking.CallTrackingRemotingDelegate.ge
tCallSeqId(CallTrackingRemotingDelegate.java:66)
	at Actions.action(Actions.java:2327)
]
Error	[MsgId: MERR-17999]
System.err: 	at
com.fusa.ssg.infra.remoting.client.service.RemoteServiceProxy.invoke(Rem
oteServiceProxy.java:58)
Error	[MsgId: MMSG-17999]
System.err: 	at $Proxy5.getCallSeqId(Unknown Source)
Error	[MsgId: MMSG-17999]
System.err: 	at
com.ccs.cco.cms.rcts.client.calltracking.CallTrackingRemotingDelegate.ge
tCallSeqId(CallTrackingRemotingDelegate.java:66)
Error	[MsgId: MMSG-17999]
System.err: 	at Actions.action(Actions.java:2327)
Error	[MsgId: MMSG-17999]
Error: System.err: -----------Wrapped Exception-----------
Error	[MsgId: MERR-17999]
Error: System.err:
com.fusa.ssg.infra.remoting.common.RemoteServiceException: Error
executing Remote Method=[getCallSeqId] for Service
Url=[http://my-loadbalancer:9810/cms.rcts/2009.9.1.006/ccs/prf.lr/2008.8
.1/CDC] Exception=[java.net.SocketException: Connection reset
	at java.net.SocketInputStream.read(SocketInputStream.java:168)
	at
java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
	at
java.io.BufferedInputStream.read(BufferedInputStream.java:235)
	at
org.apache.commons.httpclient.ChunkedInputStream.getChunkSizeFromInputSt
ream(ChunkedInputStream.java:250)
	at
org.apache.commons.httpclient.ChunkedInputStream.nextChunk(ChunkedInputS
tream.java:221)
	at
org.apache.commons.httpclient.ChunkedInputStream.read(ChunkedInputStream
.java:176)
	at
org.apache.commons.httpclient.ChunkedInputStream.read(ChunkedInputStream
.java:196)
	at
org.apache.commons.httpclient.ChunkedInputStream.exhaustInputStream(Chun
kedInputStream.java:369)
	at
org.apache.commons.httpclient.ChunkedInputStream.close(ChunkedInputStrea
m.java:346)
	at java.io.FilterInputStream.close(FilterInputStream.java:159)
	at
org.apache.commons.httpclient.AutoCloseInputStream.notifyWatcher(AutoClo
seInputStream.java:194)
	at
org.apache.commons.httpclient.AutoCloseInputStream.close(AutoCloseInputS
tream.java:158)
	at
java.io.ObjectInputStream$PeekInputStream.close(ObjectInputStream.java:2
252)
	at
java.io.ObjectInputStream$BlockDataInputStream.close(ObjectInputStream.j
ava:2587)
	at java.io.ObjectInputStream.close(ObjectInputStream.java:853)
	at
com.fusa.ssg.infra.remoting.common.io.StandardJavaSerializer.readObject(
StandardJavaSerializer.java:41)
	at
com.fusa.ssg.infra.remoting.client.service.RemoteServiceExecutorImpl.des
erializeServiceResponse(RemoteServiceExecutorImpl.java:153)
	at
com.fusa.ssg.infra.remoting.client.service.RemoteServiceExecutorImpl.exe
cuteRequest(RemoteServiceExecutorImpl.java:111)
	at
com.fusa.ssg.infra.remoting.client.service.RemoteServiceProxy.invoke(Rem
oteServiceProxy.java:54)
	at $Proxy5.getCallSeqId(Unknown Source)
	at
com.ccs.cco.cms.rcts.client.calltracking.CallTrackingRemotingDelegate.ge
tCallSeqId(CallTrackingRemotingDelegate.java:66)
	at Actions.action(Actions.java:2327)
]
Error	[MsgId: MERR-17999]
System.err: 	at
com.fusa.ssg.infra.remoting.client.service.RemoteServiceProxy.invoke(Rem
oteServiceProxy.java:58)
Error	[MsgId: MMSG-17999]
System.err: 	at $Proxy5.getCallSeqId(Unknown Source)
Error	[MsgId: MMSG-17999]
System.err: 	at
com.ccs.cco.cms.rcts.client.calltracking.CallTrackingRemotingDelegate.ge
tCallSeqId(CallTrackingRemotingDelegate.java:66)
Error	[MsgId: MMSG-17999]
System.err: 	at Actions.action(Actions.java:2327)
Error	[MsgId: MMSG-17999]










This transmission may contain information that is privileged,
confidential, legally privileged, and/or exempt from disclosure
under applicable law.  If you are not the intended recipient, you
are hereby notified that any disclosure, copying, distribution, or
use of the information contained herein (including any reliance
thereon) is STRICTLY PROHIBITED.  Although this transmission and
any attachments are believed to be free of any virus or other
defect that might affect any computer system into which it is
received and opened, it is the responsibility of the recipient to
ensure that it is virus free and no responsibility is accepted by
JPMorgan Chase & Co., its subsidiaries and affiliates, as
applicable, for any loss or damage arising in any way from its use.
 If you received this transmission in error, please immediately
contact the sender and destroy the material in its entirety,
whether in electronic or hard copy format. Thank you.

---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
For additional commands, e-mail: httpclient-users-help@hc.apache.org