[
https://issues.apache.org/jira/browse/HADOOP-13871?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15729586#comment-15729586
]
Steve Loughran edited comment on HADOOP-13871 at 12/7/16 7:12 PM:
------------------------------------------------------------------
good news, I've been able to replicate it on the new SDK too, meaning its a
network/load balance problem, not SDK related
{code}
2016-12-07 18:42:22,553 [Thread-1] DEBUG s3a.S3AFileSystem
(S3ClientFactory.java:initUserAgent(187)) - Using User-Agent: Hadoop
2.8.0-SNAPSHOT
2016-12-07 18:42:22,913 [Thread-1] DEBUG s3a.AWSCredentialProviderList
(AWSCredentialProviderList.java:getCredentials(134)) - Using credentials from
BasicAWSCredentialsProvider
2016-12-07 18:42:22,921 [Thread-1] DEBUG amazonaws.request
(AmazonHttpClient.java:executeOneRequest(1046)) - Sending Request: HEAD
https://hwdev-steve-ireland-new.s3-us-west-1.amazonaws.com / Headers:
(User-Agent: Hadoop 2.8.0-SNAPSHOT, aws-sdk-java/1.11.45 Mac_OS_X/10.12.1
Java_HotSpot(TM)_64-Bit_Server_VM/25.102-b14/1.8.0_102, amz-sdk-invocation-id:
787e1df3-9887-fd11-ec8d-801a7836e20d, Content-Type: application/octet-stream, )
2016-12-07 18:42:23,927 [Thread-1] DEBUG amazonaws.request
(AmazonHttpClient.java:handleErrorResponse(1497)) - Received error response:
com.amazonaws.services.s3.model.AmazonS3Exception: Moved Permanently (Service:
null; Status Code: 301; Error Code: 301 Moved Permanently; Request ID:
0D2990D655FE6CDD), S3 Extended Request ID:
zam+lWQRapkEc17mnHEoLgeWBuFXGGLncQaxBi/a12Y3uohpoEAzRS1frsGb81AnU1HDJn2b7IU=
2016-12-07 18:42:23,978 [Thread-1] DEBUG amazonaws.request
(AmazonHttpClient.java:executeOneRequest(1046)) - Sending Request: HEAD
https://hwdev-steve-ireland-new.s3-eu-west-1.amazonaws.com / Headers:
(User-Agent: Hadoop 2.8.0-SNAPSHOT, aws-sdk-java/1.11.45 Mac_OS_X/10.12.1
Java_HotSpot(TM)_64-Bit_Server_VM/25.102-b14/1.8.0_102, amz-sdk-invocation-id:
f9fabf3f-9809-ad08-7c2f-1683f6d593cf, Content-Type: application/octet-stream, )
2016-12-07 18:42:24,163 [Thread-1] DEBUG amazonaws.request
(AwsResponseHandlerAdapter.java:handle(87)) - Received successful response:
200, AWS Request ID: null
2016-12-07 18:42:24,164 [Thread-1] DEBUG amazonaws.request
(AwsResponseHandlerAdapter.java:logHeaderRequestId(138)) - x-amzn-RequestId:
not available
2016-12-07 18:42:24,164 [Thread-1] DEBUG amazonaws.request
(AwsResponseHandlerAdapter.java:logResponseRequestId(158)) - AWS Request ID:
not available
2016-12-07 18:42:24,165 [Thread-1] DEBUG s3a.S3AFileSystem
(S3AFileSystem.java:initialize(225)) - Using encryption null
2016-12-07 18:42:24,166 [Thread-1] DEBUG s3a.S3AFileSystem
(S3AFileSystem.java:initialize(238)) - Using S3ABlockOutputStream with buffer =
disk; block=8000000; queue limit=4
2016-12-07 18:42:24,169 [Thread-1] INFO contract.AbstractFSContractTestBase
(AbstractFSContractTestBase.java:setup(184)) - Test filesystem =
s3a://hwdev-steve-ireland-new implemented by
S3AFileSystem{uri=s3a://hwdev-steve-ireland-new,
workingDir=s3a://hwdev-steve-ireland-new/user/stevel, inputPolicy=normal,
partSize=8000000, enableMultiObjectsDelete=true, maxKeys=5000, readAhead=65536,
blockSize=33554432, multiPartThreshold=2147483647,
blockFactory=org.apache.hadoop.fs.s3a.S3ADataBlocks$DiskBlockFactory@51dffc97,
executor=BlockingThreadPoolExecutorService{SemaphoredDelegatingExecutor{permitCount=30,
available=30, waiting=0}, activeCount=0}, statistics {0 bytes read, 0 bytes
written, 0 read ops, 0 large read ops, 0 write ops}, metrics
{{Context=S3AFileSystem}
{FileSystemId=461d5b68-e18f-4e9b-b88f-ee6cee6196ac-hwdev-steve-ireland-new}
{fsURI=s3a://hwdev-steve-ireland-new/} {files_created=0} {files_copied=0}
{files_copied_bytes=0} {files_deleted=0} {fake_directories_deleted=0}
{directories_created=0} {directories_deleted=0} {ignored_errors=0}
{op_copy_from_local_file=0} {op_exists=0} {op_get_file_status=0}
{op_glob_status=0} {op_is_directory=0} {op_is_file=0} {op_list_files=0}
{op_list_located_status=0} {op_list_status=0} {op_mkdirs=0} {op_rename=0}
{object_copy_requests=0} {object_delete_requests=0} {object_list_requests=0}
{object_continue_list_requests=0} {object_metadata_requests=0}
{object_multipart_aborted=0} {object_put_bytes=0} {object_put_requests=0}
{object_put_requests_completed=0} {stream_write_failures=0}
{stream_write_block_uploads=0} {stream_write_block_uploads_committed=0}
{stream_write_block_uploads_aborted=0} {stream_write_total_time=0}
{stream_write_total_data=0} {object_put_requests_active=0}
{object_put_bytes_pending=0} {stream_write_block_uploads_active=0}
{stream_write_block_uploads_pending=0}
{stream_write_block_uploads_data_pending=0} {stream_read_fully_operations=0}
{stream_opened=0} {stream_bytes_skipped_on_seek=0} {stream_closed=0}
{stream_bytes_backwards_on_seek=0} {stream_bytes_read=0}
{stream_read_operations_incomplete=0} {stream_bytes_discarded_in_abort=0}
{stream_close_operations=0} {stream_read_operations=0} {stream_aborted=0}
{stream_forward_seek_operations=0} {stream_backward_seek_operations=0}
{stream_seek_operations=0} {stream_bytes_read_in_close=0}
{stream_read_exceptions=0} }}
2016-12-07 18:42:24,171 [Thread-1] DEBUG s3a.S3AFileSystem
(S3AFileSystem.java:innerMkdirs(1478)) - Making directory: /test
2016-12-07 18:42:24,171 [Thread-1] DEBUG s3a.S3AFileSystem
(S3AStorageStatistics.java:incrementCounter(60)) - op_mkdirs += 1 -> 1
2016-12-07 18:42:24,171 [Thread-1] DEBUG s3a.S3AFileSystem
(S3AStorageStatistics.java:incrementCounter(60)) - op_get_file_status += 1 ->
1
2016-12-07 18:42:24,172 [Thread-1] DEBUG s3a.S3AFileSystem
(S3AFileSystem.java:getFileStatus(1525)) - Getting path status for
s3a://hwdev-steve-ireland-new/test (test)
2016-12-07 18:42:24,172 [Thread-1] DEBUG s3a.S3AFileSystem
(S3AStorageStatistics.java:incrementCounter(60)) - object_metadata_requests +=
1 -> 1
2016-12-07 18:42:24,174 [Thread-1] DEBUG amazonaws.request
(AmazonHttpClient.java:executeOneRequest(1046)) - Sending Request: HEAD
https://hwdev-steve-ireland-new.s3-eu-west-1.amazonaws.com /test Headers:
(User-Agent: Hadoop 2.8.0-SNAPSHOT, aws-sdk-java/1.11.45 Mac_OS_X/10.12.1
Java_HotSpot(TM)_64-Bit_Server_VM/25.102-b14/1.8.0_102, amz-sdk-invocation-id:
57239941-1812-a15f-736a-f3da7727b192, Content-Type: application/octet-stream, )
2016-12-07 18:42:24,225 [Thread-1] DEBUG amazonaws.request
(AmazonHttpClient.java:handleErrorResponse(1497)) - Received error response:
com.amazonaws.services.s3.model.AmazonS3Exception: Not Found (Service: null;
Status Code: 404; Error Code: 404 Not Found; Request ID: 2B1E6AAB5BB13A50), S3
Extended Request ID:
37X2RRn7nQAt5RDTbO8jazu8ltPGdiUZ+OmvP0cPPtYaaoEGeI/qZ5sv4fEH3xFZOb+d5+wu/w4=
2016-12-07 18:42:24,225 [Thread-1] DEBUG s3a.S3AFileSystem
(S3AStorageStatistics.java:incrementCounter(60)) - object_metadata_requests +=
1 -> 2
2016-12-07 18:42:24,226 [Thread-1] DEBUG amazonaws.request
(AmazonHttpClient.java:executeOneRequest(1046)) - Sending Request: HEAD
https://hwdev-steve-ireland-new.s3-eu-west-1.amazonaws.com /test/ Headers:
(User-Agent: Hadoop 2.8.0-SNAPSHOT, aws-sdk-java/1.11.45 Mac_OS_X/10.12.1
Java_HotSpot(TM)_64-Bit_Server_VM/25.102-b14/1.8.0_102, amz-sdk-invocation-id:
52c578b8-6d85-49e9-d148-2db3079cc239, Content-Type: application/octet-stream, )
2016-12-07 18:42:24,274 [Thread-1] DEBUG amazonaws.request
(AmazonHttpClient.java:handleErrorResponse(1497)) - Received error response:
com.amazonaws.services.s3.model.AmazonS3Exception: Not Found (Service: null;
Status Code: 404; Error Code: 404 Not Found; Request ID: 4B7CD9CADDF086A7), S3
Extended Request ID:
9AR/mRdKgwAnb8SnWzLSqrM8K/DWFK1utzFqKXZihDtTN9UXPsxGFGN2GoBHgHNTqY41YBBptn8=
2016-12-07 18:42:24,274 [Thread-1] DEBUG s3a.S3AFileSystem
(S3AStorageStatistics.java:incrementCounter(60)) - object_list_requests += 1
-> 1
2016-12-07 18:42:24,289 [Thread-1] DEBUG amazonaws.request
(AmazonHttpClient.java:executeOneRequest(1046)) - Sending Request: GET
https://hwdev-steve-ireland-new.s3-eu-west-1.amazonaws.com / Parameters:
({"prefix":["test/"],"delimiter":["/"],"max-keys":["1"],"encoding-type":["url"]}Headers:
(User-Agent: Hadoop 2.8.0-SNAPSHOT, aws-sdk-java/1.11.45 Mac_OS_X/10.12.1
Java_HotSpot(TM)_64-Bit_Server_VM/25.102-b14/1.8.0_102, amz-sdk-invocation-id:
5cb39b7e-4fb2-5401-25d5-0fdc15db05ad, Content-Type: application/octet-stream, )
2016-12-07 18:42:24,364 [Thread-1] DEBUG amazonaws.request
(AwsResponseHandlerAdapter.java:handle(87)) - Received successful response:
200, AWS Request ID: A39D3AE5D27ABAC9
2016-12-07 18:42:24,365 [Thread-1] DEBUG amazonaws.request
(AwsResponseHandlerAdapter.java:logHeaderRequestId(138)) - x-amzn-RequestId:
not available
2016-12-07 18:42:24,365 [Thread-1] DEBUG amazonaws.request
(AwsResponseHandlerAdapter.java:logResponseRequestId(158)) - AWS Request ID:
A39D3AE5D27ABAC9
2016-12-07 18:42:24,365 [Thread-1] DEBUG s3a.S3AFileSystem
(S3AFileSystem.java:getFileStatus(1616)) - Not Found:
s3a://hwdev-steve-ireland-new/test
2016-12-07 18:42:24,365 [Thread-1] DEBUG s3a.S3AFileSystem
(S3AStorageStatistics.java:incrementCounter(60)) - op_get_file_status += 1 ->
2
2016-12-07 18:42:24,365 [Thread-1] DEBUG s3a.S3AFileSystem
(S3AFileSystem.java:getFileStatus(1525)) - Getting path status for
s3a://hwdev-steve-ireland-new/ ()
2016-12-07 18:42:24,365 [Thread-1] DEBUG s3a.S3AFileSystem
(S3AStorageStatistics.java:incrementCounter(60)) - object_list_requests += 1
-> 2
2016-12-07 18:42:24,366 [Thread-1] DEBUG amazonaws.request
(AmazonHttpClient.java:executeOneRequest(1046)) - Sending Request: GET
https://hwdev-steve-ireland-new.s3-eu-west-1.amazonaws.com / Parameters:
({"prefix":[""],"delimiter":["/"],"max-keys":["1"],"encoding-type":["url"]}Headers:
(User-Agent: Hadoop 2.8.0-SNAPSHOT, aws-sdk-java/1.11.45 Mac_OS_X/10.12.1
Java_HotSpot(TM)_64-Bit_Server_VM/25.102-b14/1.8.0_102, amz-sdk-invocation-id:
d68ca495-6dee-8f17-0ff8-008f25a75702, Content-Type: application/octet-stream, )
2016-12-07 18:42:24,426 [Thread-1] DEBUG amazonaws.request
(AwsResponseHandlerAdapter.java:handle(87)) - Received successful response:
200, AWS Request ID: 7169BE12EAD059C9
2016-12-07 18:42:24,426 [Thread-1] DEBUG amazonaws.request
(AwsResponseHandlerAdapter.java:logHeaderRequestId(138)) - x-amzn-RequestId:
not available
2016-12-07 18:42:24,426 [Thread-1] DEBUG amazonaws.request
(AwsResponseHandlerAdapter.java:logResponseRequestId(158)) - AWS Request ID:
7169BE12EAD059C9
2016-12-07 18:42:24,427 [Thread-1] DEBUG s3a.S3AFileSystem
(S3AFileSystem.java:getFileStatus(1591)) - Found path as directory (with /): 1/0
2016-12-07 18:42:24,427 [Thread-1] DEBUG s3a.S3AFileSystem
(S3AFileSystem.java:getFileStatus(1599)) - Prefix: Users/
2016-12-07 18:42:24,429 [Thread-1] DEBUG s3a.S3AFileSystem
(S3AFileSystem.java:incrementPutStartStatistics(1116)) - PUT start 0 bytes
2016-12-07 18:42:24,429 [Thread-1] DEBUG s3a.S3AFileSystem
(S3AStorageStatistics.java:incrementCounter(60)) - object_put_requests += 1 ->
1
2016-12-07 18:42:24,437 [Thread-1] DEBUG s3a.S3AFileSystem
(S3AFileSystem.java:incrementPutCompletedStatistics(1133)) - PUT completed
success=true; 0 bytes
2016-12-07 18:42:24,437 [Thread-1] DEBUG s3a.S3AFileSystem
(S3AStorageStatistics.java:incrementCounter(60)) -
object_put_requests_completed += 1 -> 1
2016-12-07 18:42:24,440 [s3a-transfer-shared-pool1-t1] DEBUG amazonaws.request
(AmazonHttpClient.java:executeOneRequest(1046)) - Sending Request: PUT
https://hwdev-steve-ireland-new.s3-eu-west-1.amazonaws.com /test/ Headers:
(User-Agent: Hadoop 2.8.0-SNAPSHOT, aws-sdk-java/1.11.45 Mac_OS_X/10.12.1
Java_HotSpot(TM)_64-Bit_Server_VM/25.102-b14/1.8.0_102
com.amazonaws.services.s3.transfer.TransferManager/1.11.45,
amz-sdk-invocation-id: fad23d78-a104-156a-81ed-f3e29d668cd8, Content-Length: 0,
Content-Type: application/octet-stream, )
2016-12-07 18:42:24,509 [s3a-transfer-shared-pool1-t1] DEBUG amazonaws.request
(AwsResponseHandlerAdapter.java:handle(87)) - Received successful response:
200, AWS Request ID: 1A25A7F6C78ED591
2016-12-07 18:42:24,509 [s3a-transfer-shared-pool1-t1] DEBUG amazonaws.request
(AwsResponseHandlerAdapter.java:logHeaderRequestId(138)) - x-amzn-RequestId:
not available
2016-12-07 18:42:24,509 [s3a-transfer-shared-pool1-t1] DEBUG amazonaws.request
(AwsResponseHandlerAdapter.java:logResponseRequestId(158)) - AWS Request ID:
1A25A7F6C78ED591
2016-12-07 18:42:24,514 [Thread-1] DEBUG S3AFileSystem.Progress
(S3AFileSystem.java:incrementPutProgressStatistics(1151)) - PUT test/: 0 bytes
2016-12-07 18:42:24,514 [Thread-1] DEBUG scale.S3AScaleTestBase
(S3AScaleTestBase.java:setup(94)) - Scale test operation count = 1
2016-12-07 18:42:24,516 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
s3a.S3AFileSystem (S3ClientFactory.java:initUserAgent(187)) - Using User-Agent:
Hadoop 2.8.0-SNAPSHOT
2016-12-07 18:42:24,519 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
s3a.AWSCredentialProviderList
(AWSCredentialProviderList.java:getCredentials(134)) - Using credentials from
BasicAWSCredentialsProvider
2016-12-07 18:42:24,520 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
amazonaws.request (AmazonHttpClient.java:executeOneRequest(1046)) - Sending
Request: HEAD https://landsat-pds.s3-us-west-1.amazonaws.com / Headers:
(User-Agent: Hadoop 2.8.0-SNAPSHOT, aws-sdk-java/1.11.45 Mac_OS_X/10.12.1
Java_HotSpot(TM)_64-Bit_Server_VM/25.102-b14/1.8.0_102, amz-sdk-invocation-id:
40808c03-5cf7-c960-4c97-353313df657b, Content-Type: application/octet-stream, )
2016-12-07 18:42:25,338 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
amazonaws.request (AmazonHttpClient.java:handleErrorResponse(1497)) - Received
error response: com.amazonaws.services.s3.model.AmazonS3Exception: Moved
Permanently (Service: null; Status Code: 301; Error Code: 301 Moved
Permanently; Request ID: 58DECB0934A6428C), S3 Extended Request ID:
QQxGx+1eyQEbD/skrLYpaXg+XuW8EvgwtCkpqqTJttl/ONjzD1xC1jVX6IqFCQZdfrSsup85pTM=
2016-12-07 18:42:25,339 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
amazonaws.request (AmazonHttpClient.java:executeOneRequest(1046)) - Sending
Request: HEAD https://landsat-pds.s3-us-west-2.amazonaws.com / Headers:
(User-Agent: Hadoop 2.8.0-SNAPSHOT, aws-sdk-java/1.11.45 Mac_OS_X/10.12.1
Java_HotSpot(TM)_64-Bit_Server_VM/25.102-b14/1.8.0_102, amz-sdk-invocation-id:
5eb0baa1-d0f0-1825-27c1-4c122afb0d72, Content-Type: application/octet-stream, )
2016-12-07 18:42:26,225 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
amazonaws.request (AwsResponseHandlerAdapter.java:handle(87)) - Received
successful response: 200, AWS Request ID: null
2016-12-07 18:42:26,225 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
amazonaws.request (AwsResponseHandlerAdapter.java:logHeaderRequestId(138)) -
x-amzn-RequestId: not available
2016-12-07 18:42:26,225 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
amazonaws.request (AwsResponseHandlerAdapter.java:logResponseRequestId(158)) -
AWS Request ID: not available
2016-12-07 18:42:26,226 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
s3a.S3AFileSystem (S3AFileSystem.java:initialize(225)) - Using encryption null
2016-12-07 18:42:26,226 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
s3a.S3AFileSystem (S3AFileSystem.java:initialize(238)) - Using
S3ABlockOutputStream with buffer = disk; block=8000000; queue limit=4
2016-12-07 18:42:26,226 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
s3a.S3AFileSystem (S3AStorageStatistics.java:incrementCounter(60)) -
op_get_file_status += 1 -> 3
2016-12-07 18:42:26,226 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
s3a.S3AFileSystem (S3AFileSystem.java:getFileStatus(1525)) - Getting path
status for s3a://landsat-pds/scene_list.gz (scene_list.gz)
2016-12-07 18:42:26,226 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
s3a.S3AFileSystem (S3AStorageStatistics.java:incrementCounter(60)) -
object_metadata_requests += 1 -> 3
2016-12-07 18:42:26,227 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
amazonaws.request (AmazonHttpClient.java:executeOneRequest(1046)) - Sending
Request: HEAD https://landsat-pds.s3-us-west-2.amazonaws.com /scene_list.gz
Headers: (User-Agent: Hadoop 2.8.0-SNAPSHOT, aws-sdk-java/1.11.45
Mac_OS_X/10.12.1 Java_HotSpot(TM)_64-Bit_Server_VM/25.102-b14/1.8.0_102,
amz-sdk-invocation-id: 33d34c3d-ead9-809a-af05-257b905fede7, Content-Type:
application/octet-stream, )
2016-12-07 18:42:26,788 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
amazonaws.request (AwsResponseHandlerAdapter.java:handle(87)) - Received
successful response: 200, AWS Request ID: C756074918F8BAB1
2016-12-07 18:42:26,788 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
amazonaws.request (AwsResponseHandlerAdapter.java:logHeaderRequestId(138)) -
x-amzn-RequestId: not available
2016-12-07 18:42:26,788 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
amazonaws.request (AwsResponseHandlerAdapter.java:logResponseRequestId(158)) -
AWS Request ID: C756074918F8BAB1
2016-12-07 18:42:26,788 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
s3a.S3AFileSystem (S3AFileSystem.java:getFileStatus(1534)) - Found exact file:
normal file
2016-12-07 18:42:26,789 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
s3a.AbstractS3ATestBase (AbstractS3ATestBase.java:describe(87)) -
testTimeToOpenAndReadWholeFileBlocks: Open the test file
s3a://landsat-pds/scene_list.gz and read it in blocks of size 1048576
2016-12-07 18:42:26,789 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
s3a.S3AFileSystem (S3AFileSystem.java:setInputPolicy(413)) - Setting input
strategy: normal
2016-12-07 18:42:26,789 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
s3a.S3AFileSystem (S3AFileSystem.java:open(503)) - Opening
's3a://landsat-pds/scene_list.gz' for reading.
2016-12-07 18:42:26,789 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
s3a.S3AFileSystem (S3AStorageStatistics.java:incrementCounter(60)) -
op_get_file_status += 1 -> 4
2016-12-07 18:42:26,789 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
s3a.S3AFileSystem (S3AFileSystem.java:getFileStatus(1525)) - Getting path
status for s3a://landsat-pds/scene_list.gz (scene_list.gz)
2016-12-07 18:42:26,789 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
s3a.S3AFileSystem (S3AStorageStatistics.java:incrementCounter(60)) -
object_metadata_requests += 1 -> 4
2016-12-07 18:42:26,790 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
amazonaws.request (AmazonHttpClient.java:executeOneRequest(1046)) - Sending
Request: HEAD https://landsat-pds.s3-us-west-2.amazonaws.com /scene_list.gz
Headers: (User-Agent: Hadoop 2.8.0-SNAPSHOT, aws-sdk-java/1.11.45
Mac_OS_X/10.12.1 Java_HotSpot(TM)_64-Bit_Server_VM/25.102-b14/1.8.0_102,
amz-sdk-invocation-id: 5d20098b-a1cc-a15d-7cf6-959355ceda8c, Content-Type:
application/octet-stream, )
2016-12-07 18:42:26,965 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
amazonaws.request (AwsResponseHandlerAdapter.java:handle(87)) - Received
successful response: 200, AWS Request ID: 48BD932265D2E504
2016-12-07 18:42:26,965 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
amazonaws.request (AwsResponseHandlerAdapter.java:logHeaderRequestId(138)) -
x-amzn-RequestId: not available
2016-12-07 18:42:26,965 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
amazonaws.request (AwsResponseHandlerAdapter.java:logResponseRequestId(158)) -
AWS Request ID: 48BD932265D2E504
2016-12-07 18:42:26,965 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
s3a.S3AFileSystem (S3AFileSystem.java:getFileStatus(1534)) - Found exact file:
normal file
2016-12-07 18:42:26,967 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
s3a.S3AFileSystem (S3AFileSystem.java:setInputPolicy(413)) - Setting input
strategy: normal
2016-12-07 18:42:26,967 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
s3a.S3AFileSystem (S3AInputStream.java:reopen(140)) -
reopen(s3a://landsat-pds/scene_list.gz) for read from new offset
range[0-38939342], length=1048576, streamPosition=0, nextReadPosition=0
2016-12-07 18:42:26,969 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
amazonaws.request (AmazonHttpClient.java:executeOneRequest(1046)) - Sending
Request: GET https://landsat-pds.s3-us-west-2.amazonaws.com /scene_list.gz
Headers: (User-Agent: Hadoop 2.8.0-SNAPSHOT, aws-sdk-java/1.11.45
Mac_OS_X/10.12.1 Java_HotSpot(TM)_64-Bit_Server_VM/25.102-b14/1.8.0_102,
amz-sdk-invocation-id: 6489ce83-1f56-b833-15dc-f78d8eed429f, Range:
bytes=0-38939342, Content-Type: application/octet-stream, )
2016-12-07 18:42:27,168 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
amazonaws.request (AwsResponseHandlerAdapter.java:handle(87)) - Received
successful response: 206, AWS Request ID: 7BB5413C293FE587
2016-12-07 18:42:27,168 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
amazonaws.request (AwsResponseHandlerAdapter.java:logHeaderRequestId(138)) -
x-amzn-RequestId: not available
2016-12-07 18:42:27,168 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
amazonaws.request (AwsResponseHandlerAdapter.java:logResponseRequestId(158)) -
AWS Request ID: 7BB5413C293FE587
2016-12-07 18:43:32,677 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 0 in 121 reads: 65,708,704,300 nS
2016-12-07 18:44:50,868 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 1 in 121 reads: 78,191,068,156 nS
2016-12-07 18:48:57,544 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
s3a.S3AFileSystem (S3AInputStream.java:onReadFailure(334)) - Got exception
while trying to read from stream s3a://landsat-pds/scene_list.gz trying to
recover: java.net.SocketTimeoutException: Read timed out
2016-12-07 18:48:57,546 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
s3a.S3AFileSystem (S3AInputStream.java:onReadFailure(336)) - While trying to
read from stream s3a://landsat-pds/scene_list.gz
java.net.SocketTimeoutException: Read timed out
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
at java.net.SocketInputStream.read(SocketInputStream.java:170)
at java.net.SocketInputStream.read(SocketInputStream.java:141)
at sun.security.ssl.InputRecord.readFully(InputRecord.java:465)
at sun.security.ssl.InputRecord.readV3Record(InputRecord.java:593)
at sun.security.ssl.InputRecord.read(InputRecord.java:532)
at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:973)
at sun.security.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:930)
at sun.security.ssl.AppInputStream.read(AppInputStream.java:105)
at
org.apache.http.impl.io.SessionInputBufferImpl.streamRead(SessionInputBufferImpl.java:139)
at
org.apache.http.impl.io.SessionInputBufferImpl.read(SessionInputBufferImpl.java:200)
at
org.apache.http.impl.io.ContentLengthInputStream.read(ContentLengthInputStream.java:178)
at
org.apache.http.conn.EofSensorInputStream.read(EofSensorInputStream.java:137)
at
com.amazonaws.internal.SdkFilterInputStream.read(SdkFilterInputStream.java:72)
at
com.amazonaws.event.ProgressInputStream.read(ProgressInputStream.java:181)
at
com.amazonaws.internal.SdkFilterInputStream.read(SdkFilterInputStream.java:72)
at
com.amazonaws.services.s3.model.S3ObjectInputStream.read(S3ObjectInputStream.java:155)
at
com.amazonaws.internal.SdkFilterInputStream.read(SdkFilterInputStream.java:72)
at
com.amazonaws.internal.SdkFilterInputStream.read(SdkFilterInputStream.java:72)
at
com.amazonaws.event.ProgressInputStream.read(ProgressInputStream.java:181)
at
com.amazonaws.internal.SdkFilterInputStream.read(SdkFilterInputStream.java:72)
at
com.amazonaws.util.LengthCheckInputStream.read(LengthCheckInputStream.java:108)
at
com.amazonaws.internal.SdkFilterInputStream.read(SdkFilterInputStream.java:72)
at
com.amazonaws.services.s3.model.S3ObjectInputStream.read(S3ObjectInputStream.java:155)
at org.apache.hadoop.fs.s3a.S3AInputStream.read(S3AInputStream.java:373)
at java.io.DataInputStream.read(DataInputStream.java:149)
at
org.apache.hadoop.fs.s3a.scale.ITestS3AInputStreamPerformance.testTimeToOpenAndReadWholeFileBlocks(ITestS3AInputStreamPerformance.java:225)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at
org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:47)
at
org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
at
org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:44)
at
org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
at
org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
at
org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
at org.junit.rules.TestWatcher$1.evaluate(TestWatcher.java:55)
at
org.junit.internal.runners.statements.FailOnTimeout$StatementThread.run(FailOnTimeout.java:74)
2016-12-07 18:48:57,550 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
s3a.S3AFileSystem (S3AInputStream.java:closeStream(463)) - Stream
s3a://landsat-pds/scene_list.gz aborted: reopen(failure recovery);
streamPos=2575953, nextReadPos=2575953, request range 0-38939342 length=38939342
2016-12-07 18:48:57,550 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
s3a.S3AFileSystem (S3AInputStream.java:reopen(140)) -
reopen(s3a://landsat-pds/scene_list.gz) for failure recovery
range[2575953-38939342], length=569775, streamPosition=2575953,
nextReadPosition=2575953
2016-12-07 18:48:57,554 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
amazonaws.request (AmazonHttpClient.java:executeOneRequest(1046)) - Sending
Request: GET https://landsat-pds.s3-us-west-2.amazonaws.com /scene_list.gz
Headers: (User-Agent: Hadoop 2.8.0-SNAPSHOT, aws-sdk-java/1.11.45
Mac_OS_X/10.12.1 Java_HotSpot(TM)_64-Bit_Server_VM/25.102-b14/1.8.0_102,
amz-sdk-invocation-id: 4ae4b351-3374-49e5-fa73-81cff322f56c, Range:
bytes=2575953-38939342, Content-Type: application/octet-stream, )
2016-12-07 18:48:58,358 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
amazonaws.request (AwsResponseHandlerAdapter.java:handle(87)) - Received
successful response: 206, AWS Request ID: 773084E647B9C370
2016-12-07 18:48:58,359 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
amazonaws.request (AwsResponseHandlerAdapter.java:logHeaderRequestId(138)) -
x-amzn-RequestId: not available
2016-12-07 18:48:58,359 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
amazonaws.request (AwsResponseHandlerAdapter.java:logResponseRequestId(158)) -
AWS Request ID: 773084E647B9C370
2016-12-07 18:48:59,397 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 2 in 121 reads: 248,531,807,139 nS
2016-12-07 18:48:59,988 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 3 in 122 reads: 590,226,556 nS
2016-12-07 18:49:00,346 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 4 in 122 reads: 357,777,268 nS
2016-12-07 18:49:00,635 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 5 in 121 reads: 288,089,615 nS
2016-12-07 18:49:00,869 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 6 in 89 reads: 233,918,422 nS
2016-12-07 18:49:01,094 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 7 in 69 reads: 224,188,050 nS
2016-12-07 18:49:01,270 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 8 in 69 reads: 175,089,680 nS
2016-12-07 18:49:01,508 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 9 in 69 reads: 237,915,953 nS
2016-12-07 18:49:03,203 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 10 in 69 reads: 1,694,581,186 nS
2016-12-07 18:49:03,562 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 11 in 69 reads: 358,629,013 nS
2016-12-07 18:49:03,814 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 12 in 69 reads: 251,512,010 nS
2016-12-07 18:49:04,080 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 13 in 69 reads: 265,251,582 nS
2016-12-07 18:49:04,284 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 14 in 69 reads: 203,401,204 nS
2016-12-07 18:49:04,488 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 15 in 69 reads: 203,355,837 nS
2016-12-07 18:49:04,682 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 16 in 69 reads: 193,974,256 nS
2016-12-07 18:49:04,902 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 17 in 69 reads: 219,901,121 nS
2016-12-07 18:49:05,089 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 18 in 69 reads: 186,285,604 nS
2016-12-07 18:49:05,323 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 19 in 69 reads: 233,165,569 nS
2016-12-07 18:49:06,021 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 20 in 69 reads: 698,049,891 nS
2016-12-07 18:49:06,350 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 21 in 69 reads: 328,816,127 nS
2016-12-07 18:49:06,571 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 22 in 69 reads: 220,920,300 nS
2016-12-07 18:49:06,785 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 23 in 69 reads: 213,269,165 nS
2016-12-07 18:49:07,044 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 24 in 69 reads: 258,383,769 nS
2016-12-07 18:49:07,260 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 25 in 69 reads: 215,997,541 nS
2016-12-07 18:49:07,472 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 26 in 69 reads: 210,871,191 nS
2016-12-07 18:49:07,675 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 27 in 69 reads: 203,160,739 nS
2016-12-07 18:49:07,905 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 28 in 69 reads: 229,260,978 nS
2016-12-07 18:49:08,107 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 29 in 69 reads: 202,102,165 nS
2016-12-07 18:49:08,387 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 30 in 69 reads: 279,023,912 nS
2016-12-07 18:49:08,751 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 31 in 69 reads: 363,367,889 nS
2016-12-07 18:49:09,066 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 32 in 69 reads: 315,399,466 nS
2016-12-07 18:49:09,312 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 33 in 69 reads: 245,392,893 nS
2016-12-07 18:49:09,566 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 34 in 69 reads: 253,079,462 nS
2016-12-07 18:49:09,813 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 35 in 69 reads: 246,456,730 nS
2016-12-07 18:49:10,093 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 36 in 69 reads: 279,688,361 nS
2016-12-07 18:49:10,093 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Time to read 38939342 bytes in 37 blocks: 403,130,941,090 nS
2016-12-07 18:49:10,094 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:bandwidth(963)) - Bandwidth
= 0.091782 MB/S
2016-12-07 18:49:10,095 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
scale.ITestS3AInputStreamPerformance
(ITestS3AInputStreamPerformance.java:logStreamStatistics(324)) - Stream
Statistics
StreamStatistics{OpenOperations=2, CloseOperations=1, Closed=0, Aborted=1,
SeekOperations=0, ReadExceptions=1, ForwardSeekOperations=0,
BackwardSeekOperations=0, BytesSkippedOnSeek=0, BytesBackwardsOnSeek=0,
BytesRead=38797312, BytesRead excluding skipped=38797312, ReadOperations=2887,
ReadFullyOperations=0, ReadsIncomplete=2850, BytesReadInClose=0,
BytesDiscardedInAbort=36363389}
2016-12-07 18:49:10,095 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.AbstractFSContractTestBase
(AbstractFSContractTestBase.java:describe(255)) - cleanup
2016-12-07 18:49:10,096 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
s3a.S3AFileSystem (S3AInputStream.java:closeStream(463)) - Stream
s3a://landsat-pds/scene_list.gz aborted: close() operation; streamPos=38797312,
nextReadPos=38797312, request range 2575953-38939342 length=38939342
{code}
was (Author: ste...@apache.org):
good news, I've been able to replicate it on the new SDK too, meaning its a
network/load balance problem, not SDK related
{code}
2016-12-07 18:42:22,553 [Thread-1] DEBUG s3a.S3AFileSystem
(S3ClientFactory.java:initUserAgent(187)) - Using User-Agent: Hadoop
2.8.0-SNAPSHOT
2016-12-07 18:42:22,913 [Thread-1] DEBUG s3a.AWSCredentialProviderList
(AWSCredentialProviderList.java:getCredentials(134)) - Using credentials from
BasicAWSCredentialsProvider
2016-12-07 18:42:22,921 [Thread-1] DEBUG amazonaws.request
(AmazonHttpClient.java:executeOneRequest(1046)) - Sending Request: HEAD
https://hwdev-steve-ireland-new.s3-us-west-1.amazonaws.com / Headers:
(User-Agent: Hadoop 2.8.0-SNAPSHOT, aws-sdk-java/1.11.45 Mac_OS_X/10.12.1
Java_HotSpot(TM)_64-Bit_Server_VM/25.102-b14/1.8.0_102, amz-sdk-invocation-id:
787e1df3-9887-fd11-ec8d-801a7836e20d, Content-Type: application/octet-stream, )
2016-12-07 18:42:23,927 [Thread-1] DEBUG amazonaws.request
(AmazonHttpClient.java:handleErrorResponse(1497)) - Received error response:
com.amazonaws.services.s3.model.AmazonS3Exception: Moved Permanently (Service:
null; Status Code: 301; Error Code: 301 Moved Permanently; Request ID:
0D2990D655FE6CDD), S3 Extended Request ID:
zam+lWQRapkEc17mnHEoLgeWBuFXGGLncQaxBi/a12Y3uohpoEAzRS1frsGb81AnU1HDJn2b7IU=
2016-12-07 18:42:23,978 [Thread-1] DEBUG amazonaws.request
(AmazonHttpClient.java:executeOneRequest(1046)) - Sending Request: HEAD
https://hwdev-steve-ireland-new.s3-eu-west-1.amazonaws.com / Headers:
(User-Agent: Hadoop 2.8.0-SNAPSHOT, aws-sdk-java/1.11.45 Mac_OS_X/10.12.1
Java_HotSpot(TM)_64-Bit_Server_VM/25.102-b14/1.8.0_102, amz-sdk-invocation-id:
f9fabf3f-9809-ad08-7c2f-1683f6d593cf, Content-Type: application/octet-stream, )
2016-12-07 18:42:24,163 [Thread-1] DEBUG amazonaws.request
(AwsResponseHandlerAdapter.java:handle(87)) - Received successful response:
200, AWS Request ID: null
2016-12-07 18:42:24,164 [Thread-1] DEBUG amazonaws.request
(AwsResponseHandlerAdapter.java:logHeaderRequestId(138)) - x-amzn-RequestId:
not available
2016-12-07 18:42:24,164 [Thread-1] DEBUG amazonaws.request
(AwsResponseHandlerAdapter.java:logResponseRequestId(158)) - AWS Request ID:
not available
2016-12-07 18:42:24,165 [Thread-1] DEBUG s3a.S3AFileSystem
(S3AFileSystem.java:initialize(225)) - Using encryption null
2016-12-07 18:42:24,166 [Thread-1] DEBUG s3a.S3AFileSystem
(S3AFileSystem.java:initialize(238)) - Using S3ABlockOutputStream with buffer =
disk; block=8000000; queue limit=4
2016-12-07 18:42:24,169 [Thread-1] INFO contract.AbstractFSContractTestBase
(AbstractFSContractTestBase.java:setup(184)) - Test filesystem =
s3a://hwdev-steve-ireland-new implemented by
S3AFileSystem{uri=s3a://hwdev-steve-ireland-new,
workingDir=s3a://hwdev-steve-ireland-new/user/stevel, inputPolicy=normal,
partSize=8000000, enableMultiObjectsDelete=true, maxKeys=5000, readAhead=65536,
blockSize=33554432, multiPartThreshold=2147483647,
blockFactory=org.apache.hadoop.fs.s3a.S3ADataBlocks$DiskBlockFactory@51dffc97,
executor=BlockingThreadPoolExecutorService{SemaphoredDelegatingExecutor{permitCount=30,
available=30, waiting=0}, activeCount=0}, statistics {0 bytes read, 0 bytes
written, 0 read ops, 0 large read ops, 0 write ops}, metrics
{{Context=S3AFileSystem}
{FileSystemId=461d5b68-e18f-4e9b-b88f-ee6cee6196ac-hwdev-steve-ireland-new}
{fsURI=s3a://hwdev-steve-ireland-new/} {files_created=0} {files_copied=0}
{files_copied_bytes=0} {files_deleted=0} {fake_directories_deleted=0}
{directories_created=0} {directories_deleted=0} {ignored_errors=0}
{op_copy_from_local_file=0} {op_exists=0} {op_get_file_status=0}
{op_glob_status=0} {op_is_directory=0} {op_is_file=0} {op_list_files=0}
{op_list_located_status=0} {op_list_status=0} {op_mkdirs=0} {op_rename=0}
{object_copy_requests=0} {object_delete_requests=0} {object_list_requests=0}
{object_continue_list_requests=0} {object_metadata_requests=0}
{object_multipart_aborted=0} {object_put_bytes=0} {object_put_requests=0}
{object_put_requests_completed=0} {stream_write_failures=0}
{stream_write_block_uploads=0} {stream_write_block_uploads_committed=0}
{stream_write_block_uploads_aborted=0} {stream_write_total_time=0}
{stream_write_total_data=0} {object_put_requests_active=0}
{object_put_bytes_pending=0} {stream_write_block_uploads_active=0}
{stream_write_block_uploads_pending=0}
{stream_write_block_uploads_data_pending=0} {stream_read_fully_operations=0}
{stream_opened=0} {stream_bytes_skipped_on_seek=0} {stream_closed=0}
{stream_bytes_backwards_on_seek=0} {stream_bytes_read=0}
{stream_read_operations_incomplete=0} {stream_bytes_discarded_in_abort=0}
{stream_close_operations=0} {stream_read_operations=0} {stream_aborted=0}
{stream_forward_seek_operations=0} {stream_backward_seek_operations=0}
{stream_seek_operations=0} {stream_bytes_read_in_close=0}
{stream_read_exceptions=0} }}
2016-12-07 18:42:24,171 [Thread-1] DEBUG s3a.S3AFileSystem
(S3AFileSystem.java:innerMkdirs(1478)) - Making directory: /test
2016-12-07 18:42:24,171 [Thread-1] DEBUG s3a.S3AFileSystem
(S3AStorageStatistics.java:incrementCounter(60)) - op_mkdirs += 1 -> 1
2016-12-07 18:42:24,171 [Thread-1] DEBUG s3a.S3AFileSystem
(S3AStorageStatistics.java:incrementCounter(60)) - op_get_file_status += 1 ->
1
2016-12-07 18:42:24,172 [Thread-1] DEBUG s3a.S3AFileSystem
(S3AFileSystem.java:getFileStatus(1525)) - Getting path status for
s3a://hwdev-steve-ireland-new/test (test)
2016-12-07 18:42:24,172 [Thread-1] DEBUG s3a.S3AFileSystem
(S3AStorageStatistics.java:incrementCounter(60)) - object_metadata_requests +=
1 -> 1
2016-12-07 18:42:24,174 [Thread-1] DEBUG amazonaws.request
(AmazonHttpClient.java:executeOneRequest(1046)) - Sending Request: HEAD
https://hwdev-steve-ireland-new.s3-eu-west-1.amazonaws.com /test Headers:
(User-Agent: Hadoop 2.8.0-SNAPSHOT, aws-sdk-java/1.11.45 Mac_OS_X/10.12.1
Java_HotSpot(TM)_64-Bit_Server_VM/25.102-b14/1.8.0_102, amz-sdk-invocation-id:
57239941-1812-a15f-736a-f3da7727b192, Content-Type: application/octet-stream, )
2016-12-07 18:42:24,225 [Thread-1] DEBUG amazonaws.request
(AmazonHttpClient.java:handleErrorResponse(1497)) - Received error response:
com.amazonaws.services.s3.model.AmazonS3Exception: Not Found (Service: null;
Status Code: 404; Error Code: 404 Not Found; Request ID: 2B1E6AAB5BB13A50), S3
Extended Request ID:
37X2RRn7nQAt5RDTbO8jazu8ltPGdiUZ+OmvP0cPPtYaaoEGeI/qZ5sv4fEH3xFZOb+d5+wu/w4=
2016-12-07 18:42:24,225 [Thread-1] DEBUG s3a.S3AFileSystem
(S3AStorageStatistics.java:incrementCounter(60)) - object_metadata_requests +=
1 -> 2
2016-12-07 18:42:24,226 [Thread-1] DEBUG amazonaws.request
(AmazonHttpClient.java:executeOneRequest(1046)) - Sending Request: HEAD
https://hwdev-steve-ireland-new.s3-eu-west-1.amazonaws.com /test/ Headers:
(User-Agent: Hadoop 2.8.0-SNAPSHOT, aws-sdk-java/1.11.45 Mac_OS_X/10.12.1
Java_HotSpot(TM)_64-Bit_Server_VM/25.102-b14/1.8.0_102, amz-sdk-invocation-id:
52c578b8-6d85-49e9-d148-2db3079cc239, Content-Type: application/octet-stream, )
2016-12-07 18:42:24,274 [Thread-1] DEBUG amazonaws.request
(AmazonHttpClient.java:handleErrorResponse(1497)) - Received error response:
com.amazonaws.services.s3.model.AmazonS3Exception: Not Found (Service: null;
Status Code: 404; Error Code: 404 Not Found; Request ID: 4B7CD9CADDF086A7), S3
Extended Request ID:
9AR/mRdKgwAnb8SnWzLSqrM8K/DWFK1utzFqKXZihDtTN9UXPsxGFGN2GoBHgHNTqY41YBBptn8=
2016-12-07 18:42:24,274 [Thread-1] DEBUG s3a.S3AFileSystem
(S3AStorageStatistics.java:incrementCounter(60)) - object_list_requests += 1
-> 1
2016-12-07 18:42:24,289 [Thread-1] DEBUG amazonaws.request
(AmazonHttpClient.java:executeOneRequest(1046)) - Sending Request: GET
https://hwdev-steve-ireland-new.s3-eu-west-1.amazonaws.com / Parameters:
({"prefix":["test/"],"delimiter":["/"],"max-keys":["1"],"encoding-type":["url"]}Headers:
(User-Agent: Hadoop 2.8.0-SNAPSHOT, aws-sdk-java/1.11.45 Mac_OS_X/10.12.1
Java_HotSpot(TM)_64-Bit_Server_VM/25.102-b14/1.8.0_102, amz-sdk-invocation-id:
5cb39b7e-4fb2-5401-25d5-0fdc15db05ad, Content-Type: application/octet-stream, )
2016-12-07 18:42:24,364 [Thread-1] DEBUG amazonaws.request
(AwsResponseHandlerAdapter.java:handle(87)) - Received successful response:
200, AWS Request ID: A39D3AE5D27ABAC9
2016-12-07 18:42:24,365 [Thread-1] DEBUG amazonaws.request
(AwsResponseHandlerAdapter.java:logHeaderRequestId(138)) - x-amzn-RequestId:
not available
2016-12-07 18:42:24,365 [Thread-1] DEBUG amazonaws.request
(AwsResponseHandlerAdapter.java:logResponseRequestId(158)) - AWS Request ID:
A39D3AE5D27ABAC9
2016-12-07 18:42:24,365 [Thread-1] DEBUG s3a.S3AFileSystem
(S3AFileSystem.java:getFileStatus(1616)) - Not Found:
s3a://hwdev-steve-ireland-new/test
2016-12-07 18:42:24,365 [Thread-1] DEBUG s3a.S3AFileSystem
(S3AStorageStatistics.java:incrementCounter(60)) - op_get_file_status += 1 ->
2
2016-12-07 18:42:24,365 [Thread-1] DEBUG s3a.S3AFileSystem
(S3AFileSystem.java:getFileStatus(1525)) - Getting path status for
s3a://hwdev-steve-ireland-new/ ()
2016-12-07 18:42:24,365 [Thread-1] DEBUG s3a.S3AFileSystem
(S3AStorageStatistics.java:incrementCounter(60)) - object_list_requests += 1
-> 2
2016-12-07 18:42:24,366 [Thread-1] DEBUG amazonaws.request
(AmazonHttpClient.java:executeOneRequest(1046)) - Sending Request: GET
https://hwdev-steve-ireland-new.s3-eu-west-1.amazonaws.com / Parameters:
({"prefix":[""],"delimiter":["/"],"max-keys":["1"],"encoding-type":["url"]}Headers:
(User-Agent: Hadoop 2.8.0-SNAPSHOT, aws-sdk-java/1.11.45 Mac_OS_X/10.12.1
Java_HotSpot(TM)_64-Bit_Server_VM/25.102-b14/1.8.0_102, amz-sdk-invocation-id:
d68ca495-6dee-8f17-0ff8-008f25a75702, Content-Type: application/octet-stream, )
2016-12-07 18:42:24,426 [Thread-1] DEBUG amazonaws.request
(AwsResponseHandlerAdapter.java:handle(87)) - Received successful response:
200, AWS Request ID: 7169BE12EAD059C9
2016-12-07 18:42:24,426 [Thread-1] DEBUG amazonaws.request
(AwsResponseHandlerAdapter.java:logHeaderRequestId(138)) - x-amzn-RequestId:
not available
2016-12-07 18:42:24,426 [Thread-1] DEBUG amazonaws.request
(AwsResponseHandlerAdapter.java:logResponseRequestId(158)) - AWS Request ID:
7169BE12EAD059C9
2016-12-07 18:42:24,427 [Thread-1] DEBUG s3a.S3AFileSystem
(S3AFileSystem.java:getFileStatus(1591)) - Found path as directory (with /): 1/0
2016-12-07 18:42:24,427 [Thread-1] DEBUG s3a.S3AFileSystem
(S3AFileSystem.java:getFileStatus(1599)) - Prefix: Users/
2016-12-07 18:42:24,429 [Thread-1] DEBUG s3a.S3AFileSystem
(S3AFileSystem.java:incrementPutStartStatistics(1116)) - PUT start 0 bytes
2016-12-07 18:42:24,429 [Thread-1] DEBUG s3a.S3AFileSystem
(S3AStorageStatistics.java:incrementCounter(60)) - object_put_requests += 1 ->
1
2016-12-07 18:42:24,437 [Thread-1] DEBUG s3a.S3AFileSystem
(S3AFileSystem.java:incrementPutCompletedStatistics(1133)) - PUT completed
success=true; 0 bytes
2016-12-07 18:42:24,437 [Thread-1] DEBUG s3a.S3AFileSystem
(S3AStorageStatistics.java:incrementCounter(60)) -
object_put_requests_completed += 1 -> 1
2016-12-07 18:42:24,440 [s3a-transfer-shared-pool1-t1] DEBUG amazonaws.request
(AmazonHttpClient.java:executeOneRequest(1046)) - Sending Request: PUT
https://hwdev-steve-ireland-new.s3-eu-west-1.amazonaws.com /test/ Headers:
(User-Agent: Hadoop 2.8.0-SNAPSHOT, aws-sdk-java/1.11.45 Mac_OS_X/10.12.1
Java_HotSpot(TM)_64-Bit_Server_VM/25.102-b14/1.8.0_102
com.amazonaws.services.s3.transfer.TransferManager/1.11.45,
amz-sdk-invocation-id: fad23d78-a104-156a-81ed-f3e29d668cd8, Content-Length: 0,
Content-Type: application/octet-stream, )
2016-12-07 18:42:24,509 [s3a-transfer-shared-pool1-t1] DEBUG amazonaws.request
(AwsResponseHandlerAdapter.java:handle(87)) - Received successful response:
200, AWS Request ID: 1A25A7F6C78ED591
2016-12-07 18:42:24,509 [s3a-transfer-shared-pool1-t1] DEBUG amazonaws.request
(AwsResponseHandlerAdapter.java:logHeaderRequestId(138)) - x-amzn-RequestId:
not available
2016-12-07 18:42:24,509 [s3a-transfer-shared-pool1-t1] DEBUG amazonaws.request
(AwsResponseHandlerAdapter.java:logResponseRequestId(158)) - AWS Request ID:
1A25A7F6C78ED591
2016-12-07 18:42:24,514 [Thread-1] DEBUG S3AFileSystem.Progress
(S3AFileSystem.java:incrementPutProgressStatistics(1151)) - PUT test/: 0 bytes
2016-12-07 18:42:24,514 [Thread-1] DEBUG scale.S3AScaleTestBase
(S3AScaleTestBase.java:setup(94)) - Scale test operation count = 1
2016-12-07 18:42:24,516 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
s3a.S3AFileSystem (S3ClientFactory.java:initUserAgent(187)) - Using User-Agent:
Hadoop 2.8.0-SNAPSHOT
2016-12-07 18:42:24,519 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
s3a.AWSCredentialProviderList
(AWSCredentialProviderList.java:getCredentials(134)) - Using credentials from
BasicAWSCredentialsProvider
2016-12-07 18:42:24,520 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
amazonaws.request (AmazonHttpClient.java:executeOneRequest(1046)) - Sending
Request: HEAD https://landsat-pds.s3-us-west-1.amazonaws.com / Headers:
(User-Agent: Hadoop 2.8.0-SNAPSHOT, aws-sdk-java/1.11.45 Mac_OS_X/10.12.1
Java_HotSpot(TM)_64-Bit_Server_VM/25.102-b14/1.8.0_102, amz-sdk-invocation-id:
40808c03-5cf7-c960-4c97-353313df657b, Content-Type: application/octet-stream, )
2016-12-07 18:42:25,338 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
amazonaws.request (AmazonHttpClient.java:handleErrorResponse(1497)) - Received
error response: com.amazonaws.services.s3.model.AmazonS3Exception: Moved
Permanently (Service: null; Status Code: 301; Error Code: 301 Moved
Permanently; Request ID: 58DECB0934A6428C), S3 Extended Request ID:
QQxGx+1eyQEbD/skrLYpaXg+XuW8EvgwtCkpqqTJttl/ONjzD1xC1jVX6IqFCQZdfrSsup85pTM=
2016-12-07 18:42:25,339 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
amazonaws.request (AmazonHttpClient.java:executeOneRequest(1046)) - Sending
Request: HEAD https://landsat-pds.s3-us-west-2.amazonaws.com / Headers:
(User-Agent: Hadoop 2.8.0-SNAPSHOT, aws-sdk-java/1.11.45 Mac_OS_X/10.12.1
Java_HotSpot(TM)_64-Bit_Server_VM/25.102-b14/1.8.0_102, amz-sdk-invocation-id:
5eb0baa1-d0f0-1825-27c1-4c122afb0d72, Content-Type: application/octet-stream, )
2016-12-07 18:42:26,225 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
amazonaws.request (AwsResponseHandlerAdapter.java:handle(87)) - Received
successful response: 200, AWS Request ID: null
2016-12-07 18:42:26,225 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
amazonaws.request (AwsResponseHandlerAdapter.java:logHeaderRequestId(138)) -
x-amzn-RequestId: not available
2016-12-07 18:42:26,225 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
amazonaws.request (AwsResponseHandlerAdapter.java:logResponseRequestId(158)) -
AWS Request ID: not available
2016-12-07 18:42:26,226 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
s3a.S3AFileSystem (S3AFileSystem.java:initialize(225)) - Using encryption null
2016-12-07 18:42:26,226 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
s3a.S3AFileSystem (S3AFileSystem.java:initialize(238)) - Using
S3ABlockOutputStream with buffer = disk; block=8000000; queue limit=4
2016-12-07 18:42:26,226 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
s3a.S3AFileSystem (S3AStorageStatistics.java:incrementCounter(60)) -
op_get_file_status += 1 -> 3
2016-12-07 18:42:26,226 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
s3a.S3AFileSystem (S3AFileSystem.java:getFileStatus(1525)) - Getting path
status for s3a://landsat-pds/scene_list.gz (scene_list.gz)
2016-12-07 18:42:26,226 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
s3a.S3AFileSystem (S3AStorageStatistics.java:incrementCounter(60)) -
object_metadata_requests += 1 -> 3
2016-12-07 18:42:26,227 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
amazonaws.request (AmazonHttpClient.java:executeOneRequest(1046)) - Sending
Request: HEAD https://landsat-pds.s3-us-west-2.amazonaws.com /scene_list.gz
Headers: (User-Agent: Hadoop 2.8.0-SNAPSHOT, aws-sdk-java/1.11.45
Mac_OS_X/10.12.1 Java_HotSpot(TM)_64-Bit_Server_VM/25.102-b14/1.8.0_102,
amz-sdk-invocation-id: 33d34c3d-ead9-809a-af05-257b905fede7, Content-Type:
application/octet-stream, )
2016-12-07 18:42:26,788 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
amazonaws.request (AwsResponseHandlerAdapter.java:handle(87)) - Received
successful response: 200, AWS Request ID: C756074918F8BAB1
2016-12-07 18:42:26,788 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
amazonaws.request (AwsResponseHandlerAdapter.java:logHeaderRequestId(138)) -
x-amzn-RequestId: not available
2016-12-07 18:42:26,788 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
amazonaws.request (AwsResponseHandlerAdapter.java:logResponseRequestId(158)) -
AWS Request ID: C756074918F8BAB1
2016-12-07 18:42:26,788 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
s3a.S3AFileSystem (S3AFileSystem.java:getFileStatus(1534)) - Found exact file:
normal file
2016-12-07 18:42:26,789 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
s3a.AbstractS3ATestBase (AbstractS3ATestBase.java:describe(87)) -
testTimeToOpenAndReadWholeFileBlocks: Open the test file
s3a://landsat-pds/scene_list.gz and read it in blocks of size 1048576
2016-12-07 18:42:26,789 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
s3a.S3AFileSystem (S3AFileSystem.java:setInputPolicy(413)) - Setting input
strategy: normal
2016-12-07 18:42:26,789 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
s3a.S3AFileSystem (S3AFileSystem.java:open(503)) - Opening
's3a://landsat-pds/scene_list.gz' for reading.
2016-12-07 18:42:26,789 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
s3a.S3AFileSystem (S3AStorageStatistics.java:incrementCounter(60)) -
op_get_file_status += 1 -> 4
2016-12-07 18:42:26,789 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
s3a.S3AFileSystem (S3AFileSystem.java:getFileStatus(1525)) - Getting path
status for s3a://landsat-pds/scene_list.gz (scene_list.gz)
2016-12-07 18:42:26,789 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
s3a.S3AFileSystem (S3AStorageStatistics.java:incrementCounter(60)) -
object_metadata_requests += 1 -> 4
2016-12-07 18:42:26,790 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
amazonaws.request (AmazonHttpClient.java:executeOneRequest(1046)) - Sending
Request: HEAD https://landsat-pds.s3-us-west-2.amazonaws.com /scene_list.gz
Headers: (User-Agent: Hadoop 2.8.0-SNAPSHOT, aws-sdk-java/1.11.45
Mac_OS_X/10.12.1 Java_HotSpot(TM)_64-Bit_Server_VM/25.102-b14/1.8.0_102,
amz-sdk-invocation-id: 5d20098b-a1cc-a15d-7cf6-959355ceda8c, Content-Type:
application/octet-stream, )
2016-12-07 18:42:26,965 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
amazonaws.request (AwsResponseHandlerAdapter.java:handle(87)) - Received
successful response: 200, AWS Request ID: 48BD932265D2E504
2016-12-07 18:42:26,965 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
amazonaws.request (AwsResponseHandlerAdapter.java:logHeaderRequestId(138)) -
x-amzn-RequestId: not available
2016-12-07 18:42:26,965 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
amazonaws.request (AwsResponseHandlerAdapter.java:logResponseRequestId(158)) -
AWS Request ID: 48BD932265D2E504
2016-12-07 18:42:26,965 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
s3a.S3AFileSystem (S3AFileSystem.java:getFileStatus(1534)) - Found exact file:
normal file
2016-12-07 18:42:26,967 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
s3a.S3AFileSystem (S3AFileSystem.java:setInputPolicy(413)) - Setting input
strategy: normal
2016-12-07 18:42:26,967 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
s3a.S3AFileSystem (S3AInputStream.java:reopen(140)) -
reopen(s3a://landsat-pds/scene_list.gz) for read from new offset
range[0-38939342], length=1048576, streamPosition=0, nextReadPosition=0
2016-12-07 18:42:26,969 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
amazonaws.request (AmazonHttpClient.java:executeOneRequest(1046)) - Sending
Request: GET https://landsat-pds.s3-us-west-2.amazonaws.com /scene_list.gz
Headers: (User-Agent: Hadoop 2.8.0-SNAPSHOT, aws-sdk-java/1.11.45
Mac_OS_X/10.12.1 Java_HotSpot(TM)_64-Bit_Server_VM/25.102-b14/1.8.0_102,
amz-sdk-invocation-id: 6489ce83-1f56-b833-15dc-f78d8eed429f, Range:
bytes=0-38939342, Content-Type: application/octet-stream, )
2016-12-07 18:42:27,168 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
amazonaws.request (AwsResponseHandlerAdapter.java:handle(87)) - Received
successful response: 206, AWS Request ID: 7BB5413C293FE587
2016-12-07 18:42:27,168 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
amazonaws.request (AwsResponseHandlerAdapter.java:logHeaderRequestId(138)) -
x-amzn-RequestId: not available
2016-12-07 18:42:27,168 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
amazonaws.request (AwsResponseHandlerAdapter.java:logResponseRequestId(158)) -
AWS Request ID: 7BB5413C293FE587
2016-12-07 18:43:32,677 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 0 in 121 reads: 65,708,704,300 nS
2016-12-07 18:44:50,868 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 1 in 121 reads: 78,191,068,156 nS
2016-12-07 18:48:57,544 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
s3a.S3AFileSystem (S3AInputStream.java:onReadFailure(334)) - Got exception
while trying to read from stream s3a://landsat-pds/scene_list.gz trying to
recover: java.net.SocketTimeoutException: Read timed out
2016-12-07 18:48:57,546 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
s3a.S3AFileSystem (S3AInputStream.java:onReadFailure(336)) - While trying to
read from stream s3a://landsat-pds/scene_list.gz
java.net.SocketTimeoutException: Read timed out
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
at java.net.SocketInputStream.read(SocketInputStream.java:170)
at java.net.SocketInputStream.read(SocketInputStream.java:141)
at sun.security.ssl.InputRecord.readFully(InputRecord.java:465)
at sun.security.ssl.InputRecord.readV3Record(InputRecord.java:593)
at sun.security.ssl.InputRecord.read(InputRecord.java:532)
at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:973)
at sun.security.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:930)
at sun.security.ssl.AppInputStream.read(AppInputStream.java:105)
at
org.apache.http.impl.io.SessionInputBufferImpl.streamRead(SessionInputBufferImpl.java:139)
at
org.apache.http.impl.io.SessionInputBufferImpl.read(SessionInputBufferImpl.java:200)
at
org.apache.http.impl.io.ContentLengthInputStream.read(ContentLengthInputStream.java:178)
at
org.apache.http.conn.EofSensorInputStream.read(EofSensorInputStream.java:137)
at
com.amazonaws.internal.SdkFilterInputStream.read(SdkFilterInputStream.java:72)
at
com.amazonaws.event.ProgressInputStream.read(ProgressInputStream.java:181)
at
com.amazonaws.internal.SdkFilterInputStream.read(SdkFilterInputStream.java:72)
at
com.amazonaws.services.s3.model.S3ObjectInputStream.read(S3ObjectInputStream.java:155)
at
com.amazonaws.internal.SdkFilterInputStream.read(SdkFilterInputStream.java:72)
at
com.amazonaws.internal.SdkFilterInputStream.read(SdkFilterInputStream.java:72)
at
com.amazonaws.event.ProgressInputStream.read(ProgressInputStream.java:181)
at
com.amazonaws.internal.SdkFilterInputStream.read(SdkFilterInputStream.java:72)
at
com.amazonaws.util.LengthCheckInputStream.read(LengthCheckInputStream.java:108)
at
com.amazonaws.internal.SdkFilterInputStream.read(SdkFilterInputStream.java:72)
at
com.amazonaws.services.s3.model.S3ObjectInputStream.read(S3ObjectInputStream.java:155)
at org.apache.hadoop.fs.s3a.S3AInputStream.read(S3AInputStream.java:373)
at java.io.DataInputStream.read(DataInputStream.java:149)
at
org.apache.hadoop.fs.s3a.scale.ITestS3AInputStreamPerformance.testTimeToOpenAndReadWholeFileBlocks(ITestS3AInputStreamPerformance.java:225)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at
org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:47)
at
org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
at
org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:44)
at
org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
at
org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
at
org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
at org.junit.rules.TestWatcher$1.evaluate(TestWatcher.java:55)
at
org.junit.internal.runners.statements.FailOnTimeout$StatementThread.run(FailOnTimeout.java:74)
2016-12-07 18:48:57,550 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
s3a.S3AFileSystem (S3AInputStream.java:closeStream(463)) - Stream
s3a://landsat-pds/scene_list.gz aborted: reopen(failure recovery);
streamPos=2575953, nextReadPos=2575953, request range 0-38939342 length=38939342
2016-12-07 18:48:57,550 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
s3a.S3AFileSystem (S3AInputStream.java:reopen(140)) -
reopen(s3a://landsat-pds/scene_list.gz) for failure recovery
range[2575953-38939342], length=569775, streamPosition=2575953,
nextReadPosition=2575953
2016-12-07 18:48:57,554 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
amazonaws.request (AmazonHttpClient.java:executeOneRequest(1046)) - Sending
Request: GET https://landsat-pds.s3-us-west-2.amazonaws.com /scene_list.gz
Headers: (User-Agent: Hadoop 2.8.0-SNAPSHOT, aws-sdk-java/1.11.45
Mac_OS_X/10.12.1 Java_HotSpot(TM)_64-Bit_Server_VM/25.102-b14/1.8.0_102,
amz-sdk-invocation-id: 4ae4b351-3374-49e5-fa73-81cff322f56c, Range:
bytes=2575953-38939342, Content-Type: application/octet-stream, )
2016-12-07 18:48:58,358 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
amazonaws.request (AwsResponseHandlerAdapter.java:handle(87)) - Received
successful response: 206, AWS Request ID: 773084E647B9C370
2016-12-07 18:48:58,359 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
amazonaws.request (AwsResponseHandlerAdapter.java:logHeaderRequestId(138)) -
x-amzn-RequestId: not available
2016-12-07 18:48:58,359 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
amazonaws.request (AwsResponseHandlerAdapter.java:logResponseRequestId(158)) -
AWS Request ID: 773084E647B9C370
2016-12-07 18:48:59,397 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 2 in 121 reads: 248,531,807,139 nS
2016-12-07 18:48:59,988 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 3 in 122 reads: 590,226,556 nS
2016-12-07 18:49:00,346 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 4 in 122 reads: 357,777,268 nS
2016-12-07 18:49:00,635 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 5 in 121 reads: 288,089,615 nS
2016-12-07 18:49:00,869 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 6 in 89 reads: 233,918,422 nS
2016-12-07 18:49:01,094 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 7 in 69 reads: 224,188,050 nS
2016-12-07 18:49:01,270 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 8 in 69 reads: 175,089,680 nS
2016-12-07 18:49:01,508 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 9 in 69 reads: 237,915,953 nS
2016-12-07 18:49:03,203 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 10 in 69 reads: 1,694,581,186 nS
2016-12-07 18:49:03,562 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 11 in 69 reads: 358,629,013 nS
2016-12-07 18:49:03,814 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 12 in 69 reads: 251,512,010 nS
2016-12-07 18:49:04,080 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 13 in 69 reads: 265,251,582 nS
2016-12-07 18:49:04,284 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 14 in 69 reads: 203,401,204 nS
2016-12-07 18:49:04,488 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 15 in 69 reads: 203,355,837 nS
2016-12-07 18:49:04,682 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 16 in 69 reads: 193,974,256 nS
2016-12-07 18:49:04,902 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 17 in 69 reads: 219,901,121 nS
2016-12-07 18:49:05,089 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 18 in 69 reads: 186,285,604 nS
2016-12-07 18:49:05,323 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 19 in 69 reads: 233,165,569 nS
2016-12-07 18:49:06,021 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 20 in 69 reads: 698,049,891 nS
2016-12-07 18:49:06,350 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 21 in 69 reads: 328,816,127 nS
2016-12-07 18:49:06,571 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 22 in 69 reads: 220,920,300 nS
2016-12-07 18:49:06,785 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 23 in 69 reads: 213,269,165 nS
2016-12-07 18:49:07,044 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 24 in 69 reads: 258,383,769 nS
2016-12-07 18:49:07,260 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 25 in 69 reads: 215,997,541 nS
2016-12-07 18:49:07,472 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 26 in 69 reads: 210,871,191 nS
2016-12-07 18:49:07,675 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 27 in 69 reads: 203,160,739 nS
2016-12-07 18:49:07,905 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 28 in 69 reads: 229,260,978 nS
2016-12-07 18:49:08,107 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 29 in 69 reads: 202,102,165 nS
2016-12-07 18:49:08,387 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 30 in 69 reads: 279,023,912 nS
2016-12-07 18:49:08,751 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 31 in 69 reads: 363,367,889 nS
2016-12-07 18:49:09,066 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 32 in 69 reads: 315,399,466 nS
2016-12-07 18:49:09,312 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 33 in 69 reads: 245,392,893 nS
2016-12-07 18:49:09,566 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 34 in 69 reads: 253,079,462 nS
2016-12-07 18:49:09,813 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 35 in 69 reads: 246,456,730 nS
2016-12-07 18:49:10,093 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Reading block 36 in 69 reads: 279,688,361 nS
2016-12-07 18:49:10,093 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:end(1441)) - Duration of
Time to read 38939342 bytes in 37 blocks: 403,130,941,090 nS
2016-12-07 18:49:10,094 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.ContractTestUtils (ContractTestUtils.java:bandwidth(963)) - Bandwidth
= 0.091782 MB/S
2016-12-07 18:49:10,095 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
scale.ITestS3AInputStreamPerformance
(ITestS3AInputStreamPerformance.java:logStreamStatistics(324)) - Stream
Statistics
StreamStatistics{OpenOperations=2, CloseOperations=1, Closed=0, Aborted=1,
SeekOperations=0, ReadExceptions=1, ForwardSeekOperations=0,
BackwardSeekOperations=0, BytesSkippedOnSeek=0, BytesBackwardsOnSeek=0,
BytesRead=38797312, BytesRead excluding skipped=38797312, ReadOperations=2887,
ReadFullyOperations=0, ReadsIncomplete=2850, BytesReadInClose=0,
BytesDiscardedInAbort=36363389}
2016-12-07 18:49:10,095 [JUnit-testTimeToOpenAndReadWholeFileBlocks] INFO
contract.AbstractFSContractTestBase
(AbstractFSContractTestBase.java:describe(255)) - cleanup
2016-12-07 18:49:10,096 [JUnit-testTimeToOpenAndReadWholeFileBlocks] DEBUG
s3a.S3AFileSystem (S3AInputStream.java:closeStream(463)) - Stream
s3a://landsat-pds/scene_list.gz aborted: close() operation; streamPos=38797312,
nextReadPos=38797312, request range 2575953-38939342 length=38939342
{code]
> ITestS3AInputStreamPerformance.testTimeToOpenAndReadWholeFileBlocks
> performance on branch-2.8 awful
> ---------------------------------------------------------------------------------------------------
>
> Key: HADOOP-13871
> URL: https://issues.apache.org/jira/browse/HADOOP-13871
> Project: Hadoop Common
> Issue Type: Sub-task
> Components: fs/s3
> Affects Versions: 2.8.0
> Environment: landsat bucket from the UK
> Reporter: Steve Loughran
> Assignee: Steve Loughran
>
> The ITestS3AInputStreamPerformance.testTimeToOpenAndReadWholeFileBlocks takes
> 15s on branch-2, but is now taking minutes on branch-2.8.
> This is a regression, and it's surfacing on some internal branches too. Even
> where the code hasn't changed. It does not happen on branch-2, which has a
> later SDK.
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
---------------------------------------------------------------------
To unsubscribe, e-mail: common-issues-unsubscr...@hadoop.apache.org
For additional commands, e-mail: common-issues-h...@hadoop.apache.org
