Don't log full stack traces for operations that will be retried

[bloudermilk]

I'm seeing this error when attempting to copy between two buckets. I see the exception happen a bunch of times consecutively, then it'll stop and everything continues normally. It appears the copy finishes without any issues, as the final stats output reports no errors.

The exception:

pool-1-thread-5 INFO : com.amazonaws.http.AmazonHttpClient - Unable to execute HTTP request: Connection to http://<BUCKET>.s3.amazonaws.com refused
org.apache.http.conn.HttpHostConnectException: Connection to http://<BUCKET>.s3.amazonaws.com refused
        at org.apache.http.impl.conn.DefaultClientConnectionOperator.openConnection(DefaultClientConnectionOperator.java:190)
        at org.apache.http.impl.conn.ManagedClientConnectionImpl.open(ManagedClientConnectionImpl.java:294)
        at org.apache.http.impl.client.DefaultRequestDirector.tryConnect(DefaultRequestDirector.java:641)
        at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:480)
        at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:906)
        at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:805)
        at com.amazonaws.http.AmazonHttpClient.executeOneRequest(AmazonHttpClient.java:635)
        at com.amazonaws.http.AmazonHttpClient.executeHelper(AmazonHttpClient.java:429)
        at com.amazonaws.http.AmazonHttpClient.execute(AmazonHttpClient.java:291)
        at com.amazonaws.services.s3.AmazonS3Client.invoke(AmazonS3Client.java:3655)
        at com.amazonaws.services.s3.AmazonS3Client.getObjectMetadata(AmazonS3Client.java:996)
        at com.amazonaws.services.s3.AmazonS3Client.getObjectMetadata(AmazonS3Client.java:974)
        at org.cobbzilla.s3s3mirror.KeyJob.getObjectMetadata(KeyJob.java:33)
        at org.cobbzilla.s3s3mirror.KeyCopyJob.run(KeyCopyJob.java:37)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
        at java.util.concurrent.FutureTask.run(FutureTask.java:262)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at java.lang.Thread.run(Thread.java:745)
Caused by: java.net.ConnectException: Cannot assign requested address
        at java.net.PlainSocketImpl.socketConnect(Native Method)
        at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:339)
        at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:200)
        at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:182)
        at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
        at java.net.Socket.connect(Socket.java:579)
        at org.apache.http.conn.scheme.PlainSocketFactory.connectSocket(PlainSocketFactory.java:127)
        at org.apache.http.impl.conn.DefaultClientConnectionOperator.openConnection(DefaultClientConnectionOperator.java:180)
        ... 18 more

The final stats:

--------------------------------------------------------------------
STATS BEGIN
read: 309101
copied: 309101
copy errors: 0
deleted: 0
delete errors: 0
duration: 0:11:23
read rate: 27141.661276207145/minute
copy rate: 27141.661276207145/minute
delete rate: 0.0/minute
bytes copied: 10.982177948579192 GB (11792023782 bytes)
GET operations: 931170
COPY operations: 309102
DELETE operations: 0
STATS END
--------------------------------------------------------------------

Running on a fresh m3.xlarge instance in the same region as both of the buckets.

[cobbzilla]

This is normal -- sometimes S3 simply refuses to honor a request, or returns an error for a request that should definitely succeed.

In these cases, s3s3mirror will retry the request, up to a maximum number of retries. The default number of retries is 5, this can be adjusted with the -r / --max-retries option.

No request failed five times consecutively, or you would have seen "copy errors" > 0

[cobbzilla]

Just thought of this: looking at your exception (Cannot assign requested address), it may not have been an S3 error but rather port exhaustion. Either your local system or the particular S3 endpoint system may have run out of temporary ports.

s3s3mirror will retry on any failure though, so apparently subsequent requests went through OK.

[bloudermilk]

@cobbzilla okay great, I figured as much. I wonder if, when not in -v mode, errors like that should be suppressed unless they surpass the retry limit? Thanks for the prompt response!

[cobbzilla]

That's a good idea. But I think people would want to know why a retry is occurring, so I'll log the retry reason, but not the full stack trace. I will re-open this issue as "Don't log full stack traces for operations that will be retried"