[
https://issues.apache.org/jira/browse/HADOOP-14596?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16066660#comment-16066660
]
Steve Loughran commented on HADOOP-14596:
-----------------------------------------
Patch 002
* add explict logger to S3AInputStream + debug-level logging messages during
close/abort operations.
* improve draining/stats collection on a normal close()
We still get told off on every abort(), this is due to code in the current AWS
SDK which is printing the warning. That's something which can only be addressed
in the SDK.
We haven't (AFAIK) cut a hadoop release with an SDK that prints the messages.
If we plan to, we should update the index.md doc to say "don't worry about
these"
{code}
testRandomIONormalPolicy: Random IO with policy "normal"
2017-06-28 15:24:21,013 [JUnit-testRandomIONormalPolicy] DEBUG
s3a.S3AInputStream (S3AInputStream.java:reopen(148)) -
reopen(s3a://landsat-pds/scene_list.gz) for read from new offset
range[2097152-45603307], length=131072, streamPosition=0,
nextReadPosition=2097152
2017-06-28 15:24:21,895 [JUnit-testRandomIONormalPolicy] DEBUG
s3a.S3AInputStream (S3AInputStream.java:closeStream(456)) - Closing stream
seekInStream(): soft
2017-06-28 15:24:21,896 [JUnit-testRandomIONormalPolicy] DEBUG
s3a.S3AInputStream (S3AInputStream.java:closeStream(486)) - Aborting stream
2017-06-28 15:24:21,896 [JUnit-testRandomIONormalPolicy] WARN
internal.S3AbortableInputStream (S3AbortableInputStream.java:close(163)) - 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.
2017-06-28 15:24:21,897 [JUnit-testRandomIONormalPolicy] DEBUG
s3a.S3AInputStream (S3AInputStream.java:closeStream(490)) - Stream
s3a://landsat-pds/scene_list.gz aborted: seekInStream(); remaining=43375083
streamPos=2228224, nextReadPos=131072, request range 2097152-45603307
length=45603307
2017-06-28 15:24:21,897 [JUnit-testRandomIONormalPolicy] DEBUG
s3a.S3AInputStream (S3AInputStream.java:reopen(148)) -
reopen(s3a://landsat-pds/scene_list.gz) for read from new offset
range[131072-45603307], length=131072, streamPosition=131072,
nextReadPosition=131072
2017-06-28 15:24:23,227 [JUnit-testRandomIONormalPolicy] DEBUG
s3a.S3AInputStream (S3AInputStream.java:closeStream(456)) - Closing stream
seekInStream(): soft
2017-06-28 15:24:23,227 [JUnit-testRandomIONormalPolicy] DEBUG
s3a.S3AInputStream (S3AInputStream.java:closeStream(486)) - Aborting stream
2017-06-28 15:24:23,228 [JUnit-testRandomIONormalPolicy] WARN
internal.S3AbortableInputStream (S3AbortableInputStream.java:close(163)) - 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.
2017-06-28 15:24:23,229 [JUnit-testRandomIONormalPolicy] DEBUG
s3a.S3AInputStream (S3AInputStream.java:closeStream(490)) - Stream
s3a://landsat-pds/scene_list.gz aborted: seekInStream(); remaining=45341163
streamPos=262144, nextReadPos=5242880, request range 131072-45603307
length=45603307
2017-06-28 15:24:23,229 [JUnit-testRandomIONormalPolicy] DEBUG
s3a.S3AInputStream (S3AInputStream.java:reopen(148)) -
reopen(s3a://landsat-pds/scene_list.gz) for read from new offset
range[5242880-45603307], length=65536, streamPosition=5242880,
nextReadPosition=5242880
2017-06-28 15:24:24,226 [JUnit-testRandomIONormalPolicy] DEBUG
s3a.S3AInputStream (S3AInputStream.java:closeStream(456)) - Closing stream
seekInStream(): soft
2017-06-28 15:24:24,228 [JUnit-testRandomIONormalPolicy] DEBUG
s3a.S3AInputStream (S3AInputStream.java:closeStream(486)) - Aborting stream
2017-06-28 15:24:24,228 [JUnit-testRandomIONormalPolicy] WARN
internal.S3AbortableInputStream (S3AbortableInputStream.java:close(163)) - 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.
2017-06-28 15:24:24,229 [JUnit-testRandomIONormalPolicy] DEBUG
s3a.S3AInputStream (S3AInputStream.java:closeStream(490)) - Stream
s3a://landsat-pds/scene_list.gz aborted: seekInStream(); remaining=40294891
streamPos=5308416, nextReadPos=1048576, request range 5242880-45603307
length=45603307
2017-06-28 15:24:24,229 [JUnit-testRandomIONormalPolicy] DEBUG
s3a.S3AInputStream (S3AInputStream.java:reopen(148)) -
reopen(s3a://landsat-pds/scene_list.gz) for read from new offset
range[1048576-45603307], length=1048576, streamPosition=1048576,
nextReadPosition=1048576
2017-06-28 15:24:26,310 [JUnit-testRandomIONormalPolicy] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1511)) - Duration of
Time to execute 4 reads of total size 1376256 bytes: 5,293,705,537 nS
2017-06-28 15:24:26,311 [JUnit-testRandomIONormalPolicy] DEBUG
s3a.S3AInputStream (S3AInputStream.java:closeStream(456)) - Closing stream
close() operation: soft
2017-06-28 15:24:26,311 [JUnit-testRandomIONormalPolicy] DEBUG
s3a.S3AInputStream (S3AInputStream.java:closeStream(486)) - Aborting stream
2017-06-28 15:24:26,311 [JUnit-testRandomIONormalPolicy] WARN
internal.S3AbortableInputStream (S3AbortableInputStream.java:close(163)) - 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.
2017-06-28 15:24:26,311 [JUnit-testRandomIONormalPolicy] DEBUG
s3a.S3AInputStream (S3AInputStream.java:closeStream(490)) - Stream
s3a://landsat-pds/scene_list.gz aborted: close() operation; remaining=43506155
streamPos=2097152, nextReadPos=0, request range 1048576-45603307 length=45603307
2017-06-28 15:24:26,312 [JUnit-testRandomIONormalPolicy] INFO
scale.ITestS3AInputStreamPerformance
(ITestS3AInputStreamPerformance.java:logTimePerIOP(203)) - Time per byte read:
3,846 nS
2017-06-28 15:24:26,312 [JUnit-testRandomIONormalPolicy] INFO
scale.ITestS3AInputStreamPerformance
(ITestS3AInputStreamPerformance.java:executeRandomIO(464)) - Effective
bandwidth 0.247936 MB/S
2017-06-28 15:24:26,313 [JUnit-testRandomIONormalPolicy] INFO
scale.ITestS3AInputStreamPerformance
(ITestS3AInputStreamPerformance.java:logStreamStatistics(365)) - Stream
Statistics
StreamStatistics{OpenOperations=4, CloseOperations=4, Closed=0, Aborted=4,
SeekOperations=2, ReadExceptions=0, ForwardSeekOperations=0,
BackwardSeekOperations=2, BytesSkippedOnSeek=0, BytesBackwardsOnSeek=6356992,
BytesRead=1376256, BytesRead excluding skipped=1376256, ReadOperations=159,
ReadFullyOperations=4, ReadsIncomplete=155, BytesReadInClose=0,
BytesDiscardedInAbort=172517292}
2017-06-28 15:24:26,313 [JUnit-testRandomIONormalPolicy] INFO
contract.AbstractFSContractTestBase
(AbstractFSContractTestBase.java:describe(255)) - cleanup
2017-06-28 15:24:26,545 [JUnit-testRandomIONormalPolicy] INFO
contract.AbstractFSContractTestBase
(AbstractFSContractTestBase.java:describe(255)) - closing file system
{code}
> AWS SDK 1.11+ aborts() on close() if > 0 bytes in stream; logs error
> --------------------------------------------------------------------
>
> Key: HADOOP-14596
> URL: https://issues.apache.org/jira/browse/HADOOP-14596
> Project: Hadoop Common
> Issue Type: Sub-task
> Components: fs/s3
> Reporter: Steve Loughran
> Priority: Minor
> Attachments: HADOOP-14596-001.patch, HADOOP-14596-002.patch,
> testlog.txt
>
>
> The latest SDK now tells us off when we do a seek() by aborting the TCP stream
> {code}
> - 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.
> 2017-06-27 15:47:35,789 [ScalaTest-main-running-S3ACSVReadSuite] WARN
> internal.S3AbortableInputStream (S3AbortableInputStream.java:close(163)) -
> 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.
> 2017-06-27 15:47:37,409 [ScalaTest-main-running-S3ACSVReadSuite] WARN
> internal.S3AbortableInputStream (S3AbortableInputStream.java:close(163)) -
> 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.
> 2017-06-27 15:47:39,003 [ScalaTest-main-running-S3ACSVReadSuite] WARN
> internal.S3AbortableInputStream (S3AbortableInputStream.java:close(163)) -
> 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.
> 2017-06-27 15:47:40,627 [ScalaTest-main-running-S3ACSVReadSuite] WARN
> internal.S3AbortableInputStream (S3AbortableInputStream.java:close(163)) -
> 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.
> {code}
--
This message was sent by Atlassian JIRA
(v6.4.14#64029)
---------------------------------------------------------------------
To unsubscribe, e-mail: common-issues-unsubscr...@hadoop.apache.org
For additional commands, e-mail: common-issues-h...@hadoop.apache.org
