"IOException: Error writing request body to server" when uploading to S3

[Martin Grotzke]

Hi,

after our problems with jclouds/S3 with stuck connections to AWS
"Loading file from S3 stuck in SocketInputStream.socketRead0" we
upgraded to jclouds 1.0-beta-9b and followed the documentation at
http://code.google.com/p/jclouds/wiki/jcloudsAPI#Configuration_Modules

(with the same properties, just left out Log4jDriver).

Today we rolled out this change and see "IOException: Error writing
request body to server":

This is printed out 100 to 200 times:

java.io.IOException: Error writing request body to server
at
sun.net.www.protocol.http.HttpURLConnection$StreamingOutputStream.checkError(HttpURLConnection.java:2637)
at
sun.net.www.protocol.http.HttpURLConnection$StreamingOutputStream.write(HttpURLConnection.java:2620)
at com.google.common.io.ByteStreams.copy(ByteStreams.java:171)
at org.jclouds.io.payloads.BasePayload.writeTo(BasePayload.java:68)
at
org.jclouds.http.internal.JavaUrlHttpCommandExecutorService.convert(JavaUrlHttpCommandExecutorService.java:221)
at
org.jclouds.http.internal.JavaUrlHttpCommandExecutorService.convert(JavaUrlHttpCommandExecutorService.java:77)
at
org.jclouds.http.internal.BaseHttpCommandExecutorService$HttpResponseCallable.call(BaseHttpCommandExecutorService.java:156)
at
org.jclouds.http.internal.BaseHttpCommandExecutorService$HttpResponseCallable.call(BaseHttpCommandExecutorService.java:135)
at
java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
at java.util.concurrent.FutureTask.run(FutureTask.java:138)
at
java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
at java.lang.Thread.run(Thread.java:619)

This is printed out only ~20 times:

org.jclouds.http.HttpResponseException: Error writing request body to
server connecting to PUT
https://somebucket.s3.amazonaws.com/transparent/63572729.png HTTP/1.1
at
org.jclouds.http.internal.BaseHttpCommandExecutorService$HttpResponseCallable.call(BaseHttpCommandExecutorService.java:184)
at
org.jclouds.http.internal.BaseHttpCommandExecutorService$HttpResponseCallable.call(BaseHttpCommandExecutorService.java:135)
at
java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
at java.util.concurrent.FutureTask.run(FutureTask.java:138)
at
java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
at java.lang.Thread.run(Thread.java:619)
Caused by: java.io.IOException: Error writing request body to server
at
sun.net.www.protocol.http.HttpURLConnection$StreamingOutputStream.checkError(HttpURLConnection.java:2637)
at
sun.net.www.protocol.http.HttpURLConnection$StreamingOutputStream.write(HttpURLConnection.java:2620)
at com.google.common.io.ByteStreams.copy(ByteStreams.java:171)
at org.jclouds.io.payloads.BasePayload.writeTo(BasePayload.java:68)
at
org.jclouds.http.internal.JavaUrlHttpCommandExecutorService.convert(JavaUrlHttpCommandExecutorService.java:221)
at
org.jclouds.http.internal.JavaUrlHttpCommandExecutorService.convert(JavaUrlHttpCommandExecutorService.java:77)
at
org.jclouds.http.internal.BaseHttpCommandExecutorService$HttpResponseCallable.call(BaseHttpCommandExecutorService.java:156)

Is this perhaps known to anyone here? Should we use different
settings/properties?

Btw: it seems as if this would happen only for bigger images that we
upload, for other images we don't get this error.

Cheers,
Martin

--
Martin Grotzke
http://twitter.com/martin_grotzke

[Adrian Cole]

Hi, Martin.

Very interesting problem :)

It seems your images are of type byte[]?  Can you isolate this into code we can run/repeat in a new test in AWSS3BlobIntegrationLiveTest?    Also, you can try to include the maven artifact org.jclouds.driver/jclouds-apachehc and use new ApacheHCHttpCommandExecutorServiceModule() to see if this is limited to the java http impl.

Cheers,
-A

[Martin Grotzke]

Hi Adrian,

On 04/07/2011 01:39 AM, Adrian Cole wrote:
> Hi, Martin.
>
> Very interesting problem :)
>
> It seems your images are of type byte[]? Can you isolate this into code
> we can run/repeat in a new test in AWSS3BlobIntegrationLiveTest?

I just pushed a test to my jclouds clone:
https://github.com/magro/jclouds/commit/714da9f120db8dbcc4c409f0fb749dc6429c442a

In fact this test also shows the issue (ran 3 times, 3 failures):

FAILED: testPutImage
org.jclouds.http.HttpResponseException: error after writing
159744/1772194 bytes to PUT
https://jclouds-test.s3.amazonaws.com/main-testimg.png HTTP/1.1
connecting to PUT https://jclouds-test.s3.amazonaws.com/main-testimg.png
HTTP/1.1
at
org.jclouds.http.internal.BaseHttpCommandExecutorService$HttpResponseCallable.call(BaseHttpCommandExecutorService.java:185)
at
org.jclouds.http.internal.BaseHttpCommandExecutorService$HttpResponseCallable.call(BaseHttpCommandExecutorService.java:1)

at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
at java.util.concurrent.FutureTask.run(FutureTask.java:138)
at
java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)

at java.lang.Thread.run(Thread.java:662)
Caused by: java.lang.RuntimeException: error after writing
159744/1772194 bytes to PUT
https://jclouds-test.s3.amazonaws.com/main-testimg.png HTTP/1.1
at
org.jclouds.http.internal.JavaUrlHttpCommandExecutorService.convert(JavaUrlHttpCommandExecutorService.java:247)
at
org.jclouds.http.internal.JavaUrlHttpCommandExecutorService.convert(JavaUrlHttpCommandExecutorService.java:1)
at
org.jclouds.http.internal.BaseHttpCommandExecutorService$HttpResponseCallable.call(BaseHttpCommandExecutorService.java:157)
... 6 more

Caused by: java.io.IOException: Error writing request body to server
at

sun.net.www.protocol.http.HttpURLConnection$StreamingOutputStream.checkError(HttpURLConnection.java:2802)
at
sun.net.www.protocol.http.HttpURLConnection$StreamingOutputStream.write(HttpURLConnection.java:2785)
at
com.google.common.io.CountingOutputStream.write(CountingOutputStream.java:51)

at com.google.common.io.ByteStreams.copy(ByteStreams.java:171)
at org.jclouds.io.payloads.BasePayload.writeTo(BasePayload.java:68)
at

org.jclouds.http.internal.JavaUrlHttpCommandExecutorService.convert(JavaUrlHttpCommandExecutorService.java:245)
... 8 more

The whole test took (failed after) ~15 seconds.

> Also, you can try to include the maven artifact
> org.jclouds.driver/jclouds-apachehc and use new
> ApacheHCHttpCommandExecutorServiceModule() to see if this is limited to
> the java http impl.

Well, I added the ApacheHCHttpCommandExecutorServiceModule - and it
worked. Still it took ~20 seconds.

What's weird / bad: then I removed the HCModule again - and then the
test was also green - several times, I couldn't get it to fail.

One thing I'd like to understand is how jclouds works, regarding to the
"IOException: Error writing request body to server" and the

"HttpResponseException: Error writing request body to server connecting
to PUT https://somebucket.s3.amazonaws.com/transparent/63572729.png

HTTP/1.1": is jclouds using separate threads for IO, that are somehow
related to user/client threads, and the result from a requested,
asynchronous operation is then passed back to the user/client thread?
I'd assume that "IOException: Error writing request body to server" is
written by the async IO-thread, and that "HttpResponseException: ..." is
written when all retries are over and the operation finally failed - to
this problem is told the user/client.

We're asking ourselves, to which uploads/resources the "IOException:
Error writing request body to server" are related. We're seeing this
exception but don't know, which images might not have been uploaded.

Is it possible that jclouds does all work in the user/client thread? Our
application is already doing everything concurrently so that image
processing is done in a bunch of threads. If jclouds would be bound to
our threads it would be easier to debug these issues.

Another issue that we're seeing since our upgrade to 1.0-beta-9b is that
download/upload times (GET/PUT) raised by factor 10.

Before we had an average download time of ~190 millis (min=41,
max=22080) (measured over hours) and an avg upload time of ~125 millis
(min=51, max=153090).
The last night we had an avg download time of ~2950 millis (min=42,
max=60639) and an avg upload time of ~1700 millis (min=52, max=59881)

Is it possible that request/response times of AWS-S3 differ that much,
or is it possible that it's related to changes in jclouds?

Cheers,
Martin

>
> Cheers,
> -A
>
> On Wed, Apr 6, 2011 at 5:03 AM, Martin Grotzke

> <martin....@googlemail.com <mailto:martin....@googlemail.com>>

> --
> You received this message because you are subscribed to the Google
> Groups "jclouds" group.
> To post to this group, send email to jcl...@googlegroups.com.
> To unsubscribe from this group, send email to
> jclouds+u...@googlegroups.com.
> For more options, visit this group at
> http://groups.google.com/group/jclouds?hl=en.

[Adrian Cole]

Hi, Martin,

I'll have a look at the test.  Are all threads of yours using the same context?  I can run our test suite on beta-8 then beta-9.  It is a concurrent test suite, and it should show easily a performance difference if the magnitudes are like what you are saying.  Probably also reasonable to get info on your java version and runtime info.  Do you mind logging an issue on this, so that it is better searchable and loggable in case we have to make a change?  http://code.google.com/p/jclouds/issues

In the mean time, I think it is correct to assume there's a resource contention issue somewhere.  I'd suggest moving properties back to default and try managing your own threads in the mean time.  you can do this by adding this to your context: new ExecutorServiceModule(MoreExecutors.sameThreadExecutor(), MoreExecutors.sameThreadExecutor())

Let me know how this affects things.  In a new release, we should probably add a metrics system to determine what the maximum parallel operations taking place are, how often threadpools are saturated, ioexceptions, etc.
http://code.google.com/p/jclouds/issues/detail?id=43

Cheers,
-Adrian

[Adrian Cole]

As noted in the other thread, Martin. I verified I get this issue in beta-9, but not snapshot (when uploading 100 of your png files simultaneously).  Do you mind testing with snapshot?

Cheers,
-A