You are viewing a plain text version of this content. The canonical link for it is here.
Posted to common-issues@hadoop.apache.org by "steveloughran (via GitHub)" <gi...@apache.org> on 2024/04/24 15:00:31 UTC
Re: [PR] HADOOP-18184. S3A Prefetching unbuffer. [hadoop]
steveloughran commented on PR #5832:
URL: https://github.com/apache/hadoop/pull/5832#issuecomment-2075157859
There's some race condition with the list add/evict causing intermittent failures of one of the tests. Looks like the failure condition is
* block has just been evicted
* read() says block is in cache
* read is attempted
* read fails with FNFE.
Suspect there's some kind of list update issue.
Improved logging but not yet fixed this.
```
2024-04-24 15:57:22,711 [setup] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:initializeClass(5724)) - Initialize S3A class
2024-04-24 15:57:22,734 [setup] DEBUG s3a.S3ATestUtils (S3ATestUtils.java:removeBucketOverrides(914)) - Removing option fs.s3a.bucket.stevel-london.directory.marker.retention; was keep
2024-04-24 15:57:22,757 [setup] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:initializeClass(5724)) - Initialize S3A class
2024-04-24 15:57:22,771 [setup] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:initialize(549)) - Initializing S3AFileSystem for stevel-london
2024-04-24 15:57:22,774 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:propagateBucketOptions(1103)) - Propagating entries under fs.s3a.bucket.stevel-london.
2024-04-24 15:57:22,777 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:propagateBucketOptions(1124)) - Updating fs.s3a.versioned.store from [core-site.xml]
2024-04-24 15:57:22,777 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:propagateBucketOptions(1124)) - Updating fs.s3a.encryption.algorithm from [core-site.xml]
2024-04-24 15:57:22,777 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:propagateBucketOptions(1124)) - Updating fs.s3a.endpoint from [core-site.xml]
2024-04-24 15:57:22,777 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:propagateBucketOptions(1124)) - Updating fs.s3a.encryption.key from [core-site.xml]
2024-04-24 15:57:22,777 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:propagateBucketOptions(1124)) - Updating fs.s3a.change.detection.source from [core-site.xml]
2024-04-24 15:57:22,778 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:maybeIsolateClassloader(1708)) - Configuration classloader set to S3AFileSystem classloader: sun.misc.Launcher$AppClassLoader@18b4aac2
2024-04-24 15:57:22,783 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:buildEncryptionSecrets(1477)) - Using SSE-KMS with key of length 75 ending with 3
2024-04-24 15:57:22,784 [setup] DEBUG s3a.S3ARetryPolicy (S3ARetryPolicy.java:<init>(145)) - Retrying on recoverable AWS failures 3 times with an initial interval of 500ms
2024-04-24 15:57:22,911 [setup] DEBUG s3a.S3AInstrumentation (S3AInstrumentation.java:getMetricsSystem(254)) - Metrics system inited org.apache.hadoop.metrics2.impl.MetricsSystemImpl@6425ab69
2024-04-24 15:57:22,917 [setup] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:initialize(605)) - Client Side Encryption enabled: false
2024-04-24 15:57:22,917 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:intOption(909)) - Value of fs.s3a.paging.maximum is 5000
2024-04-24 15:57:22,917 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:longBytesOption(952)) - Value of fs.s3a.block.size is 33554432
2024-04-24 15:57:22,918 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:longBytesOption(952)) - Value of fs.s3a.prefetch.block.size is 131072
2024-04-24 15:57:22,918 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:intOption(909)) - Value of fs.s3a.prefetch.block.count is 8
2024-04-24 15:57:22,918 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:intOption(909)) - Value of fs.s3a.max.total.tasks is 32
2024-04-24 15:57:22,920 [setup] DEBUG impl.ConfigurationHelper (ConfigurationHelper.java:getDuration(80)) - Duration of fs.s3a.threads.keepalivetime = PT1M
2024-04-24 15:57:22,920 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:intOption(909)) - Value of fs.s3a.executor.capacity is 16
2024-04-24 15:57:22,937 [setup] DEBUG auth.SignerManager (SignerManager.java:initCustomSigners(68)) - No custom signers specified
2024-04-24 15:57:22,940 [setup] DEBUG audit.AuditIntegration (AuditIntegration.java:createAndInitAuditor(109)) - Auditor class is class org.apache.hadoop.fs.s3a.audit.impl.LoggingAuditor
2024-04-24 15:57:22,943 [setup] DEBUG impl.ActiveAuditManagerS3A (ActiveAuditManagerS3A.java:serviceInit(199)) - Audit manager initialized with audit service LoggingAuditor{ID='0d643328-91f6-4da7-acae-86fd72161299', headerEnabled=true, rejectOutOfSpan=true, isMultipartUploadEnabled=true}
2024-04-24 15:57:22,943 [setup] DEBUG impl.ActiveAuditManagerS3A (ActiveAuditManagerS3A.java:serviceStart(212)) - Started audit service LoggingAuditor{ID='0d643328-91f6-4da7-acae-86fd72161299', headerEnabled=true, rejectOutOfSpan=true, isMultipartUploadEnabled=true}
2024-04-24 15:57:22,943 [setup] DEBUG audit.AuditIntegration (AuditIntegration.java:createAndStartAuditManager(76)) - Started Audit Manager Service ActiveAuditManagerS3A in state ActiveAuditManagerS3A: STARTED, auditor=LoggingAuditor{ID='0d643328-91f6-4da7-acae-86fd72161299', headerEnabled=true, rejectOutOfSpan=true, isMultipartUploadEnabled=true}}
2024-04-24 15:57:22,944 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:longOption(930)) - Value of fs.s3a.internal.upload.part.count.limit is 10000
2024-04-24 15:57:22,944 [setup] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:createRequestFactory(1202)) - Unset storage class property fs.s3a.create.storage.class; falling back to default storage class
2024-04-24 15:57:22,949 [setup] DEBUG auth.CredentialProviderListFactory (CredentialProviderListFactory.java:createAWSV2CredentialProvider(306)) - Credential provider class is org.apache.hadoop.fs.s3a.TemporaryAWSCredentialsProvider
2024-04-24 15:57:22,949 [setup] DEBUG auth.CredentialProviderListFactory (CredentialProviderListFactory.java:createAWSV2CredentialProvider(306)) - Credential provider class is org.apache.hadoop.fs.s3a.SimpleAWSCredentialsProvider
2024-04-24 15:57:22,950 [setup] DEBUG auth.CredentialProviderListFactory (CredentialProviderListFactory.java:createAWSCredentialProviderList(151)) - For URI s3a://stevel-london/, using credentials AWSCredentialProviderList name=; refcount= 1; size=2: [TemporaryAWSCredentialsProvider, SimpleAWSCredentialsProvider{accessKey.empty=false, secretKey.empty=false}]
2024-04-24 15:57:22,950 [setup] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:bindAWSClient(1047)) - Using credential provider AWSCredentialProviderList name=; refcount= 1; size=2: [TemporaryAWSCredentialsProvider, SimpleAWSCredentialsProvider{accessKey.empty=false, secretKey.empty=false}]
2024-04-24 15:57:22,952 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:intOption(909)) - Value of fs.s3a.connection.maximum is 512
2024-04-24 15:57:22,952 [setup] DEBUG impl.ConfigurationHelper (ConfigurationHelper.java:getDuration(80)) - Duration of fs.s3a.connection.acquisition.timeout = PT1M
2024-04-24 15:57:22,952 [setup] DEBUG impl.ConfigurationHelper (ConfigurationHelper.java:getDuration(80)) - Duration of fs.s3a.connection.ttl = PT5M
2024-04-24 15:57:22,952 [setup] DEBUG impl.ConfigurationHelper (ConfigurationHelper.java:getDuration(80)) - Duration of fs.s3a.connection.establish.timeout = PT30S
2024-04-24 15:57:22,952 [setup] DEBUG impl.ConfigurationHelper (ConfigurationHelper.java:getDuration(80)) - Duration of fs.s3a.connection.idle.time = PT1M
2024-04-24 15:57:22,952 [setup] DEBUG impl.ConfigurationHelper (ConfigurationHelper.java:getDuration(80)) - Duration of fs.s3a.connection.timeout = PT25S
2024-04-24 15:57:23,085 [setup] DEBUG s3a.DefaultS3ClientFactory (DefaultS3ClientFactory.java:getS3RegionFromEndpoint(397)) - Endpoint s3.eu-west-2.amazonaws.com is not the default; parsing
2024-04-24 15:57:23,090 [setup] DEBUG s3a.DefaultS3ClientFactory (DefaultS3ClientFactory.java:configureEndpointAndRegion(326)) - Setting endpoint to https://s3.eu-west-2.amazonaws.com
2024-04-24 15:57:23,091 [setup] DEBUG s3a.DefaultS3ClientFactory (DefaultS3ClientFactory.java:configureEndpointAndRegion(353)) - Setting region to eu-west-2 from endpoint
2024-04-24 15:57:23,091 [setup] DEBUG s3a.DefaultS3ClientFactory (DefaultS3ClientFactory.java:maybeApplyS3AccessGrantsConfigurations(419)) - S3 Access Grants plugin is not enabled.
2024-04-24 15:57:23,095 [setup] DEBUG impl.ConfigurationHelper (ConfigurationHelper.java:getDuration(80)) - Duration of fs.s3a.connection.request.timeout = PT1M
2024-04-24 15:57:23,097 [setup] DEBUG impl.AWSClientConfig (AWSClientConfig.java:initUserAgent(375)) - Using User-Agent: Hadoop 3.5.0-SNAPSHOT
2024-04-24 15:57:23,105 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:intOption(909)) - Value of fs.s3a.attempts.maximum is 2
2024-04-24 15:57:23,407 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:intOption(909)) - Value of fs.s3a.connection.maximum is 512
2024-04-24 15:57:23,407 [setup] DEBUG impl.ConfigurationHelper (ConfigurationHelper.java:getDuration(80)) - Duration of fs.s3a.connection.acquisition.timeout = PT1M
2024-04-24 15:57:23,408 [setup] DEBUG impl.ConfigurationHelper (ConfigurationHelper.java:getDuration(80)) - Duration of fs.s3a.connection.ttl = PT5M
2024-04-24 15:57:23,408 [setup] DEBUG impl.ConfigurationHelper (ConfigurationHelper.java:getDuration(80)) - Duration of fs.s3a.connection.establish.timeout = PT30S
2024-04-24 15:57:23,408 [setup] DEBUG impl.ConfigurationHelper (ConfigurationHelper.java:getDuration(80)) - Duration of fs.s3a.connection.idle.time = PT1M
2024-04-24 15:57:23,408 [setup] DEBUG impl.ConfigurationHelper (ConfigurationHelper.java:getDuration(80)) - Duration of fs.s3a.connection.timeout = PT25S
2024-04-24 15:57:23,430 [setup] DEBUG s3a.DefaultS3ClientFactory (DefaultS3ClientFactory.java:getS3RegionFromEndpoint(397)) - Endpoint s3.eu-west-2.amazonaws.com is not the default; parsing
2024-04-24 15:57:23,430 [setup] DEBUG s3a.DefaultS3ClientFactory (DefaultS3ClientFactory.java:configureEndpointAndRegion(326)) - Setting endpoint to https://s3.eu-west-2.amazonaws.com
2024-04-24 15:57:23,430 [setup] DEBUG s3a.DefaultS3ClientFactory (DefaultS3ClientFactory.java:configureEndpointAndRegion(353)) - Setting region to eu-west-2 from endpoint
2024-04-24 15:57:23,430 [setup] DEBUG s3a.DefaultS3ClientFactory (DefaultS3ClientFactory.java:maybeApplyS3AccessGrantsConfigurations(419)) - S3 Access Grants plugin is not enabled.
2024-04-24 15:57:23,430 [setup] DEBUG impl.ConfigurationHelper (ConfigurationHelper.java:getDuration(80)) - Duration of fs.s3a.connection.request.timeout = PT1M
2024-04-24 15:57:23,430 [setup] DEBUG impl.AWSClientConfig (AWSClientConfig.java:initUserAgent(375)) - Using User-Agent: Hadoop 3.5.0-SNAPSHOT
2024-04-24 15:57:23,431 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:intOption(909)) - Value of fs.s3a.attempts.maximum is 2
2024-04-24 15:57:23,512 [setup] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:doBucketProbing(831)) - skipping check for bucket existence
2024-04-24 15:57:23,513 [setup] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:initialize(696)) - Input fadvise policy = default
2024-04-24 15:57:23,514 [setup] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:initialize(698)) - Change detection policy = VersionIdChangeDetectionPolicy mode=Server
2024-04-24 15:57:23,514 [setup] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:initialize(702)) - Filesystem support for magic committers is enabled
2024-04-24 15:57:23,516 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:intOption(909)) - Value of fs.s3a.fast.upload.active.blocks is 4
2024-04-24 15:57:23,517 [setup] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:initialize(721)) - Using S3ABlockOutputStream with buffer = disk; block=67108864; queue limit=4; multipart=true
2024-04-24 15:57:23,517 [setup] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:initialize(731)) - fs.s3a.create.performance = false
2024-04-24 15:57:23,518 [setup] DEBUG impl.DirectoryPolicyImpl (DirectoryPolicyImpl.java:getDirectoryPolicy(189)) - Directory markers will be kept
2024-04-24 15:57:23,518 [setup] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:initialize(737)) - Directory marker retention policy is DirectoryMarkerRetention{policy='keep'}
2024-04-24 15:57:23,518 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:intOption(909)) - Value of fs.s3a.bulk.delete.page.size is 250
2024-04-24 15:57:23,519 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:longBytesOption(952)) - Value of fs.s3a.readahead.range is 32768
2024-04-24 15:57:23,519 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:intOption(909)) - Value of io.file.buffer.size is 4194304
2024-04-24 15:57:23,519 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:longBytesOption(952)) - Value of fs.s3a.input.async.drain.threshold is 1024
2024-04-24 15:57:23,519 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:intOption(909)) - Value of fs.s3a.vectored.active.ranged.reads is 4
2024-04-24 15:57:23,519 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:longBytesOption(952)) - Value of fs.s3a.vectored.read.min.seek.size is 4096
2024-04-24 15:57:23,519 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:longBytesOption(952)) - Value of fs.s3a.vectored.read.max.merged.size is 1048576
2024-04-24 15:57:23,520 [setup] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:initialize(763)) - Using optimized copyFromLocal implementation: true
2024-04-24 15:57:23,529 [setup] INFO contract.AbstractFSContractTestBase (AbstractFSContractTestBase.java:setup(196)) - Test filesystem = s3a://stevel-london implemented by S3AFileSystem{uri=s3a://stevel-london, workingDir=s3a://stevel-london/user/stevel, partSize=67108864, enableMultiObjectsDelete=true, maxKeys=5000, OpenFileSupport{changePolicy=VersionIdChangeDetectionPolicy mode=Server, defaultReadAhead=32768, defaultBufferSize=4194304, defaultAsyncDrainThreshold=1024, defaultInputPolicy=default}, blockSize=33554432, multiPartThreshold=134217728, s3EncryptionAlgorithm='SSE_KMS', blockFactory=org.apache.hadoop.fs.s3a.S3ADataBlocks$DiskBlockFactory@1fea9f7c, auditManager=Service ActiveAuditManagerS3A in state ActiveAuditManagerS3A: STARTED, auditor=LoggingAuditor{ID='0d643328-91f6-4da7-acae-86fd72161299', headerEnabled=true, rejectOutOfSpan=true, isMultipartUploadEnabled=true}}, authoritativePath=[], useListV1=false, magicCommitter=true, boundedExecutor=BlockingThreadPoolExecuto
rService{SemaphoredDelegatingExecutor{permitCount=200, available=200, waiting=0}, activeCount=0}, unboundedExecutor=java.util.concurrent.ThreadPoolExecutor@78d0d3c0[Running, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 0], credentials=AWSCredentialProviderList name=; refcount= 1; size=2: [TemporaryAWSCredentialsProvider, SimpleAWSCredentialsProvider{accessKey.empty=false, secretKey.empty=false}], delegation tokens=disabled, DirectoryMarkerRetention{policy='keep'}, instrumentation {S3AInstrumentation{instanceIOStatistics=counters=((op_get_delegation_token.failures=0) (committer_commits_completed=0) (stream_read_bytes_discarded_in_close=0) (stream_write_queue_duration.failures=0) (stream_read_vectored_operations=0) (delegation_tokens_issued=0) (stream_read_total_bytes=0) (store_exists_probe.failures=0) (stream_write_exceptions_completing_upload=0) (stream_read_seek_operations=0) (op_mkdirs=0) (committer_commits_created=0) (object_put_request_completed=0) (dir
ectories_created=0) (op_hflush=0) (stream_write_block_uploads_aborted=0) (op_get_file_status.failures=0) (object_multipart_initiated=0) (committer_magic_marker_put.failures=0) (op_exists=0) (stream_read_seek_forward_operations=0) (committer_commits_aborted=0) (object_continue_list_request=0) (op_is_directory=0) (audit_access_check_failure=0) (committer_commits.failures=0) (op_xattr_list.failures=0) (multipart_upload_completed=0) (object_put_bytes=0) (object_multipart_aborted.failures=0) (action_executor_acquired=0) (stream_write_total_data=0) (action_http_get_request.failures=0) (op_xattr_get_named=0) (stream_aborted=0) (files_copied_bytes=0) (multipart_upload_list=0) (stream_read_closed=0) (multipart_upload_list.failures=0) (object_copy_requests=0) (committer_materialize_file.failures=0) (op_is_file=0) (files_copied=0) (op_open=0) (op_access.failures=0) (directories_deleted=0) (stream_read_operations=0) (action_executor_acquired.failures=0) (store_io_throttled=0) (op_rename.failure
s=0) (committer_jobs_failed=0) (committer_tasks_completed=0) (op_is_directory.failures=0) (op_createfile=0) (stream_read_bytes_discarded_in_abort=0) (files_deleted=0) (stream_read_block_acquire_read=0) (object_delete_request.failures=0) (object_multipart_initiated.failures=0) (op_list_files.failures=0) (fake_directories_deleted=0) (stream_read_seek_bytes_skipped=0) (op_delete=0) (object_delete_objects=0) (op_create.failures=0) (object_metadata_request=0) (op_xattr_get_named_map.failures=0) (stream_read_close_operations=0) (op_access=0) (op_copy_from_local_file=0) (op_rename=0) (committer_stage_file_upload.failures=0) (multipart_upload_part_put_bytes=0) (multipart_upload_part_put=0) (stream_write_exceptions=0) (stream_read_unbuffered=0) (stream_evict_blocks_from_cache=0) (committer_tasks_failed=0) (op_get_content_summary.failures=0) (object_put_request.failures=0) (stream_read_operations_incomplete=0) (fake_directories_created=0) (stream_write_total_time=0) (op_get_file_checksum=0) (
committer_commits_reverted=0) (op_xattr_get_map.failures=0) (action_http_head_request.failures=0) (op_abort=0) (audit_span_creation=1) (op_delete.failures=0) (action_file_opened.failures=0) (committer_load_single_pending_file=0) (store_io_request=0) (stream_read_version_mismatches=0) (op_get_content_summary=0) (stream_file_cache_eviction=0) (object_multipart_list.failures=0) (committer_bytes_uploaded=0) (committer_load_single_pending_file.failures=0) (stream_read_remote_stream_drain.failures=0) (op_xattr_list=0) (committer_materialize_file=0) (stream_write_bytes=0) (stream_read_block_fetch_operations.failures=0) (stream_read_opened=0) (object_put_request=0) (store_io_retry=0) (stream_read_bytes_backwards_on_seek=0) (object_multipart_list=0) (op_xattr_get_named.failures=0) (op_get_delegation_token=0) (stream_read_seek_backward_operations=0) (op_get_file_status=0) (stream_read_remote_stream_aborted.failures=0) (op_openfile=0) (op_create=0) (stream_file_cache_eviction.failures=0) (op_x
attr_get_named_map=0) (op_mkdirs.failures=0) (op_create_non_recursive=0) (files_delete_rejected=0) (committer_commit_job=0) (ignored_errors=0) (audit_request_execution=0) (stream_read_seek_policy_changed=0) (stream_read_seek_bytes_discarded=0) (op_is_file.failures=0) (multipart_upload_started=0) (store_exists_probe=0) (op_exists.failures=0) (op_get_file_checksum.failures=0) (op_list_files=0) (op_abort.failures=0) (committer_stage_file_upload=0) (stream_read_vectored_combined_ranges=0) (object_bulk_delete_request.failures=0) (stream_write_block_uploads=0) (audit_failure=0) (committer_magic_files_created=0) (op_hsync=0) (action_http_get_request=0) (stream_read_bytes=0) (op_copy_from_local_file.failures=0) (multipart_upload_abort_under_path_invoked=0) (op_list_located_status=0) (op_glob_status.failures=0) (object_continue_list_request.failures=0) (object_multipart_aborted=0) (op_list_status=0) (stream_write_block_uploads_committed=0) (object_bulk_delete_request=0) (stream_write_queue_d
uration=0) (stream_read_fully_operations=0) (stream_read_block_fetch_operations=0) (stream_read_block_acquire_read.failures=0) (action_file_opened=0) (op_xattr_get_map=0) (committer_magic_marker_put=0) (stream_read_remote_stream_drain=0) (multipart_instantiated=0) (stream_read_remote_stream_aborted=0) (object_delete_request=0) (delegation_tokens_issued.failures=0) (op_list_status.failures=0) (multipart_upload_aborted=0) (files_created=0) (object_list_request.failures=0) (committer_jobs_completed=0) (committer_bytes_committed=0) (committer_commit_job.failures=0) (op_glob_status=0) (stream_read_vectored_read_bytes_discarded=0) (action_http_head_request=0) (stream_read_exceptions=0) (op_createfile.failures=0) (stream_read_vectored_incoming_ranges=0) (object_list_request=0));
gauges=((stream_read_block_prefetch_enabled=0) (object_put_request_active=0) (stream_read_block_fetch_operations=0) (stream_read_block_cache_enabled=0) (stream_read_blocks_in_cache=0) (stream_write_block_uploads_active=0) (client_side_encryption_enabled=0) (stream_read_block_prefetch_limit=0) (stream_read_active_memory_in_use=0) (stream_write_block_uploads_pending=0) (stream_write_block_uploads_data_pending=0) (object_put_bytes_pending=0) (stream_read_block_size=0) (stream_read_active_prefetch_operations=0));
minimums=((op_create.failures.min=-1) (object_continue_list_request.failures.min=-1) (object_continue_list_request.min=-1) (object_delete_request.min=-1) (op_is_directory.min=-1) (stream_read_remote_stream_drain.failures.min=-1) (op_xattr_get_named.failures.min=-1) (store_exists_probe.failures.min=-1) (stream_file_cache_eviction.min=-1) (committer_materialize_file.failures.min=-1) (committer_load_single_pending_file.failures.min=-1) (op_xattr_get_named.min=-1) (object_multipart_aborted.failures.min=-1) (op_delete.min=-1) (op_get_delegation_token.min=-1) (op_get_file_checksum.min=-1) (object_list_request.failures.min=-1) (object_bulk_delete_request.failures.min=-1) (op_list_status.failures.min=-1) (op_access.failures.min=-1) (action_http_head_request.min=-1) (object_multipart_list.min=-1) (op_get_file_status.min=-1) (action_http_get_request.failures.min=-1) (stream_write_queue_duration.failures.min=-1) (committer_magic_marker_put.min=-1) (store_exists_probe.min=-1) (stream_read_rem
ote_stream_aborted.failures.min=-1) (op_glob_status.failures.min=-1) (op_list_status.min=-1) (object_multipart_list.failures.min=-1) (op_delete.failures.min=-1) (committer_commit_job.failures.min=-1) (delegation_tokens_issued.failures.min=-1) (op_rename.min=-1) (object_delete_request.failures.min=-1) (op_glob_status.min=-1) (op_abort.failures.min=-1) (object_multipart_initiated.min=-1) (committer_magic_marker_put.failures.min=-1) (op_createfile.min=-1) (op_exists.min=-1) (op_copy_from_local_file.min=-1) (op_exists.failures.min=-1) (op_mkdirs.min=-1) (action_http_get_request.min=-1) (multipart_upload_list.failures.min=-1) (committer_commit_job.min=-1) (op_get_file_checksum.failures.min=-1) (op_list_files.failures.min=-1) (object_list_request.min=-1) (stream_read_block_fetch_operations.failures.min=-1) (op_xattr_get_named_map.min=-1) (op_get_content_summary.failures.min=-1) (stream_read_remote_stream_aborted.min=-1) (committer_stage_file_upload.min=-1) (object_bulk_delete_request.min=
-1) (op_get_content_summary.min=-1) (op_get_file_status.failures.min=-1) (multipart_upload_list.min=-1) (op_xattr_get_map.min=-1) (op_copy_from_local_file.failures.min=-1) (action_executor_acquired.min=-1) (stream_read_block_fetch_operations.min=-1) (op_xattr_list.min=-1) (stream_file_cache_eviction.failures.min=-1) (object_put_request.failures.min=-1) (op_abort.min=-1) (op_create.min=-1) (delegation_tokens_issued.min=-1) (action_http_head_request.failures.min=-1) (committer_load_single_pending_file.min=-1) (op_is_file.failures.min=-1) (op_xattr_get_map.failures.min=-1) (object_multipart_aborted.min=-1) (op_createfile.failures.min=-1) (stream_read_remote_stream_drain.min=-1) (op_xattr_list.failures.min=-1) (stream_read_block_acquire_read.failures.min=-1) (committer_materialize_file.min=-1) (op_access.min=-1) (action_file_opened.failures.min=-1) (op_is_file.min=-1) (object_put_request.min=-1) (op_list_files.min=-1) (op_rename.failures.min=-1) (op_xattr_get_named_map.failures.min=-1)
(stream_write_queue_duration.min=-1) (stream_read_block_acquire_read.min=-1) (object_multipart_initiated.failures.min=-1) (committer_stage_file_upload.failures.min=-1) (op_is_directory.failures.min=-1) (op_mkdirs.failures.min=-1) (op_get_delegation_token.failures.min=-1) (action_executor_acquired.failures.min=-1) (action_file_opened.min=-1));
maximums=((action_http_get_request.max=-1) (object_delete_request.failures.max=-1) (action_executor_acquired.failures.max=-1) (op_xattr_get_named.max=-1) (op_xattr_get_named_map.max=-1) (object_continue_list_request.failures.max=-1) (committer_magic_marker_put.failures.max=-1) (object_multipart_initiated.max=-1) (committer_commit_job.failures.max=-1) (stream_file_cache_eviction.failures.max=-1) (op_glob_status.failures.max=-1) (op_delete.failures.max=-1) (stream_read_block_fetch_operations.failures.max=-1) (object_bulk_delete_request.failures.max=-1) (store_exists_probe.failures.max=-1) (op_delete.max=-1) (object_multipart_list.failures.max=-1) (stream_write_queue_duration.failures.max=-1) (object_multipart_aborted.failures.max=-1) (op_xattr_get_named.failures.max=-1) (op_mkdirs.failures.max=-1) (op_xattr_get_map.max=-1) (object_continue_list_request.max=-1) (op_abort.max=-1) (op_get_file_checksum.max=-1) (stream_read_remote_stream_aborted.failures.max=-1) (object_multipart_list.m
ax=-1) (op_create.max=-1) (object_list_request.failures.max=-1) (action_http_get_request.failures.max=-1) (op_get_content_summary.max=-1) (op_get_file_status.failures.max=-1) (stream_write_queue_duration.max=-1) (action_http_head_request.failures.max=-1) (op_get_delegation_token.max=-1) (op_copy_from_local_file.max=-1) (op_exists.failures.max=-1) (action_http_head_request.max=-1) (op_is_directory.failures.max=-1) (committer_materialize_file.failures.max=-1) (op_access.failures.max=-1) (op_createfile.max=-1) (object_bulk_delete_request.max=-1) (object_multipart_aborted.max=-1) (op_copy_from_local_file.failures.max=-1) (object_list_request.max=-1) (op_xattr_list.max=-1) (stream_read_remote_stream_aborted.max=-1) (op_list_files.max=-1) (multipart_upload_list.max=-1) (op_get_file_status.max=-1) (op_access.max=-1) (op_get_content_summary.failures.max=-1) (committer_commit_job.max=-1) (op_get_delegation_token.failures.max=-1) (committer_materialize_file.max=-1) (multipart_upload_list.fail
ures.max=-1) (op_xattr_get_map.failures.max=-1) (action_file_opened.max=-1) (stream_read_remote_stream_drain.max=-1) (object_multipart_initiated.failures.max=-1) (op_createfile.failures.max=-1) (op_xattr_list.failures.max=-1) (delegation_tokens_issued.failures.max=-1) (object_put_request.failures.max=-1) (op_create.failures.max=-1) (delegation_tokens_issued.max=-1) (op_glob_status.max=-1) (action_executor_acquired.max=-1) (stream_read_block_acquire_read.failures.max=-1) (action_file_opened.failures.max=-1) (op_xattr_get_named_map.failures.max=-1) (stream_read_remote_stream_drain.failures.max=-1) (store_exists_probe.max=-1) (object_delete_request.max=-1) (committer_load_single_pending_file.max=-1) (op_list_status.max=-1) (stream_file_cache_eviction.max=-1) (committer_stage_file_upload.failures.max=-1) (op_is_directory.max=-1) (op_rename.failures.max=-1) (committer_magic_marker_put.max=-1) (op_mkdirs.max=-1) (op_rename.max=-1) (op_exists.max=-1) (committer_load_single_pending_file.fai
lures.max=-1) (stream_read_block_fetch_operations.max=-1) (op_is_file.max=-1) (op_list_files.failures.max=-1) (object_put_request.max=-1) (op_abort.failures.max=-1) (committer_stage_file_upload.max=-1) (stream_read_block_acquire_read.max=-1) (op_list_status.failures.max=-1) (op_get_file_checksum.failures.max=-1) (op_is_file.failures.max=-1));
means=((delegation_tokens_issued.failures.mean=(samples=0, sum=0, mean=0.0000)) (op_access.failures.mean=(samples=0, sum=0, mean=0.0000)) (op_get_content_summary.failures.mean=(samples=0, sum=0, mean=0.0000)) (committer_stage_file_upload.mean=(samples=0, sum=0, mean=0.0000)) (op_list_status.mean=(samples=0, sum=0, mean=0.0000)) (op_xattr_get_named_map.mean=(samples=0, sum=0, mean=0.0000)) (committer_magic_marker_put.failures.mean=(samples=0, sum=0, mean=0.0000)) (op_is_file.mean=(samples=0, sum=0, mean=0.0000)) (op_glob_status.mean=(samples=0, sum=0, mean=0.0000)) (object_multipart_aborted.mean=(samples=0, sum=0, mean=0.0000)) (delegation_tokens_issued.mean=(samples=0, sum=0, mean=0.0000)) (object_delete_request.mean=(samples=0, sum=0, mean=0.0000)) (op_delete.failures.mean=(samples=0, sum=0, mean=0.0000)) (op_abort.mean=(samples=0, sum=0, mean=0.0000)) (committer_magic_marker_put.mean=(samples=0, sum=0, mean=0.0000)) (action_executor_acquired.failures.mean=(samples=0, sum=0, mean
=0.0000)) (action_file_opened.failures.mean=(samples=0, sum=0, mean=0.0000)) (op_copy_from_local_file.failures.mean=(samples=0, sum=0, mean=0.0000)) (object_put_request.failures.mean=(samples=0, sum=0, mean=0.0000)) (object_continue_list_request.mean=(samples=0, sum=0, mean=0.0000)) (op_is_directory.failures.mean=(samples=0, sum=0, mean=0.0000)) (op_copy_from_local_file.mean=(samples=0, sum=0, mean=0.0000)) (stream_read_block_acquire_read.mean=(samples=0, sum=0, mean=0.0000)) (op_glob_status.failures.mean=(samples=0, sum=0, mean=0.0000)) (action_executor_acquired.mean=(samples=0, sum=0, mean=0.0000)) (op_create.failures.mean=(samples=0, sum=0, mean=0.0000)) (op_xattr_list.mean=(samples=0, sum=0, mean=0.0000)) (object_multipart_aborted.failures.mean=(samples=0, sum=0, mean=0.0000)) (committer_materialize_file.mean=(samples=0, sum=0, mean=0.0000)) (action_http_get_request.mean=(samples=0, sum=0, mean=0.0000)) (object_delete_request.failures.mean=(samples=0, sum=0, mean=0.0000)) (op_ge
t_file_checksum.mean=(samples=0, sum=0, mean=0.0000)) (op_delete.mean=(samples=0, sum=0, mean=0.0000)) (action_file_opened.mean=(samples=0, sum=0, mean=0.0000)) (op_exists.mean=(samples=0, sum=0, mean=0.0000)) (op_abort.failures.mean=(samples=0, sum=0, mean=0.0000)) (op_access.mean=(samples=0, sum=0, mean=0.0000)) (op_xattr_get_named_map.failures.mean=(samples=0, sum=0, mean=0.0000)) (op_list_status.failures.mean=(samples=0, sum=0, mean=0.0000)) (action_http_head_request.failures.mean=(samples=0, sum=0, mean=0.0000)) (committer_load_single_pending_file.failures.mean=(samples=0, sum=0, mean=0.0000)) (op_mkdirs.mean=(samples=0, sum=0, mean=0.0000)) (op_get_delegation_token.failures.mean=(samples=0, sum=0, mean=0.0000)) (stream_write_queue_duration.failures.mean=(samples=0, sum=0, mean=0.0000)) (op_createfile.failures.mean=(samples=0, sum=0, mean=0.0000)) (op_xattr_get_named.failures.mean=(samples=0, sum=0, mean=0.0000)) (action_http_get_request.failures.mean=(samples=0, sum=0, mean=0.
0000)) (op_xattr_get_map.failures.mean=(samples=0, sum=0, mean=0.0000)) (stream_file_cache_eviction.failures.mean=(samples=0, sum=0, mean=0.0000)) (committer_commit_job.failures.mean=(samples=0, sum=0, mean=0.0000)) (object_multipart_initiated.failures.mean=(samples=0, sum=0, mean=0.0000)) (op_list_files.mean=(samples=0, sum=0, mean=0.0000)) (op_createfile.mean=(samples=0, sum=0, mean=0.0000)) (stream_read_block_fetch_operations.failures.mean=(samples=0, sum=0, mean=0.0000)) (object_multipart_list.mean=(samples=0, sum=0, mean=0.0000)) (store_exists_probe.failures.mean=(samples=0, sum=0, mean=0.0000)) (committer_stage_file_upload.failures.mean=(samples=0, sum=0, mean=0.0000)) (op_is_file.failures.mean=(samples=0, sum=0, mean=0.0000)) (action_http_head_request.mean=(samples=0, sum=0, mean=0.0000)) (object_continue_list_request.failures.mean=(samples=0, sum=0, mean=0.0000)) (op_get_file_status.failures.mean=(samples=0, sum=0, mean=0.0000)) (op_get_file_checksum.failures.mean=(samples=0
, sum=0, mean=0.0000)) (op_is_directory.mean=(samples=0, sum=0, mean=0.0000)) (op_list_files.failures.mean=(samples=0, sum=0, mean=0.0000)) (committer_commit_job.mean=(samples=0, sum=0, mean=0.0000)) (op_rename.failures.mean=(samples=0, sum=0, mean=0.0000)) (stream_read_remote_stream_aborted.failures.mean=(samples=0, sum=0, mean=0.0000)) (object_multipart_initiated.mean=(samples=0, sum=0, mean=0.0000)) (object_bulk_delete_request.mean=(samples=0, sum=0, mean=0.0000)) (op_rename.mean=(samples=0, sum=0, mean=0.0000)) (store_exists_probe.mean=(samples=0, sum=0, mean=0.0000)) (stream_write_queue_duration.mean=(samples=0, sum=0, mean=0.0000)) (op_exists.failures.mean=(samples=0, sum=0, mean=0.0000)) (stream_read_block_fetch_operations.mean=(samples=0, sum=0, mean=0.0000)) (stream_read_remote_stream_aborted.mean=(samples=0, sum=0, mean=0.0000)) (stream_read_block_acquire_read.failures.mean=(samples=0, sum=0, mean=0.0000)) (object_multipart_list.failures.mean=(samples=0, sum=0, mean=0.0000
)) (stream_read_remote_stream_drain.failures.mean=(samples=0, sum=0, mean=0.0000)) (op_create.mean=(samples=0, sum=0, mean=0.0000)) (object_list_request.failures.mean=(samples=0, sum=0, mean=0.0000)) (object_bulk_delete_request.failures.mean=(samples=0, sum=0, mean=0.0000)) (committer_materialize_file.failures.mean=(samples=0, sum=0, mean=0.0000)) (stream_read_remote_stream_drain.mean=(samples=0, sum=0, mean=0.0000)) (stream_file_cache_eviction.mean=(samples=0, sum=0, mean=0.0000)) (object_list_request.mean=(samples=0, sum=0, mean=0.0000)) (op_get_content_summary.mean=(samples=0, sum=0, mean=0.0000)) (multipart_upload_list.failures.mean=(samples=0, sum=0, mean=0.0000)) (op_xattr_get_map.mean=(samples=0, sum=0, mean=0.0000)) (op_xattr_get_named.mean=(samples=0, sum=0, mean=0.0000)) (op_mkdirs.failures.mean=(samples=0, sum=0, mean=0.0000)) (op_get_file_status.mean=(samples=0, sum=0, mean=0.0000)) (op_get_delegation_token.mean=(samples=0, sum=0, mean=0.0000)) (object_put_request.mean=(
samples=0, sum=0, mean=0.0000)) (committer_load_single_pending_file.mean=(samples=0, sum=0, mean=0.0000)) (op_xattr_list.failures.mean=(samples=0, sum=0, mean=0.0000)) (multipart_upload_list.mean=(samples=0, sum=0, mean=0.0000)));
}}, ClientSideEncryption=false}
2024-04-24 15:57:23,534 [setup] DEBUG impl.MkdirOperation (MkdirOperation.java:execute(94)) - Making directory: s3a://stevel-london/test
2024-04-24 15:57:23,535 [setup] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:innerGetFileStatus(3950)) - Getting path status for s3a://stevel-london/test (test); needEmptyDirectory=false
2024-04-24 15:57:23,535 [setup] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:s3GetFileStatus(4009)) - S3GetFileStatus s3a://stevel-london/test
2024-04-24 15:57:23,541 [setup] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:listObjects(2965)) - LIST List stevel-london:/test/ delimiter=/ keys=2 requester pays=null
2024-04-24 15:57:23,541 [setup] DEBUG s3a.S3AFileSystem (DurationInfo.java:<init>(80)) - Starting: LIST
2024-04-24 15:57:23,574 [setup] DEBUG s3a.Invoker (DurationInfo.java:<init>(80)) - Starting: create credentials
2024-04-24 15:57:23,577 [setup] DEBUG s3a.Invoker (DurationInfo.java:close(101)) - create credentials: duration 0:00.003s
2024-04-24 15:57:23,577 [setup] DEBUG s3a.AWSCredentialProviderList (AWSCredentialProviderList.java:resolveCredentials(195)) - No credentials from TemporaryAWSCredentialsProvider: org.apache.hadoop.fs.s3a.auth.NoAwsCredentialsException: Session credentials in Hadoop configuration: No AWS Credentials
2024-04-24 15:57:23,577 [setup] DEBUG s3a.AWSCredentialProviderList (AWSCredentialProviderList.java:resolveCredentials(182)) - Using credentials from SimpleAWSCredentialsProvider{accessKey.empty=false, secretKey.empty=false}
2024-04-24 15:57:23,599 [setup] DEBUG impl.LoggingAuditor (LoggingAuditor.java:modifyHttpRequest(400)) - [11] 0d643328-91f6-4da7-acae-86fd72161299-00000005 Executing op_mkdirs with {object_list_request 'test/' size=2, mutating=false}; https://audit.example.org/hadoop/1/op_mkdirs/0d643328-91f6-4da7-acae-86fd72161299-00000005/?op=op_mkdirs&p1=test&pr=stevel&ps=d8c4e4fc-c0aa-48d0-9605-2bf9ed7b08b2&id=0d643328-91f6-4da7-acae-86fd72161299-00000005&t0=11&fs=0d643328-91f6-4da7-acae-86fd72161299&t1=11&ts=1713970643534
2024-04-24 15:57:24,224 [setup] DEBUG s3a.S3AFileSystem (DurationInfo.java:close(101)) - LIST: duration 0:00.682s
2024-04-24 15:57:24,224 [setup] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:s3GetFileStatus(4100)) - Not Found: s3a://stevel-london/test
2024-04-24 15:57:24,224 [setup] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:innerGetFileStatus(3950)) - Getting path status for s3a://stevel-london/test (test); needEmptyDirectory=false
2024-04-24 15:57:24,224 [setup] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:s3GetFileStatus(4009)) - S3GetFileStatus s3a://stevel-london/test
2024-04-24 15:57:24,230 [setup] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:lambda$getObjectMetadata$10(2903)) - HEAD test with change tracker null
2024-04-24 15:57:24,233 [setup] DEBUG impl.LoggingAuditor (LoggingAuditor.java:modifyHttpRequest(400)) - [11] 0d643328-91f6-4da7-acae-86fd72161299-00000005 Executing op_mkdirs with {action_http_head_request 'test' size=0, mutating=false}; https://audit.example.org/hadoop/1/op_mkdirs/0d643328-91f6-4da7-acae-86fd72161299-00000005/?op=op_mkdirs&p1=test&pr=stevel&ps=d8c4e4fc-c0aa-48d0-9605-2bf9ed7b08b2&id=0d643328-91f6-4da7-acae-86fd72161299-00000005&t0=11&fs=0d643328-91f6-4da7-acae-86fd72161299&t1=11&ts=1713970643534
2024-04-24 15:57:24,276 [setup] DEBUG s3a.Invoker (Invoker.java:retryUntranslated(474)) - GET test ; software.amazon.awssdk.services.s3.model.NoSuchKeyException: null (Service: S3, Status Code: 404, Request ID: YM4CDP856RPCKP8R, Extended Request ID: JbbjhNCFZf+5Hrj/WlnzH54455UAuBPn08CVH1vUqgpVm9J9Z7r6zpwxTeoaudWLrPYAzNKN0N/VmQL1yyv2LQ==) (Service: S3, Status Code: 404, Request ID: YM4CDP856RPCKP8R),
2024-04-24 15:57:24,277 [setup] DEBUG s3a.S3ARetryPolicy (S3ARetryPolicy.java:shouldRetry(308)) - Retry probe for FileNotFoundException with 0 retries and 0 failovers, idempotent=true, due to java.io.FileNotFoundException: GET test on /: software.amazon.awssdk.services.s3.model.NoSuchKeyException: null (Service: S3, Status Code: 404, Request ID: YM4CDP856RPCKP8R, Extended Request ID: JbbjhNCFZf+5Hrj/WlnzH54455UAuBPn08CVH1vUqgpVm9J9Z7r6zpwxTeoaudWLrPYAzNKN0N/VmQL1yyv2LQ==) (Service: S3, Status Code: 404, Request ID: YM4CDP856RPCKP8R):NoSuchKey
java.io.FileNotFoundException: GET test on /: software.amazon.awssdk.services.s3.model.NoSuchKeyException: null (Service: S3, Status Code: 404, Request ID: YM4CDP856RPCKP8R, Extended Request ID: JbbjhNCFZf+5Hrj/WlnzH54455UAuBPn08CVH1vUqgpVm9J9Z7r6zpwxTeoaudWLrPYAzNKN0N/VmQL1yyv2LQ==) (Service: S3, Status Code: 404, Request ID: YM4CDP856RPCKP8R):NoSuchKey
at org.apache.hadoop.fs.s3a.S3AUtils.translateException(S3AUtils.java:278)
at org.apache.hadoop.fs.s3a.Invoker.retryUntranslated(Invoker.java:481)
at org.apache.hadoop.fs.s3a.Invoker.retryUntranslated(Invoker.java:431)
at org.apache.hadoop.fs.s3a.S3AFileSystem.getObjectMetadata(S3AFileSystem.java:2895)
at org.apache.hadoop.fs.s3a.S3AFileSystem.getObjectMetadata(S3AFileSystem.java:2875)
at org.apache.hadoop.fs.s3a.S3AFileSystem.s3GetFileStatus(S3AFileSystem.java:4024)
at org.apache.hadoop.fs.s3a.S3AFileSystem.innerGetFileStatus(S3AFileSystem.java:3952)
at org.apache.hadoop.fs.s3a.S3AFileSystem$MkdirOperationCallbacksImpl.probePathStatus(S3AFileSystem.java:3809)
at org.apache.hadoop.fs.s3a.impl.MkdirOperation.probePathStatusOrNull(MkdirOperation.java:173)
at org.apache.hadoop.fs.s3a.impl.MkdirOperation.getPathStatusExpectingDir(MkdirOperation.java:197)
at org.apache.hadoop.fs.s3a.impl.MkdirOperation.execute(MkdirOperation.java:108)
at org.apache.hadoop.fs.s3a.impl.MkdirOperation.execute(MkdirOperation.java:57)
at org.apache.hadoop.fs.s3a.impl.ExecutingStoreOperation.apply(ExecutingStoreOperation.java:76)
at org.apache.hadoop.fs.statistics.impl.IOStatisticsBinding.invokeTrackingDuration(IOStatisticsBinding.java:556)
at org.apache.hadoop.fs.statistics.impl.IOStatisticsBinding.lambda$trackDurationOfOperation$5(IOStatisticsBinding.java:537)
at org.apache.hadoop.fs.statistics.impl.IOStatisticsBinding.trackDuration(IOStatisticsBinding.java:458)
at org.apache.hadoop.fs.s3a.S3AFileSystem.trackDurationAndSpan(S3AFileSystem.java:2722)
at org.apache.hadoop.fs.s3a.S3AFileSystem.trackDurationAndSpan(S3AFileSystem.java:2741)
at org.apache.hadoop.fs.s3a.S3AFileSystem.mkdirs(S3AFileSystem.java:3781)
at org.apache.hadoop.fs.FileSystem.mkdirs(FileSystem.java:2494)
at org.apache.hadoop.fs.contract.AbstractFSContractTestBase.mkdirs(AbstractFSContractTestBase.java:363)
at org.apache.hadoop.fs.contract.AbstractFSContractTestBase.setup(AbstractFSContractTestBase.java:205)
at org.apache.hadoop.fs.s3a.AbstractS3ATestBase.setup(AbstractS3ATestBase.java:111)
at org.apache.hadoop.fs.s3a.performance.AbstractS3ACostTest.setup(AbstractS3ACostTest.java:129)
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:59)
at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:56)
at org.junit.internal.runners.statements.RunBefores.invokeMethod(RunBefores.java:33)
at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:24)
at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
at org.junit.rules.TestWatcher$1.evaluate(TestWatcher.java:61)
at org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:299)
at org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:293)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.lang.Thread.run(Thread.java:750)
Caused by: software.amazon.awssdk.services.s3.model.NoSuchKeyException: null (Service: S3, Status Code: 404, Request ID: YM4CDP856RPCKP8R, Extended Request ID: JbbjhNCFZf+5Hrj/WlnzH54455UAuBPn08CVH1vUqgpVm9J9Z7r6zpwxTeoaudWLrPYAzNKN0N/VmQL1yyv2LQ==) (Service: S3, Status Code: 404, Request ID: YM4CDP856RPCKP8R)
at software.amazon.awssdk.services.s3.model.NoSuchKeyException$BuilderImpl.build(NoSuchKeyException.java:126)
at software.amazon.awssdk.services.s3.model.NoSuchKeyException$BuilderImpl.build(NoSuchKeyException.java:80)
at software.amazon.awssdk.services.s3.internal.handlers.ExceptionTranslationInterceptor.modifyException(ExceptionTranslationInterceptor.java:63)
at software.amazon.awssdk.core.interceptor.ExecutionInterceptorChain.modifyException(ExecutionInterceptorChain.java:181)
at software.amazon.awssdk.core.internal.http.pipeline.stages.utils.ExceptionReportingUtils.runModifyException(ExceptionReportingUtils.java:54)
at software.amazon.awssdk.core.internal.http.pipeline.stages.utils.ExceptionReportingUtils.reportFailureToInterceptors(ExceptionReportingUtils.java:38)
at software.amazon.awssdk.core.internal.http.pipeline.stages.ExecutionFailureExceptionReportingStage.execute(ExecutionFailureExceptionReportingStage.java:39)
at software.amazon.awssdk.core.internal.http.pipeline.stages.ExecutionFailureExceptionReportingStage.execute(ExecutionFailureExceptionReportingStage.java:26)
at software.amazon.awssdk.core.internal.http.AmazonSyncHttpClient$RequestExecutionBuilderImpl.execute(AmazonSyncHttpClient.java:224)
at software.amazon.awssdk.core.internal.handler.BaseSyncClientHandler.invoke(BaseSyncClientHandler.java:103)
at software.amazon.awssdk.core.internal.handler.BaseSyncClientHandler.doExecute(BaseSyncClientHandler.java:173)
at software.amazon.awssdk.core.internal.handler.BaseSyncClientHandler.lambda$execute$1(BaseSyncClientHandler.java:80)
at software.amazon.awssdk.core.internal.handler.BaseSyncClientHandler.measureApiCallSuccess(BaseSyncClientHandler.java:182)
at software.amazon.awssdk.core.internal.handler.BaseSyncClientHandler.execute(BaseSyncClientHandler.java:74)
at software.amazon.awssdk.core.client.handler.SdkSyncClientHandler.execute(SdkSyncClientHandler.java:45)
at software.amazon.awssdk.awscore.client.handler.AwsSyncClientHandler.execute(AwsSyncClientHandler.java:53)
at software.amazon.awssdk.services.s3.DefaultS3Client.headObject(DefaultS3Client.java:6319)
at org.apache.hadoop.fs.s3a.S3AFileSystem.lambda$getObjectMetadata$10(S3AFileSystem.java:2907)
at org.apache.hadoop.fs.s3a.Invoker.retryUntranslated(Invoker.java:468)
... 37 more
2024-04-24 15:57:24,278 [setup] DEBUG s3a.S3ARetryPolicy (S3ARetryPolicy.java:shouldRetry(313)) - Retry action is RetryAction(action=FAIL, delayMillis=0, reason=try once and fail.)
2024-04-24 15:57:24,279 [setup] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:s3GetFileStatus(4100)) - Not Found: s3a://stevel-london/test
2024-04-24 15:57:24,280 [setup] DEBUG s3a.Invoker (DurationInfo.java:<init>(80)) - Starting: PUT 0-byte object
2024-04-24 15:57:24,286 [setup] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:putObjectDirect(3267)) - PUT 0 bytes to test/
2024-04-24 15:57:24,286 [setup] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:incrementPutStartStatistics(3341)) - PUT start 0 bytes
2024-04-24 15:57:24,292 [setup] DEBUG impl.LoggingAuditor (LoggingAuditor.java:modifyHttpRequest(400)) - [11] 0d643328-91f6-4da7-acae-86fd72161299-00000005 Executing op_mkdirs with {object_put_request 'test/' size=0, mutating=true}; https://audit.example.org/hadoop/1/op_mkdirs/0d643328-91f6-4da7-acae-86fd72161299-00000005/?op=op_mkdirs&p1=test&pr=stevel&ps=d8c4e4fc-c0aa-48d0-9605-2bf9ed7b08b2&id=0d643328-91f6-4da7-acae-86fd72161299-00000005&t0=11&fs=0d643328-91f6-4da7-acae-86fd72161299&t1=11&ts=1713970643534
2024-04-24 15:57:24,376 [setup] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:incrementPutCompletedStatistics(3357)) - PUT completed success=true; 0 bytes
2024-04-24 15:57:24,376 [setup] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:finishedWrite(4690)) - Finished write to test/, len 0. etag "879c68e18e6aa75a0edcab0e0a361786", version JOVjFhK1ZAGKfaJV39PLzFeh0gEF9JCJ
2024-04-24 15:57:24,376 [setup] DEBUG s3a.Invoker (DurationInfo.java:close(101)) - PUT 0-byte object : duration 0:00.096s
2024-04-24 15:57:24,376 [setup] DEBUG S3AFileSystem.Progress (S3AFileSystem.java:incrementPutProgressStatistics(3374)) - PUT test: 0 bytes
2024-04-24 15:57:24,428 [setup] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:initializeClass(5724)) - Initialize S3A class
2024-04-24 15:57:24,435 [setup] DEBUG s3a.S3ATestUtils (S3ATestUtils.java:removeBucketOverrides(914)) - Removing option fs.s3a.bucket.stevel-london.directory.marker.retention; was keep
2024-04-24 15:57:24,436 [setup] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:initializeClass(5724)) - Initialize S3A class
2024-04-24 15:57:24,436 [setup] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:initialize(549)) - Initializing S3AFileSystem for stevel-london
2024-04-24 15:57:24,436 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:propagateBucketOptions(1103)) - Propagating entries under fs.s3a.bucket.stevel-london.
2024-04-24 15:57:24,437 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:propagateBucketOptions(1124)) - Updating fs.s3a.versioned.store from [core-site.xml]
2024-04-24 15:57:24,437 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:propagateBucketOptions(1124)) - Updating fs.s3a.encryption.algorithm from [core-site.xml]
2024-04-24 15:57:24,437 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:propagateBucketOptions(1124)) - Updating fs.s3a.endpoint from [core-site.xml]
2024-04-24 15:57:24,437 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:propagateBucketOptions(1124)) - Updating fs.s3a.encryption.key from [core-site.xml]
2024-04-24 15:57:24,437 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:propagateBucketOptions(1124)) - Updating fs.s3a.change.detection.source from [core-site.xml]
2024-04-24 15:57:24,437 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:maybeIsolateClassloader(1708)) - Configuration classloader set to S3AFileSystem classloader: sun.misc.Launcher$AppClassLoader@18b4aac2
2024-04-24 15:57:24,437 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:buildEncryptionSecrets(1477)) - Using SSE-KMS with key of length 75 ending with 3
2024-04-24 15:57:24,437 [setup] DEBUG s3a.S3ARetryPolicy (S3ARetryPolicy.java:<init>(145)) - Retrying on recoverable AWS failures 3 times with an initial interval of 500ms
2024-04-24 15:57:24,440 [setup] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:initialize(605)) - Client Side Encryption enabled: false
2024-04-24 15:57:24,440 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:intOption(909)) - Value of fs.s3a.paging.maximum is 5000
2024-04-24 15:57:24,440 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:longBytesOption(952)) - Value of fs.s3a.block.size is 33554432
2024-04-24 15:57:24,440 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:longBytesOption(952)) - Value of fs.s3a.prefetch.block.size is 131072
2024-04-24 15:57:24,440 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:intOption(909)) - Value of fs.s3a.prefetch.block.count is 8
2024-04-24 15:57:24,441 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:intOption(909)) - Value of fs.s3a.max.total.tasks is 32
2024-04-24 15:57:24,441 [setup] DEBUG impl.ConfigurationHelper (ConfigurationHelper.java:getDuration(80)) - Duration of fs.s3a.threads.keepalivetime = PT1M
2024-04-24 15:57:24,441 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:intOption(909)) - Value of fs.s3a.executor.capacity is 16
2024-04-24 15:57:24,442 [setup] DEBUG auth.SignerManager (SignerManager.java:initCustomSigners(68)) - No custom signers specified
2024-04-24 15:57:24,442 [setup] DEBUG audit.AuditIntegration (AuditIntegration.java:createAndInitAuditor(109)) - Auditor class is class org.apache.hadoop.fs.s3a.audit.impl.LoggingAuditor
2024-04-24 15:57:24,442 [setup] DEBUG impl.ActiveAuditManagerS3A (ActiveAuditManagerS3A.java:serviceInit(199)) - Audit manager initialized with audit service LoggingAuditor{ID='e40ad9fb-842f-43ee-8784-912d440e2355', headerEnabled=true, rejectOutOfSpan=true, isMultipartUploadEnabled=true}
2024-04-24 15:57:24,442 [setup] DEBUG impl.ActiveAuditManagerS3A (ActiveAuditManagerS3A.java:serviceStart(212)) - Started audit service LoggingAuditor{ID='e40ad9fb-842f-43ee-8784-912d440e2355', headerEnabled=true, rejectOutOfSpan=true, isMultipartUploadEnabled=true}
2024-04-24 15:57:24,442 [setup] DEBUG audit.AuditIntegration (AuditIntegration.java:createAndStartAuditManager(76)) - Started Audit Manager Service ActiveAuditManagerS3A in state ActiveAuditManagerS3A: STARTED, auditor=LoggingAuditor{ID='e40ad9fb-842f-43ee-8784-912d440e2355', headerEnabled=true, rejectOutOfSpan=true, isMultipartUploadEnabled=true}}
2024-04-24 15:57:24,442 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:longOption(930)) - Value of fs.s3a.internal.upload.part.count.limit is 10000
2024-04-24 15:57:24,442 [setup] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:createRequestFactory(1202)) - Unset storage class property fs.s3a.create.storage.class; falling back to default storage class
2024-04-24 15:57:24,443 [setup] DEBUG auth.CredentialProviderListFactory (CredentialProviderListFactory.java:createAWSV2CredentialProvider(306)) - Credential provider class is org.apache.hadoop.fs.s3a.TemporaryAWSCredentialsProvider
2024-04-24 15:57:24,443 [setup] DEBUG auth.CredentialProviderListFactory (CredentialProviderListFactory.java:createAWSV2CredentialProvider(306)) - Credential provider class is org.apache.hadoop.fs.s3a.SimpleAWSCredentialsProvider
2024-04-24 15:57:24,443 [setup] DEBUG auth.CredentialProviderListFactory (CredentialProviderListFactory.java:createAWSCredentialProviderList(151)) - For URI s3a://stevel-london/, using credentials AWSCredentialProviderList name=; refcount= 1; size=2: [TemporaryAWSCredentialsProvider, SimpleAWSCredentialsProvider{accessKey.empty=false, secretKey.empty=false}]
2024-04-24 15:57:24,443 [setup] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:bindAWSClient(1047)) - Using credential provider AWSCredentialProviderList name=; refcount= 1; size=2: [TemporaryAWSCredentialsProvider, SimpleAWSCredentialsProvider{accessKey.empty=false, secretKey.empty=false}]
2024-04-24 15:57:24,443 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:intOption(909)) - Value of fs.s3a.connection.maximum is 512
2024-04-24 15:57:24,443 [setup] DEBUG impl.ConfigurationHelper (ConfigurationHelper.java:getDuration(80)) - Duration of fs.s3a.connection.acquisition.timeout = PT1M
2024-04-24 15:57:24,443 [setup] DEBUG impl.ConfigurationHelper (ConfigurationHelper.java:getDuration(80)) - Duration of fs.s3a.connection.ttl = PT5M
2024-04-24 15:57:24,443 [setup] DEBUG impl.ConfigurationHelper (ConfigurationHelper.java:getDuration(80)) - Duration of fs.s3a.connection.establish.timeout = PT30S
2024-04-24 15:57:24,443 [setup] DEBUG impl.ConfigurationHelper (ConfigurationHelper.java:getDuration(80)) - Duration of fs.s3a.connection.idle.time = PT1M
2024-04-24 15:57:24,443 [setup] DEBUG impl.ConfigurationHelper (ConfigurationHelper.java:getDuration(80)) - Duration of fs.s3a.connection.timeout = PT25S
2024-04-24 15:57:24,443 [setup] DEBUG s3a.DefaultS3ClientFactory (DefaultS3ClientFactory.java:getS3RegionFromEndpoint(397)) - Endpoint s3.eu-west-2.amazonaws.com is not the default; parsing
2024-04-24 15:57:24,443 [setup] DEBUG s3a.DefaultS3ClientFactory (DefaultS3ClientFactory.java:configureEndpointAndRegion(326)) - Setting endpoint to https://s3.eu-west-2.amazonaws.com
2024-04-24 15:57:24,443 [setup] DEBUG s3a.DefaultS3ClientFactory (DefaultS3ClientFactory.java:configureEndpointAndRegion(353)) - Setting region to eu-west-2 from endpoint
2024-04-24 15:57:24,443 [setup] DEBUG s3a.DefaultS3ClientFactory (DefaultS3ClientFactory.java:maybeApplyS3AccessGrantsConfigurations(419)) - S3 Access Grants plugin is not enabled.
2024-04-24 15:57:24,443 [setup] DEBUG impl.ConfigurationHelper (ConfigurationHelper.java:getDuration(80)) - Duration of fs.s3a.connection.request.timeout = PT1M
2024-04-24 15:57:24,444 [setup] DEBUG impl.AWSClientConfig (AWSClientConfig.java:initUserAgent(375)) - Using User-Agent: Hadoop 3.5.0-SNAPSHOT
2024-04-24 15:57:24,444 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:intOption(909)) - Value of fs.s3a.attempts.maximum is 2
2024-04-24 15:57:24,447 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:intOption(909)) - Value of fs.s3a.connection.maximum is 512
2024-04-24 15:57:24,447 [setup] DEBUG impl.ConfigurationHelper (ConfigurationHelper.java:getDuration(80)) - Duration of fs.s3a.connection.acquisition.timeout = PT1M
2024-04-24 15:57:24,447 [setup] DEBUG impl.ConfigurationHelper (ConfigurationHelper.java:getDuration(80)) - Duration of fs.s3a.connection.ttl = PT5M
2024-04-24 15:57:24,447 [setup] DEBUG impl.ConfigurationHelper (ConfigurationHelper.java:getDuration(80)) - Duration of fs.s3a.connection.establish.timeout = PT30S
2024-04-24 15:57:24,447 [setup] DEBUG impl.ConfigurationHelper (ConfigurationHelper.java:getDuration(80)) - Duration of fs.s3a.connection.idle.time = PT1M
2024-04-24 15:57:24,447 [setup] DEBUG impl.ConfigurationHelper (ConfigurationHelper.java:getDuration(80)) - Duration of fs.s3a.connection.timeout = PT25S
2024-04-24 15:57:24,447 [setup] DEBUG s3a.DefaultS3ClientFactory (DefaultS3ClientFactory.java:getS3RegionFromEndpoint(397)) - Endpoint s3.eu-west-2.amazonaws.com is not the default; parsing
2024-04-24 15:57:24,447 [setup] DEBUG s3a.DefaultS3ClientFactory (DefaultS3ClientFactory.java:configureEndpointAndRegion(326)) - Setting endpoint to https://s3.eu-west-2.amazonaws.com
2024-04-24 15:57:24,447 [setup] DEBUG s3a.DefaultS3ClientFactory (DefaultS3ClientFactory.java:configureEndpointAndRegion(353)) - Setting region to eu-west-2 from endpoint
2024-04-24 15:57:24,447 [setup] DEBUG s3a.DefaultS3ClientFactory (DefaultS3ClientFactory.java:maybeApplyS3AccessGrantsConfigurations(419)) - S3 Access Grants plugin is not enabled.
2024-04-24 15:57:24,448 [setup] DEBUG impl.ConfigurationHelper (ConfigurationHelper.java:getDuration(80)) - Duration of fs.s3a.connection.request.timeout = PT1M
2024-04-24 15:57:24,448 [setup] DEBUG impl.AWSClientConfig (AWSClientConfig.java:initUserAgent(375)) - Using User-Agent: Hadoop 3.5.0-SNAPSHOT
2024-04-24 15:57:24,448 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:intOption(909)) - Value of fs.s3a.attempts.maximum is 2
2024-04-24 15:57:24,450 [setup] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:doBucketProbing(831)) - skipping check for bucket existence
2024-04-24 15:57:24,450 [setup] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:initialize(696)) - Input fadvise policy = default
2024-04-24 15:57:24,450 [setup] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:initialize(698)) - Change detection policy = VersionIdChangeDetectionPolicy mode=Server
2024-04-24 15:57:24,451 [setup] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:initialize(702)) - Filesystem support for magic committers is enabled
2024-04-24 15:57:24,451 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:intOption(909)) - Value of fs.s3a.fast.upload.active.blocks is 4
2024-04-24 15:57:24,451 [setup] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:initialize(721)) - Using S3ABlockOutputStream with buffer = disk; block=67108864; queue limit=4; multipart=true
2024-04-24 15:57:24,451 [setup] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:initialize(731)) - fs.s3a.create.performance = false
2024-04-24 15:57:24,451 [setup] DEBUG impl.DirectoryPolicyImpl (DirectoryPolicyImpl.java:getDirectoryPolicy(189)) - Directory markers will be kept
2024-04-24 15:57:24,451 [setup] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:initialize(737)) - Directory marker retention policy is DirectoryMarkerRetention{policy='keep'}
2024-04-24 15:57:24,451 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:intOption(909)) - Value of fs.s3a.bulk.delete.page.size is 250
2024-04-24 15:57:24,451 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:longBytesOption(952)) - Value of fs.s3a.readahead.range is 32768
2024-04-24 15:57:24,451 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:intOption(909)) - Value of io.file.buffer.size is 4194304
2024-04-24 15:57:24,451 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:longBytesOption(952)) - Value of fs.s3a.input.async.drain.threshold is 1024
2024-04-24 15:57:24,451 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:intOption(909)) - Value of fs.s3a.vectored.active.ranged.reads is 4
2024-04-24 15:57:24,451 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:longBytesOption(952)) - Value of fs.s3a.vectored.read.min.seek.size is 4096
2024-04-24 15:57:24,451 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:longBytesOption(952)) - Value of fs.s3a.vectored.read.max.merged.size is 1048576
2024-04-24 15:57:24,451 [setup] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:initialize(763)) - Using optimized copyFromLocal implementation: true
2024-04-24 15:57:24,454 [setup] INFO contract.AbstractFSContractTestBase (AbstractFSContractTestBase.java:setup(196)) - Test filesystem = s3a://stevel-london implemented by S3AFileSystem{uri=s3a://stevel-london, workingDir=s3a://stevel-london/user/stevel, partSize=67108864, enableMultiObjectsDelete=true, maxKeys=5000, OpenFileSupport{changePolicy=VersionIdChangeDetectionPolicy mode=Server, defaultReadAhead=32768, defaultBufferSize=4194304, defaultAsyncDrainThreshold=1024, defaultInputPolicy=default}, blockSize=33554432, multiPartThreshold=134217728, s3EncryptionAlgorithm='SSE_KMS', blockFactory=org.apache.hadoop.fs.s3a.S3ADataBlocks$DiskBlockFactory@fbacef6, auditManager=Service ActiveAuditManagerS3A in state ActiveAuditManagerS3A: STARTED, auditor=LoggingAuditor{ID='e40ad9fb-842f-43ee-8784-912d440e2355', headerEnabled=true, rejectOutOfSpan=true, isMultipartUploadEnabled=true}}, authoritativePath=[], useListV1=false, magicCommitter=true, boundedExecutor=BlockingThreadPoolExecutor
Service{SemaphoredDelegatingExecutor{permitCount=200, available=200, waiting=0}, activeCount=0}, unboundedExecutor=java.util.concurrent.ThreadPoolExecutor@6e3a3097[Running, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 0], credentials=AWSCredentialProviderList name=; refcount= 1; size=2: [TemporaryAWSCredentialsProvider, SimpleAWSCredentialsProvider{accessKey.empty=false, secretKey.empty=false}], delegation tokens=disabled, DirectoryMarkerRetention{policy='keep'}, instrumentation {S3AInstrumentation{instanceIOStatistics=counters=((stream_file_cache_eviction=0) (audit_failure=0) (committer_load_single_pending_file=0) (fake_directories_deleted=0) (store_io_request=0) (stream_read_block_acquire_read.failures=0) (multipart_upload_part_put=0) (stream_read_seek_backward_operations=0) (committer_commits_created=0) (stream_write_queue_duration.failures=0) (files_copied=0) (op_is_file=0) (op_createfile=0) (action_http_get_request.failures=0) (op_get_file_status=0) (o
bject_continue_list_request.failures=0) (stream_read_vectored_incoming_ranges=0) (op_xattr_get_map=0) (committer_bytes_uploaded=0) (multipart_upload_abort_under_path_invoked=0) (stream_read_vectored_read_bytes_discarded=0) (op_rename=0) (multipart_upload_list.failures=0) (committer_magic_files_created=0) (store_exists_probe=0) (stream_read_block_fetch_operations.failures=0) (action_executor_acquired=0) (action_file_opened=0) (committer_commits_completed=0) (object_multipart_initiated=0) (op_copy_from_local_file.failures=0) (object_put_bytes=0) (op_mkdirs.failures=0) (committer_jobs_completed=0) (object_multipart_initiated.failures=0) (stream_read_operations=0) (object_delete_objects=0) (op_get_content_summary.failures=0) (stream_read_close_operations=0) (action_http_head_request.failures=0) (stream_read_closed=0) (audit_request_execution=0) (op_get_file_status.failures=0) (op_get_file_checksum=0) (stream_write_total_data=0) (stream_read_seek_bytes_skipped=0) (committer_materialize_f
ile.failures=0) (op_list_status.failures=0) (stream_read_seek_forward_operations=0) (multipart_upload_completed=0) (store_io_throttled=0) (files_created=0) (stream_read_bytes=0) (directories_deleted=0) (committer_jobs_failed=0) (stream_read_operations_incomplete=0) (committer_materialize_file=0) (op_list_status=0) (op_xattr_get_named_map=0) (object_copy_requests=0) (committer_bytes_committed=0) (stream_read_vectored_combined_ranges=0) (stream_read_remote_stream_drain=0) (op_is_directory.failures=0) (op_get_content_summary=0) (object_multipart_aborted=0) (op_delete.failures=0) (op_list_files.failures=0) (op_access=0) (store_io_retry=0) (op_exists=0) (stream_read_total_bytes=0) (op_createfile.failures=0) (op_exists.failures=0) (stream_read_opened=0) (object_metadata_request=0) (object_put_request_completed=0) (op_create.failures=0) (object_put_request=0) (op_open=0) (op_glob_status.failures=0) (multipart_upload_started=0) (committer_tasks_failed=0) (stream_read_version_mismatches=0) (
object_multipart_list=0) (fake_directories_created=0) (op_abort=0) (object_delete_request.failures=0) (committer_commits.failures=0) (stream_read_exceptions=0) (stream_read_seek_bytes_discarded=0) (committer_stage_file_upload=0) (object_bulk_delete_request=0) (object_continue_list_request=0) (object_multipart_aborted.failures=0) (op_hsync=0) (stream_write_exceptions=0) (op_rename.failures=0) (directories_created=0) (object_delete_request=0) (stream_write_block_uploads=0) (stream_read_fully_operations=0) (stream_write_queue_duration=0) (op_copy_from_local_file=0) (object_bulk_delete_request.failures=0) (stream_read_vectored_operations=0) (op_xattr_get_map.failures=0) (stream_write_block_uploads_aborted=0) (delegation_tokens_issued.failures=0) (committer_commits_aborted=0) (committer_load_single_pending_file.failures=0) (stream_write_total_time=0) (stream_read_seek_operations=0) (stream_read_remote_stream_aborted.failures=0) (object_put_request.failures=0) (action_executor_acquired.fa
ilures=0) (op_create=0) (op_get_delegation_token=0) (op_xattr_get_named=0) (committer_stage_file_upload.failures=0) (op_get_delegation_token.failures=0) (stream_read_bytes_discarded_in_abort=0) (committer_magic_marker_put.failures=0) (op_get_file_checksum.failures=0) (object_list_request.failures=0) (op_xattr_list.failures=0) (op_access.failures=0) (files_copied_bytes=0) (committer_magic_marker_put=0) (multipart_upload_aborted=0) (op_xattr_get_named_map.failures=0) (multipart_instantiated=0) (op_delete=0) (stream_read_unbuffered=0) (op_is_file.failures=0) (op_xattr_list=0) (delegation_tokens_issued=0) (op_list_located_status=0) (action_http_get_request=0) (stream_file_cache_eviction.failures=0) (multipart_upload_part_put_bytes=0) (object_list_request=0) (op_abort.failures=0) (op_list_files=0) (committer_tasks_completed=0) (stream_read_seek_policy_changed=0) (files_deleted=0) (op_xattr_get_named.failures=0) (stream_read_bytes_backwards_on_seek=0) (object_multipart_list.failures=0) (c
ommitter_commit_job.failures=0) (stream_read_remote_stream_drain.failures=0) (audit_access_check_failure=0) (op_mkdirs=0) (op_hflush=0) (multipart_upload_list=0) (stream_read_block_fetch_operations=0) (stream_write_block_uploads_committed=0) (stream_read_bytes_discarded_in_close=0) (op_openfile=0) (action_http_head_request=0) (stream_read_remote_stream_aborted=0) (files_delete_rejected=0) (audit_span_creation=1) (stream_read_block_acquire_read=0) (op_is_directory=0) (ignored_errors=0) (stream_evict_blocks_from_cache=0) (op_create_non_recursive=0) (stream_write_exceptions_completing_upload=0) (committer_commit_job=0) (committer_commits_reverted=0) (store_exists_probe.failures=0) (stream_aborted=0) (op_glob_status=0) (action_file_opened.failures=0) (stream_write_bytes=0));
gauges=((stream_write_block_uploads_active=0) (stream_read_blocks_in_cache=0) (stream_read_block_cache_enabled=0) (object_put_request_active=0) (stream_read_active_memory_in_use=0) (stream_read_block_fetch_operations=0) (stream_read_block_prefetch_enabled=0) (stream_read_active_prefetch_operations=0) (stream_write_block_uploads_data_pending=0) (client_side_encryption_enabled=0) (object_put_bytes_pending=0) (stream_read_block_size=0) (stream_write_block_uploads_pending=0) (stream_read_block_prefetch_limit=0));
minimums=((op_exists.failures.min=-1) (op_create.failures.min=-1) (op_is_directory.min=-1) (multipart_upload_list.failures.min=-1) (object_multipart_aborted.failures.min=-1) (stream_write_queue_duration.failures.min=-1) (stream_file_cache_eviction.min=-1) (object_multipart_list.failures.min=-1) (op_glob_status.failures.min=-1) (stream_read_remote_stream_aborted.min=-1) (action_http_get_request.failures.min=-1) (stream_read_block_acquire_read.failures.min=-1) (object_delete_request.failures.min=-1) (op_xattr_list.failures.min=-1) (action_executor_acquired.min=-1) (op_abort.failures.min=-1) (delegation_tokens_issued.min=-1) (stream_file_cache_eviction.failures.min=-1) (op_list_status.failures.min=-1) (op_xattr_list.min=-1) (op_get_content_summary.failures.min=-1) (object_multipart_initiated.min=-1) (op_abort.min=-1) (op_get_file_status.failures.min=-1) (op_create.min=-1) (op_createfile.min=-1) (committer_materialize_file.failures.min=-1) (op_createfile.failures.min=-1) (op_xattr_get
_named_map.failures.min=-1) (action_http_head_request.min=-1) (action_file_opened.failures.min=-1) (object_list_request.min=-1) (op_get_file_checksum.failures.min=-1) (op_mkdirs.failures.min=-1) (op_list_files.failures.min=-1) (committer_stage_file_upload.failures.min=-1) (stream_read_block_acquire_read.min=-1) (committer_magic_marker_put.min=-1) (object_put_request.failures.min=-1) (stream_read_remote_stream_aborted.failures.min=-1) (action_http_get_request.min=-1) (object_continue_list_request.failures.min=-1) (object_multipart_aborted.min=-1) (op_get_file_status.min=-1) (store_exists_probe.failures.min=-1) (action_http_head_request.failures.min=-1) (committer_stage_file_upload.min=-1) (op_mkdirs.min=-1) (op_rename.min=-1) (delegation_tokens_issued.failures.min=-1) (op_is_directory.failures.min=-1) (object_put_request.min=-1) (op_access.min=-1) (object_delete_request.min=-1) (op_xattr_get_named.min=-1) (committer_commit_job.min=-1) (object_bulk_delete_request.failures.min=-1) (mul
tipart_upload_list.min=-1) (op_list_status.min=-1) (stream_read_block_fetch_operations.failures.min=-1) (stream_read_remote_stream_drain.min=-1) (stream_read_block_fetch_operations.min=-1) (committer_load_single_pending_file.failures.min=-1) (stream_read_remote_stream_drain.failures.min=-1) (object_continue_list_request.min=-1) (op_get_content_summary.min=-1) (op_get_delegation_token.min=-1) (op_is_file.min=-1) (op_xattr_get_map.min=-1) (op_is_file.failures.min=-1) (stream_write_queue_duration.min=-1) (committer_materialize_file.min=-1) (op_rename.failures.min=-1) (op_list_files.min=-1) (op_xattr_get_named_map.min=-1) (op_glob_status.min=-1) (op_get_delegation_token.failures.min=-1) (op_copy_from_local_file.failures.min=-1) (op_xattr_get_map.failures.min=-1) (object_multipart_list.min=-1) (op_access.failures.min=-1) (op_exists.min=-1) (object_multipart_initiated.failures.min=-1) (op_delete.failures.min=-1) (committer_magic_marker_put.failures.min=-1) (op_get_file_checksum.min=-1) (o
p_delete.min=-1) (object_bulk_delete_request.min=-1) (object_list_request.failures.min=-1) (committer_commit_job.failures.min=-1) (op_xattr_get_named.failures.min=-1) (action_file_opened.min=-1) (committer_load_single_pending_file.min=-1) (op_copy_from_local_file.min=-1) (action_executor_acquired.failures.min=-1) (store_exists_probe.min=-1));
maximums=((object_delete_request.max=-1) (op_is_file.max=-1) (object_multipart_initiated.failures.max=-1) (action_http_get_request.failures.max=-1) (op_xattr_get_named_map.max=-1) (op_mkdirs.failures.max=-1) (action_http_head_request.max=-1) (op_createfile.max=-1) (action_executor_acquired.max=-1) (op_list_files.failures.max=-1) (stream_read_remote_stream_aborted.max=-1) (stream_read_remote_stream_drain.max=-1) (op_abort.failures.max=-1) (stream_write_queue_duration.failures.max=-1) (op_get_content_summary.max=-1) (object_continue_list_request.failures.max=-1) (op_get_delegation_token.max=-1) (op_xattr_get_map.max=-1) (object_continue_list_request.max=-1) (committer_materialize_file.max=-1) (action_http_head_request.failures.max=-1) (delegation_tokens_issued.max=-1) (op_rename.max=-1) (object_bulk_delete_request.failures.max=-1) (store_exists_probe.failures.max=-1) (op_create.max=-1) (stream_read_block_fetch_operations.max=-1) (op_get_file_status.failures.max=-1) (op_is_directory.
failures.max=-1) (object_multipart_aborted.failures.max=-1) (op_create.failures.max=-1) (op_copy_from_local_file.max=-1) (stream_read_block_acquire_read.max=-1) (op_xattr_list.failures.max=-1) (op_xattr_get_named_map.failures.max=-1) (op_get_content_summary.failures.max=-1) (object_multipart_list.max=-1) (op_glob_status.failures.max=-1) (op_get_file_status.max=-1) (op_exists.failures.max=-1) (op_access.max=-1) (object_list_request.max=-1) (committer_commit_job.failures.max=-1) (stream_read_block_fetch_operations.failures.max=-1) (op_delete.failures.max=-1) (op_mkdirs.max=-1) (op_get_delegation_token.failures.max=-1) (op_rename.failures.max=-1) (committer_load_single_pending_file.max=-1) (op_list_status.failures.max=-1) (stream_file_cache_eviction.max=-1) (op_is_file.failures.max=-1) (committer_magic_marker_put.max=-1) (op_exists.max=-1) (multipart_upload_list.max=-1) (op_xattr_get_named.max=-1) (store_exists_probe.max=-1) (op_list_status.max=-1) (action_http_get_request.max=-1) (act
ion_file_opened.max=-1) (committer_magic_marker_put.failures.max=-1) (action_executor_acquired.failures.max=-1) (op_createfile.failures.max=-1) (object_put_request.failures.max=-1) (committer_stage_file_upload.max=-1) (action_file_opened.failures.max=-1) (stream_read_remote_stream_drain.failures.max=-1) (op_copy_from_local_file.failures.max=-1) (op_access.failures.max=-1) (op_delete.max=-1) (object_put_request.max=-1) (stream_read_remote_stream_aborted.failures.max=-1) (op_is_directory.max=-1) (committer_load_single_pending_file.failures.max=-1) (object_multipart_list.failures.max=-1) (object_bulk_delete_request.max=-1) (stream_read_block_acquire_read.failures.max=-1) (op_abort.max=-1) (object_list_request.failures.max=-1) (op_get_file_checksum.failures.max=-1) (object_multipart_initiated.max=-1) (committer_stage_file_upload.failures.max=-1) (op_list_files.max=-1) (op_xattr_get_named.failures.max=-1) (multipart_upload_list.failures.max=-1) (object_multipart_aborted.max=-1) (op_get_f
ile_checksum.max=-1) (delegation_tokens_issued.failures.max=-1) (stream_write_queue_duration.max=-1) (op_xattr_list.max=-1) (committer_commit_job.max=-1) (stream_file_cache_eviction.failures.max=-1) (op_xattr_get_map.failures.max=-1) (object_delete_request.failures.max=-1) (committer_materialize_file.failures.max=-1) (op_glob_status.max=-1));
means=((op_access.failures.mean=(samples=0, sum=0, mean=0.0000)) (stream_read_remote_stream_aborted.failures.mean=(samples=0, sum=0, mean=0.0000)) (stream_write_queue_duration.mean=(samples=0, sum=0, mean=0.0000)) (op_get_delegation_token.failures.mean=(samples=0, sum=0, mean=0.0000)) (stream_file_cache_eviction.mean=(samples=0, sum=0, mean=0.0000)) (op_is_directory.mean=(samples=0, sum=0, mean=0.0000)) (op_xattr_get_named_map.mean=(samples=0, sum=0, mean=0.0000)) (committer_magic_marker_put.failures.mean=(samples=0, sum=0, mean=0.0000)) (op_get_delegation_token.mean=(samples=0, sum=0, mean=0.0000)) (action_executor_acquired.failures.mean=(samples=0, sum=0, mean=0.0000)) (action_http_head_request.mean=(samples=0, sum=0, mean=0.0000)) (delegation_tokens_issued.mean=(samples=0, sum=0, mean=0.0000)) (op_glob_status.failures.mean=(samples=0, sum=0, mean=0.0000)) (op_is_file.mean=(samples=0, sum=0, mean=0.0000)) (committer_load_single_pending_file.failures.mean=(samples=0, sum=0, mean=
0.0000)) (object_put_request.mean=(samples=0, sum=0, mean=0.0000)) (object_delete_request.failures.mean=(samples=0, sum=0, mean=0.0000)) (op_is_file.failures.mean=(samples=0, sum=0, mean=0.0000)) (action_file_opened.mean=(samples=0, sum=0, mean=0.0000)) (committer_load_single_pending_file.mean=(samples=0, sum=0, mean=0.0000)) (object_multipart_initiated.mean=(samples=0, sum=0, mean=0.0000)) (stream_read_block_fetch_operations.failures.mean=(samples=0, sum=0, mean=0.0000)) (op_get_file_checksum.failures.mean=(samples=0, sum=0, mean=0.0000)) (committer_stage_file_upload.mean=(samples=0, sum=0, mean=0.0000)) (op_get_file_status.failures.mean=(samples=0, sum=0, mean=0.0000)) (stream_read_remote_stream_drain.mean=(samples=0, sum=0, mean=0.0000)) (op_xattr_get_map.failures.mean=(samples=0, sum=0, mean=0.0000)) (object_list_request.mean=(samples=0, sum=0, mean=0.0000)) (op_glob_status.mean=(samples=0, sum=0, mean=0.0000)) (object_multipart_initiated.failures.mean=(samples=0, sum=0, mean=0.
0000)) (op_create.failures.mean=(samples=0, sum=0, mean=0.0000)) (object_continue_list_request.failures.mean=(samples=0, sum=0, mean=0.0000)) (object_bulk_delete_request.failures.mean=(samples=0, sum=0, mean=0.0000)) (op_copy_from_local_file.failures.mean=(samples=0, sum=0, mean=0.0000)) (action_executor_acquired.mean=(samples=0, sum=0, mean=0.0000)) (committer_stage_file_upload.failures.mean=(samples=0, sum=0, mean=0.0000)) (op_copy_from_local_file.mean=(samples=0, sum=0, mean=0.0000)) (action_file_opened.failures.mean=(samples=0, sum=0, mean=0.0000)) (op_list_files.mean=(samples=0, sum=0, mean=0.0000)) (op_abort.mean=(samples=0, sum=0, mean=0.0000)) (op_createfile.failures.mean=(samples=0, sum=0, mean=0.0000)) (stream_file_cache_eviction.failures.mean=(samples=0, sum=0, mean=0.0000)) (op_get_file_status.mean=(samples=0, sum=0, mean=0.0000)) (multipart_upload_list.mean=(samples=0, sum=0, mean=0.0000)) (object_list_request.failures.mean=(samples=0, sum=0, mean=0.0000)) (object_multi
part_list.failures.mean=(samples=0, sum=0, mean=0.0000)) (op_list_status.mean=(samples=0, sum=0, mean=0.0000)) (op_xattr_get_map.mean=(samples=0, sum=0, mean=0.0000)) (store_exists_probe.failures.mean=(samples=0, sum=0, mean=0.0000)) (committer_commit_job.mean=(samples=0, sum=0, mean=0.0000)) (op_delete.failures.mean=(samples=0, sum=0, mean=0.0000)) (op_xattr_get_named.mean=(samples=0, sum=0, mean=0.0000)) (stream_read_remote_stream_drain.failures.mean=(samples=0, sum=0, mean=0.0000)) (op_rename.mean=(samples=0, sum=0, mean=0.0000)) (op_get_file_checksum.mean=(samples=0, sum=0, mean=0.0000)) (stream_read_remote_stream_aborted.mean=(samples=0, sum=0, mean=0.0000)) (store_exists_probe.mean=(samples=0, sum=0, mean=0.0000)) (op_mkdirs.mean=(samples=0, sum=0, mean=0.0000)) (op_create.mean=(samples=0, sum=0, mean=0.0000)) (committer_materialize_file.mean=(samples=0, sum=0, mean=0.0000)) (op_get_content_summary.mean=(samples=0, sum=0, mean=0.0000)) (op_list_files.failures.mean=(samples=0,
sum=0, mean=0.0000)) (stream_read_block_acquire_read.failures.mean=(samples=0, sum=0, mean=0.0000)) (op_abort.failures.mean=(samples=0, sum=0, mean=0.0000)) (op_delete.mean=(samples=0, sum=0, mean=0.0000)) (op_xattr_list.failures.mean=(samples=0, sum=0, mean=0.0000)) (op_is_directory.failures.mean=(samples=0, sum=0, mean=0.0000)) (op_xattr_get_named_map.failures.mean=(samples=0, sum=0, mean=0.0000)) (stream_write_queue_duration.failures.mean=(samples=0, sum=0, mean=0.0000)) (object_delete_request.mean=(samples=0, sum=0, mean=0.0000)) (object_continue_list_request.mean=(samples=0, sum=0, mean=0.0000)) (op_get_content_summary.failures.mean=(samples=0, sum=0, mean=0.0000)) (stream_read_block_fetch_operations.mean=(samples=0, sum=0, mean=0.0000)) (object_put_request.failures.mean=(samples=0, sum=0, mean=0.0000)) (object_bulk_delete_request.mean=(samples=0, sum=0, mean=0.0000)) (stream_read_block_acquire_read.mean=(samples=0, sum=0, mean=0.0000)) (delegation_tokens_issued.failures.mean=(
samples=0, sum=0, mean=0.0000)) (op_rename.failures.mean=(samples=0, sum=0, mean=0.0000)) (committer_commit_job.failures.mean=(samples=0, sum=0, mean=0.0000)) (action_http_head_request.failures.mean=(samples=0, sum=0, mean=0.0000)) (op_xattr_list.mean=(samples=0, sum=0, mean=0.0000)) (committer_magic_marker_put.mean=(samples=0, sum=0, mean=0.0000)) (op_exists.failures.mean=(samples=0, sum=0, mean=0.0000)) (op_list_status.failures.mean=(samples=0, sum=0, mean=0.0000)) (op_access.mean=(samples=0, sum=0, mean=0.0000)) (object_multipart_aborted.mean=(samples=0, sum=0, mean=0.0000)) (action_http_get_request.mean=(samples=0, sum=0, mean=0.0000)) (op_exists.mean=(samples=0, sum=0, mean=0.0000)) (op_xattr_get_named.failures.mean=(samples=0, sum=0, mean=0.0000)) (action_http_get_request.failures.mean=(samples=0, sum=0, mean=0.0000)) (multipart_upload_list.failures.mean=(samples=0, sum=0, mean=0.0000)) (object_multipart_aborted.failures.mean=(samples=0, sum=0, mean=0.0000)) (op_createfile.mea
n=(samples=0, sum=0, mean=0.0000)) (op_mkdirs.failures.mean=(samples=0, sum=0, mean=0.0000)) (object_multipart_list.mean=(samples=0, sum=0, mean=0.0000)) (committer_materialize_file.failures.mean=(samples=0, sum=0, mean=0.0000)));
}}, ClientSideEncryption=false}
2024-04-24 15:57:24,455 [setup] DEBUG impl.MkdirOperation (MkdirOperation.java:execute(94)) - Making directory: s3a://stevel-london/test
2024-04-24 15:57:24,455 [setup] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:innerGetFileStatus(3950)) - Getting path status for s3a://stevel-london/test (test); needEmptyDirectory=false
2024-04-24 15:57:24,455 [setup] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:s3GetFileStatus(4009)) - S3GetFileStatus s3a://stevel-london/test
2024-04-24 15:57:24,455 [setup] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:listObjects(2965)) - LIST List stevel-london:/test/ delimiter=/ keys=2 requester pays=null
2024-04-24 15:57:24,455 [setup] DEBUG s3a.S3AFileSystem (DurationInfo.java:<init>(80)) - Starting: LIST
2024-04-24 15:57:24,456 [setup] DEBUG s3a.Invoker (DurationInfo.java:<init>(80)) - Starting: create credentials
2024-04-24 15:57:24,456 [setup] DEBUG s3a.Invoker (DurationInfo.java:close(101)) - create credentials: duration 0:00.000s
2024-04-24 15:57:24,456 [setup] DEBUG s3a.AWSCredentialProviderList (AWSCredentialProviderList.java:resolveCredentials(195)) - No credentials from TemporaryAWSCredentialsProvider: org.apache.hadoop.fs.s3a.auth.NoAwsCredentialsException: Session credentials in Hadoop configuration: No AWS Credentials
2024-04-24 15:57:24,456 [setup] DEBUG s3a.AWSCredentialProviderList (AWSCredentialProviderList.java:resolveCredentials(182)) - Using credentials from SimpleAWSCredentialsProvider{accessKey.empty=false, secretKey.empty=false}
2024-04-24 15:57:24,457 [setup] DEBUG impl.LoggingAuditor (LoggingAuditor.java:modifyHttpRequest(400)) - [11] e40ad9fb-842f-43ee-8784-912d440e2355-00000008 Executing op_mkdirs with {object_list_request 'test/' size=2, mutating=false}; https://audit.example.org/hadoop/1/op_mkdirs/e40ad9fb-842f-43ee-8784-912d440e2355-00000008/?op=op_mkdirs&p1=test&pr=stevel&ps=d8c4e4fc-c0aa-48d0-9605-2bf9ed7b08b2&id=e40ad9fb-842f-43ee-8784-912d440e2355-00000008&t0=11&fs=e40ad9fb-842f-43ee-8784-912d440e2355&t1=11&ts=1713970644455
2024-04-24 15:57:24,848 [setup] DEBUG s3a.S3AFileSystem (DurationInfo.java:close(101)) - LIST: duration 0:00.393s
2024-04-24 15:57:24,849 [setup] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:s3GetFileStatus(4073)) - Found path as directory (with /)
2024-04-24 15:57:24,849 [setup] DEBUG s3a.S3AFileSystem (S3ListResult.java:logAtDebug(146)) - Prefix count = 0; object count=1
2024-04-24 15:57:24,849 [setup] DEBUG s3a.S3AFileSystem (S3ListResult.java:logAtDebug(149)) - Summary: test/ 0
2024-04-24 15:57:24,862 [setup] DEBUG s3a.S3ATestUtils (S3ATestUtils.java:removeBucketOverrides(914)) - Removing option fs.s3a.bucket.stevel-london.directory.marker.retention; was keep
2024-04-24 15:57:24,863 [setup] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:initialize(549)) - Initializing S3AFileSystem for noaa-cors-pds
2024-04-24 15:57:24,863 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:propagateBucketOptions(1103)) - Propagating entries under fs.s3a.bucket.noaa-cors-pds.
2024-04-24 15:57:24,865 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:propagateBucketOptions(1124)) - Updating fs.s3a.endpoint.region from [core-site.xml]
2024-04-24 15:57:24,865 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:maybeIsolateClassloader(1708)) - Configuration classloader set to S3AFileSystem classloader: sun.misc.Launcher$AppClassLoader@18b4aac2
2024-04-24 15:57:24,865 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:buildEncryptionSecrets(1493)) - Data is unencrypted
2024-04-24 15:57:24,865 [setup] DEBUG s3a.S3ARetryPolicy (S3ARetryPolicy.java:<init>(145)) - Retrying on recoverable AWS failures 3 times with an initial interval of 500ms
2024-04-24 15:57:24,868 [setup] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:initialize(605)) - Client Side Encryption enabled: false
2024-04-24 15:57:24,868 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:intOption(909)) - Value of fs.s3a.paging.maximum is 5000
2024-04-24 15:57:24,868 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:longBytesOption(952)) - Value of fs.s3a.block.size is 33554432
2024-04-24 15:57:24,868 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:longBytesOption(952)) - Value of fs.s3a.prefetch.block.size is 131072
2024-04-24 15:57:24,868 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:intOption(909)) - Value of fs.s3a.prefetch.block.count is 8
2024-04-24 15:57:24,868 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:intOption(909)) - Value of fs.s3a.max.total.tasks is 32
2024-04-24 15:57:24,868 [setup] DEBUG impl.ConfigurationHelper (ConfigurationHelper.java:getDuration(80)) - Duration of fs.s3a.threads.keepalivetime = PT1M
2024-04-24 15:57:24,868 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:intOption(909)) - Value of fs.s3a.executor.capacity is 16
2024-04-24 15:57:24,869 [setup] DEBUG auth.SignerManager (SignerManager.java:initCustomSigners(68)) - No custom signers specified
2024-04-24 15:57:24,869 [setup] DEBUG audit.AuditIntegration (AuditIntegration.java:createAndInitAuditor(109)) - Auditor class is class org.apache.hadoop.fs.s3a.audit.impl.LoggingAuditor
2024-04-24 15:57:24,869 [setup] DEBUG impl.ActiveAuditManagerS3A (ActiveAuditManagerS3A.java:serviceInit(199)) - Audit manager initialized with audit service LoggingAuditor{ID='8ccb4ca6-435a-4ba8-b138-ac7140a2c673', headerEnabled=true, rejectOutOfSpan=true, isMultipartUploadEnabled=true}
2024-04-24 15:57:24,869 [setup] DEBUG impl.ActiveAuditManagerS3A (ActiveAuditManagerS3A.java:serviceStart(212)) - Started audit service LoggingAuditor{ID='8ccb4ca6-435a-4ba8-b138-ac7140a2c673', headerEnabled=true, rejectOutOfSpan=true, isMultipartUploadEnabled=true}
2024-04-24 15:57:24,869 [setup] DEBUG audit.AuditIntegration (AuditIntegration.java:createAndStartAuditManager(76)) - Started Audit Manager Service ActiveAuditManagerS3A in state ActiveAuditManagerS3A: STARTED, auditor=LoggingAuditor{ID='8ccb4ca6-435a-4ba8-b138-ac7140a2c673', headerEnabled=true, rejectOutOfSpan=true, isMultipartUploadEnabled=true}}
2024-04-24 15:57:24,869 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:longOption(930)) - Value of fs.s3a.internal.upload.part.count.limit is 10000
2024-04-24 15:57:24,870 [setup] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:createRequestFactory(1202)) - Unset storage class property fs.s3a.create.storage.class; falling back to default storage class
2024-04-24 15:57:24,870 [setup] DEBUG auth.CredentialProviderListFactory (CredentialProviderListFactory.java:createAWSV2CredentialProvider(306)) - Credential provider class is org.apache.hadoop.fs.s3a.TemporaryAWSCredentialsProvider
2024-04-24 15:57:24,870 [setup] DEBUG auth.CredentialProviderListFactory (CredentialProviderListFactory.java:createAWSV2CredentialProvider(306)) - Credential provider class is org.apache.hadoop.fs.s3a.SimpleAWSCredentialsProvider
2024-04-24 15:57:24,870 [setup] DEBUG auth.CredentialProviderListFactory (CredentialProviderListFactory.java:createAWSCredentialProviderList(151)) - For URI s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz, using credentials AWSCredentialProviderList name=; refcount= 1; size=2: [TemporaryAWSCredentialsProvider, SimpleAWSCredentialsProvider{accessKey.empty=false, secretKey.empty=false}]
2024-04-24 15:57:24,870 [setup] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:bindAWSClient(1047)) - Using credential provider AWSCredentialProviderList name=; refcount= 1; size=2: [TemporaryAWSCredentialsProvider, SimpleAWSCredentialsProvider{accessKey.empty=false, secretKey.empty=false}]
2024-04-24 15:57:24,870 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:intOption(909)) - Value of fs.s3a.connection.maximum is 512
2024-04-24 15:57:24,870 [setup] DEBUG impl.ConfigurationHelper (ConfigurationHelper.java:getDuration(80)) - Duration of fs.s3a.connection.acquisition.timeout = PT1M
2024-04-24 15:57:24,870 [setup] DEBUG impl.ConfigurationHelper (ConfigurationHelper.java:getDuration(80)) - Duration of fs.s3a.connection.ttl = PT5M
2024-04-24 15:57:24,870 [setup] DEBUG impl.ConfigurationHelper (ConfigurationHelper.java:getDuration(80)) - Duration of fs.s3a.connection.establish.timeout = PT30S
2024-04-24 15:57:24,870 [setup] DEBUG impl.ConfigurationHelper (ConfigurationHelper.java:getDuration(80)) - Duration of fs.s3a.connection.idle.time = PT1M
2024-04-24 15:57:24,870 [setup] DEBUG impl.ConfigurationHelper (ConfigurationHelper.java:getDuration(80)) - Duration of fs.s3a.connection.timeout = PT25S
2024-04-24 15:57:24,871 [setup] DEBUG s3a.DefaultS3ClientFactory (DefaultS3ClientFactory.java:configureEndpointAndRegion(353)) - Setting region to us-east-1 from fs.s3a.endpoint.region
2024-04-24 15:57:24,871 [setup] DEBUG s3a.DefaultS3ClientFactory (DefaultS3ClientFactory.java:maybeApplyS3AccessGrantsConfigurations(419)) - S3 Access Grants plugin is not enabled.
2024-04-24 15:57:24,871 [setup] DEBUG impl.ConfigurationHelper (ConfigurationHelper.java:getDuration(80)) - Duration of fs.s3a.connection.request.timeout = PT1M
2024-04-24 15:57:24,871 [setup] DEBUG impl.AWSClientConfig (AWSClientConfig.java:initUserAgent(375)) - Using User-Agent: Hadoop 3.5.0-SNAPSHOT
2024-04-24 15:57:24,871 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:intOption(909)) - Value of fs.s3a.attempts.maximum is 2
2024-04-24 15:57:24,876 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:intOption(909)) - Value of fs.s3a.connection.maximum is 512
2024-04-24 15:57:24,877 [setup] DEBUG impl.ConfigurationHelper (ConfigurationHelper.java:getDuration(80)) - Duration of fs.s3a.connection.acquisition.timeout = PT1M
2024-04-24 15:57:24,877 [setup] DEBUG impl.ConfigurationHelper (ConfigurationHelper.java:getDuration(80)) - Duration of fs.s3a.connection.ttl = PT5M
2024-04-24 15:57:24,877 [setup] DEBUG impl.ConfigurationHelper (ConfigurationHelper.java:getDuration(80)) - Duration of fs.s3a.connection.establish.timeout = PT30S
2024-04-24 15:57:24,877 [setup] DEBUG impl.ConfigurationHelper (ConfigurationHelper.java:getDuration(80)) - Duration of fs.s3a.connection.idle.time = PT1M
2024-04-24 15:57:24,877 [setup] DEBUG impl.ConfigurationHelper (ConfigurationHelper.java:getDuration(80)) - Duration of fs.s3a.connection.timeout = PT25S
2024-04-24 15:57:24,877 [setup] DEBUG s3a.DefaultS3ClientFactory (DefaultS3ClientFactory.java:configureEndpointAndRegion(353)) - Setting region to us-east-1 from fs.s3a.endpoint.region
2024-04-24 15:57:24,877 [setup] DEBUG s3a.DefaultS3ClientFactory (DefaultS3ClientFactory.java:maybeApplyS3AccessGrantsConfigurations(419)) - S3 Access Grants plugin is not enabled.
2024-04-24 15:57:24,877 [setup] DEBUG impl.ConfigurationHelper (ConfigurationHelper.java:getDuration(80)) - Duration of fs.s3a.connection.request.timeout = PT1M
2024-04-24 15:57:24,877 [setup] DEBUG impl.AWSClientConfig (AWSClientConfig.java:initUserAgent(375)) - Using User-Agent: Hadoop 3.5.0-SNAPSHOT
2024-04-24 15:57:24,877 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:intOption(909)) - Value of fs.s3a.attempts.maximum is 2
2024-04-24 15:57:24,880 [setup] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:doBucketProbing(831)) - skipping check for bucket existence
2024-04-24 15:57:24,880 [setup] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:initialize(696)) - Input fadvise policy = default
2024-04-24 15:57:24,880 [setup] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:initialize(698)) - Change detection policy = ETagChangeDetectionPolicy mode=Server
2024-04-24 15:57:24,880 [setup] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:initialize(702)) - Filesystem support for magic committers is enabled
2024-04-24 15:57:24,880 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:intOption(909)) - Value of fs.s3a.fast.upload.active.blocks is 4
2024-04-24 15:57:24,880 [setup] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:initialize(721)) - Using S3ABlockOutputStream with buffer = disk; block=67108864; queue limit=4; multipart=true
2024-04-24 15:57:24,880 [setup] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:initialize(731)) - fs.s3a.create.performance = false
2024-04-24 15:57:24,881 [setup] DEBUG impl.DirectoryPolicyImpl (DirectoryPolicyImpl.java:getDirectoryPolicy(189)) - Directory markers will be kept
2024-04-24 15:57:24,881 [setup] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:initialize(737)) - Directory marker retention policy is DirectoryMarkerRetention{policy='keep'}
2024-04-24 15:57:24,881 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:intOption(909)) - Value of fs.s3a.bulk.delete.page.size is 250
2024-04-24 15:57:24,881 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:longBytesOption(952)) - Value of fs.s3a.readahead.range is 32768
2024-04-24 15:57:24,881 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:intOption(909)) - Value of io.file.buffer.size is 4194304
2024-04-24 15:57:24,881 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:longBytesOption(952)) - Value of fs.s3a.input.async.drain.threshold is 1024
2024-04-24 15:57:24,881 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:intOption(909)) - Value of fs.s3a.vectored.active.ranged.reads is 4
2024-04-24 15:57:24,881 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:longBytesOption(952)) - Value of fs.s3a.vectored.read.min.seek.size is 4096
2024-04-24 15:57:24,881 [setup] DEBUG s3a.S3AUtils (S3AUtils.java:longBytesOption(952)) - Value of fs.s3a.vectored.read.max.merged.size is 1048576
2024-04-24 15:57:24,881 [setup] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:initialize(763)) - Using optimized copyFromLocal implementation: true
2024-04-24 15:57:24,881 [setup] INFO contract.AbstractFSContractTestBase (AbstractFSContractTestBase.java:describe(280)) - Verify that FS cache files exist on local FS
2024-04-24 15:57:24,885 [setup] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:innerGetFileStatus(3950)) - Getting path status for s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz (raw/2023/017/ohfh/OHFH017d.23_.gz); needEmptyDirectory=false
2024-04-24 15:57:24,885 [setup] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:s3GetFileStatus(4009)) - S3GetFileStatus s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz
2024-04-24 15:57:24,885 [setup] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:lambda$getObjectMetadata$10(2903)) - HEAD raw/2023/017/ohfh/OHFH017d.23_.gz with change tracker null
2024-04-24 15:57:24,886 [setup] DEBUG s3a.Invoker (DurationInfo.java:<init>(80)) - Starting: create credentials
2024-04-24 15:57:24,886 [setup] DEBUG s3a.Invoker (DurationInfo.java:close(101)) - create credentials: duration 0:00.000s
2024-04-24 15:57:24,886 [setup] DEBUG s3a.AWSCredentialProviderList (AWSCredentialProviderList.java:resolveCredentials(195)) - No credentials from TemporaryAWSCredentialsProvider: org.apache.hadoop.fs.s3a.auth.NoAwsCredentialsException: Session credentials in Hadoop configuration: No AWS Credentials
2024-04-24 15:57:24,886 [setup] DEBUG s3a.AWSCredentialProviderList (AWSCredentialProviderList.java:resolveCredentials(182)) - Using credentials from SimpleAWSCredentialsProvider{accessKey.empty=false, secretKey.empty=false}
2024-04-24 15:57:24,887 [setup] DEBUG impl.LoggingAuditor (LoggingAuditor.java:modifyHttpRequest(400)) - [11] 8ccb4ca6-435a-4ba8-b138-ac7140a2c673-00000011 Executing op_open with {action_http_head_request 'raw/2023/017/ohfh/OHFH017d.23_.gz' size=0, mutating=false}; https://audit.example.org/hadoop/1/op_open/8ccb4ca6-435a-4ba8-b138-ac7140a2c673-00000011/?op=op_open&p1=raw/2023/017/ohfh/OHFH017d.23_.gz&pr=stevel&ps=d8c4e4fc-c0aa-48d0-9605-2bf9ed7b08b2&id=8ccb4ca6-435a-4ba8-b138-ac7140a2c673-00000011&t0=11&fs=8ccb4ca6-435a-4ba8-b138-ac7140a2c673&t1=11&ts=1713970644885
2024-04-24 15:57:25,279 [setup] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:s3GetFileStatus(4025)) - Found exact file: normal file raw/2023/017/ohfh/OHFH017d.23_.gz
2024-04-24 15:57:25,283 [setup] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:executeOpen(1764)) - Opening 'S3AReadOpContext{path=s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz, inputPolicy=default, readahead=32768, changeDetectionPolicy=ETagChangeDetectionPolicy mode=Server}'
2024-04-24 15:57:25,291 [setup] DEBUG prefetch.S3APrefetchingInputStream (S3APrefetchingInputStream.java:<init>(118)) - Creating caching input stream for s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz
2024-04-24 15:57:25,293 [setup] DEBUG impl.ChangeTracker (ChangeTracker.java:<init>(98)) - Tracker ETagChangeDetectionPolicy mode=Server has revision ID for object at s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz: "3825f3178ed5c22fd7bbadbdddb65509-3"
2024-04-24 15:57:25,296 [setup] DEBUG prefetch.S3ACachingInputStream (S3ACachingInputStream.java:demandCreateBlockManager(109)) - s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz: creating block manager
2024-04-24 15:57:25,306 [setup] DEBUG prefetch.S3ACachingInputStream (S3ACachingInputStream.java:<init>(96)) - Created caching input stream for s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz (size = 21511174)
2024-04-24 15:57:25,307 [setup] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:requestPrefetch(278)) - s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz: Requesting prefetch for block 1
2024-04-24 15:57:25,307 [setup] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:requestPrefetch(284)) - s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz: acquired [001] id: 994329416, State: EMPTY: buffer: (id = 304436027, pos = 0, lim = 131072), checksum: 0, future: (none)
2024-04-24 15:57:25,308 [setup] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - --- requestPrefetch(1)
2024-04-24 15:57:25,309 [setup] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - *** requestPrefetch(1)
2024-04-24 15:57:25,309 [setup] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:requestPrefetch(278)) - s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz: Requesting prefetch for block 2
2024-04-24 15:57:25,309 [s3a-transfer-noaa-cors-pds-bounded-pool6-t1] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - --- prefetch(1)
2024-04-24 15:57:25,309 [setup] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:requestPrefetch(284)) - s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz: acquired [002] id: 1529096865, State: EMPTY: buffer: (id = 1510469437, pos = 0, lim = 131072), checksum: 0, future: (none)
2024-04-24 15:57:25,309 [setup] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - --- requestPrefetch(2)
2024-04-24 15:57:25,309 [setup] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - *** requestPrefetch(2)
2024-04-24 15:57:25,310 [setup] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:requestPrefetch(278)) - s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz: Requesting prefetch for block 3
2024-04-24 15:57:25,310 [s3a-transfer-noaa-cors-pds-bounded-pool6-t2] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - --- prefetch(2)
2024-04-24 15:57:25,310 [setup] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:requestPrefetch(284)) - s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz: acquired [003] id: 58234618, State: EMPTY: buffer: (id = 1717825455, pos = 0, lim = 131072), checksum: 0, future: (none)
2024-04-24 15:57:25,310 [setup] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - --- requestPrefetch(3)
2024-04-24 15:57:25,310 [setup] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - *** requestPrefetch(3)
2024-04-24 15:57:25,310 [setup] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:requestPrefetch(278)) - s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz: Requesting prefetch for block 4
2024-04-24 15:57:25,310 [s3a-transfer-noaa-cors-pds-bounded-pool6-t2] DEBUG s3a.Invoker (DurationInfo.java:<init>(80)) - Starting: read s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz [262144-393216]
2024-04-24 15:57:25,310 [s3a-transfer-noaa-cors-pds-bounded-pool6-t3] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - --- prefetch(3)
2024-04-24 15:57:25,310 [s3a-transfer-noaa-cors-pds-bounded-pool6-t1] DEBUG s3a.Invoker (DurationInfo.java:<init>(80)) - Starting: read s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz [131072-262144]
2024-04-24 15:57:25,310 [s3a-transfer-noaa-cors-pds-bounded-pool6-t3] DEBUG s3a.Invoker (DurationInfo.java:<init>(80)) - Starting: read s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz [393216-524288]
2024-04-24 15:57:25,310 [setup] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:requestPrefetch(284)) - s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz: acquired [004] id: 109870965, State: EMPTY: buffer: (id = 2146170524, pos = 0, lim = 131072), checksum: 0, future: (none)
2024-04-24 15:57:25,310 [setup] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - --- requestPrefetch(4)
2024-04-24 15:57:25,310 [setup] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - *** requestPrefetch(4)
2024-04-24 15:57:25,310 [setup] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:requestPrefetch(278)) - s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz: Requesting prefetch for block 5
2024-04-24 15:57:25,310 [s3a-transfer-noaa-cors-pds-bounded-pool6-t4] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - --- prefetch(4)
2024-04-24 15:57:25,310 [setup] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:requestPrefetch(284)) - s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz: acquired [005] id: 1263896387, State: EMPTY: buffer: (id = 1797965731, pos = 0, lim = 131072), checksum: 0, future: (none)
2024-04-24 15:57:25,310 [s3a-transfer-noaa-cors-pds-bounded-pool6-t4] DEBUG s3a.Invoker (DurationInfo.java:<init>(80)) - Starting: read s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz [524288-655360]
2024-04-24 15:57:25,310 [setup] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - --- requestPrefetch(5)
2024-04-24 15:57:25,311 [setup] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - *** requestPrefetch(5)
2024-04-24 15:57:25,311 [setup] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:requestPrefetch(278)) - s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz: Requesting prefetch for block 6
2024-04-24 15:57:25,311 [s3a-transfer-noaa-cors-pds-bounded-pool6-t5] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - --- prefetch(5)
2024-04-24 15:57:25,311 [setup] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:requestPrefetch(284)) - s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz: acquired [006] id: 1150889795, State: EMPTY: buffer: (id = 2041839532, pos = 0, lim = 131072), checksum: 0, future: (none)
2024-04-24 15:57:25,311 [setup] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - --- requestPrefetch(6)
2024-04-24 15:57:25,311 [s3a-transfer-noaa-cors-pds-bounded-pool6-t5] DEBUG s3a.Invoker (DurationInfo.java:<init>(80)) - Starting: read s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz [655360-786432]
2024-04-24 15:57:25,311 [setup] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - *** requestPrefetch(6)
2024-04-24 15:57:25,311 [setup] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:requestPrefetch(278)) - s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz: Requesting prefetch for block 7
2024-04-24 15:57:25,311 [s3a-transfer-noaa-cors-pds-bounded-pool6-t6] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - --- prefetch(6)
2024-04-24 15:57:25,311 [setup] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:requestPrefetch(284)) - s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz: acquired [007] id: 1792328953, State: EMPTY: buffer: (id = 217843856, pos = 0, lim = 131072), checksum: 0, future: (none)
2024-04-24 15:57:25,311 [s3a-transfer-noaa-cors-pds-bounded-pool6-t6] DEBUG s3a.Invoker (DurationInfo.java:<init>(80)) - Starting: read s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz [786432-917504]
2024-04-24 15:57:25,311 [setup] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - --- requestPrefetch(7)
2024-04-24 15:57:25,311 [setup] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - *** requestPrefetch(7)
2024-04-24 15:57:25,312 [setup] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:requestPrefetch(278)) - s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz: Requesting prefetch for block 8
2024-04-24 15:57:25,312 [s3a-transfer-noaa-cors-pds-bounded-pool6-t7] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - --- prefetch(7)
2024-04-24 15:57:25,312 [setup] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:requestPrefetch(284)) - s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz: acquired [008] id: 1916205902, State: EMPTY: buffer: (id = 518178064, pos = 0, lim = 131072), checksum: 0, future: (none)
2024-04-24 15:57:25,312 [setup] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - --- requestPrefetch(8)
2024-04-24 15:57:25,312 [s3a-transfer-noaa-cors-pds-bounded-pool6-t7] DEBUG s3a.Invoker (DurationInfo.java:<init>(80)) - Starting: read s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz [917504-1048576]
2024-04-24 15:57:25,312 [setup] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - *** requestPrefetch(8)
2024-04-24 15:57:25,312 [s3a-transfer-noaa-cors-pds-bounded-pool6-t8] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - --- prefetch(8)
2024-04-24 15:57:25,312 [s3a-transfer-noaa-cors-pds-bounded-pool6-t8] DEBUG s3a.Invoker (DurationInfo.java:<init>(80)) - Starting: read s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz [1048576-1179648]
2024-04-24 15:57:25,313 [setup] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - --- getRead(0)
2024-04-24 15:57:25,313 [setup] DEBUG s3a.Invoker (DurationInfo.java:<init>(80)) - Starting: read s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz [0-131072]
2024-04-24 15:57:25,315 [s3a-transfer-noaa-cors-pds-bounded-pool6-t1] DEBUG impl.ChangeDetectionPolicy (ChangeDetectionPolicy.java:applyRevisionConstraint(372)) - Restricting get request to etag "3825f3178ed5c22fd7bbadbdddb65509-3"
2024-04-24 15:57:25,315 [s3a-transfer-noaa-cors-pds-bounded-pool6-t6] DEBUG impl.ChangeDetectionPolicy (ChangeDetectionPolicy.java:applyRevisionConstraint(372)) - Restricting get request to etag "3825f3178ed5c22fd7bbadbdddb65509-3"
2024-04-24 15:57:25,315 [setup] DEBUG impl.ChangeDetectionPolicy (ChangeDetectionPolicy.java:applyRevisionConstraint(372)) - Restricting get request to etag "3825f3178ed5c22fd7bbadbdddb65509-3"
2024-04-24 15:57:25,315 [s3a-transfer-noaa-cors-pds-bounded-pool6-t7] DEBUG impl.ChangeDetectionPolicy (ChangeDetectionPolicy.java:applyRevisionConstraint(372)) - Restricting get request to etag "3825f3178ed5c22fd7bbadbdddb65509-3"
2024-04-24 15:57:25,315 [s3a-transfer-noaa-cors-pds-bounded-pool6-t4] DEBUG impl.ChangeDetectionPolicy (ChangeDetectionPolicy.java:applyRevisionConstraint(372)) - Restricting get request to etag "3825f3178ed5c22fd7bbadbdddb65509-3"
2024-04-24 15:57:25,315 [s3a-transfer-noaa-cors-pds-bounded-pool6-t2] DEBUG impl.ChangeDetectionPolicy (ChangeDetectionPolicy.java:applyRevisionConstraint(372)) - Restricting get request to etag "3825f3178ed5c22fd7bbadbdddb65509-3"
2024-04-24 15:57:25,315 [s3a-transfer-noaa-cors-pds-bounded-pool6-t3] DEBUG impl.ChangeDetectionPolicy (ChangeDetectionPolicy.java:applyRevisionConstraint(372)) - Restricting get request to etag "3825f3178ed5c22fd7bbadbdddb65509-3"
2024-04-24 15:57:25,315 [s3a-transfer-noaa-cors-pds-bounded-pool6-t5] DEBUG impl.ChangeDetectionPolicy (ChangeDetectionPolicy.java:applyRevisionConstraint(372)) - Restricting get request to etag "3825f3178ed5c22fd7bbadbdddb65509-3"
2024-04-24 15:57:25,315 [s3a-transfer-noaa-cors-pds-bounded-pool6-t8] DEBUG impl.ChangeDetectionPolicy (ChangeDetectionPolicy.java:applyRevisionConstraint(372)) - Restricting get request to etag "3825f3178ed5c22fd7bbadbdddb65509-3"
2024-04-24 15:57:25,322 [s3a-transfer-noaa-cors-pds-bounded-pool6-t6] DEBUG impl.LoggingAuditor (LoggingAuditor.java:modifyHttpRequest(400)) - [41] 8ccb4ca6-435a-4ba8-b138-ac7140a2c673-00000011 Executing op_open with {action_http_get_request 'raw/2023/017/ohfh/OHFH017d.23_.gz' size=131071, mutating=false}; range=786432-917503; https://audit.example.org/hadoop/1/op_open/8ccb4ca6-435a-4ba8-b138-ac7140a2c673-00000011/?op=op_open&p1=raw/2023/017/ohfh/OHFH017d.23_.gz&pr=stevel&ps=d8c4e4fc-c0aa-48d0-9605-2bf9ed7b08b2&rg=131072-262143&id=8ccb4ca6-435a-4ba8-b138-ac7140a2c673-00000011&t0=11&fs=8ccb4ca6-435a-4ba8-b138-ac7140a2c673&t1=41&ts=1713970644885
2024-04-24 15:57:25,322 [s3a-transfer-noaa-cors-pds-bounded-pool6-t8] DEBUG impl.LoggingAuditor (LoggingAuditor.java:modifyHttpRequest(400)) - [43] 8ccb4ca6-435a-4ba8-b138-ac7140a2c673-00000011 Executing op_open with {action_http_get_request 'raw/2023/017/ohfh/OHFH017d.23_.gz' size=131071, mutating=false}; range=1048576-1179647; https://audit.example.org/hadoop/1/op_open/8ccb4ca6-435a-4ba8-b138-ac7140a2c673-00000011/?op=op_open&p1=raw/2023/017/ohfh/OHFH017d.23_.gz&pr=stevel&ps=d8c4e4fc-c0aa-48d0-9605-2bf9ed7b08b2&rg=131072-262143&id=8ccb4ca6-435a-4ba8-b138-ac7140a2c673-00000011&t0=11&fs=8ccb4ca6-435a-4ba8-b138-ac7140a2c673&t1=41&ts=1713970644885
2024-04-24 15:57:25,322 [s3a-transfer-noaa-cors-pds-bounded-pool6-t4] DEBUG impl.LoggingAuditor (LoggingAuditor.java:modifyHttpRequest(400)) - [39] 8ccb4ca6-435a-4ba8-b138-ac7140a2c673-00000011 Executing op_open with {action_http_get_request 'raw/2023/017/ohfh/OHFH017d.23_.gz' size=131071, mutating=false}; range=524288-655359; https://audit.example.org/hadoop/1/op_open/8ccb4ca6-435a-4ba8-b138-ac7140a2c673-00000011/?op=op_open&p1=raw/2023/017/ohfh/OHFH017d.23_.gz&pr=stevel&ps=d8c4e4fc-c0aa-48d0-9605-2bf9ed7b08b2&rg=131072-262143&id=8ccb4ca6-435a-4ba8-b138-ac7140a2c673-00000011&t0=11&fs=8ccb4ca6-435a-4ba8-b138-ac7140a2c673&t1=41&ts=1713970644885
2024-04-24 15:57:25,322 [setup] DEBUG impl.LoggingAuditor (LoggingAuditor.java:modifyHttpRequest(400)) - [11] 8ccb4ca6-435a-4ba8-b138-ac7140a2c673-00000011 Executing op_open with {action_http_get_request 'raw/2023/017/ohfh/OHFH017d.23_.gz' size=131071, mutating=false}; range=0-131071; https://audit.example.org/hadoop/1/op_open/8ccb4ca6-435a-4ba8-b138-ac7140a2c673-00000011/?op=op_open&p1=raw/2023/017/ohfh/OHFH017d.23_.gz&pr=stevel&ps=d8c4e4fc-c0aa-48d0-9605-2bf9ed7b08b2&rg=131072-262143&id=8ccb4ca6-435a-4ba8-b138-ac7140a2c673-00000011&t0=11&fs=8ccb4ca6-435a-4ba8-b138-ac7140a2c673&t1=41&ts=1713970644885
2024-04-24 15:57:25,322 [s3a-transfer-noaa-cors-pds-bounded-pool6-t5] DEBUG impl.LoggingAuditor (LoggingAuditor.java:modifyHttpRequest(400)) - [40] 8ccb4ca6-435a-4ba8-b138-ac7140a2c673-00000011 Executing op_open with {action_http_get_request 'raw/2023/017/ohfh/OHFH017d.23_.gz' size=131071, mutating=false}; range=655360-786431; https://audit.example.org/hadoop/1/op_open/8ccb4ca6-435a-4ba8-b138-ac7140a2c673-00000011/?op=op_open&p1=raw/2023/017/ohfh/OHFH017d.23_.gz&pr=stevel&ps=d8c4e4fc-c0aa-48d0-9605-2bf9ed7b08b2&rg=655360-786431&id=8ccb4ca6-435a-4ba8-b138-ac7140a2c673-00000011&t0=11&fs=8ccb4ca6-435a-4ba8-b138-ac7140a2c673&t1=40&ts=1713970644885
2024-04-24 15:57:25,322 [s3a-transfer-noaa-cors-pds-bounded-pool6-t2] DEBUG impl.LoggingAuditor (LoggingAuditor.java:modifyHttpRequest(400)) - [37] 8ccb4ca6-435a-4ba8-b138-ac7140a2c673-00000011 Executing op_open with {action_http_get_request 'raw/2023/017/ohfh/OHFH017d.23_.gz' size=131071, mutating=false}; range=262144-393215; https://audit.example.org/hadoop/1/op_open/8ccb4ca6-435a-4ba8-b138-ac7140a2c673-00000011/?op=op_open&p1=raw/2023/017/ohfh/OHFH017d.23_.gz&pr=stevel&ps=d8c4e4fc-c0aa-48d0-9605-2bf9ed7b08b2&rg=131072-262143&id=8ccb4ca6-435a-4ba8-b138-ac7140a2c673-00000011&t0=11&fs=8ccb4ca6-435a-4ba8-b138-ac7140a2c673&t1=41&ts=1713970644885
2024-04-24 15:57:25,322 [s3a-transfer-noaa-cors-pds-bounded-pool6-t3] DEBUG impl.LoggingAuditor (LoggingAuditor.java:modifyHttpRequest(400)) - [38] 8ccb4ca6-435a-4ba8-b138-ac7140a2c673-00000011 Executing op_open with {action_http_get_request 'raw/2023/017/ohfh/OHFH017d.23_.gz' size=131071, mutating=false}; range=393216-524287; https://audit.example.org/hadoop/1/op_open/8ccb4ca6-435a-4ba8-b138-ac7140a2c673-00000011/?op=op_open&p1=raw/2023/017/ohfh/OHFH017d.23_.gz&pr=stevel&ps=d8c4e4fc-c0aa-48d0-9605-2bf9ed7b08b2&rg=131072-262143&id=8ccb4ca6-435a-4ba8-b138-ac7140a2c673-00000011&t0=11&fs=8ccb4ca6-435a-4ba8-b138-ac7140a2c673&t1=41&ts=1713970644885
2024-04-24 15:57:25,322 [s3a-transfer-noaa-cors-pds-bounded-pool6-t1] DEBUG impl.LoggingAuditor (LoggingAuditor.java:modifyHttpRequest(400)) - [36] 8ccb4ca6-435a-4ba8-b138-ac7140a2c673-00000011 Executing op_open with {action_http_get_request 'raw/2023/017/ohfh/OHFH017d.23_.gz' size=131071, mutating=false}; range=131072-262143; https://audit.example.org/hadoop/1/op_open/8ccb4ca6-435a-4ba8-b138-ac7140a2c673-00000011/?op=op_open&p1=raw/2023/017/ohfh/OHFH017d.23_.gz&pr=stevel&ps=d8c4e4fc-c0aa-48d0-9605-2bf9ed7b08b2&rg=131072-262143&id=8ccb4ca6-435a-4ba8-b138-ac7140a2c673-00000011&t0=11&fs=8ccb4ca6-435a-4ba8-b138-ac7140a2c673&t1=41&ts=1713970644885
2024-04-24 15:57:25,322 [s3a-transfer-noaa-cors-pds-bounded-pool6-t7] DEBUG impl.LoggingAuditor (LoggingAuditor.java:modifyHttpRequest(400)) - [42] 8ccb4ca6-435a-4ba8-b138-ac7140a2c673-00000011 Executing op_open with {action_http_get_request 'raw/2023/017/ohfh/OHFH017d.23_.gz' size=131071, mutating=false}; range=917504-1048575; https://audit.example.org/hadoop/1/op_open/8ccb4ca6-435a-4ba8-b138-ac7140a2c673-00000011/?op=op_open&p1=raw/2023/017/ohfh/OHFH017d.23_.gz&pr=stevel&ps=d8c4e4fc-c0aa-48d0-9605-2bf9ed7b08b2&rg=131072-262143&id=8ccb4ca6-435a-4ba8-b138-ac7140a2c673-00000011&t0=11&fs=8ccb4ca6-435a-4ba8-b138-ac7140a2c673&t1=41&ts=1713970644885
2024-04-24 15:57:25,623 [setup] DEBUG impl.SDKStreamDrainer (SDKStreamDrainer.java:drainOrAbortHttpStream(218)) - Closing stream
2024-04-24 15:57:25,623 [setup] DEBUG s3a.Invoker (DurationInfo.java:close(101)) - read s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz [0-131072]: duration 0:00.310s
2024-04-24 15:57:25,624 [setup] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:readBlock(409)) - Completed read of block 0 [0-131072]
2024-04-24 15:57:25,624 [setup] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - *** getRead(0)
2024-04-24 15:57:25,624 [setup] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:readBlock(435)) - fetch completed: Duration of stream_read_block_fetch_operations: 0:00.311s
2024-04-24 15:57:25,624 [setup] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:requestCaching(517)) - s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz: Block 0: request caching of [000] id: 1299545752, State: READY: buffer: (id = 1384379967, pos = 0, lim = 131072), checksum: 3320762083, future: (none)
2024-04-24 15:57:25,624 [setup] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - --- requestCaching(0)
2024-04-24 15:57:25,625 [setup] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - *** requestCaching(0)
2024-04-24 15:57:25,625 [s3a-transfer-noaa-cors-pds-bounded-pool6-t9] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:addToCacheAndRelease(575)) - s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz: Block 0: Preparing to cache block
2024-04-24 15:57:25,625 [s3a-transfer-noaa-cors-pds-bounded-pool6-t9] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:addToCacheAndRelease(582)) - s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz: Block 0: awaiting any read to complete
2024-04-24 15:57:25,625 [setup] DEBUG prefetch.S3ACachingInputStream (S3ACachingInputStream.java:ensureCurrentBuffer(215)) - lazy-seek(2:262144)
2024-04-24 15:57:25,625 [setup] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:cancelPrefetches(315)) - s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz: Cancelling prefetches: RandomIO
2024-04-24 15:57:25,626 [setup] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - ... cancelPrefetches()
2024-04-24 15:57:25,626 [setup] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:requestCaching(517)) - s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz: Block 2: request caching of [002] id: 1529096865, State: PREFETCHING: buffer: (id = 1510469437, pos = 0, lim = 131072), checksum: 0, future: not done
2024-04-24 15:57:25,626 [s3a-transfer-noaa-cors-pds-bounded-pool6-t9] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - --- putC(0)
2024-04-24 15:57:25,626 [s3a-transfer-noaa-cors-pds-bounded-pool6-t9] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:cachePut(650)) - s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz: Block java.nio.HeapByteBufferR[pos=0 lim=131072 cap=131072]: Caching
2024-04-24 15:57:25,667 [s3a-transfer-noaa-cors-pds-bounded-pool6-t9] INFO prefetch.SingleFilePerBlockCache (DurationInfo.java:<init>(77)) - Starting: save 131072 bytes to /Users/stevel/Projects/IDE-files/hadoop-trunk/target/prefetch/a1dd81ba-1499-440d-ba67-79705a17d5e7/fs-cache-2283440820786611743-block-0000.bin
2024-04-24 15:57:25,668 [s3a-transfer-noaa-cors-pds-bounded-pool6-t9] INFO prefetch.SingleFilePerBlockCache (DurationInfo.java:close(98)) - save 131072 bytes to /Users/stevel/Projects/IDE-files/hadoop-trunk/target/prefetch/a1dd81ba-1499-440d-ba67-79705a17d5e7/fs-cache-2283440820786611743-block-0000.bin: duration 0:00.001s
2024-04-24 15:57:25,668 [s3a-transfer-noaa-cors-pds-bounded-pool6-t9] DEBUG prefetch.SingleFilePerBlockCache (SingleFilePerBlockCache.java:maybePushToHeadOfBlockList(336)) - Block 0 to be added to the head. Current head block 0 and tail block 0; ([000] /Users/stevel/Projects/IDE-files/hadoop-trunk/target/prefetch/a1dd81ba-1499-440d-ba67-79705a17d5e7/fs-cache-2283440820786611743-block-0000.bin: size = 131,072, checksum = 3320762083)
2024-04-24 15:57:25,668 [s3a-transfer-noaa-cors-pds-bounded-pool6-t9] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - *** putC(0)
2024-04-24 15:57:25,998 [s3a-transfer-noaa-cors-pds-bounded-pool6-t2] DEBUG impl.SDKStreamDrainer (SDKStreamDrainer.java:drainOrAbortHttpStream(218)) - Closing stream
2024-04-24 15:57:25,999 [s3a-transfer-noaa-cors-pds-bounded-pool6-t2] DEBUG s3a.Invoker (DurationInfo.java:close(101)) - read s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz [262144-393216]: duration 0:00.689s
2024-04-24 15:57:25,999 [s3a-transfer-noaa-cors-pds-bounded-pool6-t2] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:readBlock(409)) - Completed prefetch of block 2 [262144-393216]
2024-04-24 15:57:25,999 [s3a-transfer-noaa-cors-pds-bounded-pool6-t2] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - *** prefetch(2)
2024-04-24 15:57:25,999 [s3a-transfer-noaa-cors-pds-bounded-pool6-t2] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:readBlock(435)) - fetch completed: Duration of stream_read_prefetch_operations: 0:00.689s
2024-04-24 15:57:25,999 [setup] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - --- requestCaching(2)
2024-04-24 15:57:26,000 [setup] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - *** requestCaching(2)
2024-04-24 15:57:26,000 [s3a-transfer-noaa-cors-pds-bounded-pool6-t10] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:addToCacheAndRelease(575)) - s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz: Block 2: Preparing to cache block
2024-04-24 15:57:26,000 [s3a-transfer-noaa-cors-pds-bounded-pool6-t10] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:addToCacheAndRelease(582)) - s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz: Block 2: awaiting any read to complete
2024-04-24 15:57:26,000 [setup] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:requestCaching(517)) - s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz: Block 5: request caching of [005] id: 1263896387, State: PREFETCHING: buffer: (id = 1797965731, pos = 86573, lim = 131072), checksum: 0, future: not done
2024-04-24 15:57:26,000 [s3a-transfer-noaa-cors-pds-bounded-pool6-t10] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - --- putC(2)
2024-04-24 15:57:26,000 [s3a-transfer-noaa-cors-pds-bounded-pool6-t10] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:cachePut(650)) - s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz: Block java.nio.HeapByteBufferR[pos=0 lim=131072 cap=131072]: Caching
2024-04-24 15:57:26,002 [s3a-transfer-noaa-cors-pds-bounded-pool6-t10] INFO prefetch.SingleFilePerBlockCache (DurationInfo.java:<init>(77)) - Starting: save 131072 bytes to /Users/stevel/Projects/IDE-files/hadoop-trunk/target/prefetch/a1dd81ba-1499-440d-ba67-79705a17d5e7/fs-cache-1079555837997227351-block-0002.bin
2024-04-24 15:57:26,002 [s3a-transfer-noaa-cors-pds-bounded-pool6-t10] INFO prefetch.SingleFilePerBlockCache (DurationInfo.java:close(98)) - save 131072 bytes to /Users/stevel/Projects/IDE-files/hadoop-trunk/target/prefetch/a1dd81ba-1499-440d-ba67-79705a17d5e7/fs-cache-1079555837997227351-block-0002.bin: duration 0:00.000s
2024-04-24 15:57:26,004 [s3a-transfer-noaa-cors-pds-bounded-pool6-t10] DEBUG prefetch.SingleFilePerBlockCache (SingleFilePerBlockCache.java:maybePushToHeadOfBlockList(336)) - Block 2 to be added to the head. Current head block 0 and tail block 0; ([002] /Users/stevel/Projects/IDE-files/hadoop-trunk/target/prefetch/a1dd81ba-1499-440d-ba67-79705a17d5e7/fs-cache-1079555837997227351-block-0002.bin: size = 131,072, checksum = 2067391204)
2024-04-24 15:57:26,004 [s3a-transfer-noaa-cors-pds-bounded-pool6-t10] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - *** putC(2)
2024-04-24 15:57:26,120 [s3a-transfer-noaa-cors-pds-bounded-pool6-t5] DEBUG impl.SDKStreamDrainer (SDKStreamDrainer.java:drainOrAbortHttpStream(218)) - Closing stream
2024-04-24 15:57:26,121 [s3a-transfer-noaa-cors-pds-bounded-pool6-t5] DEBUG s3a.Invoker (DurationInfo.java:close(101)) - read s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz [655360-786432]: duration 0:00.810s
2024-04-24 15:57:26,121 [s3a-transfer-noaa-cors-pds-bounded-pool6-t5] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:readBlock(409)) - Completed prefetch of block 5 [655360-786432]
2024-04-24 15:57:26,121 [s3a-transfer-noaa-cors-pds-bounded-pool6-t5] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - *** prefetch(5)
2024-04-24 15:57:26,121 [s3a-transfer-noaa-cors-pds-bounded-pool6-t5] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:readBlock(435)) - fetch completed: Duration of stream_read_prefetch_operations: 0:00.810s
2024-04-24 15:57:26,120 [s3a-transfer-noaa-cors-pds-bounded-pool6-t1] DEBUG impl.SDKStreamDrainer (SDKStreamDrainer.java:drainOrAbortHttpStream(218)) - Closing stream
2024-04-24 15:57:26,122 [setup] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - --- requestCaching(5)
2024-04-24 15:57:26,122 [s3a-transfer-noaa-cors-pds-bounded-pool6-t1] DEBUG s3a.Invoker (DurationInfo.java:close(101)) - read s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz [131072-262144]: duration 0:00.812s
2024-04-24 15:57:26,122 [s3a-transfer-noaa-cors-pds-bounded-pool6-t1] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:readBlock(409)) - Completed prefetch of block 1 [131072-262144]
2024-04-24 15:57:26,123 [s3a-transfer-noaa-cors-pds-bounded-pool6-t1] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - *** prefetch(1)
2024-04-24 15:57:26,123 [setup] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - *** requestCaching(5)
2024-04-24 15:57:26,123 [s3a-transfer-noaa-cors-pds-bounded-pool6-t11] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:addToCacheAndRelease(575)) - s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz: Block 5: Preparing to cache block
2024-04-24 15:57:26,123 [s3a-transfer-noaa-cors-pds-bounded-pool6-t11] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:addToCacheAndRelease(582)) - s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz: Block 5: awaiting any read to complete
2024-04-24 15:57:26,123 [s3a-transfer-noaa-cors-pds-bounded-pool6-t1] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:readBlock(435)) - fetch completed: Duration of stream_read_prefetch_operations: 0:00.814s
2024-04-24 15:57:26,123 [s3a-transfer-noaa-cors-pds-bounded-pool6-t11] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - --- putC(5)
2024-04-24 15:57:26,123 [setup] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:requestCaching(517)) - s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz: Block 6: request caching of [006] id: 1150889795, State: PREFETCHING: buffer: (id = 2041839532, pos = 88239, lim = 131072), checksum: 0, future: not done
2024-04-24 15:57:26,123 [s3a-transfer-noaa-cors-pds-bounded-pool6-t11] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:cachePut(650)) - s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz: Block java.nio.HeapByteBufferR[pos=0 lim=131072 cap=131072]: Caching
2024-04-24 15:57:26,125 [s3a-transfer-noaa-cors-pds-bounded-pool6-t11] INFO prefetch.SingleFilePerBlockCache (DurationInfo.java:<init>(77)) - Starting: save 131072 bytes to /Users/stevel/Projects/IDE-files/hadoop-trunk/target/prefetch/a1dd81ba-1499-440d-ba67-79705a17d5e7/fs-cache-8757359741004979112-block-0005.bin
2024-04-24 15:57:26,125 [s3a-transfer-noaa-cors-pds-bounded-pool6-t11] INFO prefetch.SingleFilePerBlockCache (DurationInfo.java:close(98)) - save 131072 bytes to /Users/stevel/Projects/IDE-files/hadoop-trunk/target/prefetch/a1dd81ba-1499-440d-ba67-79705a17d5e7/fs-cache-8757359741004979112-block-0005.bin: duration 0:00.000s
2024-04-24 15:57:26,125 [s3a-transfer-noaa-cors-pds-bounded-pool6-t11] DEBUG prefetch.SingleFilePerBlockCache (SingleFilePerBlockCache.java:maybePushToHeadOfBlockList(336)) - Block 5 to be added to the head. Current head block 2 and tail block 0; ([005] /Users/stevel/Projects/IDE-files/hadoop-trunk/target/prefetch/a1dd81ba-1499-440d-ba67-79705a17d5e7/fs-cache-8757359741004979112-block-0005.bin: size = 131,072, checksum = 2937666868)
2024-04-24 15:57:26,126 [s3a-transfer-noaa-cors-pds-bounded-pool6-t11] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - *** putC(5)
2024-04-24 15:57:26,129 [s3a-transfer-noaa-cors-pds-bounded-pool6-t3] DEBUG impl.SDKStreamDrainer (SDKStreamDrainer.java:drainOrAbortHttpStream(218)) - Closing stream
2024-04-24 15:57:26,129 [s3a-transfer-noaa-cors-pds-bounded-pool6-t4] DEBUG impl.SDKStreamDrainer (SDKStreamDrainer.java:drainOrAbortHttpStream(218)) - Closing stream
2024-04-24 15:57:26,129 [s3a-transfer-noaa-cors-pds-bounded-pool6-t3] DEBUG s3a.Invoker (DurationInfo.java:close(101)) - read s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz [393216-524288]: duration 0:00.819s
2024-04-24 15:57:26,129 [s3a-transfer-noaa-cors-pds-bounded-pool6-t4] DEBUG s3a.Invoker (DurationInfo.java:close(101)) - read s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz [524288-655360]: duration 0:00.819s
2024-04-24 15:57:26,129 [s3a-transfer-noaa-cors-pds-bounded-pool6-t3] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:readBlock(409)) - Completed prefetch of block 3 [393216-524288]
2024-04-24 15:57:26,129 [s3a-transfer-noaa-cors-pds-bounded-pool6-t3] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - *** prefetch(3)
2024-04-24 15:57:26,129 [s3a-transfer-noaa-cors-pds-bounded-pool6-t4] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:readBlock(409)) - Completed prefetch of block 4 [524288-655360]
2024-04-24 15:57:26,129 [s3a-transfer-noaa-cors-pds-bounded-pool6-t3] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:readBlock(435)) - fetch completed: Duration of stream_read_prefetch_operations: 0:00.819s
2024-04-24 15:57:26,130 [s3a-transfer-noaa-cors-pds-bounded-pool6-t8] DEBUG impl.SDKStreamDrainer (SDKStreamDrainer.java:drainOrAbortHttpStream(218)) - Closing stream
2024-04-24 15:57:26,130 [s3a-transfer-noaa-cors-pds-bounded-pool6-t4] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - *** prefetch(4)
2024-04-24 15:57:26,130 [s3a-transfer-noaa-cors-pds-bounded-pool6-t8] DEBUG s3a.Invoker (DurationInfo.java:close(101)) - read s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz [1048576-1179648]: duration 0:00.818s
2024-04-24 15:57:26,130 [s3a-transfer-noaa-cors-pds-bounded-pool6-t7] DEBUG impl.SDKStreamDrainer (SDKStreamDrainer.java:drainOrAbortHttpStream(218)) - Closing stream
2024-04-24 15:57:26,130 [s3a-transfer-noaa-cors-pds-bounded-pool6-t8] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:readBlock(409)) - Completed prefetch of block 8 [1048576-1179648]
2024-04-24 15:57:26,130 [s3a-transfer-noaa-cors-pds-bounded-pool6-t4] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:readBlock(435)) - fetch completed: Duration of stream_read_prefetch_operations: 0:00.820s
2024-04-24 15:57:26,130 [s3a-transfer-noaa-cors-pds-bounded-pool6-t8] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - *** prefetch(8)
2024-04-24 15:57:26,130 [s3a-transfer-noaa-cors-pds-bounded-pool6-t7] DEBUG s3a.Invoker (DurationInfo.java:close(101)) - read s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz [917504-1048576]: duration 0:00.818s
2024-04-24 15:57:26,130 [s3a-transfer-noaa-cors-pds-bounded-pool6-t8] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:readBlock(435)) - fetch completed: Duration of stream_read_prefetch_operations: 0:00.818s
2024-04-24 15:57:26,130 [s3a-transfer-noaa-cors-pds-bounded-pool6-t7] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:readBlock(409)) - Completed prefetch of block 7 [917504-1048576]
2024-04-24 15:57:26,131 [s3a-transfer-noaa-cors-pds-bounded-pool6-t7] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - *** prefetch(7)
2024-04-24 15:57:26,131 [s3a-transfer-noaa-cors-pds-bounded-pool6-t7] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:readBlock(435)) - fetch completed: Duration of stream_read_prefetch_operations: 0:00.819s
2024-04-24 15:57:26,152 [s3a-transfer-noaa-cors-pds-bounded-pool6-t6] DEBUG impl.SDKStreamDrainer (SDKStreamDrainer.java:drainOrAbortHttpStream(218)) - Closing stream
2024-04-24 15:57:26,152 [s3a-transfer-noaa-cors-pds-bounded-pool6-t6] DEBUG s3a.Invoker (DurationInfo.java:close(101)) - read s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz [786432-917504]: duration 0:00.841s
2024-04-24 15:57:26,152 [s3a-transfer-noaa-cors-pds-bounded-pool6-t6] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:readBlock(409)) - Completed prefetch of block 6 [786432-917504]
2024-04-24 15:57:26,152 [s3a-transfer-noaa-cors-pds-bounded-pool6-t6] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - *** prefetch(6)
2024-04-24 15:57:26,152 [s3a-transfer-noaa-cors-pds-bounded-pool6-t6] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:readBlock(435)) - fetch completed: Duration of stream_read_prefetch_operations: 0:00.841s
2024-04-24 15:57:26,152 [setup] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - --- requestCaching(6)
2024-04-24 15:57:26,153 [setup] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - *** requestCaching(6)
2024-04-24 15:57:26,153 [setup] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:requestCaching(517)) - s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz: Block 1: request caching of [001] id: 994329416, State: READY: buffer: (id = 1603736230, pos = 0, lim = 131072), checksum: 2642073199, future: done
2024-04-24 15:57:26,153 [setup] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - --- requestCaching(1)
2024-04-24 15:57:26,153 [s3a-transfer-noaa-cors-pds-bounded-pool6-t12] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:addToCacheAndRelease(575)) - s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz: Block 6: Preparing to cache block
2024-04-24 15:57:26,153 [s3a-transfer-noaa-cors-pds-bounded-pool6-t12] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:addToCacheAndRelease(582)) - s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz: Block 6: awaiting any read to complete
2024-04-24 15:57:26,153 [setup] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - *** requestCaching(1)
2024-04-24 15:57:26,153 [s3a-transfer-noaa-cors-pds-bounded-pool6-t13] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:addToCacheAndRelease(575)) - s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz: Block 1: Preparing to cache block
2024-04-24 15:57:26,154 [s3a-transfer-noaa-cors-pds-bounded-pool6-t13] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:addToCacheAndRelease(582)) - s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz: Block 1: awaiting any read to complete
2024-04-24 15:57:26,153 [s3a-transfer-noaa-cors-pds-bounded-pool6-t12] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - --- putC(6)
2024-04-24 15:57:26,153 [setup] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:requestCaching(517)) - s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz: Block 8: request caching of [008] id: 1916205902, State: READY: buffer: (id = 1134026783, pos = 0, lim = 131072), checksum: 1926174145, future: done
2024-04-24 15:57:26,154 [s3a-transfer-noaa-cors-pds-bounded-pool6-t13] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - --- putC(1)
2024-04-24 15:57:26,154 [s3a-transfer-noaa-cors-pds-bounded-pool6-t13] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:cachePut(650)) - s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz: Block java.nio.HeapByteBufferR[pos=0 lim=131072 cap=131072]: Caching
2024-04-24 15:57:26,154 [s3a-transfer-noaa-cors-pds-bounded-pool6-t12] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:cachePut(650)) - s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz: Block java.nio.HeapByteBufferR[pos=0 lim=131072 cap=131072]: Caching
2024-04-24 15:57:26,154 [setup] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - --- requestCaching(8)
2024-04-24 15:57:26,154 [setup] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - *** requestCaching(8)
2024-04-24 15:57:26,154 [s3a-transfer-noaa-cors-pds-bounded-pool6-t14] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:addToCacheAndRelease(575)) - s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz: Block 8: Preparing to cache block
2024-04-24 15:57:26,155 [s3a-transfer-noaa-cors-pds-bounded-pool6-t14] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:addToCacheAndRelease(582)) - s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz: Block 8: awaiting any read to complete
2024-04-24 15:57:26,155 [setup] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:requestCaching(517)) - s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz: Block 4: request caching of [004] id: 109870965, State: READY: buffer: (id = 920412102, pos = 0, lim = 131072), checksum: 926889257, future: done
2024-04-24 15:57:26,155 [s3a-transfer-noaa-cors-pds-bounded-pool6-t14] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - --- putC(8)
2024-04-24 15:57:26,155 [s3a-transfer-noaa-cors-pds-bounded-pool6-t14] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:cachePut(650)) - s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz: Block java.nio.HeapByteBufferR[pos=0 lim=131072 cap=131072]: Caching
2024-04-24 15:57:26,155 [setup] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - --- requestCaching(4)
2024-04-24 15:57:26,155 [s3a-transfer-noaa-cors-pds-bounded-pool6-t13] INFO prefetch.SingleFilePerBlockCache (DurationInfo.java:<init>(77)) - Starting: save 131072 bytes to /Users/stevel/Projects/IDE-files/hadoop-trunk/target/prefetch/a1dd81ba-1499-440d-ba67-79705a17d5e7/fs-cache-3891072200315223991-block-0001.bin
2024-04-24 15:57:26,155 [s3a-transfer-noaa-cors-pds-bounded-pool6-t12] INFO prefetch.SingleFilePerBlockCache (DurationInfo.java:<init>(77)) - Starting: save 131072 bytes to /Users/stevel/Projects/IDE-files/hadoop-trunk/target/prefetch/a1dd81ba-1499-440d-ba67-79705a17d5e7/fs-cache-831876345754085681-block-0006.bin
2024-04-24 15:57:26,155 [setup] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - *** requestCaching(4)
2024-04-24 15:57:26,155 [s3a-transfer-noaa-cors-pds-bounded-pool6-t15] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:addToCacheAndRelease(575)) - s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz: Block 4: Preparing to cache block
2024-04-24 15:57:26,156 [s3a-transfer-noaa-cors-pds-bounded-pool6-t13] INFO prefetch.SingleFilePerBlockCache (DurationInfo.java:close(98)) - save 131072 bytes to /Users/stevel/Projects/IDE-files/hadoop-trunk/target/prefetch/a1dd81ba-1499-440d-ba67-79705a17d5e7/fs-cache-3891072200315223991-block-0001.bin: duration 0:00.001s
2024-04-24 15:57:26,156 [setup] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:requestCaching(517)) - s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz: Block 7: request caching of [007] id: 1792328953, State: READY: buffer: (id = 323265539, pos = 0, lim = 131072), checksum: 2744416371, future: done
2024-04-24 15:57:26,156 [s3a-transfer-noaa-cors-pds-bounded-pool6-t12] INFO prefetch.SingleFilePerBlockCache (DurationInfo.java:close(98)) - save 131072 bytes to /Users/stevel/Projects/IDE-files/hadoop-trunk/target/prefetch/a1dd81ba-1499-440d-ba67-79705a17d5e7/fs-cache-831876345754085681-block-0006.bin: duration 0:00.001s
2024-04-24 15:57:26,156 [s3a-transfer-noaa-cors-pds-bounded-pool6-t15] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:addToCacheAndRelease(582)) - s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz: Block 4: awaiting any read to complete
2024-04-24 15:57:26,156 [s3a-transfer-noaa-cors-pds-bounded-pool6-t14] INFO prefetch.SingleFilePerBlockCache (DurationInfo.java:<init>(77)) - Starting: save 131072 bytes to /Users/stevel/Projects/IDE-files/hadoop-trunk/target/prefetch/a1dd81ba-1499-440d-ba67-79705a17d5e7/fs-cache-5000586859770259516-block-0008.bin
2024-04-24 15:57:26,156 [setup] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - --- requestCaching(7)
2024-04-24 15:57:26,156 [s3a-transfer-noaa-cors-pds-bounded-pool6-t13] DEBUG prefetch.SingleFilePerBlockCache (SingleFilePerBlockCache.java:maybePushToHeadOfBlockList(336)) - Block 1 to be added to the head. Current head block 5 and tail block 0; ([001] /Users/stevel/Projects/IDE-files/hadoop-trunk/target/prefetch/a1dd81ba-1499-440d-ba67-79705a17d5e7/fs-cache-3891072200315223991-block-0001.bin: size = 131,072, checksum = 2642073199)
2024-04-24 15:57:26,156 [s3a-transfer-noaa-cors-pds-bounded-pool6-t14] INFO prefetch.SingleFilePerBlockCache (DurationInfo.java:close(98)) - save 131072 bytes to /Users/stevel/Projects/IDE-files/hadoop-trunk/target/prefetch/a1dd81ba-1499-440d-ba67-79705a17d5e7/fs-cache-5000586859770259516-block-0008.bin: duration 0:00.000s
2024-04-24 15:57:26,156 [s3a-transfer-noaa-cors-pds-bounded-pool6-t15] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - --- putC(4)
2024-04-24 15:57:26,156 [s3a-transfer-noaa-cors-pds-bounded-pool6-t16] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:addToCacheAndRelease(575)) - s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz: Block 7: Preparing to cache block
2024-04-24 15:57:26,156 [s3a-transfer-noaa-cors-pds-bounded-pool6-t16] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:addToCacheAndRelease(582)) - s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz: Block 7: awaiting any read to complete
2024-04-24 15:57:26,156 [s3a-transfer-noaa-cors-pds-bounded-pool6-t13] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - *** putC(1)
2024-04-24 15:57:26,156 [s3a-transfer-noaa-cors-pds-bounded-pool6-t15] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:cachePut(650)) - s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz: Block java.nio.HeapByteBufferR[pos=0 lim=131072 cap=131072]: Caching
2024-04-24 15:57:26,156 [s3a-transfer-noaa-cors-pds-bounded-pool6-t12] DEBUG prefetch.SingleFilePerBlockCache (SingleFilePerBlockCache.java:maybePushToHeadOfBlockList(336)) - Block 6 to be added to the head. Current head block 1 and tail block 0; ([006] /Users/stevel/Projects/IDE-files/hadoop-trunk/target/prefetch/a1dd81ba-1499-440d-ba67-79705a17d5e7/fs-cache-831876345754085681-block-0006.bin: size = 131,072, checksum = 3326737228)
2024-04-24 15:57:26,157 [setup] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - *** requestCaching(7)
2024-04-24 15:57:26,157 [s3a-transfer-noaa-cors-pds-bounded-pool6-t12] DEBUG prefetch.SingleFilePerBlockCache (SingleFilePerBlockCache.java:deleteBlockFileAndEvictCache(454)) - Evicting block 0 from cache: ([000] /Users/stevel/Projects/IDE-files/hadoop-trunk/target/prefetch/a1dd81ba-1499-440d-ba67-79705a17d5e7/fs-cache-2283440820786611743-block-0000.bin: size = 131,072, checksum = 3320762083)
2024-04-24 15:57:26,157 [setup] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:requestCaching(517)) - s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz: Block 3: request caching of [003] id: 58234618, State: READY: buffer: (id = 1564095827, pos = 0, lim = 131072), checksum: 2582014511, future: done
2024-04-24 15:57:26,157 [s3a-transfer-noaa-cors-pds-bounded-pool6-t16] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - --- putC(7)
2024-04-24 15:57:26,157 [s3a-transfer-noaa-cors-pds-bounded-pool6-t16] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:cachePut(650)) - s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz: Block java.nio.HeapByteBufferR[pos=0 lim=131072 cap=131072]: Caching
2024-04-24 15:57:26,157 [setup] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - --- requestCaching(3)
2024-04-24 15:57:26,157 [s3a-transfer-noaa-cors-pds-bounded-pool6-t15] INFO prefetch.SingleFilePerBlockCache (DurationInfo.java:<init>(77)) - Starting: save 131072 bytes to /Users/stevel/Projects/IDE-files/hadoop-trunk/target/prefetch/a1dd81ba-1499-440d-ba67-79705a17d5e7/fs-cache-1766922656794707645-block-0004.bin
2024-04-24 15:57:26,158 [setup] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - *** requestCaching(3)
2024-04-24 15:57:26,158 [s3a-transfer-noaa-cors-pds-bounded-pool6-t17] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:addToCacheAndRelease(575)) - s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz: Block 3: Preparing to cache block
2024-04-24 15:57:26,158 [s3a-transfer-noaa-cors-pds-bounded-pool6-t15] INFO prefetch.SingleFilePerBlockCache (DurationInfo.java:close(98)) - save 131072 bytes to /Users/stevel/Projects/IDE-files/hadoop-trunk/target/prefetch/a1dd81ba-1499-440d-ba67-79705a17d5e7/fs-cache-1766922656794707645-block-0004.bin: duration 0:00.001s
2024-04-24 15:57:26,158 [s3a-transfer-noaa-cors-pds-bounded-pool6-t17] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:addToCacheAndRelease(582)) - s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz: Block 3: awaiting any read to complete
2024-04-24 15:57:26,158 [setup] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - *** cancelPrefetches()
2024-04-24 15:57:26,158 [s3a-transfer-noaa-cors-pds-bounded-pool6-t17] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - --- putC(3)
2024-04-24 15:57:26,158 [s3a-transfer-noaa-cors-pds-bounded-pool6-t16] INFO prefetch.SingleFilePerBlockCache (DurationInfo.java:<init>(77)) - Starting: save 131072 bytes to /Users/stevel/Projects/IDE-files/hadoop-trunk/target/prefetch/a1dd81ba-1499-440d-ba67-79705a17d5e7/fs-cache-3861022982718863148-block-0007.bin
2024-04-24 15:57:26,158 [setup] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:requestPrefetch(278)) - s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz: Requesting prefetch for block 3
2024-04-24 15:57:26,158 [s3a-transfer-noaa-cors-pds-bounded-pool6-t17] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:cachePut(650)) - s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz: Block java.nio.HeapByteBufferR[pos=0 lim=131072 cap=131072]: Caching
2024-04-24 15:57:26,158 [s3a-transfer-noaa-cors-pds-bounded-pool6-t16] INFO prefetch.SingleFilePerBlockCache (DurationInfo.java:close(98)) - save 131072 bytes to /Users/stevel/Projects/IDE-files/hadoop-trunk/target/prefetch/a1dd81ba-1499-440d-ba67-79705a17d5e7/fs-cache-3861022982718863148-block-0007.bin: duration 0:00.000s
2024-04-24 15:57:26,159 [s3a-transfer-noaa-cors-pds-bounded-pool6-t17] INFO prefetch.SingleFilePerBlockCache (DurationInfo.java:<init>(77)) - Starting: save 131072 bytes to /Users/stevel/Projects/IDE-files/hadoop-trunk/target/prefetch/a1dd81ba-1499-440d-ba67-79705a17d5e7/fs-cache-6536604957243440720-block-0003.bin
2024-04-24 15:57:26,159 [s3a-transfer-noaa-cors-pds-bounded-pool6-t17] INFO prefetch.SingleFilePerBlockCache (DurationInfo.java:close(98)) - save 131072 bytes to /Users/stevel/Projects/IDE-files/hadoop-trunk/target/prefetch/a1dd81ba-1499-440d-ba67-79705a17d5e7/fs-cache-6536604957243440720-block-0003.bin: duration 0:00.000s
2024-04-24 15:57:26,159 [setup] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:requestPrefetch(284)) - s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz: acquired [003] id: 58234618, State: CACHING: buffer: (id = 1564095827, pos = 0, lim = 131072), checksum: 2582014511, future: not done
2024-04-24 15:57:26,159 [setup] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - --- getCached(2)
2024-04-24 15:57:26,160 [s3a-transfer-noaa-cors-pds-bounded-pool6-t12] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - *** putC(6)
2024-04-24 15:57:26,160 [s3a-transfer-noaa-cors-pds-bounded-pool6-t14] DEBUG prefetch.SingleFilePerBlockCache (SingleFilePerBlockCache.java:maybePushToHeadOfBlockList(336)) - Block 8 to be added to the head. Current head block 6 and tail block 2; ([008] /Users/stevel/Projects/IDE-files/hadoop-trunk/target/prefetch/a1dd81ba-1499-440d-ba67-79705a17d5e7/fs-cache-5000586859770259516-block-0008.bin: size = 131,072, checksum = 1926174145)
2024-04-24 15:57:26,160 [s3a-transfer-noaa-cors-pds-bounded-pool6-t14] DEBUG prefetch.SingleFilePerBlockCache (SingleFilePerBlockCache.java:deleteBlockFileAndEvictCache(454)) - Evicting block 2 from cache: ([002] /Users/stevel/Projects/IDE-files/hadoop-trunk/target/prefetch/a1dd81ba-1499-440d-ba67-79705a17d5e7/fs-cache-1079555837997227351-block-0002.bin: size = 131,072, checksum = 2067391204)
2024-04-24 15:57:26,161 [s3a-transfer-noaa-cors-pds-bounded-pool6-t14] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - *** putC(8)
2024-04-24 15:57:26,161 [s3a-transfer-noaa-cors-pds-bounded-pool6-t15] DEBUG prefetch.SingleFilePerBlockCache (SingleFilePerBlockCache.java:maybePushToHeadOfBlockList(336)) - Block 4 to be added to the head. Current head block 8 and tail block 5; ([004] /Users/stevel/Projects/IDE-files/hadoop-trunk/target/prefetch/a1dd81ba-1499-440d-ba67-79705a17d5e7/fs-cache-1766922656794707645-block-0004.bin: size = 131,072, checksum = 926889257)
2024-04-24 15:57:26,161 [s3a-transfer-noaa-cors-pds-bounded-pool6-t15] DEBUG prefetch.SingleFilePerBlockCache (SingleFilePerBlockCache.java:deleteBlockFileAndEvictCache(454)) - Evicting block 5 from cache: ([005] /Users/stevel/Projects/IDE-files/hadoop-trunk/target/prefetch/a1dd81ba-1499-440d-ba67-79705a17d5e7/fs-cache-8757359741004979112-block-0005.bin: size = 131,072, checksum = 2937666868)
2024-04-24 15:57:26,161 [s3a-transfer-noaa-cors-pds-bounded-pool6-t16] DEBUG prefetch.SingleFilePerBlockCache (SingleFilePerBlockCache.java:maybePushToHeadOfBlockList(336)) - Block 7 to be added to the head. Current head block 4 and tail block 1; ([007] /Users/stevel/Projects/IDE-files/hadoop-trunk/target/prefetch/a1dd81ba-1499-440d-ba67-79705a17d5e7/fs-cache-3861022982718863148-block-0007.bin: size = 131,072, checksum = 2744416371)
2024-04-24 15:57:26,161 [s3a-transfer-noaa-cors-pds-bounded-pool6-t15] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - *** putC(4)
2024-04-24 15:57:26,161 [s3a-transfer-noaa-cors-pds-bounded-pool6-t16] DEBUG prefetch.SingleFilePerBlockCache (SingleFilePerBlockCache.java:deleteBlockFileAndEvictCache(454)) - Evicting block 1 from cache: ([001] /Users/stevel/Projects/IDE-files/hadoop-trunk/target/prefetch/a1dd81ba-1499-440d-ba67-79705a17d5e7/fs-cache-3891072200315223991-block-0001.bin: size = 131,072, checksum = 2642073199)
2024-04-24 15:57:26,162 [s3a-transfer-noaa-cors-pds-bounded-pool6-t17] DEBUG prefetch.SingleFilePerBlockCache (SingleFilePerBlockCache.java:maybePushToHeadOfBlockList(336)) - Block 3 to be added to the head. Current head block 7 and tail block 6; ([003] /Users/stevel/Projects/IDE-files/hadoop-trunk/target/prefetch/a1dd81ba-1499-440d-ba67-79705a17d5e7/fs-cache-6536604957243440720-block-0003.bin: size = 131,072, checksum = 2582014511)
2024-04-24 15:57:26,162 [s3a-transfer-noaa-cors-pds-bounded-pool6-t16] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - *** putC(7)
2024-04-24 15:57:26,162 [s3a-transfer-noaa-cors-pds-bounded-pool6-t17] DEBUG prefetch.SingleFilePerBlockCache (SingleFilePerBlockCache.java:deleteBlockFileAndEvictCache(454)) - Evicting block 6 from cache: ([006] /Users/stevel/Projects/IDE-files/hadoop-trunk/target/prefetch/a1dd81ba-1499-440d-ba67-79705a17d5e7/fs-cache-831876345754085681-block-0006.bin: size = 131,072, checksum = 3326737228)
2024-04-24 15:57:26,162 [s3a-transfer-noaa-cors-pds-bounded-pool6-t17] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - *** putC(3)
2024-04-24 15:57:26,162 [setup] DEBUG prefetch.SingleFilePerBlockCache (SingleFilePerBlockCache.java:maybePushToHeadOfBlockList(336)) - Block 2 to be added to the head. Current head block 3 and tail block 8; ([002] /Users/stevel/Projects/IDE-files/hadoop-trunk/target/prefetch/a1dd81ba-1499-440d-ba67-79705a17d5e7/fs-cache-1079555837997227351-block-0002.bin: size = 131,072, checksum = 2067391204)
2024-04-24 15:57:26,163 [setup] DEBUG prefetch.SingleFilePerBlockCache (SingleFilePerBlockCache.java:maybePushToHeadOfBlockList(344)) - Block 2 is already in block list
2024-04-24 15:57:26,163 [setup] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:readBlock(414)) - Failure in read of block 2 [262144-393216]
java.nio.file.NoSuchFileException: /Users/stevel/Projects/IDE-files/hadoop-trunk/target/prefetch/a1dd81ba-1499-440d-ba67-79705a17d5e7/fs-cache-1079555837997227351-block-0002.bin
at sun.nio.fs.UnixException.translateToIOException(UnixException.java:86)
at sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:102)
at sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:107)
at sun.nio.fs.UnixFileSystemProvider.newFileChannel(UnixFileSystemProvider.java:177)
at java.nio.channels.FileChannel.open(FileChannel.java:287)
at java.nio.channels.FileChannel.open(FileChannel.java:335)
at org.apache.hadoop.fs.impl.prefetch.SingleFilePerBlockCache.readFile(SingleFilePerBlockCache.java:290)
at org.apache.hadoop.fs.impl.prefetch.SingleFilePerBlockCache.get(SingleFilePerBlockCache.java:279)
at org.apache.hadoop.fs.impl.prefetch.CachingBlockManager.readBlock(CachingBlockManager.java:389)
at org.apache.hadoop.fs.impl.prefetch.CachingBlockManager.read(CachingBlockManager.java:337)
at org.apache.hadoop.fs.impl.prefetch.CachingBlockManager.getInternal(CachingBlockManager.java:220)
at org.apache.hadoop.fs.impl.prefetch.CachingBlockManager.get(CachingBlockManager.java:175)
at org.apache.hadoop.fs.s3a.prefetch.S3ACachingInputStream.lambda$ensureCurrentBuffer$0(S3ACachingInputStream.java:238)
at org.apache.hadoop.fs.statistics.impl.IOStatisticsBinding.invokeTrackingDuration(IOStatisticsBinding.java:556)
at org.apache.hadoop.fs.s3a.prefetch.S3ACachingInputStream.ensureCurrentBuffer(S3ACachingInputStream.java:236)
at org.apache.hadoop.fs.s3a.prefetch.S3ARemoteInputStream.read(S3ARemoteInputStream.java:357)
at org.apache.hadoop.fs.s3a.prefetch.S3APrefetchingInputStream.read(S3APrefetchingInputStream.java:198)
at org.apache.hadoop.fs.FSInputStream.read(FSInputStream.java:78)
at org.apache.hadoop.fs.FSDataInputStream.read(FSDataInputStream.java:100)
at org.apache.hadoop.fs.s3a.ITestS3APrefetchingCacheFiles.testCacheFileExistence(ITestS3APrefetchingCacheFiles.java:137)
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:59)
at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:56)
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:61)
at org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:299)
at org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:293)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.lang.Thread.run(Thread.java:750)
2024-04-24 15:57:26,163 [setup] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - *** getCached(2)
2024-04-24 15:57:26,163 [setup] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:read(339)) - s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz: error reading block 2
java.nio.file.NoSuchFileException: /Users/stevel/Projects/IDE-files/hadoop-trunk/target/prefetch/a1dd81ba-1499-440d-ba67-79705a17d5e7/fs-cache-1079555837997227351-block-0002.bin
at sun.nio.fs.UnixException.translateToIOException(UnixException.java:86)
at sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:102)
at sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:107)
at sun.nio.fs.UnixFileSystemProvider.newFileChannel(UnixFileSystemProvider.java:177)
at java.nio.channels.FileChannel.open(FileChannel.java:287)
at java.nio.channels.FileChannel.open(FileChannel.java:335)
at org.apache.hadoop.fs.impl.prefetch.SingleFilePerBlockCache.readFile(SingleFilePerBlockCache.java:290)
at org.apache.hadoop.fs.impl.prefetch.SingleFilePerBlockCache.get(SingleFilePerBlockCache.java:279)
at org.apache.hadoop.fs.impl.prefetch.CachingBlockManager.readBlock(CachingBlockManager.java:389)
at org.apache.hadoop.fs.impl.prefetch.CachingBlockManager.read(CachingBlockManager.java:337)
at org.apache.hadoop.fs.impl.prefetch.CachingBlockManager.getInternal(CachingBlockManager.java:220)
at org.apache.hadoop.fs.impl.prefetch.CachingBlockManager.get(CachingBlockManager.java:175)
at org.apache.hadoop.fs.s3a.prefetch.S3ACachingInputStream.lambda$ensureCurrentBuffer$0(S3ACachingInputStream.java:238)
at org.apache.hadoop.fs.statistics.impl.IOStatisticsBinding.invokeTrackingDuration(IOStatisticsBinding.java:556)
at org.apache.hadoop.fs.s3a.prefetch.S3ACachingInputStream.ensureCurrentBuffer(S3ACachingInputStream.java:236)
at org.apache.hadoop.fs.s3a.prefetch.S3ARemoteInputStream.read(S3ARemoteInputStream.java:357)
at org.apache.hadoop.fs.s3a.prefetch.S3APrefetchingInputStream.read(S3APrefetchingInputStream.java:198)
at org.apache.hadoop.fs.FSInputStream.read(FSInputStream.java:78)
at org.apache.hadoop.fs.FSDataInputStream.read(FSDataInputStream.java:100)
at org.apache.hadoop.fs.s3a.ITestS3APrefetchingCacheFiles.testCacheFileExistence(ITestS3APrefetchingCacheFiles.java:137)
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:59)
at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:56)
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:61)
at org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:299)
at org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:293)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.lang.Thread.run(Thread.java:750)
2024-04-24 15:57:26,164 [setup] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - ... close()
2024-04-24 15:57:26,164 [setup] DEBUG prefetch.CachingBlockManager (CachingBlockManager.java:cancelPrefetches(315)) - s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz: Cancelling prefetches: Close
2024-04-24 15:57:26,164 [setup] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - ... cancelPrefetches()
2024-04-24 15:57:26,164 [setup] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - *** cancelPrefetches()
2024-04-24 15:57:26,164 [setup] DEBUG prefetch.SingleFilePerBlockCache (SingleFilePerBlockCache.java:close(520)) - #entries = 4, #gets = 1
2024-04-24 15:57:26,164 [setup] DEBUG prefetch.SingleFilePerBlockCache (SingleFilePerBlockCache.java:deleteCacheFiles(530)) - Prefetch cache close: Deleting 4 cache files
2024-04-24 15:57:26,167 [setup] DEBUG prefetch.SingleFilePerBlockCache (SingleFilePerBlockCache.java:deleteCacheFiles(553)) - Prefetch cache close: Deleted 4 cache files
2024-04-24 15:57:26,167 [setup] INFO prefetch.BlockOperations (BlockOperations.java:add(162)) - *** close()
2024-04-24 15:57:26,169 [setup] INFO prefetch.CachingBlockManager (CachingBlockManager.java:close(257)) - RP(1);ERP(1);PF(1);RP(2);ERP(2);PF(2);RP(3);ERP(3);PF(3);RP(4);ERP(4);PF(4);RP(5);ERP(5);PF(5);RP(6);ERP(6);PF(6);RP(7);ERP(7);PF(7);RP(8);ERP(8);PF(8);GR(0);EGR(0);RC(0);ERC(0);CP;C+(0);EC+(0);EPF(2);RC(2);ERC(2);C+(2);EC+(2);EPF(5);RC(5);EPF(1);ERC(5);C+(5);EC+(5);EPF(3);EPF(4);EPF(8);EPF(7);EPF(6);RC(6);ERC(6);RC(1);ERC(1);C+(6);C+(1);RC(8);ERC(8);C+(8);RC(4);ERC(4);RC(7);C+(4);EC+(1);ERC(7);C+(7);RC(3);ERC(3);ECP;C+(3);GC(2);EC+(6);EC+(8);EC+(4);EC+(7);EC+(3);EGC(2);CX;CP;ECP;ECX;
GET_CACHED : #ops = 1, total = 0.0, min: 0.0, avg: 0.0, max: 0.0
GET_PREFETCHED : --
GET_READ : #ops = 1, total = 0.3, min: 0.3, avg: 0.3, max: 0.3
CACHE_PUT : #ops = 9, total = 0.1, min: 0.0, avg: 0.0, max: 0.0
PREFETCH : #ops = 8, total = 6.4, min: 0.7, avg: 0.8, max: 0.8
REQUEST_CACHING : #ops = 9, total = 0.0, min: 0.0, avg: 0.0, max: 0.0
REQUEST_PREFETCH : #ops = 8, total = 0.0, min: 0.0, avg: 0.0, max: 0.0
CANCEL_PREFETCHES : #ops = 2, total = 0.5, min: 0.0, avg: 0.3, max: 0.5
RELEASE : --
CLOSE : #ops = 1, total = 0.0, min: 0.0, avg: 0.0, max: 0.0
2024-04-24 15:57:26,170 [setup] DEBUG s3a.S3AInstrumentation (S3AInstrumentation.java:merge(1227)) - Merging statistics into FS statistics in close(): counters=((stream_read_vectored_incoming_ranges=0) (action_http_get_request=9) (stream_read_prefetch_operations=8) (stream_read_seek_backward_operations=0) (stream_read_operations=9) (stream_read_block_read.failures=0) (stream_read_fully_operations=1) (action_http_get_request.failures=0) (stream_read_close_operations=1) (action_file_opened.failures=0) (stream_read_vectored_combined_ranges=0) (stream_read_block_read=9) (stream_read_prefetch_operations.failures=0) (stream_read_remote_stream_drain.failures=0) (stream_read_block_acquire_read=2) (stream_read_vectored_operations=0) (stream_read_seek_bytes_discarded=0) (stream_read_seek_bytes_skipped=0) (stream_read_closed=9) (stream_read_block_acquire_read.failures=1) (stream_read_exceptions=0) (stream_read_unbuffered=0) (stream_read_seek_operations=0) (stream_evict_blocks_from_cache=5) (
stream_read_vectored_read_bytes_discarded=0) (stream_read_block_fetch_operations.failures=0) (action_executor_acquired.failures=0) (stream_read_bytes=120832) (stream_file_cache_eviction=5) (stream_read_remote_stream_aborted=0) (stream_read_remote_stream_aborted.failures=0) (stream_read_opened=9) (stream_read_bytes_backwards_on_seek=0) (action_executor_acquired=0) (stream_aborted=0) (stream_file_cache_eviction.failures=0) (action_file_opened=1) (stream_read_remote_stream_drain=9) (stream_read_seek_forward_operations=0) (stream_read_operations_incomplete=0) (stream_read_bytes_discarded_in_close=0) (stream_read_version_mismatches=0) (stream_read_total_bytes=1179648) (stream_read_block_fetch_operations=1) (stream_read_bytes_discarded_in_abort=0) (stream_read_seek_policy_changed=1));
gauges=((stream_read_block_prefetch_limit=8) (stream_read_block_cache_enabled=1) (stream_read_block_fetch_operations=0) (stream_read_block_prefetch_enabled=1) (stream_read_blocks_in_cache=0) (stream_read_active_prefetch_operations=0) (stream_read_active_memory_in_use=0) (stream_read_gauge_input_policy=0) (stream_read_block_size=131072));
minimums=((stream_read_block_read.failures.min=-1) (stream_read_prefetch_operations.min=689) (action_http_get_request.min=123) (stream_read_block_acquire_read.failures.min=5) (stream_read_remote_stream_drain.min=0) (stream_read_block_acquire_read.min=312) (stream_read_block_read.min=310) (stream_read_remote_stream_aborted.failures.min=-1) (action_executor_acquired.min=0) (stream_read_prefetch_operations.failures.min=-1) (stream_file_cache_eviction.failures.min=-1) (stream_read_remote_stream_drain.failures.min=-1) (action_file_opened.failures.min=-1) (action_executor_acquired.failures.min=-1) (stream_file_cache_eviction.min=0) (action_http_get_request.failures.min=-1) (stream_read_block_fetch_operations.min=311) (action_file_opened.min=395) (stream_read_block_fetch_operations.failures.min=-1) (stream_read_remote_stream_aborted.min=-1));
maximums=((stream_read_remote_stream_aborted.max=-1) (stream_read_prefetch_operations.max=841) (action_file_opened.failures.max=-1) (action_executor_acquired.max=1) (stream_read_remote_stream_drain.failures.max=-1) (stream_read_block_fetch_operations.max=311) (stream_read_prefetch_operations.failures.max=-1) (stream_read_remote_stream_aborted.failures.max=-1) (stream_read_block_read.failures.max=-1) (action_executor_acquired.failures.max=-1) (stream_read_block_acquire_read.max=312) (stream_file_cache_eviction.max=3) (stream_read_block_read.max=841) (action_http_get_request.failures.max=-1) (action_http_get_request.max=506) (stream_read_remote_stream_drain.max=2) (stream_file_cache_eviction.failures.max=-1) (stream_read_block_fetch_operations.failures.max=-1) (action_file_opened.max=395) (stream_read_block_acquire_read.failures.max=5));
means=((stream_read_block_fetch_operations.mean=(samples=1, sum=311, mean=311.0000)) (action_file_opened.mean=(samples=1, sum=395, mean=395.0000)) (stream_read_block_read.mean=(samples=9, sum=6736, mean=748.4444)) (action_http_get_request.mean=(samples=9, sum=3772, mean=419.1111)) (stream_read_block_acquire_read.mean=(samples=1, sum=312, mean=312.0000)) (action_executor_acquired.mean=(samples=17, sum=7, mean=0.4118)) (stream_read_block_fetch_operations.failures.mean=(samples=0, sum=0, mean=0.0000)) (stream_read_block_acquire_read.failures.mean=(samples=1, sum=5, mean=5.0000)) (stream_read_prefetch_operations.mean=(samples=8, sum=6430, mean=803.7500)) (stream_read_remote_stream_aborted.failures.mean=(samples=0, sum=0, mean=0.0000)) (stream_read_block_read.failures.mean=(samples=0, sum=0, mean=0.0000)) (action_http_get_request.failures.mean=(samples=0, sum=0, mean=0.0000)) (stream_read_remote_stream_drain.failures.mean=(samples=0, sum=0, mean=0.0000)) (action_executor_acquired.failu
res.mean=(samples=0, sum=0, mean=0.0000)) (action_file_opened.failures.mean=(samples=0, sum=0, mean=0.0000)) (stream_file_cache_eviction.mean=(samples=5, sum=4, mean=0.8000)) (stream_file_cache_eviction.failures.mean=(samples=0, sum=0, mean=0.0000)) (stream_read_prefetch_operations.failures.mean=(samples=0, sum=0, mean=0.0000)) (stream_read_remote_stream_drain.mean=(samples=9, sum=5, mean=0.5556)) (stream_read_remote_stream_aborted.mean=(samples=0, sum=0, mean=0.0000)));
2024-04-24 15:57:26,176 [setup] INFO prefetch.S3ACachingInputStream (S3ACachingInputStream.java:close(135)) - closed: s3a://noaa-cors-pds/raw/2023/017/ohfh/OHFH017d.23_.gz
2024-04-24 15:57:26,180 [teardown] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:innerGetFileStatus(3950)) - Getting path status for s3a://stevel-london/test (test); needEmptyDirectory=true
2024-04-24 15:57:26,180 [teardown] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:s3GetFileStatus(4009)) - S3GetFileStatus s3a://stevel-london/test
2024-04-24 15:57:26,180 [teardown] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:lambda$getObjectMetadata$10(2903)) - HEAD test with change tracker null
2024-04-24 15:57:26,181 [teardown] DEBUG impl.LoggingAuditor (LoggingAuditor.java:modifyHttpRequest(400)) - [11] e40ad9fb-842f-43ee-8784-912d440e2355-00000012 Executing op_delete with {action_http_head_request 'test' size=0, mutating=false}; https://audit.example.org/hadoop/1/op_delete/e40ad9fb-842f-43ee-8784-912d440e2355-00000012/?op=op_delete&p1=s3a://stevel-london/test&pr=stevel&ps=d8c4e4fc-c0aa-48d0-9605-2bf9ed7b08b2&id=e40ad9fb-842f-43ee-8784-912d440e2355-00000012&t0=11&fs=e40ad9fb-842f-43ee-8784-912d440e2355&t1=11&ts=1713970646179
2024-04-24 15:57:26,208 [teardown] DEBUG s3a.Invoker (Invoker.java:retryUntranslated(474)) - GET test ; software.amazon.awssdk.services.s3.model.NoSuchKeyException: null (Service: S3, Status Code: 404, Request ID: 0WF8KXPK632CJ3VQ, Extended Request ID: hN2AQhOIUdGPGeN12s8dV0y0kITYsrazXciPu68N5G6oOrXRuJTOTtrpvXGA0liUIP/D4c+HjswEtJI+hY4uBQ==) (Service: S3, Status Code: 404, Request ID: 0WF8KXPK632CJ3VQ),
2024-04-24 15:57:26,208 [teardown] DEBUG s3a.S3ARetryPolicy (S3ARetryPolicy.java:shouldRetry(308)) - Retry probe for FileNotFoundException with 0 retries and 0 failovers, idempotent=true, due to java.io.FileNotFoundException: GET test on /: software.amazon.awssdk.services.s3.model.NoSuchKeyException: null (Service: S3, Status Code: 404, Request ID: 0WF8KXPK632CJ3VQ, Extended Request ID: hN2AQhOIUdGPGeN12s8dV0y0kITYsrazXciPu68N5G6oOrXRuJTOTtrpvXGA0liUIP/D4c+HjswEtJI+hY4uBQ==) (Service: S3, Status Code: 404, Request ID: 0WF8KXPK632CJ3VQ):NoSuchKey
java.io.FileNotFoundException: GET test on /: software.amazon.awssdk.services.s3.model.NoSuchKeyException: null (Service: S3, Status Code: 404, Request ID: 0WF8KXPK632CJ3VQ, Extended Request ID: hN2AQhOIUdGPGeN12s8dV0y0kITYsrazXciPu68N5G6oOrXRuJTOTtrpvXGA0liUIP/D4c+HjswEtJI+hY4uBQ==) (Service: S3, Status Code: 404, Request ID: 0WF8KXPK632CJ3VQ):NoSuchKey
at org.apache.hadoop.fs.s3a.S3AUtils.translateException(S3AUtils.java:278)
at org.apache.hadoop.fs.s3a.Invoker.retryUntranslated(Invoker.java:481)
at org.apache.hadoop.fs.s3a.Invoker.retryUntranslated(Invoker.java:431)
at org.apache.hadoop.fs.s3a.S3AFileSystem.getObjectMetadata(S3AFileSystem.java:2895)
at org.apache.hadoop.fs.s3a.S3AFileSystem.getObjectMetadata(S3AFileSystem.java:2875)
at org.apache.hadoop.fs.s3a.S3AFileSystem.s3GetFileStatus(S3AFileSystem.java:4024)
at org.apache.hadoop.fs.s3a.S3AFileSystem.innerGetFileStatus(S3AFileSystem.java:3952)
at org.apache.hadoop.fs.s3a.S3AFileSystem.deleteWithoutCloseCheck(S3AFileSystem.java:3538)
at org.apache.hadoop.fs.s3a.S3AFileSystem.delete(S3AFileSystem.java:3510)
at org.apache.hadoop.fs.contract.ContractTestUtils.rm(ContractTestUtils.java:425)
at org.apache.hadoop.fs.contract.ContractTestUtils.cleanup(ContractTestUtils.java:402)
at org.apache.hadoop.fs.contract.AbstractFSContractTestBase.deleteTestDirInTeardown(AbstractFSContractTestBase.java:229)
at org.apache.hadoop.fs.contract.AbstractFSContractTestBase.teardown(AbstractFSContractTestBase.java:217)
at org.apache.hadoop.fs.s3a.AbstractS3ATestBase.teardown(AbstractS3ATestBase.java:124)
at org.apache.hadoop.fs.s3a.ITestS3APrefetchingCacheFiles.teardown(ITestS3APrefetchingCacheFiles.java:112)
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:59)
at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:56)
at org.junit.internal.runners.statements.RunAfters.invokeMethod(RunAfters.java:46)
at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:33)
at org.junit.rules.TestWatcher$1.evaluate(TestWatcher.java:61)
at org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:299)
at org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:293)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.lang.Thread.run(Thread.java:750)
Caused by: software.amazon.awssdk.services.s3.model.NoSuchKeyException: null (Service: S3, Status Code: 404, Request ID: 0WF8KXPK632CJ3VQ, Extended Request ID: hN2AQhOIUdGPGeN12s8dV0y0kITYsrazXciPu68N5G6oOrXRuJTOTtrpvXGA0liUIP/D4c+HjswEtJI+hY4uBQ==) (Service: S3, Status Code: 404, Request ID: 0WF8KXPK632CJ3VQ)
at software.amazon.awssdk.services.s3.model.NoSuchKeyException$BuilderImpl.build(NoSuchKeyException.java:126)
at software.amazon.awssdk.services.s3.model.NoSuchKeyException$BuilderImpl.build(NoSuchKeyException.java:80)
at software.amazon.awssdk.services.s3.internal.handlers.ExceptionTranslationInterceptor.modifyException(ExceptionTranslationInterceptor.java:63)
at software.amazon.awssdk.core.interceptor.ExecutionInterceptorChain.modifyException(ExecutionInterceptorChain.java:181)
at software.amazon.awssdk.core.internal.http.pipeline.stages.utils.ExceptionReportingUtils.runModifyException(ExceptionReportingUtils.java:54)
at software.amazon.awssdk.core.internal.http.pipeline.stages.utils.ExceptionReportingUtils.reportFailureToInterceptors(ExceptionReportingUtils.java:38)
at software.amazon.awssdk.core.internal.http.pipeline.stages.ExecutionFailureExceptionReportingStage.execute(ExecutionFailureExceptionReportingStage.java:39)
at software.amazon.awssdk.core.internal.http.pipeline.stages.ExecutionFailureExceptionReportingStage.execute(ExecutionFailureExceptionReportingStage.java:26)
at software.amazon.awssdk.core.internal.http.AmazonSyncHttpClient$RequestExecutionBuilderImpl.execute(AmazonSyncHttpClient.java:224)
at software.amazon.awssdk.core.internal.handler.BaseSyncClientHandler.invoke(BaseSyncClientHandler.java:103)
at software.amazon.awssdk.core.internal.handler.BaseSyncClientHandler.doExecute(BaseSyncClientHandler.java:173)
at software.amazon.awssdk.core.internal.handler.BaseSyncClientHandler.lambda$execute$1(BaseSyncClientHandler.java:80)
at software.amazon.awssdk.core.internal.handler.BaseSyncClientHandler.measureApiCallSuccess(BaseSyncClientHandler.java:182)
at software.amazon.awssdk.core.internal.handler.BaseSyncClientHandler.execute(BaseSyncClientHandler.java:74)
at software.amazon.awssdk.core.client.handler.SdkSyncClientHandler.execute(SdkSyncClientHandler.java:45)
at software.amazon.awssdk.awscore.client.handler.AwsSyncClientHandler.execute(AwsSyncClientHandler.java:53)
at software.amazon.awssdk.services.s3.DefaultS3Client.headObject(DefaultS3Client.java:6319)
at org.apache.hadoop.fs.s3a.S3AFileSystem.lambda$getObjectMetadata$10(S3AFileSystem.java:2907)
at org.apache.hadoop.fs.s3a.Invoker.retryUntranslated(Invoker.java:468)
... 27 more
2024-04-24 15:57:26,209 [teardown] DEBUG s3a.S3ARetryPolicy (S3ARetryPolicy.java:shouldRetry(313)) - Retry action is RetryAction(action=FAIL, delayMillis=0, reason=try once and fail.)
2024-04-24 15:57:26,209 [teardown] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:listObjects(2965)) - LIST List stevel-london:/test/ delimiter=/ keys=2 requester pays=null
2024-04-24 15:57:26,209 [teardown] DEBUG s3a.S3AFileSystem (DurationInfo.java:<init>(80)) - Starting: LIST
2024-04-24 15:57:26,210 [teardown] DEBUG impl.LoggingAuditor (LoggingAuditor.java:modifyHttpRequest(400)) - [11] e40ad9fb-842f-43ee-8784-912d440e2355-00000012 Executing op_delete with {object_list_request 'test/' size=2, mutating=false}; https://audit.example.org/hadoop/1/op_delete/e40ad9fb-842f-43ee-8784-912d440e2355-00000012/?op=op_delete&p1=s3a://stevel-london/test&pr=stevel&ps=d8c4e4fc-c0aa-48d0-9605-2bf9ed7b08b2&id=e40ad9fb-842f-43ee-8784-912d440e2355-00000012&t0=11&fs=e40ad9fb-842f-43ee-8784-912d440e2355&t1=11&ts=1713970646179
2024-04-24 15:57:26,243 [teardown] DEBUG s3a.S3AFileSystem (DurationInfo.java:close(101)) - LIST: duration 0:00.034s
2024-04-24 15:57:26,243 [teardown] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:s3GetFileStatus(4073)) - Found path as directory (with /)
2024-04-24 15:57:26,243 [teardown] DEBUG s3a.S3AFileSystem (S3ListResult.java:logAtDebug(146)) - Prefix count = 0; object count=1
2024-04-24 15:57:26,243 [teardown] DEBUG s3a.S3AFileSystem (S3ListResult.java:logAtDebug(149)) - Summary: test/ 0
2024-04-24 15:57:26,244 [teardown] DEBUG impl.DeleteOperation (DeleteOperation.java:execute(196)) - Delete path s3a://stevel-london/test - recursive true
2024-04-24 15:57:26,244 [teardown] DEBUG impl.DeleteOperation (DeleteOperation.java:execute(197)) - Type = Empty Directory
2024-04-24 15:57:26,244 [teardown] DEBUG impl.DeleteOperation (DeleteOperation.java:execute(205)) - delete: Path is a directory: s3a://stevel-london/test
2024-04-24 15:57:26,244 [teardown] DEBUG impl.DeleteOperation (DeleteOperation.java:execute(225)) - deleting empty directory s3a://stevel-london/test
2024-04-24 15:57:26,244 [teardown] DEBUG impl.DeleteOperation (DeleteOperation.java:deleteObjectAtPath(381)) - delete: dir marker test/
2024-04-24 15:57:26,245 [teardown] DEBUG s3a.Invoker (DurationInfo.java:<init>(80)) - Starting: delete
2024-04-24 15:57:26,245 [teardown] DEBUG s3a.S3AFileSystem (DurationInfo.java:<init>(80)) - Starting: deleting test/
2024-04-24 15:57:26,249 [teardown] DEBUG impl.LoggingAuditor (LoggingAuditor.java:modifyHttpRequest(400)) - [11] e40ad9fb-842f-43ee-8784-912d440e2355-00000012 Executing op_delete with {object_delete_request 'test/' size=1, mutating=true}; https://audit.example.org/hadoop/1/op_delete/e40ad9fb-842f-43ee-8784-912d440e2355-00000012/?op=op_delete&p1=s3a://stevel-london/test&pr=stevel&ps=d8c4e4fc-c0aa-48d0-9605-2bf9ed7b08b2&ks=1&id=e40ad9fb-842f-43ee-8784-912d440e2355-00000012&t0=11&fs=e40ad9fb-842f-43ee-8784-912d440e2355&t1=11&ts=1713970646179
2024-04-24 15:57:26,285 [teardown] DEBUG s3a.S3AFileSystem (DurationInfo.java:close(101)) - deleting test/: duration 0:00.040s
2024-04-24 15:57:26,285 [teardown] DEBUG s3a.Invoker (DurationInfo.java:close(101)) - delete: duration 0:00.040s
2024-04-24 15:57:26,285 [teardown] DEBUG impl.DeleteOperation (DeleteOperation.java:execute(236)) - Deleted 1 objects
2024-04-24 15:57:26,286 [teardown] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:close(4365)) - Filesystem s3a://stevel-london is closed
2024-04-24 15:57:26,286 [teardown] DEBUG s3a.S3AFileSystem (S3AUtils.java:closeAutocloseables(1552)) - Closing software.amazon.awssdk.transfer.s3.internal.GenericS3TransferManager@699de05
2024-04-24 15:57:26,286 [teardown] DEBUG s3a.S3AFileSystem (S3AUtils.java:closeAutocloseables(1552)) - Closing software.amazon.awssdk.services.s3.DefaultS3Client@41c14b57
2024-04-24 15:57:26,286 [teardown] DEBUG s3a.AWSCredentialProviderList (AWSCredentialProviderList.java:close(314)) - Closing AWSCredentialProviderList name=; refcount= 0; size=2: [TemporaryAWSCredentialsProvider, SimpleAWSCredentialsProvider{accessKey.empty=false, secretKey.empty=false}] last provider: SimpleAWSCredentialsProvider{accessKey.empty=false, secretKey.empty=false}
2024-04-24 15:57:26,288 [teardown] DEBUG s3a.S3AFileSystem (S3AUtils.java:closeAutocloseables(1552)) - Closing software.amazon.awssdk.services.s3.internal.multipart.MultipartS3AsyncClient@29dc39ba
2024-04-24 15:57:26,292 [teardown] DEBUG s3a.S3AFileSystem (HadoopExecutors.java:shutdown(118)) - Gracefully shutting down executor service BlockingThreadPoolExecutorService{SemaphoredDelegatingExecutor{permitCount=200, available=200, waiting=0}, activeCount=0}. Waiting max 30 SECONDS
2024-04-24 15:57:26,292 [teardown] DEBUG s3a.S3AFileSystem (HadoopExecutors.java:shutdown(128)) - Succesfully shutdown executor service
2024-04-24 15:57:26,292 [teardown] DEBUG s3a.S3AFileSystem (HadoopExecutors.java:shutdown(118)) - Gracefully shutting down executor service java.util.concurrent.ThreadPoolExecutor@6e3a3097[Terminated, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 0]. Waiting max 30 SECONDS
2024-04-24 15:57:26,292 [teardown] DEBUG s3a.S3AFileSystem (HadoopExecutors.java:shutdown(128)) - Succesfully shutdown executor service
2024-04-24 15:57:26,292 [teardown] DEBUG s3a.S3AFileSystem (HadoopExecutors.java:shutdown(118)) - Gracefully shutting down executor service SemaphoredDelegatingExecutor{permitCount=200, available=200, waiting=0}. Waiting max 30 SECONDS
2024-04-24 15:57:26,292 [teardown] DEBUG s3a.S3AFileSystem (HadoopExecutors.java:shutdown(128)) - Succesfully shutdown executor service
2024-04-24 15:57:26,292 [teardown] DEBUG s3a.S3AInstrumentation (S3AInstrumentation.java:close(721)) - Unregistering metrics for S3AMetrics2-stevel-london
2024-04-24 15:57:26,292 [teardown] DEBUG auth.SignerManager (SignerManager.java:close(142)) - Unregistering fs from 0 initializers
2024-04-24 15:57:26,292 [teardown] DEBUG s3a.S3AFileSystem (S3AUtils.java:closeAutocloseables(1552)) - Closing AWSCredentialProviderList name=; refcount= 0; size=2: [TemporaryAWSCredentialsProvider, SimpleAWSCredentialsProvider{accessKey.empty=false, secretKey.empty=false}] last provider: SimpleAWSCredentialsProvider{accessKey.empty=false, secretKey.empty=false}
2024-04-24 15:57:26,294 [teardown] INFO statistics.IOStatisticsLogging (IOStatisticsLogging.java:logIOStatisticsAtLevel(269)) - IOStatistics: counters=((action_http_head_request=1)
(audit_request_execution=4)
(audit_span_creation=3)
(directories_deleted=1)
(object_delete_objects=1)
(object_delete_request=1)
(object_list_request=2)
(object_metadata_request=1)
(op_delete=1)
(op_mkdirs=1)
(store_io_request=4));
gauges=();
minimums=((action_http_head_request.min=28)
(object_delete_request.min=40)
(object_list_request.min=34)
(op_delete.min=42)
(op_mkdirs.min=396));
maximums=((action_http_head_request.max=28)
(object_delete_request.max=40)
(object_list_request.max=393)
(op_delete.max=42)
(op_mkdirs.max=396));
means=((action_http_head_request.mean=(samples=1, sum=28, mean=28.0000))
(object_delete_request.mean=(samples=1, sum=40, mean=40.0000))
(object_list_request.mean=(samples=2, sum=427, mean=213.5000))
(op_delete.mean=(samples=1, sum=42, mean=42.0000))
(op_mkdirs.mean=(samples=1, sum=396, mean=396.0000)));
2024-04-24 15:57:26,295 [teardown] INFO contract.AbstractFSContractTestBase (AbstractFSContractTestBase.java:describe(280)) - closing file system
2024-04-24 15:57:26,296 [teardown] DEBUG s3a.S3AFileSystem (S3AFileSystem.java:close(4365)) - Filesystem s3a://noaa-cors-pds is closed
2024-04-24 15:57:26,296 [teardown] DEBUG s3a.S3AFileSystem (S3AUtils.java:closeAutocloseables(1552)) - Closing software.amazon.awssdk.transfer.s3.internal.GenericS3TransferManager@76875f30
2024-04-24 15:57:26,296 [teardown] DEBUG s3a.S3AFileSystem (S3AUtils.java:closeAutocloseables(1552)) - Closing software.amazon.awssdk.services.s3.DefaultS3Client@475b15d4
2024-04-24 15:57:26,296 [teardown] DEBUG s3a.AWSCredentialProviderList (AWSCredentialProviderList.java:close(314)) - Closing AWSCredentialProviderList name=; refcount= 0; size=2: [TemporaryAWSCredentialsProvider, SimpleAWSCredentialsProvider{accessKey.empty=false, secretKey.empty=false}] last provider: SimpleAWSCredentialsProvider{accessKey.empty=false, secretKey.empty=false}
2024-04-24 15:57:26,297 [teardown] DEBUG s3a.S3AFileSystem (S3AUtils.java:closeAutocloseables(1552)) - Closing software.amazon.awssdk.services.s3.internal.multipart.MultipartS3AsyncClient@3a9f0de7
2024-04-24 15:57:26,297 [teardown] DEBUG s3a.S3AFileSystem (HadoopExecutors.java:shutdown(118)) - Gracefully shutting down executor service BlockingThreadPoolExecutorService{SemaphoredDelegatingExecutor{permitCount=200, available=200, waiting=0}, activeCount=0}. Waiting max 30 SECONDS
2024-04-24 15:57:26,297 [teardown] DEBUG s3a.S3AFileSystem (HadoopExecutors.java:shutdown(128)) - Succesfully shutdown executor service
2024-04-24 15:57:26,297 [teardown] DEBUG s3a.S3AFileSystem (HadoopExecutors.java:shutdown(118)) - Gracefully shutting down executor service java.util.concurrent.ThreadPoolExecutor@11ce9005[Terminated, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 0]. Waiting max 30 SECONDS
2024-04-24 15:57:26,297 [teardown] DEBUG s3a.S3AFileSystem (HadoopExecutors.java:shutdown(128)) - Succesfully shutdown executor service
2024-04-24 15:57:26,297 [teardown] DEBUG s3a.S3AFileSystem (HadoopExecutors.java:shutdown(118)) - Gracefully shutting down executor service SemaphoredDelegatingExecutor{permitCount=200, available=200, waiting=0}. Waiting max 30 SECONDS
2024-04-24 15:57:26,297 [teardown] DEBUG s3a.S3AFileSystem (HadoopExecutors.java:shutdown(128)) - Succesfully shutdown executor service
2024-04-24 15:57:26,297 [teardown] DEBUG s3a.S3AInstrumentation (S3AInstrumentation.java:close(721)) - Unregistering metrics for S3AMetrics3-noaa-cors-pds
2024-04-24 15:57:26,298 [teardown] DEBUG auth.SignerManager (SignerManager.java:close(142)) - Unregistering fs from 0 initializers
2024-04-24 15:57:26,298 [teardown] DEBUG s3a.S3AFileSystem (S3AUtils.java:closeAutocloseables(1552)) - Closing AWSCredentialProviderList name=; refcount= 0; size=2: [TemporaryAWSCredentialsProvider, SimpleAWSCredentialsProvider{accessKey.empty=false, secretKey.empty=false}] last provider: SimpleAWSCredentialsProvider{accessKey.empty=false, secretKey.empty=false}
2024-04-24 15:57:26,299 [teardown] INFO statistics.IOStatisticsLogging (IOStatisticsLogging.java:logIOStatisticsAtLevel(269)) - IOStatistics: counters=((action_file_opened=1)
(action_http_get_request=9)
(action_http_head_request=1)
(audit_request_execution=10)
(audit_span_creation=2)
(object_metadata_request=1)
(op_open=1)
(store_io_request=10)
(stream_evict_blocks_from_cache=5)
(stream_file_cache_eviction=5)
(stream_read_block_acquire_read=2)
(stream_read_block_acquire_read.failures=1)
(stream_read_block_fetch_operations=1)
(stream_read_bytes=120832)
(stream_read_close_operations=1)
(stream_read_closed=9)
(stream_read_fully_operations=1)
(stream_read_opened=9)
(stream_read_operations=9)
(stream_read_remote_stream_drain=9)
(stream_read_seek_policy_changed=1)
(stream_read_total_bytes=1179648));
gauges=((stream_read_block_cache_enabled=1)
(stream_read_block_prefetch_enabled=1)
(stream_read_block_prefetch_limit=8)
(stream_read_block_size=131072));
minimums=((action_executor_acquired.min=0)
(action_file_opened.min=395)
(action_http_get_request.min=123)
(action_http_head_request.min=394)
(stream_file_cache_eviction.min=0)
(stream_read_block_acquire_read.failures.min=5)
(stream_read_block_acquire_read.min=312)
(stream_read_block_fetch_operations.min=311)
(stream_read_remote_stream_drain.min=0));
maximums=((action_executor_acquired.max=1)
(action_file_opened.max=395)
(action_http_get_request.max=506)
(action_http_head_request.max=394)
(stream_file_cache_eviction.max=3)
(stream_read_block_acquire_read.failures.max=5)
(stream_read_block_acquire_read.max=312)
(stream_read_block_fetch_operations.max=311)
(stream_read_remote_stream_drain.max=2));
means=((action_executor_acquired.mean=(samples=17, sum=7, mean=0.4118))
(action_file_opened.mean=(samples=1, sum=395, mean=395.0000))
(action_http_get_request.mean=(samples=9, sum=3772, mean=419.1111))
(action_http_head_request.mean=(samples=1, sum=394, mean=394.0000))
(stream_file_cache_eviction.mean=(samples=5, sum=4, mean=0.8000))
(stream_read_block_acquire_read.failures.mean=(samples=1, sum=5, mean=5.0000))
(stream_read_block_acquire_read.mean=(samples=1, sum=312, mean=312.0000))
(stream_read_block_fetch_operations.mean=(samples=1, sum=311, mean=311.0000))
(stream_read_remote_stream_drain.mean=(samples=9, sum=5, mean=0.5556)));
java.nio.file.NoSuchFileException: /Users/stevel/Projects/IDE-files/hadoop-trunk/target/prefetch/a1dd81ba-1499-440d-ba67-79705a17d5e7/fs-cache-1079555837997227351-block-0002.bin
at sun.nio.fs.UnixException.translateToIOException(UnixException.java:86)
at sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:102)
at sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:107)
at sun.nio.fs.UnixFileSystemProvider.newFileChannel(UnixFileSystemProvider.java:177)
at java.nio.channels.FileChannel.open(FileChannel.java:287)
at java.nio.channels.FileChannel.open(FileChannel.java:335)
at org.apache.hadoop.fs.impl.prefetch.SingleFilePerBlockCache.readFile(SingleFilePerBlockCache.java:290)
at org.apache.hadoop.fs.impl.prefetch.SingleFilePerBlockCache.get(SingleFilePerBlockCache.java:279)
at org.apache.hadoop.fs.impl.prefetch.CachingBlockManager.readBlock(CachingBlockManager.java:389)
at org.apache.hadoop.fs.impl.prefetch.CachingBlockManager.read(CachingBlockManager.java:337)
at org.apache.hadoop.fs.impl.prefetch.CachingBlockManager.getInternal(CachingBlockManager.java:220)
at org.apache.hadoop.fs.impl.prefetch.CachingBlockManager.get(CachingBlockManager.java:175)
at org.apache.hadoop.fs.s3a.prefetch.S3ACachingInputStream.lambda$ensureCurrentBuffer$0(S3ACachingInputStream.java:238)
at org.apache.hadoop.fs.statistics.impl.IOStatisticsBinding.invokeTrackingDuration(IOStatisticsBinding.java:556)
at org.apache.hadoop.fs.s3a.prefetch.S3ACachingInputStream.ensureCurrentBuffer(S3ACachingInputStream.java:236)
at org.apache.hadoop.fs.s3a.prefetch.S3ARemoteInputStream.read(S3ARemoteInputStream.java:357)
at org.apache.hadoop.fs.s3a.prefetch.S3APrefetchingInputStream.read(S3APrefetchingInputStream.java:198)
at org.apache.hadoop.fs.FSInputStream.read(FSInputStream.java:78)
at org.apache.hadoop.fs.FSDataInputStream.read(FSDataInputStream.java:100)
at org.apache.hadoop.fs.s3a.ITestS3APrefetchingCacheFiles.testCacheFileExistence(ITestS3APrefetchingCacheFiles.java:137)
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:59)
at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:56)
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:61)
at org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:299)
at org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:293)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.lang.Thread.run(Thread.java:750)
```
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: common-issues-unsubscribe@hadoop.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: common-issues-unsubscribe@hadoop.apache.org
For additional commands, e-mail: common-issues-help@hadoop.apache.org