exponential backoff in HttpClient#executeMethod()

[riccardo]

Hi James,

since last Friday (09/19) we started getting an unusual large number
of socket exceptions when accessing our S3 buckets. The issue occurs
in pretty much all types of HTTP requests (GET, POST, or HEAD), and it
seems to always originate from HttpClient getting a "failed to
respond" exception from the S3 server. What is a little awkward is
that after the first failure, the retry mechanism in
HttpMethodDirector fails very quickly in all the successive attempts
(as often as 30 times/sec), thus causing RestS3Service to give up on
it. I was wondering whether an exponential backoff in HttpClient's
retry mechanism would help in this case. On the other hand, the fact
that the first "failed to respond" exception is followed so quickly by
a bunch of "connection reset" looks a little suspicious.
I would appreciate any feedback/suggestions. I am including the
detailed stack trace below (this is jets3t 0.6.1). Thanks a lot for
your help!

RB



08/09/22 20:58:55 DEBUG httpclient.RestS3Service: Retrieving Head
information for bucket netseer-*** and object
block_7978113837993767986
08/09/22 20:58:55 DEBUG httpclient.RestS3Service: S3 URL:
https://netseer-***.s3.amazonaws.com:443/block_7978113837993767986
08/09/22 20:58:55 DEBUG httpclient.RestS3Service: Performing HEAD
request for 'https://netseer-***.s3.amazonaws.com/
block_7978113837993767986', expecting response code 200
08/09/22 20:58:55 DEBUG httpclient.RestS3Service: Adding authorization
for AWS Access Key '***'.
08/09/22 20:58:55 DEBUG httpclient.RestS3Service: Canonical string
('|' is a newline): HEAD|||Tue, 23 Sep 2008 03:58:55 GMT|/netseer-***/
block_7978113837993767986
08/09/22 20:58:55 DEBUG httpclient.HttpClient: enter
HttpClient.executeMethod(HttpMethod)
08/09/22 20:58:55 DEBUG httpclient.HttpClient: enter
HttpClient.executeMethod(HostConfiguration,HttpMethod,HttpState)
08/09/22 20:58:55 DEBUG httpclient.HttpMethodDirector: Attempt number
1 to process request
08/09/22 20:59:00 DEBUG httpclient.HttpMethodDirector: Closing the
connection.
08/09/22 20:59:00 WARN httpclient.RestS3Service: Retrying HEAD request
with path '/block_7978113837993767986' - attempt 1 of 10
08/09/22 20:59:00 DEBUG httpclient.RestS3Service: Adding authorization
for AWS Access Key '***'.
08/09/22 20:59:00 DEBUG httpclient.RestS3Service: Canonical string
('|' is a newline): HEAD|||Tue, 23 Sep 2008 03:59:00 GMT|/netseer-***/
block_7978113837993767986
08/09/22 20:59:00 INFO httpclient.HttpMethodDirector: I/O exception
(org.apache.commons.httpclient.NoHttpResponseException) caught when
processing request: The server netseer-***.s3.amazonaws.com failed to
respond
08/09/22 20:59:00 DEBUG httpclient.HttpMethodDirector: The server
netseer-***.s3.amazonaws.com failed to respond
org.apache.commons.httpclient.NoHttpResponseException: The server
netseer-***.s3.amazonaws.com failed to respond
at
org.apache.commons.httpclient.HttpMethodBase.readStatusLine(HttpMethodBase.java:
1835)
at
org.apache.commons.httpclient.HttpMethodBase.readResponse(HttpMethodBase.java:
1590)
at
org.apache.commons.httpclient.HttpMethodBase.execute(HttpMethodBase.java:
995)
at
org.apache.commons.httpclient.HttpMethodDirector.executeWithRetry(HttpMethodDirector.java:
397)
at
org.apache.commons.httpclient.HttpMethodDirector.executeMethod(HttpMethodDirector.java:
170)
at
org.apache.commons.httpclient.HttpClient.executeMethod(HttpClient.java:
396)
at
org.apache.commons.httpclient.HttpClient.executeMethod(HttpClient.java:
324)
at
org.jets3t.service.impl.rest.httpclient.RestS3Service.performRequest(RestS3Service.java:
357)
at
org.jets3t.service.impl.rest.httpclient.RestS3Service.performRestHead(RestS3Service.java:
652)
at
org.jets3t.service.impl.rest.httpclient.RestS3Service.getObjectImpl(RestS3Service.java:
1556)
at
org.jets3t.service.impl.rest.httpclient.RestS3Service.getObjectDetailsImpl(RestS3Service.java:
1492)
at
org.jets3t.service.S3Service.getObjectDetails(S3Service.java:1799)
at
org.jets3t.service.S3Service.getObjectDetails(S3Service.java:1231)
(...)

08/09/22 20:59:00 INFO httpclient.HttpMethodDirector: Retrying request
08/09/22 20:59:00 DEBUG httpclient.HttpMethodDirector: Attempt number
2 to process request
08/09/22 20:59:00 DEBUG httpclient.HttpMethodDirector: Closing the
connection.
08/09/22 20:59:00 WARN httpclient.RestS3Service: Retrying HEAD request
with path '/block_7978113837993767986' - attempt 2 of 10
08/09/22 20:59:00 DEBUG httpclient.RestS3Service: Adding authorization
for AWS Access Key '***'.
08/09/22 20:59:00 DEBUG httpclient.RestS3Service: Canonical string
('|' is a newline): HEAD|||Tue, 23 Sep 2008 03:59:00 GMT|/netseer-***/
block_7978113837993767986
08/09/22 20:59:00 INFO httpclient.HttpMethodDirector: I/O exception
(java.net.SocketException) caught when processing request: Connection
reset
08/09/22 20:59:00 DEBUG httpclient.HttpMethodDirector: Connection
reset
java.net.SocketException: Connection reset
at java.net.SocketInputStream.read(SocketInputStream.java:168)
at
com.sun.net.ssl.internal.ssl.InputRecord.readFully(InputRecord.java:
293)
at
com.sun.net.ssl.internal.ssl.InputRecord.read(InputRecord.java:331)
at
com.sun.net.ssl.internal.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:
789)
at
com.sun.net.ssl.internal.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:
746)
at
com.sun.net.ssl.internal.ssl.AppInputStream.read(AppInputStream.java:
75)
at java.io.BufferedInputStream.fill(BufferedInputStream.java:
218)
at java.io.BufferedInputStream.read(BufferedInputStream.java:
237)
at
org.apache.commons.httpclient.HttpParser.readRawLine(HttpParser.java:
77)
at
org.apache.commons.httpclient.HttpParser.readLine(HttpParser.java:105)
at
org.apache.commons.httpclient.HttpConnection.readLine(HttpConnection.java:
1115)
at
org.apache.commons.httpclient.MultiThreadedHttpConnectionManager
$HttpConnectionAdapter.readLine

(MultiThreadedHttpConnectionManager.java:1373)
at
org.apache.commons.httpclient.HttpMethodBase.readStatusLine(HttpMethodBase.java:
1832)
at
org.apache.commons.httpclient.HttpMethodBase.readResponse(HttpMethodBase.java:
1590)
at
org.apache.commons.httpclient.HttpMethodBase.execute(HttpMethodBase.java:
995)
at
org.apache.commons.httpclient.HttpMethodDirector.executeWithRetry(HttpMethodDirector.java:
397)
at
org.apache.commons.httpclient.HttpMethodDirector.executeMethod(HttpMethodDirector.java:
170)
at
org.apache.commons.httpclient.HttpClient.executeMethod(HttpClient.java:
396)
at
org.apache.commons.httpclient.HttpClient.executeMethod(HttpClient.java:
324)
at
org.jets3t.service.impl.rest.httpclient.RestS3Service.performRequest(RestS3Service.java:
357)
at
org.jets3t.service.impl.rest.httpclient.RestS3Service.performRestHead(RestS3Service.java:
652)
at
org.jets3t.service.impl.rest.httpclient.RestS3Service.getObjectImpl(RestS3Service.java:
1556)
at
org.jets3t.service.impl.rest.httpclient.RestS3Service.getObjectDetailsImpl(RestS3Service.java:
1492)
at
org.jets3t.service.S3Service.getObjectDetails(S3Service.java:1799)
at
org.jets3t.service.S3Service.getObjectDetails(S3Service.java:1231)
(...)

08/09/22 20:59:00 DEBUG httpclient.HttpMethodDirector: Attempt number
11 to process request
08/09/22 20:59:00 DEBUG httpclient.HttpMethodDirector: Closing the
connection.
08/09/22 20:59:00 WARN httpclient.RestS3Service: Retried connection 11
times, which exceeds the maximum retry count of 10
08/09/22 20:59:00 DEBUG httpclient.HttpMethodDirector: Method retry
handler returned false. Automatic recovery will not be attempted
08/09/22 20:59:00 DEBUG httpclient.RestS3Service: Releasing HttpClient
connection after error: Connection reset
Exception in thread "main" java.net.SocketException: Connection reset
at java.net.SocketInputStream.read(SocketInputStream.java:168)
at
com.sun.net.ssl.internal.ssl.InputRecord.readFully(InputRecord.java:
293)
at
com.sun.net.ssl.internal.ssl.InputRecord.read(InputRecord.java:331)
at
com.sun.net.ssl.internal.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:
789)
at
com.sun.net.ssl.internal.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:
746)
at
com.sun.net.ssl.internal.ssl.AppInputStream.read(AppInputStream.java:
75)
at java.io.BufferedInputStream.fill(BufferedInputStream.java:
218)
at java.io.BufferedInputStream.read(BufferedInputStream.java:
237)
at
org.apache.commons.httpclient.HttpParser.readRawLine(HttpParser.java:
77)
at
org.apache.commons.httpclient.HttpParser.readLine(HttpParser.java:105)
at
org.apache.commons.httpclient.HttpConnection.readLine(HttpConnection.java:
1115)
at
org.apache.commons.httpclient.MultiThreadedHttpConnectionManager
$HttpConnectionAdapter.readLine

(MultiThreadedHttpConnectionManager.java:1373)
at
org.apache.commons.httpclient.HttpMethodBase.readStatusLine(HttpMethodBase.java:
1832)
at
org.apache.commons.httpclient.HttpMethodBase.readResponse(HttpMethodBase.java:
1590)
at
org.apache.commons.httpclient.HttpMethodBase.execute(HttpMethodBase.java:
995)
at
org.apache.commons.httpclient.HttpMethodDirector.executeWithRetry(HttpMethodDirector.java:
397)
at
org.apache.commons.httpclient.HttpMethodDirector.executeMethod(HttpMethodDirector.java:
170)
at
org.apache.commons.httpclient.HttpClient.executeMethod(HttpClient.java:
396)
at
org.apache.commons.httpclient.HttpClient.executeMethod(HttpClient.java:
324)
at
org.jets3t.service.impl.rest.httpclient.RestS3Service.performRequest(RestS3Service.java:
357)
at
org.jets3t.service.impl.rest.httpclient.RestS3Service.performRestHead(RestS3Service.java:
652)
at
org.jets3t.service.impl.rest.httpclient.RestS3Service.getObjectImpl(RestS3Service.java:
1556)
at
org.jets3t.service.impl.rest.httpclient.RestS3Service.getObjectDetailsImpl(RestS3Service.java:
1492)
at
org.jets3t.service.S3Service.getObjectDetails(S3Service.java:1799)
at
org.jets3t.service.S3Service.getObjectDetails(S3Service.java:1231)
(...)

[James Murty]

Hi,

From the logs you included, it looks like there may be a problem connecting to S3 through the bucket CNAME hostname. If you continue to experience the high error rates, it may be worth turning off the DNS naming option to force JetS3t to connect directly to main S3 hostname, eg. s3.amazonaws.com/your-bucket-name (set s3service.disable-dns-buckets to true).

In terms of retries and exponential backoffs, at present JetS3t does perform an exponential backoff but only when it receives a 500 or 503 HTTP error response. Of course, this won't do much good if you cannot get any HTTP connection at all... To ensure that all failures pause before retrying, you could try the brute-force approach of copying code from the utility method S3Service#sleepOnInternalError into the HttpClientRetryHandler anonymous class created in RestS3Service. This would at least cause a delay after every HTTP error no matter what kind, whether it is at the application or network level.

Ultimately though, you will need to find out why the connections are failing in the first place, as an improved retry mechanism can only mask the problem at best. I would recommend asking about the issue in the AWS S3 forum, to see if someone in Amazon can help diagnose the issue.

Hope this helps a little,
James

---
http://www.jamesmurty.com

[riccardo]

Thanks for the quick reply James. I agree with you that a fancier
retry mechanism for
plain HTTP calls will ultimately just mask the underlying problems. I
actually spoke to the
AWS folks that indeed confirmed that this kind of issue has been
reported lately. I have to
clarify that the rate of occurrence of these "connection refused"
exceptions is still very low
(around 1 every 1,000 requests or less), but they occasionally crashed
our S3 clients because we were
not prepared to handle them (as a matter of fact I have never
experienced this issue before last week).
Our current workaround is to deal with the exceptions at a higher
level, a solution that allows us to better
monitor their frequency and act accordingly.

I haven't tested the DNS naming option solution you suggested, I will
send you my feedback once I
try it out. Btw, thanks for putting together and maintaining jets3t,
it's really a great library.

Best,

RB

On Sep 24, 5:41 am, "James Murty" <ja...@misterm.org> wrote:
> Hi,
>
> From the logs you included, it looks like there may be a problem connecting
> to S3 through the bucket CNAME hostname. If you continue to experience the
> high error rates, it may be worth turning off the DNS naming option to force
> JetS3t to connect directly to main S3 hostname, eg.
> s3.amazonaws.com/your-bucket-name (set s3service.disable-dns-buckets to
> true).
>
> In terms of retries and exponential backoffs, at present JetS3t does perform
> an exponential backoff but only when it receives a 500 or 503 HTTP error
> response. Of course, this won't do much good if you cannot get any HTTP
> connection at all... To ensure that all failures pause before retrying, you
> could try the brute-force approach of copying code from the utility method
> S3Service#sleepOnInternalError into the HttpClientRetryHandler anonymous
> class created in RestS3Service. This would at least cause a delay after
> every HTTP error no matter what kind, whether it is at the application or
> network level.
>
> Ultimately though, you will need to find out why the connections are failing
> in the first place, as an improved retry mechanism can only mask the problem
> at best. I would recommend asking about the issue in the AWS S3 forum, to
> see if someone in Amazon can help diagnose the issue.
>
> Hope this helps a little,
> James
>

> ---http://www.jamesmurty.com

>
> On Wed, Sep 24, 2008 at 4:38 AM, riccardo <drbosc...@netseer.com> wrote:
>
> > Hi James,
>
> > since last Friday (09/19) we started getting an unusual large number
> > of socket exceptions when accessing our S3 buckets. The issue occurs
> > in pretty much all types of HTTP requests (GET, POST, or HEAD), and it
> > seems to always originate from HttpClient getting a "failed to
> > respond" exception from the S3 server. What is a little awkward is
> > that after the first failure, the retry mechanism in
> > HttpMethodDirector fails very quickly in all the successive attempts
> > (as often as 30 times/sec), thus causing RestS3Service to give up on
> > it. I was wondering whether an exponential backoff in HttpClient's
> > retry mechanism would help in this case. On the other hand, the fact
> > that the first "failed to respond" exception is followed so quickly by
> > a bunch of "connection reset" looks a little suspicious.
> > I would appreciate any feedback/suggestions. I am including the
> > detailed stack trace below (this is jets3t 0.6.1). Thanks a lot for
> > your help!
>
> > RB
>
> > 08/09/22 20:58:55 DEBUG httpclient.RestS3Service: Retrieving Head
> > information for bucket netseer-*** and object
> > block_7978113837993767986
> > 08/09/22 20:58:55 DEBUG httpclient.RestS3Service: S3 URL:
> >https://netseer-***.s3.amazonaws.com:443/block_7978113837993767986

> > 08/09/22 <http://s3.amazonaws.com:443/block_797811383799376798608/09/22>20:58:55 DEBUG httpclient.RestS3Service: Performing HEAD
> > request for 'https://netseer-***.s3.amazonaws.com/
> > block_7978113837993767986<http://s3.amazonaws.com/block_7978113837993767986>',

> ...
>
> read more »

[James Murty]

You're welcome RB.

Please follow up in this thread if/when you get a resolution for the underlying problem, because this may well be affecting other S3 users as well.

Cheers,
James