tribuchet: building on mac02 Running client tests... === RUN TestDoServerRequestAttachesToken === PAUSE TestDoServerRequestAttachesToken === RUN TestUploadBuildLog_FileBodyReplayedOnRetry === PAUSE TestUploadBuildLog_FileBodyReplayedOnRetry === RUN TestRegisterUploadedObjectReusesConnections === PAUSE TestRegisterUploadedObjectReusesConnections === RUN TestRunGarbageCollection_FinishedOnAnotherReplica === PAUSE TestRunGarbageCollection_FinishedOnAnotherReplica === RUN TestRunGarbageCollection_NotFoundAfterLocalRun === PAUSE TestRunGarbageCollection_NotFoundAfterLocalRun === RUN TestCaseHackSuffix === PAUSE TestCaseHackSuffix === RUN TestFilterOversizedClosures === PAUSE TestFilterOversizedClosures === RUN TestPushPathsReportsOnlyUnuploadablePathsOfSkippedClosure === PAUSE TestPushPathsReportsOnlyUnuploadablePathsOfSkippedClosure === RUN TestUploadMultipart_PartsInParallel === PAUSE TestUploadMultipart_PartsInParallel === RUN TestUploadMultipart_ProducerErrorIsNotEOF === PAUSE TestUploadMultipart_ProducerErrorIsNotEOF === RUN TestUploadMultipart_FailedPartBufferNotReused === PAUSE TestUploadMultipart_FailedPartBufferNotReused === RUN TestPartSizeForNAR === PAUSE TestPartSizeForNAR === RUN TestUploadMultipart_SupersededByPeer === PAUSE TestUploadMultipart_SupersededByPeer === RUN TestDumpPathCaseHackMatchesNix --- PASS: TestDumpPathCaseHackMatchesNix (0.08s) === RUN TestDumpPathCaseHackCollision --- PASS: TestDumpPathCaseHackCollision (0.00s) === RUN TestSupersededNARStillUploadsListing === PAUSE TestSupersededNARStillUploadsListing === RUN TestTruncatedNARDumpIsNotCompleted === PAUSE TestTruncatedNARDumpIsNotCompleted === RUN TestDumpPathMatchesNix === PAUSE TestDumpPathMatchesNix === RUN TestDumpPathSingleFile === PAUSE TestDumpPathSingleFile === RUN TestDumpPathWriterError === PAUSE TestDumpPathWriterError === RUN TestDumpPathWriterErrorStopsReading nar_test.go:280: no /proc/self/io: open /proc/self/io: no such file or directory --- SKIP: TestDumpPathWriterErrorStopsReading (0.39s) === RUN TestEncodeNixBase32 === PAUSE TestEncodeNixBase32 === RUN TestEncodeNixBase32WithRealHash === PAUSE TestEncodeNixBase32WithRealHash === RUN TestConvertHashToNix32 === PAUSE TestConvertHashToNix32 === RUN TestGetStorePathHash === PAUSE TestGetStorePathHash === RUN TestPathInfoHashCompatibility === PAUSE TestPathInfoHashCompatibility === RUN TestParsePathInfoJSON === PAUSE TestParsePathInfoJSON === RUN TestParsePathInfoJSONMultiplePaths === PAUSE TestParsePathInfoJSONMultiplePaths === RUN TestPathInfoCACompatibility === PAUSE TestPathInfoCACompatibility === RUN TestUploadPendingObjectsStopsStartingAfterFailure --- PASS: TestUploadPendingObjectsStopsStartingAfterFailure (0.01s) === RUN TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent === PAUSE TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent === RUN TestCompletePendingClosure_NotFoundWithoutKey === PAUSE TestCompletePendingClosure_NotFoundWithoutKey === RUN TestRateLimiterFeedback === PAUSE TestRateLimiterFeedback === RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess === PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess === RUN TestRegisterUploadedObject_BoundedAgainstSilentServer === PAUSE TestRegisterUploadedObject_BoundedAgainstSilentServer === RUN TestResolveStorePath === PAUSE TestResolveStorePath === RUN TestDoWithRetry_BodyReplayedViaGetBody === PAUSE TestDoWithRetry_BodyReplayedViaGetBody === RUN TestDoWithRetry_ClosesBodyWhenNoAttemptIsMade === PAUSE TestDoWithRetry_ClosesBodyWhenNoAttemptIsMade === RUN TestRetryTimeoutOutlastsMaxRetries === PAUSE TestRetryTimeoutOutlastsMaxRetries === RUN TestDoWithRetry_FinalResponseBodyReadable === PAUSE TestDoWithRetry_FinalResponseBodyReadable === RUN TestShellSplit === PAUSE TestShellSplit === RUN TestShellSplitErrors === PAUSE TestShellSplitErrors === RUN TestStreamPushReportsEveryPath === PAUSE TestStreamPushReportsEveryPath === RUN TestStreamPushBatchesUnderLoad === PAUSE TestStreamPushBatchesUnderLoad === RUN TestStreamPushIsolatesFailures === PAUSE TestStreamPushIsolatesFailures === RUN TestStreamPushGivesUpOnDeadServer === PAUSE TestStreamPushGivesUpOnDeadServer === RUN TestStreamPushRequestLine === PAUSE TestStreamPushRequestLine === RUN TestStreamPushReportsSignatures === PAUSE TestStreamPushReportsSignatures === RUN TestStreamPushReportsSkippedPaths === PAUSE TestStreamPushReportsSkippedPaths === RUN TestClientSignaturesByStorePath === PAUSE TestClientSignaturesByStorePath === RUN TestStreamPushStopsWhenCanceled === PAUSE TestStreamPushStopsWhenCanceled === RUN TestStreamPushStopsOnCancel === PAUSE TestStreamPushStopsOnCancel === RUN TestSetClientTLS === PAUSE TestSetClientTLS === RUN TestSetClientTLSDoesNotMutateDefaultTransport === PAUSE TestSetClientTLSDoesNotMutateDefaultTransport === RUN TestSetClientTLSErrors === PAUSE TestSetClientTLSErrors === RUN TestStaticToken === PAUSE TestStaticToken === RUN TestFileTokenReadsAndCaches === PAUSE TestFileTokenReadsAndCaches === RUN TestFileTokenMissing === PAUSE TestFileTokenMissing === RUN TestFileTokenEmpty === PAUSE TestFileTokenEmpty === RUN TestScriptTokenNoExpiryRerunsEveryCall === PAUSE TestScriptTokenNoExpiryRerunsEveryCall === RUN TestScriptTokenCachesUntilRefresh === PAUSE TestScriptTokenCachesUntilRefresh === RUN TestScriptTokenEmptyToken === PAUSE TestScriptTokenEmptyToken === RUN TestScriptTokenBadJSON === PAUSE TestScriptTokenBadJSON === RUN TestScriptTokenScriptFails === PAUSE TestScriptTokenScriptFails === RUN TestScriptTokenEmptyCommand === PAUSE TestScriptTokenEmptyCommand === RUN TestScriptTokenDoesNotWaitForItsChildren === PAUSE TestScriptTokenDoesNotWaitForItsChildren === CONT TestRegisterUploadedObjectReusesConnections === CONT TestScriptTokenEmptyCommand === CONT TestStreamPushReportsSignatures === CONT TestResolveStorePath === CONT TestScriptTokenScriptFails === CONT TestScriptTokenBadJSON === CONT TestScriptTokenEmptyToken === CONT TestScriptTokenCachesUntilRefresh === CONT TestFileTokenEmpty === CONT TestFileTokenMissing === CONT TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent === RUN TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/committed_earlier === CONT TestPathInfoCACompatibility === RUN TestPathInfoCACompatibility/null_ca_field === CONT TestStaticToken === CONT TestSetClientTLSErrors === CONT TestScriptTokenNoExpiryRerunsEveryCall === CONT TestGetStorePathHash === CONT TestSetClientTLS === CONT TestSetClientTLSDoesNotMutateDefaultTransport === CONT TestStreamPushStopsWhenCanceled === CONT TestClientSignaturesByStorePath === PAUSE TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/committed_earlier === CONT TestStreamPushReportsSkippedPaths === CONT TestDumpPathMatchesNix === CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess === CONT TestRegisterUploadedObject_BoundedAgainstSilentServer === CONT TestRateLimiterFeedback === CONT TestScriptTokenDoesNotWaitForItsChildren --- PASS: TestScriptTokenEmptyCommand (0.00s) === CONT TestCompletePendingClosure_NotFoundWithoutKey === CONT TestFileTokenReadsAndCaches === CONT TestPathInfoHashCompatibility === CONT TestParsePathInfoJSONMultiplePaths === PAUSE TestPathInfoCACompatibility/null_ca_field === CONT TestParsePathInfoJSON === RUN TestGetStorePathHash/valid_store_path === CONT TestConvertHashToNix32 === CONT TestEncodeNixBase32WithRealHash === RUN TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/cleaned_up === RUN TestSetClientTLSErrors/missing_cert_file === RUN TestRateLimiterFeedback/429_enables_limiter --- PASS: TestStreamPushReportsSignatures (0.00s) === RUN TestPathInfoCACompatibility/old_string_format_-_text --- PASS: TestResolveStorePath (0.00s) === RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths === CONT TestStreamPushGivesUpOnDeadServer === CONT TestEncodeNixBase32 === RUN TestParsePathInfoJSON/Nix_format === RUN TestScriptTokenDoesNotWaitForItsChildren/cancelled_while_a_child_runs === CONT TestDumpPathWriterError === PAUSE TestRateLimiterFeedback/429_enables_limiter === PAUSE TestPathInfoCACompatibility/old_string_format_-_text === CONT TestShellSplitErrors === CONT TestStreamPushStopsOnCancel === CONT TestStreamPushRequestLine --- PASS: TestScriptTokenScriptFails (0.00s) === PAUSE TestSetClientTLSErrors/missing_cert_file === PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths === PAUSE TestParsePathInfoJSON/Nix_format === PAUSE TestScriptTokenDoesNotWaitForItsChildren/cancelled_while_a_child_runs === RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) === RUN TestSetClientTLS/rejects_connection_without_client_cert === RUN TestRateLimiterFeedback/503_enables_limiter === RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive === RUN TestSetClientTLSErrors/missing_key_file --- PASS: TestStaticToken (0.00s) === RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths === RUN TestParsePathInfoJSON/Lix_format === RUN TestScriptTokenDoesNotWaitForItsChildren/child_left_holding_stdout === RUN TestConvertHashToNix32/SRI_format_to_Nix32 === CONT TestStreamPushIsolatesFailures === PAUSE TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/cleaned_up === PAUSE TestGetStorePathHash/valid_store_path --- PASS: TestFileTokenMissing (0.00s) === PAUSE TestRateLimiterFeedback/503_enables_limiter === PAUSE TestSetClientTLSErrors/missing_key_file --- PASS: TestClientSignaturesByStorePath (0.00s) === PAUSE TestSetClientTLS/rejects_connection_without_client_cert --- PASS: TestStreamPushStopsWhenCanceled (0.00s) === CONT TestStreamPushBatchesUnderLoad --- PASS: TestFileTokenEmpty (0.00s) --- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.01s) --- PASS: TestFileTokenReadsAndCaches (0.00s) === PAUSE TestScriptTokenDoesNotWaitForItsChildren/child_left_holding_stdout === PAUSE TestConvertHashToNix32/SRI_format_to_Nix32 === PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive === CONT TestPushPathsReportsOnlyUnuploadablePathsOfSkippedClosure --- PASS: TestStreamPushReportsSkippedPaths (0.01s) === CONT TestTruncatedNARDumpIsNotCompleted === PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) === PAUSE TestParsePathInfoJSON/Lix_format --- PASS: TestCompletePendingClosure_NotFoundWithoutKey (0.01s) === RUN TestEncodeNixBase32/test_string_hash --- PASS: TestScriptTokenEmptyToken (0.02s) === RUN TestParsePathInfoJSON/empty_input === PAUSE TestParsePathInfoJSON/empty_input === RUN TestParsePathInfoJSON/whitespace_only === RUN TestPathInfoHashCompatibility/old_string_format_with_colon --- PASS: TestScriptTokenBadJSON (0.02s) --- PASS: TestEncodeNixBase32WithRealHash (0.00s) --- PASS: TestStreamPushIsolatesFailures (0.00s) === PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon === RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI === PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI === RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512 === PAUSE TestParsePathInfoJSON/whitespace_only === RUN TestParsePathInfoJSON/invalid_JSON === PAUSE TestParsePathInfoJSON/invalid_JSON === PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512 === PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths === RUN TestGetStorePathHash/basename_without_hyphen_should_error === RUN TestStreamPushStopsOnCancel/waiting_for_input === CONT TestSupersededNARStillUploadsListing === RUN TestRateLimiterFeedback/200_does_not_enable_limiter === RUN TestSupersededNARStillUploadsListing/small_NAR === PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter === CONT TestUploadMultipart_ProducerErrorIsNotEOF === RUN TestSetClientTLS/succeeds_with_client_cert_and_CA === PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA === RUN TestConvertHashToNix32/already_Nix32_format === PAUSE TestConvertHashToNix32/already_Nix32_format === RUN TestPathInfoCACompatibility/new_structured_format_-_text === PAUSE TestPathInfoCACompatibility/new_structured_format_-_text === CONT TestDumpPathSingleFile === RUN TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_committed_earlier === PAUSE TestEncodeNixBase32/test_string_hash === PAUSE TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_committed_earlier === RUN TestSetClientTLSErrors/missing_ca_file === PAUSE TestSetClientTLSErrors/missing_ca_file === CONT TestUploadMultipart_FailedPartBufferNotReused --- PASS: TestShellSplitErrors (0.00s) === CONT TestUploadMultipart_SupersededByPeer === CONT TestPartSizeForNAR === PAUSE TestGetStorePathHash/basename_without_hyphen_should_error === PAUSE TestStreamPushStopsOnCancel/waiting_for_input === RUN TestStreamPushBatchesUnderLoad/together === PAUSE TestSupersededNARStillUploadsListing/small_NAR === RUN TestUploadMultipart_ProducerErrorIsNotEOF/short_read_inside_a_part === RUN TestStreamPushStopsOnCancel/partial_batch_waiting_for_a_slot === PAUSE TestStreamPushBatchesUnderLoad/together === PAUSE TestStreamPushStopsOnCancel/partial_batch_waiting_for_a_slot === RUN TestRateLimiterFeedback/400_does_not_enable_limiter === PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter --- PASS: TestStreamPushGivesUpOnDeadServer (0.01s) === RUN TestSetClientTLS/preserves_debug_logging_transport === PAUSE TestSetClientTLS/preserves_debug_logging_transport === PAUSE TestUploadMultipart_ProducerErrorIsNotEOF/short_read_inside_a_part === RUN TestConvertHashToNix32/invalid_format === RUN TestEncodeNixBase32/empty_input === RUN TestUploadMultipart_ProducerErrorIsNotEOF/empty_read_on_a_part_boundary === RUN TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_cleaned_up,_first_root_committed_by_another_client === RUN TestSetClientTLSErrors/invalid_ca_file === RUN TestUploadMultipart_SupersededByPeer/exists === RUN TestPartSizeForNAR/zero_stays_at_minimum === PAUSE TestPartSizeForNAR/zero_stays_at_minimum === RUN TestGetStorePathHash/hash_with_invalid_characters_should_error === PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error === PAUSE TestUploadMultipart_ProducerErrorIsNotEOF/empty_read_on_a_part_boundary === RUN TestGetStorePathHash/hash_with_wrong_length_should_error === CONT TestCaseHackSuffix === PAUSE TestConvertHashToNix32/invalid_format === RUN TestStreamPushBatchesUnderLoad/one_at_a_time === RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method === PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method --- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.03s) === CONT TestRetryTimeoutOutlastsMaxRetries === RUN TestStreamPushStopsOnCancel/input_closed,_last_batch_waiting_for_a_slot --- PASS: TestScriptTokenCachesUntilRefresh (0.04s) === PAUSE TestStreamPushStopsOnCancel/input_closed,_last_batch_waiting_for_a_slot === RUN TestSupersededNARStillUploadsListing/dump_cut_short === CONT TestFilterOversizedClosures === PAUSE TestEncodeNixBase32/empty_input === PAUSE TestSupersededNARStillUploadsListing/dump_cut_short === CONT TestRunGarbageCollection_FinishedOnAnotherReplica === PAUSE TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_cleaned_up,_first_root_committed_by_another_client === PAUSE TestSetClientTLSErrors/invalid_ca_file === RUN TestPartSizeForNAR/small_stays_at_minimum === RUN TestSupersededNARStillUploadsListing/listing_upload_fails === PAUSE TestPartSizeForNAR/small_stays_at_minimum === CONT TestUploadBuildLog_FileBodyReplayedOnRetry === RUN TestPartSizeForNAR/80_GiB_fits_at_minimum === PAUSE TestStreamPushBatchesUnderLoad/one_at_a_time === PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error === PAUSE TestUploadMultipart_SupersededByPeer/exists === RUN TestUploadMultipart_SupersededByPeer/missing === PAUSE TestUploadMultipart_SupersededByPeer/missing === RUN TestStreamPushStopsOnCancel/full_batch_waiting_for_a_slot === RUN TestFilterOversizedClosures/no_limit_keeps_everything === CONT TestShellSplit === PAUSE TestFilterOversizedClosures/no_limit_keeps_everything === RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped === CONT TestDoWithRetry_FinalResponseBodyReadable --- PASS: TestShellSplit (0.00s) === RUN TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_cleaned_up,_last_root_committed_by_another_client === PAUSE TestStreamPushStopsOnCancel/full_batch_waiting_for_a_slot === RUN TestStreamPushStopsOnCancel/request_line_waiting_for_a_slot === PAUSE TestStreamPushStopsOnCancel/request_line_waiting_for_a_slot === PAUSE TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_cleaned_up,_last_root_committed_by_another_client === PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped === PAUSE TestSupersededNARStillUploadsListing/listing_upload_fails === CONT TestStreamPushReportsEveryPath === CONT TestRunGarbageCollection_NotFoundAfterLocalRun === PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum === CONT TestDoWithRetry_ClosesBodyWhenNoAttemptIsMade === CONT TestDoWithRetry_BodyReplayedViaGetBody === CONT TestUploadMultipart_PartsInParallel --- PASS: TestStreamPushReportsEveryPath (0.00s) === RUN TestStreamPushStopsOnCancel/lines_read_but_not_taken === PAUSE TestStreamPushStopsOnCancel/lines_read_but_not_taken === CONT TestDoServerRequestAttachesToken === RUN TestPartSizeForNAR/115_GiB_needs_larger_parts === RUN TestDoWithRetry_ClosesBodyWhenNoAttemptIsMade/retries=0 === RUN TestFilterOversizedClosures/all_closures_skipped === CONT TestScriptTokenDoesNotWaitForItsChildren/child_left_holding_stdout --- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.01s) === CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI === PAUSE TestFilterOversizedClosures/all_closures_skipped === CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512 === CONT TestPathInfoHashCompatibility/old_string_format_with_colon === CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths --- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.01s) === CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths === CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) === CONT TestScriptTokenDoesNotWaitForItsChildren/cancelled_while_a_child_runs === PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts === RUN TestPartSizeForNAR/1_TiB === PAUSE TestPartSizeForNAR/1_TiB === RUN TestPartSizeForNAR/5_TiB_S3_max_object === PAUSE TestPartSizeForNAR/5_TiB_S3_max_object === RUN TestPartSizeForNAR/capped_at_5_GiB === PAUSE TestPartSizeForNAR/capped_at_5_GiB === PAUSE TestDoWithRetry_ClosesBodyWhenNoAttemptIsMade/retries=0 === RUN TestDoWithRetry_ClosesBodyWhenNoAttemptIsMade/retries=5 === PAUSE TestDoWithRetry_ClosesBodyWhenNoAttemptIsMade/retries=5 === CONT TestParsePathInfoJSON/Nix_format === CONT TestParsePathInfoJSON/whitespace_only --- PASS: TestDoServerRequestAttachesToken (0.02s) === CONT TestParsePathInfoJSON/invalid_JSON === CONT TestParsePathInfoJSON/empty_input === CONT TestParsePathInfoJSON/Lix_format === CONT TestRateLimiterFeedback/429_enables_limiter --- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.02s) === CONT TestSetClientTLS/rejects_connection_without_client_cert === CONT TestRateLimiterFeedback/200_does_not_enable_limiter === CONT TestRateLimiterFeedback/400_does_not_enable_limiter --- PASS: TestParsePathInfoJSON (0.02s) --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s) --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s) --- PASS: TestParsePathInfoJSON/Nix_format (0.00s) --- PASS: TestParsePathInfoJSON/empty_input (0.00s) --- PASS: TestParsePathInfoJSON/Lix_format (0.00s) === CONT TestRateLimiterFeedback/503_enables_limiter === CONT TestSetClientTLS/preserves_debug_logging_transport === CONT TestSetClientTLS/succeeds_with_client_cert_and_CA === CONT TestUploadMultipart_ProducerErrorIsNotEOF/empty_read_on_a_part_boundary --- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.01s) --- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.01s) --- PASS: TestPathInfoHashCompatibility (0.02s) --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s) --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s) --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s) --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s) === CONT TestUploadMultipart_ProducerErrorIsNotEOF/short_read_inside_a_part --- PASS: TestParsePathInfoJSONMultiplePaths (0.02s) --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s) --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s) === CONT TestConvertHashToNix32/already_Nix32_format === CONT TestConvertHashToNix32/invalid_format === CONT TestConvertHashToNix32/SRI_format_to_Nix32 === CONT TestPathInfoCACompatibility/null_ca_field === CONT TestPathInfoCACompatibility/new_structured_format_-_text === CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method === CONT TestPathInfoCACompatibility/old_string_format_-_text === CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive === CONT TestEncodeNixBase32/test_string_hash --- PASS: TestPathInfoCACompatibility (0.04s) --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s) --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s) --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s) --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s) --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s) === CONT TestEncodeNixBase32/empty_input --- PASS: TestEncodeNixBase32 (0.02s) --- PASS: TestEncodeNixBase32/test_string_hash (0.00s) --- PASS: TestEncodeNixBase32/empty_input (0.00s) === CONT TestSetClientTLSErrors/missing_key_file === CONT TestSetClientTLSErrors/invalid_ca_file === CONT TestSetClientTLSErrors/missing_ca_file === CONT TestSetClientTLSErrors/missing_cert_file === CONT TestGetStorePathHash/valid_store_path === CONT TestStreamPushBatchesUnderLoad/one_at_a_time --- PASS: TestConvertHashToNix32 (0.02s) --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s) --- PASS: TestConvertHashToNix32/invalid_format (0.00s) --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.01s) === CONT TestGetStorePathHash/hash_with_wrong_length_should_error === CONT TestGetStorePathHash/hash_with_invalid_characters_should_error === CONT TestUploadMultipart_SupersededByPeer/missing --- PASS: TestSetClientTLSErrors (0.04s) --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s) --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s) --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s) --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s) === CONT TestUploadMultipart_SupersededByPeer/exists === CONT TestGetStorePathHash/basename_without_hyphen_should_error --- PASS: TestRateLimiterFeedback (0.03s) --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.01s) --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.01s) --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.01s) --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.03s) === CONT TestStreamPushBatchesUnderLoad/together --- PASS: TestGetStorePathHash (0.04s) --- PASS: TestGetStorePathHash/valid_store_path (0.00s) --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s) --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s) --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s) === CONT TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_cleaned_up,_first_root_committed_by_another_client === CONT TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_cleaned_up,_last_root_committed_by_another_client === CONT TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_committed_earlier === CONT TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/cleaned_up --- PASS: TestStreamPushBatchesUnderLoad (0.02s) --- PASS: TestStreamPushBatchesUnderLoad/one_at_a_time (0.01s) --- PASS: TestStreamPushBatchesUnderLoad/together (0.01s) === CONT TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/committed_earlier === CONT TestSupersededNARStillUploadsListing/listing_upload_fails --- PASS: TestUploadMultipart_SupersededByPeer (0.00s) --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.01s) --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.01s) --- PASS: TestDumpPathSingleFile (0.09s) === CONT TestSupersededNARStillUploadsListing/dump_cut_short === CONT TestSupersededNARStillUploadsListing/small_NAR === CONT TestStreamPushStopsOnCancel/waiting_for_input === CONT TestStreamPushStopsOnCancel/lines_read_but_not_taken === CONT TestStreamPushStopsOnCancel/full_batch_waiting_for_a_slot === CONT TestStreamPushStopsOnCancel/input_closed,_last_batch_waiting_for_a_slot === CONT TestStreamPushStopsOnCancel/request_line_waiting_for_a_slot === CONT TestFilterOversizedClosures/all_closures_skipped === CONT TestFilterOversizedClosures/no_limit_keeps_everything --- PASS: TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent (0.04s) --- PASS: TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_cleaned_up,_last_root_committed_by_another_client (0.02s) --- PASS: TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/cleaned_up (0.02s) --- PASS: TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_cleaned_up,_first_root_committed_by_another_client (0.03s) --- PASS: TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_committed_earlier (0.04s) --- PASS: TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/committed_earlier (0.04s) === CONT TestDoWithRetry_ClosesBodyWhenNoAttemptIsMade/retries=0 --- PASS: TestUploadMultipart_ProducerErrorIsNotEOF (0.01s) --- PASS: TestUploadMultipart_ProducerErrorIsNotEOF/empty_read_on_a_part_boundary (0.06s) --- PASS: TestUploadMultipart_ProducerErrorIsNotEOF/short_read_inside_a_part (0.08s) --- PASS: TestStreamPushRequestLine (0.14s) --- PASS: TestCaseHackSuffix (0.12s) === CONT TestStreamPushStopsOnCancel/partial_batch_waiting_for_a_slot === CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped === CONT TestDoWithRetry_ClosesBodyWhenNoAttemptIsMade/retries=5 === CONT TestPartSizeForNAR/5_TiB_S3_max_object === CONT TestPartSizeForNAR/zero_stays_at_minimum === CONT TestPartSizeForNAR/1_TiB === CONT TestPartSizeForNAR/capped_at_5_GiB === CONT TestPartSizeForNAR/115_GiB_needs_larger_parts === CONT TestPartSizeForNAR/small_stays_at_minimum --- PASS: TestFilterOversizedClosures (0.01s) --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s) --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s) --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s) === CONT TestPartSizeForNAR/80_GiB_fits_at_minimum --- PASS: TestDoWithRetry_ClosesBodyWhenNoAttemptIsMade (0.02s) --- PASS: TestDoWithRetry_ClosesBodyWhenNoAttemptIsMade/retries=0 (0.00s) --- PASS: TestDoWithRetry_ClosesBodyWhenNoAttemptIsMade/retries=5 (0.00s) --- PASS: TestPartSizeForNAR (0.02s) --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s) --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s) --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s) --- PASS: TestPartSizeForNAR/1_TiB (0.00s) --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s) --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s) --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s) --- PASS: TestDumpPathWriterError (0.15s) --- PASS: TestRetryTimeoutOutlastsMaxRetries (0.13s) --- PASS: TestSetClientTLS (0.04s) --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.03s) --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.04s) --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.11s) --- PASS: TestStreamPushStopsOnCancel (0.02s) --- PASS: TestStreamPushStopsOnCancel/waiting_for_input (0.05s) --- PASS: TestStreamPushStopsOnCancel/input_closed,_last_batch_waiting_for_a_slot (0.05s) --- PASS: TestStreamPushStopsOnCancel/lines_read_but_not_taken (0.05s) --- PASS: TestStreamPushStopsOnCancel/partial_batch_waiting_for_a_slot (0.05s) --- PASS: TestStreamPushStopsOnCancel/full_batch_waiting_for_a_slot (0.05s) --- PASS: TestStreamPushStopsOnCancel/request_line_waiting_for_a_slot (0.05s) --- PASS: TestDumpPathMatchesNix (0.24s) --- PASS: TestRegisterUploadedObjectReusesConnections (0.29s) --- PASS: TestPushPathsReportsOnlyUnuploadablePathsOfSkippedClosure (0.27s) --- PASS: TestTruncatedNARDumpIsNotCompleted (0.45s) --- PASS: TestUploadMultipart_FailedPartBufferNotReused (0.67s) --- PASS: TestUploadMultipart_PartsInParallel (0.68s) --- PASS: TestSupersededNARStillUploadsListing (0.01s) --- PASS: TestSupersededNARStillUploadsListing/listing_upload_fails (0.06s) --- PASS: TestSupersededNARStillUploadsListing/small_NAR (0.04s) --- PASS: TestSupersededNARStillUploadsListing/dump_cut_short (0.65s) --- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s) --- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (2.01s) --- PASS: TestScriptTokenDoesNotWaitForItsChildren (0.01s) --- PASS: TestScriptTokenDoesNotWaitForItsChildren/child_left_holding_stdout (2.05s) --- PASS: TestScriptTokenDoesNotWaitForItsChildren/cancelled_while_a_child_runs (2.21s) PASS Running server tests... The files belonging to this database system will be owned by user "_tribuchetbld5". This user must also own the server process. The database cluster will be initialized with locale "C". The default database encoding has accordingly been set to "SQL_ASCII". The default text search configuration will be set to "english". Data page checksums are enabled. creating directory /private/var/tb/5/scratch/00f1341bdd59a71e/build/postgres1970240236/data ... ok creating subdirectories ... ok selecting dynamic shared memory implementation ... posix selecting default "max_connections" ... 100 selecting default "shared_buffers" ... 128MB selecting default time zone ... UTC creating configuration files ... ok running bootstrap script ... ok performing post-bootstrap initialization ... ok syncing data to disk ... ok initdb: warning: enabling "trust" authentication for local connections initdb: hint: You can change this by editing pg_hba.conf or using the option -A, or --auth-local and --auth-host, the next time you run initdb. Success. You can now start the database server using: pg_ctl -D /private/var/tb/5/scratch/00f1341bdd59a71e/build/postgres1970240236/data -l logfile start 2026-10-09 09:57:30.815 UTC [65329] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit 2026-10-09 09:57:30.815 UTC [65329] LOG: listening on Unix socket "/private/var/tb/5/scratch/00f1341bdd59a71e/build/postgres1970240236/.s.PGSQL.5432" 2026-10-09 09:57:30.817 UTC [65336] LOG: database system was shut down at 2026-10-09 09:57:30 UTC 2026-10-09 09:57:30.818 UTC [65329] LOG: database system is ready to accept connections /private/var/tb/5/scratch/00f1341bdd59a71e/build/postgres1970240236:5432 - accepting connections {"timestamp":"2026-10-09T09:57:33.008729Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"4d6c9634-721f-478f-ab55-734248db51ce","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":1,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":501,"threadName":"rustfs-worker","threadId":"ThreadId(4)"} === RUN TestService_AuthMiddleware === PAUSE TestService_AuthMiddleware === RUN TestService_AuthMiddleware_MTLSProxyHeader === PAUSE TestService_AuthMiddleware_MTLSProxyHeader === RUN TestService_AuthMiddleware_MTLSBoundSubjects === PAUSE TestService_AuthMiddleware_MTLSBoundSubjects === RUN TestService_ReadAuthMiddleware === PAUSE TestService_ReadAuthMiddleware === RUN TestService_AuthMiddleware_OIDC === PAUSE TestService_AuthMiddleware_OIDC === RUN TestService_RequireScope_OIDC === PAUSE TestService_RequireScope_OIDC === RUN TestService_ReadScope_PublicByDefault === PAUSE TestService_ReadScope_PublicByDefault === RUN TestCacheConfigHandler === PAUSE TestCacheConfigHandler === RUN TestCacheStatsHandler === PAUSE TestCacheStatsHandler === RUN TestClientCADerivations === PAUSE TestClientCADerivations === RUN TestClientErrorHandling === PAUSE TestClientErrorHandling === RUN TestClientIntegration === PAUSE TestClientIntegration === RUN TestClientMultipleUploads === PAUSE TestClientMultipleUploads === RUN TestClientWithDependencies === PAUSE TestClientWithDependencies === RUN TestClientSharedPathCommittedMidPush === PAUSE TestClientSharedPathCommittedMidPush === RUN TestPinProtectsFromGC === PAUSE TestPinProtectsFromGC === RUN TestClientPushesUseOnePush === PAUSE TestClientPushesUseOnePush === RUN TestClientFallsBackToClosures === PAUSE TestClientFallsBackToClosures === RUN TestDeleteClosuresRacingPins === PAUSE TestDeleteClosuresRacingPins === RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock === PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock === RUN TestResolveDBConnectionString === PAUSE TestResolveDBConnectionString === RUN TestConnectWaitsForAPeerMigration === PAUSE TestConnectWaitsForAPeerMigration === RUN TestConnectSerialisesConcurrentMigrations === PAUSE TestConnectSerialisesConcurrentMigrations === RUN TestLeadElectsOneAndHandsOver === PAUSE TestLeadElectsOneAndHandsOver === RUN TestLeadIncumbentWinsAfterRestart 2026/10/09 09:57:33 INFO lead: acquired remote=192.0.2.1:1234 2026/10/09 09:57:34 INFO lead: released remote=192.0.2.1:1234 2026/10/09 09:57:34 INFO lead: acquired remote=192.0.2.1:1234 2026/10/09 09:57:35 INFO lead: released remote=192.0.2.1:1234 --- PASS: TestLeadIncumbentWinsAfterRestart (2.08s) === RUN TestLeadIncumbentAnnouncesAtOnce === PAUSE TestLeadIncumbentAnnouncesAtOnce === RUN TestLeadEndsOnShutdown === PAUSE TestLeadEndsOnShutdown === RUN TestLeadEndsWhenItsConnectionHangs 2026/10/09 09:57:35 INFO lead: acquired remote=192.0.2.1:1234 2026-10-09 09:57:36.548 UTC [65470] FATAL: terminating connection due to administrator command 2026/10/09 09:57:36 INFO lead: acquired remote=192.0.2.1:1234 2026/10/09 09:57:37 WARN lead: lock connection lost error="timeout: context deadline exceeded" 2026/10/09 09:57:37 INFO lead: released remote=192.0.2.1:1234 2026/10/09 09:57:37 INFO lead: released remote=192.0.2.1:1234 --- PASS: TestLeadEndsWhenItsConnectionHangs (2.76s) === RUN TestGCAdvisoryLockBlocksConcurrentRun === PAUSE TestGCAdvisoryLockBlocksConcurrentRun === RUN TestGCBugBareHashReferences === PAUSE TestGCBugBareHashReferences === RUN TestGCMetrics === PAUSE TestGCMetrics === RUN TestPushDedupSurvivesConcurrentGC === PAUSE TestPushDedupSurvivesConcurrentGC === RUN TestDeduplicatedObjectsRecordedAsPending === PAUSE TestDeduplicatedObjectsRecordedAsPending === RUN TestGCSweepSkipsPendingObjects === PAUSE TestGCSweepSkipsPendingObjects === RUN TestTombstonedObjectOfferedWithoutWaiting === PAUSE TestTombstonedObjectOfferedWithoutWaiting === RUN TestGCSweepDeliversEachKeyOnce === PAUSE TestGCSweepDeliversEachKeyOnce === RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection === PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection === RUN TestForceGCDuringPushOffersSweptObject === PAUSE TestForceGCDuringPushOffersSweptObject === RUN TestFailedS3DeleteKeepsTombstone === PAUSE TestFailedS3DeleteKeepsTombstone === RUN TestSweepSkipsRowsLockedByPush === PAUSE TestSweepSkipsRowsLockedByPush === RUN TestRegisterCompletedObjectNeedsPendingRow === PAUSE TestRegisterCompletedObjectNeedsPendingRow === RUN TestGetExistingObjectsLocksRows === PAUSE TestGetExistingObjectsLocksRows === RUN TestSweepRechecksPendingAfterLocking === PAUSE TestSweepRechecksPendingAfterLocking === RUN TestPushWaitsForSweepHoldingRow === PAUSE TestPushWaitsForSweepHoldingRow === RUN TestCommitRacingPendingCleanupKeepsObjects === PAUSE TestCommitRacingPendingCleanupKeepsObjects === RUN TestGCEndsOnShutdown === PAUSE TestGCEndsOnShutdown === RUN TestGCTaskStore_StartNew === PAUSE TestGCTaskStore_StartNew === RUN TestGCTaskStore_DeduplicateSameParams === PAUSE TestGCTaskStore_DeduplicateSameParams === RUN TestGCTaskStore_ConflictDifferentParams === PAUSE TestGCTaskStore_ConflictDifferentParams === RUN TestGCTaskStore_GetEmpty === PAUSE TestGCTaskStore_GetEmpty === RUN TestGCTaskStore_GetReturnsLatest === PAUSE TestGCTaskStore_GetReturnsLatest === RUN TestGCTaskStore_CompletedAllowsNewTask === PAUSE TestGCTaskStore_CompletedAllowsNewTask === RUN TestGCTaskStore_PhaseUpdates === PAUSE TestGCTaskStore_PhaseUpdates === RUN TestGCTaskStore_Fail === PAUSE TestGCTaskStore_Fail === RUN TestGracefulShutdownDrainsInflight === PAUSE TestGracefulShutdownDrainsInflight === RUN TestService_healthCheckHandler === PAUSE TestService_healthCheckHandler === RUN TestService_readinessHandler === PAUSE TestService_readinessHandler === RUN TestGenerateLandingPage === PAUSE TestGenerateLandingPage === RUN TestCacheConfigHandlerMaxNarSize === PAUSE TestCacheConfigHandlerMaxNarSize === RUN TestCreatePendingClosureRejectsOversizedNAR === PAUSE TestCreatePendingClosureRejectsOversizedNAR === RUN TestNARDeduplicationMetadataUploadBug === PAUSE TestNARDeduplicationMetadataUploadBug === RUN TestMetricsInventory === PAUSE TestMetricsInventory === RUN TestMetricsCommit === PAUSE TestMetricsCommit === RUN TestService_NativeMTLS === PAUSE TestService_NativeMTLS === RUN TestServerTLSConfig === PAUSE TestServerTLSConfig === RUN TestMultipartCleanup === PAUSE TestMultipartCleanup === RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded === PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded === RUN TestPendingCleanupUsesOneCutoff === PAUSE TestPendingCleanupUsesOneCutoff === RUN TestPendingClosureFailureTracksEveryUpload === PAUSE TestPendingClosureFailureTracksEveryUpload === RUN TestPendingClosureFailureAbortsItsUploads === PAUSE TestPendingClosureFailureAbortsItsUploads === RUN TestObjectStatsTrigger === PAUSE TestObjectStatsTrigger === RUN TestObjectStatsLargeCommit === PAUSE TestObjectStatsLargeCommit === RUN TestReconnectLeavesObjectsUnlocked === PAUSE TestReconnectLeavesObjectsUnlocked === RUN TestOrphanedObjectsGC === PAUSE TestOrphanedObjectsGC === RUN TestOrphanedObjectsGCStressTest === PAUSE TestOrphanedObjectsGCStressTest === RUN TestCreatePin_ReservedPins === PAUSE TestCreatePin_ReservedPins === RUN TestConcurrentPinUpdatesAgree === PAUSE TestConcurrentPinUpdatesAgree === RUN TestCreatePinRejectsBadInput === PAUSE TestCreatePinRejectsBadInput === RUN TestDeletePinKeepsRowWhenS3Fails === PAUSE TestDeletePinKeepsRowWhenS3Fails === RUN TestPresentReportsOnlyClosureRoots === PAUSE TestPresentReportsOnlyClosureRoots === RUN TestPresentRefreshesOnlyStaleClosures === PAUSE TestPresentRefreshesOnlyStaleClosures === RUN TestPresentNotReportedWhileGCDeletesClosure === PAUSE TestPresentNotReportedWhileGCDeletesClosure === RUN TestParseSingleRange === PAUSE TestParseSingleRange === RUN TestProxyHeadersOnlyTrustedOnSocket 2026/10/09 09:57:38 INFO Starting HTTP server address=127.0.0.1:61170 2026/10/09 09:57:38 INFO Starting HTTP server address=proxy.sock 2026/10/09 09:57:38 WARN mTLS auth: subject not in bound subjects subject="CN=someone" 2026/10/09 09:57:38 INFO Shutdown signal received, draining in-flight requests timeout=10s --- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.15s) === RUN TestIsValidCachePath === PAUSE TestIsValidCachePath === RUN TestReadProxyNarinfo === PAUSE TestReadProxyNarinfo === RUN TestReadProxyNarinfoAlreadyDecompressed === PAUSE TestReadProxyNarinfoAlreadyDecompressed === RUN TestReadProxyContentNegotiation === PAUSE TestReadProxyContentNegotiation === RUN TestReadProxyNarStreaming === PAUSE TestReadProxyNarStreaming === RUN TestReadProxy404 === PAUSE TestReadProxy404 === RUN TestReadProxyInvalidPath === PAUSE TestReadProxyInvalidPath === RUN TestReadProxyHead === PAUSE TestReadProxyHead === RUN TestReadProxyOutlastsServerWriteTimeout === PAUSE TestReadProxyOutlastsServerWriteTimeout === RUN TestReadProxyConditionalGet === PAUSE TestReadProxyConditionalGet === RUN TestReadProxyRootRedirectsToIndexHTML === PAUSE TestReadProxyRootRedirectsToIndexHTML === RUN TestReadProxyDisabled === PAUSE TestReadProxyDisabled === RUN TestReadRedirectNar === PAUSE TestReadRedirectNar === RUN TestReadRedirectKeepsNarinfoProxied === PAUSE TestReadRedirectKeepsNarinfoProxied === RUN TestReadProxyRangeRequest === PAUSE TestReadProxyRangeRequest === RUN TestReadRedirectUsesPublicS3URL === PAUSE TestReadRedirectUsesPublicS3URL === RUN TestPush_OverlappingRootsStoreOneRowPerKey === PAUSE TestPush_OverlappingRootsStoreOneRowPerKey === RUN TestPush_CompleteCommitsEveryRoot === PAUSE TestPush_CompleteCommitsEveryRoot === RUN TestPush_RepeatedRootCommitsOnce === PAUSE TestPush_RepeatedRootCommitsOnce === RUN TestPush_CompleteWaitsForCleanupOfThePush === PAUSE TestPush_CompleteWaitsForCleanupOfThePush === RUN TestPush_RootsAreLockedInByteOrder === PAUSE TestPush_RootsAreLockedInByteOrder === RUN TestPush_SkippedKeySurvivesGCBeforeCommit === PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit === RUN TestPush_RejectsBadRequests === PAUSE TestPush_RejectsBadRequests === RUN TestPush_SignsNarinfosOfItsPendingObjects === PAUSE TestPush_SignsNarinfosOfItsPendingObjects === RUN TestRedundantMultipartUpload === PAUSE TestRedundantMultipartUpload === RUN TestCompleteMultipartUpload_ErrorButObjectExists === PAUSE TestCompleteMultipartUpload_ErrorButObjectExists === RUN TestCompletedNarNotReofferedAcrossClosures === PAUSE TestCompletedNarNotReofferedAcrossClosures === RUN TestPresignedUploadRegisteredBeforeCommit === PAUSE TestPresignedUploadRegisteredBeforeCommit === RUN TestService_Rustfstest === PAUSE TestService_Rustfstest === RUN TestParseSize === PAUSE TestParseSize === RUN TestSkippedUploadsHandler === PAUSE TestSkippedUploadsHandler === RUN TestSystemdListenerNotActivated --- PASS: TestSystemdListenerNotActivated (0.00s) === RUN TestWatchdogBeatsWhenHealthy --- PASS: TestWatchdogBeatsWhenHealthy (0.02s) === RUN TestWatchdogSkipsWhenUnhealthy 2026/10/09 09:57:38 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded" 2026/10/09 09:57:38 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded" 2026/10/09 09:57:38 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded" 2026/10/09 09:57:38 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded" 2026/10/09 09:57:38 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded" 2026/10/09 09:57:38 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded" 2026/10/09 09:57:38 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded" 2026/10/09 09:57:38 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded" 2026/10/09 09:57:38 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded" 2026/10/09 09:57:38 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded" --- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s) === RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle === PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle === RUN TestProxyWriteTimeout === PAUSE TestProxyWriteTimeout === RUN TestPendingClosureWriteTimeout === PAUSE TestPendingClosureWriteTimeout === RUN TestIsValidUploadKey === PAUSE TestIsValidUploadKey === RUN TestUploadHandlersRejectInvalidKeys === PAUSE TestUploadHandlersRejectInvalidKeys === RUN TestUploadHandlersRejectOversizedBody === PAUSE TestUploadHandlersRejectOversizedBody === RUN TestService_cleanupPendingClosuresHandler === PAUSE TestService_cleanupPendingClosuresHandler === RUN TestService_createPendingClosureHandler === PAUSE TestService_createPendingClosureHandler === RUN TestService_verifyS3Integrity === PAUSE TestService_verifyS3Integrity === RUN TestCompleteMultipartUnregistered === PAUSE TestCompleteMultipartUnregistered === RUN TestCreatePendingClosure_SmallNARUsesSimplePUT === PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT === CONT TestService_AuthMiddleware === CONT TestService_createPendingClosureHandler === CONT TestGCTaskStore_CompletedAllowsNewTask === CONT TestPendingClosureFailureAbortsItsUploads --- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s) === CONT TestIsValidUploadKey === CONT TestOrphanedObjectsGC === CONT TestService_verifyS3Integrity === CONT TestService_readinessHandler === CONT TestFailedS3DeleteKeepsTombstone === CONT TestCompleteMultipartUnregistered === CONT TestService_cleanupPendingClosuresHandler === CONT TestGracefulShutdownDrainsInflight === CONT TestObjectStatsLargeCommit === CONT TestReconnectLeavesObjectsUnlocked === CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock === CONT TestReadRedirectKeepsNarinfoProxied === CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection === CONT TestService_healthCheckHandler === CONT TestForceGCDuringPushOffersSweptObject === RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows === CONT TestPendingClosureFailureTracksEveryUpload === PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows === CONT TestUploadHandlersRejectOversizedBody === CONT TestUploadHandlersRejectInvalidKeys === CONT TestPendingClosureWriteTimeout === CONT TestObjectStatsTrigger === RUN TestIsValidUploadKey/narinfo === CONT TestCreatePendingClosure_SmallNARUsesSimplePUT === RUN TestPendingClosureFailureTracksEveryUpload/refuse_aborts=false 2026/10/09 09:57:38 INFO Starting HTTP server address=127.0.0.1:61179 === RUN TestForceGCDuringPushOffersSweptObject/after_presence_check === RUN TestPendingClosureWriteTimeout/empty === RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info === PAUSE TestIsValidUploadKey/narinfo === PAUSE TestPendingClosureWriteTimeout/empty === RUN TestIsValidUploadKey/nar_zst === RUN TestPendingClosureWriteTimeout/400_objects === PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check === PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info === PAUSE TestPendingClosureWriteTimeout/400_objects === PAUSE TestIsValidUploadKey/nar_zst === RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal === RUN TestPendingClosureWriteTimeout/670k_objects === RUN TestIsValidUploadKey/nar_xz === CONT TestGCSweepDeliversEachKeyOnce === PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal === RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key === PAUSE TestPendingClosureWriteTimeout/670k_objects === RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline === PAUSE TestIsValidUploadKey/nar_xz === PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key === RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key === PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key === CONT TestSkippedUploadsHandler === PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline === PAUSE TestPendingClosureFailureTracksEveryUpload/refuse_aborts=false === RUN TestPendingClosureFailureTracksEveryUpload/refuse_aborts=true === CONT TestPendingCleanupUsesOneCutoff === RUN TestIsValidUploadKey/nar_plain === PAUSE TestIsValidUploadKey/nar_plain === RUN TestIsValidUploadKey/listing === PAUSE TestIsValidUploadKey/listing === RUN TestIsValidUploadKey/build_log === PAUSE TestIsValidUploadKey/build_log === RUN TestIsValidUploadKey/build_log_home-manager_file === PAUSE TestIsValidUploadKey/build_log_home-manager_file === RUN TestIsValidUploadKey/build_log_plus_in_name === PAUSE TestIsValidUploadKey/build_log_plus_in_name === RUN TestIsValidUploadKey/build_log_question_mark === PAUSE TestIsValidUploadKey/build_log_question_mark === RUN TestIsValidUploadKey/build_log_equals === PAUSE TestIsValidUploadKey/build_log_equals === RUN TestIsValidUploadKey/realisation === PAUSE TestIsValidUploadKey/realisation === RUN TestIsValidUploadKey/realisation_plus_in_output === PAUSE TestIsValidUploadKey/realisation_plus_in_output === RUN TestIsValidUploadKey/nix-cache-info === PAUSE TestIsValidUploadKey/nix-cache-info === RUN TestIsValidUploadKey/index.html === PAUSE TestIsValidUploadKey/index.html === RUN TestIsValidUploadKey/narinfo_key,_nar_type === PAUSE TestIsValidUploadKey/narinfo_key,_nar_type === RUN TestIsValidUploadKey/nar_key,_narinfo_type === PAUSE TestIsValidUploadKey/nar_key,_narinfo_type === RUN TestIsValidUploadKey/listing_key,_narinfo_type === PAUSE TestIsValidUploadKey/listing_key,_narinfo_type === RUN TestIsValidUploadKey/traversal === PAUSE TestIsValidUploadKey/traversal === RUN TestIsValidUploadKey/traversal_nar === PAUSE TestIsValidUploadKey/traversal_nar === RUN TestIsValidUploadKey/absolute === PAUSE TestIsValidUploadKey/absolute === RUN TestIsValidUploadKey/empty_key === PAUSE TestIsValidUploadKey/empty_key === RUN TestIsValidUploadKey/unknown_type === PAUSE TestIsValidUploadKey/unknown_type === CONT TestService_Rustfstest === PAUSE TestPendingClosureFailureTracksEveryUpload/refuse_aborts=true 2026/10/09 09:57:38 INFO Shutdown signal received, draining in-flight requests timeout=10s === CONT TestTombstonedObjectOfferedWithoutWaiting 2026/10/09 09:57:38 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000 --- PASS: TestSkippedUploadsHandler (0.04s) === CONT TestParseSize --- PASS: TestParseSize (0.00s) === CONT TestPresignedUploadRegisteredBeforeCommit --- PASS: TestGracefulShutdownDrainsInflight (0.07s) === CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded === RUN TestUploadHandlersRejectOversizedBody/create_pending_closure === PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure === RUN TestUploadHandlersRejectOversizedBody/complete_multipart === PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart === RUN TestUploadHandlersRejectOversizedBody/request_more_parts === PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts === CONT TestCompleteMultipartUpload_ErrorButObjectExists 2026/10/09 09:57:38 INFO Received uploads request method=POST path=/api/pending_closures --- PASS: TestPendingClosureFailureAbortsItsUploads (0.74s) === CONT TestGCSweepSkipsPendingObjects --- PASS: TestReadRedirectKeepsNarinfoProxied (1.68s) === CONT TestCompletedNarNotReofferedAcrossClosures 2026/10/09 09:57:40 INFO Received uploads request method=POST path=/api/pending_closures 2026/10/09 09:57:40 INFO Received uploads request method=POST path=/api/pending_closures 2026/10/09 09:57:40 INFO Received uploads request method=POST path=/api/pending_closures === NAME TestOrphanedObjectsGC orphaned_objects_gc_test.go:287: GC Test Summary: orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3) orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y) orphaned_objects_gc_test.go:292: - Total deleted: 10 objects --- PASS: TestOrphanedObjectsGC (1.96s) === CONT TestRedundantMultipartUpload 2026/10/09 09:57:40 WARN readiness check failed error="closed pool" --- PASS: TestService_readinessHandler (2.46s) === CONT TestPush_SkippedKeySurvivesGCBeforeCommit 2026/10/09 09:57:41 INFO Received uploads request method=POST path=/api/pending_closures 2026/10/09 09:57:41 INFO Aborted multipart uploads count=0 kept=0 2026/10/09 09:57:41 WARN Force mode enabled - objects will be deleted immediately without grace period 2026/10/09 09:57:41 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied." 2026/10/09 09:57:41 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied." --- PASS: TestFailedS3DeleteKeepsTombstone (3.03s) === CONT TestService_NativeMTLS 2026/10/09 09:57:41 INFO Received uploads request method=POST path=/api/pending_closures 2026/10/09 09:57:41 INFO Received uploads request method=POST path=/api/pending_closures 2026/10/09 09:57:41 INFO Received cleanup request method=DELETE path=/api/pending_closures 2026/10/09 09:57:41 INFO Received cleanup request method=DELETE path=/api/pending_closures 2026/10/09 09:57:41 INFO Aborted multipart uploads count=0 kept=0 2026/10/09 09:57:41 INFO Received uploads request method=POST path=/api/pending_closures 2026/10/09 09:57:41 INFO Received cleanup request method=DELETE path=/api/pending_closures 2026/10/09 09:57:41 INFO Aborted multipart uploads count=1 kept=0 2026/10/09 09:57:41 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete 2026/10/09 09:57:41 INFO Received complete multipart upload request method=POST path=/api/multipart/complete 2026-10-09 09:57:41.838 UTC [65645] ERROR: Closure does not exist: id=1 2026-10-09 09:57:41.838 UTC [65645] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE 2026-10-09 09:57:41.838 UTC [65645] STATEMENT: -- name: CommitPendingClosure :one SELECT commit_pending_closure($1::bigint)::bigint === CONT TestPush_CompleteWaitsForCleanupOfThePush --- PASS: TestService_cleanupPendingClosuresHandler (3.50s) 2026/10/09 09:57:41 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=MTE5MjdlYzItNjE3OS00ZDA5LTljZjMtZGFiOThmMGQ2ZDQ0LjE5MDUyNzM0LWM0MTgtNDBkMC04OWY3LTA4Mjc4MGQ1MTVmOHgxNzkxNTM5ODYwMzc1MjkxMDAw parts=10 2026/10/09 09:57:41 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete 2026/10/09 09:57:41 INFO Completed upload id=1 objects=2 duration=16.561334ms 2026/10/09 09:57:41 INFO Received get closure request method=GET path=/api/closures/00000000000000000000000000000000 2026/10/09 09:57:41 INFO Received uploads request method=POST path=/api/pending_closures 2026/10/09 09:57:41 INFO Starting cleanup of old closures method=DELETE path=/api/closures 2026/10/09 09:57:41 INFO Aborted multipart uploads count=0 kept=0 --- PASS: TestService_Rustfstest (3.61s) 2026/10/09 09:57:41 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=0 === CONT TestPush_RootsAreLockedInByteOrder 2026/10/09 09:57:42 INFO Vacuumed table table=pending_closures 2026/10/09 09:57:42 INFO Vacuumed table table=pending_objects 2026/10/09 09:57:42 INFO Vacuumed table table=multipart_uploads 2026/10/09 09:57:42 INFO Vacuumed table table=closures 2026/10/09 09:57:42 INFO Vacuumed table table=objects 2026/10/09 09:57:42 INFO Received get closure request method=GET path=/api/closures/00000000000000000000000000000000 --- PASS: TestService_createPendingClosureHandler (3.76s) === CONT TestPushDedupSurvivesConcurrentGC 2026/10/09 09:57:42 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch" --- PASS: TestService_AuthMiddleware (3.84s) === CONT TestPush_CompleteCommitsEveryRoot --- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (3.93s) === CONT TestMetricsCommit --- PASS: TestObjectStatsTrigger (4.12s) === CONT TestPush_RejectsBadRequests 2026/10/09 09:57:42 INFO Received uploads request method=POST path=/api/pending_closures --- PASS: TestTombstonedObjectOfferedWithoutWaiting (4.37s) === CONT TestMultipartCleanup 2026/10/09 09:57:42 INFO Received uploads request method=POST path=/api/pending_closures 2026/10/09 09:57:43 INFO Received complete multipart upload request method=POST path=/api/multipart/complete 2026/10/09 09:57:43 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst === CONT TestReadRedirectUsesPublicS3URL --- PASS: TestCompleteMultipartUnregistered (4.89s) --- PASS: TestReconnectLeavesObjectsUnlocked (5.24s) === CONT TestPush_SignsNarinfosOfItsPendingObjects 2026/10/09 09:57:44 INFO Received uploads request method=POST path=/api/pending_closures --- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (5.82s) === CONT TestDeduplicatedObjectsRecordedAsPending 2026/10/09 09:57:44 INFO Received complete multipart upload request method=POST path=/api/multipart/complete 2026/10/09 09:57:44 INFO Received uploads request method=POST path=/api/pending_closures 2026/10/09 09:57:44 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=MTE5MjdlYzItNjE3OS00ZDA5LTljZjMtZGFiOThmMGQ2ZDQ0LjJlMTk3Y2M1LWQwMGItNDBhZS1hMmE3LTcwZmVkY2QzMzQyN3gxNzkxNTM5ODYyOTIzNzkzMDAw parts=10 2026/10/09 09:57:44 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete 2026/10/09 09:57:44 INFO Completed upload id=1 objects=2 duration=6.389083ms 2026/10/09 09:57:44 INFO Received uploads request method=POST path=/api/pending_closures 2026/10/09 09:57:44 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst 2026/10/09 09:57:44 INFO Received uploads request method=POST path=/api/pending_closures 2026/10/09 09:57:44 INFO Received uploads request method=POST path=/api/pending_closures 2026/10/09 09:57:44 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo 2026/10/09 09:57:44 WARN Found objects in DB but missing from S3, will re-upload count=1 --- PASS: TestPresignedUploadRegisteredBeforeCommit (6.06s) === CONT TestGCBugBareHashReferences 2026/10/09 09:57:44 INFO Received complete upload request method=POST path=/api/pending_closures/3/complete 2026/10/09 09:57:44 INFO Completed upload id=3 objects=2 duration=618.541µs --- PASS: TestService_verifyS3Integrity (6.18s) === CONT TestNARDeduplicationMetadataUploadBug 2026/10/09 09:57:44 INFO Received uploads request method=POST path=/api/pending_closures === CONT TestLeadEndsOnShutdown --- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (6.59s) === CONT TestGenerateLandingPage --- PASS: TestService_healthCheckHandler (6.60s) --- PASS: TestGenerateLandingPage (0.01s) === CONT TestCacheConfigHandlerMaxNarSize --- PASS: TestCacheConfigHandlerMaxNarSize (0.00s) === CONT TestGCAdvisoryLockBlocksConcurrentRun 2026/10/09 09:57:45 INFO Aborted multipart uploads count=0 kept=0 2026/10/09 09:57:45 WARN Force mode enabled - objects will be deleted immediately without grace period 2026/10/09 09:57:45 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=3 objects-deleted-after-grace-period=3 objects-failed-to-delete=0 2026/10/09 09:57:45 INFO Vacuumed table table=pending_closures 2026/10/09 09:57:45 INFO Vacuumed table table=pending_objects 2026/10/09 09:57:45 INFO Vacuumed table table=multipart_uploads 2026/10/09 09:57:45 INFO Vacuumed table table=closures 2026/10/09 09:57:45 INFO Received uploads request method=POST path=/api/pending_closures 2026/10/09 09:57:45 INFO Vacuumed table table=objects --- PASS: TestGCSweepDeliversEachKeyOnce (7.38s) === CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle --- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (7.48s) === CONT TestClientPushesUseOnePush 2026/10/09 09:57:45 INFO Received uploads request method=POST path=/api/pending_closures 2026/10/09 09:57:46 INFO Received uploads request method=POST path=/api/pending_closures 2026/10/09 09:57:46 INFO Received complete multipart upload request method=POST path=/api/multipart/complete 2026/10/09 09:57:46 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MTE5MjdlYzItNjE3OS00ZDA5LTljZjMtZGFiOThmMGQ2ZDQ0Ljc0YWM3NjcxLWYyZTItNDc1ZC05YWMxLTRhYjEyMjA5YjgzM3gxNzkxNTM5ODY2MDYwNjc5MDAw 2026/10/09 09:57:46 INFO Aborted multipart uploads count=0 kept=0 2026/10/09 09:57:46 WARN Force mode enabled - objects will be deleted immediately without grace period 2026/10/09 09:57:46 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=0 2026/10/09 09:57:46 WARN Failed to abort multipart upload key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MTE5MjdlYzItNjE3OS00ZDA5LTljZjMtZGFiOThmMGQ2ZDQ0Ljc0YWM3NjcxLWYyZTItNDc1ZC05YWMxLTRhYjEyMjA5YjgzM3gxNzkxNTM5ODY2MDYwNjc5MDAw error="Delete \"http://localhost:60965/bucket27/nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst?uploadId=MTE5MjdlYzItNjE3OS00ZDA5LTljZjMtZGFiOThmMGQ2ZDQ0Ljc0YWM3NjcxLWYyZTItNDc1ZC05YWMxLTRhYjEyMjA5YjgzM3gxNzkxNTM5ODY2MDYwNjc5MDAw\": injected: abort refused" 2026/10/09 09:57:46 INFO Received complete multipart upload request method=POST path=/api/multipart/complete 2026/10/09 09:57:46 INFO Vacuumed table table=pending_closures 2026/10/09 09:57:46 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MTE5MjdlYzItNjE3OS00ZDA5LTljZjMtZGFiOThmMGQ2ZDQ0Ljc0YWM3NjcxLWYyZTItNDc1ZC05YWMxLTRhYjEyMjA5YjgzM3gxNzkxNTM5ODY2MDYwNjc5MDAw 2026/10/09 09:57:46 INFO Vacuumed table table=pending_objects 2026/10/09 09:57:46 INFO Vacuumed table table=multipart_uploads 2026/10/09 09:57:46 INFO Vacuumed table table=closures 2026/10/09 09:57:46 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MTE5MjdlYzItNjE3OS00ZDA5LTljZjMtZGFiOThmMGQ2ZDQ0Ljc0YWM3NjcxLWYyZTItNDc1ZC05YWMxLTRhYjEyMjA5YjgzM3gxNzkxNTM5ODY2MDYwNjc5MDAw parts=1 2026/10/09 09:57:46 INFO Vacuumed table table=objects --- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (8.16s) === CONT TestService_ReadAuthMiddleware 2026/10/09 09:57:46 INFO Received uploads request method=POST path=/api/pending_closures --- PASS: TestGCSweepSkipsPendingObjects (7.69s) === CONT TestCacheConfigHandler === RUN TestCacheConfigHandler/full_config,_no_issuer === PAUSE TestCacheConfigHandler/full_config,_no_issuer === RUN TestCacheConfigHandler/no_cache_url_configured === PAUSE TestCacheConfigHandler/no_cache_url_configured === RUN TestCacheConfigHandler/no_signing_keys === PAUSE TestCacheConfigHandler/no_signing_keys === RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator === PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator === CONT TestClientWithDependencies 2026/10/09 09:57:46 INFO Received uploads request method=POST path=/api/pending_closures 2026/10/09 09:57:47 INFO Received uploads request method=POST path=/api/pending_closures 2026/10/09 09:57:47 INFO Received push request method=POST path=/api/pushes 2026/10/09 09:57:47 INFO Aborted multipart uploads count=1 kept=0 2026/10/09 09:57:47 INFO Received cleanup request method=DELETE path=/api/pending_closures 2026/10/09 09:57:47 INFO Aborted multipart uploads count=1 kept=0 --- PASS: TestPendingCleanupUsesOneCutoff (9.40s) === CONT TestService_RequireScope_OIDC 2026/10/09 09:57:47 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:61409/oidc 2026/10/09 09:57:47 WARN mTLS auth: subject not in bound subjects subject="CN=reader" 2026/10/09 09:57:47 WARN mTLS auth: subject not in bound subjects subject="CN=reader" --- PASS: TestService_NativeMTLS (6.65s) === CONT TestService_AuthMiddleware_OIDC 2026/10/09 09:57:48 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:61413/oidc 2026/10/09 09:57:48 INFO Received push request method=POST path=/api/pushes 2026/10/09 09:57:48 INFO Received push request method=POST path=/api/pushes 2026/10/09 09:57:49 INFO Received complete multipart upload request method=POST path=/api/multipart/complete 2026/10/09 09:57:49 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=MTE5MjdlYzItNjE3OS00ZDA5LTljZjMtZGFiOThmMGQ2ZDQ0LmM3ZGFmNWU3LTMyNjgtNDkyZS05OGQzLTg0NTgyZGVmNmRmY3gxNzkxNTM5ODY2NzkxODcwMDAw parts=12 2026/10/09 09:57:49 INFO Received uploads request method=POST path=/api/pending_closures 2026/10/09 09:57:49 INFO Received uploads request method=POST path=/api/pending_closures 2026/10/09 09:57:49 INFO Received uploads request method=POST path=/api/pending_closures 2026/10/09 09:57:49 INFO Received complete multipart upload request method=POST path=/api/multipart/complete 2026/10/09 09:57:49 INFO Aborted multipart uploads count=0 kept=0 2026/10/09 09:57:49 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=0 2026/10/09 09:57:49 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=MTE5MjdlYzItNjE3OS00ZDA5LTljZjMtZGFiOThmMGQ2ZDQ0LjBhMzRkMzQxLTdlNTgtNDcxMC1hMjc1LTM4ZDBjNGY4MmEzYXgxNzkxNTM5ODY3MTI1NDk1MDAw parts=12 2026/10/09 09:57:49 INFO Received uploads request method=POST path=/api/pending_closures 2026/10/09 09:57:49 INFO Received push request method=POST path=/api/pushes 2026/10/09 09:57:49 INFO Vacuumed table table=pending_closures 2026/10/09 09:57:49 INFO Received complete multipart upload request method=POST path=/api/multipart/complete --- PASS: TestCompletedNarNotReofferedAcrossClosures (9.90s) === CONT TestService_ReadScope_PublicByDefault 2026/10/09 09:57:49 INFO Vacuumed table table=pending_objects 2026/10/09 09:57:49 INFO Vacuumed table table=multipart_uploads 2026/10/09 09:57:50 INFO Vacuumed table table=closures 2026/10/09 09:57:50 INFO Vacuumed table table=objects 2026/10/09 09:57:50 INFO Completed multipart upload object_key=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa00000000000000000000.nar.zst upload_id=MTE5MjdlYzItNjE3OS00ZDA5LTljZjMtZGFiOThmMGQ2ZDQ0Ljk1OTdlNGI1LTg5YTEtNDFhMi1hODlkLTlmMzk1NDBlNTIxM3gxNzkxNTM5ODY3NTEzOTMwMDAw parts=10 2026/10/09 09:57:50 INFO Aborted multipart uploads count=0 kept=0 2026/10/09 09:57:50 WARN Force mode enabled - objects will be deleted immediately without grace period 2026/10/09 09:57:50 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=0 2026/10/09 09:57:50 INFO Vacuumed table table=pending_closures 2026/10/09 09:57:50 INFO Vacuumed table table=pending_objects 2026/10/09 09:57:50 INFO Vacuumed table table=multipart_uploads 2026/10/09 09:57:50 INFO Vacuumed table table=closures 2026/10/09 09:57:50 INFO Vacuumed table table=objects --- PASS: TestPushDedupSurvivesConcurrentGC (8.12s) === CONT TestService_AuthMiddleware_MTLSBoundSubjects 2026/10/09 09:57:50 INFO Received push request method=POST path=/api/pushes === RUN TestPush_RejectsBadRequests/root_not_in_objects === PAUSE TestPush_RejectsBadRequests/root_not_in_objects === RUN TestPush_RejectsBadRequests/no_roots === PAUSE TestPush_RejectsBadRequests/no_roots === RUN TestPush_RejectsBadRequests/no_objects === PAUSE TestPush_RejectsBadRequests/no_objects === RUN TestPush_RejectsBadRequests/bad_root === PAUSE TestPush_RejectsBadRequests/bad_root === CONT TestReadProxyNarinfo 2026/10/09 09:57:50 INFO Received complete multipart upload request method=POST path=/api/multipart/complete 2026/10/09 09:57:50 INFO Completed multipart upload object_key=nar/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb00000000000000000000.nar.zst upload_id=MTE5MjdlYzItNjE3OS00ZDA5LTljZjMtZGFiOThmMGQ2ZDQ0LmVjY2UyZDhiLThkMGEtNDRkYS1hNzc1LWI3YmI4ZjJhOWYyNXgxNzkxNTM5ODY4NTAxODIwMDAw parts=10 2026/10/09 09:57:51 INFO Received uploads request method=POST path=/api/pending_closures 2026-10-09 09:57:51.305 UTC [65892] ERROR: Push does not exist: id=1 2026-10-09 09:57:51.305 UTC [65892] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE 2026-10-09 09:57:51.305 UTC [65892] STATEMENT: SELECT commit_push($1) --- PASS: TestPush_CompleteWaitsForCleanupOfThePush (9.46s) === CONT TestReadProxyRangeRequest 2026/10/09 09:57:51 INFO Received complete multipart upload request method=POST path=/api/multipart/complete 2026/10/09 09:57:51 INFO Received cleanup request method=DELETE path=/api/pending_closures 2026/10/09 09:57:51 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket39/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code="" 2026/10/09 09:57:51 INFO Aborted multipart uploads count=0 kept=1 2026/10/09 09:57:51 INFO Completed multipart upload object_key=nar/ffffffffffffffffffffffffffffffff00000000000000000000.nar.zst upload_id=MTE5MjdlYzItNjE3OS00ZDA5LTljZjMtZGFiOThmMGQ2ZDQ0LjBjNzg3Y2IzLWQ4YzctNGUzZi1hZDZlLThjMzViOTMxNDUzYngxNzkxNTM5ODY4OTQ4MTkzMDAw parts=10 2026/10/09 09:57:51 INFO Received cleanup request method=DELETE path=/api/pending_closures 2026/10/09 09:57:51 INFO Aborted multipart uploads count=1 kept=0 --- PASS: TestMultipartCleanup (8.94s) === CONT TestReadRedirectNar --- PASS: TestReadRedirectUsesPublicS3URL (8.63s) === CONT TestReadProxyRootRedirectsToIndexHTML 2026/10/09 09:57:52 INFO Received push request method=POST path=/api/pushes 2026/10/09 09:57:52 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign 2026/10/09 09:57:52 INFO Signed narinfos id=1 count=1 2026/10/09 09:57:52 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign 2026/10/09 09:57:52 INFO Received complete multipart upload request method=POST path=/api/multipart/complete 2026/10/09 09:57:52 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign 2026/10/09 09:57:52 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil" 2026/10/09 09:57:52 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign 2026/10/09 09:57:52 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed" 2026/10/09 09:57:52 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign 2026/10/09 09:57:52 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=1 2026/10/09 09:57:52 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign 2026/10/09 09:57:52 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo 2026/10/09 09:57:52 INFO Received complete multipart upload request method=POST path=/api/multipart/complete --- PASS: TestPush_SignsNarinfosOfItsPendingObjects (8.93s) === CONT TestReadProxyConditionalGet 2026/10/09 09:57:52 INFO Completed multipart upload object_key=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa00000000000000000000.nar.zst upload_id=MTE5MjdlYzItNjE3OS00ZDA5LTljZjMtZGFiOThmMGQ2ZDQ0LjJmYmYwMWVmLTJjMzEtNDdlZi1iZmRmLTE4Yjk3Zjg4ZDc3YngxNzkxNTM5ODY5OTQ3NjIwMDAw parts=10 2026/10/09 09:57:52 INFO Received complete multipart upload request method=POST path=/api/multipart/complete 2026/10/09 09:57:52 INFO Completed multipart upload object_key=nar/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb00000000000000000000.nar.zst upload_id=MTE5MjdlYzItNjE3OS00ZDA5LTljZjMtZGFiOThmMGQ2ZDQ0LmU2ZTcxNTY2LWRiNzYtNDEwOC1hYzY3LThiN2JmYjdhZjRmMXgxNzkxNTM5ODY3NTEzNTM2MDAw parts=10 2026/10/09 09:57:52 INFO Received complete push request method=POST path=/api/pushes/1/complete 2026/10/09 09:57:52 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=MTE5MjdlYzItNjE3OS00ZDA5LTljZjMtZGFiOThmMGQ2ZDQ0LjNiOTc0MTI4LThlZmMtNDU5My1iYTk0LWZiNWQxYzhhMDUxNngxNzkxNTM5ODY5NzAwNDE4MDAw error="Get \"http://127.0.0.1:1/bucket29/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" 2026/10/09 09:57:52 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=MTE5MjdlYzItNjE3OS00ZDA5LTljZjMtZGFiOThmMGQ2ZDQ0LjYxMDllNGU4LWU1YzYtNDRlOS04MDYwLWNhN2VjMzkzNzlhMXgxNzkxNTM5ODY5NjAyNzc0MDAw parts=12 2026/10/09 09:57:52 INFO Received cleanup request method=DELETE path=/api/pending_closures 2026/10/09 09:57:52 INFO Completed push id=1 objects=4 duration=21.732ms 2026/10/09 09:57:52 INFO Received push request method=POST path=/api/pushes 2026/10/09 09:57:52 INFO Received uploads request method=POST path=/api/pending_closures 2026/10/09 09:57:52 INFO Aborted multipart uploads count=1 kept=0 --- PASS: TestRedundantMultipartUpload (12.53s) === CONT TestReadProxyOutlastsServerWriteTimeout --- PASS: TestDeduplicatedObjectsRecordedAsPending (8.64s) === CONT TestClientIntegration 2026/10/09 09:57:52 INFO Received complete multipart upload request method=POST path=/api/multipart/complete 2026/10/09 09:57:52 INFO Aborted multipart uploads count=0 kept=0 2026/10/09 09:57:52 WARN Force mode enabled - objects will be deleted immediately without grace period 2026/10/09 09:57:53 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=2 objects-deleted-after-grace-period=2 objects-failed-to-delete=0 2026/10/09 09:57:53 INFO Completed multipart upload object_key=nar/cccccccccccccccccccccccccccccccc00000000000000000000.nar.zst upload_id=MTE5MjdlYzItNjE3OS00ZDA5LTljZjMtZGFiOThmMGQ2ZDQ0LmIxODRmNDRkLWE4NDYtNGMwYi1iZDRiLWEyMzc4NjdlZjY2ZngxNzkxNTM5ODcwNDAyMDY5MDAw parts=10 2026/10/09 09:57:53 INFO Vacuumed table table=pending_closures 2026/10/09 09:57:53 INFO Vacuumed table table=pending_objects 2026/10/09 09:57:53 INFO Vacuumed table table=multipart_uploads 2026/10/09 09:57:53 INFO Vacuumed table table=closures 2026/10/09 09:57:53 INFO Vacuumed table table=objects --- PASS: TestGCBugBareHashReferences (9.08s) === CONT TestReadProxyDisabled 2026/10/09 09:57:54 INFO Received complete multipart upload request method=POST path=/api/multipart/complete 2026/10/09 09:57:54 INFO Completed multipart upload object_key=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa00000000000000000000.nar.zst upload_id=MTE5MjdlYzItNjE3OS00ZDA5LTljZjMtZGFiOThmMGQ2ZDQ0LjZhZDFmZDM0LWMyYTYtNDU0OS04OGM1LWNlMGIwNTNhMjM5ZngxNzkxNTM5ODY4OTQ3NTA4MDAw parts=10 2026/10/09 09:57:54 INFO lead: acquired remote=192.0.2.1:1234 === NAME TestNARDeduplicationMetadataUploadBug metadata_upload_test.go:48: First store path: /private/var/tb/5/scratch/00f1341bdd59a71e/build/TestNARDeduplicationMetadataUploadBug3739036377/001/store/jzdkkpjzngbd8hh4z6ilczfxk39vaky0-file1.txt 2026/10/09 09:57:54 INFO Received push request method=POST path=/api/pushes 2026/10/09 09:57:54 INFO Uploading 1 paths to 127.0.0.1 (0 already cached) 2026/10/09 09:57:54 INFO Uploading jzdkkpjzngbd8hh4z6ilczfxk39vaky0-file1.txt (160B) 2026/10/09 09:57:54 WARN Failed to register uploaded object key=jzdkkpjzngbd8hh4z6ilczfxk39vaky0.ls error="server returned 404: 404 page not found\n" 2026/10/09 09:57:54 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n" 2026/10/09 09:57:54 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign 2026/10/09 09:57:54 INFO Signed narinfos id=1 count=1 2026/10/09 09:57:54 INFO Uploading 1 narinfos 2026/10/09 09:57:54 INFO Received complete push request method=POST path=/api/pushes/1/complete 2026/10/09 09:57:54 WARN Failed to register uploaded object key=jzdkkpjzngbd8hh4z6ilczfxk39vaky0.narinfo error="server returned 404: 404 page not found\n" 2026/10/09 09:57:54 INFO Received complete multipart upload request method=POST path=/api/multipart/complete 2026/10/09 09:57:54 INFO Completed push id=1 objects=3 duration=96.959333ms 2026/10/09 09:57:54 INFO Upload complete. (369ms) metadata_upload_test.go:54: Retrieved narinfo from S3: StorePath: /private/var/tb/5/scratch/00f1341bdd59a71e/build/TestNARDeduplicationMetadataUploadBug3739036377/001/store/jzdkkpjzngbd8hh4z6ilczfxk39vaky0-file1.txt URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst 2026/10/09 09:57:54 INFO Completed multipart upload object_key=nar/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb00000000000000000000.nar.zst upload_id=MTE5MjdlYzItNjE3OS00ZDA5LTljZjMtZGFiOThmMGQ2ZDQ0LmZiNjRiN2Q3LWJkMTAtNGViYi1iM2FkLWE3MjA4MjJjNWI5MXgxNzkxNTM5ODY5OTQ4MTIxMDAw parts=10 Compression: zstd 2026/10/09 09:57:54 INFO Received complete push request method=POST path=/api/pushes/1/complete NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf NarSize: 160 References: CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes) metadata_upload_test.go:55: Decompressed .ls content (64 bytes): {"version":1,"root":{"type":"regular","size":44,"narOffset":96}} 2026/10/09 09:57:54 INFO Completed push id=1 objects=4 duration=28.881167ms 2026/10/09 09:57:54 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete 2026/10/09 09:57:54 INFO Completed upload id=2 objects=2 duration=945.917µs --- PASS: TestMetricsCommit (12.56s) === CONT TestCreatePendingClosureRejectsOversizedNAR 2026/10/09 09:57:54 INFO Received uploads request method=POST path=/api/pending_closures --- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.01s) === CONT TestClientSharedPathCommittedMidPush === NAME TestNARDeduplicationMetadataUploadBug metadata_upload_test.go:64: Second store path (same content): /private/var/tb/5/scratch/00f1341bdd59a71e/build/TestNARDeduplicationMetadataUploadBug3739036377/001/store/n0kh57iv90pnvqsnx7idg3b3c4327ips-file2.txt 2026/10/09 09:57:55 INFO Received uploads request method=POST path=/api/pending_closures 2026/10/09 09:57:55 INFO Received push request method=POST path=/api/pushes 2026/10/09 09:57:55 INFO Uploading 0 paths to 127.0.0.1 (1 already cached) 2026/10/09 09:57:55 WARN Failed to register uploaded object key=n0kh57iv90pnvqsnx7idg3b3c4327ips.ls error="server returned 404: 404 page not found\n" 2026/10/09 09:57:55 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign 2026/10/09 09:57:55 INFO Signed narinfos id=2 count=1 2026/10/09 09:57:55 INFO Uploading 1 narinfos 2026/10/09 09:57:55 INFO Received complete push request method=POST path=/api/pushes/2/complete 2026/10/09 09:57:55 WARN Failed to register uploaded object key=n0kh57iv90pnvqsnx7idg3b3c4327ips.narinfo error="server returned 404: 404 page not found\n" 2026/10/09 09:57:55 INFO Completed push id=2 objects=3 duration=833.5µs 2026/10/09 09:57:55 INFO Upload complete. (204ms) metadata_upload_test.go:76: Retrieved narinfo from S3: StorePath: /private/var/tb/5/scratch/00f1341bdd59a71e/build/TestNARDeduplicationMetadataUploadBug3739036377/001/store/n0kh57iv90pnvqsnx7idg3b3c4327ips-file2.txt URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst Compression: zstd NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf NarSize: 160 References: CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes) metadata_upload_test.go:77: Decompressed .ls content (49 bytes): {"version":1,"root":{"type":"regular","size":44}} 2026/10/09 09:57:55 INFO lead: released remote=192.0.2.1:1234 --- PASS: TestLeadEndsOnShutdown (10.40s) 2026/10/09 09:57:55 INFO Received complete multipart upload request method=POST path=/api/multipart/complete === CONT TestReadProxyHead 2026/10/09 09:57:55 INFO Completed multipart upload object_key=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa00000000000000000000.nar.zst upload_id=MTE5MjdlYzItNjE3OS00ZDA5LTljZjMtZGFiOThmMGQ2ZDQ0LmUwZWY4NjRiLTAyMGYtNDdhNC04NzY5LTVmOGExZjYyMWMxMXgxNzkxNTM5ODcwNDAyNDM1MDAw parts=10 --- PASS: TestNARDeduplicationMetadataUploadBug (10.98s) === CONT TestReadProxyInvalidPath 2026/10/09 09:57:55 INFO Received complete multipart upload request method=POST path=/api/multipart/complete 2026/10/09 09:57:55 INFO Completed multipart upload object_key=nar/cccccccccccccccccccccccccccccccc00000000000000000000.nar.zst upload_id=MTE5MjdlYzItNjE3OS00ZDA5LTljZjMtZGFiOThmMGQ2ZDQ0LjdlZmZmMzBiLWI2MjgtNGY5ZC1hZjI0LTFlODY4MTMyOTFlOXgxNzkxNTM5ODcyNzk0MjAxMDAw parts=10 2026/10/09 09:57:55 INFO Received complete push request method=POST path=/api/pushes/2/complete 2026/10/09 09:57:55 INFO Received complete multipart upload request method=POST path=/api/multipart/complete 2026/10/09 09:57:55 INFO Completed push id=2 objects=4 duration=91.808417ms --- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (15.00s) === CONT TestPinProtectsFromGC --- PASS: TestService_ReadAuthMiddleware (9.34s) === CONT TestReadProxyContentNegotiation 2026/10/09 09:57:56 INFO Received complete multipart upload request method=POST path=/api/multipart/complete 2026/10/09 09:57:56 INFO Completed multipart upload object_key=nar/dddddddddddddddddddddddddddddddd00000000000000000000.nar.zst upload_id=MTE5MjdlYzItNjE3OS00ZDA5LTljZjMtZGFiOThmMGQ2ZDQ0LmVmOTViZWM0LTIzNzctNGFjYy1hMDdiLTE5MDk4ZmJiNDU2NXgxNzkxNTM5ODY4OTQ4MDg4MDAw parts=10 2026/10/09 09:57:56 INFO Received push request method=POST path=/api/pushes 2026/10/09 09:57:56 INFO Uploading 2 paths to 127.0.0.1 (1 already cached) 2026/10/09 09:57:56 INFO Uploading xbqmkgdshgk5k0xjml4m1g56lpmw4j8d-b (256B) 2026/10/09 09:57:56 INFO Uploading 53ks2w0ysjv96vmx4rpi1al5gp75yamj-shared-dep (136B) 2026/10/09 09:57:56 WARN Failed to register uploaded object key=vhryrfv773fksmia7iy65577br00fhfm.ls error="server returned 404: 404 page not found\n" 2026/10/09 09:57:56 WARN Failed to register uploaded object key=nar/0hqznlhggmdhn8q1378c9hj7qi8v35l5g0yayi0xbvp8zc6wn5xl.nar.zst error="server returned 404: 404 page not found\n" 2026/10/09 09:57:56 WARN Failed to register uploaded object key=xbqmkgdshgk5k0xjml4m1g56lpmw4j8d.ls error="server returned 404: 404 page not found\n" 2026/10/09 09:57:56 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n" 2026/10/09 09:57:56 WARN Failed to register uploaded object key=53ks2w0ysjv96vmx4rpi1al5gp75yamj.ls error="server returned 404: 404 page not found\n" 2026/10/09 09:57:56 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign 2026/10/09 09:57:56 INFO Signed narinfos id=1 count=3 2026/10/09 09:57:56 INFO Uploading 3 narinfos 2026/10/09 09:57:56 WARN Failed to register uploaded object key=vhryrfv773fksmia7iy65577br00fhfm.narinfo error="server returned 404: 404 page not found\n" 2026/10/09 09:57:56 WARN Failed to register uploaded object key=53ks2w0ysjv96vmx4rpi1al5gp75yamj.narinfo error="server returned 404: 404 page not found\n" 2026/10/09 09:57:56 INFO Received complete push request method=POST path=/api/pushes/1/complete 2026/10/09 09:57:56 WARN Failed to register uploaded object key=xbqmkgdshgk5k0xjml4m1g56lpmw4j8d.narinfo error="server returned 404: 404 page not found\n" 2026/10/09 09:57:56 INFO Completed push id=1 objects=8 duration=133.390625ms 2026/10/09 09:57:56 INFO Upload complete. (383ms) === NAME TestClientPushesUseOnePush client_pushes_test.go:97: Retrieved narinfo from S3: StorePath: /private/var/tb/5/scratch/00f1341bdd59a71e/build/TestClientPushesUseOnePush2694814707/001/store/53ks2w0ysjv96vmx4rpi1al5gp75yamj-shared-dep URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst Compression: zstd NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82 NarSize: 136 References: CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n client_pushes_test.go:97: Retrieved narinfo from S3: StorePath: /private/var/tb/5/scratch/00f1341bdd59a71e/build/TestClientPushesUseOnePush2694814707/001/store/vhryrfv773fksmia7iy65577br00fhfm-a URL: nar/0hqznlhggmdhn8q1378c9hj7qi8v35l5g0yayi0xbvp8zc6wn5xl.nar.zst Compression: zstd NarHash: sha256:0hqznlhggmdhn8q1378c9hj7qi8v35l5g0yayi0xbvp8zc6wn5xl NarSize: 256 References: /private/var/tb/5/scratch/00f1341bdd59a71e/build/TestClientPushesUseOnePush2694814707/001/store/53ks2w0ysjv96vmx4rpi1al5gp75yamj-shared-dep CA: text:sha256:1yxkka82di6scx68lcanr9wjmx53w6lw2ssjns8j14j9hyjmw4qa client_pushes_test.go:97: Retrieved narinfo from S3: StorePath: /private/var/tb/5/scratch/00f1341bdd59a71e/build/TestClientPushesUseOnePush2694814707/001/store/xbqmkgdshgk5k0xjml4m1g56lpmw4j8d-b URL: nar/0hqznlhggmdhn8q1378c9hj7qi8v35l5g0yayi0xbvp8zc6wn5xl.nar.zst Compression: zstd NarHash: sha256:0hqznlhggmdhn8q1378c9hj7qi8v35l5g0yayi0xbvp8zc6wn5xl NarSize: 256 References: /private/var/tb/5/scratch/00f1341bdd59a71e/build/TestClientPushesUseOnePush2694814707/001/store/53ks2w0ysjv96vmx4rpi1al5gp75yamj-shared-dep CA: text:sha256:1yxkka82di6scx68lcanr9wjmx53w6lw2ssjns8j14j9hyjmw4qa --- PASS: TestClientPushesUseOnePush (10.99s) === CONT TestReadProxyNarinfoAlreadyDecompressed === RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token === PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token === RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected === PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected === RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected === PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected === RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured === PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured === CONT TestGCMetrics === NAME TestClientWithDependencies client_integration_test.go:735: Built derivation: /private/var/tb/5/scratch/00f1341bdd59a71e/build/TestClientWithDependencies4176572669/001/store/irf7apapgkmyry2z90ashdg40g27dhib-test-script client_integration_test.go:737: Found 1 dependencies (including self) === RUN TestService_RequireScope_OIDC/builder_may_write === PAUSE TestService_RequireScope_OIDC/builder_may_write === RUN TestService_RequireScope_OIDC/builder_may_not_admin === PAUSE TestService_RequireScope_OIDC/builder_may_not_admin === RUN TestService_RequireScope_OIDC/ops_may_admin === PAUSE TestService_RequireScope_OIDC/ops_may_admin === RUN TestService_RequireScope_OIDC/ops_may_not_write === PAUSE TestService_RequireScope_OIDC/ops_may_not_write === RUN TestService_RequireScope_OIDC/reader_may_not_write === PAUSE TestService_RequireScope_OIDC/reader_may_not_write === RUN TestService_RequireScope_OIDC/static_token_may_admin === PAUSE TestService_RequireScope_OIDC/static_token_may_admin === RUN TestService_RequireScope_OIDC/static_token_may_write === PAUSE TestService_RequireScope_OIDC/static_token_may_write === RUN TestService_RequireScope_OIDC/reader_may_read === PAUSE TestService_RequireScope_OIDC/reader_may_read === RUN TestService_RequireScope_OIDC/writer_implies_read === PAUSE TestService_RequireScope_OIDC/writer_implies_read === RUN TestService_RequireScope_OIDC/anonymous_may_not_read === PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read === RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc === PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc === RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc === PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc === RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read === PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read === RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read === PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read === CONT TestClientMultipleUploads 2026/10/09 09:57:57 INFO Received push request method=POST path=/api/pushes 2026/10/09 09:57:57 INFO Received complete multipart upload request method=POST path=/api/multipart/complete 2026/10/09 09:57:57 INFO Uploading 1 paths to 127.0.0.1 (0 already cached) 2026/10/09 09:57:57 INFO Uploading irf7apapgkmyry2z90ashdg40g27dhib-test-script (136B) 2026/10/09 09:57:57 INFO Completed multipart upload object_key=nar/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb00000000000000000000.nar.zst upload_id=MTE5MjdlYzItNjE3OS00ZDA5LTljZjMtZGFiOThmMGQ2ZDQ0LjIzNmU2NTc4LWVkN2UtNGY1Ni1hN2ZjLTU5ZTY0MzQ1NDUxM3gxNzkxNTM5ODcwNDAyNDc5MDAw parts=10 2026/10/09 09:57:57 INFO Received complete push request method=POST path=/api/pushes/1/complete 2026/10/09 09:57:57 INFO Completed push id=1 objects=6 duration=22.64675ms 2026/10/09 09:57:57 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n" 2026/10/09 09:57:57 WARN Failed to register uploaded object key=irf7apapgkmyry2z90ashdg40g27dhib.ls error="server returned 404: 404 page not found\n" 2026/10/09 09:57:57 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign 2026/10/09 09:57:57 WARN Failed to register uploaded object key=log/ny8v8b6b3fzlawc3gswr7kmdjs5svfxl-test-script.drv error="server returned 404: 404 page not found\n" 2026/10/09 09:57:57 INFO Signed narinfos id=1 count=1 2026/10/09 09:57:57 INFO Uploading 1 narinfos === CONT TestClientFallsBackToClosures --- PASS: TestPush_CompleteCommitsEveryRoot (15.24s) 2026/10/09 09:57:57 INFO Received complete push request method=POST path=/api/pushes/1/complete 2026/10/09 09:57:57 WARN Failed to register uploaded object key=irf7apapgkmyry2z90ashdg40g27dhib.narinfo error="server returned 404: 404 page not found\n" 2026/10/09 09:57:57 INFO Completed push id=1 objects=4 duration=52.092166ms 2026/10/09 09:57:57 INFO Upload complete. (291ms) 2026/10/09 09:57:57 INFO Aborted multipart uploads count=0 kept=0 2026/10/09 09:57:57 WARN Force mode enabled - objects will be deleted immediately without grace period 2026/10/09 09:57:57 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=0 2026/10/09 09:57:57 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other" 2026/10/09 09:57:57 WARN mTLS auth: bound subjects configured but subject DN unavailable 2026/10/09 09:57:57 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted" 2026/10/09 09:57:57 INFO Vacuumed table table=pending_closures --- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (7.40s) === CONT TestReadProxy404 2026/10/09 09:57:57 INFO Vacuumed table table=pending_objects 2026/10/09 09:57:57 INFO Vacuumed table table=multipart_uploads 2026/10/09 09:57:57 INFO Vacuumed table table=closures 2026/10/09 09:57:57 INFO Vacuumed table table=objects === NAME TestClientWithDependencies client_integration_test.go:753: Skipping nix copy test - isolated store (/private/var/tb/5/scratch/00f1341bdd59a71e/build/TestClientWithDependencies4176572669/001/store) requires matching store prefix --- PASS: TestClientWithDependencies (11.04s) === CONT TestGCTaskStore_Fail --- PASS: TestGCTaskStore_Fail (0.00s) === CONT TestClientErrorHandling === RUN TestClientErrorHandling/InvalidStorePath === PAUSE TestClientErrorHandling/InvalidStorePath === RUN TestClientErrorHandling/InvalidAuthToken === PAUSE TestClientErrorHandling/InvalidAuthToken === RUN TestClientErrorHandling/ServerNotAvailable === PAUSE TestClientErrorHandling/ServerNotAvailable === CONT TestLeadElectsOneAndHandsOver 2026/10/09 09:57:57 INFO Received complete multipart upload request method=POST path=/api/multipart/complete 2026/10/09 09:57:58 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggggg00000000000000000000.nar.zst upload_id=MTE5MjdlYzItNjE3OS00ZDA5LTljZjMtZGFiOThmMGQ2ZDQ0LmUzM2I5NjkwLTY0MTMtNDY3My04YTRmLTY0ZWI1OGVhNTExYngxNzkxNTM5ODY4OTQ4MTY2MDAw parts=10 --- PASS: TestService_ReadScope_PublicByDefault (8.10s) === CONT TestPush_RepeatedRootCommitsOnce === NAME TestObjectStatsLargeCommit object_stats_test.go:101: committing 60000 objects took 8.843845166s 2026/10/09 09:57:58 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error= --- PASS: TestReadProxyNarinfo (7.87s) --- FAIL: TestObjectStatsLargeCommit (20.31s) === CONT TestProxyWriteTimeout === CONT TestServerTLSConfig === RUN TestServerTLSConfig/no_client_CA === RUN TestProxyWriteTimeout/narinfo === PAUSE TestProxyWriteTimeout/narinfo === RUN TestProxyWriteTimeout/1_GiB_nar === PAUSE TestServerTLSConfig/no_client_CA === PAUSE TestProxyWriteTimeout/1_GiB_nar === RUN TestProxyWriteTimeout/10_GiB_nar === PAUSE TestProxyWriteTimeout/10_GiB_nar === RUN TestServerTLSConfig/missing_CA_file === RUN TestProxyWriteTimeout/unknown_size === PAUSE TestServerTLSConfig/missing_CA_file === PAUSE TestProxyWriteTimeout/unknown_size === RUN TestServerTLSConfig/not_a_PEM_file === CONT TestConnectWaitsForAPeerMigration === PAUSE TestServerTLSConfig/not_a_PEM_file === CONT TestConnectSerialisesConcurrentMigrations --- PASS: TestReadProxyRangeRequest (7.46s) === CONT TestMetricsInventory --- PASS: TestReadRedirectNar (7.53s) === CONT TestPush_OverlappingRootsStoreOneRowPerKey 2026/10/09 09:57:59 WARN Rate limiter enabled after throttle name=s3-test rate=5 2026/10/09 09:57:59 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate." === NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=10 throttle_test.go:215: Rate limiter: enabled=true, rate=5.00 --- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (13.77s) === CONT TestPresentNotReportedWhileGCDeletesClosure === RUN TestPresentNotReportedWhileGCDeletesClosure/stale === PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale === RUN TestPresentNotReportedWhileGCDeletesClosure/fresh === PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh === CONT TestReadProxyNarStreaming --- PASS: TestReadProxyRootRedirectsToIndexHTML (7.76s) === CONT TestParseSingleRange === RUN TestParseSingleRange/none === PAUSE TestParseSingleRange/none === RUN TestParseSingleRange/unknown_unit === PAUSE TestParseSingleRange/unknown_unit === RUN TestParseSingleRange/multi-range_ignored === PAUSE TestParseSingleRange/multi-range_ignored === RUN TestParseSingleRange/malformed_no_dash === PAUSE TestParseSingleRange/malformed_no_dash === RUN TestParseSingleRange/malformed_both_empty === PAUSE TestParseSingleRange/malformed_both_empty === RUN TestParseSingleRange/malformed_end_before_start === PAUSE TestParseSingleRange/malformed_end_before_start === RUN TestParseSingleRange/closed === PAUSE TestParseSingleRange/closed === RUN TestParseSingleRange/open-ended === PAUSE TestParseSingleRange/open-ended === RUN TestParseSingleRange/end_clamped_to_size === PAUSE TestParseSingleRange/end_clamped_to_size === RUN TestParseSingleRange/suffix === PAUSE TestParseSingleRange/suffix === RUN TestParseSingleRange/suffix_exceeds_size === PAUSE TestParseSingleRange/suffix_exceeds_size === RUN TestParseSingleRange/single_byte === PAUSE TestParseSingleRange/single_byte === RUN TestParseSingleRange/start_past_EOF === PAUSE TestParseSingleRange/start_past_EOF === RUN TestParseSingleRange/start_far_past_EOF === PAUSE TestParseSingleRange/start_far_past_EOF === CONT TestIsValidCachePath === RUN TestIsValidCachePath/narinfo === PAUSE TestIsValidCachePath/narinfo === RUN TestIsValidCachePath/narinfo_all_nix_base32_chars === PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars === RUN TestIsValidCachePath/nar_zst === PAUSE TestIsValidCachePath/nar_zst === RUN TestIsValidCachePath/nar_xz === PAUSE TestIsValidCachePath/nar_xz === RUN TestIsValidCachePath/nar_bz2 === PAUSE TestIsValidCachePath/nar_bz2 === RUN TestIsValidCachePath/nar_uncompressed === PAUSE TestIsValidCachePath/nar_uncompressed === RUN TestIsValidCachePath/ls === PAUSE TestIsValidCachePath/ls === RUN TestIsValidCachePath/log === PAUSE TestIsValidCachePath/log === RUN TestIsValidCachePath/realisation === PAUSE TestIsValidCachePath/realisation === RUN TestIsValidCachePath/nix-cache-info === PAUSE TestIsValidCachePath/nix-cache-info === RUN TestIsValidCachePath/index.html === PAUSE TestIsValidCachePath/index.html === RUN TestIsValidCachePath/traversal_parent === PAUSE TestIsValidCachePath/traversal_parent === RUN TestIsValidCachePath/traversal_in_middle === PAUSE TestIsValidCachePath/traversal_in_middle === RUN TestIsValidCachePath/invalid_char_e === PAUSE TestIsValidCachePath/invalid_char_e === RUN TestIsValidCachePath/invalid_char_u === PAUSE TestIsValidCachePath/invalid_char_u === RUN TestIsValidCachePath/random_path === PAUSE TestIsValidCachePath/random_path === RUN TestIsValidCachePath/empty === PAUSE TestIsValidCachePath/empty === RUN TestIsValidCachePath/leading_slash === PAUSE TestIsValidCachePath/leading_slash === RUN TestIsValidCachePath/wrong_extension === PAUSE TestIsValidCachePath/wrong_extension === RUN TestIsValidCachePath/short_hash === PAUSE TestIsValidCachePath/short_hash === CONT TestResolveDBConnectionString 2026/10/09 09:57:59 INFO Received complete multipart upload request method=POST path=/api/multipart/complete === RUN TestResolveDBConnectionString/flag_wins === PAUSE TestResolveDBConnectionString/flag_wins === RUN TestResolveDBConnectionString/file_when_flag_empty === PAUSE TestResolveDBConnectionString/file_when_flag_empty === RUN TestResolveDBConnectionString/missing_file_is_an_error === PAUSE TestResolveDBConnectionString/missing_file_is_an_error === RUN TestResolveDBConnectionString/PGHOST_allows_empty === PAUSE TestResolveDBConnectionString/PGHOST_allows_empty === RUN TestResolveDBConnectionString/nothing_configured === PAUSE TestResolveDBConnectionString/nothing_configured === CONT TestDeleteClosuresRacingPins 2026/10/09 09:57:59 INFO Completed multipart upload object_key=nar/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb00000000000000000000.nar.zst upload_id=MTE5MjdlYzItNjE3OS00ZDA5LTljZjMtZGFiOThmMGQ2ZDQ0LjBjYTI4NWE2LTNkMDUtNGQ4OS04M2FhLTUxZTNmM2FiNGM0ZHgxNzkxNTM5ODY4OTQ4MTkxMDAw parts=10 --- PASS: TestReadProxyConditionalGet (7.49s) === CONT TestClientCADerivations === NAME TestClientIntegration client_integration_test.go:334: Created store path: /private/var/tb/5/scratch/00f1341bdd59a71e/build/TestClientIntegration2081764932/002/store/45b2lzrw4y0rlm7xrxp9n421q405wqbi-test-file.txt 2026/10/09 09:58:00 INFO Received push request method=POST path=/api/pushes 2026/10/09 09:58:00 INFO Uploading 1 paths to 127.0.0.1 (0 already cached) 2026/10/09 09:58:00 INFO Uploading 45b2lzrw4y0rlm7xrxp9n421q405wqbi-test-file.txt (152B) 2026/10/09 09:58:00 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n" 2026/10/09 09:58:00 WARN Failed to register uploaded object key=45b2lzrw4y0rlm7xrxp9n421q405wqbi.ls error="server returned 404: 404 page not found\n" 2026/10/09 09:58:00 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign 2026/10/09 09:58:00 INFO Signed narinfos id=1 count=1 2026/10/09 09:58:01 INFO Uploading 1 narinfos 2026/10/09 09:58:01 INFO Received complete push request method=POST path=/api/pushes/1/complete 2026/10/09 09:58:01 WARN Failed to register uploaded object key=45b2lzrw4y0rlm7xrxp9n421q405wqbi.narinfo error="server returned 404: 404 page not found\n" 2026/10/09 09:58:01 INFO Completed push id=1 objects=3 duration=27.312958ms 2026/10/09 09:58:01 INFO Upload complete. (302ms) 2026/10/09 09:58:01 INFO All 1 paths already cached client_integration_test.go:360: Retrieved narinfo from S3: StorePath: /private/var/tb/5/scratch/00f1341bdd59a71e/build/TestClientIntegration2081764932/002/store/45b2lzrw4y0rlm7xrxp9n421q405wqbi-test-file.txt URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst Compression: zstd NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1 NarSize: 152 References: CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1 client_integration_test.go:361: Retrieved .ls file from S3 (compressed size: 77 bytes) client_integration_test.go:361: Decompressed .ls content (64 bytes): {"version":1,"root":{"type":"regular","size":39,"narOffset":96}} --- PASS: TestReadProxyDisabled (7.68s) === CONT TestPresentRefreshesOnlyStaleClosures 2026/10/09 09:58:01 INFO Received push request method=POST path=/api/pushes 2026/10/09 09:58:01 INFO Object in database but missing from S3 key=45b2lzrw4y0rlm7xrxp9n421q405wqbi.ls 2026/10/09 09:58:01 WARN Found objects in DB but missing from S3, will re-upload count=1 2026/10/09 09:58:01 INFO Uploading 0 paths to 127.0.0.1 (1 already cached) 2026/10/09 09:58:01 INFO Received complete push request method=POST path=/api/pushes/2/complete 2026/10/09 09:58:01 WARN Failed to register uploaded object key=45b2lzrw4y0rlm7xrxp9n421q405wqbi.ls error="server returned 404: 404 page not found\n" 2026/10/09 09:58:01 INFO Completed push id=2 objects=3 duration=1.358917ms 2026/10/09 09:58:01 INFO Upload complete. (143ms) === NAME TestClientIntegration client_integration_test.go:389: Retrieved .ls file from S3 (compressed size: 62 bytes) client_integration_test.go:389: Decompressed .ls content (49 bytes): {"version":1,"root":{"type":"regular","size":39}} 2026/10/09 09:58:01 INFO Received push request method=POST path=/api/pushes 2026/10/09 09:58:01 INFO Uploading 0 paths to 127.0.0.1 (1 already cached) 2026/10/09 09:58:01 INFO Received complete push request method=POST path=/api/pushes/3/complete 2026/10/09 09:58:01 WARN Failed to register uploaded object key=45b2lzrw4y0rlm7xrxp9n421q405wqbi.ls error="server returned 404: 404 page not found\n" 2026/10/09 09:58:01 INFO Completed push id=3 objects=3 duration=1.488167ms 2026/10/09 09:58:01 INFO Upload complete. (127ms) 2026/10/09 09:58:01 ERROR failed to check GC advisory lock error="query pg_locks: failed to connect to `user=_tribuchetbld5 database=niks3`: /nonexistent/.s.PGSQL.5432 (/nonexistent): dial error: dial unix /nonexistent/.s.PGSQL.5432: connect: no such file or directory" client_integration_test.go:405: Retrieved .ls file from S3 (compressed size: 62 bytes) client_integration_test.go:405: Decompressed .ls content (49 bytes): {"version":1,"root":{"type":"regular","size":39}} --- PASS: TestGCAdvisoryLockBlocksConcurrentRun (16.76s) === CONT TestPresentReportsOnlyClosureRoots 2026/10/09 09:58:01 INFO Received complete multipart upload request method=POST path=/api/multipart/complete 2026/10/09 09:58:01 INFO Completed multipart upload object_key=nar/cccccccccccccccccccccccccccccccc00000000000000000000.nar.zst upload_id=MTE5MjdlYzItNjE3OS00ZDA5LTljZjMtZGFiOThmMGQ2ZDQ0LmQwYjg4ZDkzLTIwZjItNGYxNC04ZGJlLWZhZWE1OTZhMGI4NHgxNzkxNTM5ODY4OTQ4MDg2MDAw parts=10 2026-10-09 09:58:01.922 UTC [65876] ERROR: could not obtain lock on row in relation "closures" 2026-10-09 09:58:01.922 UTC [65876] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT 2026/10/09 09:58:01 INFO Received push request method=POST path=/api/pushes 2026-10-09 09:58:01.935 UTC [65876] ERROR: could not obtain lock on row in relation "closures" 2026-10-09 09:58:01.935 UTC [65876] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT 2026/10/09 09:58:01 INFO Uploading 1 paths to 127.0.0.1 (0 already cached) 2026/10/09 09:58:01 INFO Uploading wb7jix9zmfkmv1g4vdn34rxj89kz2pnh-lost-commit.txt (152B) 2026-10-09 09:58:01.943 UTC [65876] ERROR: could not obtain lock on row in relation "closures" 2026-10-09 09:58:01.943 UTC [65876] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT 2026-10-09 09:58:01.948 UTC [65876] ERROR: could not obtain lock on row in relation "closures" 2026-10-09 09:58:01.948 UTC [65876] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT 2026-10-09 09:58:01.948 UTC [65876] ERROR: could not obtain lock on row in relation "closures" 2026-10-09 09:58:01.948 UTC [65876] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT 2026/10/09 09:58:01 WARN Failed to register uploaded object key=wb7jix9zmfkmv1g4vdn34rxj89kz2pnh.ls error="server returned 404: 404 page not found\n" 2026/10/09 09:58:01 WARN Failed to register uploaded object key=nar/04d5klw9iix884nk82y7nlkps8afh2bg119y7zkvcf1pc1x2y2jl.nar.zst error="server returned 404: 404 page not found\n" 2026/10/09 09:58:01 INFO Received sign narinfos request method=POST path=/api/pushes/4/sign 2026/10/09 09:58:01 INFO Signed narinfos id=4 count=1 2026/10/09 09:58:01 INFO Uploading 1 narinfos --- PASS: TestPush_RootsAreLockedInByteOrder (20.00s) === CONT TestGCEndsOnShutdown === RUN TestGCEndsOnShutdown/before_the_run === PAUSE TestGCEndsOnShutdown/before_the_run === RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete === PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete 2026/10/09 09:58:02 INFO Received complete push request method=POST path=/api/pushes/4/complete === RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark 2026/10/09 09:58:02 WARN Failed to register uploaded object key=wb7jix9zmfkmv1g4vdn34rxj89kz2pnh.narinfo error="server returned 404: 404 page not found\n" 2026/10/09 09:58:02 INFO Completed push id=4 objects=3 duration=877.708µs === PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark === CONT TestGCTaskStore_GetReturnsLatest 2026/10/09 09:58:02 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:61533/api/pushes/4/complete\": EOF" url=http://127.0.0.1:61533/api/pushes/4/complete --- PASS: TestGCTaskStore_GetReturnsLatest (0.00s) === CONT TestGCTaskStore_DeduplicateSameParams --- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s) === CONT TestGCTaskStore_ConflictDifferentParams --- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s) === CONT TestGCTaskStore_StartNew --- PASS: TestGCTaskStore_StartNew (0.00s) === CONT TestGCTaskStore_GetEmpty --- PASS: TestGCTaskStore_GetEmpty (0.00s) === CONT TestCacheStatsHandler --- PASS: TestReadProxyHead (6.76s) 2026/10/09 09:58:02 INFO Received complete push request method=POST path=/api/pushes/4/complete === CONT TestGCTaskStore_PhaseUpdates --- PASS: TestGCTaskStore_PhaseUpdates (0.00s) 2026-10-09 09:58:02.128 UTC [65985] ERROR: Push does not exist: id=4 2026-10-09 09:58:02.128 UTC [65985] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE 2026-10-09 09:58:02.128 UTC [65985] STATEMENT: -- name: CommitPush :one SELECT commit_push($1::bigint)::bigint === CONT TestPushWaitsForSweepHoldingRow 2026/10/09 09:58:02 WARN Push not found id=4 2026/10/09 09:58:02 INFO Upload complete. (278ms) === NAME TestClientIntegration client_integration_test.go:435: Retrieved narinfo from S3: StorePath: /private/var/tb/5/scratch/00f1341bdd59a71e/build/TestClientIntegration2081764932/002/store/wb7jix9zmfkmv1g4vdn34rxj89kz2pnh-lost-commit.txt URL: nar/04d5klw9iix884nk82y7nlkps8afh2bg119y7zkvcf1pc1x2y2jl.nar.zst Compression: zstd NarHash: sha256:04d5klw9iix884nk82y7nlkps8afh2bg119y7zkvcf1pc1x2y2jl NarSize: 152 References: CA: fixed:r:sha256:04d5klw9iix884nk82y7nlkps8afh2bg119y7zkvcf1pc1x2y2jl client_integration_test.go:438: Testing garbage collection... 2026/10/09 09:58:02 INFO Starting cleanup of old closures method=DELETE path=/api/closures 2026/10/09 09:58:02 INFO Garbage collection started 2026/10/09 09:58:02 INFO Aborted multipart uploads count=0 kept=0 2026/10/09 09:58:02 WARN Force mode enabled - objects will be deleted immediately without grace period 2026-10-09 09:58:02.294 UTC [66074] ERROR: duplicate key value violates unique constraint "pg_type_typname_nsp_index" 2026-10-09 09:58:02.294 UTC [66074] DETAIL: Key (typname, typnamespace)=(goose_db_version, 2200) already exists. 2026-10-09 09:58:02.294 UTC [66074] STATEMENT: CREATE TABLE goose_db_version ( id integer PRIMARY KEY GENERATED BY DEFAULT AS IDENTITY, version_id bigint NOT NULL, is_applied boolean NOT NULL, tstamp timestamp NOT NULL DEFAULT now() ) 2026/10/09 09:58:02 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=2 objects-marked-for-deletion=6 objects-deleted-after-grace-period=6 objects-failed-to-delete=0 2026/10/09 09:58:02 INFO Vacuumed table table=pending_closures 2026/10/09 09:58:02 INFO Vacuumed table table=pending_objects 2026/10/09 09:58:02 INFO Vacuumed table table=multipart_uploads 2026/10/09 09:58:02 INFO Vacuumed table table=closures 2026/10/09 09:58:02 INFO Vacuumed table table=objects === CONT TestService_AuthMiddleware_MTLSProxyHeader --- PASS: TestReadProxyInvalidPath (7.23s) 2026/10/09 09:58:02 INFO Received push request method=POST path=/api/pushes 2026/10/09 09:58:02 INFO Uploading 2 paths to 127.0.0.1 (0 already cached) 2026/10/09 09:58:02 INFO Uploading 5c5zi1r1y48bkjhw0c1ach12f9qvyfmp-shared-dep (136B) 2026/10/09 09:58:02 INFO Uploading fk1l0pgwnb8ykv2938ysa7h0fzilx3if-top (264B) 2026/10/09 09:58:02 WARN Failed to register uploaded object key=5c5zi1r1y48bkjhw0c1ach12f9qvyfmp.ls error="server returned 404: 404 page not found\n" 2026/10/09 09:58:02 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n" 2026/10/09 09:58:02 WARN Failed to register uploaded object key=fk1l0pgwnb8ykv2938ysa7h0fzilx3if.ls error="server returned 404: 404 page not found\n" 2026/10/09 09:58:02 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign 2026/10/09 09:58:02 WARN Failed to register uploaded object key=nar/0iqpvzd3p6vfgig0mgnq65fg56hwhkl3fdfm8bygqh3q33wwj93v.nar.zst error="server returned 404: 404 page not found\n" 2026/10/09 09:58:02 INFO Signed narinfos id=1 count=2 2026/10/09 09:58:02 INFO Uploading 2 narinfos 2026/10/09 09:58:03 WARN Failed to register uploaded object key=fk1l0pgwnb8ykv2938ysa7h0fzilx3if.narinfo error="server returned 404: 404 page not found\n" 2026/10/09 09:58:03 INFO Received complete push request method=POST path=/api/pushes/1/complete 2026/10/09 09:58:03 WARN Failed to register uploaded object key=5c5zi1r1y48bkjhw0c1ach12f9qvyfmp.narinfo error="server returned 404: 404 page not found\n" 2026/10/09 09:58:03 INFO Completed push id=1 objects=6 duration=32.0545ms 2026/10/09 09:58:03 INFO Upload complete. (237ms) === NAME TestClientSharedPathCommittedMidPush client_integration_test.go:816: Retrieved narinfo from S3: StorePath: /private/var/tb/5/scratch/00f1341bdd59a71e/build/TestClientSharedPathCommittedMidPush2098838153/001/store/5c5zi1r1y48bkjhw0c1ach12f9qvyfmp-shared-dep URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst Compression: zstd NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82 NarSize: 136 References: CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n client_integration_test.go:816: Retrieved narinfo from S3: StorePath: /private/var/tb/5/scratch/00f1341bdd59a71e/build/TestClientSharedPathCommittedMidPush2098838153/001/store/fk1l0pgwnb8ykv2938ysa7h0fzilx3if-top URL: nar/0iqpvzd3p6vfgig0mgnq65fg56hwhkl3fdfm8bygqh3q33wwj93v.nar.zst Compression: zstd NarHash: sha256:0iqpvzd3p6vfgig0mgnq65fg56hwhkl3fdfm8bygqh3q33wwj93v NarSize: 264 References: /private/var/tb/5/scratch/00f1341bdd59a71e/build/TestClientSharedPathCommittedMidPush2098838153/001/store/5c5zi1r1y48bkjhw0c1ach12f9qvyfmp-shared-dep CA: text:sha256:0i3n7vcsklsr2aifnh5wr7yxqhwjg2k0b9crkj27p9bhqwn5rmin --- PASS: TestClientSharedPathCommittedMidPush (8.24s) === CONT TestCommitRacingPendingCleanupKeepsObjects --- PASS: TestReadProxyContentNegotiation (7.14s) === CONT TestSweepRechecksPendingAfterLocking --- PASS: TestConnectSerialisesConcurrentMigrations (4.64s) === CONT TestDeletePinKeepsRowWhenS3Fails 2026/10/09 09:58:03 INFO Aborted multipart uploads count=0 kept=0 2026/10/09 09:58:03 WARN Force mode enabled - objects will be deleted immediately without grace period 2026/10/09 09:58:03 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=0 2026/10/09 09:58:03 INFO Vacuumed table table=pending_closures 2026/10/09 09:58:03 INFO Vacuumed table table=pending_objects 2026/10/09 09:58:03 INFO Vacuumed table table=multipart_uploads === NAME TestPinProtectsFromGC client_integration_test.go:867: Pinned store path: /private/var/tb/5/scratch/00f1341bdd59a71e/build/TestPinProtectsFromGC2645952582/001/store/pdrcsd9i9ijjm0kq6kqvagrql0r3gshc-pinned-file.txt client_integration_test.go:868: Unpinned store path: /private/var/tb/5/scratch/00f1341bdd59a71e/build/TestPinProtectsFromGC2645952582/001/store/jn0wsxl6dny48rhxhky5arzyhg47sysv-unpinned-file.txt 2026/10/09 09:58:03 INFO Vacuumed table table=closures 2026/10/09 09:58:03 INFO Vacuumed table table=objects --- PASS: TestGCMetrics (6.89s) === CONT TestCreatePinRejectsBadInput 2026/10/09 09:58:03 INFO Received push request method=POST path=/api/pushes 2026/10/09 09:58:03 INFO Uploading 1 paths to 127.0.0.1 (0 already cached) 2026/10/09 09:58:03 INFO Uploading pdrcsd9i9ijjm0kq6kqvagrql0r3gshc-pinned-file.txt (128B) 2026/10/09 09:58:03 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n" 2026/10/09 09:58:03 WARN Failed to register uploaded object key=pdrcsd9i9ijjm0kq6kqvagrql0r3gshc.ls error="server returned 404: 404 page not found\n" 2026/10/09 09:58:03 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign 2026/10/09 09:58:03 INFO Signed narinfos id=1 count=1 2026/10/09 09:58:03 INFO Uploading 1 narinfos === CONT TestConcurrentPinUpdatesAgree --- PASS: TestReadProxyNarinfoAlreadyDecompressed (7.11s) 2026/10/09 09:58:03 INFO Received complete push request method=POST path=/api/pushes/1/complete 2026/10/09 09:58:03 WARN Failed to register uploaded object key=pdrcsd9i9ijjm0kq6kqvagrql0r3gshc.narinfo error="server returned 404: 404 page not found\n" 2026/10/09 09:58:03 INFO Completed push id=1 objects=3 duration=23.210875ms 2026/10/09 09:58:03 INFO Upload complete. (187ms) 2026/10/09 09:58:04 INFO Received push request method=POST path=/api/pushes 2026/10/09 09:58:04 INFO Uploading 1 paths to 127.0.0.1 (0 already cached) 2026/10/09 09:58:04 INFO Uploading jn0wsxl6dny48rhxhky5arzyhg47sysv-unpinned-file.txt (128B) 2026/10/09 09:58:04 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n" 2026/10/09 09:58:04 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign 2026/10/09 09:58:04 WARN Failed to register uploaded object key=jn0wsxl6dny48rhxhky5arzyhg47sysv.ls error="server returned 404: 404 page not found\n" 2026/10/09 09:58:04 INFO Signed narinfos id=2 count=1 2026/10/09 09:58:04 INFO Uploading 1 narinfos 2026/10/09 09:58:04 INFO Received complete push request method=POST path=/api/pushes/2/complete 2026/10/09 09:58:04 WARN Failed to register uploaded object key=jn0wsxl6dny48rhxhky5arzyhg47sysv.narinfo error="server returned 404: 404 page not found\n" 2026/10/09 09:58:04 INFO Completed push id=2 objects=3 duration=958.083µs 2026/10/09 09:58:04 INFO Upload complete. (121ms) 2026/10/09 09:58:04 INFO Starting cleanup of old closures method=DELETE path=/api/closures 2026/10/09 09:58:04 INFO Garbage collection started 2026/10/09 09:58:04 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=2 objects_marked=6 objects_deleted=6 objects_failed=0 2026/10/09 09:58:04 INFO Aborted multipart uploads count=0 kept=0 === NAME TestClientIntegration client_integration_test.go:445: Objects in database after GC: client_integration_test.go:445: Successfully deleted all objects with GC --force 2026/10/09 09:58:04 WARN Force mode enabled - objects will be deleted immediately without grace period 2026/10/09 09:58:04 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=3 objects-failed-to-delete=0 --- PASS: TestClientIntegration (11.41s) === CONT TestOrphanedObjectsGCStressTest 2026/10/09 09:58:04 INFO Vacuumed table table=pending_closures 2026/10/09 09:58:04 INFO Vacuumed table table=pending_objects === NAME TestClientMultipleUploads client_integration_test.go:480: Created store path 0: /private/var/tb/5/scratch/00f1341bdd59a71e/build/TestClientMultipleUploads1516919282/001/store/izqdx8ksj5dggrf9w7d6zw1w8dk0cphg-test-file-0.txt 2026/10/09 09:58:04 INFO Vacuumed table table=multipart_uploads 2026/10/09 09:58:04 INFO Vacuumed table table=closures 2026/10/09 09:58:04 INFO Vacuumed table table=objects client_integration_test.go:480: Created store path 1: /private/var/tb/5/scratch/00f1341bdd59a71e/build/TestClientMultipleUploads1516919282/001/store/6a6kq2kbllxn8sqpgq9lf9dhkkr0wh59-test-file-1.txt client_integration_test.go:480: Created store path 2: /private/var/tb/5/scratch/00f1341bdd59a71e/build/TestClientMultipleUploads1516919282/001/store/rqkifjy739cgi0bca3yw8mbjslfc5vms-test-file-2.txt 2026/10/09 09:58:04 INFO Received push request method=POST path=/api/pushes 2026/10/09 09:58:04 INFO Uploading 3 paths to 127.0.0.1 (0 already cached) 2026/10/09 09:58:04 INFO Uploading rqkifjy739cgi0bca3yw8mbjslfc5vms-test-file-2.txt (160B) 2026/10/09 09:58:04 INFO Uploading 6a6kq2kbllxn8sqpgq9lf9dhkkr0wh59-test-file-1.txt (160B) 2026/10/09 09:58:04 INFO Uploading izqdx8ksj5dggrf9w7d6zw1w8dk0cphg-test-file-0.txt (160B) 2026/10/09 09:58:04 WARN Failed to register uploaded object key=6a6kq2kbllxn8sqpgq9lf9dhkkr0wh59.ls error="server returned 404: 404 page not found\n" 2026/10/09 09:58:04 WARN Failed to register uploaded object key=rqkifjy739cgi0bca3yw8mbjslfc5vms.ls error="server returned 404: 404 page not found\n" 2026/10/09 09:58:04 WARN Failed to register uploaded object key=izqdx8ksj5dggrf9w7d6zw1w8dk0cphg.ls error="server returned 404: 404 page not found\n" 2026/10/09 09:58:04 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n" 2026/10/09 09:58:04 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign 2026/10/09 09:58:04 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n" 2026/10/09 09:58:04 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n" 2026/10/09 09:58:04 INFO Signed narinfos id=1 count=3 2026/10/09 09:58:04 INFO Uploading 3 narinfos 2026/10/09 09:58:04 INFO Received complete push request method=POST path=/api/pushes/1/complete 2026/10/09 09:58:04 WARN Failed to register uploaded object key=rqkifjy739cgi0bca3yw8mbjslfc5vms.narinfo error="server returned 404: 404 page not found\n" 2026/10/09 09:58:04 WARN Failed to register uploaded object key=6a6kq2kbllxn8sqpgq9lf9dhkkr0wh59.narinfo error="server returned 404: 404 page not found\n" 2026/10/09 09:58:04 WARN Failed to register uploaded object key=izqdx8ksj5dggrf9w7d6zw1w8dk0cphg.narinfo error="server returned 404: 404 page not found\n" 2026/10/09 09:58:04 INFO Completed push id=1 objects=9 duration=14.505792ms 2026/10/09 09:58:04 INFO Upload complete. (187ms) client_integration_test.go:491: Uploaded 3 paths in 228.728375ms 2026/10/09 09:58:04 INFO Received uploads request method=POST path=/api/pending_closures --- PASS: TestClientMultipleUploads (7.72s) === CONT TestCreatePin_ReservedPins 2026/10/09 09:58:05 INFO Received uploads request method=POST path=/api/pending_closures 2026/10/09 09:58:05 INFO Uploading 2 paths to 127.0.0.1 (1 already cached) 2026/10/09 09:58:05 INFO Uploading xxzxrcmv6wadq97qdac2cd9dk468xa1m-a (256B) 2026/10/09 09:58:05 INFO Uploading m0sn449c9cypp5v62g8n3vdq4vaffrcf-shared-dep (136B) 2026/10/09 09:58:05 WARN Rate limiter enabled after throttle name=s3-test rate=5 2026/10/09 09:58:05 WARN S3 rate limit hit during proxy key=4hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo error="Please reduce your request rate." 2026/10/09 09:58:05 WARN Failed to register uploaded object key=3f3r9z4p2isbyqakgx82awx024gzkrcy.ls error="server returned 404: 404 page not found\n" 2026/10/09 09:58:05 WARN Failed to register uploaded object key=xxzxrcmv6wadq97qdac2cd9dk468xa1m.ls error="server returned 404: 404 page not found\n" 2026/10/09 09:58:05 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n" 2026/10/09 09:58:05 WARN Failed to register uploaded object key=nar/1chzg4pqjcm1s2nm5fgdkry9dkrym3gd4qxjzpi272n979qlvdk0.nar.zst error="server returned 404: 404 page not found\n" 2026/10/09 09:58:05 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign 2026/10/09 09:58:05 WARN Failed to register uploaded object key=m0sn449c9cypp5v62g8n3vdq4vaffrcf.ls error="server returned 404: 404 page not found\n" 2026/10/09 09:58:05 INFO Signed narinfos id=1 count=2 2026/10/09 09:58:05 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign 2026/10/09 09:58:05 INFO Signed narinfos id=2 count=2 2026/10/09 09:58:05 INFO Uploading 4 narinfos 2026/10/09 09:58:05 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:61638/oidc --- PASS: TestReadProxyOutlastsServerWriteTimeout (12.23s) === CONT TestSweepSkipsRowsLockedByPush 2026/10/09 09:58:05 WARN Failed to register uploaded object key=m0sn449c9cypp5v62g8n3vdq4vaffrcf.narinfo error="server returned 404: 404 page not found\n" 2026/10/09 09:58:05 WARN Failed to register uploaded object key=xxzxrcmv6wadq97qdac2cd9dk468xa1m.narinfo error="server returned 404: 404 page not found\n" 2026/10/09 09:58:05 WARN Failed to register uploaded object key=3f3r9z4p2isbyqakgx82awx024gzkrcy.narinfo error="server returned 404: 404 page not found\n" 2026/10/09 09:58:05 INFO lead: acquired remote=192.0.2.1:1234 2026/10/09 09:58:05 WARN Rate limiter backed off name=s3-test rate=5 2026/10/09 09:58:05 WARN S3 rate limit hit during proxy key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhh.nar.zst error="Please reduce your request rate." 2026/10/09 09:58:05 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete 2026/10/09 09:58:05 WARN Failed to register uploaded object key=m0sn449c9cypp5v62g8n3vdq4vaffrcf.narinfo error="server returned 404: 404 page not found\n" --- PASS: TestReadProxy404 (7.53s) === CONT TestGetExistingObjectsLocksRows 2026/10/09 09:58:05 INFO Completed upload id=1 objects=6 duration=33.109167ms 2026/10/09 09:58:05 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete 2026/10/09 09:58:05 INFO Completed upload id=2 objects=6 duration=679.959µs 2026/10/09 09:58:05 INFO Upload complete. (325ms) === NAME TestClientFallsBackToClosures client_pushes_test.go:112: Retrieved narinfo from S3: StorePath: /private/var/tb/5/scratch/00f1341bdd59a71e/build/TestClientFallsBackToClosures3382990515/001/store/m0sn449c9cypp5v62g8n3vdq4vaffrcf-shared-dep URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst Compression: zstd NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82 NarSize: 136 References: CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n client_pushes_test.go:112: Retrieved narinfo from S3: StorePath: /private/var/tb/5/scratch/00f1341bdd59a71e/build/TestClientFallsBackToClosures3382990515/001/store/xxzxrcmv6wadq97qdac2cd9dk468xa1m-a URL: nar/1chzg4pqjcm1s2nm5fgdkry9dkrym3gd4qxjzpi272n979qlvdk0.nar.zst Compression: zstd NarHash: sha256:1chzg4pqjcm1s2nm5fgdkry9dkrym3gd4qxjzpi272n979qlvdk0 NarSize: 256 References: /private/var/tb/5/scratch/00f1341bdd59a71e/build/TestClientFallsBackToClosures3382990515/001/store/m0sn449c9cypp5v62g8n3vdq4vaffrcf-shared-dep CA: text:sha256:10n9icachmk13jydkmabgzy7qd58vn5ll960zscj088g1pnbwrq3 client_pushes_test.go:112: Retrieved narinfo from S3: StorePath: /private/var/tb/5/scratch/00f1341bdd59a71e/build/TestClientFallsBackToClosures3382990515/001/store/3f3r9z4p2isbyqakgx82awx024gzkrcy-b URL: nar/1chzg4pqjcm1s2nm5fgdkry9dkrym3gd4qxjzpi272n979qlvdk0.nar.zst Compression: zstd NarHash: sha256:1chzg4pqjcm1s2nm5fgdkry9dkrym3gd4qxjzpi272n979qlvdk0 NarSize: 256 References: /private/var/tb/5/scratch/00f1341bdd59a71e/build/TestClientFallsBackToClosures3382990515/001/store/m0sn449c9cypp5v62g8n3vdq4vaffrcf-shared-dep CA: text:sha256:10n9icachmk13jydkmabgzy7qd58vn5ll960zscj088g1pnbwrq3 --- PASS: TestClientFallsBackToClosures (7.87s) === CONT TestRegisterCompletedObjectNeedsPendingRow 2026/10/09 09:58:05 INFO Received push request method=POST path=/api/pushes --- PASS: TestMetricsInventory (7.12s) === CONT TestLeadIncumbentAnnouncesAtOnce 2026/10/09 09:58:06 INFO Received push request method=POST path=/api/pushes 2026/10/09 09:58:06 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=0 2026/10/09 09:58:06 INFO Received create pin request method=POST path=/api/pins/myapp --- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (7.01s) === CONT TestForceGCDuringPushOffersSweptObject/after_presence_check 2026/10/09 09:58:06 INFO Created/updated pin name=myapp store_path=/private/var/tb/5/scratch/00f1341bdd59a71e/build/TestPinProtectsFromGC2645952582/001/store/pdrcsd9i9ijjm0kq6kqvagrql0r3gshc-pinned-file.txt narinfo_key=pdrcsd9i9ijjm0kq6kqvagrql0r3gshc.narinfo 2026/10/09 09:58:06 INFO Starting cleanup of old closures method=DELETE path=/api/closures 2026/10/09 09:58:06 INFO Garbage collection started 2026/10/09 09:58:06 INFO Aborted multipart uploads count=0 kept=0 2026/10/09 09:58:06 WARN Force mode enabled - objects will be deleted immediately without grace period 2026/10/09 09:58:06 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=0 2026/10/09 09:58:06 INFO Vacuumed table table=pending_closures 2026/10/09 09:58:06 INFO Vacuumed table table=pending_objects 2026/10/09 09:58:06 INFO Vacuumed table table=multipart_uploads 2026/10/09 09:58:06 INFO Vacuumed table table=closures 2026/10/09 09:58:06 INFO Vacuumed table table=objects 2026/10/09 09:58:06 INFO lead: released remote=192.0.2.1:1234 2026/10/09 09:58:06 INFO lead: acquired remote=192.0.2.1:1234 --- PASS: TestReadProxyNarStreaming (7.03s) === CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows 2026/10/09 09:58:07 INFO Received complete multipart upload request method=POST path=/api/multipart/complete 2026/10/09 09:58:07 INFO Completed multipart upload object_key=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa00000000000000000000.nar.zst upload_id=MTE5MjdlYzItNjE3OS00ZDA5LTljZjMtZGFiOThmMGQ2ZDQ0LmIzMzU4OTY3LWRkNjgtNGNmZS04OGJhLTc4OTE4ZjAyN2E5NXgxNzkxNTM5ODg1NTUzODIxMDAw parts=10 2026/10/09 09:58:07 INFO lead: released remote=192.0.2.1:1234 --- PASS: TestLeadElectsOneAndHandsOver (9.62s) === CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal 2026/10/09 09:58:07 INFO Received uploads request method=POST path=/ === CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key 2026/10/09 09:58:07 INFO Received complete multipart upload request method=POST path=/ === CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key 2026/10/09 09:58:07 INFO Received request for more parts method=POST path=/ === CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info 2026/10/09 09:58:07 INFO Received uploads request method=POST path=/ === CONT TestPendingClosureWriteTimeout/670k_objects === CONT TestPendingClosureWriteTimeout/empty --- PASS: TestUploadHandlersRejectInvalidKeys (0.01s) --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.01s) --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s) --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.01s) --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s) === CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline --- PASS: TestPresentRefreshesOnlyStaleClosures (6.37s) === CONT TestPendingClosureWriteTimeout/400_objects === CONT TestIsValidUploadKey/build_log_home-manager_file === CONT TestIsValidUploadKey/unknown_type === CONT TestPendingClosureFailureTracksEveryUpload/refuse_aborts=false === NAME TestClientCADerivations client_ca_test.go:136: Built CA derivation: /private/var/tb/5/scratch/00f1341bdd59a71e/build/TestClientCADerivations48090870/001/store/sbspf4zal7xybqarcb96sazpvn09dw1j-ca-test client_ca_test.go:139: Found 1 dependencies (including self) --- PASS: TestPresentReportsOnlyClosureRoots (6.25s) === CONT TestIsValidUploadKey/absolute === CONT TestIsValidUploadKey/traversal_nar === CONT TestIsValidUploadKey/traversal === CONT TestIsValidUploadKey/listing_key,_narinfo_type === CONT TestPendingClosureFailureTracksEveryUpload/refuse_aborts=true 2026/10/09 09:58:08 INFO Received push request method=POST path=/api/pushes 2026/10/09 09:58:08 INFO Uploading 1 paths to 127.0.0.1 (0 already cached) 2026/10/09 09:58:08 INFO Uploading sbspf4zal7xybqarcb96sazpvn09dw1j-ca-test (144B) --- PASS: TestConnectWaitsForAPeerMigration (9.46s) === CONT TestIsValidUploadKey/build_log_question_mark === CONT TestIsValidUploadKey/index.html === CONT TestIsValidUploadKey/build_log_plus_in_name === CONT TestIsValidUploadKey/nix-cache-info === CONT TestIsValidUploadKey/nar_key,_narinfo_type === CONT TestIsValidUploadKey/realisation_plus_in_output === CONT TestIsValidUploadKey/build_log === CONT TestIsValidUploadKey/narinfo_key,_nar_type === CONT TestIsValidUploadKey/build_log_equals === CONT TestIsValidUploadKey/listing === CONT TestIsValidUploadKey/empty_key === CONT TestIsValidUploadKey/narinfo === CONT TestIsValidUploadKey/nar_plain === CONT TestIsValidUploadKey/realisation === CONT TestIsValidUploadKey/nar_zst === CONT TestIsValidUploadKey/nar_xz === CONT TestUploadHandlersRejectOversizedBody/create_pending_closure --- PASS: TestIsValidUploadKey (0.02s) --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s) --- PASS: TestIsValidUploadKey/unknown_type (0.00s) --- PASS: TestIsValidUploadKey/absolute (0.00s) --- PASS: TestIsValidUploadKey/traversal_nar (0.00s) --- PASS: TestIsValidUploadKey/traversal (0.00s) --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s) --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s) --- PASS: TestIsValidUploadKey/index.html (0.00s) --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s) --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s) --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s) --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s) --- PASS: TestIsValidUploadKey/build_log (0.00s) --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s) --- PASS: TestIsValidUploadKey/build_log_equals (0.00s) --- PASS: TestIsValidUploadKey/listing (0.00s) --- PASS: TestIsValidUploadKey/empty_key (0.00s) --- PASS: TestIsValidUploadKey/narinfo (0.00s) --- PASS: TestIsValidUploadKey/nar_plain (0.00s) --- PASS: TestIsValidUploadKey/realisation (0.00s) --- PASS: TestIsValidUploadKey/nar_zst (0.00s) --- PASS: TestIsValidUploadKey/nar_xz (0.00s) 2026/10/09 09:58:08 INFO Received uploads request method=POST path=/ 2026/10/09 09:58:08 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n" 2026/10/09 09:58:08 WARN Failed to register uploaded object key=sbspf4zal7xybqarcb96sazpvn09dw1j.ls error="server returned 404: 404 page not found\n" 2026/10/09 09:58:08 WARN Failed to register uploaded object key=log/bbk7vwwnbls3hamrmv5i6i7fpd2b0h8y-ca-test.drv error="server returned 404: 404 page not found\n" 2026/10/09 09:58:08 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign 2026/10/09 09:58:08 INFO Signed narinfos id=1 count=1 2026/10/09 09:58:08 INFO Uploading 1 narinfos 2026/10/09 09:58:08 INFO Received complete push request method=POST path=/api/pushes/1/complete 2026/10/09 09:58:08 WARN Failed to register uploaded object key=sbspf4zal7xybqarcb96sazpvn09dw1j.narinfo error="server returned 404: 404 page not found\n" === NAME TestPinProtectsFromGC client_integration_test.go:976: Pin successfully protected closure from garbage collection 2026/10/09 09:58:08 INFO Completed push id=1 objects=4 duration=42.304709ms 2026/10/09 09:58:08 INFO Upload complete. (358ms) === NAME TestClientCADerivations client_ca_test.go:180: Narinfo contains CA field: StorePath: /private/var/tb/5/scratch/00f1341bdd59a71e/build/TestClientCADerivations48090870/001/store/sbspf4zal7xybqarcb96sazpvn09dw1j-ca-test URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst Compression: zstd NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n NarSize: 144 References: Deriver: /private/var/tb/5/scratch/00f1341bdd59a71e/build/TestClientCADerivations48090870/001/store/bbk7vwwnbls3hamrmv5i6i7fpd2b0h8y-ca-test.drv CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n client_ca_test.go:185: Checking for realisation files in S3... client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache --- PASS: TestPinProtectsFromGC (12.54s) === CONT TestUploadHandlersRejectOversizedBody/request_more_parts 2026/10/09 09:58:08 INFO Received request for more parts method=POST path=/ --- PASS: TestCacheStatsHandler (6.43s) === CONT TestUploadHandlersRejectOversizedBody/complete_multipart 2026/10/09 09:58:08 INFO Received complete multipart upload request method=POST path=/ === NAME TestClientCADerivations client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket80?endpoint=http://localhost:60965®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/private/var/tb/5/scratch/00f1341bdd59a71e/build/TestClientCADerivations48090870/001/store' client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 1 --- PASS: TestClientCADerivations (8.55s) === CONT TestCacheConfigHandler/full_config,_no_issuer === CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator === CONT TestCacheConfigHandler/no_signing_keys === CONT TestCacheConfigHandler/no_cache_url_configured === CONT TestPush_RejectsBadRequests/no_objects --- PASS: TestCacheConfigHandler (0.00s) --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s) --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s) --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s) --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s) 2026/10/09 09:58:08 INFO Received push request method=POST path=/api/pushes === CONT TestPush_RejectsBadRequests/bad_root 2026/10/09 09:58:08 INFO Received push request method=POST path=/api/pushes === CONT TestPush_RejectsBadRequests/no_roots 2026/10/09 09:58:08 INFO Received push request method=POST path=/api/pushes === CONT TestPush_RejectsBadRequests/root_not_in_objects 2026/10/09 09:58:08 INFO Received push request method=POST path=/api/pushes === CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected 2026/10/09 09:58:08 WARN Authentication failed token_preview=not-a-valid-jwt token_length=15 oidc_error="no provider could verify the token (signature or issuer mismatch)" oidc_provider="" tried_providers=[test] === CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured === CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected 2026/10/09 09:58:08 WARN Authentication failed token_preview=eyJhbGciOi...Z8feoM4R0Q token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test] === CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token === CONT TestService_RequireScope_OIDC/builder_may_write === CONT TestService_RequireScope_OIDC/static_token_may_write === CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read === CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc === CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc === CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read === CONT TestService_RequireScope_OIDC/writer_implies_read 2026/10/09 09:58:08 WARN Authentication failed token_preview=wrong token_length=5 oidc_error="no provider could verify the token (signature or issuer mismatch)" oidc_provider="" tried_providers=[test] === CONT TestService_RequireScope_OIDC/anonymous_may_not_read === CONT TestService_RequireScope_OIDC/ops_may_not_write --- PASS: TestPush_RejectsBadRequests (8.38s) --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s) --- PASS: TestPush_RejectsBadRequests/bad_root (0.01s) --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s) --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s) === CONT TestService_RequireScope_OIDC/static_token_may_admin === CONT TestService_RequireScope_OIDC/reader_may_not_write === CONT TestService_RequireScope_OIDC/builder_may_not_admin === CONT TestService_RequireScope_OIDC/reader_may_read === CONT TestService_RequireScope_OIDC/ops_may_admin === CONT TestClientErrorHandling/InvalidStorePath --- PASS: TestService_AuthMiddleware_OIDC (8.91s) --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.01s) --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s) --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.01s) --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s) === CONT TestClientErrorHandling/ServerNotAvailable 2026/10/09 09:58:08 INFO Received uploads request method=POST path=/api/pending_closures {"timestamp":"2026-10-09T09:58:08.779206Z","level":"ERROR","message":"save_config_with_opts: err: Io(Custom { kind: TooManyOpenFiles, error: \"Too many open files (os error 24)\" }), file: scanner/durable-dirty-producer-replay.json","target":"rustfs_ecstore::config::com","filename":"crates/ecstore/src/config/com.rs","line_number":813,"threadName":"rustfs-worker","threadId":"ThreadId(2)"} === CONT TestClientErrorHandling/InvalidAuthToken --- PASS: TestService_RequireScope_OIDC (9.59s) --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s) --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s) --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s) --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s) --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s) --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.01s) --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s) --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s) --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s) --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s) --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s) --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s) --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s) --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s) {"timestamp":"2026-10-09T09:58:08.906349Z","level":"ERROR","duration":"163.301583ms","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(9)"} {"timestamp":"2026-10-09T09:58:08.906473Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"58176551-7cdd-498b-9ba8-72b6e2722e38","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"PUT","uri":"/bucket75/nar/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb00000000000000000000.nar.zst","status_code":500,"suppressed_errors":0,"duration_ms":163,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":501,"threadName":"rustfs-worker","threadId":"ThreadId(9)"} === NAME TestPush_RepeatedRootCommitsOnce pushes_test.go:162: expected http status 200 for part 9, got 500 pushes_test.go:162: no ETag in response for part 9 2026/10/09 09:58:08 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present {"timestamp":"2026-10-09T09:58:08.996192Z","level":"ERROR","message":"Scanner bucket cache save failed","event":"scanner_cache_persist_state","component":"scanner","subsystem":"io","bucket":"bucket7","cache_name":"bucket7/.usage-cache.bin","state":"save_failed","error":"Io error: Too many open files (os error 24)","target":"rustfs::scanner::io","filename":"crates/scanner/src/scanner_io/io_cache.rs","line_number":1373,"threadName":"rustfs-worker","threadId":"ThreadId(10)"} 2026/10/09 09:58:09 INFO Received complete multipart upload request method=POST path=/api/multipart/complete 2026/10/09 09:58:09 ERROR Failed to complete multipart upload error="One or more of the specified parts could not be found. The part may not have been uploaded, or the specified entity tag may not match the part's entity tag." object_key=nar/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb00000000000000000000.nar.zst upload_id=MTE5MjdlYzItNjE3OS00ZDA5LTljZjMtZGFiOThmMGQ2ZDQ0LmQ5NzhjZWJlLTVjYjItNDlmYy05MGI3LTQxMDUxZTlkOTUyOHgxNzkxNTM5ODg1NTU0Mzk0MDAw pushes_test.go:162: unexpected http status=500 body=failed to complete multipart upload: One or more of the specified parts could not be found. The part may not have been uploaded, or the specified entity tag may not match the part's entity tag. 2026-10-09 09:58:09.040 UTC [65334] LOG: checkpoint starting: wal {"timestamp":"2026-10-09T09:58:09.065359Z","level":"ERROR","duration":"427.833µs","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(2)"} {"timestamp":"2026-10-09T09:58:09.066941Z","level":"ERROR","message":"Disk local scan failed","event":"disk_local_scan_failed","component":"ecstore","subsystem":"disk_local","path":"","operation":"list_dir","error":"Io(Os { code: 24, kind: TooManyOpenFiles, message: \"Too many open files\" })","target":"rustfs_ecstore::disk::local","filename":"crates/ecstore/src/disk/local.rs","line_number":7605,"threadName":"rustfs-worker","threadId":"ThreadId(6)"} {"timestamp":"2026-10-09T09:58:09.066989Z","level":"ERROR","message":"Metacache listing quorum failed","event":"metacache_listing","component":"ecstore","subsystem":"metacache","bucket":"bucket85","path":"","state":"quorum_failed","error":"drive /private/var/tb/5/scratch/00f1341bdd59a71e/build/rustfs694584765/data returned: io error Too many open files (os error 24)","target":"rustfs_ecstore::cache_value::metacache_set","filename":"crates/ecstore/src/cache_value/metacache_set.rs","line_number":909,"threadName":"rustfs-worker","threadId":"ThreadId(6)"} {"timestamp":"2026-10-09T09:58:09.067008Z","level":"ERROR","message":"Metacache merge job failed","event":"metacache_listing","component":"ecstore","subsystem":"metacache","bucket":"bucket85","path":"","state":"merge_job_failed","error":"ErasureReadQuorum","target":"rustfs_ecstore::cache_value::metacache_set","filename":"crates/ecstore/src/cache_value/metacache_set.rs","line_number":1002,"threadName":"rustfs-worker","threadId":"ThreadId(6)"} {"timestamp":"2026-10-09T09:58:09.067056Z","level":"ERROR","message":"list_path worker failed","component":"store","stage":"list_merged","bucket":"bucket85","prefix":"","base_dir":"","limit":1001,"marker":"","error":"erasure read quorum","target":"rustfs_ecstore::store::list_objects","filename":"crates/ecstore/src/store/list_objects.rs","line_number":242,"threadName":"rustfs-worker","threadId":"ThreadId(6)"} {"timestamp":"2026-10-09T09:58:09.06707Z","level":"ERROR","message":"list_path worker failed","component":"store","stage":"trailing_worker_error","bucket":"bucket85","prefix":"","base_dir":"","limit":1001,"marker":"","error":"erasure read quorum","target":"rustfs_ecstore::store::list_objects","filename":"crates/ecstore/src/store/list_objects.rs","line_number":242,"threadName":"rustfs-worker","threadId":"ThreadId(6)"} {"timestamp":"2026-10-09T09:58:09.067092Z","level":"ERROR","duration":"289.333µs","resp":"Response { status: 503, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"SlowDownReadResource requested is unreadable, please reduce your request rate\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(6)"} {"timestamp":"2026-10-09T09:58:09.067101Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"032970fa-32b0-41ab-9254-e9f2986812d9","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/bucket85/","status_code":503,"suppressed_errors":0,"duration_ms":0,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":501,"threadName":"rustfs-worker","threadId":"ThreadId(6)"} {"timestamp":"2026-10-09T09:58:09.07386Z","level":"ERROR","duration":"32.146625ms","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(6)"} {"timestamp":"2026-10-09T09:58:09.082839Z","level":"ERROR","message":"save_config_with_opts: err: Io(Custom { kind: TooManyOpenFiles, error: \"Too many open files (os error 24)\" }), file: scanner/durable-dirty-producer-replay.json","target":"rustfs_ecstore::config::com","filename":"crates/ecstore/src/config/com.rs","line_number":813,"threadName":"rustfs-worker","threadId":"ThreadId(10)"} 2026/10/09 09:58:09 WARN Request failed, retrying attempt=2 backoff=204.056967ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present {"timestamp":"2026-10-09T09:58:09.113487Z","level":"ERROR","duration":"634.583µs","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(10)"} {"timestamp":"2026-10-09T09:58:09.194901Z","level":"ERROR","message":"data usage snapshot load failed","event":"data_usage_snapshot_load_failed","component":"ecstore","subsystem":"data_usage","state":"read_failed","operation":"remove_bucket_from_observed","reason":"io","object":"buckets/.usage.observed.json","error":"Io error: Too many open files (os error 24)","target":"rustfs_ecstore::data_usage","filename":"crates/ecstore/src/data_usage/mod.rs","line_number":968,"threadName":"rustfs-worker","threadId":"ThreadId(10)"} --- FAIL: TestPush_RepeatedRootCommitsOnce (11.14s) === CONT TestProxyWriteTimeout/narinfo === CONT TestProxyWriteTimeout/unknown_size === CONT TestProxyWriteTimeout/10_GiB_nar === CONT TestProxyWriteTimeout/1_GiB_nar === CONT TestServerTLSConfig/no_client_CA --- PASS: TestProxyWriteTimeout (0.01s) --- PASS: TestProxyWriteTimeout/narinfo (0.00s) --- PASS: TestProxyWriteTimeout/unknown_size (0.00s) --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s) --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s) === CONT TestServerTLSConfig/missing_CA_file === CONT TestServerTLSConfig/not_a_PEM_file --- PASS: TestServerTLSConfig (0.01s) --- PASS: TestServerTLSConfig/no_client_CA (0.00s) --- PASS: TestServerTLSConfig/missing_CA_file (0.00s) --- PASS: TestServerTLSConfig/not_a_PEM_file (0.02s) === CONT TestPresentNotReportedWhileGCDeletesClosure/stale {"timestamp":"2026-10-09T09:58:09.254267Z","level":"ERROR","duration":"465.041µs","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(10)"} 2026/10/09 09:58:09 WARN Request failed, retrying attempt=3 backoff=371.915341ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present {"timestamp":"2026-10-09T09:58:09.302251Z","level":"ERROR","message":"save_config_with_opts: err: Io(Custom { kind: TooManyOpenFiles, error: \"Too many open files (os error 24)\" }), file: scanner/durable-dirty-producer-replay.json","target":"rustfs_ecstore::config::com","filename":"crates/ecstore/src/config/com.rs","line_number":813,"threadName":"rustfs-worker","threadId":"ThreadId(2)"} {"timestamp":"2026-10-09T09:58:09.306119Z","level":"ERROR","duration":"19.640667ms","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(2)"} {"timestamp":"2026-10-09T09:58:09.306729Z","level":"ERROR","message":"Heal scheduler task failed","event":"heal_scheduler_state","component":"heal","subsystem":"manager","task_id":"bcca5f0b-fd84-47cd-9a6f-ad089df61ac7","heal_type":"object","set":"pool_0_set_0","state":"task_failed","error":"Heal task execution failed: Object not found: bucket86/nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhh.nar.zst","target":"rustfs::heal::manager","filename":"crates/heal/src/heal/manager/scheduler.rs","line_number":269,"threadName":"rustfs-worker","threadId":"ThreadId(7)"} {"timestamp":"2026-10-09T09:58:09.315758Z","level":"ERROR","duration":"30.256041ms","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(2)"} {"timestamp":"2026-10-09T09:58:09.317222Z","level":"ERROR","duration":"1.66725ms","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(7)"} {"timestamp":"2026-10-09T09:58:09.359339Z","level":"ERROR","duration":"660µs","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(10)"} {"timestamp":"2026-10-09T09:58:09.40127Z","level":"ERROR","message":"Scanner bucket cache save failed","event":"scanner_cache_persist_state","component":"scanner","subsystem":"io","bucket":"bucket8","cache_name":"bucket8/.usage-cache.bin","state":"save_failed","error":"Io error: Too many open files (os error 24)","target":"rustfs::scanner::io","filename":"crates/scanner/src/scanner_io/io_cache.rs","line_number":1373,"threadName":"rustfs-worker","threadId":"ThreadId(7)"} {"timestamp":"2026-10-09T09:58:09.417015Z","level":"ERROR","duration":"443.458µs","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(10)"} {"timestamp":"2026-10-09T09:58:09.442516Z","level":"ERROR","duration":"446.083µs","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(2)"} {"timestamp":"2026-10-09T09:58:09.446557Z","level":"ERROR","duration":"17.875875ms","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(10)"} === NAME TestSweepRechecksPendingAfterLocking gc_races_test.go:635: unexpected error: We encountered an internal error, please try again. {"timestamp":"2026-10-09T09:58:09.458605Z","level":"ERROR","duration":"550.916µs","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(2)"} {"timestamp":"2026-10-09T09:58:09.482916Z","level":"ERROR","duration":"484.583µs","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(9)"} {"timestamp":"2026-10-09T09:58:09.641673Z","level":"ERROR","duration":"692.917µs","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(9)"} {"timestamp":"2026-10-09T09:58:09.660286Z","level":"ERROR","duration":"19.308125ms","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(2)"} 2026/10/09 09:58:09 WARN Request failed, retrying attempt=4 backoff=761.908619ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present {"timestamp":"2026-10-09T09:58:09.729025Z","level":"ERROR","duration":"378.583µs","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(10)"} {"timestamp":"2026-10-09T09:58:09.736939Z","level":"ERROR","message":"Scanner bucket cache save failed","event":"scanner_cache_persist_state","component":"scanner","subsystem":"io","bucket":"bucket9","cache_name":"bucket9/.usage-cache.bin","state":"save_failed","error":"Io error: Too many open files (os error 24)","target":"rustfs::scanner::io","filename":"crates/scanner/src/scanner_io/io_cache.rs","line_number":1373,"threadName":"rustfs-worker","threadId":"ThreadId(10)"} {"timestamp":"2026-10-09T09:58:09.737048Z","level":"ERROR","message":"Scanner cycle completed without a durable data usage snapshot","event":"scanner_persist_state","component":"scanner","subsystem":"runtime","cycle":6,"outcome":"NoUpdate","state":"usage_not_durable","target":"rustfs::scanner","filename":"crates/scanner/src/scanner.rs","line_number":2350,"threadName":"rustfs-worker","threadId":"ThreadId(9)"} {"timestamp":"2026-10-09T09:58:09.808186Z","level":"ERROR","duration":"358.5µs","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(10)"} {"timestamp":"2026-10-09T09:58:09.817506Z","level":"ERROR","duration":"297.292µs","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(10)"} {"timestamp":"2026-10-09T09:58:10.016772Z","level":"ERROR","duration":"373.458µs","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(9)"} {"timestamp":"2026-10-09T09:58:10.09051Z","level":"ERROR","duration":"442.5µs","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(6)"} {"timestamp":"2026-10-09T09:58:10.090629Z","level":"ERROR","duration":"561.875µs","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(7)"} {"timestamp":"2026-10-09T09:58:10.098924Z","level":"ERROR","message":"Scanner bucket cache save failed","event":"scanner_cache_persist_state","component":"scanner","subsystem":"io","bucket":"bucket1","cache_name":"bucket1/.usage-cache.bin","state":"save_failed","error":"Io error: Too many open files (os error 24)","target":"rustfs::scanner::io","filename":"crates/scanner/src/scanner_io/io_cache.rs","line_number":1373,"threadName":"rustfs-worker","threadId":"ThreadId(7)"} {"timestamp":"2026-10-09T09:58:10.208967Z","level":"ERROR","duration":"406.875µs","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(2)"} {"timestamp":"2026-10-09T09:58:10.309578Z","level":"ERROR","duration":"14.953792ms","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(2)"} {"timestamp":"2026-10-09T09:58:10.34909Z","level":"ERROR","duration":"9.428292ms","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(6)"} {"timestamp":"2026-10-09T09:58:10.357989Z","level":"ERROR","message":"Scanner partial bucket cache save failed","event":"scanner_cache_persist_state","component":"scanner","subsystem":"io","bucket":"bucket10","cache_name":"bucket10/.usage-cache.bin","state":"partial_save_failed","error":"Io error: Too many open files (os error 24)","target":"rustfs::scanner::io","filename":"crates/scanner/src/scanner_io/io_cache.rs","line_number":1297,"threadName":"rustfs-worker","threadId":"ThreadId(2)"} {"timestamp":"2026-10-09T09:58:10.413311Z","level":"ERROR","duration":"10.794ms","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(10)"} 2026/10/09 09:58:10 WARN Request failed, retrying attempt=5 backoff=1.629358619s error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present {"timestamp":"2026-10-09T09:58:10.651793Z","level":"ERROR","duration":"425.542µs","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(9)"} {"timestamp":"2026-10-09T09:58:10.656551Z","level":"ERROR","duration":"312.958µs","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(10)"} {"timestamp":"2026-10-09T09:58:10.666423Z","level":"ERROR","message":"Scanner bucket cache save failed","event":"scanner_cache_persist_state","component":"scanner","subsystem":"io","bucket":"bucket11","cache_name":"bucket11/.usage-cache.bin","state":"save_failed","error":"Io error: Too many open files (os error 24)","target":"rustfs::scanner::io","filename":"crates/scanner/src/scanner_io/io_cache.rs","line_number":1373,"threadName":"rustfs-worker","threadId":"ThreadId(2)"} {"timestamp":"2026-10-09T09:58:10.707Z","level":"ERROR","duration":"313.25µs","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(6)"} {"timestamp":"2026-10-09T09:58:10.762209Z","level":"ERROR","duration":"10.598833ms","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(6)"} {"timestamp":"2026-10-09T09:58:10.827838Z","level":"ERROR","duration":"314.083µs","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(9)"} {"timestamp":"2026-10-09T09:58:10.935614Z","level":"ERROR","message":"Scanner bucket cache save failed","event":"scanner_cache_persist_state","component":"scanner","subsystem":"io","bucket":"bucket12","cache_name":"bucket12/.usage-cache.bin","state":"save_failed","error":"Io error: Too many open files (os error 24)","target":"rustfs::scanner::io","filename":"crates/scanner/src/scanner_io/io_cache.rs","line_number":1373,"threadName":"rustfs-worker","threadId":"ThreadId(6)"} {"timestamp":"2026-10-09T09:58:10.983111Z","level":"ERROR","duration":"335.542µs","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(9)"} {"timestamp":"2026-10-09T09:58:11.102635Z","level":"ERROR","duration":"9.827084ms","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(9)"} {"timestamp":"2026-10-09T09:58:11.142343Z","level":"ERROR","duration":"345.167µs","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(10)"} {"timestamp":"2026-10-09T09:58:11.174448Z","level":"ERROR","duration":"298.375µs","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(10)"} {"timestamp":"2026-10-09T09:58:11.217036Z","level":"ERROR","duration":"303.958µs","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(2)"} {"timestamp":"2026-10-09T09:58:11.217125Z","level":"ERROR","message":"Scanner bucket cache save failed","event":"scanner_cache_persist_state","component":"scanner","subsystem":"io","bucket":"bucket13","cache_name":"bucket13/.usage-cache.bin","state":"save_failed","error":"Io error: Too many open files (os error 24)","target":"rustfs::scanner::io","filename":"crates/scanner/src/scanner_io/io_cache.rs","line_number":1373,"threadName":"rustfs-worker","threadId":"ThreadId(2)"} {"timestamp":"2026-10-09T09:58:11.369277Z","level":"ERROR","duration":"362.875µs","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(9)"} {"timestamp":"2026-10-09T09:58:11.509662Z","level":"ERROR","message":"Scanner bucket cache save failed","event":"scanner_cache_persist_state","component":"scanner","subsystem":"io","bucket":"bucket14","cache_name":"bucket14/.usage-cache.bin","state":"save_failed","error":"Io error: Too many open files (os error 24)","target":"rustfs::scanner::io","filename":"crates/scanner/src/scanner_io/io_cache.rs","line_number":1373,"threadName":"rustfs-worker","threadId":"ThreadId(10)"} {"timestamp":"2026-10-09T09:58:11.653783Z","level":"ERROR","duration":"415.25µs","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(6)"} {"timestamp":"2026-10-09T09:58:11.680759Z","level":"ERROR","duration":"336.208µs","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(10)"} {"timestamp":"2026-10-09T09:58:11.813764Z","level":"ERROR","message":"Scanner bucket cache save failed","event":"scanner_cache_persist_state","component":"scanner","subsystem":"io","bucket":"bucket15","cache_name":"bucket15/.usage-cache.bin","state":"save_failed","error":"Io error: Too many open files (os error 24)","target":"rustfs::scanner::io","filename":"crates/scanner/src/scanner_io/io_cache.rs","line_number":1373,"threadName":"rustfs-worker","threadId":"ThreadId(2)"} {"timestamp":"2026-10-09T09:58:11.931235Z","level":"ERROR","duration":"333.083µs","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(2)"} {"timestamp":"2026-10-09T09:58:12.013798Z","level":"ERROR","duration":"10.014208ms","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(6)"} {"timestamp":"2026-10-09T09:58:12.023709Z","level":"ERROR","duration":"306.875µs","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(2)"} {"timestamp":"2026-10-09T09:58:12.024419Z","level":"ERROR","duration":"268.25µs","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(2)"} {"timestamp":"2026-10-09T09:58:12.087947Z","level":"ERROR","message":"Scanner bucket cache save failed","event":"scanner_cache_persist_state","component":"scanner","subsystem":"io","bucket":"bucket16","cache_name":"bucket16/.usage-cache.bin","state":"save_failed","error":"Io error: Too many open files (os error 24)","target":"rustfs::scanner::io","filename":"crates/scanner/src/scanner_io/io_cache.rs","line_number":1373,"threadName":"rustfs-worker","threadId":"ThreadId(10)"} 2026/10/09 09:58:12 WARN Request failed, retrying attempt=1 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config {"timestamp":"2026-10-09T09:58:12.192889Z","level":"ERROR","duration":"370.125µs","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(2)"} 2026/10/09 09:58:12 WARN Request failed, retrying attempt=2 backoff=194.154309ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config 2026/10/09 09:58:12 WARN Request failed, retrying attempt=3 backoff=421.446163ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config {"timestamp":"2026-10-09T09:58:12.408925Z","level":"ERROR","message":"Scanner partial bucket cache save failed","event":"scanner_cache_persist_state","component":"scanner","subsystem":"io","bucket":"bucket17","cache_name":"bucket17/.usage-cache.bin","state":"partial_save_failed","error":"Io error: Too many open files (os error 24)","target":"rustfs::scanner::io","filename":"crates/scanner/src/scanner_io/io_cache.rs","line_number":1297,"threadName":"rustfs-worker","threadId":"ThreadId(10)"} === CONT TestPresentNotReportedWhileGCDeletesClosure/fresh --- PASS: TestUploadHandlersRejectOversizedBody (0.19s) --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.30s) --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.32s) --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (4.35s) {"timestamp":"2026-10-09T09:58:12.589202Z","level":"ERROR","duration":"422.042µs","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(10)"} {"timestamp":"2026-10-09T09:58:12.669501Z","level":"ERROR","message":"Scanner bucket cache save failed","event":"scanner_cache_persist_state","component":"scanner","subsystem":"io","bucket":"bucket18","cache_name":"bucket18/.usage-cache.bin","state":"save_failed","error":"Io error: Too many open files (os error 24)","target":"rustfs::scanner::io","filename":"crates/scanner/src/scanner_io/io_cache.rs","line_number":1373,"threadName":"rustfs-worker","threadId":"ThreadId(6)"} {"timestamp":"2026-10-09T09:58:12.669722Z","level":"ERROR","duration":"13.860125ms","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(2)"} 2026/10/09 09:58:12 WARN Request failed, retrying attempt=4 backoff=735.575204ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config {"timestamp":"2026-10-09T09:58:12.84792Z","level":"ERROR","duration":"1.9455ms","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(6)"} {"timestamp":"2026-10-09T09:58:12.873208Z","level":"ERROR","duration":"1.643708ms","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(9)"} {"timestamp":"2026-10-09T09:58:12.903528Z","level":"ERROR","duration":"1.385167ms","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(10)"} {"timestamp":"2026-10-09T09:58:12.920205Z","level":"ERROR","message":"Scanner bucket cache save failed","event":"scanner_cache_persist_state","component":"scanner","subsystem":"io","bucket":"bucket19","cache_name":"bucket19/.usage-cache.bin","state":"save_failed","error":"Io error: Too many open files (os error 24)","target":"rustfs::scanner::io","filename":"crates/scanner/src/scanner_io/io_cache.rs","line_number":1373,"threadName":"rustfs-worker","threadId":"ThreadId(10)"} === NAME TestService_AuthMiddleware_MTLSProxyHeader request_test.go:70: store invariants: list multipart uploads: We encountered an internal error, please try again. --- FAIL: TestService_AuthMiddleware_MTLSProxyHeader (10.40s) === CONT TestParseSingleRange/multi-range_ignored === CONT TestParseSingleRange/closed === CONT TestParseSingleRange/start_far_past_EOF === CONT TestParseSingleRange/single_byte === CONT TestParseSingleRange/suffix_exceeds_size === CONT TestParseSingleRange/suffix === CONT TestParseSingleRange/start_past_EOF === CONT TestParseSingleRange/open-ended === CONT TestParseSingleRange/malformed_no_dash === CONT TestParseSingleRange/end_clamped_to_size === CONT TestParseSingleRange/malformed_end_before_start === CONT TestParseSingleRange/unknown_unit === CONT TestParseSingleRange/malformed_both_empty === CONT TestParseSingleRange/none === CONT TestIsValidCachePath/nar_zst --- PASS: TestParseSingleRange (0.05s) --- PASS: TestParseSingleRange/multi-range_ignored (0.00s) --- PASS: TestParseSingleRange/closed (0.00s) --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s) --- PASS: TestParseSingleRange/single_byte (0.00s) --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s) --- PASS: TestParseSingleRange/suffix (0.00s) --- PASS: TestParseSingleRange/start_past_EOF (0.00s) --- PASS: TestParseSingleRange/open-ended (0.00s) --- PASS: TestParseSingleRange/malformed_no_dash (0.00s) --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s) --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s) --- PASS: TestParseSingleRange/unknown_unit (0.00s) --- PASS: TestParseSingleRange/malformed_both_empty (0.00s) --- PASS: TestParseSingleRange/none (0.00s) === CONT TestIsValidCachePath/invalid_char_u === CONT TestIsValidCachePath/short_hash === CONT TestIsValidCachePath/wrong_extension === CONT TestIsValidCachePath/leading_slash === CONT TestIsValidCachePath/random_path === CONT TestIsValidCachePath/empty === CONT TestIsValidCachePath/invalid_char_e === CONT TestIsValidCachePath/traversal_in_middle === CONT TestIsValidCachePath/traversal_parent === CONT TestIsValidCachePath/index.html === CONT TestIsValidCachePath/log === CONT TestIsValidCachePath/realisation === CONT TestIsValidCachePath/ls === CONT TestIsValidCachePath/nar_uncompressed === CONT TestIsValidCachePath/nar_xz === CONT TestIsValidCachePath/nar_bz2 === CONT TestIsValidCachePath/narinfo_all_nix_base32_chars === CONT TestIsValidCachePath/narinfo === CONT TestIsValidCachePath/nix-cache-info === CONT TestResolveDBConnectionString/flag_wins --- PASS: TestIsValidCachePath (0.10s) --- PASS: TestIsValidCachePath/nar_zst (0.00s) --- PASS: TestIsValidCachePath/invalid_char_u (0.00s) --- PASS: TestIsValidCachePath/short_hash (0.00s) --- PASS: TestIsValidCachePath/wrong_extension (0.00s) --- PASS: TestIsValidCachePath/leading_slash (0.00s) --- PASS: TestIsValidCachePath/random_path (0.00s) --- PASS: TestIsValidCachePath/empty (0.00s) --- PASS: TestIsValidCachePath/invalid_char_e (0.00s) --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s) --- PASS: TestIsValidCachePath/traversal_parent (0.00s) --- PASS: TestIsValidCachePath/index.html (0.00s) --- PASS: TestIsValidCachePath/log (0.00s) --- PASS: TestIsValidCachePath/realisation (0.00s) --- PASS: TestIsValidCachePath/ls (0.00s) --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s) --- PASS: TestIsValidCachePath/nar_xz (0.00s) --- PASS: TestIsValidCachePath/nar_bz2 (0.00s) --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s) --- PASS: TestIsValidCachePath/narinfo (0.00s) --- PASS: TestIsValidCachePath/nix-cache-info (0.00s) === CONT TestResolveDBConnectionString/PGHOST_allows_empty === CONT TestResolveDBConnectionString/nothing_configured === CONT TestResolveDBConnectionString/missing_file_is_an_error === CONT TestResolveDBConnectionString/file_when_flag_empty === CONT TestGCEndsOnShutdown/before_the_run --- PASS: TestResolveDBConnectionString (0.09s) --- PASS: TestResolveDBConnectionString/flag_wins (0.00s) --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s) --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s) --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s) --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s) {"timestamp":"2026-10-09T09:58:13.220135Z","level":"ERROR","duration":"536.542µs","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(9)"} {"timestamp":"2026-10-09T09:58:13.226739Z","level":"ERROR","message":"Scanner bucket cache save failed","event":"scanner_cache_persist_state","component":"scanner","subsystem":"io","bucket":"bucket2","cache_name":"bucket2/.usage-cache.bin","state":"save_failed","error":"Io error: Too many open files (os error 24)","target":"rustfs::scanner::io","filename":"crates/scanner/src/scanner_io/io_cache.rs","line_number":1373,"threadName":"rustfs-worker","threadId":"ThreadId(2)"} {"timestamp":"2026-10-09T09:58:13.300608Z","level":"ERROR","duration":"528.875µs","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(10)"} === NAME TestPushWaitsForSweepHoldingRow request_test.go:70: store invariants: list multipart uploads: We encountered an internal error, please try again. --- FAIL: TestPushWaitsForSweepHoldingRow (11.19s) === CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark {"timestamp":"2026-10-09T09:58:13.55611Z","level":"ERROR","message":"Scanner bucket cache save failed","event":"scanner_cache_persist_state","component":"scanner","subsystem":"io","bucket":"bucket20","cache_name":"bucket20/.usage-cache.bin","state":"save_failed","error":"Io error: Too many open files (os error 24)","target":"rustfs::scanner::io","filename":"crates/scanner/src/scanner_io/io_cache.rs","line_number":1373,"threadName":"rustfs-worker","threadId":"ThreadId(2)"} 2026/10/09 09:58:13 WARN Request failed, retrying attempt=5 backoff=1.5382196s error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config === NAME TestCommitRacingPendingCleanupKeepsObjects gc_races_test.go:737: unexpected error: We encountered an internal error, please try again. --- FAIL: TestCommitRacingPendingCleanupKeepsObjects (10.48s) === CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete {"timestamp":"2026-10-09T09:58:13.645351Z","level":"ERROR","duration":"12.946625ms","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(9)"} {"timestamp":"2026-10-09T09:58:13.676449Z","level":"ERROR","duration":"11.506333ms","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(10)"} {"timestamp":"2026-10-09T09:58:13.726377Z","level":"ERROR","duration":"13.235542ms","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(6)"} {"timestamp":"2026-10-09T09:58:13.727981Z","level":"ERROR","duration":"647.75µs","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(10)"} {"timestamp":"2026-10-09T09:58:13.797467Z","level":"ERROR","message":"save_config_with_opts: err: Io(Custom { kind: TooManyOpenFiles, error: \"Too many open files (os error 24)\" }), file: scanner/durable-dirty-producer-replay.json","target":"rustfs_ecstore::config::com","filename":"crates/ecstore/src/config/com.rs","line_number":813,"threadName":"rustfs-worker","threadId":"ThreadId(2)"} {"timestamp":"2026-10-09T09:58:13.816348Z","level":"ERROR","duration":"141.041µs","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(10)"} {"timestamp":"2026-10-09T09:58:13.82035Z","level":"ERROR","message":"Scanner bucket cache save failed","event":"scanner_cache_persist_state","component":"scanner","subsystem":"io","bucket":"bucket21","cache_name":"bucket21/.usage-cache.bin","state":"save_failed","error":"Io error: Too many open files (os error 24)","target":"rustfs::scanner::io","filename":"crates/scanner/src/scanner_io/io_cache.rs","line_number":1373,"threadName":"rustfs-worker","threadId":"ThreadId(10)"} {"timestamp":"2026-10-09T09:58:14.06371Z","level":"ERROR","duration":"17.459167ms","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(2)"} {"timestamp":"2026-10-09T09:58:14.063794Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"5abe50b5-a709-4967-b608-91b657823c83","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"PUT","uri":"/bucket88/","status_code":500,"suppressed_errors":55,"duration_ms":17,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":501,"threadName":"rustfs-worker","threadId":"ThreadId(2)"} === NAME TestSweepRechecksPendingAfterLocking request_test.go:70: store invariants: list multipart uploads: We encountered an internal error, please try again. --- FAIL: TestSweepRechecksPendingAfterLocking (10.92s) {"timestamp":"2026-10-09T09:58:14.139687Z","level":"ERROR","message":"Scanner partial bucket cache save failed","event":"scanner_cache_persist_state","component":"scanner","subsystem":"io","bucket":"bucket22","cache_name":"bucket22/.usage-cache.bin","state":"partial_save_failed","error":"Io error: Too many open files (os error 24)","target":"rustfs::scanner::io","filename":"crates/scanner/src/scanner_io/io_cache.rs","line_number":1297,"threadName":"rustfs-worker","threadId":"ThreadId(10)"} {"timestamp":"2026-10-09T09:58:14.182Z","level":"ERROR","duration":"15.743125ms","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(10)"} {"timestamp":"2026-10-09T09:58:14.28822Z","level":"ERROR","duration":"1.840833ms","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(10)"} {"timestamp":"2026-10-09T09:58:14.400103Z","level":"ERROR","message":"Scanner bucket cache save failed","event":"scanner_cache_persist_state","component":"scanner","subsystem":"io","bucket":"bucket23","cache_name":"bucket23/.usage-cache.bin","state":"save_failed","error":"Io error: Too many open files (os error 24)","target":"rustfs::scanner::io","filename":"crates/scanner/src/scanner_io/io_cache.rs","line_number":1373,"threadName":"rustfs-worker","threadId":"ThreadId(9)"} {"timestamp":"2026-10-09T09:58:14.774624Z","level":"ERROR","message":"Scanner bucket cache save failed","event":"scanner_cache_persist_state","component":"scanner","subsystem":"io","bucket":"bucket24","cache_name":"bucket24/.usage-cache.bin","state":"save_failed","error":"Io error: Too many open files (os error 24)","target":"rustfs::scanner::io","filename":"crates/scanner/src/scanner_io/io_cache.rs","line_number":1373,"threadName":"rustfs-worker","threadId":"ThreadId(2)"} === NAME TestDeleteClosuresRacingPins request_test.go:70: store invariants: list multipart uploads: We encountered an internal error, please try again. --- FAIL: TestDeleteClosuresRacingPins (14.98s) {"timestamp":"2026-10-09T09:58:15.106985Z","level":"ERROR","message":"Scanner bucket cache save failed","event":"scanner_cache_persist_state","component":"scanner","subsystem":"io","bucket":"bucket25","cache_name":"bucket25/.usage-cache.bin","state":"save_failed","error":"Io error: Too many open files (os error 24)","target":"rustfs::scanner::io","filename":"crates/scanner/src/scanner_io/io_cache.rs","line_number":1373,"threadName":"rustfs-worker","threadId":"ThreadId(10)"} 2026/10/09 09:58:15 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: sending request: request failed after retries: Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" 2026/10/09 09:58:15 WARN Request failed, retrying attempt=1 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config {"timestamp":"2026-10-09T09:58:15.190028Z","level":"ERROR","duration":"15.831084ms","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(6)"} 2026/10/09 09:58:15 WARN Request failed, retrying attempt=2 backoff=196.408927ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config === NAME TestDeletePinKeepsRowWhenS3Fails pins_test.go:231: unexpected error: context deadline exceeded --- FAIL: TestDeletePinKeepsRowWhenS3Fails (11.96s) {"timestamp":"2026-10-09T09:58:15.299942Z","level":"ERROR","duration":"10.468708ms","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(2)"} 2026/10/09 09:58:15 WARN Request failed, retrying attempt=3 backoff=400.780306ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config {"timestamp":"2026-10-09T09:58:15.431598Z","level":"ERROR","message":"Scanner bucket cache save failed","event":"scanner_cache_persist_state","component":"scanner","subsystem":"io","bucket":"bucket26","cache_name":"bucket26/.usage-cache.bin","state":"save_failed","error":"Io error: Too many open files (os error 24)","target":"rustfs::scanner::io","filename":"crates/scanner/src/scanner_io/io_cache.rs","line_number":1373,"threadName":"rustfs-worker","threadId":"ThreadId(2)"} {"timestamp":"2026-10-09T09:58:15.431473Z","level":"ERROR","message":"Heal storage request failed","event":"heal_storage_object_io","component":"heal","subsystem":"storage","operation":"object_exists","bucket":".rustfs.sys","object":"buckets/bucket26/.usage-cache.bin","result":"failed","error":"Io error: Too many open files (os error 24)","target":"rustfs::heal::storage","filename":"crates/heal/src/heal/storage.rs","line_number":1339,"threadName":"rustfs-worker","threadId":"ThreadId(6)"} {"timestamp":"2026-10-09T09:58:15.431736Z","level":"ERROR","message":"Heal scheduler task failed","event":"heal_scheduler_state","component":"heal","subsystem":"manager","task_id":"da92b888-c534-4274-aff8-bcc57e4e2dd5","heal_type":"object","set":"pool_0_set_0","state":"task_failed","error":"Other error: Io error: Too many open files (os error 24)","target":"rustfs::heal::manager","filename":"crates/heal/src/heal/manager/scheduler.rs","line_number":269,"threadName":"rustfs-worker","threadId":"ThreadId(6)"} {"timestamp":"2026-10-09T09:58:15.446414Z","level":"ERROR","duration":"644.708µs","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(9)"} {"timestamp":"2026-10-09T09:58:15.779011Z","level":"ERROR","message":"Heal storage request failed","event":"heal_storage_object_io","component":"heal","subsystem":"storage","operation":"object_exists","bucket":".rustfs.sys","object":"buckets/.usage.v2.json","result":"failed","error":"Io error: Too many open files (os error 24)","target":"rustfs::heal::storage","filename":"crates/heal/src/heal/storage.rs","line_number":1339,"threadName":"rustfs-worker","threadId":"ThreadId(10)"} {"timestamp":"2026-10-09T09:58:15.779065Z","level":"ERROR","message":"Heal scheduler task failed","event":"heal_scheduler_state","component":"heal","subsystem":"manager","task_id":"cc604d50-0af9-4b1a-adae-e1db0cc7bcdc","heal_type":"object","set":"pool_0_set_0","state":"task_failed","error":"Other error: Io error: Too many open files (os error 24)","target":"rustfs::heal::manager","filename":"crates/heal/src/heal/manager/scheduler.rs","line_number":269,"threadName":"rustfs-worker","threadId":"ThreadId(10)"} {"timestamp":"2026-10-09T09:58:15.779375Z","level":"ERROR","duration":"12.142333ms","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(10)"} 2026/10/09 09:58:15 WARN Request failed, retrying attempt=4 backoff=826.192428ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config {"timestamp":"2026-10-09T09:58:15.87813Z","level":"ERROR","message":"Scanner partial bucket cache save failed","event":"scanner_cache_persist_state","component":"scanner","subsystem":"io","bucket":"bucket27","cache_name":"bucket27/.usage-cache.bin","state":"partial_save_failed","error":"Io error: Too many open files (os error 24)","target":"rustfs::scanner::io","filename":"crates/scanner/src/scanner_io/io_cache.rs","line_number":1297,"threadName":"rustfs-worker","threadId":"ThreadId(2)"} === NAME TestCreatePinRejectsBadInput pins_test.go:189: unexpected error: context deadline exceeded --- FAIL: TestCreatePinRejectsBadInput (12.17s) {"timestamp":"2026-10-09T09:58:15.944457Z","level":"ERROR","message":"op returns error","op":"CreateBucket","err":"S3Error(Inner { code: InternalError, message: Some(\"We encountered an internal error, please try again.\"), request_id: None, status_code: None, source: Some(Io(Custom { kind: TooManyOpenFiles, error: \"Too many open files (os error 24)\" })), headers: None })","target":"s3s::ops","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/ops/mod.rs","line_number":456,"threadName":"rustfs-worker","threadId":"ThreadId(9)"} {"timestamp":"2026-10-09T09:58:15.944657Z","level":"ERROR","duration":"759.583µs","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(9)"} {"timestamp":"2026-10-09T09:58:16.001576Z","level":"ERROR","message":"op returns error","op":"CreateBucket","err":"S3Error(Inner { code: InternalError, message: Some(\"We encountered an internal error, please try again.\"), request_id: None, status_code: None, source: Some(Io(Custom { kind: TooManyOpenFiles, error: \"Too many open files (os error 24)\" })), headers: None })","target":"s3s::ops","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/ops/mod.rs","line_number":456,"threadName":"rustfs-worker","threadId":"ThreadId(9)"} {"timestamp":"2026-10-09T09:58:16.001621Z","level":"ERROR","duration":"398.375µs","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(9)"} {"timestamp":"2026-10-09T09:58:16.037028Z","level":"ERROR","message":"op returns error","op":"CreateBucket","err":"S3Error(Inner { code: InternalError, message: Some(\"We encountered an internal error, please try again.\"), request_id: None, status_code: None, source: Some(Io(Custom { kind: TooManyOpenFiles, error: \"Too many open files (os error 24)\" })), headers: None })","target":"s3s::ops","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/ops/mod.rs","line_number":456,"threadName":"rustfs-worker","threadId":"ThreadId(2)"} {"timestamp":"2026-10-09T09:58:16.037076Z","level":"ERROR","duration":"438.25µs","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"InternalErrorWe encountered an internal error, please try again.\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(2)"} === NAME TestConcurrentPinUpdatesAgree pins_test.go:111: unexpected error: context deadline exceeded --- FAIL: TestConcurrentPinUpdatesAgree (12.10s) {"timestamp":"2026-10-09T09:58:16.047155Z","level":"ERROR","message":"HTTP accept loop state changed","event":"http_accept_loop_state","component":"server","subsystem":"transport","state":"accept_failed","error":"Too many open files (os error 24)","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":1628,"threadName":"rustfs-worker","threadId":"ThreadId(9)"} {"timestamp":"2026-10-09T09:58:16.05199Z","level":"ERROR","message":"HTTP accept loop state changed","event":"http_accept_loop_state","component":"server","subsystem":"transport","state":"accept_failed","error":"Too many open files (os error 24)","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":1628,"threadName":"rustfs-worker","threadId":"ThreadId(9)"} {"timestamp":"2026-10-09T09:58:16.085236Z","level":"ERROR","message":"HTTP accept loop state changed","event":"http_accept_loop_state","component":"server","subsystem":"transport","state":"accept_failed","error":"Too many open files (os error 24)","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":1628,"threadName":"rustfs-worker","threadId":"ThreadId(9)"} {"timestamp":"2026-10-09T09:58:16.263117Z","level":"ERROR","message":"Scanner partial bucket cache save failed","event":"scanner_cache_persist_state","component":"scanner","subsystem":"io","bucket":"bucket28","cache_name":"bucket28/.usage-cache.bin","state":"partial_save_failed","error":"Io error: Too many open files (os error 24)","target":"rustfs::scanner::io","filename":"crates/scanner/src/scanner_io/io_cache.rs","line_number":1297,"threadName":"rustfs-worker","threadId":"ThreadId(9)"} 2026/10/09 09:58:16 WARN Request failed, retrying attempt=5 backoff=1.685071608s error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config {"timestamp":"2026-10-09T09:58:16.832392Z","level":"ERROR","message":"HTTP accept loop state changed","event":"http_accept_loop_state","component":"server","subsystem":"transport","state":"accept_failed","error":"Too many open files (os error 24)","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":1628,"threadName":"rustfs-worker","threadId":"ThreadId(2)"} === NAME TestOrphanedObjectsGCStressTest orphaned_objects_gc_test.go:304: unexpected error: context deadline exceeded --- FAIL: TestOrphanedObjectsGCStressTest (12.78s) {"timestamp":"2026-10-09T09:58:17.10565Z","level":"ERROR","message":"HTTP accept loop state changed","event":"http_accept_loop_state","component":"server","subsystem":"transport","state":"accept_failed","error":"Too many open files (os error 24)","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":1628,"threadName":"rustfs-worker","threadId":"ThreadId(2)"} {"timestamp":"2026-10-09T09:58:17.153145Z","level":"ERROR","message":"HTTP accept loop state changed","event":"http_accept_loop_state","component":"server","subsystem":"transport","state":"accept_failed","error":"Too many open files (os error 24)","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":1628,"threadName":"rustfs-worker","threadId":"ThreadId(2)"} {"timestamp":"2026-10-09T09:58:17.549796Z","level":"ERROR","message":"HTTP accept loop state changed","event":"http_accept_loop_state","component":"server","subsystem":"transport","state":"accept_failed","error":"Too many open files (os error 24)","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":1628,"threadName":"rustfs-worker","threadId":"ThreadId(2)"} {"timestamp":"2026-10-09T09:58:17.655232Z","level":"ERROR","message":"Scanner bucket cache load or revision lookup failed","event":"scanner_cache_persist_state","component":"scanner","subsystem":"io","bucket":"bucket29","cache_name":"bucket29/.usage-cache.bin","state":"load_or_revision_lookup_failed","error":"Io error: Too many open files (os error 24)","target":"rustfs::scanner::io","filename":"crates/scanner/src/scanner_io/io_cache.rs","line_number":988,"threadName":"rustfs-worker","threadId":"ThreadId(2)"} {"timestamp":"2026-10-09T09:58:17.972877Z","level":"ERROR","message":"HTTP accept loop state changed","event":"http_accept_loop_state","component":"server","subsystem":"transport","state":"accept_failed","error":"Too many open files (os error 24)","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":1628,"threadName":"rustfs-worker","threadId":"ThreadId(9)"} === NAME TestCreatePin_ReservedPins pins_acl_test.go:31: unexpected error: context deadline exceeded {"timestamp":"2026-10-09T09:58:18.072599Z","level":"ERROR","message":"HTTP accept loop state changed","event":"http_accept_loop_state","component":"server","subsystem":"transport","state":"accept_failed","error":"Too many open files (os error 24)","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":1628,"threadName":"rustfs-worker","threadId":"ThreadId(9)"} --- FAIL: TestCreatePin_ReservedPins (13.07s) === NAME TestSweepSkipsRowsLockedByPush gc_races_test.go:514: unexpected error: Put "http://localhost:60965/bucket93/": context deadline exceeded --- FAIL: TestSweepSkipsRowsLockedByPush (13.11s) {"timestamp":"2026-10-09T09:58:18.224835Z","level":"ERROR","message":"HTTP accept loop state changed","event":"http_accept_loop_state","component":"server","subsystem":"transport","state":"accept_failed","error":"Too many open files (os error 24)","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":1628,"threadName":"rustfs-worker","threadId":"ThreadId(9)"} {"timestamp":"2026-10-09T09:58:18.225872Z","level":"ERROR","message":"HTTP accept loop state changed","event":"http_accept_loop_state","component":"server","subsystem":"transport","state":"accept_failed","error":"Too many open files (os error 24)","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":1628,"threadName":"rustfs-worker","threadId":"ThreadId(9)"} {"timestamp":"2026-10-09T09:58:18.297935Z","level":"ERROR","message":"HTTP accept loop state changed","event":"http_accept_loop_state","component":"server","subsystem":"transport","state":"accept_failed","error":"Too many open files (os error 24)","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":1628,"threadName":"rustfs-worker","threadId":"ThreadId(9)"} 2026/10/09 09:58:18 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures === NAME TestGetExistingObjectsLocksRows gc_races_test.go:592: unexpected error: context deadline exceeded --- FAIL: TestGetExistingObjectsLocksRows (13.20s) {"timestamp":"2026-10-09T09:58:18.39833Z","level":"ERROR","message":"HTTP accept loop state changed","event":"http_accept_loop_state","component":"server","subsystem":"transport","state":"accept_failed","error":"Too many open files (os error 24)","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":1628,"threadName":"rustfs-worker","threadId":"ThreadId(9)"} {"timestamp":"2026-10-09T09:58:18.447294Z","level":"ERROR","message":"HTTP accept loop state changed","event":"http_accept_loop_state","component":"server","subsystem":"transport","state":"accept_failed","error":"Too many open files (os error 24)","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":1628,"threadName":"rustfs-worker","threadId":"ThreadId(9)"} 2026/10/09 09:58:18 WARN Request failed, retrying attempt=2 backoff=199.679109ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures === NAME TestRegisterCompletedObjectNeedsPendingRow gc_races_test.go:570: unexpected error: context deadline exceeded --- FAIL: TestRegisterCompletedObjectNeedsPendingRow (13.16s) {"timestamp":"2026-10-09T09:58:18.492269Z","level":"ERROR","message":"HTTP accept loop state changed","event":"http_accept_loop_state","component":"server","subsystem":"transport","state":"accept_failed","error":"Too many open files (os error 24)","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":1628,"threadName":"rustfs-worker","threadId":"ThreadId(9)"} 2026/10/09 09:58:18 WARN Request failed, retrying attempt=3 backoff=384.31874ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures {"timestamp":"2026-10-09T09:58:18.664821Z","level":"ERROR","message":"HTTP accept loop state changed","event":"http_accept_loop_state","component":"server","subsystem":"transport","state":"accept_failed","error":"Too many open files (os error 24)","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":1628,"threadName":"rustfs-worker","threadId":"ThreadId(10)"} {"timestamp":"2026-10-09T09:58:18.784574Z","level":"ERROR","message":"save_config_with_opts: err: Io(Custom { kind: TooManyOpenFiles, error: \"Too many open files (os error 24)\" }), file: scanner/durable-dirty-producer-replay.json","target":"rustfs_ecstore::config::com","filename":"crates/ecstore/src/config/com.rs","line_number":813,"threadName":"rustfs-worker","threadId":"ThreadId(9)"} {"timestamp":"2026-10-09T09:58:18.784731Z","level":"ERROR","message":"Heal storage request failed","event":"heal_storage_object_io","component":"heal","subsystem":"storage","operation":"object_exists","bucket":".rustfs.sys","object":"scanner/durable-dirty-producer-replay.json","result":"failed","error":"Io error: Too many open files (os error 24)","target":"rustfs::heal::storage","filename":"crates/heal/src/heal/storage.rs","line_number":1339,"threadName":"rustfs-worker","threadId":"ThreadId(10)"} {"timestamp":"2026-10-09T09:58:18.784775Z","level":"ERROR","message":"Heal scheduler task failed","event":"heal_scheduler_state","component":"heal","subsystem":"manager","task_id":"4ff19040-fd82-440c-ac3d-b94a5a334121","heal_type":"object","set":"pool_0_set_0","state":"task_failed","error":"Other error: Io error: Too many open files (os error 24)","target":"rustfs::heal::manager","filename":"crates/heal/src/heal/manager/scheduler.rs","line_number":269,"threadName":"rustfs-worker","threadId":"ThreadId(10)"} === NAME TestLeadIncumbentAnnouncesAtOnce farm_test.go:198: unexpected error: context deadline exceeded --- FAIL: TestLeadIncumbentAnnouncesAtOnce (13.06s) {"timestamp":"2026-10-09T09:58:18.981138Z","level":"ERROR","message":"HTTP accept loop state changed","event":"http_accept_loop_state","component":"server","subsystem":"transport","state":"accept_failed","error":"Too many open files (os error 24)","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":1628,"threadName":"rustfs-worker","threadId":"ThreadId(9)"} 2026/10/09 09:58:19 WARN Request failed, retrying attempt=4 backoff=745.097326ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures === NAME TestForceGCDuringPushOffersSweptObject/after_presence_check gc_races_test.go:387: unexpected error: context deadline exceeded {"timestamp":"2026-10-09T09:58:19.087694Z","level":"ERROR","message":"HTTP accept loop state changed","event":"http_accept_loop_state","component":"server","subsystem":"transport","state":"accept_failed","error":"Too many open files (os error 24)","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":1628,"threadName":"rustfs-worker","threadId":"ThreadId(9)"} === NAME TestForceGCDuringPushOffersSweptObject/before_pending_rows gc_races_test.go:387: unexpected error: context deadline exceeded --- FAIL: TestForceGCDuringPushOffersSweptObject (0.01s) --- FAIL: TestForceGCDuringPushOffersSweptObject/after_presence_check (12.85s) --- FAIL: TestForceGCDuringPushOffersSweptObject/before_pending_rows (12.62s) {"timestamp":"2026-10-09T09:58:19.181073Z","level":"ERROR","message":"HTTP accept loop state changed","event":"http_accept_loop_state","component":"server","subsystem":"transport","state":"accept_failed","error":"Too many open files (os error 24)","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":1628,"threadName":"rustfs-worker","threadId":"ThreadId(9)"} {"timestamp":"2026-10-09T09:58:19.30887Z","level":"ERROR","message":"HTTP accept loop state changed","event":"http_accept_loop_state","component":"server","subsystem":"transport","state":"accept_failed","error":"Too many open files (os error 24)","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":1628,"threadName":"rustfs-worker","threadId":"ThreadId(9)"} === NAME TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline timeout_test.go:74: unexpected error: context deadline exceeded --- FAIL: TestPendingClosureWriteTimeout (0.01s) --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s) --- PASS: TestPendingClosureWriteTimeout/empty (0.00s) --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s) --- FAIL: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (11.86s) {"timestamp":"2026-10-09T09:58:19.362912Z","level":"ERROR","message":"HTTP accept loop state changed","event":"http_accept_loop_state","component":"server","subsystem":"transport","state":"accept_failed","error":"Too many open files (os error 24)","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":1628,"threadName":"rustfs-worker","threadId":"ThreadId(9)"} === NAME TestPendingClosureFailureTracksEveryUpload/refuse_aborts=false multipart_cleanup_test.go:387: unexpected error: context deadline exceeded === NAME TestPendingClosureFailureTracksEveryUpload/refuse_aborts=true multipart_cleanup_test.go:387: unexpected error: context deadline exceeded --- FAIL: TestPendingClosureFailureTracksEveryUpload (0.02s) --- FAIL: TestPendingClosureFailureTracksEveryUpload/refuse_aborts=false (11.73s) --- FAIL: TestPendingClosureFailureTracksEveryUpload/refuse_aborts=true (11.36s) {"timestamp":"2026-10-09T09:58:19.378525Z","level":"ERROR","message":"HTTP accept loop state changed","event":"http_accept_loop_state","component":"server","subsystem":"transport","state":"accept_failed","error":"Too many open files (os error 24)","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":1628,"threadName":"rustfs-worker","threadId":"ThreadId(9)"} {"timestamp":"2026-10-09T09:58:19.44275Z","level":"ERROR","message":"HTTP accept loop state changed","event":"http_accept_loop_state","component":"server","subsystem":"transport","state":"accept_failed","error":"Too many open files (os error 24)","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":1628,"threadName":"rustfs-worker","threadId":"ThreadId(9)"} === NAME TestClientErrorHandling/InvalidStorePath client_errors_test.go:18: unexpected error: context deadline exceeded {"timestamp":"2026-10-09T09:58:19.498531Z","level":"ERROR","message":"HTTP accept loop state changed","event":"http_accept_loop_state","component":"server","subsystem":"transport","state":"accept_failed","error":"Too many open files (os error 24)","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":1628,"threadName":"rustfs-worker","threadId":"ThreadId(2)"} === NAME TestClientErrorHandling/InvalidAuthToken client_errors_test.go:44: unexpected error: context deadline exceeded {"timestamp":"2026-10-09T09:58:19.500409Z","level":"ERROR","message":"HTTP accept loop state changed","event":"http_accept_loop_state","component":"server","subsystem":"transport","state":"accept_failed","error":"Too many open files (os error 24)","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":1628,"threadName":"rustfs-worker","threadId":"ThreadId(2)"} === NAME TestPresentNotReportedWhileGCDeletesClosure/stale present_test.go:122: unexpected error: context deadline exceeded {"timestamp":"2026-10-09T09:58:19.553647Z","level":"ERROR","message":"HTTP accept loop state changed","event":"http_accept_loop_state","component":"server","subsystem":"transport","state":"accept_failed","error":"Too many open files (os error 24)","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":1628,"threadName":"rustfs-worker","threadId":"ThreadId(2)"} {"timestamp":"2026-10-09T09:58:19.706857Z","level":"ERROR","message":"HTTP accept loop state changed","event":"http_accept_loop_state","component":"server","subsystem":"transport","state":"accept_failed","error":"Too many open files (os error 24)","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":1628,"threadName":"rustfs-worker","threadId":"ThreadId(2)"} 2026/10/09 09:58:19 WARN Request failed, retrying attempt=5 backoff=1.545215406s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures {"timestamp":"2026-10-09T09:58:19.932769Z","level":"ERROR","message":"HTTP accept loop state changed","event":"http_accept_loop_state","component":"server","subsystem":"transport","state":"accept_failed","error":"Too many open files (os error 24)","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":1628,"threadName":"rustfs-worker","threadId":"ThreadId(2)"} {"timestamp":"2026-10-09T09:58:20.040717Z","level":"ERROR","message":"Scanner bucket cache load or revision lookup failed","event":"scanner_cache_persist_state","component":"scanner","subsystem":"io","bucket":"bucket3","cache_name":"bucket3/.usage-cache.bin","state":"load_or_revision_lookup_failed","error":"Io error: Too many open files (os error 24)","target":"rustfs::scanner::io","filename":"crates/scanner/src/scanner_io/io_cache.rs","line_number":988,"threadName":"rustfs-worker","threadId":"ThreadId(2)"} {"timestamp":"2026-10-09T09:58:20.534385Z","level":"ERROR","message":"HTTP accept loop state changed","event":"http_accept_loop_state","component":"server","subsystem":"transport","state":"accept_failed","error":"Too many open files (os error 24)","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":1628,"threadName":"rustfs-worker","threadId":"ThreadId(2)"} --- FAIL: TestClientErrorHandling (0.00s) --- FAIL: TestClientErrorHandling/InvalidStorePath (10.77s) --- FAIL: TestClientErrorHandling/InvalidAuthToken (10.70s) --- PASS: TestClientErrorHandling/ServerNotAvailable (12.61s) {"timestamp":"2026-10-09T09:58:21.445644Z","level":"ERROR","message":"HTTP accept loop state changed","event":"http_accept_loop_state","component":"server","subsystem":"transport","state":"accept_failed","error":"Too many open files (os error 24)","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":1628,"threadName":"rustfs-worker","threadId":"ThreadId(2)"} {"timestamp":"2026-10-09T09:58:21.772283Z","level":"ERROR","message":"HTTP accept loop state changed","event":"http_accept_loop_state","component":"server","subsystem":"transport","state":"accept_failed","error":"Too many open files (os error 24)","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":1628,"threadName":"rustfs-worker","threadId":"ThreadId(2)"} {"timestamp":"2026-10-09T09:58:21.805388Z","level":"ERROR","message":"HTTP accept loop state changed","event":"http_accept_loop_state","component":"server","subsystem":"transport","state":"accept_failed","error":"Too many open files (os error 24)","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":1628,"threadName":"rustfs-worker","threadId":"ThreadId(2)"} {"timestamp":"2026-10-09T09:58:21.837495Z","level":"ERROR","message":"HTTP accept loop state changed","event":"http_accept_loop_state","component":"server","subsystem":"transport","state":"accept_failed","error":"Too many open files (os error 24)","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":1628,"threadName":"rustfs-worker","threadId":"ThreadId(2)"} {"timestamp":"2026-10-09T09:58:22.159595Z","level":"ERROR","message":"HTTP accept loop state changed","event":"http_accept_loop_state","component":"server","subsystem":"transport","state":"accept_failed","error":"Too many open files (os error 24)","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":1628,"threadName":"rustfs-worker","threadId":"ThreadId(9)"} {"timestamp":"2026-10-09T09:58:22.461874Z","level":"ERROR","message":"HTTP accept loop state changed","event":"http_accept_loop_state","component":"server","subsystem":"transport","state":"accept_failed","error":"Too many open files (os error 24)","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":1628,"threadName":"rustfs-worker","threadId":"ThreadId(9)"} === NAME TestPresentNotReportedWhileGCDeletesClosure/fresh present_test.go:122: unexpected error: context deadline exceeded --- FAIL: TestPresentNotReportedWhileGCDeletesClosure (0.01s) --- FAIL: TestPresentNotReportedWhileGCDeletesClosure/stale (10.33s) --- FAIL: TestPresentNotReportedWhileGCDeletesClosure/fresh (10.04s) {"timestamp":"2026-10-09T09:58:22.559652Z","level":"ERROR","message":"HTTP accept loop state changed","event":"http_accept_loop_state","component":"server","subsystem":"transport","state":"accept_failed","error":"Too many open files (os error 24)","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":1628,"threadName":"rustfs-worker","threadId":"ThreadId(9)"} {"timestamp":"2026-10-09T09:58:22.574026Z","level":"ERROR","message":"Scanner bucket cache load or revision lookup failed","event":"scanner_cache_persist_state","component":"scanner","subsystem":"io","bucket":"bucket30","cache_name":"bucket30/.usage-cache.bin","state":"load_or_revision_lookup_failed","error":"Io error: Too many open files (os error 24)","target":"rustfs::scanner::io","filename":"crates/scanner/src/scanner_io/io_cache.rs","line_number":988,"threadName":"rustfs-worker","threadId":"ThreadId(9)"} {"timestamp":"2026-10-09T09:58:22.667896Z","level":"ERROR","message":"HTTP accept loop state changed","event":"http_accept_loop_state","component":"server","subsystem":"transport","state":"accept_failed","error":"Too many open files (os error 24)","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":1628,"threadName":"rustfs-worker","threadId":"ThreadId(2)"} {"timestamp":"2026-10-09T09:58:22.915968Z","level":"ERROR","message":"HTTP accept loop state changed","event":"http_accept_loop_state","component":"server","subsystem":"transport","state":"accept_failed","error":"Too many open files (os error 24)","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":1628,"threadName":"rustfs-worker","threadId":"ThreadId(6)"} {"timestamp":"2026-10-09T09:58:22.977968Z","level":"ERROR","message":"HTTP accept loop state changed","event":"http_accept_loop_state","component":"server","subsystem":"transport","state":"accept_failed","error":"Too many open files (os error 24)","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":1628,"threadName":"rustfs-worker","threadId":"ThreadId(6)"} === NAME TestGCEndsOnShutdown/before_the_run gc_shutdown_test.go:34: unexpected error: context deadline exceeded {"timestamp":"2026-10-09T09:58:23.27394Z","level":"ERROR","message":"HTTP accept loop state changed","event":"http_accept_loop_state","component":"server","subsystem":"transport","state":"accept_failed","error":"Too many open files (os error 24)","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":1628,"threadName":"rustfs-worker","threadId":"ThreadId(9)"} === NAME TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark gc_shutdown_test.go:34: unexpected error: context deadline exceeded {"timestamp":"2026-10-09T09:58:23.406369Z","level":"ERROR","message":"HTTP accept loop state changed","event":"http_accept_loop_state","component":"server","subsystem":"transport","state":"accept_failed","error":"Too many open files (os error 24)","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":1628,"threadName":"rustfs-worker","threadId":"ThreadId(9)"} {"timestamp":"2026-10-09T09:58:23.552169Z","level":"ERROR","message":"HTTP accept loop state changed","event":"http_accept_loop_state","component":"server","subsystem":"transport","state":"accept_failed","error":"Too many open files (os error 24)","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":1628,"threadName":"rustfs-worker","threadId":"ThreadId(9)"} === NAME TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete gc_shutdown_test.go:34: unexpected error: context deadline exceeded --- FAIL: TestGCEndsOnShutdown (0.02s) --- FAIL: TestGCEndsOnShutdown/before_the_run (10.10s) --- FAIL: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (10.08s) --- FAIL: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (10.15s) FAIL {"timestamp":"2026-10-09T09:58:23.772481Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:61549","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2354,"threadName":"rustfs-worker","threadId":"ThreadId(7)"} 2026-10-09 09:58:23.945 UTC [65329] LOG: received smart shutdown request 2026/10/09 09:58:33 INFO killed process group pgid=65329 2026-10-09 09:58:33.953 UTC [66253] FATAL: terminating connection due to unexpected postmaster exit 2026-10-09 09:58:33.953 UTC [66249] FATAL: terminating connection due to unexpected postmaster exit 2026-10-09 09:58:33.953 UTC [66267] FATAL: terminating connection due to unexpected postmaster exit 2026-10-09 09:58:33.953 UTC [66244] FATAL: terminating connection due to unexpected postmaster exit 2026-10-09 09:58:33.953 UTC [66243] FATAL: terminating connection due to unexpected postmaster exit 2026-10-09 09:58:33.953 UTC [66218] FATAL: terminating connection due to unexpected postmaster exit 2026-10-09 09:58:33.953 UTC [66216] FATAL: terminating connection due to unexpected postmaster exit 2026-10-09 09:58:33.953 UTC [66212] FATAL: terminating connection due to unexpected postmaster exit 2026-10-09 09:58:33.953 UTC [66187] FATAL: terminating connection due to unexpected postmaster exit 2026-10-09 09:58:33.956 UTC [66168] FATAL: terminating connection due to unexpected postmaster exit 2026-10-09 09:58:33.957 UTC [66156] FATAL: terminating connection due to unexpected postmaster exit 2026-10-09 09:58:33.961 UTC [66270] FATAL: terminating connection due to unexpected postmaster exit 2026/10/09 09:58:33 ERROR failed to wait for process error="signal: killed" 2026-10-09 09:58:33.953 UTC [66252] FATAL: terminating connection due to unexpected postmaster exit 2026-10-09 09:58:33.953 UTC [66248] FATAL: terminating connection due to unexpected postmaster exit 2026-10-09 09:58:33.953 UTC [66240] FATAL: terminating connection due to unexpected postmaster exit 2026-10-09 09:58:33.953 UTC [66211] FATAL: terminating connection due to unexpected postmaster exit 2026-10-09 09:58:33.953 UTC [66177] FATAL: terminating connection due to unexpected postmaster exit 2026-10-09 09:58:33.953 UTC [66175] FATAL: terminating connection due to unexpected postmaster exit 2026-10-09 09:58:33.962 UTC [66264] FATAL: terminating connection due to unexpected postmaster exit 2026-10-09 09:58:33.953 UTC [66254] FATAL: terminating connection due to unexpected postmaster exit 2026-10-09 09:58:33.953 UTC [66250] FATAL: terminating connection due to unexpected postmaster exit 2026-10-09 09:58:33.962 UTC [66261] FATAL: terminating connection due to unexpected postmaster exit