niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #437
· raw
1tribuchet: building on mac022Running client tests...3=== RUN TestDoServerRequestAttachesToken4=== PAUSE TestDoServerRequestAttachesToken5=== RUN TestUploadBuildLog_FileBodyReplayedOnRetry6=== PAUSE TestUploadBuildLog_FileBodyReplayedOnRetry7=== RUN TestRegisterUploadedObjectReusesConnections8=== PAUSE TestRegisterUploadedObjectReusesConnections9=== RUN TestRunGarbageCollection_FinishedOnAnotherReplica10=== PAUSE TestRunGarbageCollection_FinishedOnAnotherReplica11=== RUN TestRunGarbageCollection_NotFoundAfterLocalRun12=== PAUSE TestRunGarbageCollection_NotFoundAfterLocalRun13=== RUN TestCaseHackSuffix14=== PAUSE TestCaseHackSuffix15=== RUN TestFilterOversizedClosures16=== PAUSE TestFilterOversizedClosures17=== RUN TestPushPathsReportsOnlyUnuploadablePathsOfSkippedClosure18=== PAUSE TestPushPathsReportsOnlyUnuploadablePathsOfSkippedClosure19=== RUN TestUploadMultipart_PartsInParallel20=== PAUSE TestUploadMultipart_PartsInParallel21=== RUN TestUploadMultipart_FailedPartBufferNotReused22=== PAUSE TestUploadMultipart_FailedPartBufferNotReused23=== RUN TestUploadMultipart_ProducerErrorIsNotEOF24=== PAUSE TestUploadMultipart_ProducerErrorIsNotEOF25=== RUN TestPartSizeForNAR26=== PAUSE TestPartSizeForNAR27=== RUN TestUploadMultipart_SupersededByPeer28=== PAUSE TestUploadMultipart_SupersededByPeer29=== RUN TestDumpPathCaseHackMatchesNix30--- PASS: TestDumpPathCaseHackMatchesNix (0.21s)31=== RUN TestDumpPathCaseHackCollision32--- PASS: TestDumpPathCaseHackCollision (0.00s)33=== RUN TestSupersededNARStillUploadsListing34=== PAUSE TestSupersededNARStillUploadsListing35=== RUN TestTruncatedNARDumpIsNotCompleted36=== PAUSE TestTruncatedNARDumpIsNotCompleted37=== RUN TestDumpPathMatchesNix38=== PAUSE TestDumpPathMatchesNix39=== RUN TestDumpPathSingleFile40=== PAUSE TestDumpPathSingleFile41=== RUN TestDumpPathWriterError42=== PAUSE TestDumpPathWriterError43=== RUN TestDumpPathWriterErrorStopsReading44 nar_test.go:280: no /proc/self/io: open /proc/self/io: no such file or directory45--- SKIP: TestDumpPathWriterErrorStopsReading (0.60s)46=== RUN TestEncodeNixBase3247=== PAUSE TestEncodeNixBase3248=== RUN TestEncodeNixBase32WithRealHash49=== PAUSE TestEncodeNixBase32WithRealHash50=== RUN TestConvertHashToNix3251=== PAUSE TestConvertHashToNix3252=== RUN TestGetStorePathHash53=== PAUSE TestGetStorePathHash54=== RUN TestPathInfoHashCompatibility55=== PAUSE TestPathInfoHashCompatibility56=== RUN TestParsePathInfoJSON57=== PAUSE TestParsePathInfoJSON58=== RUN TestParsePathInfoJSONMultiplePaths59=== PAUSE TestParsePathInfoJSONMultiplePaths60=== RUN TestPathInfoCACompatibility61=== PAUSE TestPathInfoCACompatibility62=== RUN TestUploadPendingObjectsStopsStartingAfterFailure63--- PASS: TestUploadPendingObjectsStopsStartingAfterFailure (0.01s)64=== RUN TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent65=== PAUSE TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent66=== RUN TestCompletePendingClosure_NotFoundWithoutKey67=== PAUSE TestCompletePendingClosure_NotFoundWithoutKey68=== RUN TestRateLimiterFeedback69=== PAUSE TestRateLimiterFeedback70=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess71=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess72=== RUN TestRegisterUploadedObject_BoundedAgainstSilentServer73=== PAUSE TestRegisterUploadedObject_BoundedAgainstSilentServer74=== RUN TestResolveStorePath75=== PAUSE TestResolveStorePath76=== RUN TestDoWithRetry_BodyReplayedViaGetBody77=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody78=== RUN TestRetryTimeoutOutlastsMaxRetries79=== PAUSE TestRetryTimeoutOutlastsMaxRetries80=== RUN TestDoWithRetry_FinalResponseBodyReadable81=== PAUSE TestDoWithRetry_FinalResponseBodyReadable82=== RUN TestShellSplit83=== PAUSE TestShellSplit84=== RUN TestShellSplitErrors85=== PAUSE TestShellSplitErrors86=== RUN TestStreamPushReportsEveryPath87=== PAUSE TestStreamPushReportsEveryPath88=== RUN TestStreamPushBatchesUnderLoad89=== PAUSE TestStreamPushBatchesUnderLoad90=== RUN TestStreamPushIsolatesFailures91=== PAUSE TestStreamPushIsolatesFailures92=== RUN TestStreamPushGivesUpOnDeadServer93=== PAUSE TestStreamPushGivesUpOnDeadServer94=== RUN TestStreamPushRequestLine95=== PAUSE TestStreamPushRequestLine96=== RUN TestStreamPushReportsSignatures97=== PAUSE TestStreamPushReportsSignatures98=== RUN TestStreamPushReportsSkippedPaths99=== PAUSE TestStreamPushReportsSkippedPaths100=== RUN TestClientSignaturesByStorePath101=== PAUSE TestClientSignaturesByStorePath102=== RUN TestStreamPushStopsWhenCanceled103=== PAUSE TestStreamPushStopsWhenCanceled104=== RUN TestStreamPushStopsOnCancel105=== PAUSE TestStreamPushStopsOnCancel106=== RUN TestStreamPushStartsNothingOnSlotFreedByCancel107=== PAUSE TestStreamPushStartsNothingOnSlotFreedByCancel108=== RUN TestSetClientTLS109=== PAUSE TestSetClientTLS110=== RUN TestSetClientTLSDoesNotMutateDefaultTransport111=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport112=== RUN TestSetClientTLSErrors113=== PAUSE TestSetClientTLSErrors114=== RUN TestStaticToken115=== PAUSE TestStaticToken116=== RUN TestFileTokenReadsAndCaches117=== PAUSE TestFileTokenReadsAndCaches118=== RUN TestFileTokenMissing119=== PAUSE TestFileTokenMissing120=== RUN TestFileTokenEmpty121=== PAUSE TestFileTokenEmpty122=== RUN TestScriptTokenNoExpiryRerunsEveryCall123=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall124=== RUN TestScriptTokenCachesUntilRefresh125=== PAUSE TestScriptTokenCachesUntilRefresh126=== RUN TestScriptTokenEmptyToken127=== PAUSE TestScriptTokenEmptyToken128=== RUN TestScriptTokenBadJSON129=== PAUSE TestScriptTokenBadJSON130=== RUN TestScriptTokenScriptFails131=== PAUSE TestScriptTokenScriptFails132=== RUN TestScriptTokenEmptyCommand133=== PAUSE TestScriptTokenEmptyCommand134=== RUN TestScriptTokenDoesNotWaitForItsChildren135=== PAUSE TestScriptTokenDoesNotWaitForItsChildren136=== CONT TestDoServerRequestAttachesToken137=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer138=== CONT TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent139=== CONT TestStreamPushStopsOnCancel140=== CONT TestScriptTokenDoesNotWaitForItsChildren141=== RUN TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/committed_earlier142=== RUN TestScriptTokenDoesNotWaitForItsChildren/cancelled_while_a_child_runs143=== PAUSE TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/committed_earlier144=== RUN TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/cleaned_up145=== CONT TestScriptTokenEmptyCommand146=== CONT TestScriptTokenScriptFails147=== CONT TestScriptTokenBadJSON148=== CONT TestScriptTokenCachesUntilRefresh149=== CONT TestDumpPathWriterError150=== CONT TestScriptTokenEmptyToken151=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess152=== CONT TestFileTokenEmpty153=== CONT TestGetStorePathHash154=== RUN TestGetStorePathHash/valid_store_path155=== CONT TestStaticToken156=== CONT TestFileTokenReadsAndCaches157=== CONT TestScriptTokenNoExpiryRerunsEveryCall158=== CONT TestSetClientTLSErrors159=== CONT TestEncodeNixBase32WithRealHash160=== CONT TestSetClientTLSDoesNotMutateDefaultTransport161=== CONT TestEncodeNixBase32162=== CONT TestStreamPushStartsNothingOnSlotFreedByCancel163=== CONT TestDumpPathSingleFile164=== RUN TestStreamPushStopsOnCancel/waiting_for_input165=== PAUSE TestScriptTokenDoesNotWaitForItsChildren/cancelled_while_a_child_runs166=== CONT TestPathInfoCACompatibility167=== RUN TestPathInfoCACompatibility/null_ca_field168=== PAUSE TestPathInfoCACompatibility/null_ca_field169=== RUN TestPathInfoCACompatibility/old_string_format_-_text170=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text171=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive172=== CONT TestPathInfoHashCompatibility173=== PAUSE TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/cleaned_up174=== RUN TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_committed_earlier175=== CONT TestPushPathsReportsOnlyUnuploadablePathsOfSkippedClosure176--- PASS: TestScriptTokenEmptyCommand (0.00s)177=== CONT TestConvertHashToNix32178=== RUN TestConvertHashToNix32/SRI_format_to_Nix32179=== PAUSE TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_committed_earlier180=== CONT TestFileTokenMissing181=== RUN TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_cleaned_up,_first_root_committed_by_another_client182=== PAUSE TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_cleaned_up,_first_root_committed_by_another_client183=== RUN TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_cleaned_up,_last_root_committed_by_another_client184=== PAUSE TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_cleaned_up,_last_root_committed_by_another_client185--- PASS: TestStaticToken (0.00s)186=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica187--- PASS: TestDoServerRequestAttachesToken (0.01s)188=== PAUSE TestStreamPushStopsOnCancel/waiting_for_input189=== RUN TestScriptTokenDoesNotWaitForItsChildren/child_left_holding_stdout190=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive191=== CONT TestCompletePendingClosure_NotFoundWithoutKey192=== RUN TestEncodeNixBase32/test_string_hash193=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)194=== CONT TestRateLimiterFeedback195=== CONT TestDumpPathMatchesNix196=== RUN TestSetClientTLSErrors/missing_cert_file197=== CONT TestParsePathInfoJSONMultiplePaths198=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32199=== PAUSE TestGetStorePathHash/valid_store_path200=== RUN TestPathInfoCACompatibility/new_structured_format_-_text201=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text202=== RUN TestStreamPushStopsOnCancel/partial_batch_waiting_for_a_slot203--- PASS: TestEncodeNixBase32WithRealHash (0.00s)204=== PAUSE TestScriptTokenDoesNotWaitForItsChildren/child_left_holding_stdout205=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method206=== PAUSE TestStreamPushStopsOnCancel/partial_batch_waiting_for_a_slot207=== RUN TestStreamPushStopsOnCancel/input_closed,_last_batch_waiting_for_a_slot208=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method209=== CONT TestSupersededNARStillUploadsListing210=== PAUSE TestStreamPushStopsOnCancel/input_closed,_last_batch_waiting_for_a_slot211=== RUN TestStreamPushStopsOnCancel/full_batch_waiting_for_a_slot212=== PAUSE TestStreamPushStopsOnCancel/full_batch_waiting_for_a_slot213=== RUN TestRateLimiterFeedback/429_enables_limiter214=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)215=== PAUSE TestSetClientTLSErrors/missing_cert_file216=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths217=== PAUSE TestRateLimiterFeedback/429_enables_limiter218=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths219=== RUN TestRateLimiterFeedback/503_enables_limiter220--- PASS: TestScriptTokenScriptFails (0.01s)221--- PASS: TestFileTokenEmpty (0.01s)222=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths223=== RUN TestConvertHashToNix32/already_Nix32_format224=== CONT TestTruncatedNARDumpIsNotCompleted225=== PAUSE TestEncodeNixBase32/test_string_hash226=== CONT TestFilterOversizedClosures227=== RUN TestFilterOversizedClosures/no_limit_keeps_everything228=== RUN TestStreamPushStopsOnCancel/request_line_waiting_for_a_slot229=== PAUSE TestStreamPushStopsOnCancel/request_line_waiting_for_a_slot230=== RUN TestSupersededNARStillUploadsListing/small_NAR231=== PAUSE TestSupersededNARStillUploadsListing/small_NAR232=== RUN TestSupersededNARStillUploadsListing/dump_cut_short233=== RUN TestStreamPushStopsOnCancel/lines_read_but_not_taken234=== PAUSE TestStreamPushStopsOnCancel/lines_read_but_not_taken235=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon236=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon237=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI238=== PAUSE TestSupersededNARStillUploadsListing/dump_cut_short239=== RUN TestSupersededNARStillUploadsListing/listing_upload_fails240=== PAUSE TestSupersededNARStillUploadsListing/listing_upload_fails241=== RUN TestSetClientTLSErrors/missing_key_file242=== PAUSE TestSetClientTLSErrors/missing_key_file243=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths244=== CONT TestPartSizeForNAR245=== PAUSE TestConvertHashToNix32/already_Nix32_format246=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun247=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything248=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped249=== PAUSE TestRateLimiterFeedback/503_enables_limiter250=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI251=== RUN TestConvertHashToNix32/invalid_format252=== PAUSE TestConvertHashToNix32/invalid_format253=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512254=== RUN TestPartSizeForNAR/zero_stays_at_minimum255=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum256=== RUN TestPartSizeForNAR/small_stays_at_minimum257=== PAUSE TestPartSizeForNAR/small_stays_at_minimum258=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512259=== RUN TestSetClientTLSErrors/missing_ca_file260=== CONT TestUploadMultipart_FailedPartBufferNotReused261--- PASS: TestFileTokenReadsAndCaches (0.01s)262--- PASS: TestCompletePendingClosure_NotFoundWithoutKey (0.01s)263=== PAUSE TestSetClientTLSErrors/missing_ca_file264=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry265--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.01s)266=== RUN TestSetClientTLSErrors/invalid_ca_file267=== PAUSE TestSetClientTLSErrors/invalid_ca_file268--- PASS: TestFileTokenMissing (0.01s)269=== CONT TestStreamPushIsolatesFailures270--- PASS: TestScriptTokenEmptyToken (0.03s)271--- PASS: TestScriptTokenBadJSON (0.03s)272=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum273=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum274=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts275=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts276=== RUN TestPartSizeForNAR/1_TiB277=== CONT TestClientSignaturesByStorePath278=== PAUSE TestPartSizeForNAR/1_TiB279--- PASS: TestStreamPushIsolatesFailures (0.00s)280--- PASS: TestClientSignaturesByStorePath (0.00s)281=== CONT TestUploadMultipart_ProducerErrorIsNotEOF282=== CONT TestCaseHackSuffix283=== RUN TestGetStorePathHash/basename_without_hyphen_should_error284=== RUN TestEncodeNixBase32/empty_input285=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter286=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped287=== CONT TestUploadMultipart_SupersededByPeer288=== RUN TestPartSizeForNAR/5_TiB_S3_max_object289=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object290=== RUN TestUploadMultipart_SupersededByPeer/exists291=== RUN TestFilterOversizedClosures/all_closures_skipped292=== PAUSE TestUploadMultipart_SupersededByPeer/exists293=== PAUSE TestFilterOversizedClosures/all_closures_skipped294=== RUN TestUploadMultipart_SupersededByPeer/missing295=== RUN TestPartSizeForNAR/capped_at_5_GiB296=== PAUSE TestPartSizeForNAR/capped_at_5_GiB297=== CONT TestStreamPushGivesUpOnDeadServer298=== CONT TestStreamPushReportsSignatures299=== PAUSE TestUploadMultipart_SupersededByPeer/missing300=== PAUSE TestEncodeNixBase32/empty_input301=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter302=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter303=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter304=== CONT TestStreamPushStopsWhenCanceled305--- PASS: TestStreamPushStopsWhenCanceled (0.00s)306=== CONT TestRegisterUploadedObjectReusesConnections307--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.02s)308=== CONT TestStreamPushReportsSkippedPaths309--- PASS: TestStreamPushReportsSkippedPaths (0.00s)310=== CONT TestShellSplitErrors311--- PASS: TestShellSplitErrors (0.00s)312=== CONT TestRetryTimeoutOutlastsMaxRetries313=== CONT TestShellSplit314--- PASS: TestShellSplit (0.00s)315=== CONT TestDoWithRetry_FinalResponseBodyReadable316=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error317=== RUN TestUploadMultipart_ProducerErrorIsNotEOF/short_read_inside_a_part318=== CONT TestStreamPushRequestLine319=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error320--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)321=== CONT TestStreamPushBatchesUnderLoad322=== RUN TestStreamPushBatchesUnderLoad/together323=== PAUSE TestStreamPushBatchesUnderLoad/together324=== PAUSE TestUploadMultipart_ProducerErrorIsNotEOF/short_read_inside_a_part325=== RUN TestUploadMultipart_ProducerErrorIsNotEOF/empty_read_on_a_part_boundary326=== PAUSE TestUploadMultipart_ProducerErrorIsNotEOF/empty_read_on_a_part_boundary327=== RUN TestStreamPushBatchesUnderLoad/one_at_a_time328=== PAUSE TestStreamPushBatchesUnderLoad/one_at_a_time329=== CONT TestStreamPushReportsEveryPath330=== CONT TestSetClientTLS331--- PASS: TestStreamPushReportsEveryPath (0.00s)332=== CONT TestDoWithRetry_BodyReplayedViaGetBody333=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error334=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error335=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error336=== CONT TestParsePathInfoJSON337=== RUN TestParsePathInfoJSON/Nix_format338=== PAUSE TestParsePathInfoJSON/Nix_format339=== RUN TestParsePathInfoJSON/Lix_format340=== PAUSE TestParsePathInfoJSON/Lix_format341=== RUN TestParsePathInfoJSON/empty_input342=== PAUSE TestParsePathInfoJSON/empty_input343=== RUN TestParsePathInfoJSON/whitespace_only344=== PAUSE TestParsePathInfoJSON/whitespace_only345=== RUN TestParsePathInfoJSON/invalid_JSON346=== PAUSE TestParsePathInfoJSON/invalid_JSON347=== CONT TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_committed_earlier348=== CONT TestResolveStorePath349=== CONT TestUploadMultipart_PartsInParallel350--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.01s)351=== CONT TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_cleaned_up,_last_root_committed_by_another_client352--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.01s)353=== CONT TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_cleaned_up,_first_root_committed_by_another_client354--- PASS: TestStreamPushReportsSignatures (0.01s)355=== CONT TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/cleaned_up356--- PASS: TestResolveStorePath (0.01s)357=== CONT TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/committed_earlier358=== CONT TestScriptTokenDoesNotWaitForItsChildren/cancelled_while_a_child_runs359=== CONT TestScriptTokenDoesNotWaitForItsChildren/child_left_holding_stdout360--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.07s)361=== CONT TestPathInfoCACompatibility/old_string_format_-_text362--- PASS: TestScriptTokenCachesUntilRefresh (0.08s)363=== CONT TestPathInfoCACompatibility/new_structured_format_-_text364=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method365=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive366=== CONT TestPathInfoCACompatibility/null_ca_field367--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.05s)368=== CONT TestStreamPushStopsOnCancel/waiting_for_input369--- PASS: TestPathInfoCACompatibility (0.01s)370 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)371 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)372 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)373 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.01s)374 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)375=== CONT TestSupersededNARStillUploadsListing/small_NAR376=== CONT TestSupersededNARStillUploadsListing/listing_upload_fails377=== CONT TestStreamPushStopsOnCancel/input_closed,_last_batch_waiting_for_a_slot378=== RUN TestSetClientTLS/rejects_connection_without_client_cert379=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert380=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA381=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA382=== RUN TestSetClientTLS/preserves_debug_logging_transport383=== PAUSE TestSetClientTLS/preserves_debug_logging_transport384=== CONT TestSupersededNARStillUploadsListing/dump_cut_short385=== CONT TestStreamPushStopsOnCancel/lines_read_but_not_taken386=== CONT TestStreamPushStopsOnCancel/request_line_waiting_for_a_slot387--- PASS: TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent (0.02s)388 --- PASS: TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_cleaned_up,_first_root_committed_by_another_client (0.02s)389 --- PASS: TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/cleaned_up (0.03s)390 --- PASS: TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/committed_earlier (0.04s)391 --- PASS: TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_committed_earlier (0.05s)392 --- PASS: TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_cleaned_up,_last_root_committed_by_another_client (0.05s)393--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.08s)394=== CONT TestStreamPushStopsOnCancel/partial_batch_waiting_for_a_slot395=== CONT TestStreamPushStopsOnCancel/full_batch_waiting_for_a_slot396=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths397=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths398--- PASS: TestParsePathInfoJSONMultiplePaths (0.01s)399 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)400 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)401=== CONT TestConvertHashToNix32/SRI_format_to_Nix32402=== CONT TestConvertHashToNix32/already_Nix32_format403=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon404=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512405=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI406=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)407--- PASS: TestPathInfoHashCompatibility (0.02s)408 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)409 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)410 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)411 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)412=== CONT TestSetClientTLSErrors/missing_cert_file413=== CONT TestSetClientTLSErrors/invalid_ca_file414=== CONT TestSetClientTLSErrors/missing_key_file415=== CONT TestSetClientTLSErrors/missing_ca_file416=== CONT TestConvertHashToNix32/invalid_format417--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.11s)418=== CONT TestPartSizeForNAR/5_TiB_S3_max_object419=== CONT TestPartSizeForNAR/1_TiB420=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts421=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum422=== CONT TestPartSizeForNAR/zero_stays_at_minimum423=== CONT TestUploadMultipart_SupersededByPeer/exists424=== CONT TestPartSizeForNAR/small_stays_at_minimum425=== CONT TestEncodeNixBase32/empty_input426=== CONT TestEncodeNixBase32/test_string_hash427=== CONT TestUploadMultipart_SupersededByPeer/missing428--- PASS: TestEncodeNixBase32 (0.03s)429 --- PASS: TestEncodeNixBase32/empty_input (0.00s)430 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)431=== CONT TestPartSizeForNAR/capped_at_5_GiB432--- PASS: TestSetClientTLSErrors (0.03s)433 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)434 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)435 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)436 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)437--- PASS: TestDumpPathSingleFile (0.15s)438=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter439=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter440--- PASS: TestConvertHashToNix32 (0.02s)441 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)442 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)443 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)444=== CONT TestRateLimiterFeedback/503_enables_limiter445=== CONT TestRateLimiterFeedback/429_enables_limiter446--- PASS: TestPartSizeForNAR (0.00s)447 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)448 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)449 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)450 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)451 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)452 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)453 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)454=== CONT TestUploadMultipart_ProducerErrorIsNotEOF/short_read_inside_a_part455=== CONT TestStreamPushBatchesUnderLoad/together456=== CONT TestUploadMultipart_ProducerErrorIsNotEOF/empty_read_on_a_part_boundary457=== CONT TestStreamPushBatchesUnderLoad/one_at_a_time458--- PASS: TestStreamPushBatchesUnderLoad (0.00s)459 --- PASS: TestStreamPushBatchesUnderLoad/together (0.00s)460 --- PASS: TestStreamPushBatchesUnderLoad/one_at_a_time (0.00s)461=== CONT TestGetStorePathHash/basename_without_hyphen_should_error462=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error463=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error464=== CONT TestGetStorePathHash/valid_store_path465=== CONT TestParsePathInfoJSON/whitespace_only466=== CONT TestParsePathInfoJSON/invalid_JSON467=== CONT TestParsePathInfoJSON/empty_input468=== CONT TestParsePathInfoJSON/Lix_format469=== CONT TestParsePathInfoJSON/Nix_format470=== CONT TestFilterOversizedClosures/no_limit_keeps_everything471--- PASS: TestParsePathInfoJSON (0.00s)472 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)473 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)474 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)475 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)476 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)477=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped478=== CONT TestFilterOversizedClosures/all_closures_skipped479--- PASS: TestFilterOversizedClosures (0.01s)480 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)481 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)482 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)483=== CONT TestSetClientTLS/rejects_connection_without_client_cert484=== CONT TestSetClientTLS/preserves_debug_logging_transport485--- PASS: TestGetStorePathHash (0.04s)486 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)487 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)488 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)489 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.01s)490--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)491 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.01s)492 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.03s)493=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA494--- PASS: TestRateLimiterFeedback (0.02s)495 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)496 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.01s)497 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.02s)498 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.01s)499--- PASS: TestStreamPushStopsOnCancel (0.03s)500 --- PASS: TestStreamPushStopsOnCancel/waiting_for_input (0.06s)501 --- PASS: TestStreamPushStopsOnCancel/lines_read_but_not_taken (0.06s)502 --- PASS: TestStreamPushStopsOnCancel/request_line_waiting_for_a_slot (0.06s)503 --- PASS: TestStreamPushStopsOnCancel/input_closed,_last_batch_waiting_for_a_slot (0.06s)504 --- PASS: TestStreamPushStopsOnCancel/partial_batch_waiting_for_a_slot (0.05s)505 --- PASS: TestStreamPushStopsOnCancel/full_batch_waiting_for_a_slot (0.05s)506--- PASS: TestDumpPathWriterError (0.21s)507--- PASS: TestStreamPushRequestLine (0.18s)508--- PASS: TestCaseHackSuffix (0.24s)509--- PASS: TestSetClientTLS (0.09s)510 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.02s)511 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.05s)512 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.08s)513--- PASS: TestUploadMultipart_ProducerErrorIsNotEOF (0.00s)514 --- PASS: TestUploadMultipart_ProducerErrorIsNotEOF/short_read_inside_a_part (0.08s)515 --- PASS: TestUploadMultipart_ProducerErrorIsNotEOF/empty_read_on_a_part_boundary (0.13s)516--- PASS: TestStreamPushStartsNothingOnSlotFreedByCancel (0.29s)517--- PASS: TestDumpPathMatchesNix (0.30s)518--- PASS: TestPushPathsReportsOnlyUnuploadablePathsOfSkippedClosure (0.40s)519--- PASS: TestRegisterUploadedObjectReusesConnections (0.48s)520--- PASS: TestTruncatedNARDumpIsNotCompleted (0.77s)521--- PASS: TestUploadMultipart_FailedPartBufferNotReused (0.77s)522--- PASS: TestUploadMultipart_PartsInParallel (0.87s)523--- PASS: TestSupersededNARStillUploadsListing (0.01s)524 --- PASS: TestSupersededNARStillUploadsListing/small_NAR (0.06s)525 --- PASS: TestSupersededNARStillUploadsListing/listing_upload_fails (0.07s)526 --- PASS: TestSupersededNARStillUploadsListing/dump_cut_short (0.82s)527--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (1.00s)528--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.01s)529--- PASS: TestScriptTokenDoesNotWaitForItsChildren (0.02s)530 --- PASS: TestScriptTokenDoesNotWaitForItsChildren/child_left_holding_stdout (2.05s)531 --- PASS: TestScriptTokenDoesNotWaitForItsChildren/cancelled_while_a_child_runs (2.21s)532PASS533Running server tests...534The files belonging to this database system will be owned by user "_tribuchetbld6".535This user must also own the server process.536537The database cluster will be initialized with locale "C".538The default database encoding has accordingly been set to "SQL_ASCII".539The default text search configuration will be set to "english".540541Data page checksums are enabled.542543creating directory /private/var/tb/6/scratch/bedec206597db7e3/build/postgres1709347936/data ... ok544creating subdirectories ... ok545selecting dynamic shared memory implementation ... posix546selecting default "max_connections" ... 100547selecting default "shared_buffers" ... 128MB548selecting default time zone ... UTC549creating configuration files ... ok550running bootstrap script ... ok551performing post-bootstrap initialization ... ok552syncing data to disk ... ok553554initdb: warning: enabling "trust" authentication for local connections555initdb: 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.556557Success. You can now start the database server using:558559 pg_ctl -D /private/var/tb/6/scratch/bedec206597db7e3/build/postgres1709347936/data -l logfile start5605612026-10-26 22:36:10.753 UTC [29883] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit5622026-10-26 22:36:10.753 UTC [29883] LOG: listening on Unix socket "/private/var/tb/6/scratch/bedec206597db7e3/build/postgres1709347936/.s.PGSQL.5432"5632026-10-26 22:36:10.756 UTC [29890] LOG: database system was shut down at 2026-10-26 22:36:10 UTC5642026-10-26 22:36:10.757 UTC [29883] LOG: database system is ready to accept connections565/private/var/tb/6/scratch/bedec206597db7e3/build/postgres1709347936:5432 - accepting connections566{"timestamp":"2026-10-26T22:36:13.032581Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"a60b2eb9-fa81-4be5-8a01-ef9c0ab357b2","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":0,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":502,"threadName":"rustfs-worker","threadId":"ThreadId(8)"}567{"timestamp":"2026-10-26T22:36:13.136933Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"64b3d50d-07a6-472b-bae4-66a78c05c8ab","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":0,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":502,"threadName":"rustfs-worker","threadId":"ThreadId(2)"}568=== RUN TestService_AuthMiddleware569=== PAUSE TestService_AuthMiddleware570=== RUN TestService_AuthMiddleware_MTLSProxyHeader571=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader572=== RUN TestService_AuthMiddleware_MTLSBoundSubjects573=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects574=== RUN TestService_ReadAuthMiddleware575=== PAUSE TestService_ReadAuthMiddleware576=== RUN TestService_AuthMiddleware_OIDC577=== PAUSE TestService_AuthMiddleware_OIDC578=== RUN TestService_RequireScope_OIDC579=== PAUSE TestService_RequireScope_OIDC580=== RUN TestService_ReadScope_PublicByDefault581=== PAUSE TestService_ReadScope_PublicByDefault582=== RUN TestCacheConfigHandler583=== PAUSE TestCacheConfigHandler584=== RUN TestCacheStatsHandler585=== PAUSE TestCacheStatsHandler586=== RUN TestClientCADerivations587=== PAUSE TestClientCADerivations588=== RUN TestClientErrorHandling589=== PAUSE TestClientErrorHandling590=== RUN TestClientIntegration591=== PAUSE TestClientIntegration592=== RUN TestClientMultipleUploads593=== PAUSE TestClientMultipleUploads594=== RUN TestClientWithDependencies595=== PAUSE TestClientWithDependencies596=== RUN TestClientSharedPathCommittedMidPush597=== PAUSE TestClientSharedPathCommittedMidPush598=== RUN TestPinProtectsFromGC599=== PAUSE TestPinProtectsFromGC600=== RUN TestClientPushesUseOnePush601=== PAUSE TestClientPushesUseOnePush602=== RUN TestClientFallsBackToClosures603=== PAUSE TestClientFallsBackToClosures604=== RUN TestDeleteClosuresRacingPins605=== PAUSE TestDeleteClosuresRacingPins606=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock607=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock608=== RUN TestResolveDBConnectionString609=== PAUSE TestResolveDBConnectionString610=== RUN TestConnectWaitsForAPeerMigration611=== PAUSE TestConnectWaitsForAPeerMigration612=== RUN TestConnectSerialisesConcurrentMigrations613=== PAUSE TestConnectSerialisesConcurrentMigrations614=== RUN TestLeadElectsOneAndHandsOver615=== PAUSE TestLeadElectsOneAndHandsOver616=== RUN TestLeadIncumbentWinsAfterRestart6172026/10/26 22:36:13 INFO lead: acquired remote=192.0.2.1:12346182026/10/26 22:36:14 INFO lead: released remote=192.0.2.1:12346192026/10/26 22:36:14 INFO lead: acquired remote=192.0.2.1:12346202026/10/26 22:36:15 INFO lead: released remote=192.0.2.1:1234621--- PASS: TestLeadIncumbentWinsAfterRestart (2.15s)622=== RUN TestLeadIncumbentAnnouncesAtOnce623=== PAUSE TestLeadIncumbentAnnouncesAtOnce624=== RUN TestLeadEndsOnShutdown625=== PAUSE TestLeadEndsOnShutdown626=== RUN TestLeadEndsWhenItsConnectionHangs6272026/10/26 22:36:15 INFO lead: acquired remote=192.0.2.1:12346282026-10-26 22:36:16.946 UTC [29957] FATAL: terminating connection due to administrator command6292026/10/26 22:36:17 INFO lead: acquired remote=192.0.2.1:12346302026/10/26 22:36:18 WARN lead: lock connection lost error="timeout: context deadline exceeded"6312026/10/26 22:36:18 INFO lead: released remote=192.0.2.1:12346322026/10/26 22:36:18 INFO lead: released remote=192.0.2.1:1234633--- PASS: TestLeadEndsWhenItsConnectionHangs (2.95s)634=== RUN TestGCAdvisoryLockBlocksConcurrentRun635=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun636=== RUN TestGCBugBareHashReferences637=== PAUSE TestGCBugBareHashReferences638=== RUN TestGCMetrics639=== PAUSE TestGCMetrics640=== RUN TestPushDedupSurvivesConcurrentGC641=== PAUSE TestPushDedupSurvivesConcurrentGC642=== RUN TestDeduplicatedObjectsRecordedAsPending643=== PAUSE TestDeduplicatedObjectsRecordedAsPending644=== RUN TestGCSweepSkipsPendingObjects645=== PAUSE TestGCSweepSkipsPendingObjects646=== RUN TestTombstonedObjectOfferedWithoutWaiting647=== PAUSE TestTombstonedObjectOfferedWithoutWaiting648=== RUN TestGCSweepDeliversEachKeyOnce649=== PAUSE TestGCSweepDeliversEachKeyOnce650=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection651=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection652=== RUN TestForceGCDuringPushOffersSweptObject653=== PAUSE TestForceGCDuringPushOffersSweptObject654=== RUN TestFailedS3DeleteKeepsTombstone655=== PAUSE TestFailedS3DeleteKeepsTombstone656=== RUN TestSweepSkipsRowsLockedByPush657=== PAUSE TestSweepSkipsRowsLockedByPush658=== RUN TestRegisterCompletedObjectNeedsPendingRow659=== PAUSE TestRegisterCompletedObjectNeedsPendingRow660=== RUN TestGetExistingObjectsLocksRows661=== PAUSE TestGetExistingObjectsLocksRows662=== RUN TestSweepRechecksPendingAfterLocking663=== PAUSE TestSweepRechecksPendingAfterLocking664=== RUN TestPushWaitsForSweepHoldingRow665=== PAUSE TestPushWaitsForSweepHoldingRow666=== RUN TestCommitRacingPendingCleanupKeepsObjects667=== PAUSE TestCommitRacingPendingCleanupKeepsObjects668=== RUN TestGCEndsOnShutdown669=== PAUSE TestGCEndsOnShutdown670=== RUN TestGCTaskStore_StartNew671=== PAUSE TestGCTaskStore_StartNew672=== RUN TestGCTaskStore_DeduplicateSameParams673=== PAUSE TestGCTaskStore_DeduplicateSameParams674=== RUN TestGCTaskStore_ConflictDifferentParams675=== PAUSE TestGCTaskStore_ConflictDifferentParams676=== RUN TestGCTaskStore_GetEmpty677=== PAUSE TestGCTaskStore_GetEmpty678=== RUN TestGCTaskStore_GetReturnsLatest679=== PAUSE TestGCTaskStore_GetReturnsLatest680=== RUN TestGCTaskStore_CompletedAllowsNewTask681=== PAUSE TestGCTaskStore_CompletedAllowsNewTask682=== RUN TestGCTaskStore_PhaseUpdates683=== PAUSE TestGCTaskStore_PhaseUpdates684=== RUN TestGCTaskStore_Fail685=== PAUSE TestGCTaskStore_Fail686=== RUN TestGracefulShutdownDrainsInflight687=== PAUSE TestGracefulShutdownDrainsInflight688=== RUN TestService_healthCheckHandler689=== PAUSE TestService_healthCheckHandler690=== RUN TestService_readinessHandler691=== PAUSE TestService_readinessHandler692=== RUN TestGenerateLandingPage693=== PAUSE TestGenerateLandingPage694=== RUN TestChildrenInheritRaisedFileLimit695=== PAUSE TestChildrenInheritRaisedFileLimit696=== RUN TestCacheConfigHandlerMaxNarSize697=== PAUSE TestCacheConfigHandlerMaxNarSize698=== RUN TestCreatePendingClosureRejectsOversizedNAR699=== PAUSE TestCreatePendingClosureRejectsOversizedNAR700=== RUN TestNARDeduplicationMetadataUploadBug701=== PAUSE TestNARDeduplicationMetadataUploadBug702=== RUN TestMetricsInventory703=== PAUSE TestMetricsInventory704=== RUN TestMetricsCommit705=== PAUSE TestMetricsCommit706=== RUN TestService_NativeMTLS707=== PAUSE TestService_NativeMTLS708=== RUN TestServerTLSConfig709=== PAUSE TestServerTLSConfig710=== RUN TestMultipartCleanup711=== PAUSE TestMultipartCleanup712=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded713=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded714=== RUN TestPendingCleanupUsesOneCutoff715=== PAUSE TestPendingCleanupUsesOneCutoff716=== RUN TestPendingClosureFailureTracksEveryUpload717=== PAUSE TestPendingClosureFailureTracksEveryUpload718=== RUN TestPendingClosureFailureAbortsItsUploads719=== PAUSE TestPendingClosureFailureAbortsItsUploads720=== RUN TestObjectStatsTrigger721=== PAUSE TestObjectStatsTrigger722=== RUN TestObjectStatsUpdatedOncePerCommit723=== PAUSE TestObjectStatsUpdatedOncePerCommit724=== RUN TestReconnectLeavesObjectsUnlocked725=== PAUSE TestReconnectLeavesObjectsUnlocked726=== RUN TestOrphanedObjectsGC727=== PAUSE TestOrphanedObjectsGC728=== RUN TestOrphanedObjectsGCStressTest729=== PAUSE TestOrphanedObjectsGCStressTest730=== RUN TestCreatePin_ReservedPins731=== PAUSE TestCreatePin_ReservedPins732=== RUN TestConcurrentPinUpdatesAgree733=== PAUSE TestConcurrentPinUpdatesAgree734=== RUN TestCreatePinRejectsBadInput735=== PAUSE TestCreatePinRejectsBadInput736=== RUN TestDeletePinKeepsRowWhenS3Fails737=== PAUSE TestDeletePinKeepsRowWhenS3Fails738=== RUN TestPresentReportsOnlyClosureRoots739=== PAUSE TestPresentReportsOnlyClosureRoots740=== RUN TestPresentRefreshesOnlyStaleClosures741=== PAUSE TestPresentRefreshesOnlyStaleClosures742=== RUN TestPresentNotReportedWhileGCDeletesClosure743=== PAUSE TestPresentNotReportedWhileGCDeletesClosure744=== RUN TestParseSingleRange745=== PAUSE TestParseSingleRange746=== RUN TestProxyHeadersOnlyTrustedOnSocket7472026/10/26 22:36:18 INFO Starting HTTP server address=127.0.0.1:592697482026/10/26 22:36:18 INFO Starting HTTP server address=proxy.sock7492026/10/26 22:36:18 WARN mTLS auth: subject not in bound subjects subject="CN=someone"7502026/10/26 22:36:18 INFO Shutdown signal received, draining in-flight requests timeout=10s751--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.14s)752=== RUN TestIsValidCachePath753=== PAUSE TestIsValidCachePath754=== RUN TestReadProxyNarinfo755=== PAUSE TestReadProxyNarinfo756=== RUN TestReadProxyNarinfoAlreadyDecompressed757=== PAUSE TestReadProxyNarinfoAlreadyDecompressed758=== RUN TestReadProxyContentNegotiation759=== PAUSE TestReadProxyContentNegotiation760=== RUN TestReadProxyNarStreaming761=== PAUSE TestReadProxyNarStreaming762=== RUN TestReadProxy404And429763=== PAUSE TestReadProxy404And429764=== RUN TestReadProxyInvalidPath765=== PAUSE TestReadProxyInvalidPath766=== RUN TestReadProxyHead767=== PAUSE TestReadProxyHead768=== RUN TestReadProxyOutlastsServerWriteTimeout769=== PAUSE TestReadProxyOutlastsServerWriteTimeout770=== RUN TestReadProxyConditionalGet771=== PAUSE TestReadProxyConditionalGet772=== RUN TestReadProxyRootRedirectsToIndexHTML773=== PAUSE TestReadProxyRootRedirectsToIndexHTML774=== RUN TestReadProxyDisabled775=== PAUSE TestReadProxyDisabled776=== RUN TestReadRedirectNar777=== PAUSE TestReadRedirectNar778=== RUN TestReadRedirectKeepsNarinfoProxied779=== PAUSE TestReadRedirectKeepsNarinfoProxied780=== RUN TestReadProxyRangeRequest781=== PAUSE TestReadProxyRangeRequest782=== RUN TestReadRedirectUsesPublicS3URL783=== PAUSE TestReadRedirectUsesPublicS3URL784=== RUN TestPush_OverlappingRootsStoreOneRowPerKey785=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey786=== RUN TestPush_CompleteCommitsEveryRoot787=== PAUSE TestPush_CompleteCommitsEveryRoot788=== RUN TestPush_RepeatedRootCommitsOnce789=== PAUSE TestPush_RepeatedRootCommitsOnce790=== RUN TestPush_CompleteWaitsForCleanupOfThePush791=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush792=== RUN TestPush_RootsAreLockedInByteOrder793=== PAUSE TestPush_RootsAreLockedInByteOrder794=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit795=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit796=== RUN TestPush_RejectsBadRequests797=== PAUSE TestPush_RejectsBadRequests798=== RUN TestPush_SignsNarinfosOfItsPendingObjects799=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects800=== RUN TestRedundantMultipartUpload801=== PAUSE TestRedundantMultipartUpload802=== RUN TestCompleteMultipartUpload_ErrorButObjectExists803=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists804=== RUN TestCompletedNarNotReofferedAcrossClosures805=== PAUSE TestCompletedNarNotReofferedAcrossClosures806=== RUN TestPresignedUploadRegisteredBeforeCommit807=== PAUSE TestPresignedUploadRegisteredBeforeCommit808=== RUN TestService_Rustfstest809=== PAUSE TestService_Rustfstest810=== RUN TestParseSize811=== PAUSE TestParseSize812=== RUN TestSkippedUploadsHandler813=== PAUSE TestSkippedUploadsHandler814=== RUN TestSystemdListenerNotActivated815--- PASS: TestSystemdListenerNotActivated (0.00s)816=== RUN TestWatchdogBeatsWhenHealthy817--- PASS: TestWatchdogBeatsWhenHealthy (0.03s)818=== RUN TestWatchdogSkipsWhenUnhealthy8192026/10/26 22:36:18 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"8202026/10/26 22:36:18 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"8212026/10/26 22:36:18 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"8222026/10/26 22:36:18 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"8232026/10/26 22:36:18 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"8242026/10/26 22:36:18 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"8252026/10/26 22:36:18 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"8262026/10/26 22:36:18 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"8272026/10/26 22:36:18 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"828--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)829=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle830=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle831=== RUN TestProxyWriteTimeout832=== PAUSE TestProxyWriteTimeout833=== RUN TestPendingClosureWriteTimeout834=== PAUSE TestPendingClosureWriteTimeout835=== RUN TestIsValidUploadKey836=== PAUSE TestIsValidUploadKey837=== RUN TestUploadHandlersRejectInvalidKeys838=== PAUSE TestUploadHandlersRejectInvalidKeys839=== RUN TestUploadHandlersRejectOversizedBody840=== PAUSE TestUploadHandlersRejectOversizedBody841=== RUN TestService_cleanupPendingClosuresHandler842=== PAUSE TestService_cleanupPendingClosuresHandler843=== RUN TestService_createPendingClosureHandler844=== PAUSE TestService_createPendingClosureHandler845=== RUN TestService_verifyS3Integrity846=== PAUSE TestService_verifyS3Integrity847=== RUN TestCompleteMultipartUnregistered848=== PAUSE TestCompleteMultipartUnregistered849=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT850=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT851=== CONT TestService_AuthMiddleware_MTLSProxyHeader852=== CONT TestCompleteMultipartUnregistered853=== CONT TestObjectStatsTrigger854=== CONT TestReadProxyConditionalGet855=== CONT TestObjectStatsUpdatedOncePerCommit856=== CONT TestParseSingleRange857=== CONT TestReadRedirectNar858=== CONT TestReadProxyDisabled859=== CONT TestForceGCDuringPushOffersSweptObject860=== CONT TestReadProxyRangeRequest861=== CONT TestReadRedirectUsesPublicS3URL862=== CONT TestReadProxyHead863=== CONT TestReadProxyInvalidPath864=== CONT TestReadProxy404And429865=== CONT TestPendingClosureFailureAbortsItsUploads866=== CONT TestReadProxyNarStreaming867=== CONT TestReadProxyOutlastsServerWriteTimeout868=== CONT TestReadProxyNarinfoAlreadyDecompressed869=== CONT TestReadProxyContentNegotiation870=== CONT TestPendingClosureFailureTracksEveryUpload871=== RUN TestPendingClosureFailureTracksEveryUpload/refuse_aborts=false872=== CONT TestReadProxyNarinfo873=== PAUSE TestPendingClosureFailureTracksEveryUpload/refuse_aborts=false874=== RUN TestPendingClosureFailureTracksEveryUpload/refuse_aborts=true875=== CONT TestIsValidCachePath876=== PAUSE TestPendingClosureFailureTracksEveryUpload/refuse_aborts=true877=== CONT TestClientFallsBackToClosures878=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT879=== RUN TestParseSingleRange/none880=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows881=== RUN TestIsValidCachePath/narinfo882=== PAUSE TestParseSingleRange/none883=== CONT TestPresentNotReportedWhileGCDeletesClosure884=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows885=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale886=== RUN TestParseSingleRange/unknown_unit887=== PAUSE TestIsValidCachePath/narinfo888=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale889=== PAUSE TestParseSingleRange/unknown_unit890=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check891=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars892=== RUN TestParseSingleRange/multi-range_ignored893=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh894=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check895=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars896=== RUN TestIsValidCachePath/nar_zst897=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh898=== CONT TestPresentReportsOnlyClosureRoots899=== PAUSE TestParseSingleRange/multi-range_ignored900=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection901=== RUN TestParseSingleRange/malformed_no_dash902=== PAUSE TestParseSingleRange/malformed_no_dash903=== RUN TestParseSingleRange/malformed_both_empty904=== PAUSE TestIsValidCachePath/nar_zst905=== RUN TestIsValidCachePath/nar_xz906=== PAUSE TestParseSingleRange/malformed_both_empty907=== PAUSE TestIsValidCachePath/nar_xz908=== RUN TestIsValidCachePath/nar_bz2909=== PAUSE TestIsValidCachePath/nar_bz2910=== RUN TestIsValidCachePath/nar_uncompressed911=== RUN TestParseSingleRange/malformed_end_before_start912=== PAUSE TestIsValidCachePath/nar_uncompressed913=== PAUSE TestParseSingleRange/malformed_end_before_start914=== RUN TestIsValidCachePath/ls915=== RUN TestParseSingleRange/closed916=== PAUSE TestIsValidCachePath/ls917=== RUN TestIsValidCachePath/log918=== PAUSE TestIsValidCachePath/log919=== PAUSE TestParseSingleRange/closed920=== RUN TestIsValidCachePath/realisation921=== RUN TestParseSingleRange/open-ended922=== PAUSE TestIsValidCachePath/realisation923=== PAUSE TestParseSingleRange/open-ended924=== RUN TestIsValidCachePath/nix-cache-info925=== PAUSE TestIsValidCachePath/nix-cache-info926=== RUN TestIsValidCachePath/index.html927=== RUN TestParseSingleRange/end_clamped_to_size928=== PAUSE TestParseSingleRange/end_clamped_to_size929=== RUN TestParseSingleRange/suffix930=== PAUSE TestParseSingleRange/suffix931=== PAUSE TestIsValidCachePath/index.html932=== RUN TestIsValidCachePath/traversal_parent933=== PAUSE TestIsValidCachePath/traversal_parent934=== RUN TestIsValidCachePath/traversal_in_middle935=== PAUSE TestIsValidCachePath/traversal_in_middle936=== RUN TestParseSingleRange/suffix_exceeds_size937=== RUN TestIsValidCachePath/invalid_char_e938=== PAUSE TestIsValidCachePath/invalid_char_e939=== RUN TestIsValidCachePath/invalid_char_u940=== PAUSE TestIsValidCachePath/invalid_char_u941=== PAUSE TestParseSingleRange/suffix_exceeds_size942=== RUN TestParseSingleRange/single_byte943=== RUN TestIsValidCachePath/random_path944=== PAUSE TestParseSingleRange/single_byte945=== PAUSE TestIsValidCachePath/random_path946=== RUN TestParseSingleRange/start_past_EOF947=== RUN TestIsValidCachePath/empty948=== PAUSE TestParseSingleRange/start_past_EOF949=== RUN TestParseSingleRange/start_far_past_EOF950=== PAUSE TestIsValidCachePath/empty951=== RUN TestIsValidCachePath/leading_slash952=== PAUSE TestIsValidCachePath/leading_slash953=== RUN TestIsValidCachePath/wrong_extension954=== PAUSE TestIsValidCachePath/wrong_extension955=== RUN TestIsValidCachePath/short_hash956=== PAUSE TestIsValidCachePath/short_hash957=== PAUSE TestParseSingleRange/start_far_past_EOF958=== CONT TestPresentRefreshesOnlyStaleClosures959=== CONT TestDeletePinKeepsRowWhenS3Fails960--- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.78s)961=== CONT TestGCSweepDeliversEachKeyOnce962--- PASS: TestReadProxyContentNegotiation (1.46s)963=== CONT TestCreatePinRejectsBadInput9642026/10/26 22:36:20 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9652026/10/26 22:36:20 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst966--- PASS: TestCompleteMultipartUnregistered (1.57s)967=== CONT TestRegisterCompletedObjectNeedsPendingRow968--- PASS: TestReadProxyConditionalGet (1.97s)969=== CONT TestConcurrentPinUpdatesAgree970--- PASS: TestObjectStatsTrigger (2.21s)971=== CONT TestCreatePin_ReservedPins9722026/10/26 22:36:21 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:59303/oidc973--- PASS: TestObjectStatsUpdatedOncePerCommit (2.46s)974=== CONT TestTombstonedObjectOfferedWithoutWaiting975--- PASS: TestReadRedirectNar (2.60s)976=== CONT TestOrphanedObjectsGCStressTest977--- PASS: TestReadProxyInvalidPath (2.74s)978=== CONT TestGCSweepSkipsPendingObjects979--- PASS: TestPresentRefreshesOnlyStaleClosures (2.90s)980=== CONT TestOrphanedObjectsGC981--- PASS: TestReadProxyDisabled (3.09s)982=== CONT TestReconnectLeavesObjectsUnlocked983--- PASS: TestReadProxyRangeRequest (3.31s)984=== CONT TestPushDedupSurvivesConcurrentGC985--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (3.46s)986=== CONT TestService_Rustfstest987--- PASS: TestReadProxyHead (3.89s)988=== CONT TestService_verifyS3Integrity9892026/10/26 22:36:23 WARN Rate limiter enabled after throttle name=s3-test rate=59902026/10/26 22:36:23 WARN S3 rate limit hit during proxy key=4hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo error="Please reduce your request rate."9912026/10/26 22:36:23 WARN Rate limiter backed off name=s3-test rate=59922026/10/26 22:36:23 WARN S3 rate limit hit during proxy key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhh.nar.zst error="Please reduce your request rate."993--- PASS: TestReadProxy404And429 (4.30s)994=== CONT TestService_createPendingClosureHandler9952026/10/26 22:36:23 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>996--- PASS: TestReadProxyNarinfo (4.34s)997=== CONT TestDeduplicatedObjectsRecordedAsPending998=== CONT TestUploadHandlersRejectOversizedBody999--- PASS: TestReadRedirectUsesPublicS3URL (4.35s)1000=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts1001=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts1002=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure1003=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure1004=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart1005=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart1006=== CONT TestUploadHandlersRejectInvalidKeys1007=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1008=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1009=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1010=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1011=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1012=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1013=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1014=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1015=== CONT TestIsValidUploadKey1016=== RUN TestIsValidUploadKey/narinfo1017=== PAUSE TestIsValidUploadKey/narinfo1018=== RUN TestIsValidUploadKey/nar_zst1019=== PAUSE TestIsValidUploadKey/nar_zst1020=== RUN TestIsValidUploadKey/nar_xz1021=== PAUSE TestIsValidUploadKey/nar_xz1022=== RUN TestIsValidUploadKey/nar_plain1023=== PAUSE TestIsValidUploadKey/nar_plain1024=== RUN TestIsValidUploadKey/listing1025=== PAUSE TestIsValidUploadKey/listing1026=== RUN TestIsValidUploadKey/build_log1027=== PAUSE TestIsValidUploadKey/build_log1028=== RUN TestIsValidUploadKey/build_log_home-manager_file1029=== PAUSE TestIsValidUploadKey/build_log_home-manager_file1030=== RUN TestIsValidUploadKey/build_log_plus_in_name1031=== PAUSE TestIsValidUploadKey/build_log_plus_in_name1032=== RUN TestIsValidUploadKey/build_log_question_mark1033=== PAUSE TestIsValidUploadKey/build_log_question_mark1034=== RUN TestIsValidUploadKey/build_log_equals1035=== PAUSE TestIsValidUploadKey/build_log_equals1036=== RUN TestIsValidUploadKey/realisation1037=== PAUSE TestIsValidUploadKey/realisation1038=== RUN TestIsValidUploadKey/realisation_plus_in_output1039=== PAUSE TestIsValidUploadKey/realisation_plus_in_output1040=== RUN TestIsValidUploadKey/nix-cache-info1041=== PAUSE TestIsValidUploadKey/nix-cache-info1042=== RUN TestIsValidUploadKey/index.html1043=== PAUSE TestIsValidUploadKey/index.html1044=== RUN TestIsValidUploadKey/narinfo_key,_nar_type1045=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type1046=== RUN TestIsValidUploadKey/nar_key,_narinfo_type1047=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type1048=== RUN TestIsValidUploadKey/listing_key,_narinfo_type1049=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type1050=== RUN TestIsValidUploadKey/traversal1051=== PAUSE TestIsValidUploadKey/traversal1052=== RUN TestIsValidUploadKey/traversal_nar1053=== PAUSE TestIsValidUploadKey/traversal_nar1054=== RUN TestIsValidUploadKey/absolute1055=== PAUSE TestIsValidUploadKey/absolute1056=== RUN TestIsValidUploadKey/empty_key1057=== PAUSE TestIsValidUploadKey/empty_key1058=== RUN TestIsValidUploadKey/unknown_type1059=== PAUSE TestIsValidUploadKey/unknown_type1060=== CONT TestService_cleanupPendingClosuresHandler10612026/10/26 22:36:23 INFO Received uploads request method=POST path=/api/pending_closures1062--- PASS: TestPendingClosureFailureAbortsItsUploads (4.54s)1063=== CONT TestProxyWriteTimeout1064=== RUN TestProxyWriteTimeout/narinfo1065=== PAUSE TestProxyWriteTimeout/narinfo1066=== RUN TestProxyWriteTimeout/1_GiB_nar1067=== PAUSE TestProxyWriteTimeout/1_GiB_nar1068=== RUN TestProxyWriteTimeout/10_GiB_nar1069=== PAUSE TestProxyWriteTimeout/10_GiB_nar1070=== RUN TestProxyWriteTimeout/unknown_size1071=== PAUSE TestProxyWriteTimeout/unknown_size1072=== CONT TestGCBugBareHashReferences10732026/10/26 22:36:23 INFO Received create pin request method=POST path=/api/pins/app10742026/10/26 22:36:23 INFO Created/updated pin name=app store_path=/nix/store/cccccccccccccccccccccccccccccccc-app narinfo_key=cccccccccccccccccccccccccccccccc.narinfo10752026/10/26 22:36:23 INFO Received delete pin request method=DELETE path=/api/pins/app10762026/10/26 22:36:23 ERROR Failed to delete pin from S3 key=pins/app error="Get \"http://127.0.0.1:1/bucket22/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"10772026/10/26 22:36:23 INFO Received delete pin request method=DELETE path=/api/pins/app10782026/10/26 22:36:23 INFO Deleted pin name=app10792026/10/26 22:36:23 INFO Received uploads request method=POST path=/api/pending_closures1080--- PASS: TestDeletePinKeepsRowWhenS3Fails (5.00s)1081=== CONT TestSkippedUploadsHandler10822026/10/26 22:36:23 INFO Client skipped oversized paths paths=3 nar_bytes=50000000001083--- PASS: TestSkippedUploadsHandler (0.00s)1084=== CONT TestParseSize1085--- PASS: TestParseSize (0.00s)1086=== CONT TestPendingClosureWriteTimeout1087=== RUN TestPendingClosureWriteTimeout/empty1088=== PAUSE TestPendingClosureWriteTimeout/empty1089=== RUN TestPendingClosureWriteTimeout/400_objects1090=== PAUSE TestPendingClosureWriteTimeout/400_objects1091=== RUN TestPendingClosureWriteTimeout/670k_objects1092=== PAUSE TestPendingClosureWriteTimeout/670k_objects1093=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1094=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1095=== CONT TestGCMetrics1096--- PASS: TestReadProxyNarStreaming (5.23s)1097=== CONT TestPresignedUploadRegisteredBeforeCommit1098--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (5.27s)1099=== CONT TestGCAdvisoryLockBlocksConcurrentRun11002026/10/26 22:36:24 INFO Received uploads request method=POST path=/api/pending_closures1101--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (5.58s)1102=== CONT TestGCTaskStore_Fail1103--- PASS: TestGCTaskStore_Fail (0.00s)1104=== CONT TestLeadEndsOnShutdown1105--- PASS: TestPresentReportsOnlyClosureRoots (5.72s)1106=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded11072026/10/26 22:36:24 INFO Received uploads request method=POST path=/api/pending_closures11082026/10/26 22:36:24 INFO Received uploads request method=POST path=/api/pending_closures11092026/10/26 22:36:24 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)11102026/10/26 22:36:24 INFO Uploading nj85ly10j3f8bym3jxj4671df1kzdm5j-shared-dep (136B)11112026/10/26 22:36:24 INFO Uploading dm7j9dz1zfhriwhd6myyw44i5k53w570-a (256B)11122026/10/26 22:36:24 WARN Failed to register uploaded object key=b1pvygcxcsl06rb3cwdm7rn7p18zspbh.ls error="server returned 404: 404 page not found\n"11132026/10/26 22:36:24 WARN Failed to register uploaded object key=nj85ly10j3f8bym3jxj4671df1kzdm5j.ls error="server returned 404: 404 page not found\n"11142026/10/26 22:36:24 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"11152026/10/26 22:36:24 WARN Failed to register uploaded object key=dm7j9dz1zfhriwhd6myyw44i5k53w570.ls error="server returned 404: 404 page not found\n"11162026/10/26 22:36:24 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign11172026/10/26 22:36:24 WARN Failed to register uploaded object key=nar/10xhj3bj4gxzjp2pzfz5sjzanj42b3hs4gpkw5c05syrs7sy4hhr.nar.zst error="server returned 404: 404 page not found\n"11182026/10/26 22:36:24 INFO Signed narinfos id=2 count=211192026/10/26 22:36:24 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign11202026/10/26 22:36:24 INFO Signed narinfos id=1 count=211212026/10/26 22:36:24 INFO Uploading 4 narinfos11222026/10/26 22:36:24 INFO Received create pin request method=POST path=/api/pins/deploy11232026/10/26 22:36:24 INFO Received create pin request method=POST path=/api/pins/deploy11242026/10/26 22:36:24 INFO Received create pin request method=POST path=/api/pins/deploy11252026/10/26 22:36:24 INFO Received create pin request method=POST path=/api/pins/deploy11262026/10/26 22:36:24 INFO Received create pin request method=POST path=/api/pins/deploy11272026/10/26 22:36:24 INFO Received create pin request method=POST path=/api/pins/deploy11282026/10/26 22:36:24 INFO Received create pin request method=POST path=/api/pins/deploy11292026/10/26 22:36:24 INFO Received create pin request method=POST path=/api/pins/deploy11302026/10/26 22:36:24 INFO Received create pin request method=POST path=/api/pins/deploy11312026/10/26 22:36:24 WARN Failed to register uploaded object key=nj85ly10j3f8bym3jxj4671df1kzdm5j.narinfo error="server returned 404: 404 page not found\n"11322026/10/26 22:36:24 WARN Failed to register uploaded object key=dm7j9dz1zfhriwhd6myyw44i5k53w570.narinfo error="server returned 404: 404 page not found\n"11332026/10/26 22:36:24 WARN Failed to register uploaded object key=b1pvygcxcsl06rb3cwdm7rn7p18zspbh.narinfo error="server returned 404: 404 page not found\n"11342026/10/26 22:36:24 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11352026/10/26 22:36:24 WARN Failed to register uploaded object key=nj85ly10j3f8bym3jxj4671df1kzdm5j.narinfo error="server returned 404: 404 page not found\n"11362026/10/26 22:36:24 INFO Completed upload id=1 objects=6 duration=25.229834ms11372026/10/26 22:36:24 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete11382026/10/26 22:36:24 INFO Completed upload id=2 objects=6 duration=932.375µs11392026/10/26 22:36:24 INFO Upload complete. (298ms)1140=== NAME TestClientFallsBackToClosures1141 client_pushes_test.go:112: Retrieved narinfo from S3:1142 StorePath: /private/var/tb/6/scratch/bedec206597db7e3/build/TestClientFallsBackToClosures1598110332/001/store/nj85ly10j3f8bym3jxj4671df1kzdm5j-shared-dep1143 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1144 Compression: zstd1145 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821146 NarSize: 1361147 References: 1148 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1149 client_pushes_test.go:112: Retrieved narinfo from S3:1150 StorePath: /private/var/tb/6/scratch/bedec206597db7e3/build/TestClientFallsBackToClosures1598110332/001/store/dm7j9dz1zfhriwhd6myyw44i5k53w570-a1151 URL: nar/10xhj3bj4gxzjp2pzfz5sjzanj42b3hs4gpkw5c05syrs7sy4hhr.nar.zst1152 Compression: zstd1153 NarHash: sha256:10xhj3bj4gxzjp2pzfz5sjzanj42b3hs4gpkw5c05syrs7sy4hhr1154 NarSize: 2561155 References: /private/var/tb/6/scratch/bedec206597db7e3/build/TestClientFallsBackToClosures1598110332/001/store/nj85ly10j3f8bym3jxj4671df1kzdm5j-shared-dep1156 CA: text:sha256:0lzf2gfnyi7x7rfalwz8glim3r09aacazd5pgjdwqffb5ba721nj1157 client_pushes_test.go:112: Retrieved narinfo from S3:1158 StorePath: /private/var/tb/6/scratch/bedec206597db7e3/build/TestClientFallsBackToClosures1598110332/001/store/b1pvygcxcsl06rb3cwdm7rn7p18zspbh-b1159 URL: nar/10xhj3bj4gxzjp2pzfz5sjzanj42b3hs4gpkw5c05syrs7sy4hhr.nar.zst1160 Compression: zstd1161 NarHash: sha256:10xhj3bj4gxzjp2pzfz5sjzanj42b3hs4gpkw5c05syrs7sy4hhr1162 NarSize: 2561163 References: /private/var/tb/6/scratch/bedec206597db7e3/build/TestClientFallsBackToClosures1598110332/001/store/nj85ly10j3f8bym3jxj4671df1kzdm5j-shared-dep1164 CA: text:sha256:0lzf2gfnyi7x7rfalwz8glim3r09aacazd5pgjdwqffb5ba721nj1165--- PASS: TestClientFallsBackToClosures (6.05s)1166=== CONT TestMultipartCleanup1167--- PASS: TestRegisterCompletedObjectNeedsPendingRow (4.57s)1168=== CONT TestPendingCleanupUsesOneCutoff11692026/10/26 22:36:24 INFO Received create pin request method=POST path=/api/pins/deploy11702026/10/26 22:36:25 INFO Created/updated pin name=deploy store_path="/nix/store/dddddddddddddddddddddddddddddddd-app-1.0+git_x?y=z" narinfo_key=dddddddddddddddddddddddddddddddd.narinfo1171--- PASS: TestCreatePinRejectsBadInput (4.85s)1172=== CONT TestService_NativeMTLS11732026/10/26 22:36:25 INFO Aborted multipart uploads count=0 kept=011742026/10/26 22:36:25 WARN Force mode enabled - objects will be deleted immediately without grace period11752026/10/26 22:36:25 INFO Received create pin request method=POST path=/api/pins/app11762026/10/26 22:36:25 INFO Received create pin request method=POST path=/api/pins/app11772026/10/26 22:36:25 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=011782026/10/26 22:36:25 INFO Vacuumed table table=pending_closures11792026/10/26 22:36:25 INFO Vacuumed table table=pending_objects11802026/10/26 22:36:25 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux11812026/10/26 22:36:25 WARN Refused reserved pin name=worker-x86_64-linux11822026/10/26 22:36:25 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux11832026/10/26 22:36:25 INFO Vacuumed table table=multipart_uploads11842026/10/26 22:36:25 INFO Received create pin request method=POST path=/api/pins/my-app11852026/10/26 22:36:25 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux11862026/10/26 22:36:25 INFO Vacuumed table table=closures11872026/10/26 22:36:25 INFO Vacuumed table table=objects1188--- PASS: TestGCSweepDeliversEachKeyOnce (6.06s)1189=== CONT TestServerTLSConfig1190=== RUN TestServerTLSConfig/no_client_CA1191=== PAUSE TestServerTLSConfig/no_client_CA1192=== RUN TestServerTLSConfig/missing_CA_file1193=== PAUSE TestServerTLSConfig/missing_CA_file1194=== RUN TestServerTLSConfig/not_a_PEM_file1195=== PAUSE TestServerTLSConfig/not_a_PEM_file1196=== CONT TestMetricsInventory1197=== CONT TestMetricsCommit1198--- PASS: TestCreatePin_ReservedPins (4.64s)11992026/10/26 22:36:25 INFO Received uploads request method=POST path=/api/pending_closures12002026/10/26 22:36:25 INFO Created/updated pin name=app store_path=/nix/store/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa-app narinfo_key=aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.narinfo1201--- PASS: TestTombstonedObjectOfferedWithoutWaiting (4.62s)1202=== CONT TestNARDeduplicationMetadataUploadBug12032026/10/26 22:36:25 INFO Created/updated pin name=app store_path=/nix/store/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb-app narinfo_key=bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb.narinfo1204--- PASS: TestConcurrentPinUpdatesAgree (5.21s)1205=== CONT TestCacheConfigHandlerMaxNarSize1206--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1207=== CONT TestCreatePendingClosureRejectsOversizedNAR12082026/10/26 22:36:25 INFO Received uploads request method=POST path=/api/pending_closures1209--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1210=== CONT TestChildrenInheritRaisedFileLimit1211=== CONT TestService_readinessHandler1212--- PASS: TestChildrenInheritRaisedFileLimit (0.01s)12132026/10/26 22:36:26 INFO Received uploads request method=POST path=/api/pending_closures12142026/10/26 22:36:26 INFO Aborted multipart uploads count=0 kept=012152026/10/26 22:36:26 WARN Force mode enabled - objects will be deleted immediately without grace period12162026/10/26 22:36:26 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=012172026/10/26 22:36:26 INFO Vacuumed table table=pending_closures12182026/10/26 22:36:26 INFO Vacuumed table table=pending_objects12192026/10/26 22:36:26 INFO Vacuumed table table=multipart_uploads12202026/10/26 22:36:26 INFO Vacuumed table table=closures12212026/10/26 22:36:26 INFO Vacuumed table table=objects1222--- PASS: TestGCSweepSkipsPendingObjects (5.20s)1223=== CONT TestGenerateLandingPage1224--- PASS: TestGenerateLandingPage (0.01s)1225=== CONT TestGracefulShutdownDrainsInflight12262026/10/26 22:36:26 INFO Starting HTTP server address=127.0.0.1:5946412272026/10/26 22:36:26 INFO Shutdown signal received, draining in-flight requests timeout=10s1228--- PASS: TestGracefulShutdownDrainsInflight (0.08s)1229=== CONT TestService_healthCheckHandler1230--- PASS: TestReconnectLeavesObjectsUnlocked (5.24s)1231=== CONT TestCommitRacingPendingCleanupKeepsObjects12322026/10/26 22:36:27 INFO Received uploads request method=POST path=/api/pending_closures12332026/10/26 22:36:27 INFO Aborted multipart uploads count=0 kept=01234=== CONT TestGCTaskStore_CompletedAllowsNewTask12352026/10/26 22:36:27 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=01236--- PASS: TestReadProxyOutlastsServerWriteTimeout (9.03s)1237=== CONT TestGCTaskStore_PhaseUpdates1238--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1239--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1240=== CONT TestGCTaskStore_GetEmpty1241=== CONT TestGCTaskStore_GetReturnsLatest1242--- PASS: TestGCTaskStore_GetEmpty (0.00s)1243=== CONT TestLeadIncumbentAnnouncesAtOnce1244--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1245--- PASS: TestService_Rustfstest (5.64s)1246=== CONT TestGCTaskStore_ConflictDifferentParams12472026/10/26 22:36:27 INFO Vacuumed table table=pending_closures1248--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1249=== CONT TestLeadElectsOneAndHandsOver12502026/10/26 22:36:27 INFO Vacuumed table table=pending_objects12512026/10/26 22:36:27 INFO Vacuumed table table=multipart_uploads12522026/10/26 22:36:27 INFO Vacuumed table table=closures12532026/10/26 22:36:27 INFO Vacuumed table table=objects12542026/10/26 22:36:28 INFO Aborted multipart uploads count=0 kept=012552026/10/26 22:36:28 WARN Force mode enabled - objects will be deleted immediately without grace period12562026/10/26 22:36:28 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=012572026/10/26 22:36:28 INFO Vacuumed table table=pending_closures12582026/10/26 22:36:28 INFO Vacuumed table table=pending_objects12592026/10/26 22:36:28 INFO Vacuumed table table=multipart_uploads12602026/10/26 22:36:28 INFO Vacuumed table table=closures12612026/10/26 22:36:28 INFO Vacuumed table table=objects1262--- PASS: TestPushDedupSurvivesConcurrentGC (6.12s)1263=== CONT TestGCTaskStore_DeduplicateSameParams1264--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1265=== CONT TestConnectWaitsForAPeerMigration12662026/10/26 22:36:28 INFO Received uploads request method=POST path=/api/pending_closures12672026/10/26 22:36:28 INFO Received uploads request method=POST path=/api/pending_closures1268--- PASS: TestDeduplicatedObjectsRecordedAsPending (5.80s)1269=== CONT TestGCTaskStore_StartNew1270=== CONT TestConnectSerialisesConcurrentMigrations1271--- PASS: TestGCTaskStore_StartNew (0.00s)1272=== NAME TestOrphanedObjectsGC1273 orphaned_objects_gc_test.go:287: GC Test Summary:1274 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A1275 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B1276 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)1277 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)1278 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects1279--- PASS: TestOrphanedObjectsGC (7.57s)1280=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock12812026/10/26 22:36:29 INFO Received uploads request method=POST path=/api/pending_closures12822026/10/26 22:36:29 INFO Received uploads request method=POST path=/api/pending_closures12832026/10/26 22:36:29 INFO Received uploads request method=POST path=/api/pending_closures12842026/10/26 22:36:29 INFO Received cleanup request method=DELETE path=/api/pending_closures12852026/10/26 22:36:29 INFO Aborted multipart uploads count=0 kept=012862026/10/26 22:36:29 INFO Received uploads request method=POST path=/api/pending_closures12872026/10/26 22:36:29 INFO Received cleanup request method=DELETE path=/api/pending_closures12882026/10/26 22:36:29 INFO Aborted multipart uploads count=1 kept=012892026/10/26 22:36:29 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12902026-10-26 22:36:29.926 UTC [30128] ERROR: Closure does not exist: id=112912026-10-26 22:36:29.926 UTC [30128] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE12922026-10-26 22:36:29.926 UTC [30128] STATEMENT: -- name: CommitPendingClosure :one1293 SELECT commit_pending_closure($1::bigint)::bigint1294 1295--- PASS: TestService_cleanupPendingClosuresHandler (6.81s)1296=== CONT TestResolveDBConnectionString1297=== RUN TestResolveDBConnectionString/flag_wins1298=== PAUSE TestResolveDBConnectionString/flag_wins1299=== RUN TestResolveDBConnectionString/file_when_flag_empty1300=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1301=== RUN TestResolveDBConnectionString/missing_file_is_an_error1302=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1303=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1304=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1305=== RUN TestResolveDBConnectionString/nothing_configured1306=== PAUSE TestResolveDBConnectionString/nothing_configured1307=== CONT TestPush_RootsAreLockedInByteOrder1308--- PASS: TestGCBugBareHashReferences (7.33s)1309=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle13102026/10/26 22:36:30 INFO Aborted multipart uploads count=0 kept=013112026/10/26 22:36:30 WARN Force mode enabled - objects will be deleted immediately without grace period13122026/10/26 22:36:30 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=013132026/10/26 22:36:30 INFO Vacuumed table table=pending_closures13142026/10/26 22:36:30 INFO Vacuumed table table=pending_objects13152026/10/26 22:36:30 INFO Vacuumed table table=multipart_uploads13162026/10/26 22:36:30 INFO Vacuumed table table=closures13172026/10/26 22:36:30 INFO Vacuumed table table=objects1318--- PASS: TestGCMetrics (7.03s)1319=== CONT TestCompletedNarNotReofferedAcrossClosures13202026/10/26 22:36:30 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13212026/10/26 22:36:31 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=OWMwNzc0ZDMtYTE4Mi00M2UyLWIzMDYtNWM1NTcyYjI1ZGE4LjA4YWM2ZmE0LTdmMDEtNGZmZC1hMzdlLWI4ZjMwYzcxZGUyZngxNzkzMDU0MTg4MzQxOTcxMDAw parts=1013222026/10/26 22:36:31 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13232026/10/26 22:36:31 INFO Completed upload id=1 objects=2 duration=25.727083ms13242026/10/26 22:36:31 INFO Received uploads request method=POST path=/api/pending_closures13252026/10/26 22:36:31 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst13262026/10/26 22:36:31 INFO Received uploads request method=POST path=/api/pending_closures1327--- PASS: TestPresignedUploadRegisteredBeforeCommit (7.42s)1328=== CONT TestPush_SignsNarinfosOfItsPendingObjects13292026/10/26 22:36:31 INFO Received uploads request method=POST path=/api/pending_closures13302026/10/26 22:36:31 INFO Received uploads request method=POST path=/api/pending_closures13312026/10/26 22:36:31 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo13322026/10/26 22:36:31 WARN Found objects in DB but missing from S3, will re-upload count=113332026/10/26 22:36:31 INFO Received complete upload request method=POST path=/api/pending_closures/3/complete13342026/10/26 22:36:31 INFO Completed upload id=3 objects=2 duration=1.7795ms1335--- PASS: TestService_verifyS3Integrity (8.91s)1336=== CONT TestCompleteMultipartUpload_ErrorButObjectExists13372026/10/26 22:36:31 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13382026/10/26 22:36:31 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=OWMwNzc0ZDMtYTE4Mi00M2UyLWIzMDYtNWM1NTcyYjI1ZGE4LjIxYTMxMTZkLTFmOTEtNDIwYi05MDUyLTE4ZTI3OGM3ZTcwYngxNzkzMDU0MTg5MzgyMTQxMDAw parts=1013392026/10/26 22:36:31 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13402026/10/26 22:36:31 INFO Completed upload id=1 objects=2 duration=20.832958ms13412026/10/26 22:36:31 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000013422026/10/26 22:36:31 INFO Received uploads request method=POST path=/api/pending_closures13432026/10/26 22:36:31 INFO Starting cleanup of old closures method=DELETE path=/api/closures13442026/10/26 22:36:31 INFO Aborted multipart uploads count=0 kept=013452026/10/26 22:36:31 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=013462026/10/26 22:36:31 INFO Vacuumed table table=pending_closures13472026/10/26 22:36:31 INFO Vacuumed table table=pending_objects13482026/10/26 22:36:32 INFO Vacuumed table table=multipart_uploads13492026/10/26 22:36:32 INFO Vacuumed table table=closures13502026/10/26 22:36:32 INFO lead: acquired remote=192.0.2.1:123413512026/10/26 22:36:32 INFO Vacuumed table table=objects13522026/10/26 22:36:32 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001353=== CONT TestRedundantMultipartUpload1354--- PASS: TestService_createPendingClosureHandler (9.10s)13552026/10/26 22:36:32 INFO Received uploads request method=POST path=/api/pending_closures1356--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (8.26s)1357=== CONT TestPush_RejectsBadRequests13582026/10/26 22:36:32 INFO Received uploads request method=POST path=/api/pending_closures13592026-10-26 22:36:33.060 UTC [30333] ERROR: duplicate key value violates unique constraint "pg_class_relname_nsp_index"13602026-10-26 22:36:33.060 UTC [30333] DETAIL: Key (relname, relnamespace)=(goose_db_version_id_seq, 2200) already exists.13612026-10-26 22:36:33.060 UTC [30333] STATEMENT: CREATE TABLE goose_db_version (1362 id integer PRIMARY KEY GENERATED BY DEFAULT AS IDENTITY,1363 version_id bigint NOT NULL,1364 is_applied boolean NOT NULL,1365 tstamp timestamp NOT NULL DEFAULT now()1366 )13672026/10/26 22:36:33 INFO lead: released remote=192.0.2.1:123413682026/10/26 22:36:33 INFO Received cleanup request method=DELETE path=/api/pending_closures13692026/10/26 22:36:33 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket50/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""13702026/10/26 22:36:33 INFO Aborted multipart uploads count=0 kept=113712026/10/26 22:36:33 INFO Received cleanup request method=DELETE path=/api/pending_closures1372--- PASS: TestLeadEndsOnShutdown (8.88s)1373=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit13742026/10/26 22:36:33 INFO Aborted multipart uploads count=1 kept=01375--- PASS: TestMultipartCleanup (8.45s)1376=== CONT TestPush_CompleteWaitsForCleanupOfThePush13772026/10/26 22:36:33 INFO Received uploads request method=POST path=/api/pending_closures13782026/10/26 22:36:33 INFO Received uploads request method=POST path=/api/pending_closures13792026/10/26 22:36:33 INFO Received cleanup request method=DELETE path=/api/pending_closures13802026/10/26 22:36:33 WARN mTLS auth: subject not in bound subjects subject="CN=reader"13812026/10/26 22:36:33 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1382--- PASS: TestService_NativeMTLS (8.59s)1383=== CONT TestCacheStatsHandler1384--- PASS: TestMetricsInventory (8.45s)1385=== CONT TestPush_RepeatedRootCommitsOnce1386--- PASS: TestConnectSerialisesConcurrentMigrations (5.18s)1387=== CONT TestClientPushesUseOnePush13882026/10/26 22:36:34 INFO Received push request method=POST path=/api/pushes13892026/10/26 22:36:34 WARN readiness check failed error="closed pool"1390=== NAME TestNARDeduplicationMetadataUploadBug1391 metadata_upload_test.go:48: First store path: /private/var/tb/6/scratch/bedec206597db7e3/build/TestNARDeduplicationMetadataUploadBug2492187507/001/store/028650c7d5z1528xkbp23cdl83m2x29b-file1.txt1392--- PASS: TestService_readinessHandler (9.12s)1393=== CONT TestGetExistingObjectsLocksRows13942026/10/26 22:36:35 INFO Received push request method=POST path=/api/pushes13952026/10/26 22:36:35 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)13962026/10/26 22:36:35 INFO Uploading 028650c7d5z1528xkbp23cdl83m2x29b-file1.txt (160B)13972026/10/26 22:36:35 WARN Failed to register uploaded object key=028650c7d5z1528xkbp23cdl83m2x29b.ls error="server returned 404: 404 page not found\n"13982026/10/26 22:36:35 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"13992026/10/26 22:36:35 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14002026/10/26 22:36:35 INFO Signed narinfos id=1 count=114012026/10/26 22:36:35 INFO Uploading 1 narinfos1402--- PASS: TestService_healthCheckHandler (8.58s)1403=== CONT TestDeleteClosuresRacingPins14042026/10/26 22:36:35 INFO Received complete push request method=POST path=/api/pushes/1/complete14052026/10/26 22:36:35 WARN Failed to register uploaded object key=028650c7d5z1528xkbp23cdl83m2x29b.narinfo error="server returned 404: 404 page not found\n"14062026/10/26 22:36:35 INFO Completed push id=1 objects=3 duration=27.259083ms14072026/10/26 22:36:35 INFO Upload complete. (357ms)1408=== NAME TestNARDeduplicationMetadataUploadBug1409 metadata_upload_test.go:54: Retrieved narinfo from S3:1410 StorePath: /private/var/tb/6/scratch/bedec206597db7e3/build/TestNARDeduplicationMetadataUploadBug2492187507/001/store/028650c7d5z1528xkbp23cdl83m2x29b-file1.txt1411 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1412 Compression: zstd1413 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1414 NarSize: 1601415 References: 1416 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1417 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1418 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1419 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}1420 metadata_upload_test.go:64: Second store path (same content): /private/var/tb/6/scratch/bedec206597db7e3/build/TestNARDeduplicationMetadataUploadBug2492187507/001/store/pi6wrqr9w7p3gbhhmd36b16jyqg3vyrh-file2.txt14212026/10/26 22:36:35 INFO Received push request method=POST path=/api/pushes14222026/10/26 22:36:35 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)14232026/10/26 22:36:35 WARN Failed to register uploaded object key=pi6wrqr9w7p3gbhhmd36b16jyqg3vyrh.ls error="server returned 404: 404 page not found\n"14242026/10/26 22:36:35 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign14252026/10/26 22:36:35 INFO Signed narinfos id=2 count=114262026/10/26 22:36:35 INFO Uploading 1 narinfos14272026/10/26 22:36:35 INFO Received complete push request method=POST path=/api/pushes/2/complete14282026/10/26 22:36:35 WARN Failed to register uploaded object key=pi6wrqr9w7p3gbhhmd36b16jyqg3vyrh.narinfo error="server returned 404: 404 page not found\n"14292026/10/26 22:36:35 INFO Completed push id=2 objects=3 duration=625.625µs14302026/10/26 22:36:35 INFO Upload complete. (197ms)1431 metadata_upload_test.go:76: Retrieved narinfo from S3:1432 StorePath: /private/var/tb/6/scratch/bedec206597db7e3/build/TestNARDeduplicationMetadataUploadBug2492187507/001/store/pi6wrqr9w7p3gbhhmd36b16jyqg3vyrh-file2.txt1433 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1434 Compression: zstd1435 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1436 NarSize: 1601437 References: 1438 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1439 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1440 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1441 {"version":1,"root":{"type":"regular","size":44}}14422026/10/26 22:36:35 INFO Aborted multipart uploads count=0 kept=014432026/10/26 22:36:35 WARN Force mode enabled - objects will be deleted immediately without grace period14442026/10/26 22:36:35 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=01445--- PASS: TestNARDeduplicationMetadataUploadBug (10.16s)1446=== CONT TestGCEndsOnShutdown1447=== RUN TestGCEndsOnShutdown/before_the_run1448=== PAUSE TestGCEndsOnShutdown/before_the_run1449=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1450=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1451=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1452=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1453=== CONT TestClientSharedPathCommittedMidPush14542026/10/26 22:36:36 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14552026/10/26 22:36:36 INFO Vacuumed table table=pending_closures14562026/10/26 22:36:36 INFO Vacuumed table table=pending_objects14572026/10/26 22:36:36 INFO Vacuumed table table=multipart_uploads14582026/10/26 22:36:36 INFO lead: acquired remote=192.0.2.1:123414592026/10/26 22:36:36 INFO Vacuumed table table=closures14602026/10/26 22:36:36 INFO Vacuumed table table=objects14612026/10/26 22:36:36 INFO Completed multipart upload object_key=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa00000000000000000000.nar.zst upload_id=OWMwNzc0ZDMtYTE4Mi00M2UyLWIzMDYtNWM1NTcyYjI1ZGE4LmRiZTIzNTEzLTBhODgtNGNlOC05NzgxLWM1NzYyYTAwMjhhZngxNzkzMDU0MTk0Mjg3Mzc5MDAw parts=101462--- PASS: TestCommitRacingPendingCleanupKeepsObjects (9.15s)1463=== CONT TestSweepRechecksPendingAfterLocking14642026/10/26 22:36:36 INFO lead: acquired remote=192.0.2.1:123414652026/10/26 22:36:36 INFO lead: released remote=192.0.2.1:12341466--- PASS: TestLeadIncumbentAnnouncesAtOnce (8.76s)1467=== CONT TestPinProtectsFromGC14682026/10/26 22:36:37 INFO Received push request method=POST path=/api/pushes14692026/10/26 22:36:37 INFO lead: released remote=192.0.2.1:123414702026/10/26 22:36:37 INFO lead: acquired remote=192.0.2.1:123414712026/10/26 22:36:37 INFO Received uploads request method=POST path=/api/pending_closures14722026/10/26 22:36:38 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14732026/10/26 22:36:38 INFO Received uploads request method=POST path=/api/pending_closures14742026/10/26 22:36:38 INFO Completed multipart upload object_key=nar/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb00000000000000000000.nar.zst upload_id=OWMwNzc0ZDMtYTE4Mi00M2UyLWIzMDYtNWM1NTcyYjI1ZGE4LjM2ZmJlZDJlLWI2YTgtNDliOC05Y2Q1LTgwY2Y0Njg1NGM0ZHgxNzkzMDU0MTk0Mjg2ODU5MDAw parts=1014752026/10/26 22:36:38 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14762026/10/26 22:36:38 INFO Received complete push request method=POST path=/api/pushes/1/complete14772026/10/26 22:36:38 INFO Completed push id=1 objects=4 duration=27.233667ms14782026/10/26 22:36:38 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete14792026/10/26 22:36:38 INFO Completed upload id=2 objects=2 duration=565.666µs1480--- PASS: TestMetricsCommit (12.76s)1481=== CONT TestPushWaitsForSweepHoldingRow14822026/10/26 22:36:38 INFO lead: released remote=192.0.2.1:123414832026/10/26 22:36:38 INFO Received push request method=POST path=/api/pushes1484--- PASS: TestLeadElectsOneAndHandsOver (10.68s)1485=== CONT TestFailedS3DeleteKeepsTombstone14862026/10/26 22:36:38 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14872026/10/26 22:36:38 INFO Signed narinfos id=1 count=114882026/10/26 22:36:38 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14892026/10/26 22:36:38 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14902026/10/26 22:36:38 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"1491--- PASS: TestConnectWaitsForAPeerMigration (10.50s)14922026/10/26 22:36:38 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign1493=== CONT TestClientWithDependencies14942026/10/26 22:36:38 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"14952026/10/26 22:36:38 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14962026/10/26 22:36:38 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=114972026/10/26 22:36:38 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14982026/10/26 22:36:38 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo1499--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (7.34s)1500=== CONT TestReadRedirectKeepsNarinfoProxied15012026/10/26 22:36:38 ERROR failed to check GC advisory lock error="query pg_locks: failed to connect to `user=_tribuchetbld6 database=niks3`: /nonexistent/.s.PGSQL.5432 (/nonexistent): dial error: dial unix /nonexistent/.s.PGSQL.5432: connect: no such file or directory"1502--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (15.09s)1503=== CONT TestClientErrorHandling1504=== RUN TestClientErrorHandling/InvalidStorePath1505=== PAUSE TestClientErrorHandling/InvalidStorePath1506=== RUN TestClientErrorHandling/InvalidAuthToken1507=== PAUSE TestClientErrorHandling/InvalidAuthToken1508=== RUN TestClientErrorHandling/ServerNotAvailable1509=== PAUSE TestClientErrorHandling/ServerNotAvailable1510=== CONT TestSweepSkipsRowsLockedByPush15112026/10/26 22:36:39 INFO Received uploads request method=POST path=/api/pending_closures15122026/10/26 22:36:39 INFO Aborted multipart uploads count=1 kept=015132026/10/26 22:36:39 INFO Received complete multipart upload request method=POST path=/api/multipart/complete15142026/10/26 22:36:39 INFO Received cleanup request method=DELETE path=/api/pending_closures15152026/10/26 22:36:39 INFO Aborted multipart uploads count=1 kept=01516--- PASS: TestPendingCleanupUsesOneCutoff (14.73s)1517=== CONT TestClientMultipleUploads15182026/10/26 22:36:39 INFO Completed multipart upload object_key=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa00000000000000000000.nar.zst upload_id=OWMwNzc0ZDMtYTE4Mi00M2UyLWIzMDYtNWM1NTcyYjI1ZGE4LjRhNjhiYmQzLTc0M2QtNGNkNi1hMzhlLTE0ZDBkNDY1ZmU2NHgxNzkzMDU0MTk3MjcyNDQ3MDAw parts=1015192026/10/26 22:36:39 INFO Received uploads request method=POST path=/api/pending_closures15202026/10/26 22:36:39 INFO Received complete multipart upload request method=POST path=/api/multipart/complete15212026/10/26 22:36:39 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=OWMwNzc0ZDMtYTE4Mi00M2UyLWIzMDYtNWM1NTcyYjI1ZGE4LjRhNTNlMGE3LTQyMzAtNGU4My1hNTFlLTA2ZjFjNzkyYjg5M3gxNzkzMDU0MTk5NDc5MTY1MDAw15222026/10/26 22:36:39 INFO Received uploads request method=POST path=/api/pending_closures15232026/10/26 22:36:39 WARN Failed to abort multipart upload key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=OWMwNzc0ZDMtYTE4Mi00M2UyLWIzMDYtNWM1NTcyYjI1ZGE4LjRhNTNlMGE3LTQyMzAtNGU4My1hNTFlLTA2ZjFjNzkyYjg5M3gxNzkzMDU0MTk5NDc5MTY1MDAw error="Delete \"http://localhost:59205/bucket67/nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst?uploadId=OWMwNzc0ZDMtYTE4Mi00M2UyLWIzMDYtNWM1NTcyYjI1ZGE4LjRhNTNlMGE3LTQyMzAtNGU4My1hNTFlLTA2ZjFjNzkyYjg5M3gxNzkzMDU0MTk5NDc5MTY1MDAw\": injected: abort refused"15242026/10/26 22:36:39 INFO Received complete multipart upload request method=POST path=/api/multipart/complete15252026/10/26 22:36:40 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=OWMwNzc0ZDMtYTE4Mi00M2UyLWIzMDYtNWM1NTcyYjI1ZGE4LjRhNTNlMGE3LTQyMzAtNGU4My1hNTFlLTA2ZjFjNzkyYjg5M3gxNzkzMDU0MTk5NDc5MTY1MDAw15262026/10/26 22:36:40 ERROR Failed to register completed object error="get pending object \"nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst\": context canceled" object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst15272026/10/26 22:36:40 INFO Received complete multipart upload request method=POST path=/api/multipart/complete15282026/10/26 22:36:40 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified multipart upload does not exist. The upload ID may be invalid, or the upload may have been aborted or completed." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=OWMwNzc0ZDMtYTE4Mi00M2UyLWIzMDYtNWM1NTcyYjI1ZGE4LjRhNTNlMGE3LTQyMzAtNGU4My1hNTFlLTA2ZjFjNzkyYjg5M3gxNzkzMDU0MTk5NDc5MTY1MDAw15292026/10/26 22:36:40 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=OWMwNzc0ZDMtYTE4Mi00M2UyLWIzMDYtNWM1NTcyYjI1ZGE4LjRhNTNlMGE3LTQyMzAtNGU4My1hNTFlLTA2ZjFjNzkyYjg5M3gxNzkzMDU0MTk5NDc5MTY1MDAw parts=11530--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (8.58s)1531=== CONT TestService_ReadScope_PublicByDefault1532=== RUN TestPush_RejectsBadRequests/no_roots1533=== PAUSE TestPush_RejectsBadRequests/no_roots1534=== RUN TestPush_RejectsBadRequests/no_objects1535=== PAUSE TestPush_RejectsBadRequests/no_objects1536=== RUN TestPush_RejectsBadRequests/bad_root1537=== PAUSE TestPush_RejectsBadRequests/bad_root1538=== RUN TestPush_RejectsBadRequests/root_not_in_objects1539=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1540=== CONT TestService_AuthMiddleware_OIDC1541--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (11.16s)1542=== CONT TestClientCADerivations15432026/10/26 22:36:40 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:59655/oidc15442026/10/26 22:36:40 INFO Received complete multipart upload request method=POST path=/api/multipart/complete15452026/10/26 22:36:40 INFO Received push request method=POST path=/api/pushes15462026/10/26 22:36:40 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=OWMwNzc0ZDMtYTE4Mi00M2UyLWIzMDYtNWM1NTcyYjI1ZGE4Ljc4NGZlMzVjLTg4NWEtNDAwYS1hZWIwLWJkMDBlMGEwYTcyMXgxNzkzMDU0MTk4MjM0NTMyMDAw parts=1215472026/10/26 22:36:40 INFO Received uploads request method=POST path=/api/pending_closures1548--- PASS: TestCompletedNarNotReofferedAcrossClosures (10.17s)1549=== CONT TestClientIntegration15502026/10/26 22:36:41 INFO Received push request method=POST path=/api/pushes1551=== NAME TestOrphanedObjectsGCStressTest1552 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains1553 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion1554--- PASS: TestCacheStatsHandler (8.36s)1555=== CONT TestService_ReadAuthMiddleware15562026/10/26 22:36:42 INFO Received complete multipart upload request method=POST path=/api/multipart/complete15572026/10/26 22:36:42 INFO Completed multipart upload object_key=nar/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb00000000000000000000.nar.zst upload_id=OWMwNzc0ZDMtYTE4Mi00M2UyLWIzMDYtNWM1NTcyYjI1ZGE4LjUxODUxOWVlLThkNjktNDVmYi05NDU5LTQ5NzZiNDU0N2M1OHgxNzkzMDU0MTk3MjcyNDQ3MDAw parts=1015582026/10/26 22:36:42 INFO Received push request method=POST path=/api/pushes15592026/10/26 22:36:42 WARN Rate limiter enabled after throttle name=s3-test rate=515602026/10/26 22:36:42 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1561=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1562 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101563 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001564--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (12.05s)1565=== CONT TestPush_CompleteCommitsEveryRoot15662026/10/26 22:36:42 INFO Received complete multipart upload request method=POST path=/api/multipart/complete15672026/10/26 22:36:43 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=OWMwNzc0ZDMtYTE4Mi00M2UyLWIzMDYtNWM1NTcyYjI1ZGE4LjdiNGFlMmM2LTU0YjktNDg1Mi1iMDlmLWY4NjdhYmIwNWY4NXgxNzkzMDU0MTk5OTE3NjE0MDAw parts=1215682026/10/26 22:36:43 INFO Received uploads request method=POST path=/api/pending_closures15692026/10/26 22:36:43 INFO Received uploads request method=POST path=/api/pending_closures15702026/10/26 22:36:43 INFO Received complete multipart upload request method=POST path=/api/multipart/complete15712026/10/26 22:36:43 INFO Completed multipart upload object_key=nar/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb00000000000000000000.nar.zst upload_id=OWMwNzc0ZDMtYTE4Mi00M2UyLWIzMDYtNWM1NTcyYjI1ZGE4LjM3MmY1ZTA3LTQzNjQtNDEyYy05OWViLTZhOWE4ZDFkNTA4NngxNzkzMDU0MjAwOTU1MjQwMDAw parts=101572--- PASS: TestGetExistingObjectsLocksRows (8.68s)1573=== CONT TestCacheConfigHandler1574=== RUN TestCacheConfigHandler/full_config,_no_issuer1575=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1576=== RUN TestCacheConfigHandler/no_cache_url_configured1577=== PAUSE TestCacheConfigHandler/no_cache_url_configured1578=== RUN TestCacheConfigHandler/no_signing_keys1579=== PAUSE TestCacheConfigHandler/no_signing_keys1580=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1581=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1582=== CONT TestPush_OverlappingRootsStoreOneRowPerKey15832026-10-26 22:36:44.006 UTC [30507] ERROR: Push does not exist: id=115842026-10-26 22:36:44.006 UTC [30507] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE15852026-10-26 22:36:44.006 UTC [30507] STATEMENT: SELECT commit_push($1)1586=== CONT TestService_AuthMiddleware_MTLSBoundSubjects1587--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (10.87s)15882026/10/26 22:36:44 INFO Received complete multipart upload request method=POST path=/api/multipart/complete15892026/10/26 22:36:44 INFO Completed multipart upload object_key=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa00000000000000000000.nar.zst upload_id=OWMwNzc0ZDMtYTE4Mi00M2UyLWIzMDYtNWM1NTcyYjI1ZGE4LjA5MWE0YmY2LTI0YzYtNDQ1NS1iMDc4LTMwZGFkMmQyZjNmZXgxNzkzMDU0MjAxNDEwMzY4MDAw parts=1015902026/10/26 22:36:44 INFO Received push request method=POST path=/api/pushes15912026/10/26 22:36:44 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)15922026/10/26 22:36:44 INFO Uploading k2kjdjz90nms1v556p05m6szr5d1k0b6-shared-dep (136B)15932026/10/26 22:36:44 INFO Uploading slng9dphg67gp1kvjx7m8rgknf0h5879-b (256B)15942026/10/26 22:36:44 WARN Failed to register uploaded object key=561bhn2rjj76gdvbyrski8f0d6q9zyn1.ls error="server returned 404: 404 page not found\n"15952026/10/26 22:36:44 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"15962026/10/26 22:36:44 WARN Failed to register uploaded object key=nar/1q2k2k4yi7ngx0sicspv1yj2gjlipdqf4aqr7a96ybv522wdk33i.nar.zst error="server returned 404: 404 page not found\n"15972026/10/26 22:36:44 WARN Failed to register uploaded object key=k2kjdjz90nms1v556p05m6szr5d1k0b6.ls error="server returned 404: 404 page not found\n"15982026/10/26 22:36:45 WARN Failed to register uploaded object key=slng9dphg67gp1kvjx7m8rgknf0h5879.ls error="server returned 404: 404 page not found\n"15992026/10/26 22:36:45 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16002026/10/26 22:36:45 INFO Signed narinfos id=1 count=316012026/10/26 22:36:45 INFO Uploading 3 narinfos16022026/10/26 22:36:45 WARN Failed to register uploaded object key=k2kjdjz90nms1v556p05m6szr5d1k0b6.narinfo error="server returned 404: 404 page not found\n"16032026/10/26 22:36:45 WARN Failed to register uploaded object key=561bhn2rjj76gdvbyrski8f0d6q9zyn1.narinfo error="server returned 404: 404 page not found\n"16042026/10/26 22:36:45 INFO Received complete multipart upload request method=POST path=/api/multipart/complete16052026/10/26 22:36:45 INFO Received complete push request method=POST path=/api/pushes/1/complete16062026/10/26 22:36:45 WARN Failed to register uploaded object key=slng9dphg67gp1kvjx7m8rgknf0h5879.narinfo error="server returned 404: 404 page not found\n"16072026/10/26 22:36:45 INFO Completed push id=1 objects=8 duration=78.07975ms16082026/10/26 22:36:45 INFO Upload complete. (647ms)1609=== NAME TestClientPushesUseOnePush1610 client_pushes_test.go:97: Retrieved narinfo from S3:1611 StorePath: /private/var/tb/6/scratch/bedec206597db7e3/build/TestClientPushesUseOnePush2368558504/001/store/k2kjdjz90nms1v556p05m6szr5d1k0b6-shared-dep1612 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1613 Compression: zstd1614 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y8216152026/10/26 22:36:45 INFO Completed multipart upload object_key=nar/cccccccccccccccccccccccccccccccc00000000000000000000.nar.zst upload_id=OWMwNzc0ZDMtYTE4Mi00M2UyLWIzMDYtNWM1NTcyYjI1ZGE4LjkyOTU5ZTVhLTYxMDUtNGY3NC05ZmU4LTNkNDc4NDlmODY5YXgxNzkzMDU0MTk3MjcyNTA1MDAw parts=101616 NarSize: 1361617 References: 1618 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1619 client_pushes_test.go:97: Retrieved narinfo from S3:1620 StorePath: /private/var/tb/6/scratch/bedec206597db7e3/build/TestClientPushesUseOnePush2368558504/001/store/561bhn2rjj76gdvbyrski8f0d6q9zyn1-a1621 URL: nar/1q2k2k4yi7ngx0sicspv1yj2gjlipdqf4aqr7a96ybv522wdk33i.nar.zst1622 Compression: zstd1623 NarHash: sha256:1q2k2k4yi7ngx0sicspv1yj2gjlipdqf4aqr7a96ybv522wdk33i1624 NarSize: 2561625 References: /private/var/tb/6/scratch/bedec206597db7e3/build/TestClientPushesUseOnePush2368558504/001/store/k2kjdjz90nms1v556p05m6szr5d1k0b6-shared-dep1626 CA: text:sha256:02wcma4npv8jipc7bycqsz027mpd4587dk3a0sdn6z35fshs86i91627 client_pushes_test.go:97: Retrieved narinfo from S3:1628 StorePath: /private/var/tb/6/scratch/bedec206597db7e3/build/TestClientPushesUseOnePush2368558504/001/store/slng9dphg67gp1kvjx7m8rgknf0h5879-b1629 URL: nar/1q2k2k4yi7ngx0sicspv1yj2gjlipdqf4aqr7a96ybv522wdk33i.nar.zst1630 Compression: zstd1631 NarHash: sha256:1q2k2k4yi7ngx0sicspv1yj2gjlipdqf4aqr7a96ybv522wdk33i1632 NarSize: 2561633 References: /private/var/tb/6/scratch/bedec206597db7e3/build/TestClientPushesUseOnePush2368558504/001/store/k2kjdjz90nms1v556p05m6szr5d1k0b6-shared-dep1634 CA: text:sha256:02wcma4npv8jipc7bycqsz027mpd4587dk3a0sdn6z35fshs86i91635--- PASS: TestClientPushesUseOnePush (11.47s)1636=== CONT TestService_AuthMiddleware16372026/10/26 22:36:45 INFO Received complete multipart upload request method=POST path=/api/multipart/complete16382026/10/26 22:36:45 INFO Aborted multipart uploads count=0 kept=016392026/10/26 22:36:45 INFO Completed multipart upload object_key=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa00000000000000000000.nar.zst upload_id=OWMwNzc0ZDMtYTE4Mi00M2UyLWIzMDYtNWM1NTcyYjI1ZGE4LmY2ODZkZmZmLTBmYTQtNGY2YS1hOTg4LTZmZjFkYTRjZmMwZngxNzkzMDU0MjAyNDg1NDQyMDAw parts=1016402026/10/26 22:36:45 WARN Force mode enabled - objects will be deleted immediately without grace period16412026/10/26 22:36:45 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=016422026/10/26 22:36:46 INFO Vacuumed table table=pending_closures16432026/10/26 22:36:46 INFO Received push request method=POST path=/api/pushes16442026/10/26 22:36:46 INFO Vacuumed table table=pending_objects16452026/10/26 22:36:46 INFO Vacuumed table table=multipart_uploads16462026/10/26 22:36:46 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)16472026/10/26 22:36:46 INFO Uploading ibyc131f9bnzn513qagmzbjl6v2gllny-top (264B)16482026/10/26 22:36:46 INFO Uploading c8mnr2cda8jh5ch73grb78gsa8il02hb-shared-dep (136B)16492026/10/26 22:36:46 INFO Vacuumed table table=closures16502026/10/26 22:36:46 INFO Vacuumed table table=objects16512026/10/26 22:36:46 WARN Failed to register uploaded object key=nar/1m56kb3b1gs5cn96f493k9rccxjbgfgxij1h6z126cywybzf49x2.nar.zst error="server returned 404: 404 page not found\n"1652--- PASS: TestSweepRechecksPendingAfterLocking (10.04s)1653=== CONT TestService_RequireScope_OIDC16542026/10/26 22:36:46 WARN Failed to register uploaded object key=c8mnr2cda8jh5ch73grb78gsa8il02hb.ls error="server returned 404: 404 page not found\n"16552026/10/26 22:36:46 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"16562026/10/26 22:36:46 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16572026/10/26 22:36:46 WARN Failed to register uploaded object key=ibyc131f9bnzn513qagmzbjl6v2gllny.ls error="server returned 404: 404 page not found\n"16582026/10/26 22:36:46 INFO Signed narinfos id=1 count=216592026/10/26 22:36:46 INFO Uploading 2 narinfos16602026/10/26 22:36:46 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:59730/oidc16612026/10/26 22:36:46 WARN Failed to register uploaded object key=ibyc131f9bnzn513qagmzbjl6v2gllny.narinfo error="server returned 404: 404 page not found\n"16622026/10/26 22:36:46 INFO Received complete push request method=POST path=/api/pushes/1/complete16632026/10/26 22:36:46 WARN Failed to register uploaded object key=c8mnr2cda8jh5ch73grb78gsa8il02hb.narinfo error="server returned 404: 404 page not found\n"16642026/10/26 22:36:46 INFO Completed push id=1 objects=6 duration=49.941875ms16652026/10/26 22:36:46 INFO Upload complete. (536ms)1666=== NAME TestClientSharedPathCommittedMidPush1667 client_integration_test.go:803: Retrieved narinfo from S3:1668 StorePath: /private/var/tb/6/scratch/bedec206597db7e3/build/TestClientSharedPathCommittedMidPush346357540/001/store/c8mnr2cda8jh5ch73grb78gsa8il02hb-shared-dep1669 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1670 Compression: zstd1671 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821672 NarSize: 1361673 References: 1674 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1675 client_integration_test.go:803: Retrieved narinfo from S3:1676 StorePath: /private/var/tb/6/scratch/bedec206597db7e3/build/TestClientSharedPathCommittedMidPush346357540/001/store/ibyc131f9bnzn513qagmzbjl6v2gllny-top1677 URL: nar/1m56kb3b1gs5cn96f493k9rccxjbgfgxij1h6z126cywybzf49x2.nar.zst1678 Compression: zstd1679 NarHash: sha256:1m56kb3b1gs5cn96f493k9rccxjbgfgxij1h6z126cywybzf49x21680 NarSize: 2641681 References: /private/var/tb/6/scratch/bedec206597db7e3/build/TestClientSharedPathCommittedMidPush346357540/001/store/c8mnr2cda8jh5ch73grb78gsa8il02hb-shared-dep1682 CA: text:sha256:1kp6m5r1irvsiidf5wq7604brxv14ys4n56s9fhbzibah62krsza1683--- PASS: TestClientSharedPathCommittedMidPush (10.74s)1684=== CONT TestReadProxyRootRedirectsToIndexHTML16852026/10/26 22:36:46 INFO Received complete multipart upload request method=POST path=/api/multipart/complete16862026/10/26 22:36:46 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=OWMwNzc0ZDMtYTE4Mi00M2UyLWIzMDYtNWM1NTcyYjI1ZGE4LmVjZDhmZjgyLTYwMjAtNGFkNi04OGMxLTdhOGVmNzU2ZDZjOXgxNzkzMDU0MjAzMzExODI4MDAw error="Get \"http://127.0.0.1:1/bucket68/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"16872026/10/26 22:36:46 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=OWMwNzc0ZDMtYTE4Mi00M2UyLWIzMDYtNWM1NTcyYjI1ZGE4LjA5M2QwNGU4LTI0Y2ItNGY1ZC05MmU1LWJjMDBhNTZiYzM2YXgxNzkzMDU0MjAzMjE2MTg3MDAw parts=1216882026/10/26 22:36:47 INFO Received cleanup request method=DELETE path=/api/pending_closures16892026/10/26 22:36:47 INFO Aborted multipart uploads count=1 kept=01690=== NAME TestPinProtectsFromGC1691 client_integration_test.go:854: Pinned store path: /private/var/tb/6/scratch/bedec206597db7e3/build/TestPinProtectsFromGC3458340302/001/store/yrqsgih6xxh0f08rjgmyha9q1cl8dai9-pinned-file.txt1692 client_integration_test.go:855: Unpinned store path: /private/var/tb/6/scratch/bedec206597db7e3/build/TestPinProtectsFromGC3458340302/001/store/0gxcax5agb5cmw7pd5xnaijccdxkz9b9-unpinned-file.txt1693--- PASS: TestRedundantMultipartUpload (14.92s)1694=== CONT TestPendingClosureFailureTracksEveryUpload/refuse_aborts=true16952026/10/26 22:36:47 INFO Received push request method=POST path=/api/pushes16962026/10/26 22:36:47 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16972026/10/26 22:36:47 INFO Received uploads request method=POST path=/api/pending_closures16982026/10/26 22:36:47 INFO Uploading yrqsgih6xxh0f08rjgmyha9q1cl8dai9-pinned-file.txt (128B)16992026/10/26 22:36:47 WARN Failed to register uploaded object key=yrqsgih6xxh0f08rjgmyha9q1cl8dai9.ls error="server returned 404: 404 page not found\n"17002026/10/26 22:36:47 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"17012026/10/26 22:36:47 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17022026/10/26 22:36:47 INFO Signed narinfos id=1 count=117032026/10/26 22:36:47 INFO Received complete multipart upload request method=POST path=/api/multipart/complete17042026/10/26 22:36:47 INFO Uploading 1 narinfos17052026/10/26 22:36:47 INFO Received complete push request method=POST path=/api/pushes/1/complete17062026/10/26 22:36:47 WARN Failed to register uploaded object key=yrqsgih6xxh0f08rjgmyha9q1cl8dai9.narinfo error="server returned 404: 404 page not found\n"17072026/10/26 22:36:47 INFO Completed multipart upload object_key=nar/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb00000000000000000000.nar.zst upload_id=OWMwNzc0ZDMtYTE4Mi00M2UyLWIzMDYtNWM1NTcyYjI1ZGE4LjUwMDQ1MDc0LWYzZjAtNDUyNC1hMmEyLWJhMDhiMWIxMmVkNngxNzkzMDU0MjAxNDExMTEyMDAw parts=1017082026/10/26 22:36:47 INFO Received complete push request method=POST path=/api/pushes/1/complete17092026/10/26 22:36:47 INFO Completed push id=1 objects=3 duration=28.075042ms17102026/10/26 22:36:47 INFO Upload complete. (437ms)17112026/10/26 22:36:47 INFO Completed push id=1 objects=4 duration=23.747166ms17122026/10/26 22:36:47 INFO Received push request method=POST path=/api/pushes1713=== NAME TestClientWithDependencies1714 client_integration_test.go:722: Built derivation: /private/var/tb/6/scratch/bedec206597db7e3/build/TestClientWithDependencies3330017192/001/store/33nw3dbbachg6svflac0lps0najj1ymj-test-script17152026/10/26 22:36:47 INFO Received push request method=POST path=/api/pushes1716 client_integration_test.go:724: Found 1 dependencies (including self)17172026/10/26 22:36:47 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17182026/10/26 22:36:47 INFO Uploading 0gxcax5agb5cmw7pd5xnaijccdxkz9b9-unpinned-file.txt (128B)1719--- PASS: TestPushWaitsForSweepHoldingRow (9.41s)1720=== CONT TestPendingClosureFailureTracksEveryUpload/refuse_aborts=false17212026/10/26 22:36:47 INFO Aborted multipart uploads count=0 kept=017222026/10/26 22:36:47 WARN Force mode enabled - objects will be deleted immediately without grace period17232026/10/26 22:36:47 WARN Failed to register uploaded object key=0gxcax5agb5cmw7pd5xnaijccdxkz9b9.ls error="server returned 404: 404 page not found\n"17242026/10/26 22:36:47 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign17252026/10/26 22:36:47 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"17262026/10/26 22:36:47 INFO Signed narinfos id=2 count=117272026/10/26 22:36:47 INFO Uploading 1 narinfos1728--- PASS: TestReadRedirectKeepsNarinfoProxied (9.13s)1729=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check17302026/10/26 22:36:47 INFO Received push request method=POST path=/api/pushes17312026/10/26 22:36:47 INFO Received complete push request method=POST path=/api/pushes/2/complete17322026/10/26 22:36:47 WARN Failed to register uploaded object key=0gxcax5agb5cmw7pd5xnaijccdxkz9b9.narinfo error="server returned 404: 404 page not found\n"17332026/10/26 22:36:47 INFO Completed push id=2 objects=3 duration=1.636792ms17342026/10/26 22:36:47 INFO Upload complete. (388ms)17352026/10/26 22:36:47 INFO Received complete multipart upload request method=POST path=/api/multipart/complete17362026/10/26 22:36:47 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17372026/10/26 22:36:47 INFO Uploading 33nw3dbbachg6svflac0lps0najj1ymj-test-script (136B)17382026/10/26 22:36:48 INFO Starting cleanup of old closures method=DELETE path=/api/closures17392026/10/26 22:36:48 INFO Garbage collection started17402026/10/26 22:36:48 INFO Aborted multipart uploads count=0 kept=017412026/10/26 22:36:48 INFO Completed multipart upload object_key=nar/dddddddddddddddddddddddddddddddd00000000000000000000.nar.zst upload_id=OWMwNzc0ZDMtYTE4Mi00M2UyLWIzMDYtNWM1NTcyYjI1ZGE4LmE3NDhmMDliLTU3YWQtNGE5MS1hZjA4LWIyODMxMWI5YWM0MHgxNzkzMDU0MTk3MjcyNDgyMDAw parts=1017422026/10/26 22:36:48 WARN Force mode enabled - objects will be deleted immediately without grace period17432026/10/26 22:36:48 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"17442026/10/26 22:36:48 WARN Failed to register uploaded object key=33nw3dbbachg6svflac0lps0najj1ymj.ls error="server returned 404: 404 page not found\n"17452026/10/26 22:36:48 WARN Failed to register uploaded object key=log/andp81hq0r9ynip084wa62ilg9dsshzz-test-script.drv error="server returned 404: 404 page not found\n"17462026/10/26 22:36:48 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17472026/10/26 22:36:48 INFO Signed narinfos id=1 count=117482026/10/26 22:36:48 INFO Uploading 1 narinfos17492026/10/26 22:36:48 INFO Received complete push request method=POST path=/api/pushes/1/complete17502026/10/26 22:36:48 WARN Failed to register uploaded object key=33nw3dbbachg6svflac0lps0najj1ymj.narinfo error="server returned 404: 404 page not found\n"17512026/10/26 22:36:48 INFO Received complete multipart upload request method=POST path=/api/multipart/complete17522026/10/26 22:36:48 INFO Received uploads request method=POST path=/api/pending_closures17532026/10/26 22:36:48 INFO Completed push id=1 objects=4 duration=79.67275ms17542026/10/26 22:36:48 INFO Upload complete. (596ms)17552026/10/26 22:36:48 INFO Aborted multipart uploads count=0 kept=017562026/10/26 22:36:48 WARN Force mode enabled - objects will be deleted immediately without grace period17572026/10/26 22:36:48 INFO Completed multipart upload object_key=nar/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb00000000000000000000.nar.zst upload_id=OWMwNzc0ZDMtYTE4Mi00M2UyLWIzMDYtNWM1NTcyYjI1ZGE4LmFkNjk3NjRhLTljZDUtNDRjZC04MjgzLWY2MTc5NmM3ZmMyZHgxNzkzMDU0MjAyNDg0NjU4MDAw parts=1017582026/10/26 22:36:48 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=017592026/10/26 22:36:48 INFO Vacuumed table table=pending_closures17602026/10/26 22:36:48 INFO Received complete push request method=POST path=/api/pushes/1/complete17612026/10/26 22:36:48 INFO Vacuumed table table=pending_objects17622026/10/26 22:36:48 INFO Vacuumed table table=multipart_uploads17632026/10/26 22:36:48 INFO Completed push id=1 objects=4 duration=46.3785ms17642026/10/26 22:36:48 INFO Aborted multipart uploads count=0 kept=01765--- PASS: TestPush_RepeatedRootCommitsOnce (14.67s)1766=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows17672026/10/26 22:36:48 INFO Vacuumed table table=closures17682026/10/26 22:36:48 WARN Force mode enabled - objects will be deleted immediately without grace period17692026/10/26 22:36:48 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=017702026/10/26 22:36:48 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."17712026/10/26 22:36:48 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."17722026/10/26 22:36:48 INFO Vacuumed table table=objects17732026/10/26 22:36:48 INFO Vacuumed table table=pending_closures1774--- PASS: TestFailedS3DeleteKeepsTombstone (10.27s)1775=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale1776=== NAME TestClientWithDependencies1777 client_integration_test.go:740: Skipping nix copy test - isolated store (/private/var/tb/6/scratch/bedec206597db7e3/build/TestClientWithDependencies3330017192/001/store) requires matching store prefix17782026/10/26 22:36:48 INFO Vacuumed table table=pending_objects17792026/10/26 22:36:48 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=017802026/10/26 22:36:48 INFO Vacuumed table table=multipart_uploads17812026/10/26 22:36:48 INFO Vacuumed table table=pending_closures17822026/10/26 22:36:48 INFO Vacuumed table table=closures17832026/10/26 22:36:48 INFO Vacuumed table table=pending_objects17842026/10/26 22:36:48 INFO Vacuumed table table=multipart_uploads17852026/10/26 22:36:48 INFO Vacuumed table table=objects1786--- PASS: TestClientWithDependencies (10.33s)1787=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh17882026/10/26 22:36:49 INFO Vacuumed table table=closures17892026/10/26 22:36:49 INFO Aborted multipart uploads count=0 kept=017902026/10/26 22:36:49 WARN Force mode enabled - objects will be deleted immediately without grace period17912026/10/26 22:36:49 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=017922026/10/26 22:36:49 INFO Vacuumed table table=objects17932026/10/26 22:36:49 INFO Vacuumed table table=pending_closures17942026/10/26 22:36:49 INFO Vacuumed table table=pending_objects17952026/10/26 22:36:49 INFO Vacuumed table table=multipart_uploads17962026/10/26 22:36:49 INFO Vacuumed table table=closures17972026/10/26 22:36:49 INFO Vacuumed table table=objects17982026/10/26 22:36:49 INFO Aborted multipart uploads count=0 kept=017992026/10/26 22:36:49 WARN Force mode enabled - objects will be deleted immediately without grace period18002026/10/26 22:36:49 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=1 objects-failed-to-delete=018012026/10/26 22:36:49 INFO Vacuumed table table=pending_closures18022026/10/26 22:36:49 INFO Vacuumed table table=pending_objects18032026/10/26 22:36:49 INFO Vacuumed table table=multipart_uploads18042026/10/26 22:36:49 INFO Vacuumed table table=closures18052026/10/26 22:36:49 INFO Vacuumed table table=objects1806--- PASS: TestSweepSkipsRowsLockedByPush (10.53s)1807=== CONT TestIsValidCachePath/narinfo1808=== CONT TestIsValidCachePath/nix-cache-info1809=== CONT TestIsValidCachePath/short_hash1810=== CONT TestIsValidCachePath/wrong_extension1811=== CONT TestIsValidCachePath/empty1812=== CONT TestIsValidCachePath/random_path1813=== CONT TestIsValidCachePath/invalid_char_u1814=== CONT TestIsValidCachePath/invalid_char_e1815=== CONT TestIsValidCachePath/traversal_in_middle1816=== CONT TestIsValidCachePath/leading_slash1817=== CONT TestIsValidCachePath/index.html1818=== CONT TestIsValidCachePath/nar_uncompressed1819=== CONT TestIsValidCachePath/realisation1820=== CONT TestIsValidCachePath/log1821=== CONT TestIsValidCachePath/traversal_parent1822=== CONT TestIsValidCachePath/ls1823=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1824=== CONT TestIsValidCachePath/nar_bz21825=== CONT TestIsValidCachePath/nar_xz1826=== CONT TestIsValidCachePath/nar_zst1827--- PASS: TestIsValidCachePath (0.01s)1828 --- PASS: TestIsValidCachePath/narinfo (0.00s)1829 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1830 --- PASS: TestIsValidCachePath/short_hash (0.00s)1831 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1832 --- PASS: TestIsValidCachePath/empty (0.00s)1833 --- PASS: TestIsValidCachePath/random_path (0.00s)1834 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1835 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1836 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1837 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1838 --- PASS: TestIsValidCachePath/index.html (0.00s)1839 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1840 --- PASS: TestIsValidCachePath/realisation (0.00s)1841 --- PASS: TestIsValidCachePath/log (0.00s)1842 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1843 --- PASS: TestIsValidCachePath/ls (0.00s)1844 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1845 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1846 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1847 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1848=== CONT TestParseSingleRange/none1849=== CONT TestParseSingleRange/open-ended1850=== CONT TestParseSingleRange/start_far_past_EOF1851=== CONT TestParseSingleRange/single_byte1852=== CONT TestParseSingleRange/start_past_EOF1853=== CONT TestParseSingleRange/suffix1854=== CONT TestParseSingleRange/suffix_exceeds_size1855=== CONT TestParseSingleRange/end_clamped_to_size1856=== CONT TestParseSingleRange/closed1857=== CONT TestParseSingleRange/malformed_end_before_start1858=== CONT TestParseSingleRange/malformed_both_empty1859=== CONT TestParseSingleRange/multi-range_ignored1860=== CONT TestParseSingleRange/malformed_no_dash1861=== CONT TestParseSingleRange/unknown_unit1862--- PASS: TestParseSingleRange (0.01s)1863 --- PASS: TestParseSingleRange/none (0.00s)1864 --- PASS: TestParseSingleRange/open-ended (0.00s)1865 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1866 --- PASS: TestParseSingleRange/single_byte (0.00s)1867 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1868 --- PASS: TestParseSingleRange/suffix (0.00s)1869 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1870 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1871 --- PASS: TestParseSingleRange/closed (0.00s)1872 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1873 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1874 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1875 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1876 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1877=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts18782026/10/26 22:36:49 INFO Received request for more parts method=POST path=/1879--- PASS: TestService_ReadScope_PublicByDefault (9.70s)1880=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart18812026/10/26 22:36:49 INFO Received complete multipart upload request method=POST path=/1882=== NAME TestClientMultipleUploads1883 client_integration_test.go:467: Created store path 0: /private/var/tb/6/scratch/bedec206597db7e3/build/TestClientMultipleUploads1156209793/001/store/xpnngqnhszqrqalgp8lanz44lgm4dx6x-test-file-0.txt18842026/10/26 22:36:50 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=01885 client_integration_test.go:467: Created store path 1: /private/var/tb/6/scratch/bedec206597db7e3/build/TestClientMultipleUploads1156209793/001/store/4q01xc90sc6n51ahw1wknibmjcdrn7cw-test-file-1.txt1886=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure18872026/10/26 22:36:50 INFO Received uploads request method=POST path=/1888=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal18892026/10/26 22:36:50 INFO Received uploads request method=POST path=/1890=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key18912026/10/26 22:36:50 INFO Received request for more parts method=POST path=/1892=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key18932026/10/26 22:36:50 INFO Received create pin request method=POST path=/api/pins/myapp18942026/10/26 22:36:50 INFO Received complete multipart upload request method=POST path=/1895=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info18962026/10/26 22:36:50 INFO Received uploads request method=POST path=/1897=== CONT TestIsValidUploadKey/nar_zst1898--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1899 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1900 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1901 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.01s)1902 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1903=== CONT TestIsValidUploadKey/realisation1904=== CONT TestIsValidUploadKey/unknown_type1905=== CONT TestIsValidUploadKey/absolute1906=== CONT TestIsValidUploadKey/traversal_nar1907=== CONT TestIsValidUploadKey/empty_key1908=== CONT TestIsValidUploadKey/build_log_plus_in_name1909=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1910=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1911=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1912=== CONT TestIsValidUploadKey/build_log_question_mark1913=== CONT TestIsValidUploadKey/traversal1914=== CONT TestIsValidUploadKey/build_log_equals1915=== CONT TestIsValidUploadKey/index.html19162026/10/26 22:36:50 INFO Created/updated pin name=myapp store_path=/private/var/tb/6/scratch/bedec206597db7e3/build/TestPinProtectsFromGC3458340302/001/store/yrqsgih6xxh0f08rjgmyha9q1cl8dai9-pinned-file.txt narinfo_key=yrqsgih6xxh0f08rjgmyha9q1cl8dai9.narinfo1917=== CONT TestIsValidUploadKey/build_log_home-manager_file19182026/10/26 22:36:50 INFO Starting cleanup of old closures method=DELETE path=/api/closures1919=== CONT TestIsValidUploadKey/nix-cache-info19202026/10/26 22:36:50 INFO Garbage collection started19212026/10/26 22:36:50 INFO Aborted multipart uploads count=0 kept=01922=== CONT TestIsValidUploadKey/build_log1923=== CONT TestIsValidUploadKey/realisation_plus_in_output19242026/10/26 22:36:50 WARN Force mode enabled - objects will be deleted immediately without grace period1925=== CONT TestIsValidUploadKey/nar_xz19262026/10/26 22:36: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=01927=== CONT TestIsValidUploadKey/narinfo19282026/10/26 22:36:50 INFO Vacuumed table table=pending_closures1929=== NAME TestClientMultipleUploads19302026/10/26 22:36:50 INFO Vacuumed table table=pending_objects1931 client_integration_test.go:467: Created store path 2: /private/var/tb/6/scratch/bedec206597db7e3/build/TestClientMultipleUploads1156209793/001/store/y4y1rsxabxsw7dbzlbrfx9agmhibb9jl-test-file-2.txt19322026/10/26 22:36:50 INFO Vacuumed table table=multipart_uploads1933=== CONT TestIsValidUploadKey/listing19342026/10/26 22:36:50 INFO Vacuumed table table=closures1935=== CONT TestIsValidUploadKey/nar_plain19362026/10/26 22:36:50 INFO Vacuumed table table=objects1937=== CONT TestProxyWriteTimeout/10_GiB_nar1938--- PASS: TestIsValidUploadKey (0.01s)1939 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1940 --- PASS: TestIsValidUploadKey/realisation (0.00s)1941 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1942 --- PASS: TestIsValidUploadKey/absolute (0.00s)1943 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1944 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1945 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1946 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1947 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1948 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1949 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1950 --- PASS: TestIsValidUploadKey/traversal (0.00s)1951 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1952 --- PASS: TestIsValidUploadKey/index.html (0.00s)1953 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1954 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1955 --- PASS: TestIsValidUploadKey/build_log (0.00s)1956 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1957 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1958 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1959 --- PASS: TestIsValidUploadKey/listing (0.00s)1960 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1961=== CONT TestProxyWriteTimeout/1_GiB_nar19622026/10/26 22:36:50 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1963=== CONT TestProxyWriteTimeout/unknown_size1964=== CONT TestProxyWriteTimeout/narinfo1965=== CONT TestPendingClosureWriteTimeout/670k_objects1966=== CONT TestPendingClosureWriteTimeout/400_objects1967--- PASS: TestProxyWriteTimeout (0.00s)1968 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1969 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1970 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1971 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1972=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline19732026/10/26 22:36:50 INFO Completed multipart upload object_key=nar/ffffffffffffffffffffffffffffffff00000000000000000000.nar.zst upload_id=OWMwNzc0ZDMtYTE4Mi00M2UyLWIzMDYtNWM1NTcyYjI1ZGE4LjE1MjQ5NjMyLThhMDQtNGE1NC04NWQ1LTgwNjRmYWYxYzdhZngxNzkzMDU0MTk3MjcyNTM2MDAw parts=1019742026/10/26 22:36:50 INFO Received push request method=POST path=/api/pushes19752026/10/26 22:36:50 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)19762026/10/26 22:36:50 INFO Uploading y4y1rsxabxsw7dbzlbrfx9agmhibb9jl-test-file-2.txt (160B)19772026/10/26 22:36:50 INFO Uploading 4q01xc90sc6n51ahw1wknibmjcdrn7cw-test-file-1.txt (160B)19782026/10/26 22:36:50 INFO Uploading xpnngqnhszqrqalgp8lanz44lgm4dx6x-test-file-0.txt (160B)19792026/10/26 22:36:50 WARN Failed to register uploaded object key=y4y1rsxabxsw7dbzlbrfx9agmhibb9jl.ls error="server returned 404: 404 page not found\n"19802026/10/26 22:36:50 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"19812026/10/26 22:36:50 WARN Failed to register uploaded object key=4q01xc90sc6n51ahw1wknibmjcdrn7cw.ls error="server returned 404: 404 page not found\n"19822026/10/26 22:36:50 WARN Failed to register uploaded object key=xpnngqnhszqrqalgp8lanz44lgm4dx6x.ls error="server returned 404: 404 page not found\n"19832026/10/26 22:36:50 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"19842026/10/26 22:36:50 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"19852026/10/26 22:36:50 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19862026/10/26 22:36:50 INFO Signed narinfos id=1 count=319872026/10/26 22:36:50 INFO Uploading 3 narinfos19882026/10/26 22:36:50 WARN Failed to register uploaded object key=xpnngqnhszqrqalgp8lanz44lgm4dx6x.narinfo error="server returned 404: 404 page not found\n"19892026/10/26 22:36:50 WARN Failed to register uploaded object key=y4y1rsxabxsw7dbzlbrfx9agmhibb9jl.narinfo error="server returned 404: 404 page not found\n"19902026/10/26 22:36:50 INFO Received complete push request method=POST path=/api/pushes/1/complete19912026/10/26 22:36:50 WARN Failed to register uploaded object key=4q01xc90sc6n51ahw1wknibmjcdrn7cw.narinfo error="server returned 404: 404 page not found\n"1992=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1993=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1994=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1995=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1996=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1997=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1998=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1999=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2000=== CONT TestPendingClosureWriteTimeout/empty2001=== CONT TestServerTLSConfig/not_a_PEM_file20022026/10/26 22:36:50 INFO Completed push id=1 objects=9 duration=54.322125ms20032026/10/26 22:36:50 INFO Upload complete. (502ms)2004=== NAME TestClientMultipleUploads2005 client_integration_test.go:478: Uploaded 3 paths in 544.185584ms2006=== CONT TestServerTLSConfig/missing_CA_file2007=== CONT TestServerTLSConfig/no_client_CA2008--- PASS: TestServerTLSConfig (0.00s)2009 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.05s)2010 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)2011 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)2012=== CONT TestResolveDBConnectionString/nothing_configured2013=== CONT TestResolveDBConnectionString/missing_file_is_an_error2014=== CONT TestResolveDBConnectionString/PGHOST_allows_empty2015=== CONT TestResolveDBConnectionString/file_when_flag_empty2016=== CONT TestResolveDBConnectionString/flag_wins2017=== CONT TestGCEndsOnShutdown/before_the_run2018--- PASS: TestResolveDBConnectionString (0.07s)2019 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)2020 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)2021 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)2022 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)2023 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)2024--- PASS: TestClientMultipleUploads (11.48s)2025=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark20262026/10/26 22:36:51 INFO Received complete multipart upload request method=POST path=/api/multipart/complete20272026/10/26 22:36:51 INFO Completed multipart upload object_key=nar/cccccccccccccccccccccccccccccccc00000000000000000000.nar.zst upload_id=OWMwNzc0ZDMtYTE4Mi00M2UyLWIzMDYtNWM1NTcyYjI1ZGE4LmY4OWQ3NGRiLTk4MGEtNDJiNi05YTQ4LWM3Y2RkZTUyNjMyNXgxNzkzMDU0MjA3NTM1MzIzMDAw parts=1020282026/10/26 22:36:51 INFO Received complete push request method=POST path=/api/pushes/2/complete20292026/10/26 22:36:51 INFO Completed push id=2 objects=4 duration=5.599042ms2030=== NAME TestClientCADerivations2031 client_ca_test.go:136: Built CA derivation: /private/var/tb/6/scratch/bedec206597db7e3/build/TestClientCADerivations963802304/001/store/kkqp37256qdvxjnyin77vd8y0zdxgrda-ca-test2032=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete2033--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (18.33s)2034=== NAME TestClientCADerivations2035 client_ca_test.go:139: Found 1 dependencies (including self)20362026/10/26 22:36:51 INFO Received push request method=POST path=/api/pushes2037--- PASS: TestService_ReadAuthMiddleware (9.83s)2038=== CONT TestClientErrorHandling/InvalidStorePath20392026/10/26 22:36:51 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)20402026/10/26 22:36:51 INFO Uploading kkqp37256qdvxjnyin77vd8y0zdxgrda-ca-test (144B)2041=== NAME TestClientIntegration2042 client_integration_test.go:331: Created store path: /private/var/tb/6/scratch/bedec206597db7e3/build/TestClientIntegration1348781518/002/store/gwvxh3p4j5d1aq6gdrdg95kqrn44ffzm-test-file.txt20432026/10/26 22:36:51 WARN Failed to register uploaded object key=kkqp37256qdvxjnyin77vd8y0zdxgrda.ls error="server returned 404: 404 page not found\n"20442026/10/26 22:36:51 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"20452026/10/26 22:36:52 WARN Failed to register uploaded object key=log/g7f1ivmd9jfk913hn0dsic9w07izkkqj-ca-test.drv error="server returned 404: 404 page not found\n"20462026/10/26 22:36:52 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign20472026/10/26 22:36:52 INFO Signed narinfos id=1 count=120482026/10/26 22:36:52 INFO Uploading 1 narinfos20492026/10/26 22:36:52 WARN Failed to register uploaded object key=kkqp37256qdvxjnyin77vd8y0zdxgrda.narinfo error="server returned 404: 404 page not found\n"20502026/10/26 22:36:52 INFO Received complete push request method=POST path=/api/pushes/1/complete20512026/10/26 22:36:52 INFO Received push request method=POST path=/api/pushes20522026/10/26 22:36:52 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)20532026/10/26 22:36:52 INFO Uploading gwvxh3p4j5d1aq6gdrdg95kqrn44ffzm-test-file.txt (152B)20542026/10/26 22:36:52 INFO Completed push id=1 objects=4 duration=55.159875ms20552026/10/26 22:36:52 INFO Upload complete. (497ms)2056=== NAME TestClientCADerivations2057 client_ca_test.go:180: Narinfo contains CA field: StorePath: /private/var/tb/6/scratch/bedec206597db7e3/build/TestClientCADerivations963802304/001/store/kkqp37256qdvxjnyin77vd8y0zdxgrda-ca-test2058 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst2059 Compression: zstd2060 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2061 NarSize: 1442062 References: 2063 Deriver: /private/var/tb/6/scratch/bedec206597db7e3/build/TestClientCADerivations963802304/001/store/g7f1ivmd9jfk913hn0dsic9w07izkkqj-ca-test.drv2064 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2065 client_ca_test.go:185: Checking for realisation files in S3...2066 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations2067 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache20682026/10/26 22:36:52 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign20692026/10/26 22:36:52 WARN Failed to register uploaded object key=gwvxh3p4j5d1aq6gdrdg95kqrn44ffzm.ls error="server returned 404: 404 page not found\n"20702026/10/26 22:36:52 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"20712026/10/26 22:36:52 INFO Signed narinfos id=1 count=120722026/10/26 22:36:52 INFO Uploading 1 narinfos2073=== NAME TestPinProtectsFromGC2074 client_integration_test.go:963: Pin successfully protected closure from garbage collection20752026/10/26 22:36:52 INFO Received push request method=POST path=/api/pushes20762026/10/26 22:36:52 INFO Received complete push request method=POST path=/api/pushes/1/complete20772026/10/26 22:36:52 WARN Failed to register uploaded object key=gwvxh3p4j5d1aq6gdrdg95kqrn44ffzm.narinfo error="server returned 404: 404 page not found\n"20782026/10/26 22:36:52 INFO Completed push id=1 objects=3 duration=60.221125ms20792026/10/26 22:36:52 INFO Upload complete. (488ms)2080--- PASS: TestPinProtectsFromGC (15.94s)2081=== CONT TestClientErrorHandling/ServerNotAvailable20822026/10/26 22:36:52 INFO All 1 paths already cached2083=== NAME TestClientIntegration2084 client_integration_test.go:357: Retrieved narinfo from S3:2085 StorePath: /private/var/tb/6/scratch/bedec206597db7e3/build/TestClientIntegration1348781518/002/store/gwvxh3p4j5d1aq6gdrdg95kqrn44ffzm-test-file.txt2086 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst2087 Compression: zstd2088 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk12089 NarSize: 1522090 References: 2091 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk12092=== NAME TestClientCADerivations2093 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket87?endpoint=http://localhost:59205®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/private/var/tb/6/scratch/bedec206597db7e3/build/TestClientCADerivations963802304/001/store'2094=== NAME TestClientIntegration2095 client_integration_test.go:358: Retrieved .ls file from S3 (compressed size: 77 bytes)2096=== NAME TestClientCADerivations2097 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 12098=== NAME TestClientIntegration2099 client_integration_test.go:358: Decompressed .ls content (64 bytes):2100 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}2101--- PASS: TestClientCADerivations (12.42s)2102=== CONT TestClientErrorHandling/InvalidAuthToken21032026/10/26 22:36:52 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21042026/10/26 22:36:52 INFO Received push request method=POST path=/api/pushes21052026/10/26 22:36:52 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggggg00000000000000000000.nar.zst upload_id=OWMwNzc0ZDMtYTE4Mi00M2UyLWIzMDYtNWM1NTcyYjI1ZGE4LjA5ZmI2YzUxLWVhNTQtNGJmZi05MmY2LTY0MjAxOTU0MzcxZXgxNzkzMDU0MTk3MjcxODU3MDAw parts=1021062026/10/26 22:36:53 INFO Received push request method=POST path=/api/pushes21072026/10/26 22:36:53 INFO Object in database but missing from S3 key=gwvxh3p4j5d1aq6gdrdg95kqrn44ffzm.ls21082026/10/26 22:36:53 WARN Found objects in DB but missing from S3, will re-upload count=121092026/10/26 22:36:53 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)2110--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (9.28s)2111=== CONT TestPush_RejectsBadRequests/no_objects21122026/10/26 22:36:53 INFO Received push request method=POST path=/api/pushes2113=== CONT TestPush_RejectsBadRequests/root_not_in_objects21142026/10/26 22:36:53 INFO Received push request method=POST path=/api/pushes2115=== CONT TestPush_RejectsBadRequests/bad_root21162026/10/26 22:36:53 INFO Received push request method=POST path=/api/pushes2117=== CONT TestPush_RejectsBadRequests/no_roots21182026/10/26 22:36:53 INFO Received push request method=POST path=/api/pushes2119=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2120=== CONT TestCacheConfigHandler/no_cache_url_configured2121=== CONT TestCacheConfigHandler/no_signing_keys2122=== CONT TestCacheConfigHandler/full_config,_no_issuer2123--- PASS: TestCacheConfigHandler (0.05s)2124 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)2125 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)2126 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)2127 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)2128=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token21292026-10-26 22:36:53.127 UTC [30441] ERROR: could not obtain lock on row in relation "closures"21302026-10-26 22:36:53.127 UTC [30441] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT2131=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected21322026-10-26 22:36:53.133 UTC [29888] LOG: checkpoint starting: wal21332026/10/26 22:36:53 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present21342026-10-26 22:36:53.138 UTC [30441] ERROR: could not obtain lock on row in relation "closures"21352026-10-26 22:36:53.138 UTC [30441] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT21362026/10/26 22:36:53 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]21372026-10-26 22:36:53.145 UTC [30441] ERROR: could not obtain lock on row in relation "closures"21382026-10-26 22:36:53.145 UTC [30441] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT21392026/10/26 22:36:53 INFO Received complete push request method=POST path=/api/pushes/2/complete21402026/10/26 22:36:53 WARN Failed to register uploaded object key=gwvxh3p4j5d1aq6gdrdg95kqrn44ffzm.ls error="server returned 404: 404 page not found\n"2141=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2142=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected21432026-10-26 22:36:53.154 UTC [30441] ERROR: could not obtain lock on row in relation "closures"21442026-10-26 22:36:53.154 UTC [30441] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT21452026/10/26 22:36:53 WARN Authentication failed token_preview=eyJhbGciOi...ZKHdvFYiJw token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]21462026-10-26 22:36:53.164 UTC [30441] ERROR: could not obtain lock on row in relation "closures"21472026-10-26 22:36:53.164 UTC [30441] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT2148--- PASS: TestPush_RejectsBadRequests (7.73s)2149 --- PASS: TestPush_RejectsBadRequests/no_objects (0.01s)2150 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)2151 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)2152 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)21532026/10/26 22:36:53 INFO Completed push id=2 objects=3 duration=53.794917ms21542026/10/26 22:36:53 INFO Upload complete. (247ms)2155=== NAME TestClientIntegration2156 client_integration_test.go:375: Retrieved .ls file from S3 (compressed size: 62 bytes)2157 client_integration_test.go:375: Decompressed .ls content (49 bytes):2158 {"version":1,"root":{"type":"regular","size":39}}21592026/10/26 22:36:53 WARN Request failed, retrying attempt=2 backoff=210.297159ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2160--- PASS: TestService_AuthMiddleware_OIDC (10.60s)2161 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2162 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.01s)2163 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2164 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.01s)2165--- PASS: TestPush_RootsAreLockedInByteOrder (23.24s)2166--- PASS: TestDeleteClosuresRacingPins (17.94s)21672026/10/26 22:36:53 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"21682026/10/26 22:36:53 WARN mTLS auth: bound subjects configured but subject DN unavailable21692026/10/26 22:36:53 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"2170--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (9.31s)21712026/10/26 22:36:53 WARN Request failed, retrying attempt=3 backoff=412.319691ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present21722026/10/26 22:36:53 INFO Received push request method=POST path=/api/pushes21732026/10/26 22:36:53 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)21742026/10/26 22:36:53 INFO Received complete push request method=POST path=/api/pushes/3/complete21752026/10/26 22:36:53 WARN Failed to register uploaded object key=gwvxh3p4j5d1aq6gdrdg95kqrn44ffzm.ls error="server returned 404: 404 page not found\n"21762026/10/26 22:36:53 INFO Completed push id=3 objects=3 duration=1.130125ms21772026/10/26 22:36:53 INFO Upload complete. (127ms)2178=== NAME TestClientIntegration2179 client_integration_test.go:392: Retrieved .ls file from S3 (compressed size: 62 bytes)2180 client_integration_test.go:392: Decompressed .ls content (49 bytes):2181 {"version":1,"root":{"type":"regular","size":39}}21822026/10/26 22:36:53 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"2183--- PASS: TestService_AuthMiddleware (8.30s)21842026/10/26 22:36:53 WARN Request failed, retrying attempt=4 backoff=735.234439ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present21852026/10/26 22:36:53 INFO Received push request method=POST path=/api/pushes21862026/10/26 22:36:53 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)21872026/10/26 22:36:53 INFO Uploading 8i5cfd7a93gl4ly8pa3063zq8b0jv06q-lost-commit.txt (152B)21882026/10/26 22:36:54 WARN Failed to register uploaded object key=nar/04d5klw9iix884nk82y7nlkps8afh2bg119y7zkvcf1pc1x2y2jl.nar.zst error="server returned 404: 404 page not found\n"21892026/10/26 22:36:54 WARN Failed to register uploaded object key=8i5cfd7a93gl4ly8pa3063zq8b0jv06q.ls error="server returned 404: 404 page not found\n"21902026/10/26 22:36:54 INFO Received sign narinfos request method=POST path=/api/pushes/4/sign21912026/10/26 22:36:54 INFO Signed narinfos id=4 count=121922026/10/26 22:36:54 INFO Uploading 1 narinfos21932026/10/26 22:36:54 INFO Received complete push request method=POST path=/api/pushes/4/complete21942026/10/26 22:36:54 WARN Failed to register uploaded object key=8i5cfd7a93gl4ly8pa3063zq8b0jv06q.narinfo error="server returned 404: 404 page not found\n"21952026/10/26 22:36:54 INFO Completed push id=4 objects=3 duration=570.041µs21962026/10/26 22:36:54 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:59831/api/pushes/4/complete\": EOF" url=http://127.0.0.1:59831/api/pushes/4/complete2197=== RUN TestService_RequireScope_OIDC/builder_may_write2198=== PAUSE TestService_RequireScope_OIDC/builder_may_write21992026/10/26 22:36:54 INFO Received complete push request method=POST path=/api/pushes/4/complete2200=== RUN TestService_RequireScope_OIDC/builder_may_not_admin22012026-10-26 22:36:54.221 UTC [30529] ERROR: Push does not exist: id=422022026-10-26 22:36:54.221 UTC [30529] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE22032026-10-26 22:36:54.221 UTC [30529] STATEMENT: -- name: CommitPush :one2204 SELECT commit_push($1::bigint)::bigint2205 2206=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin22072026/10/26 22:36:54 WARN Push not found id=42208=== RUN TestService_RequireScope_OIDC/ops_may_admin2209=== PAUSE TestService_RequireScope_OIDC/ops_may_admin2210=== RUN TestService_RequireScope_OIDC/ops_may_not_write2211=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write2212=== RUN TestService_RequireScope_OIDC/reader_may_not_write22132026/10/26 22:36:54 INFO Upload complete. (366ms)2214=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write2215=== RUN TestService_RequireScope_OIDC/static_token_may_admin2216=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin2217=== RUN TestService_RequireScope_OIDC/static_token_may_write2218=== PAUSE TestService_RequireScope_OIDC/static_token_may_write2219=== NAME TestClientIntegration2220 client_integration_test.go:422: Retrieved narinfo from S3:2221 StorePath: /private/var/tb/6/scratch/bedec206597db7e3/build/TestClientIntegration1348781518/002/store/8i5cfd7a93gl4ly8pa3063zq8b0jv06q-lost-commit.txt2222 URL: nar/04d5klw9iix884nk82y7nlkps8afh2bg119y7zkvcf1pc1x2y2jl.nar.zst2223=== RUN TestService_RequireScope_OIDC/reader_may_read2224=== PAUSE TestService_RequireScope_OIDC/reader_may_read2225=== NAME TestClientIntegration2226 Compression: zstd2227 NarHash: sha256:04d5klw9iix884nk82y7nlkps8afh2bg119y7zkvcf1pc1x2y2jl2228 NarSize: 1522229 References: 2230 CA: fixed:r:sha256:04d5klw9iix884nk82y7nlkps8afh2bg119y7zkvcf1pc1x2y2jl2231=== RUN TestService_RequireScope_OIDC/writer_implies_read2232=== PAUSE TestService_RequireScope_OIDC/writer_implies_read2233=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read2234=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read2235=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc2236=== NAME TestClientIntegration2237 client_integration_test.go:425: Testing garbage collection...2238=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc2239=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc2240=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc2241=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read2242=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read2243=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read2244=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read2245=== CONT TestService_RequireScope_OIDC/static_token_may_write2246=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc2247=== CONT TestService_RequireScope_OIDC/ops_may_not_write2248=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read22492026/10/26 22:36:54 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]2250=== CONT TestService_RequireScope_OIDC/writer_implies_read2251=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2252=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc2253=== CONT TestService_RequireScope_OIDC/reader_may_not_write2254=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read2255=== CONT TestService_RequireScope_OIDC/reader_may_read2256=== CONT TestService_RequireScope_OIDC/builder_may_write2257=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2258=== CONT TestService_RequireScope_OIDC/static_token_may_admin2259=== CONT TestService_RequireScope_OIDC/ops_may_admin22602026/10/26 22:36:54 INFO Starting cleanup of old closures method=DELETE path=/api/closures22612026/10/26 22:36:54 INFO Garbage collection started2262--- PASS: TestService_RequireScope_OIDC (8.04s)2263 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2264 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)2265 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2266 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2267 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2268 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)2269 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)2270 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)2271 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2272 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2273 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2274 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2275 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2276 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)22772026/10/26 22:36:54 INFO Aborted multipart uploads count=0 kept=022782026/10/26 22:36:54 WARN Force mode enabled - objects will be deleted immediately without grace period22792026/10/26 22:36:54 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22802026/10/26 22:36:54 WARN Request failed, retrying attempt=5 backoff=1.499294036s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2281--- PASS: TestReadProxyRootRedirectsToIndexHTML (7.87s)22822026/10/26 22:36:54 INFO Completed multipart upload object_key=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa00000000000000000000.nar.zst upload_id=OWMwNzc0ZDMtYTE4Mi00M2UyLWIzMDYtNWM1NTcyYjI1ZGE4LmE3MGRiOWYxLTdiODMtNGZlZi04OTRiLWM0NmZjZjQ5MzNjZngxNzkzMDU0MjEyNDA1ODUwMDAw parts=102283--- PASS: TestUploadHandlersRejectOversizedBody (0.07s)2284 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.31s)2285 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.30s)2286 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (4.82s)22872026/10/26 22:36:54 INFO Received uploads request method=POST path=/api/pending_closures22882026/10/26 22:36:55 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=022892026/10/26 22:36:55 INFO Vacuumed table table=pending_closures22902026/10/26 22:36:55 INFO Vacuumed table table=pending_objects22912026/10/26 22:36:55 INFO Vacuumed table table=multipart_uploads22922026/10/26 22:36:55 INFO Vacuumed table table=closures22932026/10/26 22:36:55 INFO Vacuumed table table=objects22942026/10/26 22:36:55 INFO Received uploads request method=POST path=/api/pending_closures22952026/10/26 22:36:55 WARN Failed to abort multipart upload key=nar/ssssssssssssssssssssssssssssssssssssssssssssssssssss.nar.zst upload_id=OWMwNzc0ZDMtYTE4Mi00M2UyLWIzMDYtNWM1NTcyYjI1ZGE4LjIxNzliZmFkLTViOWItNGI3MC1hYjllLTMyYWRlYmZmZDBmN3gxNzkzMDU0MjE1MDU1MzIxMDAw error="Access Denied"22962026/10/26 22:36:55 WARN keeping failed pending closure for cleanup to retry the abort id=122972026/10/26 22:36:55 INFO Received uploads request method=POST path=/api/pending_closures22982026/10/26 22:36:55 INFO Aborted multipart uploads count=0 kept=022992026/10/26 22:36:55 WARN Force mode enabled - objects will be deleted immediately without grace period23002026/10/26 22:36:55 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=023012026/10/26 22:36:55 INFO Vacuumed table table=pending_closures23022026/10/26 22:36:55 INFO Vacuumed table table=pending_objects23032026/10/26 22:36:55 INFO Vacuumed table table=multipart_uploads23042026/10/26 22:36:55 INFO Vacuumed table table=closures23052026/10/26 22:36:56 INFO Vacuumed table table=objects2306--- PASS: TestPendingClosureFailureTracksEveryUpload (0.00s)2307 --- PASS: TestPendingClosureFailureTracksEveryUpload/refuse_aborts=true (8.58s)2308 --- PASS: TestPendingClosureFailureTracksEveryUpload/refuse_aborts=false (8.27s)23092026/10/26 22:36:56 WARN Request failed, retrying attempt=1 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config23102026/10/26 22:36:56 WARN Request failed, retrying attempt=2 backoff=183.799445ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config23112026/10/26 22:36:56 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=2 objects_marked=6 objects_deleted=6 objects_failed=02312=== NAME TestClientIntegration2313 client_integration_test.go:432: Objects in database after GC:2314 client_integration_test.go:432: Successfully deleted all objects with GC --force23152026/10/26 22:36:56 INFO Received complete multipart upload request method=POST path=/api/multipart/complete2316--- PASS: TestClientIntegration (15.47s)23172026/10/26 22:36:56 INFO Completed multipart upload object_key=nar/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb00000000000000000000.nar.zst upload_id=OWMwNzc0ZDMtYTE4Mi00M2UyLWIzMDYtNWM1NTcyYjI1ZGE4LjcyYmU0Yjc0LTMxZWItNGU1NS05Zjk5LTQ2NjE1NWNlN2U3OHgxNzkzMDU0MjEyNDA2MjQxMDAw parts=1023182026/10/26 22:36:56 WARN Request failed, retrying attempt=3 backoff=360.584628ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config23192026/10/26 22:36:56 INFO Received uploads request method=POST path=/api/pending_closures23202026/10/26 22:36:56 INFO Aborted multipart uploads count=0 kept=023212026/10/26 22:36:56 WARN Force mode enabled - objects will be deleted immediately without grace period23222026/10/26 22:36:56 WARN Request failed, retrying attempt=4 backoff=813.097973ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2323--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2324 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (7.86s)2325 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (7.93s)23262026/10/26 22:36:57 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=1 objects-deleted-after-grace-period=1 objects-failed-to-delete=023272026/10/26 22:36:57 INFO Vacuumed table table=pending_closures23282026/10/26 22:36:57 INFO Vacuumed table table=pending_objects23292026/10/26 22:36:57 INFO Vacuumed table table=multipart_uploads23302026/10/26 22:36:57 INFO Vacuumed table table=closures23312026/10/26 22:36:57 INFO Received uploads request method=POST path=/api/pending_closures23322026/10/26 22:36:57 INFO Vacuumed table table=objects2333--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2334 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (8.21s)2335 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (8.48s)23362026/10/26 22:36:57 WARN Request failed, retrying attempt=5 backoff=1.447956615s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config23372026/10/26 22:36:57 INFO Aborted multipart uploads count=0 kept=023382026/10/26 22:36:57 WARN Force mode enabled - objects will be deleted immediately without grace period23392026-10-26 22:36:57.709 UTC [30751] ERROR: canceling statement due to user request23402026-10-26 22:36:57.709 UTC [30751] STATEMENT: -- name: MarkStaleObjects :execrows2341 WITH RECURSIVE ct AS (2342 SELECT timezone('UTC', now()) AS now2343 ),2344 closure_reach AS (2345 -- Start with all closure keys2346 SELECT o.key, o.refs2347 FROM objects o2348 INNER JOIN closures c ON o.key = c.key2349 UNION2350 -- Recursively add all referenced objects2351 SELECT o.key, o.refs2352 FROM objects o2353 INNER JOIN closure_reach cr ON o.key = ANY(cr.refs)2354 ),2355 reachable_objects AS (2356 SELECT DISTINCT key FROM closure_reach2357 ),2358 stale_objects AS (2359 SELECT o.key2360 FROM objects AS o, ct2361 WHERE2362 NOT EXISTS (2363 SELECT 12364 FROM reachable_objects ro2365 WHERE ro.key = o.key2366 )2367 AND NOT EXISTS (2368 SELECT 12369 FROM pending_objects AS po2370 WHERE po.key = o.key2371 )2372 AND o.deleted_at IS NULL -- Only mark fresh objects2373 ORDER BY o.key COLLATE "C" -- lock in key order, like commit_pending_closure2374 FOR UPDATE2375 )2376 UPDATE objects2377 SET2378 deleted_at = ct.now,2379 first_deleted_at = COALESCE(first_deleted_at, ct.now)2380 FROM stale_objects, ct2381 WHERE objects.key = stale_objects.key2382 23832026/10/26 22:36:57 INFO Received complete multipart upload request method=POST path=/api/multipart/complete2384--- PASS: TestPendingClosureWriteTimeout (0.00s)2385 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2386 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2387 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2388 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (7.43s)23892026/10/26 22:36:57 INFO Completed multipart upload object_key=nar/cccccccccccccccccccccccccccccccc00000000000000000000.nar.zst upload_id=OWMwNzc0ZDMtYTE4Mi00M2UyLWIzMDYtNWM1NTcyYjI1ZGE4Ljc2Y2JkM2YyLWEzMmItNGVkZi1iYjkxLWI2MzUyMDNhMjNjNngxNzkzMDU0MjEyNDA2Mjc3MDAw parts=1023902026/10/26 22:36:57 INFO Received complete push request method=POST path=/api/pushes/1/complete23912026/10/26 22:36:57 INFO Completed push id=1 objects=6 duration=8.591042ms23922026/10/26 22:36:57 INFO Aborted multipart uploads count=0 kept=02393--- PASS: TestPush_CompleteCommitsEveryRoot (15.22s)23942026/10/26 22:36:57 WARN Force mode enabled - objects will be deleted immediately without grace period23952026/10/26 22:36:57 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:59205/bucket106/?delete=\": context canceled"2396--- PASS: TestGCEndsOnShutdown (0.01s)2397 --- PASS: TestGCEndsOnShutdown/before_the_run (6.40s)2398 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (6.61s)2399 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (6.40s)24002026/10/26 22:36:58 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"24012026/10/26 22:36:58 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"24022026/10/26 22:36:59 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 [::1]:19999: connect: connection refused"24032026/10/26 22:36:59 WARN Request failed, retrying attempt=1 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config24042026/10/26 22:36:59 WARN Request failed, retrying attempt=2 backoff=216.062972ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config24052026/10/26 22:36:59 WARN Request failed, retrying attempt=3 backoff=385.990122ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config24062026/10/26 22:36:59 WARN Request failed, retrying attempt=4 backoff=837.352423ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config24072026/10/26 22:37:00 WARN Request failed, retrying attempt=5 backoff=1.710573783s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config24082026/10/26 22:37:02 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures24092026/10/26 22:37:02 WARN Request failed, retrying attempt=2 backoff=210.775978ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures24102026/10/26 22:37:02 WARN Request failed, retrying attempt=3 backoff=390.02589ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures24112026/10/26 22:37:03 WARN Request failed, retrying attempt=4 backoff=735.917538ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures24122026/10/26 22:37:03 WARN Request failed, retrying attempt=5 backoff=1.683719333s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2413=== NAME TestOrphanedObjectsGCStressTest2414 orphaned_objects_gc_test.go:503: Stress test completed successfully:2415 orphaned_objects_gc_test.go:504: - Active objects preserved: 202416 orphaned_objects_gc_test.go:505: - Objects deleted: 2102417 orphaned_objects_gc_test.go:506: - Total GC'd: 2102418--- PASS: TestOrphanedObjectsGCStressTest (43.04s)2419--- PASS: TestClientErrorHandling (0.01s)2420 --- PASS: TestClientErrorHandling/InvalidStorePath (6.28s)2421 --- PASS: TestClientErrorHandling/InvalidAuthToken (5.65s)2422 --- PASS: TestClientErrorHandling/ServerNotAvailable (13.11s)2423PASS2424{"timestamp":"2026-10-26T22:37:05.621729Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:59884","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(6)"}24252026-10-26 22:37:05.837 UTC [29883] LOG: received smart shutdown request24262026-10-26 22:37:05.838 UTC [29883] LOG: background worker "logical replication launcher" (PID 29893) exited with exit code 124272026-10-26 22:37:07.796 UTC [29888] LOG: checkpoint complete: wrote 8223 buffers (50.2%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 33 recycled; write=13.122 s, sync=1.376 s, total=14.664 s; sync files=37078, longest=0.013 s, average=0.001 s; distance=533851 kB, estimate=533851 kB; lsn=0/233A9008, redo lsn=0/220E3D4024282026-10-26 22:37:07.798 UTC [29888] LOG: shutting down24292026-10-26 22:37:07.798 UTC [29888] LOG: checkpoint starting: shutdown immediate24302026-10-26 22:37:07.977 UTC [29888] LOG: checkpoint complete: wrote 3313 buffers (20.2%), wrote 1 SLRU buffers; 0 WAL file(s) added, 0 removed, 1 recycled; write=0.143 s, sync=0.035 s, total=0.180 s; sync files=1041, longest=0.001 s, average=0.001 s; distance=19220 kB, estimate=482388 kB; lsn=0/233A9080, redo lsn=0/233A908024312026-10-26 22:37:07.991 UTC [29883] LOG: database system is shut down2432Running OIDC tests...2433=== RUN TestAudienceForIssuer2434=== PAUSE TestAudienceForIssuer2435=== RUN TestHTTPClientForHasTimeouts2436=== PAUSE TestHTTPClientForHasTimeouts2437=== RUN TestGlobMatch2438=== PAUSE TestGlobMatch2439=== RUN TestValidateToken_ValidToken2440=== PAUSE TestValidateToken_ValidToken2441=== RUN TestValidateToken_WrongAudience2442=== PAUSE TestValidateToken_WrongAudience2443=== RUN TestValidateToken_Expired2444=== PAUSE TestValidateToken_Expired2445=== RUN TestValidateToken_BoundClaimsMismatch2446=== PAUSE TestValidateToken_BoundClaimsMismatch2447=== RUN TestValidateToken_BoundSubjectMismatch2448=== PAUSE TestValidateToken_BoundSubjectMismatch2449=== RUN TestValidateToken_MultipleProviders2450=== PAUSE TestValidateToken_MultipleProviders2451=== RUN TestValidateToken_NoMatchingProvider2452=== PAUSE TestValidateToken_NoMatchingProvider2453=== RUN TestValidateToken_KubernetesServiceAccount2454=== PAUSE TestValidateToken_KubernetesServiceAccount2455=== RUN TestNewValidator_KubernetesRequiresCA2456=== PAUSE TestNewValidator_KubernetesRequiresCA2457=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2458=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2459=== RUN TestPins_ReservedForMatchingRule2460=== PAUSE TestPins_ReservedForMatchingRule2461=== RUN TestPins_TopLevelShorthand2462=== PAUSE TestPins_TopLevelShorthand2463=== RUN TestPins_ConfigValidation2464=== PAUSE TestPins_ConfigValidation2465=== RUN TestScopes_LegacyProviderDefaultsToWrite2466=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2467=== RUN TestScopes_Rules2468=== PAUSE TestScopes_Rules2469=== RUN TestScopes_ConfigValidation2470=== PAUSE TestScopes_ConfigValidation2471=== CONT TestValidateToken_ValidToken2472=== CONT TestValidateToken_WrongAudience2473=== CONT TestValidateToken_NoMatchingProvider2474=== CONT TestPins_TopLevelShorthand2475=== CONT TestScopes_ConfigValidation2476=== CONT TestScopes_Rules2477=== CONT TestPins_ConfigValidation2478=== CONT TestGlobMatch2479=== RUN TestGlobMatch/foo_foo2480=== CONT TestValidateToken_Expired2481=== PAUSE TestGlobMatch/foo_foo2482=== RUN TestGlobMatch/foo_bar2483=== PAUSE TestGlobMatch/foo_bar2484=== RUN TestGlobMatch/*_2485=== PAUSE TestGlobMatch/*_2486=== RUN TestGlobMatch/*_anything2487=== PAUSE TestGlobMatch/*_anything2488=== RUN TestGlobMatch/foo*_foo2489=== PAUSE TestGlobMatch/foo*_foo2490=== RUN TestGlobMatch/foo*_foobar2491=== PAUSE TestGlobMatch/foo*_foobar2492=== RUN TestGlobMatch/foo*_bar2493=== PAUSE TestGlobMatch/foo*_bar2494=== RUN TestGlobMatch/*bar_bar2495=== PAUSE TestGlobMatch/*bar_bar2496=== RUN TestGlobMatch/*bar_foobar2497=== PAUSE TestGlobMatch/*bar_foobar2498=== RUN TestGlobMatch/*bar_foo2499=== PAUSE TestGlobMatch/*bar_foo2500=== RUN TestGlobMatch/foo*bar_foobar2501=== PAUSE TestGlobMatch/foo*bar_foobar2502=== RUN TestGlobMatch/foo*bar_foo123bar2503=== PAUSE TestGlobMatch/foo*bar_foo123bar2504=== RUN TestGlobMatch/foo*bar_foobarbaz2505=== PAUSE TestGlobMatch/foo*bar_foobarbaz2506=== RUN TestGlobMatch/*/*_foo/bar2507=== PAUSE TestGlobMatch/*/*_foo/bar2508=== RUN TestGlobMatch/*/*_foo2509=== PAUSE TestGlobMatch/*/*_foo2510=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2511=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2512=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02513=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02514=== RUN TestGlobMatch/refs/*/main_refs/heads/main2515=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2516=== RUN TestGlobMatch/fo?_foo2517=== PAUSE TestGlobMatch/fo?_foo2518=== RUN TestGlobMatch/fo?_fo2519=== PAUSE TestGlobMatch/fo?_fo2520=== RUN TestGlobMatch/fo?_fooo2521=== PAUSE TestGlobMatch/fo?_fooo2522=== RUN TestGlobMatch/?oo_foo2523=== PAUSE TestGlobMatch/?oo_foo2524=== RUN TestGlobMatch/?oo_boo2525=== PAUSE TestGlobMatch/?oo_boo2526=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2527=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2528=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2529=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2530=== CONT TestGlobMatch/foo_foo2531=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2532=== CONT TestGlobMatch/?oo_boo2533=== CONT TestGlobMatch/?oo_foo2534=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2535=== CONT TestGlobMatch/fo?_fooo2536=== CONT TestGlobMatch/fo?_fo2537=== CONT TestGlobMatch/fo?_foo2538=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02539=== CONT TestGlobMatch/*bar_foobar2540=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2541=== CONT TestGlobMatch/refs/*/main_refs/heads/main2542=== CONT TestGlobMatch/*/*_foo/bar2543=== CONT TestGlobMatch/foo*bar_foobarbaz2544=== CONT TestGlobMatch/*/*_foo2545=== CONT TestGlobMatch/*bar_bar2546=== CONT TestGlobMatch/foo*bar_foo123bar2547=== CONT TestGlobMatch/foo_bar2548=== CONT TestGlobMatch/foo*_foo2549=== CONT TestGlobMatch/*_anything2550=== CONT TestValidateToken_MultipleProviders2551=== CONT TestGlobMatch/*_2552=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2553--- PASS: TestScopes_ConfigValidation (0.01s)2554=== CONT TestScopes_LegacyProviderDefaultsToWrite2555=== CONT TestPins_ReservedForMatchingRule2556--- PASS: TestPins_ConfigValidation (0.01s)2557=== CONT TestHTTPClientForHasTimeouts2558=== CONT TestAudienceForIssuer2559--- PASS: TestAudienceForIssuer (0.00s)2560=== CONT TestValidateToken_BoundClaimsMismatch2561=== CONT TestValidateToken_KubernetesServiceAccount2562=== CONT TestNewValidator_KubernetesRequiresCA2563=== CONT TestGlobMatch/foo*bar_foobar2564=== CONT TestGlobMatch/*bar_foo2565=== CONT TestValidateToken_BoundSubjectMismatch2566=== CONT TestGlobMatch/foo*_foobar2567=== CONT TestGlobMatch/foo*_bar2568--- PASS: TestGlobMatch (0.00s)2569 --- PASS: TestGlobMatch/foo_foo (0.00s)2570 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2571 --- PASS: TestGlobMatch/?oo_boo (0.00s)2572 --- PASS: TestGlobMatch/?oo_foo (0.00s)2573 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2574 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2575 --- PASS: TestGlobMatch/fo?_fo (0.00s)2576 --- PASS: TestGlobMatch/fo?_foo (0.00s)2577 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2578 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2579 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2580 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2581 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2582 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2583 --- PASS: TestGlobMatch/*bar_bar (0.00s)2584 --- PASS: TestGlobMatch/*/*_foo (0.00s)2585 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2586 --- PASS: TestGlobMatch/*_anything (0.00s)2587 --- PASS: TestGlobMatch/foo*_foo (0.00s)2588 --- PASS: TestGlobMatch/foo_bar (0.00s)2589 --- PASS: TestGlobMatch/*_ (0.00s)2590 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2591 --- PASS: TestGlobMatch/*bar_foo (0.00s)2592 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2593 --- PASS: TestGlobMatch/foo*_bar (0.00s)25942026/10/26 22:37:11 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:60088/oidc25952026/10/26 22:37:11 http: TLS handshake error from 127.0.0.1:60090: read tcp 127.0.0.1:60089->127.0.0.1:60090: use of closed network connection2596--- PASS: TestNewValidator_KubernetesRequiresCA (0.04s)25972026/10/26 22:37:11 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:60093/oidc2598--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.06s)2599--- PASS: TestPins_ReservedForMatchingRule (0.06s)26002026/10/26 22:37:11 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:60095/oidc2601--- PASS: TestValidateToken_ValidToken (0.09s)26022026/10/26 22:37:11 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:60099/oidc26032026/10/26 22:37:11 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:600972604--- PASS: TestValidateToken_BoundSubjectMismatch (0.08s)2605--- PASS: TestValidateToken_KubernetesServiceAccount (0.09s)26062026/10/26 22:37:11 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232607--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.11s)26082026/10/26 22:37:11 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:60104/oidc2609--- PASS: TestValidateToken_BoundClaimsMismatch (0.12s)26102026/10/26 22:37:11 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:60107/oidc26112026/10/26 22:37:11 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:60109/oidc2612--- PASS: TestValidateToken_WrongAudience (0.18s)2613--- PASS: TestScopes_Rules (0.19s)26142026/10/26 22:37:11 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:60101/oidc2615--- PASS: TestValidateToken_NoMatchingProvider (0.21s)26162026/10/26 22:37:11 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:60114/oidc2617--- PASS: TestValidateToken_Expired (0.26s)26182026/10/26 22:37:11 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:60116/oidc2619--- PASS: TestPins_TopLevelShorthand (0.29s)2620--- PASS: TestHTTPClientForHasTimeouts (0.41s)26212026/10/26 22:37:11 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:60118/oidc26222026/10/26 22:37:11 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:60120/oidc2623--- PASS: TestValidateToken_MultipleProviders (0.42s)2624PASS2625Running hook tests...2626=== RUN TestSendPathsEmpty2627=== PAUSE TestSendPathsEmpty2628=== RUN TestQueueEnqueueAndFetch2629=== PAUSE TestQueueEnqueueAndFetch2630=== RUN TestQueueDeduplication2631=== PAUSE TestQueueDeduplication2632=== RUN TestQueueRemove2633=== PAUSE TestQueueRemove2634=== RUN TestQueueFetchBatchLimit2635=== PAUSE TestQueueFetchBatchLimit2636=== RUN TestQueueRetryMovesToBack2637=== PAUSE TestQueueRetryMovesToBack2638=== RUN TestQueueFetchRemoveLifecycle2639=== PAUSE TestQueueFetchRemoveLifecycle2640=== RUN TestQueueConcurrentWriters2641=== PAUSE TestQueueConcurrentWriters2642=== RUN TestQueueEnqueueWaitsOutSlowWriter2643=== PAUSE TestQueueEnqueueWaitsOutSlowWriter2644=== RUN TestQueueRemoveLargeClosure2645=== PAUSE TestQueueRemoveLargeClosure2646=== RUN TestServerClientIntegration2647--- PASS: TestServerClientIntegration (0.00s)2648=== RUN TestServerQueueError26492026/10/26 22:37:13 ERROR Failed to queue paths error="permission denied" count=12650--- PASS: TestServerQueueError (0.00s)2651=== RUN TestServerRefusesOversizedAndNonStoreRequests2652=== PAUSE TestServerRefusesOversizedAndNonStoreRequests2653=== RUN TestGetListenerSocketActivation2654 server_test.go:236: systemd socket activation does not exist on darwin2655--- SKIP: TestGetListenerSocketActivation (0.00s)2656=== RUN TestServerStalledClientDoesNotBlockShutdown2657=== PAUSE TestServerStalledClientDoesNotBlockShutdown2658=== RUN TestServerBacksOffOnAcceptErrors2659=== PAUSE TestServerBacksOffOnAcceptErrors2660=== RUN TestDrainIsolatesPoisonPath2661=== PAUSE TestDrainIsolatesPoisonPath2662=== RUN TestRunNotBlockedByPoisonHead2663=== PAUSE TestRunNotBlockedByPoisonHead2664=== RUN TestDrainGivesUpWhenServerDown2665=== PAUSE TestDrainGivesUpWhenServerDown2666=== RUN TestFailedPathPrunedByLaterClosure2667=== PAUSE TestFailedPathPrunedByLaterClosure2668=== RUN TestWorkerUploadsAndRemoves2669=== PAUSE TestWorkerUploadsAndRemoves2670=== RUN TestWorkerSkipsGCdPaths2671=== PAUSE TestWorkerSkipsGCdPaths2672=== RUN TestWorkerPrunesClosureDeps2673=== PAUSE TestWorkerPrunesClosureDeps2674=== RUN TestWorkerRemovesCachedPathBatchedWithLargerClosure2675=== PAUSE TestWorkerRemovesCachedPathBatchedWithLargerClosure2676=== RUN TestDrainTimeout2677=== PAUSE TestDrainTimeout2678=== RUN TestDrainTimeoutDuringIsolation2679=== PAUSE TestDrainTimeoutDuringIsolation2680=== RUN TestShutdownFinishesInFlightPush2681=== PAUSE TestShutdownFinishesInFlightPush2682=== RUN TestWorkerRemoveFailureIsNotProgress2683=== PAUSE TestWorkerRemoveFailureIsNotProgress2684=== RUN TestWorkerKeepsPathItCannotStat2685=== PAUSE TestWorkerKeepsPathItCannotStat2686=== CONT TestQueueDeduplication2687=== CONT TestDrainIsolatesPoisonPath2688=== CONT TestWorkerRemovesCachedPathBatchedWithLargerClosure2689=== CONT TestQueueRemove2690=== CONT TestServerStalledClientDoesNotBlockShutdown2691=== CONT TestWorkerPrunesClosureDeps2692=== CONT TestServerRefusesOversizedAndNonStoreRequests2693=== CONT TestQueueRemoveLargeClosure2694=== CONT TestWorkerRemoveFailureIsNotProgress2695=== RUN TestWorkerRemoveFailureIsNotProgress/collected_path2696=== PAUSE TestWorkerRemoveFailureIsNotProgress/collected_path2697=== CONT TestWorkerKeepsPathItCannotStat2698=== RUN TestWorkerRemoveFailureIsNotProgress/pushed_batch26992026/10/26 22:37:13 ERROR Refusing path outside the store path=/etc/shadow store=/nix/store2700=== PAUSE TestWorkerRemoveFailureIsNotProgress/pushed_batch2701=== CONT TestShutdownFinishesInFlightPush2702=== RUN TestShutdownFinishesInFlightPush/completes2703=== CONT TestQueueEnqueueWaitsOutSlowWriter2704=== CONT TestDrainTimeoutDuringIsolation2705=== CONT TestServerBacksOffOnAcceptErrors2706=== CONT TestQueueFetchRemoveLifecycle2707=== CONT TestQueueRetryMovesToBack2708=== CONT TestQueueEnqueueAndFetch2709=== CONT TestQueueFetchBatchLimit2710=== CONT TestDrainTimeout27112026/10/26 22:37:13 ERROR Accept failed error="too many open files"2712=== CONT TestWorkerSkipsGCdPaths2713=== CONT TestWorkerUploadsAndRemoves27142026/10/26 22:37:13 ERROR Refusing path outside the store path=/nix/store store=/nix/store27152026/10/26 22:37:13 ERROR Refusing path outside the store path=/nix/store/ store=/nix/store27162026/10/26 22:37:13 ERROR Refusing path outside the store path=/nix/store/../../etc/shadow store=/nix/store27172026/10/26 22:37:13 ERROR Refusing path outside the store path=/nix/store/0123456789abcdfghijklmnpqrsvwxyz-hello/bin/sh store=/nix/store2718=== CONT TestFailedPathPrunedByLaterClosure2719=== CONT TestDrainGivesUpWhenServerDown27202026/10/26 22:37:13 ERROR Refusing path outside the store path=nix/store/0123456789abcdfghijklmnpqrsvwxyz-hello store=/nix/store27212026/10/26 22:37:13 ERROR Refusing path outside the store path=/nix/storeX/0123456789abcdfghijklmnpqrsvwxyz-hello store=/nix/store27222026/10/26 22:37:13 ERROR Refusing path outside the store path=/nix/store/.links store=/nix/store27232026/10/26 22:37:13 ERROR Refusing path outside the store path=/nix/store/aaa-hello store=/nix/store27242026/10/26 22:37:13 ERROR Refusing path outside the store path=/nix/store/0123456789abcdfghijklmnpqrsvwxyz store=/nix/store27252026/10/26 22:37:13 ERROR Refusing path outside the store path=/nix/store/0123456789abcdfghijklmnpqrsvwxyz- store=/nix/store2726=== CONT TestQueueConcurrentWriters2727=== RUN TestWorkerRemoveFailureIsNotProgress/isolated_paths27282026/10/26 22:37:13 ERROR Refusing path outside the store path=/nix/store/0123456789ebcdfghijklmnpqrsvwxyz-hello store=/nix/store2729=== PAUSE TestShutdownFinishesInFlightPush/completes2730=== RUN TestDrainTimeoutDuringIsolation/probe_cut_short2731=== PAUSE TestWorkerRemoveFailureIsNotProgress/isolated_paths2732=== PAUSE TestDrainTimeoutDuringIsolation/probe_cut_short2733=== RUN TestDrainTimeoutDuringIsolation/probe_outlasts_the_deadline2734=== RUN TestShutdownFinishesInFlightPush/hung_push_bounded_by_the_drain_timeout2735=== PAUSE TestDrainTimeoutDuringIsolation/probe_outlasts_the_deadline2736=== PAUSE TestShutdownFinishesInFlightPush/hung_push_bounded_by_the_drain_timeout2737=== CONT TestSendPathsEmpty2738--- PASS: TestSendPathsEmpty (0.00s)2739=== CONT TestRunNotBlockedByPoisonHead2740=== CONT TestWorkerRemoveFailureIsNotProgress/isolated_paths2741=== CONT TestWorkerRemoveFailureIsNotProgress/pushed_batch27422026/10/26 22:37:13 ERROR Refusing path outside the store path="/nix/store/0123456789abcdfghijklmnpqrsvwxyz-hel\x00lo" store=/nix/store27432026/10/26 22:37:13 ERROR Refusing path outside the store path=/nix/store/0123456789abcdfghijklmnpqrsvwxyz-hel/lo store=/nix/store27442026/10/26 22:37:13 ERROR Refusing path outside the store path=/nix/store/0123456789abcdfghijklmnpqrsvwxyz-xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx store=/nix/store27452026/10/26 22:37:13 ERROR Accept failed error="too many open files"27462026/10/26 22:37:13 ERROR Failed to decode request error="unexpected EOF"2747--- PASS: TestServerRefusesOversizedAndNonStoreRequests (0.01s)2748=== CONT TestWorkerRemoveFailureIsNotProgress/collected_path27492026/10/26 22:37:13 ERROR Accept failed error="too many open files"27502026/10/26 22:37:13 INFO Uploading batch count=127512026/10/26 22:37:13 ERROR Upload failed error="upload failed" count=127522026/10/26 22:37:13 INFO Upload queue status pending=227532026/10/26 22:37:13 INFO Uploading batch count=127542026/10/26 22:37:13 INFO Uploading batch count=427552026/10/26 22:37:13 ERROR Upload failed error="upload failed" count=427562026/10/26 22:37:13 INFO Upload queue status pending=227572026/10/26 22:37:13 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/6/scratch/bedec206597db7e3/build/TestDrainIsolatesPoisonPath1367493309/002/bbb27582026/10/26 22:37:13 INFO Uploading batch count=227592026/10/26 22:37:13 INFO Upload queue status pending=227602026/10/26 22:37:13 INFO Uploading batch count=127612026/10/26 22:37:13 INFO Uploading batch count=127622026/10/26 22:37:13 INFO Uploading batch count=22763--- PASS: TestQueueFetchBatchLimit (0.03s)2764=== CONT TestShutdownFinishesInFlightPush/completes27652026/10/26 22:37:13 WARN Cannot stat store path, will retry later path=/private/var/tb/6/scratch/bedec206597db7e3/build/TestWorkerKeepsPathItCannotStat3628119427/002/locked/aaa error="lstat /private/var/tb/6/scratch/bedec206597db7e3/build/TestWorkerKeepsPathItCannotStat3628119427/002/locked/aaa: permission denied"2766--- PASS: TestQueueEnqueueAndFetch (0.03s)2767=== CONT TestShutdownFinishesInFlightPush/hung_push_bounded_by_the_drain_timeout27682026/10/26 22:37:13 INFO Upload queue status pending=327692026/10/26 22:37:13 INFO Uploading batch count=127702026/10/26 22:37:13 ERROR Upload failed error="upload failed" count=127712026/10/26 22:37:13 INFO Uploading batch count=22772=== CONT TestDrainTimeoutDuringIsolation/probe_outlasts_the_deadline2773=== CONT TestDrainTimeoutDuringIsolation/probe_cut_short27742026/10/26 22:37:13 INFO Upload queue status pending=327752026/10/26 22:37:13 INFO Uploading batch count=127762026/10/26 22:37:13 ERROR Upload failed error="upload failed" count=12777--- PASS: TestQueueDeduplication (0.04s)2778--- PASS: TestQueueRetryMovesToBack (0.03s)27792026/10/26 22:37:13 INFO Uploading batch count=227802026/10/26 22:37:13 ERROR Upload failed error="upload failed" count=227812026/10/26 22:37:13 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/6/scratch/bedec206597db7e3/build/TestDrainGivesUpWhenServerDown1309172897/002/a27822026/10/26 22:37:13 WARN Cannot stat store path, will retry later path=/private/var/tb/6/scratch/bedec206597db7e3/build/TestWorkerKeepsPathItCannotStat3628119427/002/locked/aaa error="lstat /private/var/tb/6/scratch/bedec206597db7e3/build/TestWorkerKeepsPathItCannotStat3628119427/002/locked/aaa: permission denied"27832026/10/26 22:37:13 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/6/scratch/bedec206597db7e3/build/TestWorkerSkipsGCdPaths860962838/002/nonexistent27842026/10/26 22:37:13 ERROR Accept failed error="too many open files"27852026/10/26 22:37:13 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/6/scratch/bedec206597db7e3/build/TestDrainGivesUpWhenServerDown1309172897/002/b27862026/10/26 22:37:13 INFO Uploading batch count=227872026/10/26 22:37:13 WARN Cannot stat store path, will retry later path=/private/var/tb/6/scratch/bedec206597db7e3/build/TestWorkerKeepsPathItCannotStat3628119427/002/locked/aaa error="lstat /private/var/tb/6/scratch/bedec206597db7e3/build/TestWorkerKeepsPathItCannotStat3628119427/002/locked/aaa: permission denied"2788--- PASS: TestFailedPathPrunedByLaterClosure (0.04s)27892026/10/26 22:37:13 INFO Uploading batch count=127902026/10/26 22:37:13 ERROR Upload failed error="upload failed" count=127912026/10/26 22:37:13 ERROR Drain finished with paths left in queue remaining=127922026/10/26 22:37:13 INFO Uploading batch count=227932026/10/26 22:37:13 ERROR Upload failed error="upload failed" count=227942026/10/26 22:37:13 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/6/scratch/bedec206597db7e3/build/TestDrainGivesUpWhenServerDown1309172897/002/c27952026/10/26 22:37:13 INFO Uploading batch count=127962026/10/26 22:37:13 ERROR Upload failed error="upload failed" count=127972026/10/26 22:37:13 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/6/scratch/bedec206597db7e3/build/TestDrainGivesUpWhenServerDown1309172897/002/d2798--- PASS: TestQueueRemove (0.04s)27992026/10/26 22:37:13 ERROR Drain finished with paths left in queue remaining=12800--- PASS: TestQueueFetchRemoveLifecycle (0.04s)28012026/10/26 22:37:13 INFO Uploading batch count=228022026/10/26 22:37:13 INFO Uploading batch count=228032026/10/26 22:37:13 ERROR Upload failed error="upload failed" count=228042026/10/26 22:37:13 ERROR Upload failed error="upload failed" count=228052026/10/26 22:37:13 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/6/scratch/bedec206597db7e3/build/TestDrainGivesUpWhenServerDown1309172897/002/e28062026/10/26 22:37:13 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=12807--- PASS: TestDrainIsolatesPoisonPath (0.05s)2808--- PASS: TestWorkerKeepsPathItCannotStat (0.05s)28092026/10/26 22:37:13 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/6/scratch/bedec206597db7e3/build/TestDrainGivesUpWhenServerDown1309172897/002/f28102026/10/26 22:37:13 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=128112026/10/26 22:37:13 INFO Uploading batch count=228122026/10/26 22:37:13 ERROR Upload failed error="upload failed" count=228132026/10/26 22:37:13 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=128142026/10/26 22:37:13 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=128152026/10/26 22:37:13 INFO Upload queue status pending=228162026/10/26 22:37:13 INFO Uploading batch count=228172026/10/26 22:37:13 ERROR Upload failed error="upload failed" count=228182026/10/26 22:37:13 ERROR Drain finished with paths left in queue remaining=1028192026/10/26 22:37:13 INFO Uploading batch count=228202026/10/26 22:37:13 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=128212026/10/26 22:37:13 INFO Uploading batch count=428222026/10/26 22:37:13 ERROR Upload failed error="upload failed" count=428232026/10/26 22:37:13 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=128242026/10/26 22:37:13 INFO Upload queue status pending=228252026/10/26 22:37:13 ERROR Drain finished with paths left in queue remaining=228262026/10/26 22:37:13 INFO Uploading batch count=428272026/10/26 22:37:13 ERROR Upload failed error="upload failed" count=428282026/10/26 22:37:13 INFO Uploading batch count=22829--- PASS: TestWorkerRemovesCachedPathBatchedWithLargerClosure (0.05s)28302026/10/26 22:37:13 INFO Uploading batch count=228312026/10/26 22:37:13 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/6/scratch/bedec206597db7e3/build/TestWorkerRemoveFailureIsNotProgresscollected_path3299399464/001/nonexistent28322026/10/26 22:37:13 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=228332026/10/26 22:37:13 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=12834--- PASS: TestDrainGivesUpWhenServerDown (0.05s)2835--- PASS: TestWorkerUploadsAndRemoves (0.05s)28362026/10/26 22:37:13 INFO Uploading batch count=228372026/10/26 22:37:13 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/6/scratch/bedec206597db7e3/build/TestWorkerRemoveFailureIsNotProgresscollected_path3299399464/001/nonexistent28382026/10/26 22:37:13 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=228392026/10/26 22:37:13 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=128402026/10/26 22:37:13 INFO Uploading batch count=228412026/10/26 22:37:13 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/6/scratch/bedec206597db7e3/build/TestWorkerRemoveFailureIsNotProgresscollected_path3299399464/001/nonexistent28422026/10/26 22:37:13 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=128432026/10/26 22:37:13 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=228442026/10/26 22:37:13 ERROR Drain finished with paths left in queue remaining=128452026/10/26 22:37:13 ERROR Drain finished with paths left in queue remaining=22846--- PASS: TestWorkerPrunesClosureDeps (0.05s)2847--- PASS: TestWorkerRemoveFailureIsNotProgress (0.00s)2848 --- PASS: TestWorkerRemoveFailureIsNotProgress/isolated_paths (0.05s)2849 --- PASS: TestWorkerRemoveFailureIsNotProgress/collected_path (0.05s)2850 --- PASS: TestWorkerRemoveFailureIsNotProgress/pushed_batch (0.05s)2851--- PASS: TestWorkerSkipsGCdPaths (0.05s)28522026/10/26 22:37:13 ERROR Accept failed error="too many open files"28532026/10/26 22:37:13 ERROR Accept failed error="too many open files"28542026/10/26 22:37:13 ERROR Failed to decode request error="read unix /private/var/tb/6/scratch/bedec206597db7e3/build/hook3222829465/test.sock->: i/o timeout"28552026/10/26 22:37:13 ERROR Failed to write response error="write unix /private/var/tb/6/scratch/bedec206597db7e3/build/hook3222829465/test.sock->: i/o timeout"2856--- PASS: TestServerStalledClientDoesNotBlockShutdown (0.20s)28572026/10/26 22:37:13 ERROR Upload failed error="context canceled" count=228582026/10/26 22:37:13 ERROR Drain finished with paths left in queue remaining=42859--- PASS: TestDrainTimeout (0.24s)28602026/10/26 22:37:13 ERROR Drain finished with paths left in queue remaining=428612026/10/26 22:37:13 ERROR Upload failed error="context canceled" count=228622026/10/26 22:37:13 ERROR Drain finished with paths left in queue remaining=22863--- PASS: TestShutdownFinishesInFlightPush (0.00s)2864 --- PASS: TestShutdownFinishesInFlightPush/completes (0.12s)2865 --- PASS: TestShutdownFinishesInFlightPush/hung_push_bounded_by_the_drain_timeout (0.22s)2866--- PASS: TestQueueConcurrentWriters (0.27s)28672026/10/26 22:37:13 ERROR Accept failed error="too many open files"28682026/10/26 22:37:13 ERROR Drain finished with paths left in queue remaining=32869--- PASS: TestDrainTimeoutDuringIsolation (0.00s)2870 --- PASS: TestDrainTimeoutDuringIsolation/probe_cut_short (0.22s)2871 --- PASS: TestDrainTimeoutDuringIsolation/probe_outlasts_the_deadline (0.32s)28722026/10/26 22:37:13 ERROR Accept failed error="too many open files"2873--- PASS: TestServerBacksOffOnAcceptErrors (0.64s)28742026/10/26 22:37:14 INFO Uploading batch count=128752026/10/26 22:37:14 INFO Uploading batch count=128762026/10/26 22:37:14 INFO Uploading batch count=128772026/10/26 22:37:14 ERROR Upload failed error="upload failed" count=128782026/10/26 22:37:14 INFO Uploading batch count=128792026/10/26 22:37:14 ERROR Upload failed error="upload failed" count=128802026/10/26 22:37:14 INFO Uploading batch count=128812026/10/26 22:37:14 ERROR Upload failed error="upload failed" count=128822026/10/26 22:37:14 INFO Uploading batch count=128832026/10/26 22:37:14 ERROR Upload failed error="upload failed" count=128842026/10/26 22:37:14 ERROR Drain finished with paths left in queue remaining=12885--- PASS: TestRunNotBlockedByPoisonHead (1.06s)2886--- PASS: TestQueueRemoveLargeClosure (1.20s)2887--- PASS: TestQueueEnqueueWaitsOutSlowWriter (6.03s)2888PASS2889Running signing tests...2890=== RUN TestExternalSigner2891=== PAUSE TestExternalSigner2892=== RUN TestExternalSignerWrongPublicKey2893=== PAUSE TestExternalSignerWrongPublicKey2894=== RUN TestExternalSignerErrors2895=== PAUSE TestExternalSignerErrors2896=== RUN TestExternalSignerRestartsAfterCrash2897=== PAUSE TestExternalSignerRestartsAfterCrash2898=== RUN TestExternalSignerProgramErrorKeepsProcess2899=== PAUSE TestExternalSignerProgramErrorKeepsProcess2900=== RUN TestExternalSignerClose2901=== PAUSE TestExternalSignerClose2902=== RUN TestExternalSignerRejectsInvalidPublicKey2903=== PAUSE TestExternalSignerRejectsInvalidPublicKey2904=== RUN TestExternalSignerCancellation2905=== PAUSE TestExternalSignerCancellation2906=== RUN TestGenerateFingerprint2907=== PAUSE TestGenerateFingerprint2908=== RUN TestParseSigningKey2909=== PAUSE TestParseSigningKey2910=== RUN TestSign2911=== PAUSE TestSign2912=== RUN TestSignBatch2913=== PAUSE TestSignBatch2914=== RUN TestNilKeyPublicKey2915=== PAUSE TestNilKeyPublicKey2916=== RUN TestSignErrors2917=== PAUSE TestSignErrors2918=== CONT TestExternalSigner2919=== CONT TestSign2920=== CONT TestSignErrors2921=== CONT TestExternalSignerClose2922=== CONT TestExternalSignerRejectsInvalidPublicKey2923=== CONT TestExternalSignerProgramErrorKeepsProcess2924=== CONT TestNilKeyPublicKey2925--- PASS: TestNilKeyPublicKey (0.00s)2926=== CONT TestExternalSignerWrongPublicKey2927=== CONT TestExternalSignerRestartsAfterCrash2928=== CONT TestGenerateFingerprint2929=== RUN TestGenerateFingerprint/basic_with_references2930=== CONT TestParseSigningKey2931=== PAUSE TestGenerateFingerprint/basic_with_references2932=== RUN TestParseSigningKey/valid_32-byte_key2933=== RUN TestGenerateFingerprint/no_references2934=== CONT TestExternalSignerErrors2935=== PAUSE TestGenerateFingerprint/no_references2936=== CONT TestExternalSignerCancellation2937=== RUN TestExternalSignerErrors/null2938=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2939=== PAUSE TestExternalSignerErrors/null2940=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2941=== CONT TestSignBatch2942=== PAUSE TestParseSigningKey/valid_32-byte_key2943=== RUN TestExternalSignerRejectsInvalidPublicKey/#002944=== RUN TestExternalSignerErrors/null_signatures2945=== PAUSE TestExternalSignerErrors/null_signatures2946=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2947=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002948=== RUN TestExternalSignerErrors/invalid_JSON2949=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2950=== PAUSE TestExternalSignerErrors/invalid_JSON2951=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2952=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2953=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2954=== RUN TestExternalSignerErrors/wrong_id2955=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2956=== RUN TestParseSigningKey/no_colon2957=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2958=== PAUSE TestParseSigningKey/no_colon2959=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2960=== RUN TestParseSigningKey/empty_name2961=== PAUSE TestParseSigningKey/empty_name2962=== PAUSE TestExternalSignerErrors/wrong_id2963=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2964=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2965=== RUN TestExternalSignerErrors/missing_signatures2966=== PAUSE TestExternalSignerErrors/missing_signatures2967=== RUN TestParseSigningKey/invalid_base642968=== RUN TestExternalSignerErrors/missing_signature_name2969=== RUN TestGenerateFingerprint/invalid_nar_hash_length2970=== PAUSE TestParseSigningKey/invalid_base642971=== RUN TestParseSigningKey/wrong_length2972=== PAUSE TestParseSigningKey/wrong_length2973=== PAUSE TestExternalSignerErrors/missing_signature_name2974=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2975=== CONT TestParseSigningKey/valid_32-byte_key2976=== RUN TestGenerateFingerprint/invalid_store_path_prefix2977=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2978=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2979=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2980=== RUN TestGenerateFingerprint/invalid_reference_prefix2981=== RUN TestExternalSignerErrors/wrong_signature_name2982=== CONT TestParseSigningKey/empty_name2983=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2984=== CONT TestParseSigningKey/wrong_length2985=== PAUSE TestExternalSignerErrors/wrong_signature_name2986=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2987=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2988=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2989=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2990=== RUN TestExternalSignerErrors/invalid_signature_base642991=== CONT TestParseSigningKey/no_colon2992=== CONT TestGenerateFingerprint/invalid_store_path_prefix2993=== CONT TestGenerateFingerprint/no_references2994=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2995=== CONT TestParseSigningKey/invalid_base642996=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2997=== CONT TestExternalSignerRejectsInvalidPublicKey/#002998=== CONT TestGenerateFingerprint/invalid_reference_prefix2999=== CONT TestGenerateFingerprint/invalid_nar_hash_length3000=== PAUSE TestExternalSignerErrors/invalid_signature_base643001=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!3002=== CONT TestGenerateFingerprint/basic_with_references3003--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)3004 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)3005 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)3006 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)3007 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)3008 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)3009=== RUN TestExternalSignerErrors/wrong_signature_length3010=== PAUSE TestExternalSignerErrors/wrong_signature_length3011=== RUN TestExternalSignerErrors/program_error3012--- PASS: TestGenerateFingerprint (0.00s)3013 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)3014 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)3015 --- PASS: TestGenerateFingerprint/no_references (0.00s)3016 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)3017 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)3018 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)3019 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)3020=== PAUSE TestExternalSignerErrors/program_error3021=== RUN TestExternalSignerErrors/exit_on_request3022=== PAUSE TestExternalSignerErrors/exit_on_request3023=== RUN TestExternalSignerErrors/wrong_signatures_shape3024=== PAUSE TestExternalSignerErrors/wrong_signatures_shape3025=== RUN TestExternalSignerErrors/too_few_signatures3026=== PAUSE TestExternalSignerErrors/too_few_signatures3027=== RUN TestExternalSignerErrors/unrequested_key3028=== PAUSE TestExternalSignerErrors/unrequested_key3029=== RUN TestExternalSignerErrors/exit_at_startup3030=== PAUSE TestExternalSignerErrors/exit_at_startup3031=== RUN TestExternalSignerErrors/wrong_shape3032=== PAUSE TestExternalSignerErrors/wrong_shape3033=== CONT TestExternalSignerErrors/null3034=== CONT TestExternalSignerErrors/wrong_id3035=== CONT TestExternalSignerErrors/unrequested_key3036=== CONT TestExternalSignerErrors/program_error3037=== CONT TestExternalSignerErrors/exit_at_startup3038=== CONT TestExternalSignerErrors/wrong_signature_length3039=== RUN TestSignErrors/nil_key3040=== PAUSE TestSignErrors/nil_key3041=== RUN TestSignErrors/nil_narinfo3042=== PAUSE TestSignErrors/nil_narinfo3043=== RUN TestSignErrors/invalid_narinfo3044=== CONT TestExternalSignerErrors/wrong_signature_name3045=== CONT TestExternalSignerErrors/invalid_signature_base643046=== CONT TestExternalSignerErrors/wrong_shape3047=== CONT TestExternalSignerErrors/wrong_signatures_shape3048=== PAUSE TestSignErrors/invalid_narinfo3049=== CONT TestExternalSignerErrors/exit_on_request3050--- PASS: TestSign (0.01s)3051=== CONT TestExternalSignerErrors/missing_signatures3052=== CONT TestExternalSignerErrors/missing_signature_name3053=== RUN TestSignErrors/canceled3054=== CONT TestExternalSignerErrors/too_few_signatures3055=== PAUSE TestSignErrors/canceled3056=== CONT TestExternalSignerErrors/invalid_JSON3057=== CONT TestExternalSignerErrors/null_signatures3058=== CONT TestSignErrors/nil_key3059=== CONT TestSignErrors/canceled3060--- PASS: TestParseSigningKey (0.00s)3061 --- PASS: TestParseSigningKey/empty_name (0.00s)3062 --- PASS: TestParseSigningKey/wrong_length (0.00s)3063 --- PASS: TestParseSigningKey/no_colon (0.00s)3064 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)3065 --- PASS: TestParseSigningKey/valid_32-byte_key (0.01s)3066 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.01s)3067=== CONT TestSignErrors/invalid_narinfo3068=== CONT TestSignErrors/nil_narinfo3069--- PASS: TestSignErrors (0.01s)3070 --- PASS: TestSignErrors/nil_key (0.00s)3071 --- PASS: TestSignErrors/canceled (0.00s)3072 --- PASS: TestSignErrors/invalid_narinfo (0.00s)3073 --- PASS: TestSignErrors/nil_narinfo (0.00s)3074--- PASS: TestSignBatch (0.02s)3075--- PASS: TestExternalSigner (0.23s)3076--- PASS: TestExternalSignerClose (0.40s)3077--- PASS: TestExternalSignerProgramErrorKeepsProcess (0.58s)3078--- PASS: TestExternalSignerWrongPublicKey (0.78s)3079--- PASS: TestExternalSignerCancellation (0.99s)3080--- PASS: TestExternalSignerRestartsAfterCrash (1.17s)3081--- PASS: TestExternalSignerErrors (0.01s)3082 --- PASS: TestExternalSignerErrors/missing_signatures (1.32s)3083 --- PASS: TestExternalSignerErrors/wrong_signature_name (1.52s)3084 --- PASS: TestExternalSignerErrors/invalid_JSON (1.79s)3085 --- PASS: TestExternalSignerErrors/null_signatures (1.98s)3086 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (2.25s)3087 --- PASS: TestExternalSignerErrors/unrequested_key (2.44s)3088 --- PASS: TestExternalSignerErrors/wrong_id (2.63s)3089 --- PASS: TestExternalSignerErrors/wrong_signature_length (2.82s)3090 --- PASS: TestExternalSignerErrors/exit_on_request (3.01s)3091 --- PASS: TestExternalSignerErrors/too_few_signatures (3.20s)3092 --- PASS: TestExternalSignerErrors/program_error (3.40s)3093 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (3.58s)3094 --- PASS: TestExternalSignerErrors/wrong_shape (3.78s)3095 --- PASS: TestExternalSignerErrors/null (3.97s)3096 --- PASS: TestExternalSignerErrors/missing_signature_name (4.16s)3097 --- PASS: TestExternalSignerErrors/exit_at_startup (4.36s)3098PASS3099Running OpenBao signer tests...3100=== RUN TestSign3101=== PAUSE TestSign3102=== RUN TestSignErrors3103=== PAUSE TestSignErrors3104=== RUN TestServe3105=== PAUSE TestServe3106=== RUN TestServeRejectsGarbage3107=== PAUSE TestServeRejectsGarbage3108=== CONT TestSignErrors3109=== RUN TestSignErrors/http_error3110=== CONT TestSign3111=== CONT TestServe3112=== CONT TestServeRejectsGarbage3113=== PAUSE TestSignErrors/http_error3114=== RUN TestSignErrors/invalid_json3115--- PASS: TestServeRejectsGarbage (0.00s)3116=== PAUSE TestSignErrors/invalid_json3117=== RUN TestSignErrors/no_prefix3118=== PAUSE TestSignErrors/no_prefix3119=== RUN TestSignErrors/invalid_base643120=== PAUSE TestSignErrors/invalid_base643121=== CONT TestSignErrors/http_error3122=== CONT TestSignErrors/no_prefix3123=== CONT TestSignErrors/invalid_json3124=== CONT TestSignErrors/invalid_base643125--- PASS: TestServe (0.00s)3126--- PASS: TestSign (0.01s)3127--- PASS: TestSignErrors (0.00s)3128 --- PASS: TestSignErrors/invalid_json (0.00s)3129 --- PASS: TestSignErrors/no_prefix (0.00s)3130 --- PASS: TestSignErrors/invalid_base64 (0.00s)3131 --- PASS: TestSignErrors/http_error (0.00s)3132PASS3133Running niks3-hook command tests...3134=== RUN TestServeSecondSignalEndsDrain3135=== PAUSE TestServeSecondSignalEndsDrain3136=== RUN TestServeThenDrainPushesSendAcceptedBeforeShutdown3137=== PAUSE TestServeThenDrainPushesSendAcceptedBeforeShutdown3138=== CONT TestServeSecondSignalEndsDrain3139=== CONT TestServeThenDrainPushesSendAcceptedBeforeShutdown3140--- PASS: TestServeSecondSignalEndsDrain (0.05s)31412026/10/26 22:37:27 INFO Upload queue status pending=131422026/10/26 22:37:27 INFO Uploading batch count=13143--- PASS: TestServeThenDrainPushesSendAcceptedBeforeShutdown (0.12s)3144PASS3145Running rate limiter tests...3146=== RUN TestAdaptiveRateLimiter_ThreadSafety3147=== PAUSE TestAdaptiveRateLimiter_ThreadSafety3148=== CONT TestAdaptiveRateLimiter_ThreadSafety31492026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=124.0092700000000731502026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=86.8064890000000431512026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=60.7645423000000231522026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=42.53517961000001431532026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=29.77462572700000731542026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=20.84223800890000431552026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=14.58956660623000331562026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=10.21269662436100131572026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=7.14888763705270131582026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=5.0042213459368931592026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=5.64154396389137631602026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=531612026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=531622026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=531632026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=531642026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=531652026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=531662026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=531672026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=531682026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=531692026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=531702026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=531712026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=531722026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=531732026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=531742026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=531752026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=531762026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=531772026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=531782026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=531792026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=531802026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=531812026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=531822026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=531832026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=531842026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=531852026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=531862026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=531872026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=531882026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=531892026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=531902026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=531912026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=531922026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=531932026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=531942026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=531952026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=531962026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=531972026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=531982026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=531992026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=532002026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=532012026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=532022026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=532032026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=532042026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=5.12435000000000132052026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=532062026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=532072026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=532082026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=532092026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=532102026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=532112026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=532122026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=532132026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=8.25281691850000432142026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=5.77697184295000332152026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=532162026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=532172026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=532182026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=532192026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=532202026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=532212026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=532222026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=532232026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=532242026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=532252026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=532262026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=532272026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=532282026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=532292026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=532302026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=532312026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=532322026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=532332026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=532342026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=532352026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=532362026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=532372026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=532382026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=5.12435000000000132392026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=532402026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=532412026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=532422026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=532432026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=532442026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=532452026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=532462026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=7.50256083500000332472026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=5.25179258450000232482026/10/26 22:37:29 WARN Rate limiter backed off name=test rate=53249--- PASS: TestAdaptiveRateLimiter_ThreadSafety (0.09s)3250PASS