S3 Incomplete Read Warning Despite Aborting

[atorstling]

Hello!

I'm getting the warnings when reading an S3 getObject stream incompletely and aborting at the end:

try(S3Object object = s3.getObject(bucketName, objectKey)) {
   S3ObjectInputStream is = object.getObjectContent();
   try {
      readSomeFrom(is);
   } finally {
    is.abort();
  }
}

The log entry is:

WARN com.amazonaws.services.s3.internal.S3AbortableInputStream - Not all bytes were read from the S3ObjectInputStream, aborting HTTP connection. This is likely an error and may result in sub-optimal behavior. Request only the bytes you need via a ranged GET or drain the input stream after use.

I've debugged it and dug up the following stack:

close:178, S3AbortableInputStream (com.amazonaws.services.s3.internal)
close:99, SdkFilterInputStream (com.amazonaws.internal)
close:136, S3ObjectInputStream (com.amazonaws.services.s3.model)
close:99, SdkFilterInputStream (com.amazonaws.internal)
close:99, SdkFilterInputStream (com.amazonaws.internal)
close:211, ProgressInputStream (com.amazonaws.event)
close:181, FilterInputStream (java.io)
closeQuietly:70, IOUtils (com.amazonaws.util)
abort:98, S3ObjectInputStream (com.amazonaws.services.s3.model)

The lowest frame:

@Override
    public void abort() {
        super.abort();

        if (httpRequest != null) {
            httpRequest.abort();
        }

        // The default abort() implementation calls abort on the wrapped stream
        // if it's an SdkFilterInputStream; otherwise we'll need to close the
        // stream.
        if (!(in instanceof SdkFilterInputStream)) {
-->         IOUtils.closeQuietly(in, null);
        }
    }

The highest frame:

@Override
    public void close() throws IOException {
        if (readAllBytes() || isAborted()) {
            super.close();
        } else {
-->         LOG.warn(
                    "Not all bytes were read from the S3ObjectInputStream, aborting HTTP connection. This is likely an error and " +
                    "may result in sub-optimal behavior. Request only the bytes you need via a ranged GET or drain the input " +
                    "stream after use.");
            if (httpRequest != null) {
                httpRequest.abort();
            }
            IOUtils.closeQuietly(in, null);
        }
    }

I think that the problem is incomplete aborting since the delegate stream is of the S3ObjectInputStream is a DigestValidationInputStream and not a SdkFilterInputStream. That seems to happen due to etag validation. I'm on 1.11.355.

[steveloughran]

Looks like a regression; Hadoop is still only on 1.11.271, and not seeing this on its codepaths. If it has come back: Regression.

Or: it was always there but your choice in input validation has changed the input streams

When it is fixed, can the fix include a call of the abort & verification that the message didn't get logged? As clearly this is a fairly brittle fix and if it returns once, it's going to keep coming back. I am already thinking to declare part of the AWS SDK update for hadoop process one of "play with it on the CLI to see what new error messages appear", but at least this one could be automated out. thanks.

[shorea]

Was able to reproduce this, have a fix in mind.

[shorea]

I've pushed a fix for this, it will be available in the next release.

[steveloughran]

thanks.

do you have a regression test to verify that this message won't get logged in future?

this is one of those behaviours where a test run which doesn't look at the logs will see success in terms of semantics, but the logs will be full of noise. As this issue now seems to recur, I'd be happy if the patch includes not just a fix but a check of the output logs. I know its fiddly, but log4j is there to be captured if you try hard

[steveloughran]

FWIW, I'm doing an upgrade of hadoop trunk from v 1.11.271 of the SDK to 1.11.374 and I'm not seeing this error message in our logs. Either its been fixed or we our uses of abort() never managed to trigger it.