Timeout problem

[HasanB]

Hi,

Could there have been a change in Rexster that affects client side
timeouts?

Until recently my client software (based on
org.apache.http.client.HttpClient) would happily wait while my Rexster
extension uploaded a large file. Now it times out after about 3
seconds.

Strangely :
- my extension processes all the files correctly, carrying on even
after the client throws the read timeout IOException.
- the client uploads small files without problem, beyond 3 seconds it
gives up
- curl uploads all the files without complaint.

The fingers all point to the client, but it has NOT changed at all.

I've tried altering timeouts but, not surprisingly, this has no
effect.

Regards,
Hasan

[stephen mallette]

It's interesting that curl is working. It does seem to indicate
something with the client, but if you haven't changed any code, it
does seem odd that there would be problems. I can't think of anything
that has changed in Rexster that would cause it to behave that way,
but if you are using the latest from github and building your rexster
from source, there have been some dependency version changes with
grizzly/jersey. What version of Rexster are you using?

I could try to recreate the problem on my end...can you provide a test
case for the failure (maybe with the working curl script)?

[HasanB]

Ouch.

Providing a test case would be a real time sink for both of us.

My problem is that I have never had a reason to look at the nuts'n
bolts of HTTP, so I do not know where to begin to look for the root
cause.

The exception looks like this:

Http call failed for IO failure :: Read timed out
java.net.SocketInputStream.socketRead0(Native Method)
java.net.SocketInputStream.read(Unknown Source)
java.io.BufferedInputStream.fill(Unknown Source)
java.io.BufferedInputStream.read(Unknown Source)
org.apache.commons.httpclient.HttpParser.readRawLine(HttpParser.java:
78)
:
:
:

> What version of Rexster are you using?

Fresh pull this morning, but I've been trying to solve this since
Friday (on & off).

How would I learn what it is that HttpClient doesn't like about the
server side's behaviour?

Thanks,
Hasan

Btw, this is all localhost stuff. No intervening firewall or
anything.

[stephen mallette]

Yeah...I just realized that any test case you wrote is wrapped around
your extension...that would take a bit of work to develop.

I guess I was interested in how you were making the call via
HttpClient. Are you making multiple successive calls from your client-
side?

[James Thornton]

"Apache's HttpClient has two separate timeouts: a timeout for how long to wait to establish a TCP connection, and a separate timeout for how long to wait for a subsequent byte of data. HttpConnectionParams.setConnectionTimeout() is the former, HttpConnectionParams.setSoTimeout() is the latter " (http://stackoverflow.com/questions/3000214/java-http-client-request-with-defined-timeout).

http://hc.apache.org/httpclient-3.x/apidocs/org/apache/commons/httpclient/params/HttpConnectionParams.html#setSoTimeout(int)

[HasanB]

Hi Stephen

To answer my own question, I've been looking into how to get logging
going on the Jakarta HttpClient :

08:19:17,187 DEBUG [DefaultHttpParams] - Set parameter http.useragent
= Jakarta Commons-HttpClient/3.1
08:19:17,187 DEBUG [DefaultHttpParams] - Set parameter
http.protocol.version = HTTP/1.1
08:19:17,187 DEBUG [DefaultHttpParams] - Set parameter http.connection-
manager.class = class
org.apache.commons.httpclient.SimpleHttpConnectionManager
08:19:17,187 DEBUG [DefaultHttpParams] - Set parameter
http.protocol.cookie-policy = default
08:19:17,187 DEBUG [DefaultHttpParams] - Set parameter
http.protocol.element-charset = US-ASCII
08:19:17,187 DEBUG [DefaultHttpParams] - Set parameter
http.protocol.content-charset = ISO-8859-1
08:19:17,203 DEBUG [DefaultHttpParams] - Set parameter
http.method.retry-handler =
org.apache.commons.httpclient.DefaultHttpMethodRetryHandler@7546c1d4
08:19:17,203 DEBUG [DefaultHttpParams] - Set parameter
http.dateparser.patterns = [EEE, dd MMM yyyy HH:mm:ss zzz, EEEE, dd-
MMM-yy HH:mm:ss zzz, EEE MMM d HH:mm:ss yyyy, EEE, dd-MMM-yyyy
HH:mm:ss z, EEE, dd-MMM-yyyy HH-mm-ss z, EEE, dd MMM yy HH:mm:ss z,
EEE dd-MMM-yyyy HH:mm:ss z, EEE dd MMM yyyy HH:mm:ss z, EEE dd-MMM-
yyyy HH-mm-ss z, EEE dd-MMM-yy HH:mm:ss z, EEE dd MMM yy HH:mm:ss z,
EEE,dd-MMM-yy HH:mm:ss z, EEE,dd-MMM-yyyy HH:mm:ss z, EEE, dd-MM-yyyy
HH:mm:ss z]
08:19:17,203 DEBUG [DefaultHttpParams] - Set parameter
http.socket.timeout = 3000
08:19:17,203 DEBUG [DefaultHttpParams] - Set parameter
http.socket.timeout = 3000
08:19:17,203 DEBUG [HttpClient] - Java version: 1.6.0_18
08:19:17,203 DEBUG [HttpClient] - Java vendor: Sun Microsystems Inc.
08:19:17,203 DEBUG [HttpClient] - Java class path: fitnesse.jar;E:/
programs/org/smartrics/RestFixture/dist/artifacts/
RestFixture_fitnesse.jar;E:/programs/org/smartrics/RestFixture/dist/
artifacts/RestFixture.jar;E:/programs/org/smartrics/RestFixture/dist/
artifacts/lib/commons-beanutils.jar;E:/programs/org/smartrics/
RestFixture/dist/artifacts/lib/commons-codec-1.3.jar;E:/programs/org/
smartrics/RestFixture/dist/artifacts/lib/commons-
collections-3.2.jar;E:/programs/org/smartrics/RestFixture/dist/
artifacts/lib/commons-httpclient-3.1.jar;E:/programs/org/smartrics/
RestFixture/dist/artifacts/lib/commons-lang-2.3.jar;E:/programs/org/
smartrics/RestFixture/dist/artifacts/lib/commons-logging-1.1.jar;E:/
programs/org/smartrics/RestFixture/dist/artifacts/lib/cos.jar;E:/
programs/org/smartrics/RestFixture/dist/artifacts/lib/
ezmorph-1.0.4.jar;E:/programs/org/smartrics/RestFixture/dist/artifacts/
lib/jettison-1.0.1.jar;E:/programs/org/smartrics/RestFixture/dist/
artifacts/lib/js.jar;E:/programs/org/smartrics/RestFixture/dist/
artifacts/lib/json-lib-2.2.2-jdk15.jar;E:/programs/org/smartrics/
RestFixture/dist/artifacts/lib/jsr173_1.0_api.jar;E:/programs/org/
smartrics/RestFixture/dist/artifacts/lib/PicBuilder.jar;E:/programs/
org/smartrics/RestFixture/dist/artifacts/lib/RestClient.jar;E:/
programs/org/smartrics/RestFixture/dist/artifacts/lib/xbean.jar;E:/
programs/org/smartrics/RestFixture/dist/artifacts/lib/
xstream-1.3.1.jar;E:/programs/org/smartrics/RestFixture/dist/artifacts/
lib/log4j-1.2.14.jar;E:/programs/org/smartrics/RestFixture/dist/
artifacts/lib
08:19:17,203 DEBUG [HttpClient] - Operating system name: Windows XP
08:19:17,203 DEBUG [HttpClient] - Operating system architecture: amd64
08:19:17,203 DEBUG [HttpClient] - Operating system version: 5.2
08:19:17,265 DEBUG [HttpClient] - SUN 1.6: SUN (DSA key/parameter
generation; DSA signing; SHA-1, MD5 digests; SecureRandom; X.509
certificates; JKS keystore; PKIX CertPathValidator; PKIX
CertPathBuilder; LDAP, Collection CertStores, JavaPolicy Policy;
JavaLoginConfig Configuration)
08:19:17,265 DEBUG [HttpClient] - SunRsaSign 1.5: Sun RSA signature
provider
08:19:17,265 DEBUG [HttpClient] - SunJSSE 1.6: Sun JSSE
provider(PKCS12, SunX509 key/trust factories, SSLv3, TLSv1)
08:19:17,265 DEBUG [HttpClient] - SunJCE 1.6: SunJCE Provider
(implements RSA, DES, Triple DES, AES, Blowfish, ARCFOUR, RC2, PBE,
Diffie-Hellman, HMAC)
08:19:17,265 DEBUG [HttpClient] - SunJGSS 1.0: Sun (Kerberos v5,
SPNEGO)
08:19:17,265 DEBUG [HttpClient] - SunSASL 1.5: Sun SASL
provider(implements client mechanisms for: DIGEST-MD5, GSSAPI,
EXTERNAL, PLAIN, CRAM-MD5; server mechanisms for: DIGEST-MD5, GSSAPI,
CRAM-MD5)
08:19:17,265 DEBUG [HttpClient] - XMLDSig 1.0: XMLDSig (DOM
XMLSignatureFactory; DOM KeyInfoFactory)
08:19:17,265 DEBUG [HttpClient] - SunPCSC 1.6: Sun PC/SC provider
08:19:17,265 DEBUG [DefaultHttpParams] - Set parameter
http.socket.timeout = 3000
08:19:17,265 DEBUG [DefaultHttpParams] - Set parameter
http.socket.timeout = 3000
08:19:17,281 DEBUG [RestClientImpl] - * * * * * Method request * * * *
*
08:19:17,281 DEBUG [RestClientImpl] - http://localhost:8182 : Put /
neo4jsample/mowa/stevens/


08:19:17,296 WARN [RestClientImpl] - * * * * * Timeout : 60000 * * *
* *
08:19:17,296 DEBUG [DefaultHttpParams] - Set parameter
http.connection.timeout = 60000
08:19:17,296 DEBUG [DefaultHttpParams] - Set parameter http.connection-
manager.timeout = 60000
08:19:17,296 DEBUG [DefaultHttpParams] - Set parameter
http.socket.timeout = 60000
08:19:17,296 WARN [RestClientImpl] - * * * * * Start : 1310995157296
* * * * *
08:19:17,312 DEBUG [HttpConnection] - Open connection to localhost:
8182
08:19:17,312 DEBUG [header] - >> "PUT /neo4jsample/mowa/stevens/ HTTP/
1.1[\r][\n]"
08:19:17,312 DEBUG [HttpMethodBase] - Adding Host request header
08:19:17,312 DEBUG [header] - >> "User-Agent: Jakarta Commons-
HttpClient/3.1[\r][\n]"
08:19:17,312 DEBUG [header] - >> "Host: localhost:8182[\r][\n]"
08:19:17,312 DEBUG [header] - >> "Content-Length: 1578[\r][\n]"
08:19:17,312 DEBUG [header] - >> "Content-Type: application/octet-
stream[\r][\n]"
08:19:17,312 DEBUG [header] - >> "[\r][\n]"
08:19:17,312 DEBUG [EntityEnclosingMethod] - Request body sent
08:19:20,312 DEBUG [HttpMethodDirector] - Closing the connection.
08:19:20,312 DEBUG [HttpMethodDirector] - Method retry handler
returned false. Automatic recovery will not be attempted
08:19:20,312 DEBUG [HttpConnection] - Releasing connection back to
connection manager.
08:19:20,312 WARN [RestClientImpl] - * * * * * End : 1310995160312 *
* * * *
08:19:20,312 WARN [RestClientImpl] - Http call failed for IO
failure :: Read timed out
08:19:20,312 WARN [RestClientImpl] -
08:19:20,328 WARN [RestClientImpl] -

java.net.SocketInputStream.socketRead0(Native Method)
java.net.SocketInputStream.read(Unknown Source)
java.io.BufferedInputStream.fill(Unknown Source)
java.io.BufferedInputStream.read(Unknown Source)
org.apache.commons.httpclient.HttpParser.readRawLine(HttpParser.java:
78)

org.apache.commons.httpclient.HttpParser.readLine(HttpParser.java:106)
org.apache.commons.httpclient.HttpConnection.readLine(HttpConnection.java:
1116)
org.apache.commons.httpclient.HttpMethodBase.readStatusLine(HttpMethodBase.java:
1973)
org.apache.commons.httpclient.HttpMethodBase.readResponse(HttpMethodBase.java:
1735)
org.apache.commons.httpclient.HttpMethodBase.execute(HttpMethodBase.java:
1098)
org.apache.commons.httpclient.HttpMethodDirector.executeWithRetry(HttpMethodDirector.java:
398)
org.apache.commons.httpclient.HttpMethodDirector.executeMethod(HttpMethodDirector.java:
171)
org.apache.commons.httpclient.HttpClient.executeMethod(HttpClient.java:
397)
org.apache.commons.httpclient.HttpClient.executeMethod(HttpClient.java:
323)
smartrics.rest.client.RestClientImpl.execute(RestClientImpl.java:135)


Something notable is that socket timeouts are indeed set to 3
seconds. Is that normal? Is the client too fast or my extension too
slow?

It occurs to me that my attempt to alter the socket time out comes to
late. I'll see if there is some sort of environment variable.

I wonder, could Rexster be failing to send some sort of handshake
within those 3 seconds? At the current logging resolution it appears
the client really doesn't hear anything back for three seconds :

08:19:17,312 DEBUG [EntityEnclosingMethod] - Request body sent
08:19:20,312 DEBUG [HttpMethodDirector] - Closing the connection.

Is there a way for my extension to say, "Please hold while I take note
of your request."?

Thanks,
Hasan

[James Thornton]

Hasan,  I think you've found the issue -- it's closing the connection exactly 3 seconds after the request body is sent...

08:19:17,312 DEBUG [EntityEnclosingMethod] - Request body sent 08:19:20,312 DEBUG [HttpMethodDirector] - Closing the connection. 
08:19:20,312 DEBUG [HttpMethodDirector] - Method retry handler 

And as you've noted, http.socket.timeout = 3000 is set just before the request is sent:

8:19:17,265 DEBUG [DefaultHttpParams] - Set parameter 
http.socket.timeout = 3000 
08:19:17,281 DEBUG [RestClientImpl] - * * * * * Method request * * * * 
* 
08:19:17,281 DEBUG [RestClientImpl] - http://localhost:8182 : Put / 
neo4jsample/mowa/stevens/ 

And the change to http.connection.timeout = 60000 comes after the request.