niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #442
· 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.06s)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.42s)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 TestDoWithRetry_BodyReplayedViaGetBody137=== CONT TestScriptTokenScriptFails138=== CONT TestPathInfoHashCompatibility139=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer140=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess141=== CONT TestCompletePendingClosure_NotFoundWithoutKey142=== CONT TestRateLimiterFeedback143=== CONT TestPathInfoCACompatibility144=== CONT TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent145=== CONT TestParsePathInfoJSON146=== RUN TestPathInfoCACompatibility/null_ca_field147=== RUN TestParsePathInfoJSON/Nix_format148=== RUN TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/committed_earlier149=== PAUSE TestParsePathInfoJSON/Nix_format150=== RUN TestParsePathInfoJSON/Lix_format151=== PAUSE TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/committed_earlier152=== CONT TestGetStorePathHash153=== PAUSE TestPathInfoCACompatibility/null_ca_field154=== CONT TestScriptTokenDoesNotWaitForItsChildren155=== CONT TestConvertHashToNix32156=== CONT TestEncodeNixBase32157=== RUN TestScriptTokenDoesNotWaitForItsChildren/cancelled_while_a_child_runs158=== CONT TestDumpPathWriterError159=== CONT TestFileTokenReadsAndCaches160=== RUN TestEncodeNixBase32/test_string_hash161=== CONT TestDumpPathMatchesNix162=== CONT TestEncodeNixBase32WithRealHash163=== CONT TestDumpPathSingleFile164=== CONT TestScriptTokenBadJSON165=== CONT TestSupersededNARStillUploadsListing166=== RUN TestSupersededNARStillUploadsListing/small_NAR167=== PAUSE TestSupersededNARStillUploadsListing/small_NAR168=== RUN TestSupersededNARStillUploadsListing/dump_cut_short169=== PAUSE TestSupersededNARStillUploadsListing/dump_cut_short170=== CONT TestScriptTokenEmptyToken171=== CONT TestDoServerRequestAttachesToken172=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)173=== RUN TestRateLimiterFeedback/429_enables_limiter174=== CONT TestSetClientTLSErrors175=== RUN TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/cleaned_up176=== PAUSE TestParsePathInfoJSON/Lix_format177=== RUN TestGetStorePathHash/valid_store_path178=== RUN TestPathInfoCACompatibility/old_string_format_-_text179=== PAUSE TestScriptTokenDoesNotWaitForItsChildren/cancelled_while_a_child_runs180=== RUN TestConvertHashToNix32/SRI_format_to_Nix32181=== PAUSE TestEncodeNixBase32/test_string_hash182--- PASS: TestEncodeNixBase32WithRealHash (0.00s)183=== CONT TestScriptTokenCachesUntilRefresh184=== RUN TestSupersededNARStillUploadsListing/listing_upload_fails185=== CONT TestScriptTokenNoExpiryRerunsEveryCall186=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)187=== PAUSE TestRateLimiterFeedback/429_enables_limiter188=== PAUSE TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/cleaned_up189=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text190=== PAUSE TestGetStorePathHash/valid_store_path191=== RUN TestParsePathInfoJSON/empty_input192=== RUN TestScriptTokenDoesNotWaitForItsChildren/child_left_holding_stdout193=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32194=== RUN TestEncodeNixBase32/empty_input195=== PAUSE TestEncodeNixBase32/empty_input196=== PAUSE TestParsePathInfoJSON/empty_input197--- PASS: TestFileTokenReadsAndCaches (0.00s)198=== PAUSE TestScriptTokenDoesNotWaitForItsChildren/child_left_holding_stdout199--- PASS: TestScriptTokenScriptFails (0.01s)200--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.01s)201=== RUN TestRateLimiterFeedback/503_enables_limiter202--- PASS: TestCompletePendingClosure_NotFoundWithoutKey (0.01s)203=== CONT TestSetClientTLS204=== RUN TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_committed_earlier205=== CONT TestStaticToken206=== PAUSE TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_committed_earlier207=== PAUSE TestRateLimiterFeedback/503_enables_limiter208=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon209--- PASS: TestStaticToken (0.00s)210=== RUN TestParsePathInfoJSON/whitespace_only211=== CONT TestFileTokenMissing212=== RUN TestGetStorePathHash/basename_without_hyphen_should_error213=== CONT TestFileTokenEmpty214=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon215=== PAUSE TestSupersededNARStillUploadsListing/listing_upload_fails216=== CONT TestUploadMultipart_SupersededByPeer217=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter218=== PAUSE TestParsePathInfoJSON/whitespace_only219=== RUN TestConvertHashToNix32/already_Nix32_format220=== PAUSE TestConvertHashToNix32/already_Nix32_format221=== RUN TestParsePathInfoJSON/invalid_JSON222=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter223=== RUN TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_cleaned_up,_first_root_committed_by_another_client224=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter225=== CONT TestSetClientTLSDoesNotMutateDefaultTransport226=== PAUSE TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_cleaned_up,_first_root_committed_by_another_client227=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI228=== RUN TestConvertHashToNix32/invalid_format229=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive230=== RUN TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_cleaned_up,_last_root_committed_by_another_client231=== PAUSE TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_cleaned_up,_last_root_committed_by_another_client232=== CONT TestFilterOversizedClosures233=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive234=== RUN TestFilterOversizedClosures/no_limit_keeps_everything235=== RUN TestSetClientTLSErrors/missing_cert_file236=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error237=== PAUSE TestParsePathInfoJSON/invalid_JSON238=== RUN TestUploadMultipart_SupersededByPeer/exists239=== CONT TestScriptTokenEmptyCommand240=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter241=== PAUSE TestConvertHashToNix32/invalid_format242=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI243--- PASS: TestFileTokenMissing (0.00s)244=== CONT TestPartSizeForNAR245=== RUN TestPathInfoCACompatibility/new_structured_format_-_text246=== CONT TestCaseHackSuffix247=== PAUSE TestSetClientTLSErrors/missing_cert_file248=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything249=== CONT TestUploadMultipart_PartsInParallel250=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error251=== RUN TestSetClientTLSErrors/missing_key_file252=== PAUSE TestUploadMultipart_SupersededByPeer/exists253=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun254=== RUN TestUploadMultipart_SupersededByPeer/missing255--- PASS: TestDoServerRequestAttachesToken (0.01s)256=== CONT TestPushPathsReportsOnlyUnuploadablePathsOfSkippedClosure257--- PASS: TestScriptTokenEmptyToken (0.01s)258=== CONT TestStreamPushRequestLine259--- PASS: TestScriptTokenEmptyCommand (0.00s)260--- PASS: TestFileTokenEmpty (0.01s)261--- PASS: TestScriptTokenBadJSON (0.01s)262=== CONT TestStreamPushStartsNothingOnSlotFreedByCancel263=== RUN TestPartSizeForNAR/zero_stays_at_minimum264=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text265=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped266=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped267=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica268=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error269=== CONT TestParsePathInfoJSONMultiplePaths270=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths271=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths272=== CONT TestTruncatedNARDumpIsNotCompleted273=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error274=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error275=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths276=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths277=== CONT TestStreamPushStopsOnCancel278=== RUN TestStreamPushStopsOnCancel/waiting_for_input279=== PAUSE TestStreamPushStopsOnCancel/waiting_for_input280=== RUN TestStreamPushStopsOnCancel/partial_batch_waiting_for_a_slot281=== PAUSE TestStreamPushStopsOnCancel/partial_batch_waiting_for_a_slot282=== RUN TestStreamPushStopsOnCancel/input_closed,_last_batch_waiting_for_a_slot283=== PAUSE TestStreamPushStopsOnCancel/input_closed,_last_batch_waiting_for_a_slot284=== CONT TestClientSignaturesByStorePath285=== RUN TestStreamPushStopsOnCancel/full_batch_waiting_for_a_slot286=== PAUSE TestStreamPushStopsOnCancel/full_batch_waiting_for_a_slot287=== RUN TestStreamPushStopsOnCancel/request_line_waiting_for_a_slot288=== PAUSE TestStreamPushStopsOnCancel/request_line_waiting_for_a_slot289=== RUN TestStreamPushStopsOnCancel/lines_read_but_not_taken290=== CONT TestStreamPushStopsWhenCanceled291=== PAUSE TestStreamPushStopsOnCancel/lines_read_but_not_taken292=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum293=== PAUSE TestUploadMultipart_SupersededByPeer/missing294=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512295--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.01s)296=== RUN TestFilterOversizedClosures/all_closures_skipped297=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method298=== PAUSE TestSetClientTLSErrors/missing_key_file299=== CONT TestStreamPushReportsSignatures300=== CONT TestStreamPushReportsSkippedPaths301=== CONT TestStreamPushGivesUpOnDeadServer302--- PASS: TestClientSignaturesByStorePath (0.00s)303=== RUN TestPartSizeForNAR/small_stays_at_minimum304=== RUN TestSetClientTLS/rejects_connection_without_client_cert305=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512306=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method307=== PAUSE TestPartSizeForNAR/small_stays_at_minimum308=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum309=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert310=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA311=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum312=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts313=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts314=== RUN TestPartSizeForNAR/1_TiB315=== PAUSE TestPartSizeForNAR/1_TiB316=== RUN TestPartSizeForNAR/5_TiB_S3_max_object317=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object318=== RUN TestPartSizeForNAR/capped_at_5_GiB319=== PAUSE TestPartSizeForNAR/capped_at_5_GiB320=== PAUSE TestFilterOversizedClosures/all_closures_skipped321=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA322=== RUN TestSetClientTLSErrors/missing_ca_file323=== RUN TestSetClientTLS/preserves_debug_logging_transport324=== PAUSE TestSetClientTLSErrors/missing_ca_file325=== PAUSE TestSetClientTLS/preserves_debug_logging_transport326=== RUN TestSetClientTLSErrors/invalid_ca_file327=== PAUSE TestSetClientTLSErrors/invalid_ca_file328=== CONT TestStreamPushReportsEveryPath329=== CONT TestStreamPushIsolatesFailures330=== CONT TestShellSplitErrors331=== CONT TestStreamPushBatchesUnderLoad332=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=false333=== CONT TestShellSplit334=== CONT TestDoWithRetry_FinalResponseBodyReadable335--- PASS: TestStreamPushStopsWhenCanceled (0.00s)336=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=false337=== CONT TestRegisterUploadedObjectReusesConnections338=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=true339=== CONT TestUploadMultipart_ProducerErrorIsNotEOF340=== RUN TestUploadMultipart_ProducerErrorIsNotEOF/short_read_inside_a_part341=== PAUSE TestUploadMultipart_ProducerErrorIsNotEOF/short_read_inside_a_part342=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=true343=== CONT TestRetryTimeoutOutlastsMaxRetries344=== RUN TestUploadMultipart_ProducerErrorIsNotEOF/empty_read_on_a_part_boundary345=== CONT TestResolveStorePath346--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)347--- PASS: TestStreamPushReportsSkippedPaths (0.00s)348=== CONT TestUploadMultipart_FailedPartBufferNotReused349--- PASS: TestShellSplitErrors (0.00s)350--- PASS: TestStreamPushReportsEveryPath (0.00s)351=== PAUSE TestUploadMultipart_ProducerErrorIsNotEOF/empty_read_on_a_part_boundary352--- PASS: TestStreamPushIsolatesFailures (0.00s)353=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry354--- PASS: TestShellSplit (0.00s)355--- PASS: TestStreamPushReportsSignatures (0.00s)356=== CONT TestEncodeNixBase32/test_string_hash357=== CONT TestEncodeNixBase32/empty_input358--- PASS: TestResolveStorePath (0.00s)359=== CONT TestScriptTokenDoesNotWaitForItsChildren/child_left_holding_stdout360=== CONT TestScriptTokenDoesNotWaitForItsChildren/cancelled_while_a_child_runs361--- PASS: TestEncodeNixBase32 (0.01s)362 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)363 --- PASS: TestEncodeNixBase32/empty_input (0.00s)364--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.02s)365=== CONT TestSupersededNARStillUploadsListing/dump_cut_short366=== CONT TestSupersededNARStillUploadsListing/listing_upload_fails367=== CONT TestSupersededNARStillUploadsListing/small_NAR368--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.01s)369=== CONT TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_cleaned_up,_first_root_committed_by_another_client370--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.03s)371=== CONT TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_cleaned_up,_last_root_committed_by_another_client372--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.05s)373=== CONT TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_committed_earlier374=== CONT TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/committed_earlier375=== CONT TestParsePathInfoJSON/Nix_format376=== CONT TestParsePathInfoJSON/invalid_JSON377=== CONT TestParsePathInfoJSON/empty_input378=== CONT TestParsePathInfoJSON/whitespace_only379=== CONT TestParsePathInfoJSON/Lix_format380=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter381--- PASS: TestParsePathInfoJSON (0.01s)382 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)383 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)384 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)385 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)386 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)387--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.04s)388=== CONT TestRateLimiterFeedback/503_enables_limiter389=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter390=== CONT TestRateLimiterFeedback/429_enables_limiter391=== CONT TestConvertHashToNix32/invalid_format392--- PASS: TestCaseHackSuffix (0.07s)393=== CONT TestConvertHashToNix32/already_Nix32_format394=== CONT TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/cleaned_up395--- PASS: TestDumpPathSingleFile (0.08s)396=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error397=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error398--- PASS: TestScriptTokenCachesUntilRefresh (0.08s)399=== CONT TestGetStorePathHash/valid_store_path400=== CONT TestGetStorePathHash/basename_without_hyphen_should_error401=== CONT TestConvertHashToNix32/SRI_format_to_Nix32402=== CONT TestStreamPushStopsOnCancel/full_batch_waiting_for_a_slot403=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths404=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths405=== CONT TestStreamPushStopsOnCancel/request_line_waiting_for_a_slot406=== CONT TestUploadMultipart_SupersededByPeer/exists407=== CONT TestStreamPushStopsOnCancel/waiting_for_input408=== CONT TestStreamPushStopsOnCancel/partial_batch_waiting_for_a_slot409=== CONT TestStreamPushStopsOnCancel/lines_read_but_not_taken410=== CONT TestStreamPushStopsOnCancel/input_closed,_last_batch_waiting_for_a_slot411--- PASS: TestRateLimiterFeedback (0.01s)412 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.01s)413 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.01s)414 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)415 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)416--- PASS: TestGetStorePathHash (0.02s)417 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)418 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)419 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)420 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)421--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)422 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)423 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)424=== CONT TestSetClientTLSErrors/missing_ca_file425=== CONT TestUploadMultipart_SupersededByPeer/missing426--- PASS: TestConvertHashToNix32 (0.01s)427 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)428 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)429 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)430=== CONT TestSetClientTLSErrors/invalid_ca_file431--- PASS: TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent (0.01s)432 --- PASS: TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_cleaned_up,_first_root_committed_by_another_client (0.03s)433 --- PASS: TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_committed_earlier (0.01s)434 --- PASS: TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/committed_earlier (0.02s)435 --- PASS: TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_cleaned_up,_last_root_committed_by_another_client (0.03s)436 --- PASS: TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/cleaned_up (0.01s)437=== CONT TestSetClientTLSErrors/missing_key_file438=== CONT TestSetClientTLSErrors/missing_cert_file439=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts440=== CONT TestPartSizeForNAR/5_TiB_S3_max_object441=== CONT TestPartSizeForNAR/1_TiB442=== CONT TestPartSizeForNAR/capped_at_5_GiB443=== CONT TestPartSizeForNAR/zero_stays_at_minimum444=== CONT TestPartSizeForNAR/small_stays_at_minimum445=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI446=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon447=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512448=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)449=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum450=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=false451--- PASS: TestPartSizeForNAR (0.01s)452 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)453 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)454 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)455 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)456 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)457 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)458 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)459=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=true460--- PASS: TestUploadMultipart_SupersededByPeer (0.01s)461 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)462 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)463=== CONT TestUploadMultipart_ProducerErrorIsNotEOF/short_read_inside_a_part464--- PASS: TestSetClientTLSErrors (0.02s)465 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)466 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)467 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)468 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)469=== CONT TestUploadMultipart_ProducerErrorIsNotEOF/empty_read_on_a_part_boundary470--- PASS: TestStreamPushBatchesUnderLoad (0.00s)471 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=false (0.00s)472 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=true (0.00s)473=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA474--- PASS: TestPathInfoHashCompatibility (0.02s)475 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)476 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)477 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)478 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)479--- PASS: TestStreamPushRequestLine (0.11s)480=== CONT TestSetClientTLS/preserves_debug_logging_transport481=== CONT TestSetClientTLS/rejects_connection_without_client_cert482=== CONT TestFilterOversizedClosures/all_closures_skipped483=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped484=== CONT TestFilterOversizedClosures/no_limit_keeps_everything485=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive486=== CONT TestPathInfoCACompatibility/null_ca_field487=== CONT TestPathInfoCACompatibility/old_string_format_-_text488=== CONT TestPathInfoCACompatibility/new_structured_format_-_text489=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method490--- PASS: TestFilterOversizedClosures (0.01s)491 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)492 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)493 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)494--- PASS: TestPathInfoCACompatibility (0.02s)495 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)496 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)497 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)498 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)499 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)500--- PASS: TestStreamPushStopsOnCancel (0.00s)501 --- PASS: TestStreamPushStopsOnCancel/full_batch_waiting_for_a_slot (0.06s)502 --- PASS: TestStreamPushStopsOnCancel/partial_batch_waiting_for_a_slot (0.06s)503 --- PASS: TestStreamPushStopsOnCancel/request_line_waiting_for_a_slot (0.06s)504 --- PASS: TestStreamPushStopsOnCancel/waiting_for_input (0.06s)505 --- PASS: TestStreamPushStopsOnCancel/input_closed,_last_batch_waiting_for_a_slot (0.06s)506 --- PASS: TestStreamPushStopsOnCancel/lines_read_but_not_taken (0.07s)507--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.13s)508--- PASS: TestUploadMultipart_ProducerErrorIsNotEOF (0.00s)509 --- PASS: TestUploadMultipart_ProducerErrorIsNotEOF/short_read_inside_a_part (0.06s)510 --- PASS: TestUploadMultipart_ProducerErrorIsNotEOF/empty_read_on_a_part_boundary (0.06s)511--- PASS: TestSetClientTLS (0.02s)512 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.02s)513 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.02s)514 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.05s)515--- PASS: TestDumpPathWriterError (0.19s)516--- PASS: TestPushPathsReportsOnlyUnuploadablePathsOfSkippedClosure (0.18s)517--- PASS: TestStreamPushStartsNothingOnSlotFreedByCancel (0.21s)518--- PASS: TestDumpPathMatchesNix (0.23s)519--- PASS: TestRegisterUploadedObjectReusesConnections (0.24s)520--- PASS: TestTruncatedNARDumpIsNotCompleted (0.43s)521--- PASS: TestUploadMultipart_FailedPartBufferNotReused (0.65s)522--- PASS: TestUploadMultipart_PartsInParallel (0.70s)523--- PASS: TestSupersededNARStillUploadsListing (0.01s)524 --- PASS: TestSupersededNARStillUploadsListing/small_NAR (0.05s)525 --- PASS: TestSupersededNARStillUploadsListing/listing_upload_fails (0.06s)526 --- PASS: TestSupersededNARStillUploadsListing/dump_cut_short (0.71s)527--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)528--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (1.00s)529--- PASS: TestScriptTokenDoesNotWaitForItsChildren (0.01s)530 --- PASS: TestScriptTokenDoesNotWaitForItsChildren/child_left_holding_stdout (2.03s)531 --- PASS: TestScriptTokenDoesNotWaitForItsChildren/cancelled_while_a_child_runs (2.20s)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/7ab19ce6cf566bc8/build/postgres2790069543/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/7ab19ce6cf566bc8/build/postgres2790069543/data -l logfile start560561/private/var/tb/6/scratch/7ab19ce6cf566bc8/build/postgres2790069543:5432 - no response5622026-10-27 08:49:44.839 UTC [85926] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit5632026-10-27 08:49:44.840 UTC [85926] LOG: listening on Unix socket "/private/var/tb/6/scratch/7ab19ce6cf566bc8/build/postgres2790069543/.s.PGSQL.5432"5642026-10-27 08:49:44.842 UTC [85934] LOG: database system was shut down at 2026-10-27 08:49:44 UTC5652026-10-27 08:49:44.843 UTC [85926] LOG: database system is ready to accept connections566/private/var/tb/6/scratch/7ab19ce6cf566bc8/build/postgres2790069543:5432 - accepting connections567=== RUN TestService_AuthMiddleware568=== PAUSE TestService_AuthMiddleware569=== RUN TestService_AuthMiddleware_MTLSProxyHeader570=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader571=== RUN TestService_AuthMiddleware_MTLSBoundSubjects572=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects573=== RUN TestService_ReadAuthMiddleware574=== PAUSE TestService_ReadAuthMiddleware575=== RUN TestService_AuthMiddleware_OIDC576=== PAUSE TestService_AuthMiddleware_OIDC577=== RUN TestService_RequireScope_OIDC578=== PAUSE TestService_RequireScope_OIDC579=== RUN TestService_ReadScope_PublicByDefault580=== PAUSE TestService_ReadScope_PublicByDefault581=== RUN TestCacheConfigHandler582=== PAUSE TestCacheConfigHandler583=== RUN TestCacheStatsHandler584=== PAUSE TestCacheStatsHandler585=== RUN TestClientCADerivations586=== PAUSE TestClientCADerivations587=== RUN TestClientErrorHandling588=== PAUSE TestClientErrorHandling589=== RUN TestClientIntegration590=== PAUSE TestClientIntegration591=== RUN TestClientMultipleUploads592=== PAUSE TestClientMultipleUploads593=== RUN TestClientWithDependencies594=== PAUSE TestClientWithDependencies595=== RUN TestClientSharedPathCommittedMidPush596=== PAUSE TestClientSharedPathCommittedMidPush597=== RUN TestPinProtectsFromGC598=== PAUSE TestPinProtectsFromGC599=== RUN TestClientPushesUseOnePush600=== PAUSE TestClientPushesUseOnePush601=== RUN TestClientFallsBackToClosures602=== PAUSE TestClientFallsBackToClosures603=== RUN TestDeleteClosuresRacingPins604=== PAUSE TestDeleteClosuresRacingPins605=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock606=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock607=== RUN TestResolveDBConnectionString608=== PAUSE TestResolveDBConnectionString609=== RUN TestConnectWaitsForAPeerMigration610=== PAUSE TestConnectWaitsForAPeerMigration611=== RUN TestConnectSerialisesConcurrentMigrations612=== PAUSE TestConnectSerialisesConcurrentMigrations613=== RUN TestLeadElectsOneAndHandsOver614=== PAUSE TestLeadElectsOneAndHandsOver615=== RUN TestLeadIncumbentWinsAfterRestart6162026/10/27 08:49:45 INFO lead: acquired remote=192.0.2.1:12346172026/10/27 08:49:45 INFO lead: released remote=192.0.2.1:12346182026/10/27 08:49:45 INFO lead: acquired remote=192.0.2.1:12346192026/10/27 08:49:47 INFO lead: released remote=192.0.2.1:1234620--- PASS: TestLeadIncumbentWinsAfterRestart (1.98s)621=== RUN TestLeadIncumbentAnnouncesAtOnce622=== PAUSE TestLeadIncumbentAnnouncesAtOnce623=== RUN TestLeadEndsOnShutdown624=== PAUSE TestLeadEndsOnShutdown625=== RUN TestLeadEndsWhenItsConnectionHangs6262026/10/27 08:49:47 INFO lead: acquired remote=192.0.2.1:12346272026-10-27 08:49:48.614 UTC [85970] FATAL: terminating connection due to administrator command6282026/10/27 08:49:48 INFO lead: acquired remote=192.0.2.1:12346292026/10/27 08:49:49 WARN lead: lock connection lost error="timeout: context deadline exceeded"6302026/10/27 08:49:49 INFO lead: released remote=192.0.2.1:12346312026/10/27 08:49:50 INFO lead: released remote=192.0.2.1:1234632--- PASS: TestLeadEndsWhenItsConnectionHangs (2.98s)633=== RUN TestGCAdvisoryLockBlocksConcurrentRun634=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun635=== RUN TestGCBugBareHashReferences636=== PAUSE TestGCBugBareHashReferences637=== RUN TestGCMetrics638=== PAUSE TestGCMetrics639=== RUN TestPushDedupSurvivesConcurrentGC640=== PAUSE TestPushDedupSurvivesConcurrentGC641=== RUN TestDeduplicatedObjectsRecordedAsPending642=== PAUSE TestDeduplicatedObjectsRecordedAsPending643=== RUN TestGCSweepSkipsPendingObjects644=== PAUSE TestGCSweepSkipsPendingObjects645=== RUN TestTombstonedObjectOfferedWithoutWaiting646=== PAUSE TestTombstonedObjectOfferedWithoutWaiting647=== RUN TestGCSweepDeliversEachKeyOnce648=== PAUSE TestGCSweepDeliversEachKeyOnce649=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection650=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection651=== RUN TestForceGCDuringPushOffersSweptObject652=== PAUSE TestForceGCDuringPushOffersSweptObject653=== RUN TestFailedS3DeleteKeepsTombstone654=== PAUSE TestFailedS3DeleteKeepsTombstone655=== RUN TestSweepSkipsRowsLockedByPush656=== PAUSE TestSweepSkipsRowsLockedByPush657=== RUN TestRegisterCompletedObjectNeedsPendingRow658=== PAUSE TestRegisterCompletedObjectNeedsPendingRow659=== RUN TestGetExistingObjectsLocksRows660=== PAUSE TestGetExistingObjectsLocksRows661=== RUN TestSweepRechecksPendingAfterLocking662=== PAUSE TestSweepRechecksPendingAfterLocking663=== RUN TestPushWaitsForSweepHoldingRow664=== PAUSE TestPushWaitsForSweepHoldingRow665=== RUN TestCommitRacingPendingCleanupKeepsObjects666=== PAUSE TestCommitRacingPendingCleanupKeepsObjects667=== RUN TestGCEndsOnShutdown668=== PAUSE TestGCEndsOnShutdown669=== RUN TestGCTaskStore_StartNew670=== PAUSE TestGCTaskStore_StartNew671=== RUN TestGCTaskStore_DeduplicateSameParams672=== PAUSE TestGCTaskStore_DeduplicateSameParams673=== RUN TestGCTaskStore_ConflictDifferentParams674=== PAUSE TestGCTaskStore_ConflictDifferentParams675=== RUN TestGCTaskStore_GetEmpty676=== PAUSE TestGCTaskStore_GetEmpty677=== RUN TestGCTaskStore_GetReturnsLatest678=== PAUSE TestGCTaskStore_GetReturnsLatest679=== RUN TestGCTaskStore_CompletedAllowsNewTask680=== PAUSE TestGCTaskStore_CompletedAllowsNewTask681=== RUN TestGCTaskStore_PhaseUpdates682=== PAUSE TestGCTaskStore_PhaseUpdates683=== RUN TestGCTaskStore_Fail684=== PAUSE TestGCTaskStore_Fail685=== RUN TestGracefulShutdownDrainsInflight686=== PAUSE TestGracefulShutdownDrainsInflight687=== RUN TestService_healthCheckHandler688=== PAUSE TestService_healthCheckHandler689=== RUN TestService_readinessHandler690=== PAUSE TestService_readinessHandler691=== RUN TestGenerateLandingPage692=== PAUSE TestGenerateLandingPage693=== RUN TestChildrenInheritRaisedFileLimit694=== PAUSE TestChildrenInheritRaisedFileLimit695=== RUN TestCacheConfigHandlerMaxNarSize696=== PAUSE TestCacheConfigHandlerMaxNarSize697=== RUN TestCreatePendingClosureRejectsOversizedNAR698=== PAUSE TestCreatePendingClosureRejectsOversizedNAR699=== RUN TestNARDeduplicationMetadataUploadBug700=== PAUSE TestNARDeduplicationMetadataUploadBug701=== RUN TestMetricsInventory702=== PAUSE TestMetricsInventory703=== RUN TestMetricsCommit704=== PAUSE TestMetricsCommit705=== RUN TestService_NativeMTLS706=== PAUSE TestService_NativeMTLS707=== RUN TestServerTLSConfig708=== PAUSE TestServerTLSConfig709=== RUN TestMultipartCleanup710=== PAUSE TestMultipartCleanup711=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded712=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded713=== RUN TestPendingCleanupUsesOneCutoff714=== PAUSE TestPendingCleanupUsesOneCutoff715=== RUN TestPendingClosureFailureTracksEveryUpload716=== PAUSE TestPendingClosureFailureTracksEveryUpload717=== RUN TestPendingClosureFailureAbortsItsUploads718=== PAUSE TestPendingClosureFailureAbortsItsUploads719=== RUN TestObjectStatsTrigger720=== PAUSE TestObjectStatsTrigger721=== RUN TestObjectStatsUpdatedOncePerCommit722=== PAUSE TestObjectStatsUpdatedOncePerCommit723=== RUN TestReconnectLeavesObjectsUnlocked724=== PAUSE TestReconnectLeavesObjectsUnlocked725=== RUN TestOrphanedObjectsGC726=== PAUSE TestOrphanedObjectsGC727=== RUN TestOrphanedObjectsGCStressTest728=== PAUSE TestOrphanedObjectsGCStressTest729=== RUN TestCreatePin_ReservedPins730=== PAUSE TestCreatePin_ReservedPins731=== RUN TestConcurrentPinUpdatesAgree732=== PAUSE TestConcurrentPinUpdatesAgree733=== RUN TestCreatePinRejectsBadInput734=== PAUSE TestCreatePinRejectsBadInput735=== RUN TestDeletePinKeepsRowWhenS3Fails736=== PAUSE TestDeletePinKeepsRowWhenS3Fails737=== RUN TestPresentReportsOnlyClosureRoots738=== PAUSE TestPresentReportsOnlyClosureRoots739=== RUN TestPresentRefreshesOnlyStaleClosures740=== PAUSE TestPresentRefreshesOnlyStaleClosures741=== RUN TestPresentNotReportedWhileGCDeletesClosure742=== PAUSE TestPresentNotReportedWhileGCDeletesClosure743=== RUN TestParseSingleRange744=== PAUSE TestParseSingleRange745=== RUN TestProxyHeadersOnlyTrustedOnSocket7462026/10/27 08:49:50 INFO Starting HTTP server address=proxy.sock7472026/10/27 08:49:50 INFO Starting HTTP server address=127.0.0.1:648997482026/10/27 08:49:50 WARN mTLS auth: subject not in bound subjects subject="CN=someone"7492026/10/27 08:49:50 INFO Shutdown signal received, draining in-flight requests timeout=10s750--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.16s)751=== RUN TestIsValidCachePath752=== PAUSE TestIsValidCachePath753=== RUN TestReadProxyNarinfo754=== PAUSE TestReadProxyNarinfo755=== RUN TestReadProxyNarinfoAlreadyDecompressed756=== PAUSE TestReadProxyNarinfoAlreadyDecompressed757=== RUN TestReadProxyContentNegotiation758=== PAUSE TestReadProxyContentNegotiation759=== RUN TestReadProxyNarStreaming760=== PAUSE TestReadProxyNarStreaming761=== RUN TestReadProxy404And429762=== PAUSE TestReadProxy404And429763=== RUN TestReadProxyInvalidPath764=== PAUSE TestReadProxyInvalidPath765=== RUN TestReadProxyHead766=== PAUSE TestReadProxyHead767=== RUN TestReadProxyOutlastsServerWriteTimeout768=== PAUSE TestReadProxyOutlastsServerWriteTimeout769=== RUN TestReadProxyConditionalGet770=== PAUSE TestReadProxyConditionalGet771=== RUN TestReadProxyRootRedirectsToIndexHTML772=== PAUSE TestReadProxyRootRedirectsToIndexHTML773=== RUN TestReadProxyDisabled774=== PAUSE TestReadProxyDisabled775=== RUN TestReadRedirectNar776=== PAUSE TestReadRedirectNar777=== RUN TestReadRedirectKeepsNarinfoProxied778=== PAUSE TestReadRedirectKeepsNarinfoProxied779=== RUN TestReadProxyRangeRequest780=== PAUSE TestReadProxyRangeRequest781=== RUN TestReadRedirectUsesPublicS3URL782=== PAUSE TestReadRedirectUsesPublicS3URL783=== RUN TestPush_OverlappingRootsStoreOneRowPerKey784=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey785=== RUN TestPush_CompleteCommitsEveryRoot786=== PAUSE TestPush_CompleteCommitsEveryRoot787=== RUN TestPush_RepeatedRootCommitsOnce788=== PAUSE TestPush_RepeatedRootCommitsOnce789=== RUN TestPush_CompleteWaitsForCleanupOfThePush790=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush791=== RUN TestPush_RootsAreLockedInByteOrder792=== PAUSE TestPush_RootsAreLockedInByteOrder793=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit794=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit795=== RUN TestPush_RejectsBadRequests796=== PAUSE TestPush_RejectsBadRequests797=== RUN TestPush_SignsNarinfosOfItsPendingObjects798=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects799=== RUN TestRedundantMultipartUpload800=== PAUSE TestRedundantMultipartUpload801=== RUN TestCompleteMultipartUpload_ErrorButObjectExists802=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists803=== RUN TestCompletedNarNotReofferedAcrossClosures804=== PAUSE TestCompletedNarNotReofferedAcrossClosures805=== RUN TestPresignedUploadRegisteredBeforeCommit806=== PAUSE TestPresignedUploadRegisteredBeforeCommit807=== RUN TestService_Rustfstest808=== PAUSE TestService_Rustfstest809=== RUN TestParseSize810=== PAUSE TestParseSize811=== RUN TestSkippedUploadsHandler812=== PAUSE TestSkippedUploadsHandler813=== RUN TestSystemdListenerNotActivated814--- PASS: TestSystemdListenerNotActivated (0.00s)815=== RUN TestWatchdogBeatsWhenHealthy816--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)817=== RUN TestWatchdogSkipsWhenUnhealthy8182026/10/27 08:49:50 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"8192026/10/27 08:49:50 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"8202026/10/27 08:49:50 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"8212026/10/27 08:49:50 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"8222026/10/27 08:49:50 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"8232026/10/27 08:49:50 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"8242026/10/27 08:49:50 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"8252026/10/27 08:49:50 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"8262026/10/27 08:49:50 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"8272026/10/27 08:49:50 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 TestPush_RepeatedRootCommitsOnce852=== CONT TestReadProxyRootRedirectsToIndexHTML853=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT854=== CONT TestCreatePinRejectsBadInput855=== CONT TestCompleteMultipartUnregistered856=== CONT TestCreatePin_ReservedPins857=== CONT TestPush_CompleteCommitsEveryRoot858=== CONT TestPush_OverlappingRootsStoreOneRowPerKey859=== CONT TestReadRedirectUsesPublicS3URL860=== CONT TestRegisterCompletedObjectNeedsPendingRow861=== CONT TestReadRedirectKeepsNarinfoProxied862=== CONT TestSweepRechecksPendingAfterLocking863=== CONT TestReadRedirectNar864=== CONT TestSkippedUploadsHandler865=== CONT TestService_verifyS3Integrity866=== CONT TestConcurrentPinUpdatesAgree867=== CONT TestService_createPendingClosureHandler868=== CONT TestForceGCDuringPushOffersSweptObject869=== CONT TestService_cleanupPendingClosuresHandler870=== CONT TestUploadHandlersRejectOversizedBody871=== CONT TestFailedS3DeleteKeepsTombstone872=== CONT TestOrphanedObjectsGC873=== CONT TestService_AuthMiddleware874=== CONT TestPush_RootsAreLockedInByteOrder875=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows876=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows877=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check878=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check879=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection8802026/10/27 08:49:50 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000881--- PASS: TestSkippedUploadsHandler (0.04s)882=== CONT TestOrphanedObjectsGCStressTest883=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure884=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure885=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart886=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart887=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts888=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts889=== CONT TestGCSweepDeliversEachKeyOnce8902026/10/27 08:49:50 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:64903/oidc8912026/10/27 08:49:50 INFO Received push request method=POST path=/api/pushes892--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.73s)893=== CONT TestReconnectLeavesObjectsUnlocked8942026/10/27 08:49:51 INFO Received uploads request method=POST path=/api/pending_closures895--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (1.17s)896=== CONT TestGCSweepSkipsPendingObjects8972026/10/27 08:49:51 INFO Received create pin request method=POST path=/api/pins/deploy8982026/10/27 08:49:51 INFO Received create pin request method=POST path=/api/pins/deploy8992026/10/27 08:49:51 INFO Received create pin request method=POST path=/api/pins/deploy9002026/10/27 08:49:51 INFO Received create pin request method=POST path=/api/pins/deploy9012026/10/27 08:49:51 INFO Received create pin request method=POST path=/api/pins/deploy9022026/10/27 08:49:51 INFO Received create pin request method=POST path=/api/pins/deploy9032026/10/27 08:49:51 INFO Received create pin request method=POST path=/api/pins/deploy9042026/10/27 08:49:51 INFO Received create pin request method=POST path=/api/pins/deploy9052026/10/27 08:49:51 INFO Received create pin request method=POST path=/api/pins/deploy9062026/10/27 08:49:52 INFO Received create pin request method=POST path=/api/pins/deploy9072026/10/27 08:49:52 INFO Created/updated pin name=deploy store_path="/nix/store/dddddddddddddddddddddddddddddddd-app-1.0+git_x?y=z" narinfo_key=dddddddddddddddddddddddddddddddd.narinfo908--- PASS: TestCreatePinRejectsBadInput (1.71s)909=== CONT TestDeduplicatedObjectsRecordedAsPending9102026/10/27 08:49:52 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"911--- PASS: TestService_AuthMiddleware (1.91s)912=== CONT TestObjectStatsTrigger9132026/10/27 08:49:52 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9142026/10/27 08:49:52 INFO Completed multipart upload object_key=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa00000000000000000000.nar.zst upload_id=YTE1YjQ3ZTctZDJlNS00N2M0LTg3MTgtMDhhNGZlYmRjYzA1LmU0ZjI5ZWEzLThjZGItNDQ4MS05YTdkLTRhYzNhN2JkYWQ5MHgxNzkzMDkwOTkwOTgxNjgxMDAw parts=109152026/10/27 08:49:52 INFO Aborted multipart uploads count=0 kept=09162026/10/27 08:49:52 WARN Force mode enabled - objects will be deleted immediately without grace period9172026/10/27 08:49:52 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=09182026/10/27 08:49:52 INFO Vacuumed table table=pending_closures9192026/10/27 08:49:52 INFO Vacuumed table table=pending_objects9202026/10/27 08:49:52 INFO Vacuumed table table=multipart_uploads9212026/10/27 08:49:52 INFO Vacuumed table table=closures9222026/10/27 08:49:52 INFO Vacuumed table table=objects923--- PASS: TestSweepRechecksPendingAfterLocking (2.32s)924=== CONT TestObjectStatsUpdatedOncePerCommit925--- PASS: TestReadRedirectUsesPublicS3URL (2.50s)926=== CONT TestPushDedupSurvivesConcurrentGC9272026/10/27 08:49:53 INFO Received push request method=POST path=/api/pushes928--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (2.73s)929=== CONT TestPendingClosureFailureTracksEveryUpload930=== RUN TestPendingClosureFailureTracksEveryUpload/refuse_aborts=false931=== PAUSE TestPendingClosureFailureTracksEveryUpload/refuse_aborts=false932=== RUN TestPendingClosureFailureTracksEveryUpload/refuse_aborts=true933=== PAUSE TestPendingClosureFailureTracksEveryUpload/refuse_aborts=true934=== CONT TestTombstonedObjectOfferedWithoutWaiting9352026/10/27 08:49:53 INFO Received push request method=POST path=/api/pushes936--- PASS: TestReadRedirectKeepsNarinfoProxied (3.18s)937=== CONT TestPendingCleanupUsesOneCutoff9382026/10/27 08:49:53 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9392026/10/27 08:49:53 INFO Completed multipart upload object_key=nar/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb00000000000000000000.nar.zst upload_id=YTE1YjQ3ZTctZDJlNS00N2M0LTg3MTgtMDhhNGZlYmRjYzA1Ljk3NGM1MzUzLTA4M2ItNDgxYS1hMDVkLTIzZWUyMDYwYzI3NXgxNzkzMDkwOTkwOTgxMjc5MDAw parts=109402026/10/27 08:49:53 INFO Received complete push request method=POST path=/api/pushes/1/complete9412026/10/27 08:49:53 INFO Completed push id=1 objects=4 duration=12.24725ms942--- PASS: TestPush_RepeatedRootCommitsOnce (3.30s)943=== CONT TestGCBugBareHashReferences9442026/10/27 08:49:53 INFO Received uploads request method=POST path=/api/pending_closures9452026/10/27 08:49:54 INFO Aborted multipart uploads count=0 kept=09462026/10/27 08:49:54 WARN Force mode enabled - objects will be deleted immediately without grace period9472026/10/27 08:49:54 INFO Received uploads request method=POST path=/api/pending_closures9482026/10/27 08:49:54 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."9492026/10/27 08:49:54 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."950--- PASS: TestFailedS3DeleteKeepsTombstone (3.61s)951=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded9522026/10/27 08:49:54 INFO Received complete multipart upload request method=POST path=/api/multipart/complete953--- PASS: TestRegisterCompletedObjectNeedsPendingRow (4.11s)954=== CONT TestGCMetrics9552026/10/27 08:49:54 INFO Completed multipart upload object_key=nar/cccccccccccccccccccccccccccccccc00000000000000000000.nar.zst upload_id=YTE1YjQ3ZTctZDJlNS00N2M0LTg3MTgtMDhhNGZlYmRjYzA1LjI2N2Q3NGM0LWNmMjMtNDkwNy1iYmFjLWU2NTBjMjU3MDFlMXgxNzkzMDkwOTkzMzMwNTYxMDAw parts=10956--- PASS: TestReadRedirectNar (4.39s)957=== CONT TestPendingClosureFailureAbortsItsUploads9582026/10/27 08:49:55 INFO Received cleanup request method=DELETE path=/api/pending_closures9592026/10/27 08:49:55 INFO Aborted multipart uploads count=0 kept=09602026/10/27 08:49:55 INFO Received uploads request method=POST path=/api/pending_closures9612026/10/27 08:49:55 INFO Received cleanup request method=DELETE path=/api/pending_closures9622026/10/27 08:49:55 INFO Aborted multipart uploads count=1 kept=09632026/10/27 08:49:55 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9642026-10-27 08:49:55.196 UTC [86048] ERROR: Closure does not exist: id=19652026-10-27 08:49:55.196 UTC [86048] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE9662026-10-27 08:49:55.196 UTC [86048] STATEMENT: -- name: CommitPendingClosure :one967 SELECT commit_pending_closure($1::bigint)::bigint968 969--- PASS: TestService_cleanupPendingClosuresHandler (4.80s)970=== CONT TestGCAdvisoryLockBlocksConcurrentRun9712026/10/27 08:49:55 INFO Received create pin request method=POST path=/api/pins/app9722026/10/27 08:49:55 INFO Received create pin request method=POST path=/api/pins/app9732026/10/27 08:49:55 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9742026/10/27 08:49:55 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=YTE1YjQ3ZTctZDJlNS00N2M0LTg3MTgtMDhhNGZlYmRjYzA1Ljk5YzFhODYxLWUwNTQtNDBhZS05NzZhLTIyNTY4OWNiNTdkOXgxNzkzMDkwOTk0MDY2OTAyMDAw parts=109752026/10/27 08:49:55 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9762026/10/27 08:49:55 INFO Completed upload id=1 objects=2 duration=24.615666ms9772026/10/27 08:49:55 INFO Received uploads request method=POST path=/api/pending_closures9782026/10/27 08:49:55 INFO Received uploads request method=POST path=/api/pending_closures9792026/10/27 08:49:55 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo9802026/10/27 08:49:55 WARN Found objects in DB but missing from S3, will re-upload count=19812026/10/27 08:49:55 INFO Created/updated pin name=app store_path=/nix/store/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa-app narinfo_key=aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.narinfo9822026/10/27 08:49:55 INFO Received complete upload request method=POST path=/api/pending_closures/3/complete9832026/10/27 08:49:55 INFO Completed upload id=3 objects=2 duration=1.50025ms984--- PASS: TestService_verifyS3Integrity (5.61s)985=== CONT TestServerTLSConfig986=== RUN TestServerTLSConfig/no_client_CA987=== PAUSE TestServerTLSConfig/no_client_CA988=== RUN TestServerTLSConfig/missing_CA_file989=== PAUSE TestServerTLSConfig/missing_CA_file990=== RUN TestServerTLSConfig/not_a_PEM_file9912026/10/27 08:49:56 INFO Created/updated pin name=app store_path=/nix/store/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb-app narinfo_key=bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb.narinfo992=== PAUSE TestServerTLSConfig/not_a_PEM_file993=== CONT TestLeadEndsOnShutdown994=== CONT TestService_NativeMTLS995--- PASS: TestConcurrentPinUpdatesAgree (5.69s)9962026/10/27 08:49:56 INFO Received push request method=POST path=/api/pushes997=== NAME TestOrphanedObjectsGC998 orphaned_objects_gc_test.go:287: GC Test Summary:999 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A1000 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B1001 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)1002 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)1003 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects1004--- PASS: TestOrphanedObjectsGC (5.95s)1005=== CONT TestLeadIncumbentAnnouncesAtOnce10062026/10/27 08:49:56 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10072026/10/27 08:49:56 INFO Completed multipart upload object_key=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa00000000000000000000.nar.zst upload_id=YTE1YjQ3ZTctZDJlNS00N2M0LTg3MTgtMDhhNGZlYmRjYzA1LjZiNmJmNzdiLTNlYmItNDE4My05MGE2LWE5MDY2Y2UzZGI3NHgxNzkzMDkwOTkzMzMwNTQwMDAw parts=1010082026/10/27 08:49:56 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10092026/10/27 08:49:56 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst1010--- PASS: TestCompleteMultipartUnregistered (6.21s)1011=== CONT TestMultipartCleanup10122026/10/27 08:49:56 INFO Received uploads request method=POST path=/api/pending_closures10132026/10/27 08:49:56 INFO Received uploads request method=POST path=/api/pending_closures10142026/10/27 08:49:56 INFO Received uploads request method=POST path=/api/pending_closures10152026/10/27 08:49:57 INFO Received uploads request method=POST path=/api/pending_closures1016--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (7.18s)1017=== CONT TestMetricsInventory10182026/10/27 08:49:57 INFO Aborted multipart uploads count=0 kept=010192026/10/27 08:49:57 WARN Force mode enabled - objects will be deleted immediately without grace period1020--- PASS: TestReconnectLeavesObjectsUnlocked (7.04s)1021=== CONT TestLeadElectsOneAndHandsOver10222026/10/27 08:49:58 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10232026/10/27 08:49:58 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10242026/10/27 08:49:58 INFO Completed multipart upload object_key=nar/cccccccccccccccccccccccccccccccc00000000000000000000.nar.zst upload_id=YTE1YjQ3ZTctZDJlNS00N2M0LTg3MTgtMDhhNGZlYmRjYzA1LjViNzRmMmEwLWNiMzktNGMzYy1hZTU5LWU0ZWQ5MDAzNzEzOXgxNzkzMDkwOTk2Mjc4OTUwMDAw parts=1010252026/10/27 08:49:58 INFO Completed multipart upload object_key=nar/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb00000000000000000000.nar.zst upload_id=YTE1YjQ3ZTctZDJlNS00N2M0LTg3MTgtMDhhNGZlYmRjYzA1LjQxNmQ4NzVkLTNiZTUtNDdkYi1hMWI2LTk4ZTAwOTcwNjVkZHgxNzkzMDkwOTkzMzI5NzU3MDAw parts=1010262026/10/27 08:49:58 INFO Received complete push request method=POST path=/api/pushes/1/complete10272026/10/27 08:49:58 INFO Completed push id=1 objects=6 duration=23.453667ms1028--- PASS: TestPush_CompleteCommitsEveryRoot (8.08s)1029=== CONT TestNARDeduplicationMetadataUploadBug10302026/10/27 08:49:58 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux10312026/10/27 08:49:58 WARN Refused reserved pin name=worker-x86_64-linux10322026/10/27 08:49:58 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux10332026/10/27 08:49:58 INFO Received create pin request method=POST path=/api/pins/my-app10342026/10/27 08:49:58 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux10352026/10/27 08:49:58 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=010362026/10/27 08:49:58 INFO Vacuumed table table=pending_closures10372026/10/27 08:49:58 INFO Vacuumed table table=pending_objects10382026/10/27 08:49:58 INFO Vacuumed table table=multipart_uploads10392026/10/27 08:49:58 INFO Vacuumed table table=closures1040--- PASS: TestCreatePin_ReservedPins (8.24s)1041=== CONT TestConnectSerialisesConcurrentMigrations10422026/10/27 08:49:58 INFO Vacuumed table table=objects1043--- PASS: TestGCSweepDeliversEachKeyOnce (8.12s)1044=== CONT TestCreatePendingClosureRejectsOversizedNAR10452026/10/27 08:49:58 INFO Received uploads request method=POST path=/api/pending_closures1046--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.01s)1047=== CONT TestResolveDBConnectionString1048=== RUN TestResolveDBConnectionString/flag_wins1049=== PAUSE TestResolveDBConnectionString/flag_wins1050=== RUN TestResolveDBConnectionString/file_when_flag_empty1051=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1052=== RUN TestResolveDBConnectionString/missing_file_is_an_error1053=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1054=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1055=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1056=== RUN TestResolveDBConnectionString/nothing_configured1057=== PAUSE TestResolveDBConnectionString/nothing_configured1058=== CONT TestCacheConfigHandlerMaxNarSize1059--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1060=== CONT TestMetricsCommit10612026/10/27 08:49:58 INFO Received uploads request method=POST path=/api/pending_closures10622026/10/27 08:49:59 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10632026/10/27 08:49:59 INFO Aborted multipart uploads count=0 kept=010642026/10/27 08:49:59 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=YTE1YjQ3ZTctZDJlNS00N2M0LTg3MTgtMDhhNGZlYmRjYzA1LmUzYjI4YmQ0LTU5MzYtNDZmMy04MmIzLTMxZmE2OGY2YjU0YXgxNzkzMDkwOTk3MDA4MzQzMDAw parts=1010652026/10/27 08:49:59 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10662026/10/27 08:49:59 WARN Force mode enabled - objects will be deleted immediately without grace period10672026/10/27 08:49:59 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=010682026/10/27 08:49:59 INFO Completed upload id=1 objects=2 duration=27.687959ms10692026/10/27 08:49:59 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000010702026/10/27 08:49:59 INFO Vacuumed table table=pending_closures10712026/10/27 08:49:59 INFO Received uploads request method=POST path=/api/pending_closures10722026/10/27 08:49:59 INFO Starting cleanup of old closures method=DELETE path=/api/closures10732026/10/27 08:49:59 INFO Aborted multipart uploads count=0 kept=010742026/10/27 08:49:59 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=010752026/10/27 08:49:59 INFO Vacuumed table table=pending_objects10762026/10/27 08:49:59 INFO Vacuumed table table=multipart_uploads10772026/10/27 08:49:59 INFO Vacuumed table table=closures10782026/10/27 08:49:59 INFO Vacuumed table table=objects10792026/10/27 08:49:59 INFO Vacuumed table table=pending_closures10802026/10/27 08:49:59 INFO Vacuumed table table=pending_objects1081--- PASS: TestObjectStatsTrigger (7.13s)1082=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock1083--- PASS: TestGCSweepSkipsPendingObjects (7.89s)1084=== CONT TestGenerateLandingPage10852026/10/27 08:49:59 INFO Vacuumed table table=multipart_uploads10862026/10/27 08:49:59 INFO Vacuumed table table=closures1087--- PASS: TestGenerateLandingPage (0.01s)1088=== CONT TestDeleteClosuresRacingPins10892026/10/27 08:49:59 INFO Vacuumed table table=objects10902026/10/27 08:49:59 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001091--- PASS: TestService_createPendingClosureHandler (9.16s)1092=== CONT TestConnectWaitsForAPeerMigration10932026/10/27 08:49:59 INFO Received uploads request method=POST path=/api/pending_closures1094--- PASS: TestDeduplicatedObjectsRecordedAsPending (7.62s)1095=== CONT TestChildrenInheritRaisedFileLimit1096=== CONT TestClientFallsBackToClosures1097--- PASS: TestChildrenInheritRaisedFileLimit (0.01s)10982026/10/27 08:50:00 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10992026/10/27 08:50:00 INFO Completed multipart upload object_key=nar/dddddddddddddddddddddddddddddddd00000000000000000000.nar.zst upload_id=YTE1YjQ3ZTctZDJlNS00N2M0LTg3MTgtMDhhNGZlYmRjYzA1LmY2NWMyNmRlLTMwYzctNDEzMy1hZTA4LThjYWMzMjcxYjViNHgxNzkzMDkwOTk2Mjc5MDU5MDAw parts=101100=== CONT TestService_readinessHandler1101--- PASS: TestObjectStatsUpdatedOncePerCommit (7.67s)11022026/10/27 08:50:00 INFO Received uploads request method=POST path=/api/pending_closures11032026/10/27 08:50:00 INFO Received uploads request method=POST path=/api/pending_closures11042026/10/27 08:50:00 INFO Aborted multipart uploads count=0 kept=011052026/10/27 08:50:00 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=01106--- PASS: TestTombstonedObjectOfferedWithoutWaiting (7.67s)1107=== CONT TestGracefulShutdownDrainsInflight11082026/10/27 08:50:00 INFO Vacuumed table table=pending_closures11092026/10/27 08:50:00 INFO Starting HTTP server address=127.0.0.1:6509111102026/10/27 08:50:00 INFO Shutdown signal received, draining in-flight requests timeout=10s11112026/10/27 08:50:00 INFO Vacuumed table table=pending_objects11122026/10/27 08:50:00 INFO Vacuumed table table=multipart_uploads1113--- PASS: TestGracefulShutdownDrainsInflight (0.08s)1114=== CONT TestPinProtectsFromGC11152026/10/27 08:50:00 INFO Vacuumed table table=closures11162026/10/27 08:50:00 INFO Vacuumed table table=objects11172026/10/27 08:50:00 INFO Aborted multipart uploads count=0 kept=011182026/10/27 08:50:00 WARN Force mode enabled - objects will be deleted immediately without grace period11192026/10/27 08:50:00 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=011202026/10/27 08:50:01 INFO Vacuumed table table=pending_closures11212026/10/27 08:50:01 INFO Vacuumed table table=pending_objects11222026/10/27 08:50:01 INFO Vacuumed table table=multipart_uploads11232026/10/27 08:50:01 INFO Vacuumed table table=closures11242026/10/27 08:50:01 INFO Vacuumed table table=objects11252026/10/27 08:50:01 INFO Received uploads request method=POST path=/api/pending_closures1126--- PASS: TestPushDedupSurvivesConcurrentGC (8.16s)1127=== CONT TestService_healthCheckHandler11282026/10/27 08:50:01 INFO Received uploads request method=POST path=/api/pending_closures11292026/10/27 08:50:01 INFO Received cleanup request method=DELETE path=/api/pending_closures11302026-10-27 08:50:01.596 UTC [86177] ERROR: duplicate key value violates unique constraint "pg_type_typname_nsp_index"11312026-10-27 08:50:01.596 UTC [86177] DETAIL: Key (typname, typnamespace)=(goose_db_version, 2200) already exists.11322026-10-27 08:50:01.596 UTC [86177] STATEMENT: CREATE TABLE goose_db_version (1133 id integer PRIMARY KEY GENERATED BY DEFAULT AS IDENTITY,1134 version_id bigint NOT NULL,1135 is_applied boolean NOT NULL,1136 tstamp timestamp NOT NULL DEFAULT now()1137 )1138--- PASS: TestGCBugBareHashReferences (7.99s)1139=== CONT TestGCTaskStore_Fail1140--- PASS: TestGCTaskStore_Fail (0.00s)1141=== CONT TestClientSharedPathCommittedMidPush11422026/10/27 08:50:01 INFO Received uploads request method=POST path=/api/pending_closures1143--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (7.91s)1144=== CONT TestGCTaskStore_CompletedAllowsNewTask1145--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1146=== CONT TestClientPushesUseOnePush11472026/10/27 08:50:02 INFO Aborted multipart uploads count=0 kept=011482026/10/27 08:50:02 WARN Force mode enabled - objects will be deleted immediately without grace period11492026/10/27 08:50:02 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=011502026/10/27 08:50:02 INFO Vacuumed table table=pending_closures11512026/10/27 08:50:02 INFO Vacuumed table table=pending_objects11522026/10/27 08:50:02 INFO Vacuumed table table=multipart_uploads11532026/10/27 08:50:02 INFO Vacuumed table table=closures11542026/10/27 08:50:02 INFO Vacuumed table table=objects1155--- PASS: TestGCMetrics (7.71s)1156=== CONT TestGCTaskStore_PhaseUpdates1157--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1158=== CONT TestClientWithDependencies11592026/10/27 08:50:02 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11602026/10/27 08:50:02 INFO Completed multipart upload object_key=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa00000000000000000000.nar.zst upload_id=YTE1YjQ3ZTctZDJlNS00N2M0LTg3MTgtMDhhNGZlYmRjYzA1LmRiYzU0MzE3LWNiNjAtNGJmNS1iMjAxLWEzZWM1Yzc4ZWU1MngxNzkzMDkwOTk2Mjc5MDExMDAw parts=1011612026/10/27 08:50:02 INFO Received uploads request method=POST path=/api/pending_closures1162--- PASS: TestPendingClosureFailureAbortsItsUploads (7.79s)1163=== CONT TestGCTaskStore_GetReturnsLatest1164--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1165=== CONT TestGCTaskStore_ConflictDifferentParams1166--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1167=== CONT TestClientIntegration1168--- PASS: TestConnectSerialisesConcurrentMigrations (3.97s)1169=== CONT TestGCTaskStore_GetEmpty1170=== CONT TestClientErrorHandling1171=== RUN TestClientErrorHandling/InvalidStorePath1172--- PASS: TestGCTaskStore_GetEmpty (0.00s)1173=== PAUSE TestClientErrorHandling/InvalidStorePath1174=== RUN TestClientErrorHandling/InvalidAuthToken1175=== PAUSE TestClientErrorHandling/InvalidAuthToken1176=== RUN TestClientErrorHandling/ServerNotAvailable1177=== PAUSE TestClientErrorHandling/ServerNotAvailable1178=== CONT TestGCTaskStore_StartNew1179--- PASS: TestGCTaskStore_StartNew (0.00s)1180=== CONT TestClientMultipleUploads11812026/10/27 08:50:03 WARN mTLS auth: subject not in bound subjects subject="CN=reader"11822026/10/27 08:50:03 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1183--- PASS: TestService_NativeMTLS (7.03s)1184=== CONT TestCacheStatsHandler11852026/10/27 08:50:03 INFO lead: acquired remote=192.0.2.1:123411862026/10/27 08:50:03 INFO lead: acquired remote=192.0.2.1:123411872026/10/27 08:50:03 INFO lead: released remote=192.0.2.1:12341188--- PASS: TestLeadIncumbentAnnouncesAtOnce (7.39s)1189=== CONT TestGCEndsOnShutdown1190=== RUN TestGCEndsOnShutdown/before_the_run1191=== PAUSE TestGCEndsOnShutdown/before_the_run1192=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1193=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1194=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1195=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1196=== CONT TestCommitRacingPendingCleanupKeepsObjects11972026/10/27 08:50:03 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11982026/10/27 08:50:04 INFO Completed multipart upload object_key=nar/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb00000000000000000000.nar.zst upload_id=YTE1YjQ3ZTctZDJlNS00N2M0LTg3MTgtMDhhNGZlYmRjYzA1LmQ0N2JjZWRhLTE4YjgtNDYyMS1hZjljLWFjZDI1MzI2MTc1M3gxNzkzMDkwOTk2Mjc4ODk1MDAw parts=1011992026/10/27 08:50:04 INFO Received uploads request method=POST path=/api/pending_closures12002026/10/27 08:50:04 INFO Received cleanup request method=DELETE path=/api/pending_closures12012026/10/27 08:50:04 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket44/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""12022026/10/27 08:50:04 INFO Aborted multipart uploads count=0 kept=112032026/10/27 08:50:04 INFO Received cleanup request method=DELETE path=/api/pending_closures12042026/10/27 08:50:04 INFO Aborted multipart uploads count=1 kept=012052026/10/27 08:50:04 INFO lead: released remote=192.0.2.1:12341206--- PASS: TestLeadEndsOnShutdown (8.38s)1207=== CONT TestGCTaskStore_DeduplicateSameParams1208=== CONT TestPushWaitsForSweepHoldingRow1209--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1210--- PASS: TestMultipartCleanup (7.86s)1211=== CONT TestCacheConfigHandler1212=== RUN TestCacheConfigHandler/full_config,_no_issuer1213=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1214=== RUN TestCacheConfigHandler/no_cache_url_configured1215=== PAUSE TestCacheConfigHandler/no_cache_url_configured1216=== RUN TestCacheConfigHandler/no_signing_keys1217=== PAUSE TestCacheConfigHandler/no_signing_keys1218=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1219=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1220=== CONT TestGetExistingObjectsLocksRows1221--- PASS: TestMetricsInventory (6.97s)1222=== CONT TestService_ReadScope_PublicByDefault12232026/10/27 08:50:04 INFO lead: acquired remote=192.0.2.1:123412242026/10/27 08:50:05 INFO Received push request method=POST path=/api/pushes1225=== NAME TestNARDeduplicationMetadataUploadBug1226 metadata_upload_test.go:48: First store path: /private/var/tb/6/scratch/7ab19ce6cf566bc8/build/TestNARDeduplicationMetadataUploadBug3631889982/001/store/jmmlqds1bx06qjm164wag187ivlw22dq-file1.txt12272026/10/27 08:50:05 INFO Received push request method=POST path=/api/pushes12282026/10/27 08:50:05 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12292026/10/27 08:50:05 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12302026/10/27 08:50:05 INFO Uploading jmmlqds1bx06qjm164wag187ivlw22dq-file1.txt (160B)12312026/10/27 08:50:05 WARN Failed to register uploaded object key=jmmlqds1bx06qjm164wag187ivlw22dq.ls error="server returned 404: 404 page not found\n"12322026/10/27 08:50:05 INFO Completed multipart upload object_key=nar/ffffffffffffffffffffffffffffffff00000000000000000000.nar.zst upload_id=YTE1YjQ3ZTctZDJlNS00N2M0LTg3MTgtMDhhNGZlYmRjYzA1Ljc1OGJlNzc4LWMwOTktNGI0Yi04MDExLWQxMDhlYTQ4MTFiYXgxNzkzMDkwOTk2Mjc4OTU4MDAw parts=1012332026/10/27 08:50:05 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"12342026/10/27 08:50:05 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12352026/10/27 08:50:05 INFO Signed narinfos id=1 count=112362026/10/27 08:50:05 INFO Uploading 1 narinfos12372026/10/27 08:50:05 INFO Received complete push request method=POST path=/api/pushes/1/complete12382026/10/27 08:50:05 WARN Failed to register uploaded object key=jmmlqds1bx06qjm164wag187ivlw22dq.narinfo error="server returned 404: 404 page not found\n"12392026/10/27 08:50:05 INFO Completed push id=1 objects=3 duration=52.137666ms12402026/10/27 08:50:05 INFO Upload complete. (359ms)1241 metadata_upload_test.go:54: Retrieved narinfo from S3:1242 StorePath: /private/var/tb/6/scratch/7ab19ce6cf566bc8/build/TestNARDeduplicationMetadataUploadBug3631889982/001/store/jmmlqds1bx06qjm164wag187ivlw22dq-file1.txt1243 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1244 Compression: zstd1245 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1246 NarSize: 1601247 References: 1248 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1249 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1250 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1251 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}12522026/10/27 08:50:06 INFO lead: released remote=192.0.2.1:123412532026/10/27 08:50:06 INFO lead: acquired remote=192.0.2.1:12341254 metadata_upload_test.go:64: Second store path (same content): /private/var/tb/6/scratch/7ab19ce6cf566bc8/build/TestNARDeduplicationMetadataUploadBug3631889982/001/store/mw50dnp74mv0ha7viyy5a8vxrczasm25-file2.txt12552026/10/27 08:50:06 INFO Received push request method=POST path=/api/pushes12562026/10/27 08:50:06 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)12572026/10/27 08:50:06 WARN Failed to register uploaded object key=mw50dnp74mv0ha7viyy5a8vxrczasm25.ls error="server returned 404: 404 page not found\n"12582026/10/27 08:50:06 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign12592026/10/27 08:50:06 INFO Signed narinfos id=2 count=112602026/10/27 08:50:06 INFO Uploading 1 narinfos12612026/10/27 08:50:06 INFO Received complete push request method=POST path=/api/pushes/2/complete12622026/10/27 08:50:06 WARN Failed to register uploaded object key=mw50dnp74mv0ha7viyy5a8vxrczasm25.narinfo error="server returned 404: 404 page not found\n"12632026/10/27 08:50:06 INFO Completed push id=2 objects=3 duration=812.042µs12642026/10/27 08:50:06 INFO Upload complete. (238ms)1265 metadata_upload_test.go:76: Retrieved narinfo from S3:1266 StorePath: /private/var/tb/6/scratch/7ab19ce6cf566bc8/build/TestNARDeduplicationMetadataUploadBug3631889982/001/store/mw50dnp74mv0ha7viyy5a8vxrczasm25-file2.txt1267 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1268 Compression: zstd1269 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1270 NarSize: 1601271 References: 1272 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1273 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1274 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1275 {"version":1,"root":{"type":"regular","size":44}}1276--- PASS: TestNARDeduplicationMetadataUploadBug (8.10s)1277=== CONT TestClientCADerivations12782026/10/27 08:50:07 WARN readiness check failed error="closed pool"1279--- PASS: TestService_readinessHandler (6.68s)1280=== CONT TestService_AuthMiddleware_MTLSProxyHeader12812026/10/27 08:50:07 INFO lead: released remote=192.0.2.1:12341282--- PASS: TestLeadElectsOneAndHandsOver (8.98s)1283=== CONT TestService_AuthMiddleware_MTLSBoundSubjects12842026/10/27 08:50:07 INFO Aborted multipart uploads count=1 kept=012852026/10/27 08:50:07 INFO Received cleanup request method=DELETE path=/api/pending_closures12862026/10/27 08:50:07 INFO Aborted multipart uploads count=1 kept=01287--- PASS: TestPendingCleanupUsesOneCutoff (13.75s)1288=== CONT TestReadProxyRangeRequest12892026/10/27 08:50:07 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12902026/10/27 08:50:07 INFO Received uploads request method=POST path=/api/pending_closures12912026/10/27 08:50:07 INFO Received uploads request method=POST path=/api/pending_closures12922026/10/27 08:50:07 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)12932026/10/27 08:50:07 INFO Uploading absmzg61r7kzjhsm3fq9acsh6fwrg1c9-shared-dep (136B)12942026/10/27 08:50:07 INFO Uploading yr0nvf9liaj5xnrysnpvzqrif4vqa8s7-a (256B)12952026/10/27 08:50:07 INFO Completed multipart upload object_key=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa00000000000000000000.nar.zst upload_id=YTE1YjQ3ZTctZDJlNS00N2M0LTg3MTgtMDhhNGZlYmRjYzA1LjhiYjg4ZmZhLWQyYWItNGFhMi05ODA4LTM4NjI3ZDJhZTNlZHgxNzkzMDkxMDA1NjMwMzEwMDAw parts=1012962026/10/27 08:50:07 WARN Failed to register uploaded object key=rkx3nwhra8wijccvikqhkhkgp6l8y6rz.ls error="server returned 404: 404 page not found\n"12972026/10/27 08:50:07 WARN Failed to register uploaded object key=absmzg61r7kzjhsm3fq9acsh6fwrg1c9.ls error="server returned 404: 404 page not found\n"12982026/10/27 08:50:07 WARN Failed to register uploaded object key=nar/0a0hcjgc7q08bx09xk0gdb6c3jcfsf5hpmlwd0a4l6d566jgnk21.nar.zst error="server returned 404: 404 page not found\n"12992026/10/27 08:50:07 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"13002026/10/27 08:50:07 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign13012026/10/27 08:50:07 WARN Failed to register uploaded object key=yr0nvf9liaj5xnrysnpvzqrif4vqa8s7.ls error="server returned 404: 404 page not found\n"13022026/10/27 08:50:07 INFO Signed narinfos id=1 count=213032026/10/27 08:50:07 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign13042026/10/27 08:50:07 INFO Signed narinfos id=2 count=213052026/10/27 08:50:07 INFO Uploading 4 narinfos13062026/10/27 08:50:07 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13072026/10/27 08:50:07 WARN Failed to register uploaded object key=absmzg61r7kzjhsm3fq9acsh6fwrg1c9.narinfo error="server returned 404: 404 page not found\n"13082026/10/27 08:50:07 WARN Failed to register uploaded object key=rkx3nwhra8wijccvikqhkhkgp6l8y6rz.narinfo error="server returned 404: 404 page not found\n"13092026/10/27 08:50:07 WARN Failed to register uploaded object key=yr0nvf9liaj5xnrysnpvzqrif4vqa8s7.narinfo error="server returned 404: 404 page not found\n"13102026/10/27 08:50:07 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggggg00000000000000000000.nar.zst upload_id=YTE1YjQ3ZTctZDJlNS00N2M0LTg3MTgtMDhhNGZlYmRjYzA1LjEwNDM4MDAwLWNjMTQtNDVmNS1iY2E1LTBkYmIwYjkxNzZkMHgxNzkzMDkwOTk2Mjc4Mjc2MDAw parts=1013112026/10/27 08:50:07 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13122026/10/27 08:50:07 WARN Failed to register uploaded object key=absmzg61r7kzjhsm3fq9acsh6fwrg1c9.narinfo error="server returned 404: 404 page not found\n"13132026/10/27 08:50:07 INFO Completed upload id=1 objects=6 duration=40.155959ms13142026/10/27 08:50:07 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete13152026-10-27 08:50:07.906 UTC [86113] ERROR: could not obtain lock on row in relation "closures"13162026-10-27 08:50:07.906 UTC [86113] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT13172026/10/27 08:50:07 INFO Completed upload id=2 objects=6 duration=1.1365ms13182026/10/27 08:50:07 INFO Upload complete. (515ms)13192026-10-27 08:50:07.914 UTC [86113] ERROR: could not obtain lock on row in relation "closures"13202026-10-27 08:50:07.914 UTC [86113] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT13212026-10-27 08:50:07.922 UTC [86113] ERROR: could not obtain lock on row in relation "closures"13222026-10-27 08:50:07.922 UTC [86113] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT1323--- PASS: TestService_healthCheckHandler (6.82s)1324=== CONT TestPresentNotReportedWhileGCDeletesClosure1325=== NAME TestClientFallsBackToClosures1326 client_pushes_test.go:112: Retrieved narinfo from S3:1327 StorePath: /private/var/tb/6/scratch/7ab19ce6cf566bc8/build/TestClientFallsBackToClosures1756656097/001/store/absmzg61r7kzjhsm3fq9acsh6fwrg1c9-shared-dep1328 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1329 Compression: zstd1330 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821331 NarSize: 1361332 References: 1333 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1334=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale1335=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale1336=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh1337=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh1338=== CONT TestPendingClosureWriteTimeout13392026-10-27 08:50:07.929 UTC [86113] ERROR: could not obtain lock on row in relation "closures"13402026-10-27 08:50:07.929 UTC [86113] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT1341=== RUN TestPendingClosureWriteTimeout/empty1342=== NAME TestClientFallsBackToClosures1343 client_pushes_test.go:112: Retrieved narinfo from S3:13442026-10-27 08:50:07.935 UTC [86113] ERROR: could not obtain lock on row in relation "closures"13452026-10-27 08:50:07.935 UTC [86113] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT1346 StorePath: /private/var/tb/6/scratch/7ab19ce6cf566bc8/build/TestClientFallsBackToClosures1756656097/001/store/yr0nvf9liaj5xnrysnpvzqrif4vqa8s7-a1347=== PAUSE TestPendingClosureWriteTimeout/empty1348=== RUN TestPendingClosureWriteTimeout/400_objects1349=== NAME TestClientFallsBackToClosures1350 URL: nar/0a0hcjgc7q08bx09xk0gdb6c3jcfsf5hpmlwd0a4l6d566jgnk21.nar.zst1351 Compression: zstd1352 NarHash: sha256:0a0hcjgc7q08bx09xk0gdb6c3jcfsf5hpmlwd0a4l6d566jgnk211353 NarSize: 2561354 References: /private/var/tb/6/scratch/7ab19ce6cf566bc8/build/TestClientFallsBackToClosures1756656097/001/store/absmzg61r7kzjhsm3fq9acsh6fwrg1c9-shared-dep1355=== PAUSE TestPendingClosureWriteTimeout/400_objects1356=== NAME TestClientFallsBackToClosures1357 CA: text:sha256:15c8bxh9fb2gv8j0q56v4iiaisvxyczqvvgq4383kkk7rjqvw8vn1358=== RUN TestPendingClosureWriteTimeout/670k_objects1359=== NAME TestClientFallsBackToClosures1360 client_pushes_test.go:112: Retrieved narinfo from S3:1361 StorePath: /private/var/tb/6/scratch/7ab19ce6cf566bc8/build/TestClientFallsBackToClosures1756656097/001/store/rkx3nwhra8wijccvikqhkhkgp6l8y6rz-b1362 URL: nar/0a0hcjgc7q08bx09xk0gdb6c3jcfsf5hpmlwd0a4l6d566jgnk21.nar.zst1363 Compression: zstd1364 NarHash: sha256:0a0hcjgc7q08bx09xk0gdb6c3jcfsf5hpmlwd0a4l6d566jgnk211365 NarSize: 2561366 References: /private/var/tb/6/scratch/7ab19ce6cf566bc8/build/TestClientFallsBackToClosures1756656097/001/store/absmzg61r7kzjhsm3fq9acsh6fwrg1c9-shared-dep1367 CA: text:sha256:15c8bxh9fb2gv8j0q56v4iiaisvxyczqvvgq4383kkk7rjqvw8vn1368=== PAUSE TestPendingClosureWriteTimeout/670k_objects1369=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1370=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1371=== CONT TestUploadHandlersRejectInvalidKeys1372=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1373=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1374=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1375=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1376=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1377=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1378=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1379=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1380=== CONT TestIsValidUploadKey1381=== RUN TestIsValidUploadKey/narinfo1382=== PAUSE TestIsValidUploadKey/narinfo1383=== RUN TestIsValidUploadKey/nar_zst1384=== PAUSE TestIsValidUploadKey/nar_zst1385=== RUN TestIsValidUploadKey/nar_xz1386=== PAUSE TestIsValidUploadKey/nar_xz1387=== RUN TestIsValidUploadKey/nar_plain1388=== PAUSE TestIsValidUploadKey/nar_plain1389=== RUN TestIsValidUploadKey/listing1390=== PAUSE TestIsValidUploadKey/listing1391=== RUN TestIsValidUploadKey/build_log1392=== PAUSE TestIsValidUploadKey/build_log1393=== RUN TestIsValidUploadKey/build_log_home-manager_file1394=== PAUSE TestIsValidUploadKey/build_log_home-manager_file1395=== RUN TestIsValidUploadKey/build_log_plus_in_name1396=== PAUSE TestIsValidUploadKey/build_log_plus_in_name1397=== RUN TestIsValidUploadKey/build_log_question_mark1398=== PAUSE TestIsValidUploadKey/build_log_question_mark1399=== RUN TestIsValidUploadKey/build_log_equals1400=== PAUSE TestIsValidUploadKey/build_log_equals1401=== RUN TestIsValidUploadKey/realisation1402=== PAUSE TestIsValidUploadKey/realisation1403=== RUN TestIsValidUploadKey/realisation_plus_in_output1404=== PAUSE TestIsValidUploadKey/realisation_plus_in_output1405=== RUN TestIsValidUploadKey/nix-cache-info1406=== PAUSE TestIsValidUploadKey/nix-cache-info1407=== RUN TestIsValidUploadKey/index.html1408=== PAUSE TestIsValidUploadKey/index.html1409=== RUN TestIsValidUploadKey/narinfo_key,_nar_type1410=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type1411=== RUN TestIsValidUploadKey/nar_key,_narinfo_type1412=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type1413=== RUN TestIsValidUploadKey/listing_key,_narinfo_type1414=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type1415=== RUN TestIsValidUploadKey/traversal1416=== PAUSE TestIsValidUploadKey/traversal1417=== RUN TestIsValidUploadKey/traversal_nar1418=== PAUSE TestIsValidUploadKey/traversal_nar1419=== RUN TestIsValidUploadKey/absolute1420=== PAUSE TestIsValidUploadKey/absolute1421=== RUN TestIsValidUploadKey/empty_key1422=== PAUSE TestIsValidUploadKey/empty_key1423=== RUN TestIsValidUploadKey/unknown_type1424=== PAUSE TestIsValidUploadKey/unknown_type1425=== CONT TestService_AuthMiddleware_OIDC1426--- PASS: TestPush_RootsAreLockedInByteOrder (17.54s)1427=== CONT TestProxyWriteTimeout1428=== RUN TestProxyWriteTimeout/narinfo1429=== PAUSE TestProxyWriteTimeout/narinfo1430=== RUN TestProxyWriteTimeout/1_GiB_nar1431=== PAUSE TestProxyWriteTimeout/1_GiB_nar1432=== RUN TestProxyWriteTimeout/10_GiB_nar1433=== PAUSE TestProxyWriteTimeout/10_GiB_nar1434=== RUN TestProxyWriteTimeout/unknown_size1435=== PAUSE TestProxyWriteTimeout/unknown_size1436=== CONT TestReadProxyNarinfoAlreadyDecompressed1437=== NAME TestPinProtectsFromGC1438 client_integration_test.go:854: Pinned store path: /private/var/tb/6/scratch/7ab19ce6cf566bc8/build/TestPinProtectsFromGC2059254608/001/store/65166ybli39ws7kbh140wa9fxp2p2rhv-pinned-file.txt1439 client_integration_test.go:855: Unpinned store path: /private/var/tb/6/scratch/7ab19ce6cf566bc8/build/TestPinProtectsFromGC2059254608/001/store/kmvq9hcf5zh8m9mp6gpz9nwiw5qdzp2s-unpinned-file.txt1440--- PASS: TestConnectWaitsForAPeerMigration (8.42s)1441=== CONT TestReadProxyDisabled14422026/10/27 08:50:08 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:65210/oidc1443--- PASS: TestClientFallsBackToClosures (8.30s)1444=== CONT TestService_ReadAuthMiddleware14452026/10/27 08:50:08 INFO Received push request method=POST path=/api/pushes14462026/10/27 08:50:08 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14472026/10/27 08:50:08 INFO Uploading 65166ybli39ws7kbh140wa9fxp2p2rhv-pinned-file.txt (128B)14482026/10/27 08:50:08 WARN Failed to register uploaded object key=65166ybli39ws7kbh140wa9fxp2p2rhv.ls error="server returned 404: 404 page not found\n"14492026/10/27 08:50:08 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"14502026/10/27 08:50:08 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14512026/10/27 08:50:08 INFO Signed narinfos id=1 count=114522026/10/27 08:50:08 INFO Uploading 1 narinfos14532026/10/27 08:50:08 INFO Received complete push request method=POST path=/api/pushes/1/complete14542026/10/27 08:50:08 WARN Failed to register uploaded object key=65166ybli39ws7kbh140wa9fxp2p2rhv.narinfo error="server returned 404: 404 page not found\n"14552026/10/27 08:50:08 INFO Completed push id=1 objects=3 duration=12.562459ms14562026/10/27 08:50:08 INFO Upload complete. (269ms)14572026/10/27 08:50:08 INFO Received push request method=POST path=/api/pushes14582026/10/27 08:50:08 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14592026/10/27 08:50:08 INFO Uploading kmvq9hcf5zh8m9mp6gpz9nwiw5qdzp2s-unpinned-file.txt (128B)14602026/10/27 08:50:08 WARN Failed to register uploaded object key=kmvq9hcf5zh8m9mp6gpz9nwiw5qdzp2s.ls error="server returned 404: 404 page not found\n"14612026/10/27 08:50:08 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"14622026/10/27 08:50:08 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign14632026/10/27 08:50:08 INFO Signed narinfos id=2 count=114642026/10/27 08:50:08 INFO Uploading 1 narinfos14652026/10/27 08:50:08 INFO Received complete push request method=POST path=/api/pushes/2/complete14662026/10/27 08:50:08 WARN Failed to register uploaded object key=kmvq9hcf5zh8m9mp6gpz9nwiw5qdzp2s.narinfo error="server returned 404: 404 page not found\n"14672026/10/27 08:50:08 INFO Completed push id=2 objects=3 duration=1.397125ms14682026/10/27 08:50:08 INFO Upload complete. (254ms)14692026/10/27 08:50:08 INFO Starting cleanup of old closures method=DELETE path=/api/closures14702026/10/27 08:50:08 INFO Garbage collection started14712026/10/27 08:50:08 INFO Aborted multipart uploads count=0 kept=014722026/10/27 08:50:08 WARN Force mode enabled - objects will be deleted immediately without grace period14732026/10/27 08:50:08 INFO Received push request method=POST path=/api/pushes14742026/10/27 08:50:08 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)14752026/10/27 08:50:08 INFO Uploading x5gr7sdlmn11avvdpjn70cv0k98n0lf8-top (264B)14762026/10/27 08:50:08 INFO Uploading kapi1fzbdmq017fw200spxvfy4qfh0wd-shared-dep (136B)14772026/10/27 08:50:08 WARN Failed to register uploaded object key=x5gr7sdlmn11avvdpjn70cv0k98n0lf8.ls error="server returned 404: 404 page not found\n"14782026/10/27 08:50:08 WARN Failed to register uploaded object key=kapi1fzbdmq017fw200spxvfy4qfh0wd.ls error="server returned 404: 404 page not found\n"14792026/10/27 08:50:08 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"14802026/10/27 08:50:08 WARN Failed to register uploaded object key=nar/1dbbzxv6xxmrs7ib7nzk47443fz1zzcrnzlh0pzz3y7kiqnidfr7.nar.zst error="server returned 404: 404 page not found\n"14812026/10/27 08:50:08 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14822026/10/27 08:50:08 INFO Signed narinfos id=1 count=214832026/10/27 08:50:08 INFO Uploading 2 narinfos14842026/10/27 08:50:09 INFO Received complete push request method=POST path=/api/pushes/1/complete14852026/10/27 08:50:09 WARN Failed to register uploaded object key=kapi1fzbdmq017fw200spxvfy4qfh0wd.narinfo error="server returned 404: 404 page not found\n"14862026/10/27 08:50:09 WARN Failed to register uploaded object key=x5gr7sdlmn11avvdpjn70cv0k98n0lf8.narinfo error="server returned 404: 404 page not found\n"14872026/10/27 08:50:09 INFO Completed push id=1 objects=6 duration=45.967916ms14882026/10/27 08:50:09 INFO Upload complete. (402ms)1489=== NAME TestClientSharedPathCommittedMidPush1490 client_integration_test.go:803: Retrieved narinfo from S3:1491 StorePath: /private/var/tb/6/scratch/7ab19ce6cf566bc8/build/TestClientSharedPathCommittedMidPush3846513763/001/store/kapi1fzbdmq017fw200spxvfy4qfh0wd-shared-dep1492 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1493 Compression: zstd1494 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821495 NarSize: 1361496 References: 1497 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1498 client_integration_test.go:803: Retrieved narinfo from S3:1499 StorePath: /private/var/tb/6/scratch/7ab19ce6cf566bc8/build/TestClientSharedPathCommittedMidPush3846513763/001/store/x5gr7sdlmn11avvdpjn70cv0k98n0lf8-top1500 URL: nar/1dbbzxv6xxmrs7ib7nzk47443fz1zzcrnzlh0pzz3y7kiqnidfr7.nar.zst1501 Compression: zstd1502 NarHash: sha256:1dbbzxv6xxmrs7ib7nzk47443fz1zzcrnzlh0pzz3y7kiqnidfr71503 NarSize: 2641504 References: /private/var/tb/6/scratch/7ab19ce6cf566bc8/build/TestClientSharedPathCommittedMidPush3846513763/001/store/kapi1fzbdmq017fw200spxvfy4qfh0wd-shared-dep1505 CA: text:sha256:0h9y3srr5aczrlzn4bdy2frrn1brgxhmz6ag9lihs0axmwiwgcyq15062026/10/27 08:50:09 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=01507--- PASS: TestClientSharedPathCommittedMidPush (7.57s)1508=== CONT TestReadProxyConditionalGet15092026/10/27 08:50:09 INFO Vacuumed table table=pending_closures15102026/10/27 08:50:09 INFO Received complete multipart upload request method=POST path=/api/multipart/complete15112026/10/27 08:50:09 INFO Vacuumed table table=pending_objects15122026/10/27 08:50:09 INFO Vacuumed table table=multipart_uploads15132026/10/27 08:50:09 INFO Vacuumed table table=closures15142026/10/27 08:50:09 INFO Completed multipart upload object_key=nar/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb00000000000000000000.nar.zst upload_id=YTE1YjQ3ZTctZDJlNS00N2M0LTg3MTgtMDhhNGZlYmRjYzA1LjZiYmJmMzRiLWFjYmYtNDQyYy04YWRhLWM1NDMwNTU4MzMxM3gxNzkzMDkxMDA1NjI5NjU3MDAw parts=1015152026/10/27 08:50:09 INFO Received complete push request method=POST path=/api/pushes/1/complete1516=== NAME TestOrphanedObjectsGCStressTest1517 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains15182026/10/27 08:50:09 INFO Vacuumed table table=objects15192026/10/27 08:50:09 INFO Completed push id=1 objects=4 duration=40.054875ms15202026/10/27 08:50:09 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete1521 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion15222026/10/27 08:50:09 INFO Completed upload id=2 objects=2 duration=1.5715ms15232026/10/27 08:50:09 INFO Received push request method=POST path=/api/pushes1524--- PASS: TestMetricsCommit (10.77s)1525=== CONT TestSweepSkipsRowsLockedByPush1526--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (10.12s)1527=== CONT TestReadProxyOutlastsServerWriteTimeout15282026/10/27 08:50:09 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)15292026/10/27 08:50:09 INFO Uploading 373my6c6p4v7sfn4mi1pp6awwlpjmjm3-shared-dep (136B)15302026/10/27 08:50:09 INFO Uploading 5hkmx1jbppqprxwncaczpvdwyphig11d-b (256B)15312026/10/27 08:50:09 WARN Failed to register uploaded object key=5hkmx1jbppqprxwncaczpvdwyphig11d.ls error="server returned 404: 404 page not found\n"1532=== NAME TestClientWithDependencies1533 client_integration_test.go:722: Built derivation: /private/var/tb/6/scratch/7ab19ce6cf566bc8/build/TestClientWithDependencies700175592/001/store/0pfk2gx8n92bc3y0cmp8pavda2d0bj3y-test-script15342026/10/27 08:50:09 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"15352026/10/27 08:50:09 WARN Failed to register uploaded object key=ncxchm615kz70rckkd0ifg7c7s68zma3.ls error="server returned 404: 404 page not found\n"1536=== NAME TestClientMultipleUploads1537 client_integration_test.go:467: Created store path 0: /private/var/tb/6/scratch/7ab19ce6cf566bc8/build/TestClientMultipleUploads3308417039/001/store/qdib22b4mg20qiygcjbbfdd5f217x7g6-test-file-0.txt15382026/10/27 08:50:09 WARN Failed to register uploaded object key=373my6c6p4v7sfn4mi1pp6awwlpjmjm3.ls error="server returned 404: 404 page not found\n"15392026/10/27 08:50:09 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15402026/10/27 08:50:09 WARN Failed to register uploaded object key=nar/03hcpnj3zfippw71kzr9xm2z3z1qilwvrh4a4c1gz3li3nsr9rlh.nar.zst error="server returned 404: 404 page not found\n"15412026/10/27 08:50:09 INFO Signed narinfos id=1 count=315422026/10/27 08:50:09 INFO Uploading 3 narinfos1543=== NAME TestClientWithDependencies1544 client_integration_test.go:724: Found 1 dependencies (including self)15452026/10/27 08:50:09 WARN Failed to register uploaded object key=373my6c6p4v7sfn4mi1pp6awwlpjmjm3.narinfo error="server returned 404: 404 page not found\n"15462026/10/27 08:50:09 WARN Failed to register uploaded object key=ncxchm615kz70rckkd0ifg7c7s68zma3.narinfo error="server returned 404: 404 page not found\n"15472026/10/27 08:50:09 WARN Failed to register uploaded object key=5hkmx1jbppqprxwncaczpvdwyphig11d.narinfo error="server returned 404: 404 page not found\n"15482026/10/27 08:50:09 INFO Received complete push request method=POST path=/api/pushes/1/complete15492026/10/27 08:50:09 INFO Completed push id=1 objects=8 duration=52.148792ms15502026/10/27 08:50:09 INFO Upload complete. (501ms)1551=== NAME TestClientPushesUseOnePush1552 client_pushes_test.go:97: Retrieved narinfo from S3:1553 StorePath: /private/var/tb/6/scratch/7ab19ce6cf566bc8/build/TestClientPushesUseOnePush2882181164/001/store/373my6c6p4v7sfn4mi1pp6awwlpjmjm3-shared-dep1554 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1555=== NAME TestClientMultipleUploads1556 client_integration_test.go:467: Created store path 1: /private/var/tb/6/scratch/7ab19ce6cf566bc8/build/TestClientMultipleUploads3308417039/001/store/k6w9iv2z5nnznzk8131mbsz66fv847ng-test-file-1.txt1557=== NAME TestClientPushesUseOnePush1558 Compression: zstd1559 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821560 NarSize: 1361561 References: 1562 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1563 client_pushes_test.go:97: Retrieved narinfo from S3:1564 StorePath: /private/var/tb/6/scratch/7ab19ce6cf566bc8/build/TestClientPushesUseOnePush2882181164/001/store/ncxchm615kz70rckkd0ifg7c7s68zma3-a1565 URL: nar/03hcpnj3zfippw71kzr9xm2z3z1qilwvrh4a4c1gz3li3nsr9rlh.nar.zst1566 Compression: zstd1567 NarHash: sha256:03hcpnj3zfippw71kzr9xm2z3z1qilwvrh4a4c1gz3li3nsr9rlh1568 NarSize: 2561569 References: /private/var/tb/6/scratch/7ab19ce6cf566bc8/build/TestClientPushesUseOnePush2882181164/001/store/373my6c6p4v7sfn4mi1pp6awwlpjmjm3-shared-dep1570 CA: text:sha256:1b1l20grjnl58j4jhl82p4iil75szsbnh40ahvdzj1q97i7mwgl31571 client_pushes_test.go:97: Retrieved narinfo from S3:1572 StorePath: /private/var/tb/6/scratch/7ab19ce6cf566bc8/build/TestClientPushesUseOnePush2882181164/001/store/5hkmx1jbppqprxwncaczpvdwyphig11d-b1573 URL: nar/03hcpnj3zfippw71kzr9xm2z3z1qilwvrh4a4c1gz3li3nsr9rlh.nar.zst1574 Compression: zstd1575 NarHash: sha256:03hcpnj3zfippw71kzr9xm2z3z1qilwvrh4a4c1gz3li3nsr9rlh1576 NarSize: 2561577 References: /private/var/tb/6/scratch/7ab19ce6cf566bc8/build/TestClientPushesUseOnePush2882181164/001/store/373my6c6p4v7sfn4mi1pp6awwlpjmjm3-shared-dep1578 CA: text:sha256:1b1l20grjnl58j4jhl82p4iil75szsbnh40ahvdzj1q97i7mwgl315792026/10/27 08:50:10 INFO Received push request method=POST path=/api/pushes15802026/10/27 08:50:10 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15812026/10/27 08:50:10 INFO Uploading 0pfk2gx8n92bc3y0cmp8pavda2d0bj3y-test-script (136B)15822026/10/27 08:50:10 WARN Failed to register uploaded object key=0pfk2gx8n92bc3y0cmp8pavda2d0bj3y.ls error="server returned 404: 404 page not found\n"15832026/10/27 08:50:10 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"1584=== NAME TestClientMultipleUploads15852026/10/27 08:50:10 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"1586 client_integration_test.go:467: Created store path 2: /private/var/tb/6/scratch/7ab19ce6cf566bc8/build/TestClientMultipleUploads3308417039/001/store/mn1bylwqygdp4c4p4zr1z9yy4pbrhkjh-test-file-2.txt15872026/10/27 08:50:10 WARN Failed to register uploaded object key=log/a5qr9q67am7p4d5dw521c4mixj0di0x6-test-script.drv error="server returned 404: 404 page not found\n"1588--- PASS: TestClientPushesUseOnePush (8.21s)15892026/10/27 08:50:10 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign1590=== CONT TestRedundantMultipartUpload15912026/10/27 08:50:10 INFO Signed narinfos id=1 count=115922026/10/27 08:50:10 INFO Uploading 1 narinfos1593=== NAME TestClientIntegration1594 client_integration_test.go:331: Created store path: /private/var/tb/6/scratch/7ab19ce6cf566bc8/build/TestClientIntegration817432971/002/store/7sqshhnzvbhsv50rfal59xawg7985naa-test-file.txt15952026/10/27 08:50:10 INFO Received complete push request method=POST path=/api/pushes/1/complete15962026/10/27 08:50:10 WARN Failed to register uploaded object key=0pfk2gx8n92bc3y0cmp8pavda2d0bj3y.narinfo error="server returned 404: 404 page not found\n"15972026/10/27 08:50:10 INFO Received push request method=POST path=/api/pushes15982026/10/27 08:50:10 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)15992026/10/27 08:50:10 INFO Uploading qdib22b4mg20qiygcjbbfdd5f217x7g6-test-file-0.txt (160B)16002026/10/27 08:50:10 INFO Uploading mn1bylwqygdp4c4p4zr1z9yy4pbrhkjh-test-file-2.txt (160B)16012026/10/27 08:50:10 INFO Completed push id=1 objects=4 duration=54.063375ms16022026/10/27 08:50:10 INFO Uploading k6w9iv2z5nnznzk8131mbsz66fv847ng-test-file-1.txt (160B)16032026/10/27 08:50:10 INFO Upload complete. (393ms)1604--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (15.10s)1605=== CONT TestService_RequireScope_OIDC16062026/10/27 08:50:10 INFO Aborted multipart uploads count=0 kept=016072026/10/27 08:50:10 WARN Force mode enabled - objects will be deleted immediately without grace period16082026/10/27 08:50:10 WARN Failed to register uploaded object key=mn1bylwqygdp4c4p4zr1z9yy4pbrhkjh.ls error="server returned 404: 404 page not found\n"16092026/10/27 08:50:10 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=016102026/10/27 08:50:10 WARN Failed to register uploaded object key=k6w9iv2z5nnznzk8131mbsz66fv847ng.ls error="server returned 404: 404 page not found\n"16112026/10/27 08:50:10 INFO Received push request method=POST path=/api/pushes16122026/10/27 08:50:10 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"16132026/10/27 08:50:10 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16142026/10/27 08:50:10 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"16152026/10/27 08:50:10 WARN Failed to register uploaded object key=qdib22b4mg20qiygcjbbfdd5f217x7g6.ls error="server returned 404: 404 page not found\n"16162026/10/27 08:50:10 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"16172026/10/27 08:50:10 INFO Signed narinfos id=1 count=316182026/10/27 08:50:10 INFO Uploading 3 narinfos16192026/10/27 08:50:10 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:65303/oidc16202026/10/27 08:50:10 INFO Vacuumed table table=pending_closures16212026/10/27 08:50:10 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16222026/10/27 08:50:10 INFO Uploading 7sqshhnzvbhsv50rfal59xawg7985naa-test-file.txt (152B)16232026/10/27 08:50:10 WARN Failed to register uploaded object key=k6w9iv2z5nnznzk8131mbsz66fv847ng.narinfo error="server returned 404: 404 page not found\n"16242026/10/27 08:50:10 WARN Failed to register uploaded object key=mn1bylwqygdp4c4p4zr1z9yy4pbrhkjh.narinfo error="server returned 404: 404 page not found\n"16252026/10/27 08:50:10 INFO Received complete push request method=POST path=/api/pushes/1/complete16262026/10/27 08:50:10 WARN Failed to register uploaded object key=qdib22b4mg20qiygcjbbfdd5f217x7g6.narinfo error="server returned 404: 404 page not found\n"16272026/10/27 08:50:10 INFO Vacuumed table table=pending_objects16282026/10/27 08:50:10 WARN Failed to register uploaded object key=7sqshhnzvbhsv50rfal59xawg7985naa.ls error="server returned 404: 404 page not found\n"16292026/10/27 08:50:10 INFO Vacuumed table table=multipart_uploads16302026/10/27 08:50:10 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"16312026/10/27 08:50:10 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16322026/10/27 08:50:10 INFO Completed push id=1 objects=9 duration=21.371042ms16332026/10/27 08:50:10 INFO Signed narinfos id=1 count=116342026/10/27 08:50:10 INFO Uploading 1 narinfos16352026/10/27 08:50:10 INFO Upload complete. (344ms)16362026/10/27 08:50:10 INFO Vacuumed table table=closures1637=== NAME TestClientMultipleUploads1638 client_integration_test.go:478: Uploaded 3 paths in 387.878917ms16392026/10/27 08:50:10 INFO Vacuumed table table=objects1640=== NAME TestClientWithDependencies1641 client_integration_test.go:740: Skipping nix copy test - isolated store (/private/var/tb/6/scratch/7ab19ce6cf566bc8/build/TestClientWithDependencies700175592/001/store) requires matching store prefix16422026/10/27 08:50:10 INFO Received complete push request method=POST path=/api/pushes/1/complete16432026/10/27 08:50:10 WARN Failed to register uploaded object key=7sqshhnzvbhsv50rfal59xawg7985naa.narinfo error="server returned 404: 404 page not found\n"16442026/10/27 08:50:10 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=016452026/10/27 08:50:10 INFO Completed push id=1 objects=3 duration=113.05375ms16462026/10/27 08:50:10 INFO Upload complete. (428ms)16472026/10/27 08:50:10 INFO Received create pin request method=POST path=/api/pins/myapp1648--- PASS: TestClientMultipleUploads (8.09s)1649=== CONT TestParseSize1650--- PASS: TestParseSize (0.00s)1651=== CONT TestReadProxyHead1652--- PASS: TestClientWithDependencies (8.52s)1653=== CONT TestService_Rustfstest16542026/10/27 08:50:10 INFO All 1 paths already cached1655=== NAME TestClientIntegration1656 client_integration_test.go:357: Retrieved narinfo from S3:1657 StorePath: /private/var/tb/6/scratch/7ab19ce6cf566bc8/build/TestClientIntegration817432971/002/store/7sqshhnzvbhsv50rfal59xawg7985naa-test-file.txt1658 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1659 Compression: zstd1660 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11661 NarSize: 1521662 References: 1663 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk116642026/10/27 08:50:10 INFO Created/updated pin name=myapp store_path=/private/var/tb/6/scratch/7ab19ce6cf566bc8/build/TestPinProtectsFromGC2059254608/001/store/65166ybli39ws7kbh140wa9fxp2p2rhv-pinned-file.txt narinfo_key=65166ybli39ws7kbh140wa9fxp2p2rhv.narinfo1665 client_integration_test.go:358: Retrieved .ls file from S3 (compressed size: 77 bytes)1666 client_integration_test.go:358: Decompressed .ls content (64 bytes):16672026/10/27 08:50:10 INFO Starting cleanup of old closures method=DELETE path=/api/closures1668 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}16692026/10/27 08:50:10 INFO Garbage collection started16702026/10/27 08:50:10 INFO Aborted multipart uploads count=0 kept=016712026/10/27 08:50:10 WARN Force mode enabled - objects will be deleted immediately without grace period16722026/10/27 08:50:10 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=01673--- PASS: TestCacheStatsHandler (7.70s)1674=== CONT TestReadProxy404And42916752026/10/27 08:50:10 INFO Vacuumed table table=pending_closures16762026/10/27 08:50:10 INFO Vacuumed table table=pending_objects16772026/10/27 08:50:10 INFO Vacuumed table table=multipart_uploads16782026/10/27 08:50:10 INFO Vacuumed table table=closures16792026/10/27 08:50:10 INFO Vacuumed table table=objects16802026/10/27 08:50:11 INFO Received push request method=POST path=/api/pushes16812026/10/27 08:50:11 INFO Object in database but missing from S3 key=7sqshhnzvbhsv50rfal59xawg7985naa.ls16822026/10/27 08:50:11 WARN Found objects in DB but missing from S3, will re-upload count=116832026/10/27 08:50:11 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)16842026/10/27 08:50:11 INFO Aborted multipart uploads count=0 kept=016852026/10/27 08:50:11 WARN Force mode enabled - objects will be deleted immediately without grace period16862026/10/27 08:50:11 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=016872026/10/27 08:50:11 INFO Received complete push request method=POST path=/api/pushes/2/complete16882026/10/27 08:50:11 WARN Failed to register uploaded object key=7sqshhnzvbhsv50rfal59xawg7985naa.ls error="server returned 404: 404 page not found\n"16892026/10/27 08:50:11 INFO Completed push id=2 objects=3 duration=866.875µs16902026/10/27 08:50:11 INFO Upload complete. (148ms)16912026/10/27 08:50:11 INFO Vacuumed table table=pending_closures1692=== NAME TestClientIntegration1693 client_integration_test.go:375: Retrieved .ls file from S3 (compressed size: 62 bytes)1694 client_integration_test.go:375: Decompressed .ls content (49 bytes):1695 {"version":1,"root":{"type":"regular","size":39}}16962026/10/27 08:50:11 INFO Vacuumed table table=pending_objects16972026/10/27 08:50:11 INFO Vacuumed table table=multipart_uploads16982026/10/27 08:50:11 INFO Vacuumed table table=closures16992026/10/27 08:50:11 INFO Vacuumed table table=objects1700--- PASS: TestCommitRacingPendingCleanupKeepsObjects (7.60s)1701=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1702--- PASS: TestGetExistingObjectsLocksRows (6.96s)1703=== CONT TestReadProxyContentNegotiation17042026/10/27 08:50:11 INFO Received push request method=POST path=/api/pushes17052026/10/27 08:50:11 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)17062026/10/27 08:50:11 INFO Received uploads request method=POST path=/api/pending_closures17072026/10/27 08:50:11 WARN Failed to register uploaded object key=7sqshhnzvbhsv50rfal59xawg7985naa.ls error="server returned 404: 404 page not found\n"17082026/10/27 08:50:11 INFO Received complete push request method=POST path=/api/pushes/3/complete17092026/10/27 08:50:11 INFO Completed push id=3 objects=3 duration=1.646625ms17102026/10/27 08:50:11 INFO Upload complete. (142ms)1711=== NAME TestClientIntegration1712 client_integration_test.go:392: Retrieved .ls file from S3 (compressed size: 62 bytes)1713 client_integration_test.go:392: Decompressed .ls content (49 bytes):1714 {"version":1,"root":{"type":"regular","size":39}}17152026/10/27 08:50:12 INFO Received push request method=POST path=/api/pushes17162026/10/27 08:50:12 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17172026/10/27 08:50:12 INFO Uploading 61jlyv5scd3crswwmcr21in2gg3x2kj7-lost-commit.txt (152B)1718--- PASS: TestService_ReadScope_PublicByDefault (7.45s)1719=== CONT TestPresignedUploadRegisteredBeforeCommit17202026/10/27 08:50:12 WARN Failed to register uploaded object key=61jlyv5scd3crswwmcr21in2gg3x2kj7.ls error="server returned 404: 404 page not found\n"17212026/10/27 08:50:12 INFO Received sign narinfos request method=POST path=/api/pushes/4/sign17222026/10/27 08:50:12 WARN Failed to register uploaded object key=nar/04d5klw9iix884nk82y7nlkps8afh2bg119y7zkvcf1pc1x2y2jl.nar.zst error="server returned 404: 404 page not found\n"17232026/10/27 08:50:12 INFO Signed narinfos id=4 count=117242026/10/27 08:50:12 INFO Uploading 1 narinfos17252026/10/27 08:50:12 INFO Received complete push request method=POST path=/api/pushes/4/complete17262026/10/27 08:50:12 WARN Failed to register uploaded object key=61jlyv5scd3crswwmcr21in2gg3x2kj7.narinfo error="server returned 404: 404 page not found\n"17272026/10/27 08:50:12 INFO Completed push id=4 objects=3 duration=740.958µs17282026/10/27 08:50:12 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:65272/api/pushes/4/complete\": EOF" url=http://127.0.0.1:65272/api/pushes/4/complete17292026/10/27 08:50:12 INFO Received complete push request method=POST path=/api/pushes/4/complete17302026-10-27 08:50:12.272 UTC [86227] ERROR: Push does not exist: id=417312026-10-27 08:50:12.272 UTC [86227] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE17322026-10-27 08:50:12.272 UTC [86227] STATEMENT: -- name: CommitPush :one1733 SELECT commit_push($1::bigint)::bigint1734 17352026/10/27 08:50:12 WARN Push not found id=417362026/10/27 08:50:12 INFO Upload complete. (292ms)1737=== NAME TestClientIntegration1738 client_integration_test.go:422: Retrieved narinfo from S3:1739 StorePath: /private/var/tb/6/scratch/7ab19ce6cf566bc8/build/TestClientIntegration817432971/002/store/61jlyv5scd3crswwmcr21in2gg3x2kj7-lost-commit.txt1740 URL: nar/04d5klw9iix884nk82y7nlkps8afh2bg119y7zkvcf1pc1x2y2jl.nar.zst1741 Compression: zstd1742 NarHash: sha256:04d5klw9iix884nk82y7nlkps8afh2bg119y7zkvcf1pc1x2y2jl1743 NarSize: 1521744 References: 1745 CA: fixed:r:sha256:04d5klw9iix884nk82y7nlkps8afh2bg119y7zkvcf1pc1x2y2jl1746 client_integration_test.go:425: Testing garbage collection...1747--- PASS: TestPushWaitsForSweepHoldingRow (7.82s)1748=== CONT TestCompletedNarNotReofferedAcrossClosures17492026/10/27 08:50:12 INFO Starting cleanup of old closures method=DELETE path=/api/closures17502026/10/27 08:50:12 INFO Garbage collection started17512026/10/27 08:50:12 INFO Aborted multipart uploads count=0 kept=017522026/10/27 08:50:12 WARN Force mode enabled - objects will be deleted immediately without grace period1753--- PASS: TestDeleteClosuresRacingPins (13.12s)1754=== CONT TestReadProxyNarStreaming1755--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (5.63s)1756=== CONT TestPush_SignsNarinfosOfItsPendingObjects1757=== NAME TestPinProtectsFromGC1758 client_integration_test.go:963: Pin successfully protected closure from garbage collection1759--- PASS: TestPinProtectsFromGC (12.14s)1760=== CONT TestPush_RejectsBadRequests1761=== NAME TestClientCADerivations17622026/10/27 08:50:13 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=01763 client_ca_test.go:136: Built CA derivation: /private/var/tb/6/scratch/7ab19ce6cf566bc8/build/TestClientCADerivations1972799770/001/store/j1f2d5p1vn6vakqsr1gdiazgf8c1vaxc-ca-test17642026/10/27 08:50:13 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"17652026/10/27 08:50:13 WARN mTLS auth: bound subjects configured but subject DN unavailable17662026/10/27 08:50:13 INFO Vacuumed table table=pending_closures17672026/10/27 08:50:13 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"17682026/10/27 08:50:13 INFO Vacuumed table table=pending_objects1769 client_ca_test.go:139: Found 1 dependencies (including self)17702026/10/27 08:50:13 INFO Vacuumed table table=multipart_uploads1771--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (6.15s)1772=== CONT TestCompleteMultipartUpload_ErrorButObjectExists17732026/10/27 08:50:13 INFO Vacuumed table table=closures17742026/10/27 08:50:13 INFO Vacuumed table table=objects17752026/10/27 08:50:13 INFO Received push request method=POST path=/api/pushes17762026/10/27 08:50:13 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17772026/10/27 08:50:13 INFO Uploading j1f2d5p1vn6vakqsr1gdiazgf8c1vaxc-ca-test (144B)17782026/10/27 08:50:13 WARN Failed to register uploaded object key=j1f2d5p1vn6vakqsr1gdiazgf8c1vaxc.ls error="server returned 404: 404 page not found\n"17792026/10/27 08:50:13 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"17802026/10/27 08:50:13 WARN Failed to register uploaded object key=log/fz6mw0s40d9gwp5qbhjjn35fwwqmdd98-ca-test.drv error="server returned 404: 404 page not found\n"17812026/10/27 08:50:13 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17822026/10/27 08:50:13 INFO Signed narinfos id=1 count=117832026/10/27 08:50:13 INFO Uploading 1 narinfos1784--- PASS: TestReadProxyRangeRequest (6.36s)1785=== CONT TestPush_CompleteWaitsForCleanupOfThePush17862026/10/27 08:50:13 INFO Received complete push request method=POST path=/api/pushes/1/complete17872026/10/27 08:50:13 WARN Failed to register uploaded object key=j1f2d5p1vn6vakqsr1gdiazgf8c1vaxc.narinfo error="server returned 404: 404 page not found\n"17882026/10/27 08:50:13 INFO Completed push id=1 objects=4 duration=47.448292ms17892026/10/27 08:50:13 INFO Upload complete. (421ms)1790=== NAME TestClientCADerivations1791 client_ca_test.go:180: Narinfo contains CA field: StorePath: /private/var/tb/6/scratch/7ab19ce6cf566bc8/build/TestClientCADerivations1972799770/001/store/j1f2d5p1vn6vakqsr1gdiazgf8c1vaxc-ca-test1792 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1793 Compression: zstd1794 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1795 NarSize: 1441796 References: 1797 Deriver: /private/var/tb/6/scratch/7ab19ce6cf566bc8/build/TestClientCADerivations1972799770/001/store/fz6mw0s40d9gwp5qbhjjn35fwwqmdd98-ca-test.drv1798 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1799 client_ca_test.go:185: Checking for realisation files in S3...1800 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1801 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache1802--- PASS: TestReadProxyDisabled (6.00s)1803=== CONT TestIsValidCachePath1804=== RUN TestIsValidCachePath/narinfo1805=== PAUSE TestIsValidCachePath/narinfo1806=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1807=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1808=== RUN TestIsValidCachePath/nar_zst1809=== PAUSE TestIsValidCachePath/nar_zst1810=== RUN TestIsValidCachePath/nar_xz1811=== PAUSE TestIsValidCachePath/nar_xz1812=== RUN TestIsValidCachePath/nar_bz21813=== PAUSE TestIsValidCachePath/nar_bz21814=== RUN TestIsValidCachePath/nar_uncompressed1815=== PAUSE TestIsValidCachePath/nar_uncompressed1816=== RUN TestIsValidCachePath/ls1817=== PAUSE TestIsValidCachePath/ls1818=== RUN TestIsValidCachePath/log1819=== PAUSE TestIsValidCachePath/log1820=== RUN TestIsValidCachePath/realisation1821=== PAUSE TestIsValidCachePath/realisation1822=== RUN TestIsValidCachePath/nix-cache-info1823=== PAUSE TestIsValidCachePath/nix-cache-info1824=== RUN TestIsValidCachePath/index.html1825=== PAUSE TestIsValidCachePath/index.html1826=== RUN TestIsValidCachePath/traversal_parent1827=== PAUSE TestIsValidCachePath/traversal_parent1828=== RUN TestIsValidCachePath/traversal_in_middle1829=== PAUSE TestIsValidCachePath/traversal_in_middle1830=== RUN TestIsValidCachePath/invalid_char_e1831=== PAUSE TestIsValidCachePath/invalid_char_e1832=== RUN TestIsValidCachePath/invalid_char_u1833=== PAUSE TestIsValidCachePath/invalid_char_u1834=== RUN TestIsValidCachePath/random_path1835=== PAUSE TestIsValidCachePath/random_path1836=== RUN TestIsValidCachePath/empty1837=== PAUSE TestIsValidCachePath/empty1838=== RUN TestIsValidCachePath/leading_slash1839=== PAUSE TestIsValidCachePath/leading_slash1840=== RUN TestIsValidCachePath/wrong_extension1841=== PAUSE TestIsValidCachePath/wrong_extension1842=== RUN TestIsValidCachePath/short_hash1843=== PAUSE TestIsValidCachePath/short_hash1844=== CONT TestReadProxyInvalidPath1845=== NAME TestClientCADerivations1846 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket66?endpoint=http://localhost:64877®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/private/var/tb/6/scratch/7ab19ce6cf566bc8/build/TestClientCADerivations1972799770/001/store'1847 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 11848--- PASS: TestClientCADerivations (7.53s)1849=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit18502026/10/27 08:50:14 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=2 objects_marked=6 objects_deleted=6 objects_failed=01851=== NAME TestClientIntegration1852 client_integration_test.go:432: Objects in database after GC:1853 client_integration_test.go:432: Successfully deleted all objects with GC --force1854--- PASS: TestReadProxyNarinfoAlreadyDecompressed (6.40s)1855=== CONT TestReadProxyNarinfo1856--- PASS: TestClientIntegration (11.91s)1857=== CONT TestParseSingleRange1858=== RUN TestParseSingleRange/none1859=== PAUSE TestParseSingleRange/none1860=== RUN TestParseSingleRange/unknown_unit1861=== PAUSE TestParseSingleRange/unknown_unit1862=== RUN TestParseSingleRange/multi-range_ignored1863=== PAUSE TestParseSingleRange/multi-range_ignored1864=== RUN TestParseSingleRange/malformed_no_dash1865=== PAUSE TestParseSingleRange/malformed_no_dash1866=== RUN TestParseSingleRange/malformed_both_empty1867=== PAUSE TestParseSingleRange/malformed_both_empty1868=== RUN TestParseSingleRange/malformed_end_before_start1869=== PAUSE TestParseSingleRange/malformed_end_before_start1870=== RUN TestParseSingleRange/closed1871=== PAUSE TestParseSingleRange/closed1872=== RUN TestParseSingleRange/open-ended1873=== PAUSE TestParseSingleRange/open-ended1874=== RUN TestParseSingleRange/end_clamped_to_size1875=== PAUSE TestParseSingleRange/end_clamped_to_size1876=== RUN TestParseSingleRange/suffix1877=== PAUSE TestParseSingleRange/suffix1878=== RUN TestParseSingleRange/suffix_exceeds_size1879=== PAUSE TestParseSingleRange/suffix_exceeds_size1880=== RUN TestParseSingleRange/single_byte1881=== PAUSE TestParseSingleRange/single_byte1882=== RUN TestParseSingleRange/start_past_EOF1883=== PAUSE TestParseSingleRange/start_past_EOF1884=== RUN TestParseSingleRange/start_far_past_EOF1885=== PAUSE TestParseSingleRange/start_far_past_EOF1886=== CONT TestDeletePinKeepsRowWhenS3Fails1887=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1888=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1889=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1890=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1891=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1892=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1893=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1894=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1895=== CONT TestPresentReportsOnlyClosureRoots1896--- PASS: TestService_ReadAuthMiddleware (7.09s)1897=== CONT TestPresentRefreshesOnlyStaleClosures1898--- PASS: TestReadProxyConditionalGet (6.35s)1899=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows19002026/10/27 08:50:16 INFO Aborted multipart uploads count=0 kept=019012026/10/27 08:50:16 WARN Force mode enabled - objects will be deleted immediately without grace period19022026/10/27 08:50:16 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=019032026/10/27 08:50:16 INFO Vacuumed table table=pending_closures19042026/10/27 08:50:16 INFO Vacuumed table table=pending_objects19052026/10/27 08:50:16 INFO Vacuumed table table=multipart_uploads19062026/10/27 08:50:16 INFO Vacuumed table table=closures19072026/10/27 08:50:16 INFO Vacuumed table table=objects19082026/10/27 08:50:16 INFO Aborted multipart uploads count=0 kept=019092026/10/27 08:50:16 WARN Force mode enabled - objects will be deleted immediately without grace period19102026/10/27 08:50:16 INFO Received uploads request method=POST path=/api/pending_closures19112026/10/27 08:50:16 INFO Received uploads request method=POST path=/api/pending_closures19122026/10/27 08:50:16 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=019132026/10/27 08:50:16 INFO Vacuumed table table=pending_closures19142026/10/27 08:50:16 INFO Vacuumed table table=pending_objects19152026/10/27 08:50:16 INFO Vacuumed table table=multipart_uploads19162026/10/27 08:50:16 INFO Vacuumed table table=closures19172026/10/27 08:50:16 INFO Vacuumed table table=objects1918--- PASS: TestSweepSkipsRowsLockedByPush (7.22s)1919=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check1920=== RUN TestService_RequireScope_OIDC/builder_may_write1921=== PAUSE TestService_RequireScope_OIDC/builder_may_write1922=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1923=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1924=== RUN TestService_RequireScope_OIDC/ops_may_admin1925=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1926=== RUN TestService_RequireScope_OIDC/ops_may_not_write1927=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1928=== RUN TestService_RequireScope_OIDC/reader_may_not_write1929=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1930=== RUN TestService_RequireScope_OIDC/static_token_may_admin1931=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1932=== RUN TestService_RequireScope_OIDC/static_token_may_write1933=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1934=== RUN TestService_RequireScope_OIDC/reader_may_read1935=== PAUSE TestService_RequireScope_OIDC/reader_may_read1936=== RUN TestService_RequireScope_OIDC/writer_implies_read1937=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1938=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1939=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1940=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1941=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc1942=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1943=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1944=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1945=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1946=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1947=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1948=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure19492026/10/27 08:50:16 INFO Received uploads request method=POST path=/1950--- PASS: TestReadProxyHead (6.94s)1951=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts19522026/10/27 08:50:17 INFO Received request for more parts method=POST path=/1953--- PASS: TestService_Rustfstest (7.14s)1954=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart19552026/10/27 08:50:17 INFO Received complete multipart upload request method=POST path=/1956=== CONT TestPendingClosureFailureTracksEveryUpload/refuse_aborts=true19572026/10/27 08:50:18 WARN Rate limiter enabled after throttle name=s3-test rate=519582026/10/27 08:50:18 WARN S3 rate limit hit during proxy key=4hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo error="Please reduce your request rate."19592026/10/27 08:50:18 WARN Rate limiter backed off name=s3-test rate=519602026/10/27 08:50:18 WARN S3 rate limit hit during proxy key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhh.nar.zst error="Please reduce your request rate."1961--- PASS: TestReadProxy404And429 (7.21s)1962=== CONT TestPendingClosureFailureTracksEveryUpload/refuse_aborts=false19632026/10/27 08:50:18 INFO Received uploads request method=POST path=/api/pending_closures1964=== CONT TestServerTLSConfig/no_client_CA1965=== CONT TestServerTLSConfig/not_a_PEM_file1966=== CONT TestServerTLSConfig/missing_CA_file1967=== CONT TestResolveDBConnectionString/flag_wins1968=== CONT TestResolveDBConnectionString/file_when_flag_empty1969--- PASS: TestServerTLSConfig (0.04s)1970 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1971 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.03s)1972 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1973=== CONT TestResolveDBConnectionString/missing_file_is_an_error1974=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1975=== CONT TestResolveDBConnectionString/nothing_configured1976=== CONT TestClientErrorHandling/InvalidStorePath1977--- PASS: TestResolveDBConnectionString (0.07s)1978 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1979 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)1980 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1981 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1982 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)19832026/10/27 08:50:18 INFO Received complete multipart upload request method=POST path=/api/multipart/complete19842026/10/27 08:50:18 INFO Received complete multipart upload request method=POST path=/api/multipart/complete19852026/10/27 08:50:18 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=YTE1YjQ3ZTctZDJlNS00N2M0LTg3MTgtMDhhNGZlYmRjYzA1LjIxY2E3OTU3LTU0NTUtNGEzNS1iMjNhLTcwN2U4Njk3OThmYXgxNzkzMDkxMDE2NjI2ODUxMDAw parts=1219862026/10/27 08:50:18 INFO Received uploads request method=POST path=/api/pending_closures19872026/10/27 08:50:18 INFO Received uploads request method=POST path=/api/pending_closures1988--- PASS: TestReadProxyContentNegotiation (7.18s)1989=== CONT TestClientErrorHandling/ServerNotAvailable19902026/10/27 08:50:18 INFO Received uploads request method=POST path=/api/pending_closures19912026/10/27 08:50:18 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst19922026/10/27 08:50:18 INFO Received uploads request method=POST path=/api/pending_closures1993--- PASS: TestPresignedUploadRegisteredBeforeCommit (6.81s)1994=== CONT TestClientErrorHandling/InvalidAuthToken19952026/10/27 08:50:18 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/present19962026/10/27 08:50:19 INFO Received uploads request method=POST path=/api/pending_closures19972026/10/27 08:50:19 WARN Request failed, retrying attempt=2 backoff=196.561999ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present19982026/10/27 08:50:19 WARN Request failed, retrying attempt=3 backoff=438.091932ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present1999--- PASS: TestReadProxyNarStreaming (6.74s)2000=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete20012026/10/27 08:50:19 INFO Received push request method=POST path=/api/pushes20022026/10/27 08:50:19 WARN Request failed, retrying attempt=4 backoff=860.398465ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20032026/10/27 08:50:19 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign20042026/10/27 08:50:19 INFO Signed narinfos id=1 count=120052026/10/27 08:50:19 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign20062026/10/27 08:50:19 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign20072026/10/27 08:50:19 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"20082026/10/27 08:50:19 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign20092026/10/27 08:50:19 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"20102026/10/27 08:50:19 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign20112026/10/27 08:50:19 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=120122026/10/27 08:50:19 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign20132026/10/27 08:50:19 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo2014--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (6.99s)2015=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark2016=== RUN TestPush_RejectsBadRequests/no_roots2017=== PAUSE TestPush_RejectsBadRequests/no_roots2018=== RUN TestPush_RejectsBadRequests/no_objects2019=== PAUSE TestPush_RejectsBadRequests/no_objects2020=== RUN TestPush_RejectsBadRequests/bad_root2021=== PAUSE TestPush_RejectsBadRequests/bad_root2022=== RUN TestPush_RejectsBadRequests/root_not_in_objects2023=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects2024=== CONT TestGCEndsOnShutdown/before_the_run2025--- PASS: TestReadProxyOutlastsServerWriteTimeout (10.61s)2026=== CONT TestCacheConfigHandler/no_signing_keys2027=== CONT TestCacheConfigHandler/no_cache_url_configured2028=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2029=== CONT TestCacheConfigHandler/full_config,_no_issuer2030=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale2031--- PASS: TestCacheConfigHandler (0.01s)2032 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)2033 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)2034 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)2035 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)20362026/10/27 08:50:20 INFO Received complete multipart upload request method=POST path=/api/multipart/complete20372026/10/27 08:50:20 INFO Received uploads request method=POST path=/api/pending_closures20382026/10/27 08:50:20 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=YTE1YjQ3ZTctZDJlNS00N2M0LTg3MTgtMDhhNGZlYmRjYzA1LjI4NWI5NTc1LTg0ZjAtNDA1MC04OTQ5LTQ1NDdjMjFiNDEyY3gxNzkzMDkxMDE4NTk5ODAzMDAw error="Get \"http://127.0.0.1:1/bucket77/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"20392026/10/27 08:50:20 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=YTE1YjQ3ZTctZDJlNS00N2M0LTg3MTgtMDhhNGZlYmRjYzA1LjQ2OTQ5MTgzLWZmNjAtNDIyNy1hZTMwLWFiMjU2ZTZlNTU4ZHgxNzkzMDkxMDE4NTcxNDgxMDAw parts=1220402026/10/27 08:50:20 INFO Received cleanup request method=DELETE path=/api/pending_closures20412026/10/27 08:50:20 INFO Aborted multipart uploads count=1 kept=02042--- PASS: TestRedundantMultipartUpload (10.26s)2043=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh20442026/10/27 08:50:20 WARN Request failed, retrying attempt=5 backoff=1.716435532s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20452026/10/27 08:50:20 INFO Received push request method=POST path=/api/pushes20462026/10/27 08:50:20 INFO Received complete multipart upload request method=POST path=/api/multipart/complete20472026/10/27 08:50:20 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=YTE1YjQ3ZTctZDJlNS00N2M0LTg3MTgtMDhhNGZlYmRjYzA1LmYxNmQ1M2YyLWUzNjMtNDM3Ni1hOTIzLTAwZDJlZTQ3MGQ2OHgxNzkzMDkxMDIwMzQ5NzQxMDAw20482026/10/27 08:50:20 WARN Failed to abort multipart upload key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=YTE1YjQ3ZTctZDJlNS00N2M0LTg3MTgtMDhhNGZlYmRjYzA1LmYxNmQ1M2YyLWUzNjMtNDM3Ni1hOTIzLTAwZDJlZTQ3MGQ2OHgxNzkzMDkxMDIwMzQ5NzQxMDAw error="Delete \"http://localhost:64877/bucket89/nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst?uploadId=YTE1YjQ3ZTctZDJlNS00N2M0LTg3MTgtMDhhNGZlYmRjYzA1LmYxNmQ1M2YyLWUzNjMtNDM3Ni1hOTIzLTAwZDJlZTQ3MGQ2OHgxNzkzMDkxMDIwMzQ5NzQxMDAw\": injected: abort refused"20492026/10/27 08:50:20 INFO Received complete multipart upload request method=POST path=/api/multipart/complete20502026/10/27 08:50:20 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=YTE1YjQ3ZTctZDJlNS00N2M0LTg3MTgtMDhhNGZlYmRjYzA1LmYxNmQ1M2YyLWUzNjMtNDM3Ni1hOTIzLTAwZDJlZTQ3MGQ2OHgxNzkzMDkxMDIwMzQ5NzQxMDAw20512026/10/27 08:50:20 ERROR Failed to register completed object error="get pending object \"nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst\": context canceled" object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst20522026/10/27 08:50:20 INFO Received complete multipart upload request method=POST path=/api/multipart/complete20532026/10/27 08:50:20 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=YTE1YjQ3ZTctZDJlNS00N2M0LTg3MTgtMDhhNGZlYmRjYzA1LmYxNmQ1M2YyLWUzNjMtNDM3Ni1hOTIzLTAwZDJlZTQ3MGQ2OHgxNzkzMDkxMDIwMzQ5NzQxMDAw20542026/10/27 08:50:20 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=YTE1YjQ3ZTctZDJlNS00N2M0LTg3MTgtMDhhNGZlYmRjYzA1LmYxNmQ1M2YyLWUzNjMtNDM3Ni1hOTIzLTAwZDJlZTQ3MGQ2OHgxNzkzMDkxMDIwMzQ5NzQxMDAw parts=12055--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (7.42s)2056=== CONT TestPendingClosureWriteTimeout/empty2057=== CONT TestPendingClosureWriteTimeout/400_objects2058=== CONT TestPendingClosureWriteTimeout/670k_objects2059=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline20602026-10-27 08:50:20.946 UTC [85932] LOG: checkpoint starting: wal20612026/10/27 08:50:21 INFO Received complete multipart upload request method=POST path=/api/multipart/complete2062--- PASS: TestReadProxyInvalidPath (7.04s)2063=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info20642026/10/27 08:50:21 INFO Received uploads request method=POST path=/2065=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key20662026/10/27 08:50:21 INFO Received request for more parts method=POST path=/2067=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key20682026/10/27 08:50:21 INFO Received complete multipart upload request method=POST path=/2069=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal20702026/10/27 08:50:21 INFO Received uploads request method=POST path=/2071--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)2072 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)2073 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)2074 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)2075 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)2076=== CONT TestIsValidUploadKey/narinfo2077=== CONT TestIsValidUploadKey/realisation_plus_in_output2078=== CONT TestIsValidUploadKey/unknown_type2079=== CONT TestIsValidUploadKey/empty_key20802026/10/27 08:50:21 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=YTE1YjQ3ZTctZDJlNS00N2M0LTg3MTgtMDhhNGZlYmRjYzA1LmU1M2NjNjExLTI0NzctNGVlNC05OGMwLTk5ODAzNDhkNzdkZHgxNzkzMDkxMDE5MDM1MTQ4MDAw parts=122081=== CONT TestIsValidUploadKey/absolute20822026/10/27 08:50:21 INFO Received uploads request method=POST path=/api/pending_closures2083=== CONT TestIsValidUploadKey/traversal2084=== CONT TestIsValidUploadKey/listing_key,_narinfo_type2085=== CONT TestIsValidUploadKey/nar_key,_narinfo_type2086=== CONT TestIsValidUploadKey/traversal_nar2087=== CONT TestIsValidUploadKey/index.html2088=== CONT TestIsValidUploadKey/nix-cache-info2089=== CONT TestIsValidUploadKey/narinfo_key,_nar_type2090=== CONT TestIsValidUploadKey/build_log_plus_in_name2091=== CONT TestIsValidUploadKey/realisation2092=== CONT TestIsValidUploadKey/build_log_equals2093=== CONT TestIsValidUploadKey/build_log_question_mark2094=== CONT TestIsValidUploadKey/build_log_home-manager_file2095=== CONT TestIsValidUploadKey/nar_xz2096=== CONT TestIsValidUploadKey/build_log2097=== CONT TestIsValidUploadKey/listing2098=== CONT TestIsValidUploadKey/nar_plain2099=== CONT TestIsValidUploadKey/nar_zst2100=== CONT TestProxyWriteTimeout/1_GiB_nar2101=== CONT TestProxyWriteTimeout/10_GiB_nar2102=== CONT TestProxyWriteTimeout/unknown_size2103--- PASS: TestIsValidUploadKey (0.02s)2104 --- PASS: TestIsValidUploadKey/narinfo (0.00s)2105 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)2106 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)2107 --- PASS: TestIsValidUploadKey/empty_key (0.00s)2108 --- PASS: TestIsValidUploadKey/absolute (0.00s)2109 --- PASS: TestIsValidUploadKey/traversal (0.00s)2110 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)2111 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)2112 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)2113 --- PASS: TestIsValidUploadKey/index.html (0.00s)2114 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)2115 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)2116 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)2117 --- PASS: TestIsValidUploadKey/realisation (0.00s)2118 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)2119 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)2120 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)2121 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)2122 --- PASS: TestIsValidUploadKey/build_log (0.00s)2123 --- PASS: TestIsValidUploadKey/listing (0.00s)2124 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)2125 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)2126=== CONT TestProxyWriteTimeout/narinfo2127--- PASS: TestCompletedNarNotReofferedAcrossClosures (8.81s)2128=== CONT TestIsValidCachePath/nar_bz22129=== CONT TestIsValidCachePath/short_hash2130=== CONT TestIsValidCachePath/index.html2131=== CONT TestIsValidCachePath/wrong_extension2132=== CONT TestIsValidCachePath/leading_slash2133--- PASS: TestProxyWriteTimeout (0.01s)2134 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)2135 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)2136 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)2137 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)2138=== CONT TestIsValidCachePath/empty2139=== CONT TestIsValidCachePath/invalid_char_e2140=== CONT TestIsValidCachePath/invalid_char_u2141=== CONT TestIsValidCachePath/traversal_in_middle2142=== CONT TestIsValidCachePath/random_path2143=== CONT TestIsValidCachePath/traversal_parent2144=== CONT TestIsValidCachePath/nix-cache-info2145=== CONT TestIsValidCachePath/nar_uncompressed2146=== CONT TestIsValidCachePath/realisation2147=== CONT TestIsValidCachePath/ls2148=== CONT TestIsValidCachePath/log2149=== CONT TestIsValidCachePath/nar_zst2150=== CONT TestIsValidCachePath/nar_xz2151=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars2152=== CONT TestIsValidCachePath/narinfo2153=== CONT TestParseSingleRange/unknown_unit2154=== CONT TestParseSingleRange/start_far_past_EOF2155=== CONT TestParseSingleRange/single_byte2156--- PASS: TestIsValidCachePath (0.00s)2157 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)2158 --- PASS: TestIsValidCachePath/short_hash (0.00s)2159 --- PASS: TestIsValidCachePath/index.html (0.00s)2160 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)2161 --- PASS: TestIsValidCachePath/leading_slash (0.00s)2162 --- PASS: TestIsValidCachePath/empty (0.00s)2163 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)2164 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)2165 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)2166 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)2167 --- PASS: TestIsValidCachePath/random_path (0.00s)2168 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)2169 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)2170 --- PASS: TestIsValidCachePath/realisation (0.00s)2171 --- PASS: TestIsValidCachePath/ls (0.00s)2172 --- PASS: TestIsValidCachePath/log (0.00s)2173 --- PASS: TestIsValidCachePath/nar_zst (0.00s)2174 --- PASS: TestIsValidCachePath/nar_xz (0.00s)2175 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)2176 --- PASS: TestIsValidCachePath/narinfo (0.00s)2177=== CONT TestParseSingleRange/start_past_EOF2178=== CONT TestParseSingleRange/closed2179=== CONT TestParseSingleRange/suffix_exceeds_size2180=== CONT TestParseSingleRange/suffix2181=== CONT TestParseSingleRange/open-ended2182=== CONT TestParseSingleRange/malformed_end_before_start2183=== CONT TestParseSingleRange/malformed_no_dash2184=== CONT TestParseSingleRange/malformed_both_empty2185=== CONT TestParseSingleRange/multi-range_ignored2186=== CONT TestParseSingleRange/none2187=== CONT TestParseSingleRange/end_clamped_to_size2188=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2189=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected2190--- PASS: TestParseSingleRange (0.02s)2191 --- PASS: TestParseSingleRange/unknown_unit (0.00s)2192 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)2193 --- PASS: TestParseSingleRange/single_byte (0.00s)2194 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)2195 --- PASS: TestParseSingleRange/closed (0.00s)2196 --- PASS: TestParseSingleRange/suffix (0.00s)2197 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)2198 --- PASS: TestParseSingleRange/open-ended (0.00s)2199 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)2200 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)2201 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)2202 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)2203 --- PASS: TestParseSingleRange/none (0.00s)2204 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)22052026/10/27 08:50:21 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]2206=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2207=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured22082026/10/27 08:50:21 WARN Authentication failed token_preview=eyJhbGciOi...q-Eu740q5w token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2209=== CONT TestService_RequireScope_OIDC/reader_may_not_write2210=== CONT TestService_RequireScope_OIDC/ops_may_admin2211=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2212=== CONT TestService_RequireScope_OIDC/builder_may_write2213=== CONT TestService_RequireScope_OIDC/static_token_may_write2214=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc2215=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2216=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read22172026/10/27 08:50:21 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]2218=== CONT TestService_RequireScope_OIDC/reader_may_read2219=== CONT TestService_RequireScope_OIDC/writer_implies_read2220=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc2221=== CONT TestService_RequireScope_OIDC/static_token_may_admin2222=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read2223=== CONT TestService_RequireScope_OIDC/ops_may_not_write2224=== CONT TestPush_RejectsBadRequests/no_roots22252026/10/27 08:50:21 INFO Received push request method=POST path=/api/pushes2226=== CONT TestPush_RejectsBadRequests/root_not_in_objects22272026/10/27 08:50:21 INFO Received push request method=POST path=/api/pushes2228=== CONT TestPush_RejectsBadRequests/bad_root22292026/10/27 08:50:21 INFO Received push request method=POST path=/api/pushes2230=== CONT TestPush_RejectsBadRequests/no_objects22312026/10/27 08:50:21 INFO Received push request method=POST path=/api/pushes2232--- PASS: TestService_AuthMiddleware_OIDC (6.80s)2233 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2234 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2235 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.01s)2236 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2237--- PASS: TestPush_RejectsBadRequests (6.87s)2238 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)2239 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.01s)2240 --- PASS: TestPush_RejectsBadRequests/bad_root (0.01s)2241 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)2242--- PASS: TestService_RequireScope_OIDC (6.67s)2243 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2244 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2245 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2246 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2247 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2248 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2249 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)2250 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2251 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2252 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)2253 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)2254 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2255 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)2256 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)22572026/10/27 08:50:21 INFO Received push request method=POST path=/api/pushes2258--- PASS: TestUploadHandlersRejectOversizedBody (0.17s)2259 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.28s)2260 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.29s)2261 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (4.47s)22622026/10/27 08:50:22 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>2263--- PASS: TestReadProxyNarinfo (7.66s)22642026/10/27 08:50:22 INFO Received create pin request method=POST path=/api/pins/app22652026/10/27 08:50:22 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-config22662026/10/27 08:50:22 INFO Created/updated pin name=app store_path=/nix/store/cccccccccccccccccccccccccccccccc-app narinfo_key=cccccccccccccccccccccccccccccccc.narinfo22672026/10/27 08:50:22 INFO Received delete pin request method=DELETE path=/api/pins/app22682026/10/27 08:50:22 ERROR Failed to delete pin from S3 key=pins/app error="Get \"http://127.0.0.1:1/bucket94/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"22692026/10/27 08:50:22 INFO Received delete pin request method=DELETE path=/api/pins/app22702026/10/27 08:50:22 WARN Request failed, retrying attempt=2 backoff=187.103224ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22712026/10/27 08:50:22 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22722026/10/27 08:50:22 WARN Request failed, retrying attempt=3 backoff=427.081664ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22732026/10/27 08:50:22 INFO Completed multipart upload object_key=nar/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb00000000000000000000.nar.zst upload_id=YTE1YjQ3ZTctZDJlNS00N2M0LTg3MTgtMDhhNGZlYmRjYzA1LjgyMWE3MWVhLWM1ZDYtNDU4MS04YzE4LTMwMDUxYTdkOTc2M3gxNzkzMDkxMDIwNzI1NjM4MDAw parts=1022742026/10/27 08:50:22 INFO Deleted pin name=app2275--- PASS: TestPresentReportsOnlyClosureRoots (8.02s)2276--- PASS: TestDeletePinKeepsRowWhenS3Fails (8.21s)22772026-10-27 08:50:23.013 UTC [86494] ERROR: Push does not exist: id=122782026-10-27 08:50:23.013 UTC [86494] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE22792026-10-27 08:50:23.013 UTC [86494] STATEMENT: SELECT commit_push($1)2280--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (9.34s)22812026/10/27 08:50:23 WARN Request failed, retrying attempt=4 backoff=759.739571ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2282--- PASS: TestPresentRefreshesOnlyStaleClosures (7.90s)22832026/10/27 08:50:23 WARN Rate limiter enabled after throttle name=s3-test rate=522842026/10/27 08:50:23 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."2285=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle2286 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=102287 throttle_test.go:215: Rate limiter: enabled=true, rate=5.002288--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (11.86s)22892026/10/27 08:50:23 INFO Received uploads request method=POST path=/api/pending_closures22902026/10/27 08:50:23 INFO Aborted multipart uploads count=0 kept=022912026/10/27 08:50:23 WARN Force mode enabled - objects will be deleted immediately without grace period22922026/10/27 08:50:23 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22932026/10/27 08:50:23 INFO Completed multipart upload object_key=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa00000000000000000000.nar.zst upload_id=YTE1YjQ3ZTctZDJlNS00N2M0LTg3MTgtMDhhNGZlYmRjYzA1LjVkOTNlNGVhLWZjODItNGE5YS1hODRiLWRmODk0ODU1MTFhZXgxNzkzMDkxMDIxNDcyNDY4MDAw parts=1022942026/10/27 08:50:23 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=022952026/10/27 08:50:23 INFO Vacuumed table table=pending_closures22962026/10/27 08:50:23 INFO Vacuumed table table=pending_objects22972026/10/27 08:50:23 INFO Vacuumed table table=multipart_uploads22982026/10/27 08:50:23 INFO Vacuumed table table=closures22992026/10/27 08:50:23 WARN Request failed, retrying attempt=5 backoff=1.445643492s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config23002026/10/27 08:50:23 INFO Vacuumed table table=objects23012026/10/27 08:50:23 INFO Received uploads request method=POST path=/api/pending_closures23022026/10/27 08:50:23 INFO Aborted multipart uploads count=0 kept=023032026/10/27 08:50:23 WARN Force mode enabled - objects will be deleted immediately without grace period23042026/10/27 08:50:23 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=023052026/10/27 08:50:23 INFO Vacuumed table table=pending_closures23062026/10/27 08:50:23 INFO Vacuumed table table=pending_objects23072026/10/27 08:50:23 INFO Vacuumed table table=multipart_uploads23082026/10/27 08:50:24 INFO Vacuumed table table=closures23092026/10/27 08:50:24 INFO Vacuumed table table=objects23102026/10/27 08:50:24 INFO Received uploads request method=POST path=/api/pending_closures2311--- PASS: TestForceGCDuringPushOffersSweptObject (0.02s)2312 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (8.37s)2313 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (7.33s)23142026/10/27 08:50:24 INFO Received uploads request method=POST path=/api/pending_closures23152026/10/27 08:50:24 WARN Failed to abort multipart upload key=nar/ssssssssssssssssssssssssssssssssssssssssssssssssssss.nar.zst upload_id=YTE1YjQ3ZTctZDJlNS00N2M0LTg3MTgtMDhhNGZlYmRjYzA1LmQ3ZDU0M2JmLTg1OTctNDkzMy04NGM5LWRhYTI4YTE5NDE2MHgxNzkzMDkxMDI0MTk0NzEzMDAw error="Access Denied"23162026/10/27 08:50:24 WARN keeping failed pending closure for cleanup to retry the abort id=12317--- PASS: TestPendingClosureFailureTracksEveryUpload (0.01s)2318 --- PASS: TestPendingClosureFailureTracksEveryUpload/refuse_aborts=true (6.78s)2319 --- PASS: TestPendingClosureFailureTracksEveryUpload/refuse_aborts=false (7.09s)23202026/10/27 08:50:25 INFO Received complete multipart upload request method=POST path=/api/multipart/complete23212026/10/27 08:50:25 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"23222026/10/27 08:50:25 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-config23232026/10/27 08:50:25 WARN Request failed, retrying attempt=2 backoff=204.304649ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config23242026/10/27 08:50:25 INFO Completed multipart upload object_key=nar/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb00000000000000000000.nar.zst upload_id=YTE1YjQ3ZTctZDJlNS00N2M0LTg3MTgtMDhhNGZlYmRjYzA1LmY3NDA3NWU5LWQwNzAtNDRhYi05NzVkLWI4MzI5Y2U3NGNmOXgxNzkzMDkxMDIxNDcyODMzMDAw parts=1023252026/10/27 08:50:25 INFO Received complete push request method=POST path=/api/pushes/1/complete23262026/10/27 08:50:25 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"23272026/10/27 08:50:25 INFO Completed push id=1 objects=4 duration=24.92975ms23282026/10/27 08:50:25 INFO Received push request method=POST path=/api/pushes23292026/10/27 08:50:25 WARN Request failed, retrying attempt=3 backoff=410.255367ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config23302026/10/27 08:50:25 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"23312026/10/27 08:50:25 INFO Aborted multipart uploads count=0 kept=023322026/10/27 08:50:25 WARN Force mode enabled - objects will be deleted immediately without grace period23332026/10/27 08:50:25 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:64877/bucket103/?delete=\": context canceled"23342026/10/27 08:50:25 INFO Aborted multipart uploads count=0 kept=023352026/10/27 08:50:25 WARN Force mode enabled - objects will be deleted immediately without grace period23362026/10/27 08:50:26 WARN Request failed, retrying attempt=4 backoff=813.895953ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config23372026/10/27 08:50:26 INFO Aborted multipart uploads count=0 kept=023382026/10/27 08:50:26 WARN Force mode enabled - objects will be deleted immediately without grace period23392026-10-27 08:50:26.600 UTC [86524] ERROR: canceling statement due to user request23402026-10-27 08:50:26.600 UTC [86524] 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/27 08:50:26 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=023842026/10/27 08:50:26 INFO Vacuumed table table=pending_closures23852026/10/27 08:50:26 INFO Vacuumed table table=pending_objects23862026/10/27 08:50:26 WARN Request failed, retrying attempt=5 backoff=1.600779207s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config23872026/10/27 08:50:26 INFO Vacuumed table table=multipart_uploads23882026/10/27 08:50:26 INFO Vacuumed table table=closures23892026/10/27 08:50:27 INFO Vacuumed table table=objects2390--- PASS: TestGCEndsOnShutdown (0.02s)2391 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (6.37s)2392 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (6.88s)2393 --- PASS: TestGCEndsOnShutdown/before_the_run (7.48s)23942026/10/27 08:50:28 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_closures23952026/10/27 08:50:28 WARN Request failed, retrying attempt=2 backoff=188.851827ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures23962026/10/27 08:50:28 WARN Request failed, retrying attempt=3 backoff=392.117722ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures23972026/10/27 08:50:29 WARN Request failed, retrying attempt=4 backoff=822.485948ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2398--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2399 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (8.35s)2400 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (8.83s)24012026/10/27 08:50:29 INFO Received uploads request method=POST path=/api/pending_closures24022026/10/27 08:50:30 WARN Request failed, retrying attempt=5 backoff=1.631728466s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2403=== NAME TestOrphanedObjectsGCStressTest2404 orphaned_objects_gc_test.go:503: Stress test completed successfully:2405 orphaned_objects_gc_test.go:504: - Active objects preserved: 202406 orphaned_objects_gc_test.go:505: - Objects deleted: 2102407 orphaned_objects_gc_test.go:506: - Total GC'd: 2102408--- PASS: TestOrphanedObjectsGCStressTest (39.60s)24092026/10/27 08:50:30 INFO Received complete multipart upload request method=POST path=/api/multipart/complete24102026/10/27 08:50:30 INFO Completed multipart upload object_key=nar/cccccccccccccccccccccccccccccccc00000000000000000000.nar.zst upload_id=YTE1YjQ3ZTctZDJlNS00N2M0LTg3MTgtMDhhNGZlYmRjYzA1LmRjNmQwYjcwLWFlMDAtNDY5Ny1hNmZhLTc0ZGMxZmQyOTUyMngxNzkzMDkxMDI1NjE4MDkyMDAw parts=1024112026/10/27 08:50:30 INFO Received complete push request method=POST path=/api/pushes/2/complete24122026/10/27 08:50:30 INFO Completed push id=2 objects=4 duration=1.448709ms2413--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (15.98s)2414--- PASS: TestPendingClosureWriteTimeout (0.03s)2415 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2416 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2417 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2418 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (9.72s)2419--- PASS: TestClientErrorHandling (0.01s)2420 --- PASS: TestClientErrorHandling/InvalidStorePath (6.68s)2421 --- PASS: TestClientErrorHandling/InvalidAuthToken (7.01s)2422 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.99s)2423PASS2424{"timestamp":"2026-10-27T08:50:31.675935Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:65329","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(9)"}24252026-10-27 08:50:31.862 UTC [85926] LOG: received smart shutdown request24262026-10-27 08:50:31.863 UTC [85926] LOG: background worker "logical replication launcher" (PID 85937) exited with exit code 124272026-10-27 08:50:33.015 UTC [85932] LOG: checkpoint complete: wrote 8522 buffers (52.0%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 33 recycled; write=11.186 s, sync=0.721 s, total=12.070 s; sync files=37079, longest=0.001 s, average=0.001 s; distance=533361 kB, estimate=533361 kB; lsn=0/234C1968, redo lsn=0/2206951024282026-10-27 08:50:33.016 UTC [85932] LOG: shutting down24292026-10-27 08:50:33.016 UTC [85932] LOG: checkpoint starting: shutdown immediate24302026-10-27 08:50:33.173 UTC [85932] LOG: checkpoint complete: wrote 3703 buffers (22.6%), wrote 1 SLRU buffers; 0 WAL file(s) added, 0 removed, 1 recycled; write=0.128 s, sync=0.028 s, total=0.157 s; sync files=1135, longest=0.001 s, average=0.001 s; distance=20833 kB, estimate=482108 kB; lsn=0/234C19E0, redo lsn=0/234C19E024312026-10-27 08:50:33.181 UTC [85926] 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 TestHTTPClientForHasTimeouts2472=== CONT TestValidateToken_NoMatchingProvider2473=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2474=== CONT TestPins_ConfigValidation2475=== CONT TestValidateToken_KubernetesServiceAccount2476=== CONT TestGlobMatch2477=== RUN TestGlobMatch/foo_foo2478=== PAUSE TestGlobMatch/foo_foo2479=== RUN TestGlobMatch/foo_bar2480=== CONT TestScopes_Rules2481=== PAUSE TestGlobMatch/foo_bar2482=== CONT TestNewValidator_KubernetesRequiresCA2483--- PASS: TestPins_ConfigValidation (0.00s)2484=== CONT TestValidateToken_BoundSubjectMismatch2485=== CONT TestValidateToken_BoundClaimsMismatch2486=== CONT TestValidateToken_Expired2487=== CONT TestPins_ReservedForMatchingRule2488=== CONT TestPins_TopLevelShorthand2489=== CONT TestValidateToken_ValidToken2490=== CONT TestValidateToken_WrongAudience2491=== CONT TestScopes_LegacyProviderDefaultsToWrite2492=== CONT TestValidateToken_MultipleProviders2493=== CONT TestAudienceForIssuer2494--- PASS: TestAudienceForIssuer (0.00s)2495=== CONT TestScopes_ConfigValidation2496=== RUN TestGlobMatch/*_2497=== PAUSE TestGlobMatch/*_2498=== RUN TestGlobMatch/*_anything2499=== PAUSE TestGlobMatch/*_anything2500--- PASS: TestScopes_ConfigValidation (0.00s)2501=== RUN TestGlobMatch/foo*_foo2502=== PAUSE TestGlobMatch/foo*_foo2503=== RUN TestGlobMatch/foo*_foobar2504=== PAUSE TestGlobMatch/foo*_foobar2505=== RUN TestGlobMatch/foo*_bar2506=== PAUSE TestGlobMatch/foo*_bar2507=== RUN TestGlobMatch/*bar_bar2508=== PAUSE TestGlobMatch/*bar_bar2509=== RUN TestGlobMatch/*bar_foobar2510=== PAUSE TestGlobMatch/*bar_foobar2511=== RUN TestGlobMatch/*bar_foo2512=== PAUSE TestGlobMatch/*bar_foo2513=== RUN TestGlobMatch/foo*bar_foobar2514=== PAUSE TestGlobMatch/foo*bar_foobar2515=== RUN TestGlobMatch/foo*bar_foo123bar2516=== PAUSE TestGlobMatch/foo*bar_foo123bar2517=== RUN TestGlobMatch/foo*bar_foobarbaz2518=== PAUSE TestGlobMatch/foo*bar_foobarbaz2519=== RUN TestGlobMatch/*/*_foo/bar2520=== PAUSE TestGlobMatch/*/*_foo/bar2521=== RUN TestGlobMatch/*/*_foo2522=== PAUSE TestGlobMatch/*/*_foo2523=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2524=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2525=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02526=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02527=== RUN TestGlobMatch/refs/*/main_refs/heads/main2528=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2529=== RUN TestGlobMatch/fo?_foo2530=== PAUSE TestGlobMatch/fo?_foo2531=== RUN TestGlobMatch/fo?_fo2532=== PAUSE TestGlobMatch/fo?_fo2533=== RUN TestGlobMatch/fo?_fooo2534=== PAUSE TestGlobMatch/fo?_fooo2535=== RUN TestGlobMatch/?oo_foo2536=== PAUSE TestGlobMatch/?oo_foo2537=== RUN TestGlobMatch/?oo_boo2538=== PAUSE TestGlobMatch/?oo_boo2539=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2540=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2541=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2542=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2543=== CONT TestGlobMatch/foo_foo2544=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2545=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2546=== CONT TestGlobMatch/?oo_boo2547=== CONT TestGlobMatch/?oo_foo2548=== CONT TestGlobMatch/fo?_fo2549=== CONT TestGlobMatch/fo?_fooo2550=== CONT TestGlobMatch/fo?_foo2551=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02552=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2553=== CONT TestGlobMatch/*/*_foo2554=== CONT TestGlobMatch/refs/*/main_refs/heads/main2555=== CONT TestGlobMatch/foo*bar_foobarbaz2556=== CONT TestGlobMatch/*/*_foo/bar2557=== CONT TestGlobMatch/foo*bar_foobar2558=== CONT TestGlobMatch/*bar_foo2559=== CONT TestGlobMatch/*bar_foobar2560=== CONT TestGlobMatch/*bar_bar2561=== CONT TestGlobMatch/foo*bar_foo123bar2562=== CONT TestGlobMatch/foo*_bar2563=== CONT TestGlobMatch/foo*_foo2564=== CONT TestGlobMatch/*_anything2565=== CONT TestGlobMatch/foo*_foobar2566=== CONT TestGlobMatch/*_2567=== CONT TestGlobMatch/foo_bar2568--- PASS: TestGlobMatch (0.04s)2569 --- PASS: TestGlobMatch/foo_foo (0.00s)2570 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2571 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2572 --- PASS: TestGlobMatch/?oo_boo (0.00s)2573 --- PASS: TestGlobMatch/?oo_foo (0.00s)2574 --- PASS: TestGlobMatch/fo?_fo (0.00s)2575 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2576 --- PASS: TestGlobMatch/fo?_foo (0.00s)2577 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2578 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2579 --- PASS: TestGlobMatch/*/*_foo (0.00s)2580 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2581 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2582 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2583 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2584 --- PASS: TestGlobMatch/*bar_foo (0.00s)2585 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2586 --- PASS: TestGlobMatch/*bar_bar (0.00s)2587 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2588 --- PASS: TestGlobMatch/foo*_bar (0.00s)2589 --- PASS: TestGlobMatch/foo*_foo (0.00s)2590 --- PASS: TestGlobMatch/*_anything (0.00s)2591 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2592 --- PASS: TestGlobMatch/*_ (0.00s)2593 --- PASS: TestGlobMatch/foo_bar (0.00s)25942026/10/27 08:50:36 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:49307/oidc25952026/10/27 08:50:36 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:49311/oidc2596--- PASS: TestValidateToken_Expired (0.08s)25972026/10/27 08:50:36 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:49310/oidc25982026/10/27 08:50:36 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:49309/oidc2599--- PASS: TestValidateToken_WrongAudience (0.08s)2600--- PASS: TestValidateToken_BoundSubjectMismatch (0.08s)2601--- PASS: TestPins_ReservedForMatchingRule (0.09s)26022026/10/27 08:50:36 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:49319/oidc26032026/10/27 08:50:36 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:493122604--- PASS: TestValidateToken_ValidToken (0.09s)26052026/10/27 08:50:36 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:49321/oidc2606--- PASS: TestValidateToken_KubernetesServiceAccount (0.10s)26072026/10/27 08:50:36 http: TLS handshake error from 127.0.0.1:49318: remote error: tls: bad certificate2608--- PASS: TestNewValidator_KubernetesRequiresCA (0.10s)2609--- PASS: TestPins_TopLevelShorthand (0.10s)26102026/10/27 08:50:36 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:49323/oidc2611--- PASS: TestValidateToken_BoundClaimsMismatch (0.11s)26122026/10/27 08:50:36 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC12326132026/10/27 08:50:36 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:49327/oidc2614--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.12s)2615--- PASS: TestScopes_Rules (0.13s)26162026/10/27 08:50:36 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:49306/oidc2617--- PASS: TestValidateToken_NoMatchingProvider (0.16s)26182026/10/27 08:50:36 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:49333/oidc2619--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.22s)26202026/10/27 08:50:36 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:49330/oidc26212026/10/27 08:50:36 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:49335/oidc2622--- PASS: TestValidateToken_MultipleProviders (0.32s)2623--- PASS: TestHTTPClientForHasTimeouts (0.41s)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/27 08:50:38 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 TestSendPathsEmpty2687=== CONT TestWorkerSkipsGCdPaths2688=== CONT TestQueueEnqueueWaitsOutSlowWriter2689=== CONT TestWorkerRemoveFailureIsNotProgress2690=== RUN TestWorkerRemoveFailureIsNotProgress/collected_path2691=== CONT TestShutdownFinishesInFlightPush2692=== CONT TestWorkerKeepsPathItCannotStat2693=== CONT TestDrainTimeout2694=== CONT TestDrainTimeoutDuringIsolation2695=== RUN TestDrainTimeoutDuringIsolation/probe_cut_short2696=== CONT TestServerBacksOffOnAcceptErrors2697=== CONT TestQueueConcurrentWriters2698=== CONT TestServerRefusesOversizedAndNonStoreRequests26992026/10/27 08:50:38 ERROR Accept failed error="too many open files"2700=== CONT TestServerStalledClientDoesNotBlockShutdown2701=== CONT TestWorkerRemovesCachedPathBatchedWithLargerClosure2702=== CONT TestQueueRetryMovesToBack27032026/10/27 08:50:38 ERROR Refusing path outside the store path=/etc/shadow store=/nix/store2704=== CONT TestQueueFetchBatchLimit2705=== CONT TestQueueFetchRemoveLifecycle27062026/10/27 08:50:38 ERROR Refusing path outside the store path=/nix/store store=/nix/store2707=== CONT TestQueueRemoveLargeClosure2708=== CONT TestWorkerUploadsAndRemoves2709=== CONT TestDrainGivesUpWhenServerDown2710=== CONT TestRunNotBlockedByPoisonHead27112026/10/27 08:50:38 ERROR Refusing path outside the store path=/nix/store/ store=/nix/store2712=== CONT TestFailedPathPrunedByLaterClosure2713=== CONT TestQueueDeduplication2714=== CONT TestQueueRemove27152026/10/27 08:50:38 ERROR Refusing path outside the store path=/nix/store/../../etc/shadow store=/nix/store2716=== CONT TestWorkerPrunesClosureDeps2717--- PASS: TestSendPathsEmpty (0.00s)2718=== CONT TestDrainIsolatesPoisonPath2719=== PAUSE TestWorkerRemoveFailureIsNotProgress/collected_path2720=== RUN TestShutdownFinishesInFlightPush/completes2721=== RUN TestWorkerRemoveFailureIsNotProgress/pushed_batch2722=== PAUSE TestDrainTimeoutDuringIsolation/probe_cut_short2723=== PAUSE TestShutdownFinishesInFlightPush/completes2724=== RUN TestDrainTimeoutDuringIsolation/probe_outlasts_the_deadline2725=== RUN TestShutdownFinishesInFlightPush/hung_push_bounded_by_the_drain_timeout2726=== PAUSE TestWorkerRemoveFailureIsNotProgress/pushed_batch2727=== PAUSE TestDrainTimeoutDuringIsolation/probe_outlasts_the_deadline2728=== RUN TestWorkerRemoveFailureIsNotProgress/isolated_paths2729=== PAUSE TestShutdownFinishesInFlightPush/hung_push_bounded_by_the_drain_timeout2730=== PAUSE TestWorkerRemoveFailureIsNotProgress/isolated_paths2731=== CONT TestQueueEnqueueAndFetch2732=== CONT TestDrainTimeoutDuringIsolation/probe_cut_short2733=== CONT TestDrainTimeoutDuringIsolation/probe_outlasts_the_deadline27342026/10/27 08:50:38 ERROR Refusing path outside the store path=/nix/store/0123456789abcdfghijklmnpqrsvwxyz-hello/bin/sh store=/nix/store27352026/10/27 08:50:38 ERROR Refusing path outside the store path=nix/store/0123456789abcdfghijklmnpqrsvwxyz-hello store=/nix/store27362026/10/27 08:50:38 ERROR Refusing path outside the store path=/nix/storeX/0123456789abcdfghijklmnpqrsvwxyz-hello store=/nix/store27372026/10/27 08:50:38 ERROR Refusing path outside the store path=/nix/store/.links store=/nix/store27382026/10/27 08:50:38 ERROR Refusing path outside the store path=/nix/store/aaa-hello store=/nix/store27392026/10/27 08:50:38 ERROR Refusing path outside the store path=/nix/store/0123456789abcdfghijklmnpqrsvwxyz store=/nix/store27402026/10/27 08:50:38 ERROR Accept failed error="too many open files"27412026/10/27 08:50:38 ERROR Refusing path outside the store path=/nix/store/0123456789abcdfghijklmnpqrsvwxyz- store=/nix/store27422026/10/27 08:50:38 ERROR Refusing path outside the store path=/nix/store/0123456789ebcdfghijklmnpqrsvwxyz-hello store=/nix/store27432026/10/27 08:50:38 ERROR Refusing path outside the store path="/nix/store/0123456789abcdfghijklmnpqrsvwxyz-hel\x00lo" store=/nix/store27442026/10/27 08:50:38 ERROR Refusing path outside the store path=/nix/store/0123456789abcdfghijklmnpqrsvwxyz-hel/lo store=/nix/store27452026/10/27 08:50:38 ERROR Refusing path outside the store path=/nix/store/0123456789abcdfghijklmnpqrsvwxyz-xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx store=/nix/store27462026/10/27 08:50:38 ERROR Failed to decode request error="unexpected EOF"2747--- PASS: TestServerRefusesOversizedAndNonStoreRequests (0.01s)2748=== CONT TestWorkerRemoveFailureIsNotProgress/collected_path27492026/10/27 08:50:38 ERROR Accept failed error="too many open files"27502026/10/27 08:50:38 INFO Upload queue status pending=327512026/10/27 08:50:38 INFO Uploading batch count=127522026/10/27 08:50:38 ERROR Upload failed error="upload failed" count=127532026/10/27 08:50:38 INFO Uploading batch count=227542026/10/27 08:50:38 INFO Upload queue status pending=227552026/10/27 08:50:38 INFO Uploading batch count=427562026/10/27 08:50:38 ERROR Upload failed error="upload failed" count=427572026/10/27 08:50:38 INFO Uploading batch count=427582026/10/27 08:50:38 ERROR Upload failed error="upload failed" count=427592026/10/27 08:50:38 INFO Upload queue status pending=227602026/10/27 08:50:38 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/6/scratch/7ab19ce6cf566bc8/build/TestWorkerSkipsGCdPaths2632122784/002/nonexistent27612026/10/27 08:50:38 INFO Uploading batch count=127622026/10/27 08:50:38 INFO Uploading batch count=227632026/10/27 08:50:38 WARN Cannot stat store path, will retry later path=/private/var/tb/6/scratch/7ab19ce6cf566bc8/build/TestWorkerKeepsPathItCannotStat1362072870/002/locked/aaa error="lstat /private/var/tb/6/scratch/7ab19ce6cf566bc8/build/TestWorkerKeepsPathItCannotStat1362072870/002/locked/aaa: permission denied"2764--- PASS: TestQueueEnqueueAndFetch (0.03s)2765=== CONT TestWorkerRemoveFailureIsNotProgress/isolated_paths27662026/10/27 08:50:38 INFO Uploading batch count=127672026/10/27 08:50:38 ERROR Accept failed error="too many open files"27682026/10/27 08:50:38 INFO Upload queue status pending=22769--- PASS: TestQueueDeduplication (0.03s)2770=== CONT TestWorkerRemoveFailureIsNotProgress/pushed_batch2771--- PASS: TestQueueRetryMovesToBack (0.04s)2772=== CONT TestShutdownFinishesInFlightPush/completes27732026/10/27 08:50:38 INFO Upload queue status pending=327742026/10/27 08:50:38 INFO Uploading batch count=227752026/10/27 08:50:38 INFO Uploading batch count=227762026/10/27 08:50:38 WARN Cannot stat store path, will retry later path=/private/var/tb/6/scratch/7ab19ce6cf566bc8/build/TestWorkerKeepsPathItCannotStat1362072870/002/locked/aaa error="lstat /private/var/tb/6/scratch/7ab19ce6cf566bc8/build/TestWorkerKeepsPathItCannotStat1362072870/002/locked/aaa: permission denied"27772026/10/27 08:50:38 INFO Uploading batch count=127782026/10/27 08:50:38 INFO Uploading batch count=427792026/10/27 08:50:38 INFO Uploading batch count=127802026/10/27 08:50:38 ERROR Upload failed error="upload failed" count=427812026/10/27 08:50:38 ERROR Upload failed error="upload failed" count=127822026/10/27 08:50:38 WARN Cannot stat store path, will retry later path=/private/var/tb/6/scratch/7ab19ce6cf566bc8/build/TestWorkerKeepsPathItCannotStat1362072870/002/locked/aaa error="lstat /private/var/tb/6/scratch/7ab19ce6cf566bc8/build/TestWorkerKeepsPathItCannotStat1362072870/002/locked/aaa: permission denied"27832026/10/27 08:50:38 INFO Uploading batch count=227842026/10/27 08:50:38 ERROR Upload failed error="upload failed" count=227852026/10/27 08:50:38 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/6/scratch/7ab19ce6cf566bc8/build/TestDrainGivesUpWhenServerDown4004188311/002/a2786--- PASS: TestQueueFetchRemoveLifecycle (0.04s)2787=== CONT TestShutdownFinishesInFlightPush/hung_push_bounded_by_the_drain_timeout27882026/10/27 08:50:38 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/6/scratch/7ab19ce6cf566bc8/build/TestDrainIsolatesPoisonPath1450560644/002/bbb27892026/10/27 08:50:38 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/6/scratch/7ab19ce6cf566bc8/build/TestDrainGivesUpWhenServerDown4004188311/002/b27902026/10/27 08:50:38 ERROR Drain finished with paths left in queue remaining=12791--- PASS: TestQueueRemove (0.04s)27922026/10/27 08:50:38 INFO Uploading batch count=22793--- PASS: TestQueueFetchBatchLimit (0.04s)27942026/10/27 08:50:38 ERROR Upload failed error="upload failed" count=227952026/10/27 08:50:38 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/6/scratch/7ab19ce6cf566bc8/build/TestDrainGivesUpWhenServerDown4004188311/002/c2796--- PASS: TestFailedPathPrunedByLaterClosure (0.04s)27972026/10/27 08:50:38 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/6/scratch/7ab19ce6cf566bc8/build/TestDrainGivesUpWhenServerDown4004188311/002/d2798--- PASS: TestWorkerKeepsPathItCannotStat (0.05s)27992026/10/27 08:50:38 INFO Uploading batch count=128002026/10/27 08:50:38 ERROR Upload failed error="upload failed" count=128012026/10/27 08:50:38 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/6/scratch/7ab19ce6cf566bc8/build/TestWorkerRemoveFailureIsNotProgresscollected_path1432789974/001/nonexistent28022026/10/27 08:50:38 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=128032026/10/27 08:50:38 INFO Uploading batch count=228042026/10/27 08:50:38 ERROR Upload failed error="upload failed" count=228052026/10/27 08:50:38 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/6/scratch/7ab19ce6cf566bc8/build/TestDrainGivesUpWhenServerDown4004188311/002/e28062026/10/27 08:50:38 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/6/scratch/7ab19ce6cf566bc8/build/TestWorkerRemoveFailureIsNotProgresscollected_path1432789974/001/nonexistent28072026/10/27 08:50:38 INFO Uploading batch count=128082026/10/27 08:50:38 ERROR Upload failed error="upload failed" count=128092026/10/27 08:50:38 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=128102026/10/27 08:50:38 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/6/scratch/7ab19ce6cf566bc8/build/TestDrainGivesUpWhenServerDown4004188311/002/f28112026/10/27 08:50:38 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/6/scratch/7ab19ce6cf566bc8/build/TestWorkerRemoveFailureIsNotProgresscollected_path1432789974/001/nonexistent28122026/10/27 08:50:38 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=128132026/10/27 08:50:38 INFO Upload queue status pending=228142026/10/27 08:50:38 ERROR Drain finished with paths left in queue remaining=128152026/10/27 08:50:38 INFO Uploading batch count=228162026/10/27 08:50:38 INFO Uploading batch count=128172026/10/27 08:50:38 ERROR Upload failed error="upload failed" count=128182026/10/27 08:50:38 INFO Upload queue status pending=228192026/10/27 08:50:38 ERROR Drain finished with paths left in queue remaining=128202026/10/27 08:50:38 ERROR Drain finished with paths left in queue remaining=1028212026/10/27 08:50:38 INFO Uploading batch count=22822--- PASS: TestDrainIsolatesPoisonPath (0.05s)2823--- PASS: TestDrainGivesUpWhenServerDown (0.05s)2824--- PASS: TestWorkerSkipsGCdPaths (0.05s)28252026/10/27 08:50:38 INFO Uploading batch count=228262026/10/27 08:50:38 INFO Uploading batch count=228272026/10/27 08:50:38 ERROR Upload failed error="upload failed" count=228282026/10/27 08:50:38 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=228292026/10/27 08:50:38 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=128302026/10/27 08:50:38 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=128312026/10/27 08:50:38 INFO Uploading batch count=228322026/10/27 08:50:38 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=228332026/10/27 08:50:38 INFO Uploading batch count=228342026/10/27 08:50:38 ERROR Upload failed error="upload failed" count=228352026/10/27 08:50:38 INFO Uploading batch count=228362026/10/27 08:50:38 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=12837--- PASS: TestWorkerRemovesCachedPathBatchedWithLargerClosure (0.05s)28382026/10/27 08:50:38 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=228392026/10/27 08:50:38 ERROR Drain finished with paths left in queue remaining=228402026/10/27 08:50:38 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=12841--- PASS: TestWorkerPrunesClosureDeps (0.05s)28422026/10/27 08:50:38 INFO Uploading batch count=228432026/10/27 08:50:38 ERROR Upload failed error="upload failed" count=228442026/10/27 08:50:38 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=128452026/10/27 08:50:38 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=128462026/10/27 08:50:38 ERROR Drain finished with paths left in queue remaining=22847--- PASS: TestWorkerUploadsAndRemoves (0.06s)2848--- PASS: TestWorkerRemoveFailureIsNotProgress (0.00s)2849 --- PASS: TestWorkerRemoveFailureIsNotProgress/collected_path (0.04s)2850 --- PASS: TestWorkerRemoveFailureIsNotProgress/pushed_batch (0.02s)2851 --- PASS: TestWorkerRemoveFailureIsNotProgress/isolated_paths (0.02s)28522026/10/27 08:50:38 ERROR Accept failed error="too many open files"28532026/10/27 08:50:38 ERROR Accept failed error="too many open files"2854--- PASS: TestQueueConcurrentWriters (0.17s)28552026/10/27 08:50:38 ERROR Failed to decode request error="read unix /private/var/tb/6/scratch/7ab19ce6cf566bc8/build/hook4045083026/test.sock->: i/o timeout"28562026/10/27 08:50:38 ERROR Failed to write response error="write unix /private/var/tb/6/scratch/7ab19ce6cf566bc8/build/hook4045083026/test.sock->: i/o timeout"2857--- PASS: TestServerStalledClientDoesNotBlockShutdown (0.20s)28582026/10/27 08:50:38 ERROR Upload failed error="context canceled" count=228592026/10/27 08:50:38 ERROR Drain finished with paths left in queue remaining=42860--- PASS: TestDrainTimeout (0.23s)28612026/10/27 08:50:38 ERROR Drain finished with paths left in queue remaining=428622026/10/27 08:50:38 ERROR Upload failed error="context canceled" count=228632026/10/27 08:50:38 ERROR Drain finished with paths left in queue remaining=22864--- PASS: TestShutdownFinishesInFlightPush (0.00s)2865 --- PASS: TestShutdownFinishesInFlightPush/completes (0.11s)2866 --- PASS: TestShutdownFinishesInFlightPush/hung_push_bounded_by_the_drain_timeout (0.21s)28672026/10/27 08:50:38 ERROR Accept failed error="too many open files"28682026/10/27 08:50:38 ERROR Drain finished with paths left in queue remaining=32869--- PASS: TestDrainTimeoutDuringIsolation (0.00s)2870 --- PASS: TestDrainTimeoutDuringIsolation/probe_cut_short (0.23s)2871 --- PASS: TestDrainTimeoutDuringIsolation/probe_outlasts_the_deadline (0.33s)28722026/10/27 08:50:38 ERROR Accept failed error="too many open files"2873--- PASS: TestServerBacksOffOnAcceptErrors (0.64s)2874--- PASS: TestQueueRemoveLargeClosure (0.81s)28752026/10/27 08:50:39 INFO Uploading batch count=128762026/10/27 08:50:39 INFO Uploading batch count=128772026/10/27 08:50:39 INFO Uploading batch count=128782026/10/27 08:50:39 ERROR Upload failed error="upload failed" count=128792026/10/27 08:50:39 INFO Uploading batch count=128802026/10/27 08:50:39 ERROR Upload failed error="upload failed" count=128812026/10/27 08:50:39 INFO Uploading batch count=128822026/10/27 08:50:39 ERROR Upload failed error="upload failed" count=128832026/10/27 08:50:39 INFO Uploading batch count=128842026/10/27 08:50:39 ERROR Upload failed error="upload failed" count=128852026/10/27 08:50:39 ERROR Drain finished with paths left in queue remaining=12886--- PASS: TestRunNotBlockedByPoisonHead (1.07s)2887--- PASS: TestQueueEnqueueWaitsOutSlowWriter (6.06s)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 TestExternalSignerRejectsInvalidPublicKey2920=== CONT TestExternalSignerProgramErrorKeepsProcess2921=== CONT TestGenerateFingerprint2922=== CONT TestExternalSignerClose2923=== RUN TestGenerateFingerprint/basic_with_references2924=== PAUSE TestGenerateFingerprint/basic_with_references2925=== RUN TestGenerateFingerprint/no_references2926=== PAUSE TestGenerateFingerprint/no_references2927=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2928=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2929=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2930=== CONT TestSignBatch2931=== CONT TestSignErrors2932=== CONT TestNilKeyPublicKey2933--- PASS: TestNilKeyPublicKey (0.00s)2934=== CONT TestParseSigningKey2935=== RUN TestParseSigningKey/valid_32-byte_key2936=== CONT TestSign2937=== CONT TestExternalSignerCancellation2938=== PAUSE TestParseSigningKey/valid_32-byte_key2939=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2940=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2941=== RUN TestParseSigningKey/no_colon2942=== PAUSE TestParseSigningKey/no_colon2943=== RUN TestParseSigningKey/empty_name2944=== PAUSE TestParseSigningKey/empty_name2945=== RUN TestParseSigningKey/invalid_base642946=== CONT TestExternalSignerRestartsAfterCrash2947=== CONT TestExternalSignerErrors2948=== CONT TestExternalSignerWrongPublicKey2949=== RUN TestExternalSignerRejectsInvalidPublicKey/#002950=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2951=== RUN TestGenerateFingerprint/invalid_nar_hash_length2952=== PAUSE TestParseSigningKey/invalid_base642953=== RUN TestExternalSignerErrors/missing_signatures2954=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002955=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2956=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2957=== RUN TestGenerateFingerprint/invalid_store_path_prefix2958=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2959=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2960=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2961=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2962=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2963=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2964=== RUN TestGenerateFingerprint/invalid_reference_prefix2965=== RUN TestParseSigningKey/wrong_length2966=== PAUSE TestParseSigningKey/wrong_length2967=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2968=== PAUSE TestExternalSignerErrors/missing_signatures2969=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2970=== RUN TestExternalSignerErrors/invalid_signature_base642971=== CONT TestParseSigningKey/valid_32-byte_key2972=== PAUSE TestExternalSignerErrors/invalid_signature_base642973=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2974=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2975=== CONT TestParseSigningKey/wrong_length2976=== CONT TestExternalSignerRejectsInvalidPublicKey/#002977=== RUN TestExternalSignerErrors/wrong_signature_length2978=== PAUSE TestExternalSignerErrors/wrong_signature_length2979=== RUN TestExternalSignerErrors/program_error2980=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2981=== CONT TestParseSigningKey/invalid_base642982=== PAUSE TestExternalSignerErrors/program_error2983=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2984=== CONT TestGenerateFingerprint/invalid_reference_prefix2985=== CONT TestGenerateFingerprint/invalid_store_path_prefix2986=== CONT TestGenerateFingerprint/invalid_nar_hash_length2987=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2988=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2989=== CONT TestGenerateFingerprint/basic_with_references2990=== RUN TestExternalSignerErrors/wrong_shape2991=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2992--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2993 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2994 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2995 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2996 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2997 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2998=== CONT TestGenerateFingerprint/no_references2999=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name3000=== CONT TestParseSigningKey/empty_name3001=== CONT TestParseSigningKey/no_colon3002=== PAUSE TestExternalSignerErrors/wrong_shape3003--- PASS: TestGenerateFingerprint (0.00s)3004 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)3005 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)3006 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)3007 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)3008 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)3009 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)3010 --- PASS: TestGenerateFingerprint/no_references (0.00s)3011=== RUN TestExternalSignerErrors/wrong_id3012=== PAUSE TestExternalSignerErrors/wrong_id3013=== RUN TestExternalSignerErrors/too_few_signatures3014=== PAUSE TestExternalSignerErrors/too_few_signatures3015=== RUN TestExternalSignerErrors/exit_at_startup3016=== PAUSE TestExternalSignerErrors/exit_at_startup3017=== RUN TestExternalSignerErrors/wrong_signatures_shape3018=== PAUSE TestExternalSignerErrors/wrong_signatures_shape3019=== RUN TestExternalSignerErrors/unrequested_key3020=== PAUSE TestExternalSignerErrors/unrequested_key3021=== RUN TestExternalSignerErrors/wrong_signature_name3022=== PAUSE TestExternalSignerErrors/wrong_signature_name3023=== RUN TestExternalSignerErrors/exit_on_request3024=== PAUSE TestExternalSignerErrors/exit_on_request3025=== RUN TestExternalSignerErrors/invalid_JSON3026=== PAUSE TestExternalSignerErrors/invalid_JSON3027=== RUN TestExternalSignerErrors/null3028=== PAUSE TestExternalSignerErrors/null3029=== RUN TestExternalSignerErrors/null_signatures3030=== PAUSE TestExternalSignerErrors/null_signatures3031=== RUN TestExternalSignerErrors/missing_signature_name3032=== PAUSE TestExternalSignerErrors/missing_signature_name3033=== RUN TestSignErrors/nil_key3034=== CONT TestExternalSignerErrors/invalid_signature_base643035=== CONT TestExternalSignerErrors/wrong_signatures_shape3036=== CONT TestExternalSignerErrors/wrong_id3037=== CONT TestExternalSignerErrors/invalid_JSON3038--- PASS: TestParseSigningKey (0.00s)3039 --- PASS: TestParseSigningKey/wrong_length (0.00s)3040 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)3041 --- PASS: TestParseSigningKey/empty_name (0.00s)3042 --- PASS: TestParseSigningKey/no_colon (0.00s)3043 --- PASS: TestParseSigningKey/valid_32-byte_key (0.01s)3044 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.01s)3045=== CONT TestExternalSignerErrors/wrong_signature_length3046=== CONT TestExternalSignerErrors/exit_on_request3047=== CONT TestExternalSignerErrors/program_error3048=== CONT TestExternalSignerErrors/wrong_signature_name3049=== CONT TestExternalSignerErrors/null_signatures3050=== CONT TestExternalSignerErrors/missing_signatures3051=== PAUSE TestSignErrors/nil_key3052=== CONT TestExternalSignerErrors/null3053=== RUN TestSignErrors/nil_narinfo3054=== PAUSE TestSignErrors/nil_narinfo3055=== RUN TestSignErrors/invalid_narinfo3056=== PAUSE TestSignErrors/invalid_narinfo3057=== RUN TestSignErrors/canceled3058=== PAUSE TestSignErrors/canceled3059=== CONT TestSignErrors/canceled3060=== CONT TestSignErrors/invalid_narinfo3061=== CONT TestSignErrors/nil_narinfo3062=== CONT TestSignErrors/nil_key3063=== CONT TestExternalSignerErrors/unrequested_key3064=== CONT TestExternalSignerErrors/too_few_signatures3065=== CONT TestExternalSignerErrors/exit_at_startup3066=== CONT TestExternalSignerErrors/missing_signature_name3067--- PASS: TestSign (0.01s)3068=== CONT TestExternalSignerErrors/wrong_shape3069--- PASS: TestSignErrors (0.01s)3070 --- PASS: TestSignErrors/canceled (0.00s)3071 --- PASS: TestSignErrors/invalid_narinfo (0.00s)3072 --- PASS: TestSignErrors/nil_narinfo (0.00s)3073 --- PASS: TestSignErrors/nil_key (0.00s)3074--- PASS: TestSignBatch (0.02s)3075--- PASS: TestExternalSigner (0.24s)3076--- PASS: TestExternalSignerWrongPublicKey (0.41s)3077--- PASS: TestExternalSignerClose (0.60s)3078--- PASS: TestExternalSignerProgramErrorKeepsProcess (0.79s)3079--- PASS: TestExternalSignerCancellation (1.00s)3080--- PASS: TestExternalSignerRestartsAfterCrash (2.35s)3081--- PASS: TestExternalSignerErrors (0.01s)3082 --- PASS: TestExternalSignerErrors/invalid_JSON (1.16s)3083 --- PASS: TestExternalSignerErrors/exit_on_request (1.35s)3084 --- PASS: TestExternalSignerErrors/wrong_signature_name (1.55s)3085 --- PASS: TestExternalSignerErrors/null_signatures (1.74s)3086 --- PASS: TestExternalSignerErrors/null (1.93s)3087 --- PASS: TestExternalSignerErrors/program_error (2.12s)3088 --- PASS: TestExternalSignerErrors/wrong_id (2.51s)3089 --- PASS: TestExternalSignerErrors/wrong_signature_length (2.70s)3090 --- PASS: TestExternalSignerErrors/missing_signature_name (2.89s)3091 --- PASS: TestExternalSignerErrors/unrequested_key (3.08s)3092 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (3.28s)3093 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (3.47s)3094 --- PASS: TestExternalSignerErrors/missing_signatures (3.66s)3095 --- PASS: TestExternalSignerErrors/too_few_signatures (3.85s)3096 --- PASS: TestExternalSignerErrors/wrong_shape (4.04s)3097 --- PASS: TestExternalSignerErrors/exit_at_startup (4.23s)3098PASS3099Running OpenBao signer tests...3100=== RUN TestSign3101=== PAUSE TestSign3102=== RUN TestSignErrors3103=== PAUSE TestSignErrors3104=== RUN TestServe3105=== PAUSE TestServe3106=== RUN TestServeRejectsGarbage3107=== PAUSE TestServeRejectsGarbage3108=== CONT TestSign3109=== CONT TestSignErrors3110=== RUN TestSignErrors/invalid_json3111=== PAUSE TestSignErrors/invalid_json3112=== CONT TestServe3113=== CONT TestServeRejectsGarbage3114=== RUN TestSignErrors/no_prefix3115--- PASS: TestServeRejectsGarbage (0.00s)3116=== PAUSE TestSignErrors/no_prefix3117=== RUN TestSignErrors/invalid_base643118=== PAUSE TestSignErrors/invalid_base643119=== RUN TestSignErrors/http_error3120=== PAUSE TestSignErrors/http_error3121=== CONT TestSignErrors/no_prefix3122=== CONT TestSignErrors/invalid_base643123=== CONT TestSignErrors/invalid_json3124=== CONT TestSignErrors/http_error3125--- PASS: TestServe (0.00s)3126--- PASS: TestSign (0.00s)3127--- PASS: TestSignErrors (0.00s)3128 --- PASS: TestSignErrors/no_prefix (0.00s)3129 --- PASS: TestSignErrors/http_error (0.00s)3130 --- PASS: TestSignErrors/invalid_json (0.00s)3131 --- PASS: TestSignErrors/invalid_base64 (0.00s)3132PASS3133Running niks3-hook command tests...3134=== RUN TestServeSecondSignalEndsDrain3135=== PAUSE TestServeSecondSignalEndsDrain3136=== RUN TestServeThenDrainPushesSendAcceptedBeforeShutdown3137=== PAUSE TestServeThenDrainPushesSendAcceptedBeforeShutdown3138=== CONT TestServeSecondSignalEndsDrain3139=== CONT TestServeThenDrainPushesSendAcceptedBeforeShutdown3140--- PASS: TestServeSecondSignalEndsDrain (0.08s)31412026/10/27 08:50:52 INFO Upload queue status pending=131422026/10/27 08:50:52 INFO Uploading batch count=13143--- PASS: TestServeThenDrainPushesSendAcceptedBeforeShutdown (0.12s)3144PASS3145Running rate limiter tests...3146=== RUN TestAdaptiveRateLimiter_ThreadSafety3147=== PAUSE TestAdaptiveRateLimiter_ThreadSafety3148=== CONT TestAdaptiveRateLimiter_ThreadSafety31492026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=7031502026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=4931512026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=34.331522026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=24.00999999999999831532026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=16.80731542026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=11.76489999999999931552026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=8.2354331562026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=5.76480099999999931572026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=531582026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=531592026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=5.63678500000000131602026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=531612026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=531622026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=531632026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=531642026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=531652026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=531662026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=531672026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=531682026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=531692026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=531702026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=531712026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=531722026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=531732026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=531742026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=531752026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=531762026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=531772026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=531782026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=531792026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=5.12435000000000131802026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=531812026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=531822026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=531832026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=531842026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=531852026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=531862026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=531872026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=531882026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=531892026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=531902026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=531912026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=531922026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=531932026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=531942026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=531952026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=5.12435000000000131962026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=531972026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=531982026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=531992026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=532002026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=532012026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=532022026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=532032026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=532042026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=7.50256083500000332052026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=5.25179258450000232062026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=532072026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=532082026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=532092026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=532102026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=532112026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=532122026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=532132026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=6.200463500000001532142026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=532152026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=532162026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=532172026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=532182026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=532192026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=532202026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=5.63678500000000132212026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=532222026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=532232026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=532242026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=532252026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=532262026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=532272026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=532282026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=532292026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=532302026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=532312026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=532322026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=532332026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=532342026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=532352026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=6.200463500000001532362026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=532372026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=532382026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=532392026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=532402026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=532412026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=532422026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=532432026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=532442026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=532452026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=532462026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=532472026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=532482026/10/27 08:50:54 WARN Rate limiter backed off name=test rate=53249--- PASS: TestAdaptiveRateLimiter_ThreadSafety (0.01s)3250PASS