niks3-go-unit-tests
checks.x86_64-linux.go-unit-tests
· build #307
· raw
1tribuchet: building on jamie2Running 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_ProducerErrorIsNotEOF22=== PAUSE TestUploadMultipart_ProducerErrorIsNotEOF23=== RUN TestUploadMultipart_FailedPartBufferNotReused24=== PAUSE TestUploadMultipart_FailedPartBufferNotReused25=== RUN TestPartSizeForNAR26=== PAUSE TestPartSizeForNAR27=== RUN TestUploadMultipart_SupersededByPeer28=== PAUSE TestUploadMultipart_SupersededByPeer29=== RUN TestDumpPathCaseHackMatchesNix30--- PASS: TestDumpPathCaseHackMatchesNix (0.04s)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:289: read 114 of 32768000 bytes45--- PASS: TestDumpPathWriterErrorStopsReading (0.59s)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.02s)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 TestDoWithRetry_FinalResponseBodyReadable79=== PAUSE TestDoWithRetry_FinalResponseBodyReadable80=== RUN TestShellSplit81=== PAUSE TestShellSplit82=== RUN TestShellSplitErrors83=== PAUSE TestShellSplitErrors84=== RUN TestStreamPushReportsEveryPath85=== PAUSE TestStreamPushReportsEveryPath86=== RUN TestStreamPushBatchesUnderLoad87=== PAUSE TestStreamPushBatchesUnderLoad88=== RUN TestStreamPushIsolatesFailures89=== PAUSE TestStreamPushIsolatesFailures90=== RUN TestStreamPushGivesUpOnDeadServer91=== PAUSE TestStreamPushGivesUpOnDeadServer92=== RUN TestStreamPushRequestLine93=== PAUSE TestStreamPushRequestLine94=== RUN TestStreamPushReportsSignatures95=== PAUSE TestStreamPushReportsSignatures96=== RUN TestClientSignaturesByStorePath97=== PAUSE TestClientSignaturesByStorePath98=== RUN TestStreamPushStopsOnCancel99=== PAUSE TestStreamPushStopsOnCancel100=== RUN TestSetClientTLS101=== PAUSE TestSetClientTLS102=== RUN TestSetClientTLSDoesNotMutateDefaultTransport103=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport104=== RUN TestSetClientTLSErrors105=== PAUSE TestSetClientTLSErrors106=== RUN TestStaticToken107=== PAUSE TestStaticToken108=== RUN TestFileTokenReadsAndCaches109=== PAUSE TestFileTokenReadsAndCaches110=== RUN TestFileTokenMissing111=== PAUSE TestFileTokenMissing112=== RUN TestFileTokenEmpty113=== PAUSE TestFileTokenEmpty114=== RUN TestScriptTokenNoExpiryRerunsEveryCall115=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall116=== RUN TestScriptTokenCachesUntilRefresh117=== PAUSE TestScriptTokenCachesUntilRefresh118=== RUN TestScriptTokenEmptyToken119=== PAUSE TestScriptTokenEmptyToken120=== RUN TestScriptTokenBadJSON121=== PAUSE TestScriptTokenBadJSON122=== RUN TestScriptTokenScriptFails123=== PAUSE TestScriptTokenScriptFails124=== RUN TestScriptTokenEmptyCommand125=== PAUSE TestScriptTokenEmptyCommand126=== RUN TestScriptTokenDoesNotWaitForItsChildren127=== PAUSE TestScriptTokenDoesNotWaitForItsChildren128=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry129=== CONT TestSetClientTLS130=== CONT TestDoWithRetry_FinalResponseBodyReadable131=== CONT TestParsePathInfoJSONMultiplePaths132=== CONT TestDumpPathSingleFile133=== CONT TestStreamPushStopsOnCancel134=== RUN TestStreamPushStopsOnCancel/waiting_for_input135=== CONT TestParsePathInfoJSON136=== CONT TestStreamPushReportsEveryPath137=== RUN TestParsePathInfoJSON/Nix_format138=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths139=== PAUSE TestParsePathInfoJSON/Nix_format140=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths141=== CONT TestScriptTokenDoesNotWaitForItsChildren142=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths143=== RUN TestScriptTokenDoesNotWaitForItsChildren/cancelled_while_a_child_runs144=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths145=== CONT TestStreamPushReportsSignatures146=== CONT TestPushPathsReportsOnlyUnuploadablePathsOfSkippedClosure147=== CONT TestStreamPushIsolatesFailures148=== CONT TestShellSplit149=== PAUSE TestScriptTokenDoesNotWaitForItsChildren/cancelled_while_a_child_runs150=== CONT TestStreamPushGivesUpOnDeadServer151=== CONT TestStreamPushRequestLine152=== CONT TestClientSignaturesByStorePath153=== CONT TestStreamPushBatchesUnderLoad154=== CONT TestScriptTokenBadJSON155=== CONT TestScriptTokenScriptFails156=== CONT TestScriptTokenCachesUntilRefresh157=== CONT TestScriptTokenEmptyToken158=== CONT TestTruncatedNARDumpIsNotCompleted159=== CONT TestScriptTokenEmptyCommand160=== CONT TestResolveStorePath161=== PAUSE TestStreamPushStopsOnCancel/waiting_for_input162=== RUN TestParsePathInfoJSON/Lix_format163=== CONT TestSetClientTLSDoesNotMutateDefaultTransport164--- PASS: TestShellSplit (0.00s)165=== CONT TestUploadMultipart_PartsInParallel166=== RUN TestScriptTokenDoesNotWaitForItsChildren/child_left_holding_stdout167=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer168--- PASS: TestStreamPushReportsEveryPath (0.02s)169=== CONT TestSetClientTLSErrors170--- PASS: TestClientSignaturesByStorePath (0.00s)171--- PASS: TestScriptTokenEmptyCommand (0.00s)172=== PAUSE TestScriptTokenDoesNotWaitForItsChildren/child_left_holding_stdout173=== RUN TestStreamPushStopsOnCancel/partial_batch_waiting_for_a_slot174--- PASS: TestStreamPushIsolatesFailures (0.02s)175=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess176=== PAUSE TestParsePathInfoJSON/Lix_format177=== CONT TestShellSplitErrors178=== RUN TestSetClientTLSErrors/missing_cert_file179=== CONT TestFileTokenEmpty180=== RUN TestSetClientTLS/rejects_connection_without_client_cert181=== CONT TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent182=== CONT TestRegisterUploadedObjectReusesConnections183=== PAUSE TestStreamPushStopsOnCancel/partial_batch_waiting_for_a_slot184=== RUN TestStreamPushBatchesUnderLoad/together185=== CONT TestDoServerRequestAttachesToken186=== CONT TestEncodeNixBase32WithRealHash187--- PASS: TestStreamPushGivesUpOnDeadServer (0.01s)188=== CONT TestRateLimiterFeedback189=== RUN TestParsePathInfoJSON/empty_input190=== RUN TestRateLimiterFeedback/429_enables_limiter191=== PAUSE TestParsePathInfoJSON/empty_input192=== PAUSE TestSetClientTLSErrors/missing_cert_file193=== CONT TestUploadMultipart_ProducerErrorIsNotEOF194=== CONT TestPathInfoHashCompatibility195=== RUN TestUploadMultipart_ProducerErrorIsNotEOF/short_read_inside_a_part196=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)197=== PAUSE TestUploadMultipart_ProducerErrorIsNotEOF/short_read_inside_a_part198=== CONT TestEncodeNixBase32199=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert200=== RUN TestStreamPushStopsOnCancel/input_closed,_last_batch_waiting_for_a_slot201=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)202=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA203=== PAUSE TestStreamPushBatchesUnderLoad/together204=== CONT TestSupersededNARStillUploadsListing205=== RUN TestStreamPushBatchesUnderLoad/one_at_a_time206=== RUN TestSupersededNARStillUploadsListing/small_NAR207=== PAUSE TestStreamPushStopsOnCancel/input_closed,_last_batch_waiting_for_a_slot208=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA209=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon210=== PAUSE TestStreamPushBatchesUnderLoad/one_at_a_time211=== PAUSE TestSupersededNARStillUploadsListing/small_NAR212=== CONT TestDumpPathMatchesNix213=== RUN TestSupersededNARStillUploadsListing/dump_cut_short214=== PAUSE TestSupersededNARStillUploadsListing/dump_cut_short215=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon216=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI217=== RUN TestSupersededNARStillUploadsListing/listing_upload_fails218=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI219=== CONT TestGetStorePathHash220=== PAUSE TestSupersededNARStillUploadsListing/listing_upload_fails221=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512222=== RUN TestGetStorePathHash/valid_store_path223=== CONT TestPartSizeForNAR224=== RUN TestPartSizeForNAR/zero_stays_at_minimum225=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512226=== CONT TestUploadMultipart_SupersededByPeer227=== RUN TestUploadMultipart_SupersededByPeer/exists228=== PAUSE TestUploadMultipart_SupersededByPeer/exists229=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum230=== RUN TestParsePathInfoJSON/whitespace_only231=== PAUSE TestParsePathInfoJSON/whitespace_only232=== CONT TestFileTokenReadsAndCaches233=== RUN TestParsePathInfoJSON/invalid_JSON234=== RUN TestUploadMultipart_SupersededByPeer/missing235=== RUN TestSetClientTLSErrors/missing_key_file236=== PAUSE TestSetClientTLSErrors/missing_key_file237=== PAUSE TestParsePathInfoJSON/invalid_JSON238=== PAUSE TestUploadMultipart_SupersededByPeer/missing239=== RUN TestEncodeNixBase32/test_string_hash240=== PAUSE TestEncodeNixBase32/test_string_hash241=== RUN TestSetClientTLSErrors/missing_ca_file242=== CONT TestCaseHackSuffix243=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun244=== CONT TestFileTokenMissing245=== RUN TestUploadMultipart_ProducerErrorIsNotEOF/empty_read_on_a_part_boundary246=== RUN TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/committed_earlier247=== RUN TestEncodeNixBase32/empty_input248=== PAUSE TestUploadMultipart_ProducerErrorIsNotEOF/empty_read_on_a_part_boundary249=== PAUSE TestEncodeNixBase32/empty_input250=== RUN TestSetClientTLS/preserves_debug_logging_transport251=== CONT TestScriptTokenNoExpiryRerunsEveryCall252=== PAUSE TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/committed_earlier253=== RUN TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/cleaned_up254=== RUN TestStreamPushStopsOnCancel/full_batch_waiting_for_a_slot255=== CONT TestConvertHashToNix32256--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.01s)257=== CONT TestDumpPathWriterError258=== CONT TestUploadMultipart_FailedPartBufferNotReused259=== PAUSE TestRateLimiterFeedback/429_enables_limiter260=== PAUSE TestGetStorePathHash/valid_store_path261=== CONT TestFilterOversizedClosures262=== RUN TestPartSizeForNAR/small_stays_at_minimum263=== PAUSE TestSetClientTLSErrors/missing_ca_file264=== CONT TestStaticToken265=== PAUSE TestSetClientTLS/preserves_debug_logging_transport266=== CONT TestDoWithRetry_BodyReplayedViaGetBody267=== RUN TestSetClientTLSErrors/invalid_ca_file268=== PAUSE TestSetClientTLSErrors/invalid_ca_file269=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica270=== PAUSE TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/cleaned_up271=== CONT TestPathInfoCACompatibility272=== CONT TestCompletePendingClosure_NotFoundWithoutKey273=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths274=== RUN TestPathInfoCACompatibility/null_ca_field275=== PAUSE TestPathInfoCACompatibility/null_ca_field276=== RUN TestPathInfoCACompatibility/old_string_format_-_text277=== RUN TestConvertHashToNix32/SRI_format_to_Nix32278=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text279=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive280=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32281=== RUN TestConvertHashToNix32/already_Nix32_format282=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths283=== RUN TestRateLimiterFeedback/503_enables_limiter284=== PAUSE TestRateLimiterFeedback/503_enables_limiter285=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter286=== PAUSE TestStreamPushStopsOnCancel/full_batch_waiting_for_a_slot287=== RUN TestStreamPushStopsOnCancel/request_line_waiting_for_a_slot288=== PAUSE TestStreamPushStopsOnCancel/request_line_waiting_for_a_slot289=== PAUSE TestConvertHashToNix32/already_Nix32_format290=== RUN TestConvertHashToNix32/invalid_format291=== PAUSE TestConvertHashToNix32/invalid_format292=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter293=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter294=== PAUSE TestPartSizeForNAR/small_stays_at_minimum295--- PASS: TestScriptTokenCachesUntilRefresh (0.01s)296=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive297=== CONT TestScriptTokenDoesNotWaitForItsChildren/cancelled_while_a_child_runs298=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum299=== RUN TestPathInfoCACompatibility/new_structured_format_-_text300--- PASS: TestCompletePendingClosure_NotFoundWithoutKey (0.00s)301=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text302--- PASS: TestStreamPushReportsSignatures (0.17s)303--- PASS: TestShellSplitErrors (0.00s)304=== RUN TestStreamPushStopsOnCancel/lines_read_but_not_taken305=== CONT TestScriptTokenDoesNotWaitForItsChildren/child_left_holding_stdout306=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter307=== RUN TestGetStorePathHash/basename_without_hyphen_should_error308=== CONT TestStreamPushBatchesUnderLoad/one_at_a_time309=== CONT TestSupersededNARStillUploadsListing/dump_cut_short310=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum311=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)312=== RUN TestFilterOversizedClosures/no_limit_keeps_everything313=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method314=== CONT TestStreamPushBatchesUnderLoad/together315--- PASS: TestScriptTokenBadJSON (0.15s)316=== PAUSE TestStreamPushStopsOnCancel/lines_read_but_not_taken317=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error318=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts319--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.17s)320=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method321=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error322=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts323=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI324=== CONT TestSupersededNARStillUploadsListing/listing_upload_fails325=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512326=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error327=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything328=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error329--- PASS: TestResolveStorePath (0.15s)330=== CONT TestSupersededNARStillUploadsListing/small_NAR331=== CONT TestUploadMultipart_SupersededByPeer/missing332=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped333--- PASS: TestEncodeNixBase32WithRealHash (0.00s)334--- PASS: TestDumpPathSingleFile (0.17s)335--- PASS: TestScriptTokenEmptyToken (0.15s)336--- PASS: TestScriptTokenScriptFails (0.15s)337--- PASS: TestFileTokenEmpty (0.00s)338=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon339=== CONT TestParsePathInfoJSON/Nix_format340=== RUN TestPartSizeForNAR/1_TiB341=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped342=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error343--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.18s)344=== CONT TestParsePathInfoJSON/invalid_JSON345=== CONT TestUploadMultipart_SupersededByPeer/exists346--- PASS: TestDoServerRequestAttachesToken (0.01s)347--- PASS: TestFileTokenReadsAndCaches (0.00s)348=== CONT TestParsePathInfoJSON/Lix_format349=== CONT TestEncodeNixBase32/empty_input350--- PASS: TestFileTokenMissing (0.00s)351=== CONT TestUploadMultipart_ProducerErrorIsNotEOF/empty_read_on_a_part_boundary352--- PASS: TestStaticToken (0.00s)353=== CONT TestEncodeNixBase32/test_string_hash354=== PAUSE TestPartSizeForNAR/1_TiB355=== RUN TestFilterOversizedClosures/all_closures_skipped356=== CONT TestParsePathInfoJSON/empty_input357=== CONT TestParsePathInfoJSON/whitespace_only358=== CONT TestUploadMultipart_ProducerErrorIsNotEOF/short_read_inside_a_part359=== CONT TestSetClientTLS/preserves_debug_logging_transport360--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.01s)361=== RUN TestPartSizeForNAR/5_TiB_S3_max_object362=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object363=== PAUSE TestFilterOversizedClosures/all_closures_skipped364--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.01s)365=== RUN TestPartSizeForNAR/capped_at_5_GiB366=== PAUSE TestPartSizeForNAR/capped_at_5_GiB367=== CONT TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/committed_earlier368=== CONT TestSetClientTLSErrors/missing_key_file369=== CONT TestSetClientTLSErrors/missing_ca_file370--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.24s)371--- PASS: TestCaseHackSuffix (0.24s)372--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.24s)373--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)374 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)375 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)376=== CONT TestSetClientTLS/rejects_connection_without_client_cert377--- PASS: TestStreamPushBatchesUnderLoad (0.16s)378 --- PASS: TestStreamPushBatchesUnderLoad/together (0.00s)379 --- PASS: TestStreamPushBatchesUnderLoad/one_at_a_time (0.01s)380=== CONT TestSetClientTLSErrors/missing_cert_file381=== CONT TestConvertHashToNix32/SRI_format_to_Nix32382=== CONT TestConvertHashToNix32/invalid_format383--- PASS: TestPathInfoHashCompatibility (0.00s)384 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)385 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)386 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)387 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)388=== CONT TestRateLimiterFeedback/429_enables_limiter389=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA390=== CONT TestConvertHashToNix32/already_Nix32_format391=== CONT TestSetClientTLSErrors/invalid_ca_file392--- PASS: TestEncodeNixBase32 (0.01s)393 --- PASS: TestEncodeNixBase32/empty_input (0.00s)394 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)395--- PASS: TestParsePathInfoJSON (0.18s)396 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)397 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)398 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)399 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)400 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)401--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)402 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.01s)403 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.01s)404=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter405=== CONT TestRateLimiterFeedback/503_enables_limiter406=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter407--- PASS: TestPushPathsReportsOnlyUnuploadablePathsOfSkippedClosure (0.43s)408=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method409=== CONT TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/cleaned_up410--- PASS: TestConvertHashToNix32 (0.01s)411 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)412 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)413 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)414=== CONT TestPathInfoCACompatibility/null_ca_field415=== CONT TestPathInfoCACompatibility/old_string_format_-_text416=== CONT TestStreamPushStopsOnCancel/full_batch_waiting_for_a_slot417=== CONT TestPathInfoCACompatibility/new_structured_format_-_text418=== CONT TestStreamPushStopsOnCancel/lines_read_but_not_taken419=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive420--- PASS: TestRateLimiterFeedback (0.02s)421 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)422 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)423 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)424 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)425--- PASS: TestSetClientTLSErrors (0.17s)426 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)427 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)428 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)429 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)430=== CONT TestStreamPushStopsOnCancel/request_line_waiting_for_a_slot431=== CONT TestStreamPushStopsOnCancel/input_closed,_last_batch_waiting_for_a_slot432--- PASS: TestPathInfoCACompatibility (0.01s)433 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)434 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)435 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)436 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)437 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)438=== CONT TestStreamPushStopsOnCancel/partial_batch_waiting_for_a_slot439--- PASS: TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent (0.01s)440 --- PASS: TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/committed_earlier (0.00s)441 --- PASS: TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/cleaned_up (0.01s)442=== CONT TestStreamPushStopsOnCancel/waiting_for_input443=== CONT TestGetStorePathHash/valid_store_path444=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error445=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error446=== CONT TestGetStorePathHash/basename_without_hyphen_should_error447=== CONT TestFilterOversizedClosures/all_closures_skipped448--- PASS: TestGetStorePathHash (0.24s)449 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)450 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)451 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)452 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)453=== CONT TestPartSizeForNAR/5_TiB_S3_max_object454=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped455=== CONT TestFilterOversizedClosures/no_limit_keeps_everything456=== CONT TestPartSizeForNAR/capped_at_5_GiB457=== CONT TestPartSizeForNAR/1_TiB458=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts459--- PASS: TestFilterOversizedClosures (0.24s)460 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)461 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)462 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)463=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum464=== CONT TestPartSizeForNAR/small_stays_at_minimum465=== CONT TestPartSizeForNAR/zero_stays_at_minimum466--- PASS: TestPartSizeForNAR (0.25s)467 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)468 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)469 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)470 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)471 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)472 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)473 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)474--- PASS: TestStreamPushStopsOnCancel (0.20s)475 --- PASS: TestStreamPushStopsOnCancel/request_line_waiting_for_a_slot (0.05s)476 --- PASS: TestStreamPushStopsOnCancel/lines_read_but_not_taken (0.05s)477 --- PASS: TestStreamPushStopsOnCancel/input_closed,_last_batch_waiting_for_a_slot (0.05s)478 --- PASS: TestStreamPushStopsOnCancel/full_batch_waiting_for_a_slot (0.05s)479 --- PASS: TestStreamPushStopsOnCancel/partial_batch_waiting_for_a_slot (0.05s)480 --- PASS: TestStreamPushStopsOnCancel/waiting_for_input (0.05s)481--- PASS: TestDumpPathWriterError (0.32s)482--- PASS: TestSetClientTLS (0.19s)483 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.02s)484 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.03s)485 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.30s)486--- PASS: TestUploadMultipart_ProducerErrorIsNotEOF (0.01s)487 --- PASS: TestUploadMultipart_ProducerErrorIsNotEOF/short_read_inside_a_part (0.36s)488 --- PASS: TestUploadMultipart_ProducerErrorIsNotEOF/empty_read_on_a_part_boundary (0.37s)489--- PASS: TestStreamPushRequestLine (0.83s)490--- PASS: TestRegisterUploadedObjectReusesConnections (0.68s)491--- PASS: TestDumpPathMatchesNix (0.72s)492--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)493--- PASS: TestSupersededNARStillUploadsListing (0.00s)494 --- PASS: TestSupersededNARStillUploadsListing/listing_upload_fails (0.27s)495 --- PASS: TestSupersededNARStillUploadsListing/small_NAR (0.27s)496 --- PASS: TestSupersededNARStillUploadsListing/dump_cut_short (1.25s)497--- PASS: TestUploadMultipart_FailedPartBufferNotReused (1.32s)498--- PASS: TestUploadMultipart_PartsInParallel (1.51s)499--- PASS: TestTruncatedNARDumpIsNotCompleted (1.55s)500--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (2.15s)501--- PASS: TestScriptTokenDoesNotWaitForItsChildren (0.17s)502 --- PASS: TestScriptTokenDoesNotWaitForItsChildren/child_left_holding_stdout (2.01s)503 --- PASS: TestScriptTokenDoesNotWaitForItsChildren/cancelled_while_a_child_runs (2.23s)504PASS505Running server tests...506The files belonging to this database system will be owned by user "nixbld".507This user must also own the server process.508509The database cluster will be initialized with locale "C".510The default database encoding has accordingly been set to "SQL_ASCII".511The default text search configuration will be set to "english".512513Data page checksums are enabled.514515creating directory /build/postgres872348293/data ... ok516creating subdirectories ... ok517selecting dynamic shared memory implementation ... posix518selecting default "max_connections" ... 100519selecting default "shared_buffers" ... 128MB520selecting default time zone ... UTC521creating configuration files ... ok522running bootstrap script ... ok523performing post-bootstrap initialization ... ok524syncing data to disk ... ok525526initdb: warning: enabling "trust" authentication for local connections527initdb: 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.528529Success. You can now start the database server using:530531 pg_ctl -D /build/postgres872348293/data -l logfile start532533/build/postgres872348293:5432 - no response5342026-10-01 09:22:12.385 UTC [172] LOG: starting PostgreSQL 18.6 on x86_64-pc-linux-gnu, compiled by clang version 21.1.8, 64-bit5352026-10-01 09:22:12.385 UTC [172] LOG: listening on Unix socket "/build/postgres872348293/.s.PGSQL.5432"5362026-10-01 09:22:12.390 UTC [179] LOG: database system was shut down at 2026-10-01 09:22:12 UTC5372026-10-01 09:22:12.394 UTC [172] LOG: database system is ready to accept connections538/build/postgres872348293:5432 - accepting connections539{"timestamp":"2026-10-01T09:22:12.696005776Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"e9cae99b-fae5-4a64-b68d-6964194d98cc","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":0,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":501,"threadName":"rustfs-worker","threadId":"ThreadId(399)"}540=== RUN TestService_AuthMiddleware541=== PAUSE TestService_AuthMiddleware542=== RUN TestService_AuthMiddleware_MTLSProxyHeader543=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader544=== RUN TestService_AuthMiddleware_MTLSBoundSubjects545=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects546=== RUN TestService_ReadAuthMiddleware547=== PAUSE TestService_ReadAuthMiddleware548=== RUN TestService_AuthMiddleware_OIDC549=== PAUSE TestService_AuthMiddleware_OIDC550=== RUN TestService_RequireScope_OIDC551=== PAUSE TestService_RequireScope_OIDC552=== RUN TestService_ReadScope_PublicByDefault553=== PAUSE TestService_ReadScope_PublicByDefault554=== RUN TestCacheConfigHandler555=== PAUSE TestCacheConfigHandler556=== RUN TestCacheStatsHandler557=== PAUSE TestCacheStatsHandler558=== RUN TestClientCADerivations559=== PAUSE TestClientCADerivations560=== RUN TestClientErrorHandling561=== PAUSE TestClientErrorHandling562=== RUN TestClientIntegration563=== PAUSE TestClientIntegration564=== RUN TestClientMultipleUploads565=== PAUSE TestClientMultipleUploads566=== RUN TestClientWithDependencies567=== PAUSE TestClientWithDependencies568=== RUN TestClientSharedPathCommittedMidPush569=== PAUSE TestClientSharedPathCommittedMidPush570=== RUN TestPinProtectsFromGC571=== PAUSE TestPinProtectsFromGC572=== RUN TestClientPushesUseOnePush573=== PAUSE TestClientPushesUseOnePush574=== RUN TestClientFallsBackToClosures575=== PAUSE TestClientFallsBackToClosures576=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock577=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock578=== RUN TestResolveDBConnectionString579=== PAUSE TestResolveDBConnectionString580=== RUN TestConnectWaitsForAPeerMigration581=== PAUSE TestConnectWaitsForAPeerMigration582=== RUN TestConnectSerialisesConcurrentMigrations583=== PAUSE TestConnectSerialisesConcurrentMigrations584=== RUN TestLeadElectsOneAndHandsOver585=== PAUSE TestLeadElectsOneAndHandsOver586=== RUN TestLeadIncumbentWinsAfterRestart5872026/10/01 09:22:12 INFO lead: acquired remote=192.0.2.1:12345882026/10/01 09:22:14 INFO lead: released remote=192.0.2.1:12345892026/10/01 09:22:14 INFO lead: acquired remote=192.0.2.1:12345902026/10/01 09:22:15 INFO lead: released remote=192.0.2.1:1234591--- PASS: TestLeadIncumbentWinsAfterRestart (2.33s)592=== RUN TestLeadEndsOnShutdown593=== PAUSE TestLeadEndsOnShutdown594=== RUN TestLeadEndsWhenItsConnectionHangs5952026/10/01 09:22:15 INFO lead: acquired remote=192.0.2.1:12345962026-10-01 09:22:16.476 UTC [626] FATAL: terminating connection due to administrator command5972026/10/01 09:22:16 INFO lead: acquired remote=192.0.2.1:12345982026/10/01 09:22:17 WARN lead: lock connection lost error="timeout: context deadline exceeded"5992026/10/01 09:22:17 INFO lead: released remote=192.0.2.1:12346002026/10/01 09:22:17 INFO lead: released remote=192.0.2.1:1234601--- PASS: TestLeadEndsWhenItsConnectionHangs (2.76s)602=== RUN TestGCAdvisoryLockBlocksConcurrentRun603=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun604=== RUN TestGCBugBareHashReferences605=== PAUSE TestGCBugBareHashReferences606=== RUN TestGCMetrics607=== PAUSE TestGCMetrics608=== RUN TestPushDedupSurvivesConcurrentGC609=== PAUSE TestPushDedupSurvivesConcurrentGC610=== RUN TestDeduplicatedObjectsRecordedAsPending611=== PAUSE TestDeduplicatedObjectsRecordedAsPending612=== RUN TestGCSweepSkipsPendingObjects613=== PAUSE TestGCSweepSkipsPendingObjects614=== RUN TestTombstonedObjectOfferedWithoutWaiting615=== PAUSE TestTombstonedObjectOfferedWithoutWaiting616=== RUN TestGCSweepDeliversEachKeyOnce617=== PAUSE TestGCSweepDeliversEachKeyOnce618=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection619=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection620=== RUN TestForceGCDuringPushOffersSweptObject621=== PAUSE TestForceGCDuringPushOffersSweptObject622=== RUN TestFailedS3DeleteKeepsTombstone623=== PAUSE TestFailedS3DeleteKeepsTombstone624=== RUN TestSweepSkipsRowsLockedByPush625=== PAUSE TestSweepSkipsRowsLockedByPush626=== RUN TestRegisterCompletedObjectNeedsPendingRow627=== PAUSE TestRegisterCompletedObjectNeedsPendingRow628=== RUN TestGetExistingObjectsLocksRows629=== PAUSE TestGetExistingObjectsLocksRows630=== RUN TestSweepRechecksPendingAfterLocking631=== PAUSE TestSweepRechecksPendingAfterLocking632=== RUN TestPushWaitsForSweepHoldingRow633=== PAUSE TestPushWaitsForSweepHoldingRow634=== RUN TestCommitRacingPendingCleanupKeepsObjects635=== PAUSE TestCommitRacingPendingCleanupKeepsObjects636=== RUN TestGCEndsOnShutdown637=== PAUSE TestGCEndsOnShutdown638=== RUN TestGCTaskStore_StartNew639=== PAUSE TestGCTaskStore_StartNew640=== RUN TestGCTaskStore_DeduplicateSameParams641=== PAUSE TestGCTaskStore_DeduplicateSameParams642=== RUN TestGCTaskStore_ConflictDifferentParams643=== PAUSE TestGCTaskStore_ConflictDifferentParams644=== RUN TestGCTaskStore_GetEmpty645=== PAUSE TestGCTaskStore_GetEmpty646=== RUN TestGCTaskStore_GetReturnsLatest647=== PAUSE TestGCTaskStore_GetReturnsLatest648=== RUN TestGCTaskStore_CompletedAllowsNewTask649=== PAUSE TestGCTaskStore_CompletedAllowsNewTask650=== RUN TestGCTaskStore_PhaseUpdates651=== PAUSE TestGCTaskStore_PhaseUpdates652=== RUN TestGCTaskStore_Fail653=== PAUSE TestGCTaskStore_Fail654=== RUN TestGracefulShutdownDrainsInflight655=== PAUSE TestGracefulShutdownDrainsInflight656=== RUN TestService_healthCheckHandler657=== PAUSE TestService_healthCheckHandler658=== RUN TestService_readinessHandler659=== PAUSE TestService_readinessHandler660=== RUN TestGenerateLandingPage661=== PAUSE TestGenerateLandingPage662=== RUN TestCacheConfigHandlerMaxNarSize663=== PAUSE TestCacheConfigHandlerMaxNarSize664=== RUN TestCreatePendingClosureRejectsOversizedNAR665=== PAUSE TestCreatePendingClosureRejectsOversizedNAR666=== RUN TestNARDeduplicationMetadataUploadBug667=== PAUSE TestNARDeduplicationMetadataUploadBug668=== RUN TestMetricsInventory669=== PAUSE TestMetricsInventory670=== RUN TestService_NativeMTLS671=== PAUSE TestService_NativeMTLS672=== RUN TestServerTLSConfig673=== PAUSE TestServerTLSConfig674=== RUN TestMultipartCleanup675=== PAUSE TestMultipartCleanup676=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded677=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded678=== RUN TestPendingCleanupUsesOneCutoff679=== PAUSE TestPendingCleanupUsesOneCutoff680=== RUN TestPendingClosureFailureTracksEveryUpload681=== PAUSE TestPendingClosureFailureTracksEveryUpload682=== RUN TestPendingClosureFailureAbortsItsUploads683=== PAUSE TestPendingClosureFailureAbortsItsUploads684=== RUN TestObjectStatsTrigger685=== PAUSE TestObjectStatsTrigger686=== RUN TestReconnectLeavesObjectsUnlocked687=== PAUSE TestReconnectLeavesObjectsUnlocked688=== RUN TestValidateS3Concurrency689=== PAUSE TestValidateS3Concurrency690=== RUN TestOrphanedObjectsGC691=== PAUSE TestOrphanedObjectsGC692=== RUN TestOrphanedObjectsGCStressTest693=== PAUSE TestOrphanedObjectsGCStressTest694=== RUN TestCreatePin_ReservedPins695=== PAUSE TestCreatePin_ReservedPins696=== RUN TestConcurrentPinUpdatesAgree697=== PAUSE TestConcurrentPinUpdatesAgree698=== RUN TestCreatePinRejectsBadInput699=== PAUSE TestCreatePinRejectsBadInput700=== RUN TestDeletePinKeepsRowWhenS3Fails701=== PAUSE TestDeletePinKeepsRowWhenS3Fails702=== RUN TestPresentReportsOnlyClosureRoots703=== PAUSE TestPresentReportsOnlyClosureRoots704=== RUN TestPresentNotReportedWhileGCDeletesClosure705=== PAUSE TestPresentNotReportedWhileGCDeletesClosure706=== RUN TestParseSingleRange707=== PAUSE TestParseSingleRange708=== RUN TestProxyHeadersOnlyTrustedOnSocket709=== PAUSE TestProxyHeadersOnlyTrustedOnSocket710=== RUN TestIsValidCachePath711=== PAUSE TestIsValidCachePath712=== RUN TestReadProxyNarinfo713=== PAUSE TestReadProxyNarinfo714=== RUN TestReadProxyNarinfoAlreadyDecompressed715=== PAUSE TestReadProxyNarinfoAlreadyDecompressed716=== RUN TestReadProxyNarStreaming717=== PAUSE TestReadProxyNarStreaming718=== RUN TestReadProxy404719=== PAUSE TestReadProxy404720=== RUN TestReadProxyInvalidPath721=== PAUSE TestReadProxyInvalidPath722=== RUN TestReadProxyHead723=== PAUSE TestReadProxyHead724=== RUN TestReadProxyOutlastsServerWriteTimeout725=== PAUSE TestReadProxyOutlastsServerWriteTimeout726=== RUN TestReadProxyConditionalGet727=== PAUSE TestReadProxyConditionalGet728=== RUN TestReadProxyRootRedirectsToIndexHTML729=== PAUSE TestReadProxyRootRedirectsToIndexHTML730=== RUN TestReadProxyDisabled731=== PAUSE TestReadProxyDisabled732=== RUN TestReadRedirectNar733=== PAUSE TestReadRedirectNar734=== RUN TestReadRedirectKeepsNarinfoProxied735=== PAUSE TestReadRedirectKeepsNarinfoProxied736=== RUN TestReadProxyRangeRequest737=== PAUSE TestReadProxyRangeRequest738=== RUN TestReadRedirectUsesPublicS3URL739=== PAUSE TestReadRedirectUsesPublicS3URL740=== RUN TestPush_OverlappingRootsStoreOneRowPerKey741=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey742=== RUN TestPush_CompleteCommitsEveryRoot743=== PAUSE TestPush_CompleteCommitsEveryRoot744=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit745=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit746=== RUN TestPush_RejectsBadRequests747=== PAUSE TestPush_RejectsBadRequests748=== RUN TestPush_SignsNarinfosOfItsPendingObjects749=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects750=== RUN TestRedundantMultipartUpload751=== PAUSE TestRedundantMultipartUpload752=== RUN TestCompleteMultipartUpload_ErrorButObjectExists753=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists754=== RUN TestCompletedNarNotReofferedAcrossClosures755=== PAUSE TestCompletedNarNotReofferedAcrossClosures756=== RUN TestPresignedUploadRegisteredBeforeCommit757=== PAUSE TestPresignedUploadRegisteredBeforeCommit758=== RUN TestService_Rustfstest759=== PAUSE TestService_Rustfstest760=== RUN TestParseSize761=== PAUSE TestParseSize762=== RUN TestSkippedUploadsHandler763=== PAUSE TestSkippedUploadsHandler764=== RUN TestSystemdListenerNotActivated765--- PASS: TestSystemdListenerNotActivated (0.00s)766=== RUN TestWatchdogBeatsWhenHealthy767--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)768=== RUN TestWatchdogSkipsWhenUnhealthy7692026/10/01 09:22:17 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7702026/10/01 09:22:17 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7712026/10/01 09:22:17 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7722026/10/01 09:22:18 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7732026/10/01 09:22:18 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7742026/10/01 09:22:18 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7752026/10/01 09:22:18 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7762026/10/01 09:22:18 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7772026/10/01 09:22:18 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7782026/10/01 09:22:18 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"779--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)780=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle781=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle782=== RUN TestProxyWriteTimeout783=== PAUSE TestProxyWriteTimeout784=== RUN TestPendingClosureWriteTimeout785=== PAUSE TestPendingClosureWriteTimeout786=== RUN TestIsValidUploadKey787=== PAUSE TestIsValidUploadKey788=== RUN TestUploadHandlersRejectInvalidKeys789=== PAUSE TestUploadHandlersRejectInvalidKeys790=== RUN TestUploadHandlersRejectOversizedBody791=== PAUSE TestUploadHandlersRejectOversizedBody792=== RUN TestService_cleanupPendingClosuresHandler793=== PAUSE TestService_cleanupPendingClosuresHandler794=== RUN TestService_createPendingClosureHandler795=== PAUSE TestService_createPendingClosureHandler796=== RUN TestService_verifyS3Integrity797=== PAUSE TestService_verifyS3Integrity798=== RUN TestCompleteMultipartUnregistered799=== PAUSE TestCompleteMultipartUnregistered800=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT801=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT802=== CONT TestReadProxyNarinfo803=== CONT TestService_AuthMiddleware804=== CONT TestIsValidCachePath805=== RUN TestIsValidCachePath/narinfo806=== CONT TestReadProxyNarStreaming807=== CONT TestParseSingleRange808=== CONT TestProxyHeadersOnlyTrustedOnSocket809=== CONT TestPresentNotReportedWhileGCDeletesClosure810=== CONT TestPresentReportsOnlyClosureRoots811=== CONT TestCreatePinRejectsBadInput812=== CONT TestConcurrentPinUpdatesAgree813=== CONT TestDeletePinKeepsRowWhenS3Fails814=== CONT TestOrphanedObjectsGCStressTest815=== CONT TestOrphanedObjectsGC816=== CONT TestValidateS3Concurrency817=== CONT TestReconnectLeavesObjectsUnlocked818=== CONT TestObjectStatsTrigger819=== CONT TestPendingClosureFailureAbortsItsUploads820=== CONT TestCreatePin_ReservedPins821=== CONT TestPendingCleanupUsesOneCutoff822=== CONT TestPendingClosureFailureTracksEveryUpload823=== CONT TestServerTLSConfig824=== CONT TestService_NativeMTLS825=== CONT TestRedundantMultipartUpload826=== CONT TestMultipartCleanup827=== PAUSE TestIsValidCachePath/narinfo828=== RUN TestParseSingleRange/none829--- PASS: TestValidateS3Concurrency (0.00s)830=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT831=== RUN TestServerTLSConfig/no_client_CA832=== PAUSE TestServerTLSConfig/no_client_CA833=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars834=== PAUSE TestParseSingleRange/none835=== RUN TestServerTLSConfig/missing_CA_file836=== RUN TestParseSingleRange/unknown_unit837=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars838=== PAUSE TestServerTLSConfig/missing_CA_file839=== PAUSE TestParseSingleRange/unknown_unit840=== RUN TestServerTLSConfig/not_a_PEM_file841=== RUN TestParseSingleRange/multi-range_ignored842=== PAUSE TestParseSingleRange/multi-range_ignored843=== RUN TestParseSingleRange/malformed_no_dash844=== PAUSE TestParseSingleRange/malformed_no_dash845=== RUN TestParseSingleRange/malformed_both_empty846=== RUN TestIsValidCachePath/nar_zst847=== PAUSE TestIsValidCachePath/nar_zst848=== PAUSE TestServerTLSConfig/not_a_PEM_file849=== PAUSE TestParseSingleRange/malformed_both_empty850=== CONT TestCreatePendingClosureRejectsOversizedNAR851=== RUN TestIsValidCachePath/nar_xz852=== RUN TestParseSingleRange/malformed_end_before_start853=== PAUSE TestParseSingleRange/malformed_end_before_start854=== RUN TestParseSingleRange/closed855=== PAUSE TestIsValidCachePath/nar_xz856=== PAUSE TestParseSingleRange/closed8572026/10/01 09:22:18 INFO Received uploads request method=POST path=/api/pending_closures858=== RUN TestParseSingleRange/open-ended859=== RUN TestIsValidCachePath/nar_bz2860=== PAUSE TestIsValidCachePath/nar_bz2861=== PAUSE TestParseSingleRange/open-ended862=== RUN TestParseSingleRange/end_clamped_to_size863=== RUN TestIsValidCachePath/nar_uncompressed864=== PAUSE TestParseSingleRange/end_clamped_to_size865=== RUN TestParseSingleRange/suffix866=== PAUSE TestIsValidCachePath/nar_uncompressed867=== PAUSE TestParseSingleRange/suffix868=== RUN TestIsValidCachePath/ls869=== RUN TestParseSingleRange/suffix_exceeds_size870=== PAUSE TestIsValidCachePath/ls871=== PAUSE TestParseSingleRange/suffix_exceeds_size872=== RUN TestIsValidCachePath/log873=== RUN TestParseSingleRange/single_byte874--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)875=== CONT TestNARDeduplicationMetadataUploadBug876=== PAUSE TestIsValidCachePath/log877=== PAUSE TestParseSingleRange/single_byte878=== RUN TestIsValidCachePath/realisation879=== RUN TestParseSingleRange/start_past_EOF880=== PAUSE TestIsValidCachePath/realisation881=== RUN TestIsValidCachePath/nix-cache-info882=== PAUSE TestParseSingleRange/start_past_EOF883=== PAUSE TestIsValidCachePath/nix-cache-info884=== RUN TestParseSingleRange/start_far_past_EOF885=== RUN TestIsValidCachePath/index.html886=== PAUSE TestParseSingleRange/start_far_past_EOF887=== PAUSE TestIsValidCachePath/index.html888=== CONT TestGenerateLandingPage889=== RUN TestIsValidCachePath/traversal_parent890=== PAUSE TestIsValidCachePath/traversal_parent891=== RUN TestIsValidCachePath/traversal_in_middle892=== PAUSE TestIsValidCachePath/traversal_in_middle893=== RUN TestIsValidCachePath/invalid_char_e894=== PAUSE TestIsValidCachePath/invalid_char_e895=== RUN TestIsValidCachePath/invalid_char_u896=== PAUSE TestIsValidCachePath/invalid_char_u897=== RUN TestIsValidCachePath/random_path898=== PAUSE TestIsValidCachePath/random_path899=== RUN TestIsValidCachePath/empty900=== PAUSE TestIsValidCachePath/empty901=== RUN TestIsValidCachePath/leading_slash902=== PAUSE TestIsValidCachePath/leading_slash903=== RUN TestIsValidCachePath/wrong_extension904=== PAUSE TestIsValidCachePath/wrong_extension905=== RUN TestIsValidCachePath/short_hash906=== PAUSE TestIsValidCachePath/short_hash907=== CONT TestService_readinessHandler908--- PASS: TestGenerateLandingPage (0.01s)909=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle9102026/10/01 09:22:18 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:36583/oidc9112026/10/01 09:22:18 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"912--- PASS: TestService_AuthMiddleware (0.49s)913=== CONT TestGracefulShutdownDrainsInflight9142026/10/01 09:22:18 INFO Starting HTTP server address=127.0.0.1:335639152026/10/01 09:22:18 INFO Shutdown signal received, draining in-flight requests timeout=10s916=== CONT TestService_healthCheckHandler917--- PASS: TestReadProxyNarStreaming (0.56s)918=== CONT TestGCTaskStore_Fail919--- PASS: TestGracefulShutdownDrainsInflight (0.07s)920=== CONT TestMetricsInventory921--- PASS: TestGCTaskStore_Fail (0.00s)922--- PASS: TestObjectStatsTrigger (0.57s)923=== CONT TestGCTaskStore_GetReturnsLatest924--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)925=== CONT TestService_Rustfstest9262026/10/01 09:22:18 INFO Received create pin request method=POST path=/api/pins/app9272026/10/01 09:22:18 INFO Received create pin request method=POST path=/api/pins/app9282026/10/01 09:22:18 INFO Starting HTTP server address=127.0.0.1:352699292026/10/01 09:22:18 INFO Starting HTTP server address=/build/TestProxyHeadersOnlyTrustedOnSocket719160245/001/proxy.sock9302026/10/01 09:22:18 WARN mTLS auth: subject not in bound subjects subject="CN=someone"9312026/10/01 09:22:18 INFO Shutdown signal received, draining in-flight requests timeout=10s932=== CONT TestGCTaskStore_GetEmpty933--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.65s)934=== CONT TestCompletedNarNotReofferedAcrossClosures935--- PASS: TestGCTaskStore_GetEmpty (0.00s)9362026/10/01 09:22:18 INFO Received uploads request method=POST path=/api/pending_closures9372026/10/01 09:22:18 INFO Received create pin request method=POST path=/api/pins/deploy9382026/10/01 09:22:18 INFO Received create pin request method=POST path=/api/pins/deploy9392026/10/01 09:22:18 INFO Received create pin request method=POST path=/api/pins/deploy9402026/10/01 09:22:18 INFO Received create pin request method=POST path=/api/pins/deploy9412026/10/01 09:22:18 INFO Received create pin request method=POST path=/api/pins/deploy9422026/10/01 09:22:18 INFO Received create pin request method=POST path=/api/pins/deploy9432026/10/01 09:22:18 INFO Received create pin request method=POST path=/api/pins/deploy9442026/10/01 09:22:18 INFO Received create pin request method=POST path=/api/pins/deploy9452026/10/01 09:22:18 INFO Received create pin request method=POST path=/api/pins/app9462026/10/01 09:22:18 INFO Created/updated pin name=app store_path=/nix/store/cccccccccccccccccccccccccccccccc-app narinfo_key=cccccccccccccccccccccccccccccccc.narinfo9472026/10/01 09:22:18 INFO Received delete pin request method=DELETE path=/api/pins/app9482026/10/01 09:22:18 ERROR Failed to delete pin from S3 key=pins/app error="Get \"http://127.0.0.1:1/bucket14/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"9492026/10/01 09:22:18 INFO Received delete pin request method=DELETE path=/api/pins/app9502026/10/01 09:22:18 INFO Deleted pin name=app951=== NAME TestOrphanedObjectsGC952 orphaned_objects_gc_test.go:290: GC Test Summary:953 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A954 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B955 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)956 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)957 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects958--- PASS: TestPresentReportsOnlyClosureRoots (0.79s)959=== CONT TestService_verifyS3Integrity960=== CONT TestGCEndsOnShutdown961--- PASS: TestDeletePinKeepsRowWhenS3Fails (0.79s)962=== RUN TestGCEndsOnShutdown/before_the_run963=== PAUSE TestGCEndsOnShutdown/before_the_run964=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete965=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete966=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark967=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark968=== CONT TestCompleteMultipartUnregistered9692026/10/01 09:22:18 INFO Received create pin request method=POST path=/api/pins/deploy970--- PASS: TestOrphanedObjectsGC (0.81s)971=== CONT TestCompleteMultipartUpload_ErrorButObjectExists9722026/10/01 09:22:18 WARN readiness check failed error="closed pool"973--- PASS: TestReconnectLeavesObjectsUnlocked (0.83s)974=== CONT TestGetExistingObjectsLocksRows975--- PASS: TestService_readinessHandler (0.83s)976=== CONT TestPush_SignsNarinfosOfItsPendingObjects9772026/10/01 09:22:18 WARN mTLS auth: subject not in bound subjects subject="CN=reader"9782026/10/01 09:22:18 WARN mTLS auth: subject not in bound subjects subject="CN=reader"9792026/10/01 09:22:19 ERROR Failed to decompress narinfo error="decompressed size exceeds configured limit"980--- PASS: TestService_NativeMTLS (0.87s)981=== CONT TestSweepSkipsRowsLockedByPush9822026/10/01 09:22:19 INFO Received uploads request method=POST path=/api/pending_closures9832026/10/01 09:22:19 INFO Received uploads request method=POST path=/api/pending_closures9842026/10/01 09:22:19 INFO Received uploads request method=POST path=/api/pending_closures9852026/10/01 09:22:19 INFO Received cleanup request method=DELETE path=/api/pending_closures986=== NAME TestNARDeduplicationMetadataUploadBug987 metadata_upload_test.go:48: First store path: /build/TestNARDeduplicationMetadataUploadBug93386866/001/store/00i9p04fwrwa37b1y69hl5zpnfmhz13d-file1.txt9882026/10/01 09:22:19 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux9892026/10/01 09:22:19 WARN Refused reserved pin name=worker-x86_64-linux9902026/10/01 09:22:19 INFO Received uploads request method=POST path=/api/pending_closures9912026/10/01 09:22:19 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux9922026/10/01 09:22:19 INFO Received create pin request method=POST path=/api/pins/my-app9932026/10/01 09:22:19 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux9942026/10/01 09:22:19 INFO Received uploads request method=POST path=/api/pending_closures995--- PASS: TestCreatePin_ReservedPins (1.03s)996=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit9972026/10/01 09:22:19 INFO Received uploads request method=POST path=/api/pending_closures9982026/10/01 09:22:19 INFO Received uploads request method=POST path=/api/pending_closures9992026/10/01 09:22:19 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1000--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (1.07s)1001=== CONT TestReadProxyRangeRequest10022026/10/01 09:22:19 INFO Received push request method=POST path=/api/pushes10032026/10/01 09:22:19 INFO Created/updated pin name=app store_path=/nix/store/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa-app narinfo_key=aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.narinfo10042026/10/01 09:22:19 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)10052026/10/01 09:22:19 INFO Received uploads request method=POST path=/api/pending_closures10062026/10/01 09:22:19 INFO Uploading 00i9p04fwrwa37b1y69hl5zpnfmhz13d-file1.txt (160B)10072026/10/01 09:22:19 INFO Created/updated pin name=app store_path=/nix/store/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb-app narinfo_key=bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb.narinfo10082026/10/01 09:22:19 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"10092026/10/01 09:22:19 WARN Failed to register uploaded object key=00i9p04fwrwa37b1y69hl5zpnfmhz13d.ls error="server returned 404: 404 page not found\n"10102026/10/01 09:22:19 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10112026/10/01 09:22:19 INFO Signed narinfos id=1 count=110122026/10/01 09:22:19 INFO Uploading 1 narinfos1013--- PASS: TestPendingClosureFailureAbortsItsUploads (1.12s)1014=== CONT TestGCAdvisoryLockBlocksConcurrentRun1015=== CONT TestCacheConfigHandler1016--- PASS: TestConcurrentPinUpdatesAgree (1.13s)1017=== RUN TestCacheConfigHandler/full_config,_no_issuer1018=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1019=== RUN TestCacheConfigHandler/no_cache_url_configured1020=== PAUSE TestCacheConfigHandler/no_cache_url_configured1021=== RUN TestCacheConfigHandler/no_signing_keys1022=== PAUSE TestCacheConfigHandler/no_signing_keys1023=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1024=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1025--- PASS: TestPresentNotReportedWhileGCDeletesClosure (1.14s)1026=== CONT TestClientFallsBackToClosures1027=== CONT TestLeadElectsOneAndHandsOver10282026/10/01 09:22:19 INFO Received complete push request method=POST path=/api/pushes/1/complete10292026/10/01 09:22:19 WARN Failed to register uploaded object key=00i9p04fwrwa37b1y69hl5zpnfmhz13d.narinfo error="server returned 404: 404 page not found\n"10302026/10/01 09:22:19 INFO Upload complete. (127ms)1031=== NAME TestNARDeduplicationMetadataUploadBug1032 metadata_upload_test.go:54: Retrieved narinfo from S3:1033 StorePath: /build/TestNARDeduplicationMetadataUploadBug93386866/001/store/00i9p04fwrwa37b1y69hl5zpnfmhz13d-file1.txt1034 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1035 Compression: zstd1036 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1037 NarSize: 1601038 References: 1039 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1040 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1041 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1042 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}1043=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock1044--- PASS: TestService_Rustfstest (0.61s)1045--- PASS: TestPendingClosureFailureTracksEveryUpload (1.21s)1046--- PASS: TestService_healthCheckHandler (0.65s)1047=== CONT TestReadProxyOutlastsServerWriteTimeout1048=== CONT TestClientPushesUseOnePush1049=== NAME TestNARDeduplicationMetadataUploadBug1050 metadata_upload_test.go:64: Second store path (same content): /build/TestNARDeduplicationMetadataUploadBug93386866/001/store/5kbdz1vlbz1wqawbr6aq15sg2smix11a-file2.txt10512026/10/01 09:22:19 INFO Received cleanup request method=DELETE path=/api/pending_closures10522026/10/01 09:22:19 INFO Received uploads request method=POST path=/api/pending_closures10532026/10/01 09:22:19 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket26/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""10542026/10/01 09:22:19 INFO Aborted multipart uploads count=0 kept=110552026/10/01 09:22:19 INFO Received cleanup request method=DELETE path=/api/pending_closures10562026/10/01 09:22:19 INFO Aborted multipart uploads count=1 kept=010572026/10/01 09:22:19 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10582026/10/01 09:22:19 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst1059=== CONT TestProxyWriteTimeout1060--- PASS: TestCompleteMultipartUnregistered (0.48s)1061=== RUN TestProxyWriteTimeout/narinfo1062=== PAUSE TestProxyWriteTimeout/narinfo1063=== RUN TestProxyWriteTimeout/1_GiB_nar1064=== PAUSE TestProxyWriteTimeout/1_GiB_nar1065=== RUN TestProxyWriteTimeout/10_GiB_nar1066=== PAUSE TestProxyWriteTimeout/10_GiB_nar1067=== RUN TestProxyWriteTimeout/unknown_size1068=== PAUSE TestProxyWriteTimeout/unknown_size1069=== CONT TestGCTaskStore_CompletedAllowsNewTask1070=== CONT TestParseSize1071--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1072--- PASS: TestParseSize (0.00s)1073=== CONT TestGCTaskStore_ConflictDifferentParams1074--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1075=== CONT TestPresignedUploadRegisteredBeforeCommit1076--- PASS: TestMultipartCleanup (1.28s)1077=== CONT TestSkippedUploadsHandler1078--- PASS: TestMetricsInventory (0.72s)1079=== CONT TestGCTaskStore_DeduplicateSameParams1080=== CONT TestGCTaskStore_StartNew1081=== CONT TestService_createPendingClosureHandler1082--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1083--- PASS: TestGCTaskStore_StartNew (0.00s)10842026/10/01 09:22:19 INFO Received push request method=POST path=/api/pushes10852026/10/01 09:22:19 INFO Client skipped oversized paths paths=3 nar_bytes=500000000010862026/10/01 09:22:19 INFO Received uploads request method=POST path=/api/pending_closures10872026/10/01 09:22:19 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)10882026/10/01 09:22:19 INFO Received uploads request method=POST path=/api/pending_closures10892026/10/01 09:22:19 WARN Failed to register uploaded object key=5kbdz1vlbz1wqawbr6aq15sg2smix11a.ls error="server returned 404: 404 page not found\n"10902026/10/01 09:22:19 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign10912026/10/01 09:22:19 INFO Signed narinfos id=2 count=110922026/10/01 09:22:19 INFO Uploading 1 narinfos10932026/10/01 09:22:19 ERROR Refusing narinfo larger than the limit key=5hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=1677721610942026/10/01 09:22:19 INFO Received complete push request method=POST path=/api/pushes/2/complete10952026/10/01 09:22:19 WARN Failed to register uploaded object key=5kbdz1vlbz1wqawbr6aq15sg2smix11a.narinfo error="server returned 404: 404 page not found\n"10962026/10/01 09:22:19 INFO Upload complete. (193ms)1097--- PASS: TestSkippedUploadsHandler (0.17s)1098=== CONT TestCacheConfigHandlerMaxNarSize1099--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1100=== CONT TestUploadHandlersRejectOversizedBody1101=== NAME TestNARDeduplicationMetadataUploadBug1102 metadata_upload_test.go:76: Retrieved narinfo from S3:1103 StorePath: /build/TestNARDeduplicationMetadataUploadBug93386866/001/store/5kbdz1vlbz1wqawbr6aq15sg2smix11a-file2.txt1104 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1105 Compression: zstd1106 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1107 NarSize: 1601108 References: 1109 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf11102026/10/01 09:22:19 INFO Received push request method=POST path=/api/pushes1111 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1112 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1113 {"version":1,"root":{"type":"regular","size":44}}1114=== CONT TestPushWaitsForSweepHoldingRow1115--- PASS: TestReadProxyNarinfo (1.47s)11162026/10/01 09:22:19 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1117--- PASS: TestGetExistingObjectsLocksRows (0.65s)1118=== CONT TestCommitRacingPendingCleanupKeepsObjects11192026/10/01 09:22:19 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MmUwNWI5YmEtZDFkYS00ZmMyLWIxMzUtMzdiMzQ0YTZhNzZkLjcwYmFhMTkzLTFiNTYtNGViZi1hM2QxLWMzYjk5NDFiYWIzMngxNzkwODQ2NTM5NTU3OTQ1OTY111202026/10/01 09:22:19 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11212026/10/01 09:22:19 INFO Signed narinfos id=1 count=11122=== CONT TestSweepRechecksPendingAfterLocking1123--- PASS: TestNARDeduplicationMetadataUploadBug (1.49s)1124--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (0.68s)1125=== CONT TestGCTaskStore_PhaseUpdates1126--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1127=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded11282026/10/01 09:22:19 INFO Received push request method=POST path=/api/pushes11292026/10/01 09:22:19 INFO Aborted multipart uploads count=0 kept=011302026/10/01 09:22:19 WARN Force mode enabled - objects will be deleted immediately without grace period11312026/10/01 09:22:19 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=011322026/10/01 09:22:19 INFO Vacuumed table table=pending_closures11332026/10/01 09:22:19 INFO Vacuumed table table=pending_objects11342026/10/01 09:22:19 INFO Vacuumed table table=multipart_uploads11352026/10/01 09:22:19 INFO Vacuumed table table=closures11362026/10/01 09:22:19 INFO Vacuumed table table=objects11372026/10/01 09:22:19 INFO Aborted multipart uploads count=0 kept=011382026/10/01 09:22:19 WARN Force mode enabled - objects will be deleted immediately without grace period11392026/10/01 09:22:19 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=011402026/10/01 09:22:19 INFO Vacuumed table table=pending_closures11412026/10/01 09:22:19 INFO Vacuumed table table=pending_objects11422026/10/01 09:22:19 INFO Vacuumed table table=multipart_uploads11432026/10/01 09:22:19 INFO Vacuumed table table=closures11442026/10/01 09:22:19 INFO Vacuumed table table=objects1145=== CONT TestReadProxyDisabled1146--- PASS: TestReadProxyRangeRequest (0.52s)1147--- PASS: TestSweepSkipsRowsLockedByPush (0.74s)1148=== CONT TestReadRedirectUsesPublicS3URL11492026/10/01 09:22:19 INFO lead: acquired remote=192.0.2.1:123411502026/10/01 09:22:19 WARN Failed to abort multipart upload key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MmUwNWI5YmEtZDFkYS00ZmMyLWIxMzUtMzdiMzQ0YTZhNzZkLjcwYmFhMTkzLTFiNTYtNGViZi1hM2QxLWMzYjk5NDFiYWIzMngxNzkwODQ2NTM5NTU3OTQ1OTY1 error="Delete \"http://localhost:33885/bucket33/nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst?uploadId=MmUwNWI5YmEtZDFkYS00ZmMyLWIxMzUtMzdiMzQ0YTZhNzZkLjcwYmFhMTkzLTFiNTYtNGViZi1hM2QxLWMzYjk5NDFiYWIzMngxNzkwODQ2NTM5NTU3OTQ1OTY1\": injected: abort refused"11512026/10/01 09:22:19 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11522026/10/01 09:22:19 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MmUwNWI5YmEtZDFkYS00ZmMyLWIxMzUtMzdiMzQ0YTZhNzZkLjcwYmFhMTkzLTFiNTYtNGViZi1hM2QxLWMzYjk5NDFiYWIzMngxNzkwODQ2NTM5NTU3OTQ1OTY111532026/10/01 09:22:19 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MmUwNWI5YmEtZDFkYS00ZmMyLWIxMzUtMzdiMzQ0YTZhNzZkLjcwYmFhMTkzLTFiNTYtNGViZi1hM2QxLWMzYjk5NDFiYWIzMngxNzkwODQ2NTM5NTU3OTQ1OTY1 parts=11154--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (0.91s)1155=== CONT TestPush_OverlappingRootsStoreOneRowPerKey11562026/10/01 09:22:19 INFO Received uploads request method=POST path=/api/pending_closures11572026/10/01 09:22:19 INFO Received uploads request method=POST path=/api/pending_closures11582026/10/01 09:22:19 INFO Received uploads request method=POST path=/api/pending_closures11592026/10/01 09:22:19 INFO Received create pin request method=POST path=/api/pins/deploy11602026/10/01 09:22:19 INFO Created/updated pin name=deploy store_path="/nix/store/dddddddddddddddddddddddddddddddd-app-1.0+git_x?y=z" narinfo_key=dddddddddddddddddddddddddddddddd.narinfo11612026/10/01 09:22:19 INFO Received uploads request method=POST path=/api/pending_closures1162--- PASS: TestCreatePinRejectsBadInput (1.78s)1163=== CONT TestPush_RejectsBadRequests11642026/10/01 09:22:19 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst11652026/10/01 09:22:19 INFO Received uploads request method=POST path=/api/pending_closures1166--- PASS: TestPresignedUploadRegisteredBeforeCommit (0.54s)1167=== CONT TestFailedS3DeleteKeepsTombstone11682026/10/01 09:22:20 INFO Received uploads request method=POST path=/api/pending_closures11692026/10/01 09:22:20 INFO Received uploads request method=POST path=/api/pending_closures11702026/10/01 09:22:20 INFO Received uploads request method=POST path=/api/pending_closures11712026/10/01 09:22:20 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)11722026/10/01 09:22:20 INFO Uploading s655fs5ajyvqhg3qjsrk01hnxncqafpw-a (216B)11732026/10/01 09:22:20 INFO Uploading shd31q4bmcl1vzm6vada5vi8cyhacrnv-shared-dep (136B)11742026/10/01 09:22:20 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11752026/10/01 09:22:20 WARN Failed to register uploaded object key=q0g9s7gcl965a2wd0nv876adqs01yjcp.ls error="server returned 404: 404 page not found\n"11762026/10/01 09:22:20 WARN Failed to register uploaded object key=nar/16pm3v6i2imwm6d58y5bd7ilqz9jwxwv1705zdm5z7fz4sj0gzp5.nar.zst error="server returned 404: 404 page not found\n"11772026/10/01 09:22:20 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"11782026/10/01 09:22:20 INFO Aborted multipart uploads count=0 kept=011792026/10/01 09:22:20 WARN Force mode enabled - objects will be deleted immediately without grace period11802026/10/01 09:22:20 INFO Aborted multipart uploads count=0 kept=011812026/10/01 09:22:20 WARN Force mode enabled - objects will be deleted immediately without grace period11822026/10/01 09:22:20 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=011832026/10/01 09:22:20 WARN Failed to register uploaded object key=s655fs5ajyvqhg3qjsrk01hnxncqafpw.ls error="server returned 404: 404 page not found\n"11842026/10/01 09:22:20 INFO Vacuumed table table=pending_closures11852026/10/01 09:22:20 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=MmUwNWI5YmEtZDFkYS00ZmMyLWIxMzUtMzdiMzQ0YTZhNzZkLjM5MjhhMmQwLTUwM2EtNGM2ZS1iMTNjLWE4Yjc3OTUyM2Q3MngxNzkwODQ2NTM5MTU3NjQ3MDM2 parts=1211862026/10/01 09:22:20 INFO Vacuumed table table=pending_objects11872026/10/01 09:22:20 INFO Vacuumed table table=multipart_uploads11882026/10/01 09:22:20 INFO Received uploads request method=POST path=/api/pending_closures11892026/10/01 09:22:20 INFO Received uploads request method=POST path=/api/pending_closures11902026/10/01 09:22:20 INFO Vacuumed table table=closures11912026/10/01 09:22:20 INFO Vacuumed table table=objects11922026/10/01 09:22:20 WARN Failed to register uploaded object key=shd31q4bmcl1vzm6vada5vi8cyhacrnv.ls error="server returned 404: 404 page not found\n"11932026/10/01 09:22:20 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign11942026/10/01 09:22:20 INFO Signed narinfos id=2 count=211952026/10/01 09:22:20 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign11962026/10/01 09:22:20 INFO Signed narinfos id=1 count=211972026/10/01 09:22:20 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=011982026/10/01 09:22:20 INFO Uploading 4 narinfos11992026/10/01 09:22:20 INFO Vacuumed table table=pending_closures12002026/10/01 09:22:20 INFO Vacuumed table table=pending_objects12012026/10/01 09:22:20 INFO Vacuumed table table=multipart_uploads12022026/10/01 09:22:20 INFO Vacuumed table table=closures12032026/10/01 09:22:20 INFO Vacuumed table table=objects12042026/10/01 09:22:20 INFO Received uploads request method=POST path=/api/pending_closures12052026/10/01 09:22:20 WARN Failed to register uploaded object key=s655fs5ajyvqhg3qjsrk01hnxncqafpw.narinfo error="server returned 404: 404 page not found\n"12062026/10/01 09:22:20 WARN Failed to register uploaded object key=q0g9s7gcl965a2wd0nv876adqs01yjcp.narinfo error="server returned 404: 404 page not found\n"12072026/10/01 09:22:20 WARN Failed to register uploaded object key=shd31q4bmcl1vzm6vada5vi8cyhacrnv.narinfo error="server returned 404: 404 page not found\n"12082026/10/01 09:22:20 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12092026/10/01 09:22:20 WARN Failed to register uploaded object key=shd31q4bmcl1vzm6vada5vi8cyhacrnv.narinfo error="server returned 404: 404 page not found\n"1210=== CONT TestForceGCDuringPushOffersSweptObject1211--- PASS: TestCommitRacingPendingCleanupKeepsObjects (0.50s)1212=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows1213=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows1214=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check1215=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check1216=== CONT TestReadRedirectNar1217--- PASS: TestSweepRechecksPendingAfterLocking (0.48s)1218=== CONT TestRegisterCompletedObjectNeedsPendingRow12192026/10/01 09:22:20 INFO Completed upload id=112202026/10/01 09:22:20 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete12212026/10/01 09:22:20 INFO Completed upload id=212222026/10/01 09:22:20 INFO Upload complete. (167ms)1223=== CONT TestPush_CompleteCommitsEveryRoot1224--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (0.47s)1225=== NAME TestClientFallsBackToClosures1226 client_pushes_test.go:112: Retrieved narinfo from S3:1227 StorePath: /build/TestClientFallsBackToClosures3165019861/001/store/shd31q4bmcl1vzm6vada5vi8cyhacrnv-shared-dep1228 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1229 Compression: zstd1230 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821231 NarSize: 1361232 References: 1233 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1234=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection1235--- PASS: TestReadProxyDisabled (0.40s)1236=== NAME TestClientFallsBackToClosures1237 client_pushes_test.go:112: Retrieved narinfo from S3:1238 StorePath: /build/TestClientFallsBackToClosures3165019861/001/store/s655fs5ajyvqhg3qjsrk01hnxncqafpw-a1239 URL: nar/16pm3v6i2imwm6d58y5bd7ilqz9jwxwv1705zdm5z7fz4sj0gzp5.nar.zst1240 Compression: zstd1241 NarHash: sha256:16pm3v6i2imwm6d58y5bd7ilqz9jwxwv1705zdm5z7fz4sj0gzp51242 NarSize: 2161243 References: /build/TestClientFallsBackToClosures3165019861/001/store/shd31q4bmcl1vzm6vada5vi8cyhacrnv-shared-dep1244 CA: text:sha256:04alj0hm8n9j3grx314lys7rmy5war5l84p1sbkabgpn6c5jz1ip1245 client_pushes_test.go:112: Retrieved narinfo from S3:1246 StorePath: /build/TestClientFallsBackToClosures3165019861/001/store/q0g9s7gcl965a2wd0nv876adqs01yjcp-b1247 URL: nar/16pm3v6i2imwm6d58y5bd7ilqz9jwxwv1705zdm5z7fz4sj0gzp5.nar.zst1248 Compression: zstd1249 NarHash: sha256:16pm3v6i2imwm6d58y5bd7ilqz9jwxwv1705zdm5z7fz4sj0gzp51250 NarSize: 2161251 References: /build/TestClientFallsBackToClosures3165019861/001/store/shd31q4bmcl1vzm6vada5vi8cyhacrnv-shared-dep1252 CA: text:sha256:04alj0hm8n9j3grx314lys7rmy5war5l84p1sbkabgpn6c5jz1ip12532026/10/01 09:22:20 ERROR failed to check GC advisory lock error="query pg_locks: failed to connect to `user=nixbld database=niks3`: /nonexistent/.s.PGSQL.5432 (/nonexistent): dial error: dial unix /nonexistent/.s.PGSQL.5432: connect: no such file or directory"12542026/10/01 09:22:20 INFO Received push request method=POST path=/api/pushes12552026/10/01 09:22:20 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)12562026/10/01 09:22:20 INFO Uploading kr4pcafnqfrqqsggllvfrn17wmy71pfd-shared-dep (136B)12572026/10/01 09:22:20 INFO Uploading hv76j71b770zwy4rl6kb5yc0z7gsb6h7-a (208B)12582026/10/01 09:22:20 WARN Failed to register uploaded object key=nar/14dv6jakd6k6yd7ibby6clzm56mx9d8v4c2ghvz9yimp76zh330z.nar.zst error="server returned 404: 404 page not found\n"12592026/10/01 09:22:20 WARN Failed to register uploaded object key=hv76j71b770zwy4rl6kb5yc0z7gsb6h7.ls error="server returned 404: 404 page not found\n"12602026/10/01 09:22:20 WARN Failed to register uploaded object key=kr4pcafnqfrqqsggllvfrn17wmy71pfd.ls error="server returned 404: 404 page not found\n"12612026/10/01 09:22:20 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"1262--- PASS: TestClientFallsBackToClosures (0.91s)1263=== CONT TestUploadHandlersRejectInvalidKeys1264=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1265=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1266=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1267=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1268=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1269=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1270=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1271=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1272=== CONT TestService_cleanupPendingClosuresHandler12732026/10/01 09:22:20 WARN Failed to register uploaded object key=s516c9n4wi6iwlrkg0rpkp4smpym5m5k.ls error="server returned 404: 404 page not found\n"12742026/10/01 09:22:20 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12752026/10/01 09:22:20 INFO Signed narinfos id=1 count=312762026/10/01 09:22:20 INFO Uploading 3 narinfos1277=== CONT TestIsValidUploadKey1278=== RUN TestIsValidUploadKey/narinfo1279=== PAUSE TestIsValidUploadKey/narinfo1280--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.93s)1281=== RUN TestIsValidUploadKey/nar_zst1282=== PAUSE TestIsValidUploadKey/nar_zst1283=== RUN TestIsValidUploadKey/nar_xz1284=== PAUSE TestIsValidUploadKey/nar_xz1285=== RUN TestIsValidUploadKey/nar_plain1286=== PAUSE TestIsValidUploadKey/nar_plain1287=== RUN TestIsValidUploadKey/listing1288=== PAUSE TestIsValidUploadKey/listing1289=== RUN TestIsValidUploadKey/build_log1290=== PAUSE TestIsValidUploadKey/build_log1291=== RUN TestIsValidUploadKey/build_log_home-manager_file1292=== PAUSE TestIsValidUploadKey/build_log_home-manager_file1293=== RUN TestIsValidUploadKey/build_log_plus_in_name1294=== PAUSE TestIsValidUploadKey/build_log_plus_in_name1295=== RUN TestIsValidUploadKey/build_log_question_mark1296=== PAUSE TestIsValidUploadKey/build_log_question_mark1297=== RUN TestIsValidUploadKey/build_log_equals1298=== PAUSE TestIsValidUploadKey/build_log_equals12992026/10/01 09:22:20 WARN Failed to register uploaded object key=hv76j71b770zwy4rl6kb5yc0z7gsb6h7.narinfo error="server returned 404: 404 page not found\n"1300=== RUN TestIsValidUploadKey/realisation1301=== PAUSE TestIsValidUploadKey/realisation1302=== RUN TestIsValidUploadKey/realisation_plus_in_output1303=== PAUSE TestIsValidUploadKey/realisation_plus_in_output1304=== RUN TestIsValidUploadKey/nix-cache-info13052026/10/01 09:22:20 WARN Failed to register uploaded object key=s516c9n4wi6iwlrkg0rpkp4smpym5m5k.narinfo error="server returned 404: 404 page not found\n"1306=== PAUSE TestIsValidUploadKey/nix-cache-info1307=== RUN TestIsValidUploadKey/index.html1308=== PAUSE TestIsValidUploadKey/index.html1309=== RUN TestIsValidUploadKey/narinfo_key,_nar_type1310=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type1311=== RUN TestIsValidUploadKey/nar_key,_narinfo_type1312=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type1313=== RUN TestIsValidUploadKey/listing_key,_narinfo_type1314=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type1315=== RUN TestIsValidUploadKey/traversal1316=== PAUSE TestIsValidUploadKey/traversal1317=== RUN TestIsValidUploadKey/traversal_nar1318=== PAUSE TestIsValidUploadKey/traversal_nar1319=== RUN TestIsValidUploadKey/absolute1320=== PAUSE TestIsValidUploadKey/absolute1321=== RUN TestIsValidUploadKey/empty_key1322=== PAUSE TestIsValidUploadKey/empty_key1323=== RUN TestIsValidUploadKey/unknown_type1324=== PAUSE TestIsValidUploadKey/unknown_type1325=== CONT TestTombstonedObjectOfferedWithoutWaiting13262026/10/01 09:22:20 INFO Received complete push request method=POST path=/api/pushes/1/complete13272026/10/01 09:22:20 INFO Received push request method=POST path=/api/pushes13282026/10/01 09:22:20 WARN Failed to register uploaded object key=kr4pcafnqfrqqsggllvfrn17wmy71pfd.narinfo error="server returned 404: 404 page not found\n"13292026/10/01 09:22:20 INFO Upload complete. (109ms)1330=== NAME TestClientPushesUseOnePush1331 client_pushes_test.go:97: Retrieved narinfo from S3:1332 StorePath: /build/TestClientPushesUseOnePush930425267/001/store/kr4pcafnqfrqqsggllvfrn17wmy71pfd-shared-dep1333 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1334 Compression: zstd1335 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821336 NarSize: 1361337 References: 1338 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n13392026/10/01 09:22:20 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1340 client_pushes_test.go:97: Retrieved narinfo from S3:1341 StorePath: /build/TestClientPushesUseOnePush930425267/001/store/hv76j71b770zwy4rl6kb5yc0z7gsb6h7-a1342 URL: nar/14dv6jakd6k6yd7ibby6clzm56mx9d8v4c2ghvz9yimp76zh330z.nar.zst1343 Compression: zstd1344 NarHash: sha256:14dv6jakd6k6yd7ibby6clzm56mx9d8v4c2ghvz9yimp76zh330z1345 NarSize: 2081346 References: /build/TestClientPushesUseOnePush930425267/001/store/kr4pcafnqfrqqsggllvfrn17wmy71pfd-shared-dep1347 CA: text:sha256:1136lm7nlmhd646f0caz7x49cvnhss2k2risajmmisrsw8p3rdap1348 client_pushes_test.go:97: Retrieved narinfo from S3:1349 StorePath: /build/TestClientPushesUseOnePush930425267/001/store/s516c9n4wi6iwlrkg0rpkp4smpym5m5k-b1350 URL: nar/14dv6jakd6k6yd7ibby6clzm56mx9d8v4c2ghvz9yimp76zh330z.nar.zst1351 Compression: zstd1352 NarHash: sha256:14dv6jakd6k6yd7ibby6clzm56mx9d8v4c2ghvz9yimp76zh330z1353 NarSize: 2081354 References: /build/TestClientPushesUseOnePush930425267/001/store/kr4pcafnqfrqqsggllvfrn17wmy71pfd-shared-dep1355 CA: text:sha256:1136lm7nlmhd646f0caz7x49cvnhss2k2risajmmisrsw8p3rdap1356=== RUN TestPush_RejectsBadRequests/no_roots1357=== PAUSE TestPush_RejectsBadRequests/no_roots1358=== RUN TestPush_RejectsBadRequests/no_objects1359=== PAUSE TestPush_RejectsBadRequests/no_objects1360=== RUN TestPush_RejectsBadRequests/bad_root1361=== PAUSE TestPush_RejectsBadRequests/bad_root1362=== RUN TestPush_RejectsBadRequests/root_not_in_objects1363=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1364=== CONT TestGCMetrics13652026/10/01 09:22:20 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=MmUwNWI5YmEtZDFkYS00ZmMyLWIxMzUtMzdiMzQ0YTZhNzZkLjUxYTg1ZDYwLWFkMGYtNGQyMS1iZTZjLTE1OWI5NTJhMzA5YngxNzkwODQ2NTM5NDc5ODkwMDk3 parts=1013662026/10/01 09:22:20 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13672026/10/01 09:22:20 INFO Completed upload id=113682026/10/01 09:22:20 INFO Received uploads request method=POST path=/api/pending_closures13692026/10/01 09:22:20 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1370--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (0.41s)1371=== CONT TestPinProtectsFromGC13722026/10/01 09:22:20 INFO Received uploads request method=POST path=/api/pending_closures13732026/10/01 09:22:20 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1374--- PASS: TestClientPushesUseOnePush (0.95s)1375=== CONT TestClientSharedPathCommittedMidPush13762026/10/01 09:22:20 INFO Received uploads request method=POST path=/api/pending_closures13772026/10/01 09:22:20 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo13782026/10/01 09:22:20 WARN Found objects in DB but missing from S3, will re-upload count=113792026/10/01 09:22:20 INFO Received complete upload request method=POST path=/api/pending_closures/3/complete13802026/10/01 09:22:20 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=MmUwNWI5YmEtZDFkYS00ZmMyLWIxMzUtMzdiMzQ0YTZhNzZkLjZmMGY0NWFlLTJjODMtNGM5ZS1hYTI0LTgxZjQyZjgyOTJkNngxNzkwODQ2NTM5Mzc5ODAxNTk1 parts=1213812026/10/01 09:22:20 INFO Received uploads request method=POST path=/api/pending_closures13822026/10/01 09:22:20 INFO Completed upload id=31383=== CONT TestGCSweepSkipsPendingObjects1384--- PASS: TestReadRedirectUsesPublicS3URL (0.57s)13852026/10/01 09:22:20 INFO Completed multipart upload object_key=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa00000000000000000000.nar.zst upload_id=MmUwNWI5YmEtZDFkYS00ZmMyLWIxMzUtMzdiMzQ0YTZhNzZkLjYzZTIzZGI0LTUxY2MtNDU5Zi1iYmE5LWFjMWFiYTVjMjcyNXgxNzkwODQ2NTM5NjgwMzA5NjAx parts=101386=== CONT TestPendingClosureWriteTimeout1387--- PASS: TestService_verifyS3Integrity (1.41s)1388=== RUN TestPendingClosureWriteTimeout/empty1389=== PAUSE TestPendingClosureWriteTimeout/empty1390=== RUN TestPendingClosureWriteTimeout/negative1391=== PAUSE TestPendingClosureWriteTimeout/negative1392=== RUN TestPendingClosureWriteTimeout/400_objects1393=== PAUSE TestPendingClosureWriteTimeout/400_objects1394=== RUN TestPendingClosureWriteTimeout/670k_objects1395=== PAUSE TestPendingClosureWriteTimeout/670k_objects1396=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1397=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1398=== CONT TestGCSweepDeliversEachKeyOnce1399--- PASS: TestCompletedNarNotReofferedAcrossClosures (1.55s)1400=== CONT TestClientCADerivations1401=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure1402=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure1403=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart1404=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart1405=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts1406=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts1407=== CONT TestPushDedupSurvivesConcurrentGC1408--- PASS: TestRegisterCompletedObjectNeedsPendingRow (0.25s)1409=== CONT TestResolveDBConnectionString1410=== RUN TestResolveDBConnectionString/flag_wins1411=== PAUSE TestResolveDBConnectionString/flag_wins1412=== RUN TestResolveDBConnectionString/file_when_flag_empty1413=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1414=== RUN TestResolveDBConnectionString/missing_file_is_an_error1415=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1416=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1417=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1418=== RUN TestResolveDBConnectionString/nothing_configured1419=== PAUSE TestResolveDBConnectionString/nothing_configured1420=== CONT TestDeduplicatedObjectsRecordedAsPending14212026/10/01 09:22:20 INFO Aborted multipart uploads count=0 kept=014222026/10/01 09:22:20 WARN Force mode enabled - objects will be deleted immediately without grace period14232026/10/01 09:22:20 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."14242026/10/01 09:22:20 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."14252026/10/01 09:22:20 INFO Received uploads request method=POST path=/api/pending_closures1426--- PASS: TestReadRedirectNar (0.30s)1427=== CONT TestService_AuthMiddleware_MTLSBoundSubjects1428--- PASS: TestFailedS3DeleteKeepsTombstone (0.48s)1429=== CONT TestClientMultipleUploads14302026/10/01 09:22:20 INFO Received push request method=POST path=/api/pushes14312026/10/01 09:22:20 INFO Received uploads request method=POST path=/api/pending_closures14322026/10/01 09:22:20 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14332026/10/01 09:22:20 INFO Received cleanup request method=DELETE path=/api/pending_closures14342026/10/01 09:22:20 INFO Aborted multipart uploads count=0 kept=014352026/10/01 09:22:20 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=MmUwNWI5YmEtZDFkYS00ZmMyLWIxMzUtMzdiMzQ0YTZhNzZkLmRiNGFmZTM4LTU1NTUtNDY4OS1iYTE0LTg3YjY5OGJkYTIwYXgxNzkwODQ2NTM5ODgyMjg4OTc1 parts=1014362026/10/01 09:22:20 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14372026/10/01 09:22:20 INFO Received uploads request method=POST path=/api/pending_closures14382026/10/01 09:22:20 INFO Completed upload id=11439--- PASS: TestTombstonedObjectOfferedWithoutWaiting (0.32s)1440=== CONT TestGCBugBareHashReferences14412026/10/01 09:22:20 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000014422026/10/01 09:22:20 INFO Received uploads request method=POST path=/api/pending_closures1443--- PASS: TestPushWaitsForSweepHoldingRow (0.93s)1444=== CONT TestService_ReadAuthMiddleware14452026/10/01 09:22:20 INFO Starting cleanup of old closures method=DELETE path=/api/closures14462026/10/01 09:22:20 INFO Received cleanup request method=DELETE path=/api/pending_closures14472026/10/01 09:22:20 INFO Aborted multipart uploads count=1 kept=014482026/10/01 09:22:20 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14492026-10-01 09:22:20.561 UTC [1209] ERROR: Closure does not exist: id=114502026-10-01 09:22:20.561 UTC [1209] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 12 at RAISE14512026-10-01 09:22:20.561 UTC [1209] STATEMENT: -- name: CommitPendingClosure :exec1452 SELECT commit_pending_closure($1::bigint)1453 14542026/10/01 09:22:20 INFO Aborted multipart uploads count=0 kept=014552026/10/01 09:22:20 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=014562026/10/01 09:22:20 INFO Vacuumed table table=pending_closures1457--- PASS: TestService_cleanupPendingClosuresHandler (0.39s)1458=== CONT TestClientWithDependencies14592026/10/01 09:22:20 INFO Vacuumed table table=pending_objects14602026/10/01 09:22:20 INFO Vacuumed table table=multipart_uploads14612026/10/01 09:22:20 INFO Vacuumed table table=closures14622026/10/01 09:22:20 INFO Vacuumed table table=objects14632026/10/01 09:22:20 INFO Aborted multipart uploads count=0 kept=014642026/10/01 09:22:20 WARN Force mode enabled - objects will be deleted immediately without grace period14652026/10/01 09:22:20 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=014662026/10/01 09:22:20 INFO Vacuumed table table=pending_closures14672026/10/01 09:22:20 INFO Vacuumed table table=pending_objects14682026/10/01 09:22:20 INFO Vacuumed table table=multipart_uploads14692026/10/01 09:22:20 INFO Vacuumed table table=closures14702026/10/01 09:22:20 INFO Vacuumed table table=objects1471=== NAME TestPinProtectsFromGC1472 client_integration_test.go:867: Pinned store path: /build/TestPinProtectsFromGC430617214/001/store/44pnhih9ch4c3d5jn58pclbma89796ky-pinned-file.txt1473 client_integration_test.go:868: Unpinned store path: /build/TestPinProtectsFromGC430617214/001/store/dv5lpq65586zlvkzfclpxpbh54v1fydl-unpinned-file.txt14742026/10/01 09:22:20 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001475--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (0.52s)1476=== CONT TestClientIntegration1477--- PASS: TestService_createPendingClosureHandler (1.24s)1478=== CONT TestClientErrorHandling1479=== RUN TestClientErrorHandling/InvalidStorePath1480=== PAUSE TestClientErrorHandling/InvalidStorePath1481=== RUN TestClientErrorHandling/InvalidAuthToken1482=== PAUSE TestClientErrorHandling/InvalidAuthToken1483=== RUN TestClientErrorHandling/ServerNotAvailable1484=== PAUSE TestClientErrorHandling/ServerNotAvailable1485=== CONT TestService_AuthMiddleware_MTLSProxyHeader14862026/10/01 09:22:20 INFO Received uploads request method=POST path=/api/pending_closures1487--- PASS: TestGCMetrics (0.43s)1488=== CONT TestConnectSerialisesConcurrentMigrations14892026/10/01 09:22:20 INFO Aborted multipart uploads count=0 kept=014902026/10/01 09:22:20 WARN Force mode enabled - objects will be deleted immediately without grace period14912026/10/01 09:22:20 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=014922026/10/01 09:22:20 INFO Vacuumed table table=pending_closures14932026/10/01 09:22:20 INFO Vacuumed table table=pending_objects14942026/10/01 09:22:20 INFO Vacuumed table table=multipart_uploads14952026/10/01 09:22:20 INFO Vacuumed table table=closures14962026/10/01 09:22:20 INFO Vacuumed table table=objects14972026/10/01 09:22:20 INFO Aborted multipart uploads count=0 kept=014982026/10/01 09:22:20 INFO Received push request method=POST path=/api/pushes14992026/10/01 09:22:20 WARN Force mode enabled - objects will be deleted immediately without grace period15002026/10/01 09:22:20 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15012026/10/01 09:22:20 INFO Uploading 44pnhih9ch4c3d5jn58pclbma89796ky-pinned-file.txt (128B)15022026/10/01 09:22:20 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"15032026/10/01 09:22:20 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=015042026/10/01 09:22:20 WARN Failed to register uploaded object key=44pnhih9ch4c3d5jn58pclbma89796ky.ls error="server returned 404: 404 page not found\n"15052026/10/01 09:22:20 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15062026/10/01 09:22:20 INFO Vacuumed table table=pending_closures15072026/10/01 09:22:20 INFO Vacuumed table table=pending_objects15082026/10/01 09:22:20 INFO Vacuumed table table=multipart_uploads15092026/10/01 09:22:20 INFO Vacuumed table table=closures15102026/10/01 09:22:20 INFO Signed narinfos id=1 count=115112026/10/01 09:22:20 INFO Uploading 1 narinfos1512=== CONT TestReadProxyHead1513--- PASS: TestGCSweepSkipsPendingObjects (0.43s)15142026/10/01 09:22:20 INFO Vacuumed table table=objects15152026/10/01 09:22:20 INFO Received complete push request method=POST path=/api/pushes/1/complete15162026/10/01 09:22:20 WARN Failed to register uploaded object key=44pnhih9ch4c3d5jn58pclbma89796ky.narinfo error="server returned 404: 404 page not found\n"1517--- PASS: TestGCSweepDeliversEachKeyOnce (0.43s)1518=== CONT TestReadProxyInvalidPath15192026/10/01 09:22:20 INFO Upload complete. (92ms)15202026/10/01 09:22:20 INFO Received complete multipart upload request method=POST path=/api/multipart/complete15212026/10/01 09:22:20 INFO Received uploads request method=POST path=/api/pending_closures15222026/10/01 09:22:20 INFO Received uploads request method=POST path=/api/pending_closures15232026/10/01 09:22:20 INFO Received push request method=POST path=/api/pushes15242026-10-01 09:22:20.806 UTC [1428] ERROR: duplicate key value violates unique constraint "pg_type_typname_nsp_index"15252026-10-01 09:22:20.806 UTC [1428] DETAIL: Key (typname, typnamespace)=(goose_db_version, 2200) already exists.15262026-10-01 09:22:20.806 UTC [1428] STATEMENT: CREATE TABLE goose_db_version (1527 id integer PRIMARY KEY GENERATED BY DEFAULT AS IDENTITY,1528 version_id bigint NOT NULL,1529 is_applied boolean NOT NULL,1530 tstamp timestamp NOT NULL DEFAULT now()1531 )15322026/10/01 09:22:20 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=MmUwNWI5YmEtZDFkYS00ZmMyLWIxMzUtMzdiMzQ0YTZhNzZkLjY1ZmU4ODFkLTQ1M2MtNGFjYi04Mzg2LWUxYzYwOWI0MTA5OXgxNzkwODQ2NTQwMTEyNjgxNjUy error="Get \"http://127.0.0.1:1/bucket23/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"15332026/10/01 09:22:20 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=MmUwNWI5YmEtZDFkYS00ZmMyLWIxMzUtMzdiMzQ0YTZhNzZkLmIzZGFlM2EyLTVkM2ItNDVkNy05MDY5LTk3Y2NmZDhhMGZlNHgxNzkwODQ2NTQwMDk4MzM5OTI1 parts=1215342026/10/01 09:22:20 INFO Received cleanup request method=DELETE path=/api/pending_closures15352026/10/01 09:22:20 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"15362026/10/01 09:22:20 WARN mTLS auth: bound subjects configured but subject DN unavailable15372026/10/01 09:22:20 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"15382026/10/01 09:22:20 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)15392026/10/01 09:22:20 INFO Uploading hmh9iyfd0v95kswgjfs7pigvm2cqx6ds-shared-dep (136B)15402026/10/01 09:22:20 INFO Uploading p8pw6mgdf96k5j074sylryv764795kyf-top (224B)1541--- PASS: TestDeduplicatedObjectsRecordedAsPending (0.44s)1542=== CONT TestConnectWaitsForAPeerMigration1543=== NAME TestClientCADerivations1544 client_ca_test.go:136: Built CA derivation: /build/TestClientCADerivations2774618578/001/store/7mwn9y4hdb4k7q1fngbsdaacwckdz5ka-ca-test15452026/10/01 09:22:20 INFO Aborted multipart uploads count=1 kept=015462026/10/01 09:22:20 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"15472026/10/01 09:22:20 WARN Failed to register uploaded object key=hmh9iyfd0v95kswgjfs7pigvm2cqx6ds.ls error="server returned 404: 404 page not found\n"1548=== CONT TestReadRedirectKeepsNarinfoProxied1549--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.40s)15502026/10/01 09:22:20 WARN Failed to register uploaded object key=nar/0c0n5s3b47lyl28k9kza2lga77r6z0xwrl9lx8hiy054b9ssrlhh.nar.zst error="server returned 404: 404 page not found\n"15512026/10/01 09:22:20 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15522026/10/01 09:22:20 WARN Failed to register uploaded object key=p8pw6mgdf96k5j074sylryv764795kyf.ls error="server returned 404: 404 page not found\n"15532026/10/01 09:22:20 INFO Signed narinfos id=1 count=215542026/10/01 09:22:20 INFO Uploading 2 narinfos15552026/10/01 09:22:20 INFO Received push request method=POST path=/api/pushes15562026/10/01 09:22:20 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15572026/10/01 09:22:20 INFO Uploading dv5lpq65586zlvkzfclpxpbh54v1fydl-unpinned-file.txt (128B)15582026/10/01 09:22:20 WARN Failed to register uploaded object key=p8pw6mgdf96k5j074sylryv764795kyf.narinfo error="server returned 404: 404 page not found\n"15592026/10/01 09:22:20 INFO Received complete push request method=POST path=/api/pushes/1/complete15602026/10/01 09:22:20 WARN Failed to register uploaded object key=hmh9iyfd0v95kswgjfs7pigvm2cqx6ds.narinfo error="server returned 404: 404 page not found\n"1561=== NAME TestClientCADerivations1562 client_ca_test.go:139: Found 1 dependencies (including self)1563=== CONT TestLeadEndsOnShutdown1564--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (1.53s)15652026/10/01 09:22:20 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"1566=== CONT TestReadProxy4041567--- PASS: TestRedundantMultipartUpload (2.72s)15682026/10/01 09:22:20 INFO Upload complete. (102ms)1569=== NAME TestClientSharedPathCommittedMidPush1570 client_integration_test.go:816: Retrieved narinfo from S3:1571 StorePath: /build/TestClientSharedPathCommittedMidPush3665305598/001/store/hmh9iyfd0v95kswgjfs7pigvm2cqx6ds-shared-dep15722026/10/01 09:22:20 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign1573 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1574 Compression: zstd1575 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y8215762026/10/01 09:22:20 WARN Failed to register uploaded object key=dv5lpq65586zlvkzfclpxpbh54v1fydl.ls error="server returned 404: 404 page not found\n"1577 NarSize: 1361578 References: 1579 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n15802026/10/01 09:22:20 INFO Signed narinfos id=2 count=115812026/10/01 09:22:20 INFO Aborted multipart uploads count=0 kept=015822026/10/01 09:22:20 INFO Uploading 1 narinfos1583 client_integration_test.go:816: Retrieved narinfo from S3:1584 StorePath: /build/TestClientSharedPathCommittedMidPush3665305598/001/store/p8pw6mgdf96k5j074sylryv764795kyf-top1585 URL: nar/0c0n5s3b47lyl28k9kza2lga77r6z0xwrl9lx8hiy054b9ssrlhh.nar.zst1586 Compression: zstd1587 NarHash: sha256:0c0n5s3b47lyl28k9kza2lga77r6z0xwrl9lx8hiy054b9ssrlhh1588 NarSize: 2241589 References: /build/TestClientSharedPathCommittedMidPush3665305598/001/store/hmh9iyfd0v95kswgjfs7pigvm2cqx6ds-shared-dep1590 CA: text:sha256:00wykfxlqa85ybdv73kx6fzachgz4kdbyxz4z6axyfljj2wa38sq15912026/10/01 09:22:20 INFO Received complete push request method=POST path=/api/pushes/2/complete15922026/10/01 09:22:20 WARN Failed to register uploaded object key=dv5lpq65586zlvkzfclpxpbh54v1fydl.narinfo error="server returned 404: 404 page not found\n"15932026/10/01 09:22:20 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=015942026/10/01 09:22:20 INFO Upload complete. (71ms)15952026/10/01 09:22:20 INFO Vacuumed table table=pending_closures15962026/10/01 09:22:20 INFO Vacuumed table table=pending_objects15972026/10/01 09:22:20 INFO Vacuumed table table=multipart_uploads1598--- PASS: TestService_ReadAuthMiddleware (0.35s)1599=== CONT TestReadProxyRootRedirectsToIndexHTML16002026/10/01 09:22:20 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1601=== NAME TestClientMultipleUploads1602 client_integration_test.go:480: Created store path 0: /build/TestClientMultipleUploads1594754244/001/store/ja7xskj54lh5j5y922vxv34p2b1bn268-test-file-0.txt16032026/10/01 09:22:20 INFO Vacuumed table table=closures16042026/10/01 09:22:20 INFO Vacuumed table table=objects1605--- PASS: TestClientSharedPathCommittedMidPush (0.61s)1606=== CONT TestReadProxyNarinfoAlreadyDecompressed16072026/10/01 09:22:20 INFO Aborted multipart uploads count=0 kept=016082026/10/01 09:22:20 WARN Force mode enabled - objects will be deleted immediately without grace period16092026/10/01 09:22:20 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/01 09:22:20 INFO Completed multipart upload object_key=nar/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb00000000000000000000.nar.zst upload_id=MmUwNWI5YmEtZDFkYS00ZmMyLWIxMzUtMzdiMzQ0YTZhNzZkLmRiZWFkZmRjLWUyMjQtNGE5OS1hOWI0LTc1OGYzNThmZjI3ZHgxNzkwODQ2NTM5Njc4MTQyMzMy parts=1016112026/10/01 09:22:20 INFO Vacuumed table table=pending_closures16122026/10/01 09:22:20 INFO Vacuumed table table=pending_objects16132026/10/01 09:22:20 INFO Vacuumed table table=multipart_uploads16142026/10/01 09:22:20 INFO Starting cleanup of old closures method=DELETE path=/api/closures16152026/10/01 09:22:20 INFO Garbage collection started16162026/10/01 09:22:20 INFO Vacuumed table table=closures16172026/10/01 09:22:20 INFO Vacuumed table table=objects16182026/10/01 09:22:20 INFO Received complete push request method=POST path=/api/pushes/1/complete1619=== NAME TestClientMultipleUploads1620 client_integration_test.go:480: Created store path 1: /build/TestClientMultipleUploads1594754244/001/store/4z4n9qgy02rbkbzyyial9wlp966ah9r2-test-file-1.txt16212026/10/01 09:22:20 INFO Aborted multipart uploads count=0 kept=016222026/10/01 09:22:20 INFO Received push request method=POST path=/api/pushes16232026/10/01 09:22:20 WARN Force mode enabled - objects will be deleted immediately without grace period1624--- PASS: TestPushDedupSurvivesConcurrentGC (0.58s)1625=== CONT TestService_RequireScope_OIDC16262026/10/01 09:22:20 INFO lead: released remote=192.0.2.1:123416272026/10/01 09:22:20 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=016282026/10/01 09:22:20 INFO Vacuumed table table=pending_closures16292026/10/01 09:22:20 INFO Vacuumed table table=pending_objects16302026/10/01 09:22:20 INFO Vacuumed table table=multipart_uploads16312026/10/01 09:22:20 INFO Received push request method=POST path=/api/pushes16322026/10/01 09:22:20 INFO Vacuumed table table=closures1633=== NAME TestClientMultipleUploads1634 client_integration_test.go:480: Created store path 2: /build/TestClientMultipleUploads1594754244/001/store/81jc1w2dqbv9n04qafgvjg3d9pikzxrp-test-file-2.txt16352026/10/01 09:22:20 INFO Vacuumed table table=objects16362026/10/01 09:22:20 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16372026/10/01 09:22:20 INFO Uploading 7mwn9y4hdb4k7q1fngbsdaacwckdz5ka-ca-test (144B)16382026/10/01 09:22:20 WARN Failed to register uploaded object key=log/qzvxqhafx4sckwp80l248c22jic67cpf-ca-test.drv error="server returned 404: 404 page not found\n"16392026/10/01 09:22:21 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"1640--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.34s)1641=== CONT TestService_AuthMiddleware_OIDC16422026/10/01 09:22:21 INFO lead: acquired remote=192.0.2.1:12341643=== NAME TestClientIntegration1644 client_integration_test.go:334: Created store path: /build/TestClientIntegration37894531/002/store/a3hslxw7r09vwlqzgp4n6xigr8vva591-test-file.txt16452026/10/01 09:22:21 WARN Failed to register uploaded object key=7mwn9y4hdb4k7q1fngbsdaacwckdz5ka.ls error="server returned 404: 404 page not found\n"16462026/10/01 09:22:21 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16472026/10/01 09:22:21 INFO Signed narinfos id=1 count=116482026/10/01 09:22:21 INFO Uploading 1 narinfos16492026/10/01 09:22:21 INFO Aborted multipart uploads count=0 kept=016502026/10/01 09:22:21 WARN Force mode enabled - objects will be deleted immediately without grace period1651=== NAME TestClientWithDependencies1652 client_integration_test.go:735: Built derivation: /build/TestClientWithDependencies643650649/001/store/agpkq0nqh97aa5sq2rwq0bf01skwgzvq-test-script16532026/10/01 09:22:21 INFO Received complete push request method=POST path=/api/pushes/1/complete16542026/10/01 09:22:21 WARN Failed to register uploaded object key=7mwn9y4hdb4k7q1fngbsdaacwckdz5ka.narinfo error="server returned 404: 404 page not found\n"16552026/10/01 09:22:21 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:38721/oidc16562026/10/01 09:22:21 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:36553/oidc1657--- PASS: TestReadProxyHead (0.40s)1658=== CONT TestService_ReadScope_PublicByDefault16592026/10/01 09:22:21 INFO Upload complete. (290ms)16602026/10/01 09:22:21 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=016612026/10/01 09:22:21 INFO Vacuumed table table=pending_closures1662=== NAME TestClientWithDependencies1663 client_integration_test.go:737: Found 1 dependencies (including self)16642026/10/01 09:22:21 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1665=== NAME TestClientCADerivations16662026/10/01 09:22:21 INFO Received push request method=POST path=/api/pushes1667 client_ca_test.go:180: Narinfo contains CA field: StorePath: /build/TestClientCADerivations2774618578/001/store/7mwn9y4hdb4k7q1fngbsdaacwckdz5ka-ca-test16682026/10/01 09:22:21 INFO Vacuumed table table=pending_objects1669 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1670 Compression: zstd1671 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1672 NarSize: 1441673 References: 1674 Deriver: /build/TestClientCADerivations2774618578/001/store/qzvxqhafx4sckwp80l248c22jic67cpf-ca-test.drv1675 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1676 client_ca_test.go:185: Checking for realisation files in S3...1677 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1678 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache16792026/10/01 09:22:21 INFO Vacuumed table table=multipart_uploads16802026/10/01 09:22:21 INFO Vacuumed table table=closures16812026/10/01 09:22:21 INFO Vacuumed table table=objects16822026/10/01 09:22:21 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)16832026/10/01 09:22:21 INFO Uploading 4z4n9qgy02rbkbzyyial9wlp966ah9r2-test-file-1.txt (160B)16842026/10/01 09:22:21 INFO Uploading 81jc1w2dqbv9n04qafgvjg3d9pikzxrp-test-file-2.txt (160B)16852026/10/01 09:22:21 INFO Uploading ja7xskj54lh5j5y922vxv34p2b1bn268-test-file-0.txt (160B)1686--- PASS: TestReadProxyInvalidPath (0.45s)1687=== CONT TestReadProxyConditionalGet1688=== CONT TestCacheStatsHandler1689--- PASS: TestGCBugBareHashReferences (0.69s)16902026/10/01 09:22:21 INFO Completed multipart upload object_key=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa00000000000000000000.nar.zst upload_id=MmUwNWI5YmEtZDFkYS00ZmMyLWIxMzUtMzdiMzQ0YTZhNzZkLjE4NTAzYTI1LTg2OTEtNGRjYy1iNDI4LTljODg4OTFjYzgyYngxNzkwODQ2NTQwNDY2NzEyNjYz parts=1016912026/10/01 09:22:21 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"16922026/10/01 09:22:21 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"16932026/10/01 09:22:21 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"16942026/10/01 09:22:21 INFO Received push request method=POST path=/api/pushes16952026/10/01 09:22:21 WARN Failed to register uploaded object key=81jc1w2dqbv9n04qafgvjg3d9pikzxrp.ls error="server returned 404: 404 page not found\n"16962026/10/01 09:22:21 WARN Failed to register uploaded object key=4z4n9qgy02rbkbzyyial9wlp966ah9r2.ls error="server returned 404: 404 page not found\n"16972026/10/01 09:22:21 WARN Failed to register uploaded object key=ja7xskj54lh5j5y922vxv34p2b1bn268.ls error="server returned 404: 404 page not found\n"16982026/10/01 09:22:21 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16992026/10/01 09:22:21 INFO Signed narinfos id=1 count=317002026/10/01 09:22:21 INFO Uploading 3 narinfos17012026/10/01 09:22:21 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17022026/10/01 09:22:21 INFO Uploading a3hslxw7r09vwlqzgp4n6xigr8vva591-test-file.txt (152B)17032026/10/01 09:22:21 INFO lead: acquired remote=192.0.2.1:123417042026/10/01 09:22:21 WARN Failed to register uploaded object key=81jc1w2dqbv9n04qafgvjg3d9pikzxrp.narinfo error="server returned 404: 404 page not found\n"17052026/10/01 09:22:21 WARN Failed to register uploaded object key=4z4n9qgy02rbkbzyyial9wlp966ah9r2.narinfo error="server returned 404: 404 page not found\n"17062026/10/01 09:22:21 INFO Received complete push request method=POST path=/api/pushes/1/complete17072026/10/01 09:22:21 WARN Failed to register uploaded object key=ja7xskj54lh5j5y922vxv34p2b1bn268.narinfo error="server returned 404: 404 page not found\n"17082026/10/01 09:22:21 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"17092026/10/01 09:22:21 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17102026/10/01 09:22:21 INFO Upload complete. (269ms)17112026/10/01 09:22:21 WARN Failed to register uploaded object key=a3hslxw7r09vwlqzgp4n6xigr8vva591.ls error="server returned 404: 404 page not found\n"1712=== NAME TestClientMultipleUploads1713 client_integration_test.go:491: Uploaded 3 paths in 314.064443ms17142026/10/01 09:22:21 INFO Signed narinfos id=1 count=117152026/10/01 09:22:21 INFO Uploading 1 narinfos17162026/10/01 09:22:21 INFO Received complete push request method=POST path=/api/pushes/1/complete17172026/10/01 09:22:21 WARN Failed to register uploaded object key=a3hslxw7r09vwlqzgp4n6xigr8vva591.narinfo error="server returned 404: 404 page not found\n"17182026/10/01 09:22:21 INFO Upload complete. (112ms)17192026/10/01 09:22:21 INFO Received push request method=POST path=/api/pushes17202026/10/01 09:22:21 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17212026/10/01 09:22:21 INFO Uploading agpkq0nqh97aa5sq2rwq0bf01skwgzvq-test-script (136B)1722--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.46s)1723=== CONT TestServerTLSConfig/no_client_CA1724=== CONT TestServerTLSConfig/not_a_PEM_file1725=== CONT TestServerTLSConfig/missing_CA_file1726--- PASS: TestClientMultipleUploads (0.90s)1727=== CONT TestParseSingleRange/none1728=== CONT TestParseSingleRange/start_far_past_EOF1729=== CONT TestParseSingleRange/start_past_EOF17302026/10/01 09:22:21 INFO All 1 paths already cached1731=== CONT TestParseSingleRange/malformed_end_before_start1732=== CONT TestParseSingleRange/single_byte1733=== CONT TestParseSingleRange/end_clamped_to_size1734=== CONT TestParseSingleRange/suffix_exceeds_size1735=== CONT TestParseSingleRange/suffix1736=== CONT TestParseSingleRange/open-ended1737=== CONT TestParseSingleRange/multi-range_ignored1738=== CONT TestParseSingleRange/closed1739=== CONT TestParseSingleRange/malformed_both_empty1740=== CONT TestParseSingleRange/malformed_no_dash1741=== CONT TestParseSingleRange/unknown_unit1742=== CONT TestIsValidCachePath/narinfo1743=== NAME TestClientCADerivations1744 client_ca_test.go:258: nix copy output: warning: you don't have Internet access; disabling some network-dependent features1745 warning: failed to create TLS context for AWS credential providers; SSO, STS WebIdentity, and ECS container authentication will be unavailable1746 error: binary cache 's3://bucket68?endpoint=http://localhost:33885®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/build/TestClientCADerivations2774618578/001/store'1747 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 11748=== CONT TestIsValidCachePath/short_hash1749=== CONT TestIsValidCachePath/nix-cache-info1750=== NAME TestClientIntegration1751 client_integration_test.go:360: Retrieved narinfo from S3:1752 StorePath: /build/TestClientIntegration37894531/002/store/a3hslxw7r09vwlqzgp4n6xigr8vva591-test-file.txt1753--- PASS: TestParseSingleRange (0.01s)1754 --- PASS: TestParseSingleRange/none (0.00s)1755 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1756 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1757 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1758 --- PASS: TestParseSingleRange/single_byte (0.00s)1759 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1760 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1761 --- PASS: TestParseSingleRange/open-ended (0.00s)1762 --- PASS: TestParseSingleRange/suffix (0.00s)1763 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1764 --- PASS: TestParseSingleRange/closed (0.00s)1765 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1766 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1767 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1768=== CONT TestIsValidCachePath/wrong_extension1769=== CONT TestIsValidCachePath/leading_slash1770=== NAME TestClientIntegration1771 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1772 Compression: zstd1773 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11774 NarSize: 1521775 References: 1776 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11777=== CONT TestIsValidCachePath/empty17782026/10/01 09:22:21 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"1779=== CONT TestIsValidCachePath/invalid_char_u1780=== CONT TestIsValidCachePath/random_path1781--- PASS: TestServerTLSConfig (0.00s)1782 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1783 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)1784 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1785=== CONT TestIsValidCachePath/traversal_parent1786=== CONT TestIsValidCachePath/invalid_char_e1787=== CONT TestIsValidCachePath/traversal_in_middle1788=== CONT TestIsValidCachePath/realisation1789=== CONT TestIsValidCachePath/index.html1790=== CONT TestIsValidCachePath/log1791=== CONT TestIsValidCachePath/ls1792=== CONT TestIsValidCachePath/nar_xz1793=== CONT TestIsValidCachePath/nar_bz21794=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1795=== CONT TestIsValidCachePath/nar_zst1796=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1797=== CONT TestIsValidCachePath/nar_uncompressed1798=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1799--- PASS: TestIsValidCachePath (0.01s)1800 --- PASS: TestIsValidCachePath/narinfo (0.00s)1801 --- PASS: TestIsValidCachePath/short_hash (0.00s)1802 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1803 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1804 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1805 --- PASS: TestIsValidCachePath/empty (0.00s)1806 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1807 --- PASS: TestIsValidCachePath/random_path (0.00s)1808 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1809 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1810 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1811 --- PASS: TestIsValidCachePath/realisation (0.00s)1812 --- PASS: TestIsValidCachePath/index.html (0.00s)1813 --- PASS: TestIsValidCachePath/log (0.00s)1814 --- PASS: TestIsValidCachePath/ls (0.00s)1815 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1816 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1817 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1818 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1819 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1820=== NAME TestClientIntegration1821 client_integration_test.go:361: Retrieved .ls file from S3 (compressed size: 77 bytes)1822 client_integration_test.go:361: Decompressed .ls content (64 bytes):1823 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1824=== NAME TestOrphanedObjectsGCStressTest1825 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains18262026/10/01 09:22:21 WARN Failed to register uploaded object key=agpkq0nqh97aa5sq2rwq0bf01skwgzvq.ls error="server returned 404: 404 page not found\n"18272026/10/01 09:22:21 WARN Failed to register uploaded object key=log/gfdy5p3r899m4s44xxf75izs61xf7s8m-test-script.drv error="server returned 404: 404 page not found\n"18282026/10/01 09:22:21 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18292026/10/01 09:22:21 INFO Signed narinfos id=1 count=118302026/10/01 09:22:21 INFO Uploading 1 narinfos1831=== CONT TestGCEndsOnShutdown/before_the_run1832--- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.48s)1833--- PASS: TestClientCADerivations (1.05s)1834=== CONT TestCacheConfigHandler/full_config,_no_issuer1835=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1836=== CONT TestCacheConfigHandler/no_signing_keys1837=== CONT TestCacheConfigHandler/no_cache_url_configured1838=== CONT TestProxyWriteTimeout/1_GiB_nar1839--- PASS: TestCacheConfigHandler (0.01s)1840 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1841 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1842 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1843 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1844=== CONT TestProxyWriteTimeout/10_GiB_nar1845=== CONT TestProxyWriteTimeout/unknown_size1846=== CONT TestProxyWriteTimeout/narinfo1847=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows1848--- PASS: TestProxyWriteTimeout (0.00s)1849 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1850 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1851 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1852 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)18532026/10/01 09:22:21 INFO Received complete push request method=POST path=/api/pushes/1/complete18542026/10/01 09:22:21 WARN Failed to register uploaded object key=agpkq0nqh97aa5sq2rwq0bf01skwgzvq.narinfo error="server returned 404: 404 page not found\n"18552026/10/01 09:22:21 INFO Upload complete. (180ms)1856=== NAME TestOrphanedObjectsGCStressTest1857 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion1858--- PASS: TestService_ReadScope_PublicByDefault (0.28s)1859=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check18602026/10/01 09:22:21 INFO Aborted multipart uploads count=0 kept=018612026/10/01 09:22:21 WARN Force mode enabled - objects will be deleted immediately without grace period18622026/10/01 09:22:21 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=018632026/10/01 09:22:21 INFO Vacuumed table table=pending_closures18642026/10/01 09:22:21 INFO Vacuumed table table=pending_objects1865=== RUN TestService_RequireScope_OIDC/builder_may_write18662026/10/01 09:22:21 INFO Vacuumed table table=multipart_uploads1867=== PAUSE TestService_RequireScope_OIDC/builder_may_write1868=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1869=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1870=== RUN TestService_RequireScope_OIDC/ops_may_admin1871=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1872=== RUN TestService_RequireScope_OIDC/ops_may_not_write1873=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1874=== RUN TestService_RequireScope_OIDC/reader_may_not_write1875=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1876=== RUN TestService_RequireScope_OIDC/static_token_may_admin1877=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1878=== RUN TestService_RequireScope_OIDC/static_token_may_write18792026/10/01 09:22:21 INFO Received push request method=POST path=/api/pushes1880=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1881=== RUN TestService_RequireScope_OIDC/reader_may_read1882=== PAUSE TestService_RequireScope_OIDC/reader_may_read1883=== RUN TestService_RequireScope_OIDC/writer_implies_read1884=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1885=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1886=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read18872026/10/01 09:22:21 INFO Vacuumed table table=closures1888=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal18892026/10/01 09:22:21 INFO Received uploads request method=POST path=/1890=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key18912026/10/01 09:22:21 INFO Received complete multipart upload request method=POST path=/1892=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key18932026/10/01 09:22:21 INFO Received request for more parts method=POST path=/1894=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info18952026/10/01 09:22:21 INFO Received uploads request method=POST path=/1896=== CONT TestIsValidUploadKey/unknown_type1897=== CONT TestIsValidUploadKey/narinfo1898--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1899 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1900 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1901 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1902 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1903=== CONT TestIsValidUploadKey/listing19042026/10/01 09:22:21 INFO Vacuumed table table=objects1905=== CONT TestIsValidUploadKey/build_log_plus_in_name1906=== CONT TestIsValidUploadKey/nar_zst1907=== CONT TestIsValidUploadKey/realisation1908=== CONT TestIsValidUploadKey/nar_plain1909=== CONT TestIsValidUploadKey/index.html1910=== CONT TestIsValidUploadKey/build_log1911=== CONT TestIsValidUploadKey/build_log_question_mark1912=== CONT TestIsValidUploadKey/realisation_plus_in_output1913=== CONT TestIsValidUploadKey/build_log_equals1914=== CONT TestIsValidUploadKey/nar_xz1915=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1916=== CONT TestIsValidUploadKey/empty_key1917=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1918=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1919=== NAME TestClientWithDependencies1920 client_integration_test.go:753: Skipping nix copy test - isolated store (/build/TestClientWithDependencies643650649/001/store) requires matching store prefix1921=== CONT TestIsValidUploadKey/traversal_nar1922=== CONT TestIsValidUploadKey/build_log_home-manager_file1923=== CONT TestIsValidUploadKey/traversal1924=== CONT TestIsValidUploadKey/nix-cache-info19252026/10/01 09:22:21 INFO Object in database but missing from S3 key=a3hslxw7r09vwlqzgp4n6xigr8vva591.ls19262026/10/01 09:22:21 WARN Found objects in DB but missing from S3, will re-upload count=11927=== CONT TestIsValidUploadKey/absolute1928=== CONT TestPush_RejectsBadRequests/no_roots1929--- PASS: TestIsValidUploadKey (0.01s)1930 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1931 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1932 --- PASS: TestIsValidUploadKey/listing (0.00s)1933 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1934 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1935 --- PASS: TestIsValidUploadKey/realisation (0.00s)1936 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1937 --- PASS: TestIsValidUploadKey/index.html (0.00s)1938 --- PASS: TestIsValidUploadKey/build_log (0.00s)1939 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1940 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1941 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1942 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1943 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1944 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1945 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1946 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1947 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1948 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1949 --- PASS: TestIsValidUploadKey/traversal (0.00s)1950 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1951 --- PASS: TestIsValidUploadKey/absolute (0.00s)19522026/10/01 09:22:21 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)19532026/10/01 09:22:21 INFO Received push request method=POST path=/api/pushes1954=== CONT TestPush_RejectsBadRequests/no_objects19552026/10/01 09:22:21 INFO Received push request method=POST path=/api/pushes1956=== CONT TestPush_RejectsBadRequests/bad_root19572026/10/01 09:22:21 INFO Received push request method=POST path=/api/pushes1958=== CONT TestPush_RejectsBadRequests/root_not_in_objects19592026/10/01 09:22:21 INFO Received push request method=POST path=/api/pushes1960=== CONT TestPendingClosureWriteTimeout/empty1961=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline19622026/10/01 09:22:21 INFO Received complete push request method=POST path=/api/pushes/2/complete19632026/10/01 09:22:21 WARN Failed to register uploaded object key=a3hslxw7r09vwlqzgp4n6xigr8vva591.ls error="server returned 404: 404 page not found\n"19642026/10/01 09:22:21 INFO Upload complete. (72ms)1965--- PASS: TestReadRedirectKeepsNarinfoProxied (0.66s)1966=== CONT TestPendingClosureWriteTimeout/670k_objects1967=== CONT TestPendingClosureWriteTimeout/400_objects1968=== CONT TestPendingClosureWriteTimeout/negative1969=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure19702026/10/01 09:22:21 INFO Received uploads request method=POST path=/1971--- PASS: TestClientWithDependencies (0.91s)1972=== NAME TestClientIntegration1973 client_integration_test.go:389: Retrieved .ls file from S3 (compressed size: 62 bytes)1974=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts19752026/10/01 09:22:21 INFO Received request for more parts method=POST path=/1976=== NAME TestClientIntegration1977 client_integration_test.go:389: Decompressed .ls content (49 bytes):1978 {"version":1,"root":{"type":"regular","size":39}}1979--- PASS: TestPush_RejectsBadRequests (0.36s)1980 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)1981 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)1982 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)1983 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)1984=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1985=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1986=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1987=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1988=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1989=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1990=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1991=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1992=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart19932026/10/01 09:22:21 INFO Received complete multipart upload request method=POST path=/1994=== CONT TestResolveDBConnectionString/flag_wins1995--- PASS: TestCacheStatsHandler (0.36s)1996=== CONT TestResolveDBConnectionString/nothing_configured1997=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1998=== CONT TestResolveDBConnectionString/missing_file_is_an_error1999=== CONT TestResolveDBConnectionString/file_when_flag_empty2000=== CONT TestClientErrorHandling/InvalidStorePath2001--- PASS: TestResolveDBConnectionString (0.00s)2002 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)2003 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)2004 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)2005 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)2006 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)20072026/10/01 09:22:21 INFO Received push request method=POST path=/api/pushes20082026/10/01 09:22:21 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)20092026/10/01 09:22:21 INFO Aborted multipart uploads count=0 kept=020102026/10/01 09:22:21 WARN Force mode enabled - objects will be deleted immediately without grace period20112026/10/01 09:22:21 INFO Aborted multipart uploads count=0 kept=020122026/10/01 09:22:21 WARN Force mode enabled - objects will be deleted immediately without grace period20132026-10-01 09:22:21.650 UTC [2194] ERROR: canceling statement due to user request20142026-10-01 09:22:21.650 UTC [2194] CONTEXT: PL/pgSQL function object_stats_apply() line 5 at statement block20152026-10-01 09:22:21.650 UTC [2194] STATEMENT: -- name: MarkStaleObjects :execrows2016 WITH RECURSIVE ct AS (2017 SELECT timezone('UTC', now()) AS now2018 ),2019 closure_reach AS (2020 -- Start with all closure keys2021 SELECT o.key, o.refs2022 FROM objects o2023 INNER JOIN closures c ON o.key = c.key2024 UNION2025 -- Recursively add all referenced objects2026 SELECT o.key, o.refs2027 FROM objects o2028 INNER JOIN closure_reach cr ON o.key = ANY(cr.refs)2029 ),2030 reachable_objects AS (2031 SELECT DISTINCT key FROM closure_reach2032 ),2033 stale_objects AS (2034 SELECT o.key2035 FROM objects AS o, ct2036 WHERE2037 NOT EXISTS (2038 SELECT 12039 FROM reachable_objects ro2040 WHERE ro.key = o.key2041 )2042 AND NOT EXISTS (2043 SELECT 12044 FROM pending_objects AS po2045 WHERE po.key = o.key2046 )2047 AND o.deleted_at IS NULL -- Only mark fresh objects2048 ORDER BY o.key COLLATE "C" -- lock in key order, like commit_pending_closure2049 FOR UPDATE2050 )2051 UPDATE objects2052 SET2053 deleted_at = ct.now,2054 first_deleted_at = COALESCE(first_deleted_at, ct.now)2055 FROM stale_objects, ct2056 WHERE objects.key = stale_objects.key2057 20582026/10/01 09:22:21 INFO Received complete push request method=POST path=/api/pushes/3/complete20592026/10/01 09:22:21 WARN Failed to register uploaded object key=a3hslxw7r09vwlqzgp4n6xigr8vva591.ls error="server returned 404: 404 page not found\n"20602026/10/01 09:22:21 INFO Upload complete. (88ms)2061=== NAME TestClientIntegration2062 client_integration_test.go:405: Retrieved .ls file from S3 (compressed size: 62 bytes)2063 client_integration_test.go:405: Decompressed .ls content (49 bytes):2064 {"version":1,"root":{"type":"regular","size":39}}20652026/10/01 09:22:21 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:33885/bucket91/?delete=\": context canceled"2066=== CONT TestClientErrorHandling/InvalidAuthToken2067=== CONT TestClientErrorHandling/ServerNotAvailable2068=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2069--- PASS: TestGCEndsOnShutdown (0.00s)2070 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (0.31s)2071 --- PASS: TestGCEndsOnShutdown/before_the_run (0.30s)2072 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (0.32s)2073=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2074=== CONT TestService_RequireScope_OIDC/writer_implies_read2075=== CONT TestService_RequireScope_OIDC/reader_may_read2076=== CONT TestService_RequireScope_OIDC/static_token_may_write2077=== CONT TestService_RequireScope_OIDC/static_token_may_admin2078=== CONT TestService_RequireScope_OIDC/ops_may_not_write2079=== CONT TestService_RequireScope_OIDC/reader_may_not_write20802026/10/01 09:22:21 INFO Received uploads request method=POST path=/api/pending_closures2081=== CONT TestService_RequireScope_OIDC/ops_may_admin2082=== CONT TestService_RequireScope_OIDC/builder_may_write2083=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected20842026/10/01 09:22:21 INFO Aborted multipart uploads count=0 kept=020852026/10/01 09:22:21 WARN Authentication failed token_preview=eyJhbGciOi...Tlhy4cChmg token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2086=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token20872026/10/01 09:22:21 WARN Force mode enabled - objects will be deleted immediately without grace period2088=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected20892026/10/01 09:22: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]2090=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2091--- PASS: TestService_RequireScope_OIDC (0.54s)2092 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2093 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2094 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2095 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2096 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2097 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2098 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2099 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2100 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2101 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)21022026/10/01 09:22:21 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=02103--- PASS: TestReadProxyConditionalGet (0.50s)21042026/10/01 09:22:21 INFO Vacuumed table table=pending_closures21052026/10/01 09:22:21 INFO Vacuumed table table=pending_objects21062026/10/01 09:22:21 INFO Vacuumed table table=multipart_uploads21072026/10/01 09:22:21 INFO Vacuumed table table=closures2108--- PASS: TestService_AuthMiddleware_OIDC (0.52s)2109 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.01s)2110 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2111 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2112 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)21132026/10/01 09:22:21 INFO Vacuumed table table=objects21142026/10/01 09:22:21 INFO Received uploads request method=POST path=/api/pending_closures21152026/10/01 09:22:21 INFO Aborted multipart uploads count=0 kept=021162026/10/01 09:22:21 WARN Force mode enabled - objects will be deleted immediately without grace period21172026/10/01 09:22:21 INFO Received uploads request method=POST path=/api/pending_closures21182026/10/01 09:22:21 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=021192026/10/01 09:22:21 INFO Vacuumed table table=pending_closures21202026/10/01 09:22:21 INFO Vacuumed table table=pending_objects21212026/10/01 09:22:21 INFO Vacuumed table table=multipart_uploads21222026/10/01 09:22:21 INFO Vacuumed table table=closures21232026/10/01 09:22:21 INFO Vacuumed table table=objects21242026/10/01 09:22:21 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present21252026/10/01 09:22:21 INFO Received push request method=POST path=/api/pushes21262026/10/01 09:22:21 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)21272026/10/01 09:22:21 INFO Uploading 211qqz4fh20gzq9f4w4acx99dym9ild0-lost-commit.txt (152B)21282026/10/01 09:22:21 WARN Failed to register uploaded object key=nar/04d5klw9iix884nk82y7nlkps8afh2bg119y7zkvcf1pc1x2y2jl.nar.zst error="server returned 404: 404 page not found\n"2129--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2130 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (0.38s)2131 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (0.37s)21322026/10/01 09:22:21 INFO Received sign narinfos request method=POST path=/api/pushes/4/sign21332026/10/01 09:22:21 WARN Failed to register uploaded object key=211qqz4fh20gzq9f4w4acx99dym9ild0.ls error="server returned 404: 404 page not found\n"21342026/10/01 09:22:21 INFO Signed narinfos id=4 count=121352026/10/01 09:22:21 INFO Uploading 1 narinfos21362026/10/01 09:22:21 INFO Received complete push request method=POST path=/api/pushes/4/complete21372026/10/01 09:22:21 WARN Failed to register uploaded object key=211qqz4fh20gzq9f4w4acx99dym9ild0.narinfo error="server returned 404: 404 page not found\n"2138--- PASS: TestConnectSerialisesConcurrentMigrations (1.14s)21392026/10/01 09:22:21 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Post \"http://127.0.0.1:35761/api/pushes/4/complete\": EOF" url=http://127.0.0.1:35761/api/pushes/4/complete21402026/10/01 09:22:21 WARN Rate limiter enabled after throttle name=s3-test rate=521412026/10/01 09:22:21 WARN S3 rate limit hit during proxy key=4hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo error="Please reduce your request rate."21422026/10/01 09:22:21 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=211.624068ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2143=== NAME TestOrphanedObjectsGCStressTest2144 orphaned_objects_gc_test.go:509: Stress test completed successfully:2145 orphaned_objects_gc_test.go:510: - Active objects preserved: 202146 orphaned_objects_gc_test.go:511: - Objects deleted: 2102147 orphaned_objects_gc_test.go:512: - Total GC'd: 21021482026/10/01 09:22:21 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21492026/10/01 09:22:21 INFO Completed multipart upload object_key=nar/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb00000000000000000000.nar.zst upload_id=MmUwNWI5YmEtZDFkYS00ZmMyLWIxMzUtMzdiMzQ0YTZhNzZkLmJiZDY1MGQ5LTMwNTgtNDM1OS1hNTNlLTkwYTNjMjMzODkwZHgxNzkwODQ2NTQwNDY3MTExNDgz parts=102150--- PASS: TestOrphanedObjectsGCStressTest (3.78s)21512026/10/01 09:22:21 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21522026/10/01 09:22:21 INFO Received complete push request method=POST path=/api/pushes/4/complete21532026-10-01 09:22:21.923 UTC [1412] ERROR: Push does not exist: id=421542026-10-01 09:22:21.923 UTC [1412] CONTEXT: PL/pgSQL function commit_push(bigint) line 9 at RAISE21552026-10-01 09:22:21.923 UTC [1412] STATEMENT: -- name: CommitPush :exec2156 SELECT commit_push($1::bigint)2157 21582026/10/01 09:22:21 INFO Upload complete. (190ms)2159=== NAME TestClientIntegration2160 client_integration_test.go:435: Retrieved narinfo from S3:2161 StorePath: /build/TestClientIntegration37894531/002/store/211qqz4fh20gzq9f4w4acx99dym9ild0-lost-commit.txt2162 URL: nar/04d5klw9iix884nk82y7nlkps8afh2bg119y7zkvcf1pc1x2y2jl.nar.zst2163 Compression: zstd2164 NarHash: sha256:04d5klw9iix884nk82y7nlkps8afh2bg119y7zkvcf1pc1x2y2jl2165 NarSize: 1522166 References: 2167 CA: fixed:r:sha256:04d5klw9iix884nk82y7nlkps8afh2bg119y7zkvcf1pc1x2y2jl2168 client_integration_test.go:438: Testing garbage collection...21692026/10/01 09:22:21 INFO Completed multipart upload object_key=nar/cccccccccccccccccccccccccccccccc00000000000000000000.nar.zst upload_id=MmUwNWI5YmEtZDFkYS00ZmMyLWIxMzUtMzdiMzQ0YTZhNzZkLjdiMTE3MmM3LTgyNTktNDUyNy04ODk2LWIyNzRkYmI3N2E3N3gxNzkwODQ2NTQwOTQ5ODI2NDk5 parts=1021702026/10/01 09:22:21 INFO Received complete push request method=POST path=/api/pushes/2/complete21712026/10/01 09:22:21 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"2172--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (2.79s)21732026/10/01 09:22:21 INFO Starting cleanup of old closures method=DELETE path=/api/closures21742026/10/01 09:22:21 INFO Garbage collection started21752026/10/01 09:22:21 INFO Aborted multipart uploads count=0 kept=021762026/10/01 09:22:21 WARN Force mode enabled - objects will be deleted immediately without grace period21772026/10/01 09:22:21 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"21782026/10/01 09:22:21 WARN Rate limiter backed off name=s3-test rate=521792026/10/01 09:22:21 WARN S3 rate limit hit during proxy key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhh.nar.zst error="Please reduce your request rate."21802026/10/01 09:22:22 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=021812026/10/01 09:22:22 INFO Vacuumed table table=pending_closures21822026/10/01 09:22:22 INFO Vacuumed table table=pending_objects21832026/10/01 09:22:22 INFO Vacuumed table table=multipart_uploads21842026/10/01 09:22:22 INFO Vacuumed table table=closures21852026/10/01 09:22:22 INFO Vacuumed table table=objects2186--- PASS: TestReadProxy404 (1.16s)21872026/10/01 09:22:22 INFO lead: released remote=192.0.2.1:123421882026/10/01 09:22:22 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=422.317889ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2189--- PASS: TestLeadElectsOneAndHandsOver (2.81s)21902026/10/01 09:22:22 INFO lead: released remote=192.0.2.1:12342191--- PASS: TestLeadEndsOnShutdown (1.47s)21922026/10/01 09:22:22 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21932026/10/01 09:22:22 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=767.45959ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present21942026/10/01 09:22:22 INFO Completed multipart upload object_key=nar/cccccccccccccccccccccccccccccccc00000000000000000000.nar.zst upload_id=MmUwNWI5YmEtZDFkYS00ZmMyLWIxMzUtMzdiMzQ0YTZhNzZkLmYyNzVjYzNlLWI5MzEtNDUwYi1hZTEwLTVmMWI2ODhlZWZlOHgxNzkwODQ2NTQwNDY2MDc2NDQz parts=1021952026/10/01 09:22:22 INFO Received complete push request method=POST path=/api/pushes/1/complete2196--- PASS: TestPush_CompleteCommitsEveryRoot (2.43s)2197--- PASS: TestPendingClosureWriteTimeout (0.00s)2198 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2199 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2200 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2201 --- PASS: TestPendingClosureWriteTimeout/negative (0.00s)2202 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (1.11s)22032026/10/01 09:22:22 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=022042026/10/01 09:22:22 INFO Received create pin request method=POST path=/api/pins/myapp22052026/10/01 09:22:22 INFO Created/updated pin name=myapp store_path=/build/TestPinProtectsFromGC430617214/001/store/44pnhih9ch4c3d5jn58pclbma89796ky-pinned-file.txt narinfo_key=44pnhih9ch4c3d5jn58pclbma89796ky.narinfo22062026/10/01 09:22:22 INFO Starting cleanup of old closures method=DELETE path=/api/closures22072026/10/01 09:22:22 INFO Garbage collection started22082026/10/01 09:22:22 INFO Aborted multipart uploads count=0 kept=022092026/10/01 09:22:22 WARN Force mode enabled - objects will be deleted immediately without grace period22102026/10/01 09:22:22 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=022112026/10/01 09:22:22 INFO Vacuumed table table=pending_closures22122026/10/01 09:22:22 INFO Vacuumed table table=pending_objects22132026/10/01 09:22:22 INFO Vacuumed table table=multipart_uploads22142026/10/01 09:22:22 INFO Vacuumed table table=closures22152026/10/01 09:22:22 INFO Vacuumed table table=objects22162026/10/01 09:22:22 WARN Rate limiter enabled after throttle name=s3-test rate=522172026/10/01 09:22:22 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."2218=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle2219 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=102220 throttle_test.go:215: Rate limiter: enabled=true, rate=5.002221--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (4.85s)22222026/10/01 09:22:23 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.543162345s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present22232026/10/01 09:22:23 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=2 objects_marked=6 objects_deleted=6 objects_failed=02224=== NAME TestClientIntegration2225 client_integration_test.go:445: Objects in database after GC:2226 client_integration_test.go:445: Successfully deleted all objects with GC --force2227--- PASS: TestClientIntegration (3.35s)2228--- PASS: TestReadProxyOutlastsServerWriteTimeout (4.99s)22292026/10/01 09:22:24 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2230=== NAME TestPinProtectsFromGC2231 client_integration_test.go:976: Pin successfully protected closure from garbage collection22322026/10/01 09:22:24 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=192.733818ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2233--- PASS: TestPinProtectsFromGC (4.71s)22342026/10/01 09:22:25 INFO Aborted multipart uploads count=1 kept=022352026/10/01 09:22:25 INFO Received cleanup request method=DELETE path=/api/pending_closures22362026/10/01 09:22:25 INFO Aborted multipart uploads count=1 kept=02237--- PASS: TestPendingCleanupUsesOneCutoff (6.98s)22382026/10/01 09:22:25 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=416.800031ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22392026/10/01 09:22:25 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=865.04089ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2240--- PASS: TestConnectWaitsForAPeerMigration (5.20s)22412026/10/01 09:22:26 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.669345773s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22422026/10/01 09:22:28 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"22432026/10/01 09:22:28 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22442026/10/01 09:22:28 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=200.976985ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22452026/10/01 09:22:28 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=382.525616ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2246--- PASS: TestUploadHandlersRejectOversizedBody (0.76s)2247 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.60s)2248 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.70s)2249 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (7.12s)22502026/10/01 09:22:28 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=854.283041ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22512026/10/01 09:22:29 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.638305836s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22522026/10/01 09:22:31 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22532026/10/01 09:22:31 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=182.657712ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22542026/10/01 09:22:31 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=435.209268ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22552026/10/01 09:22:32 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=727.739686ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22562026/10/01 09:22:32 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.559205233s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2257--- PASS: TestClientErrorHandling (0.00s)2258 --- PASS: TestClientErrorHandling/InvalidStorePath (0.25s)2259 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.34s)2260 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.66s)2261PASS2262{"timestamp":"2026-10-01T09:22:34.346488538Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:60272","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2354,"threadName":"rustfs-worker","threadId":"ThreadId(396)"}2263{"timestamp":"2026-10-01T09:22:34.347049227Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:60866","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2354,"threadName":"rustfs-worker","threadId":"ThreadId(397)"}2264{"timestamp":"2026-10-01T09:22:34.347350187Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:60854","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2354,"threadName":"rustfs-worker","threadId":"ThreadId(388)"}22652026-10-01 09:22:34.740 UTC [172] LOG: received smart shutdown request22662026-10-01 09:22:34.744 UTC [172] LOG: background worker "logical replication launcher" (PID 182) exited with exit code 122672026-10-01 09:22:34.755 UTC [177] LOG: shutting down22682026-10-01 09:22:34.756 UTC [177] LOG: checkpoint starting: shutdown immediate22692026-10-01 09:22:36.624 UTC [177] LOG: checkpoint complete: wrote 10804 buffers (65.9%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 28 recycled; write=0.268 s, sync=1.543 s, total=1.869 s; sync files=33362, longest=0.002 s, average=0.001 s; distance=467238 kB, estimate=467238 kB; lsn=0/1DFAF6A0, redo lsn=0/1DFAF6A022702026-10-01 09:22:36.698 UTC [172] LOG: database system is shut down2271Running OIDC tests...2272=== RUN TestAudienceForIssuer2273=== PAUSE TestAudienceForIssuer2274=== RUN TestHTTPClientForHasTimeouts2275=== PAUSE TestHTTPClientForHasTimeouts2276=== RUN TestGlobMatch2277=== PAUSE TestGlobMatch2278=== RUN TestValidateToken_ValidToken2279=== PAUSE TestValidateToken_ValidToken2280=== RUN TestValidateToken_WrongAudience2281=== PAUSE TestValidateToken_WrongAudience2282=== RUN TestValidateToken_Expired2283=== PAUSE TestValidateToken_Expired2284=== RUN TestValidateToken_BoundClaimsMismatch2285=== PAUSE TestValidateToken_BoundClaimsMismatch2286=== RUN TestValidateToken_BoundSubjectMismatch2287=== PAUSE TestValidateToken_BoundSubjectMismatch2288=== RUN TestValidateToken_MultipleProviders2289=== PAUSE TestValidateToken_MultipleProviders2290=== RUN TestValidateToken_NoMatchingProvider2291=== PAUSE TestValidateToken_NoMatchingProvider2292=== RUN TestValidateToken_KubernetesServiceAccount2293=== PAUSE TestValidateToken_KubernetesServiceAccount2294=== RUN TestNewValidator_KubernetesRequiresCA2295=== PAUSE TestNewValidator_KubernetesRequiresCA2296=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2297=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2298=== RUN TestPins_ReservedForMatchingRule2299=== PAUSE TestPins_ReservedForMatchingRule2300=== RUN TestPins_TopLevelShorthand2301=== PAUSE TestPins_TopLevelShorthand2302=== RUN TestPins_ConfigValidation2303=== PAUSE TestPins_ConfigValidation2304=== RUN TestScopes_LegacyProviderDefaultsToWrite2305=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2306=== RUN TestScopes_Rules2307=== PAUSE TestScopes_Rules2308=== RUN TestScopes_ConfigValidation2309=== PAUSE TestScopes_ConfigValidation2310=== CONT TestValidateToken_Expired2311=== CONT TestValidateToken_KubernetesServiceAccount2312=== CONT TestPins_ConfigValidation2313=== CONT TestValidateToken_WrongAudience2314=== CONT TestValidateToken_NoMatchingProvider2315=== CONT TestValidateToken_MultipleProviders2316=== CONT TestValidateToken_BoundSubjectMismatch2317--- PASS: TestPins_ConfigValidation (0.00s)2318=== CONT TestValidateToken_BoundClaimsMismatch2319=== CONT TestScopes_LegacyProviderDefaultsToWrite2320=== CONT TestScopes_ConfigValidation2321=== CONT TestGlobMatch2322=== CONT TestValidateToken_ValidToken2323=== CONT TestScopes_Rules2324=== CONT TestHTTPClientForHasTimeouts2325=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2326=== CONT TestPins_ReservedForMatchingRule2327=== CONT TestNewValidator_KubernetesRequiresCA2328=== CONT TestAudienceForIssuer2329=== CONT TestPins_TopLevelShorthand2330--- PASS: TestScopes_ConfigValidation (0.00s)2331--- PASS: TestAudienceForIssuer (0.00s)2332=== RUN TestGlobMatch/foo_foo2333=== PAUSE TestGlobMatch/foo_foo2334=== RUN TestGlobMatch/foo_bar2335=== PAUSE TestGlobMatch/foo_bar2336=== RUN TestGlobMatch/*_2337=== PAUSE TestGlobMatch/*_2338=== RUN TestGlobMatch/*_anything2339=== PAUSE TestGlobMatch/*_anything2340=== RUN TestGlobMatch/foo*_foo2341=== PAUSE TestGlobMatch/foo*_foo2342=== RUN TestGlobMatch/foo*_foobar2343=== PAUSE TestGlobMatch/foo*_foobar2344=== RUN TestGlobMatch/foo*_bar2345=== PAUSE TestGlobMatch/foo*_bar2346=== RUN TestGlobMatch/*bar_bar2347=== PAUSE TestGlobMatch/*bar_bar2348=== RUN TestGlobMatch/*bar_foobar2349=== PAUSE TestGlobMatch/*bar_foobar2350=== RUN TestGlobMatch/*bar_foo2351=== PAUSE TestGlobMatch/*bar_foo2352=== RUN TestGlobMatch/foo*bar_foobar2353=== PAUSE TestGlobMatch/foo*bar_foobar2354=== RUN TestGlobMatch/foo*bar_foo123bar2355=== PAUSE TestGlobMatch/foo*bar_foo123bar2356=== RUN TestGlobMatch/foo*bar_foobarbaz2357=== PAUSE TestGlobMatch/foo*bar_foobarbaz2358=== RUN TestGlobMatch/*/*_foo/bar2359=== PAUSE TestGlobMatch/*/*_foo/bar2360=== RUN TestGlobMatch/*/*_foo2361=== PAUSE TestGlobMatch/*/*_foo2362=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2363=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2364=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02365=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02366=== RUN TestGlobMatch/refs/*/main_refs/heads/main2367=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2368=== RUN TestGlobMatch/fo?_foo2369=== PAUSE TestGlobMatch/fo?_foo2370=== RUN TestGlobMatch/fo?_fo2371=== PAUSE TestGlobMatch/fo?_fo2372=== RUN TestGlobMatch/fo?_fooo2373=== PAUSE TestGlobMatch/fo?_fooo2374=== RUN TestGlobMatch/?oo_foo2375=== PAUSE TestGlobMatch/?oo_foo2376=== RUN TestGlobMatch/?oo_boo2377=== PAUSE TestGlobMatch/?oo_boo2378=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2379=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2380=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2381=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2382=== CONT TestGlobMatch/foo_bar2383=== CONT TestGlobMatch/foo*bar_foobarbaz2384=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2385=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2386=== CONT TestGlobMatch/?oo_boo2387=== CONT TestGlobMatch/fo?_fooo2388=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02389=== CONT TestGlobMatch/*/*_foo/bar2390=== CONT TestGlobMatch/?oo_foo2391=== CONT TestGlobMatch/fo?_foo2392=== CONT TestGlobMatch/foo*_foo2393=== CONT TestGlobMatch/foo*_bar2394=== CONT TestGlobMatch/refs/*/main_refs/heads/main2395=== CONT TestGlobMatch/*_2396=== CONT TestGlobMatch/*bar_foo2397=== CONT TestGlobMatch/foo_foo2398=== CONT TestGlobMatch/*/*_foo2399=== CONT TestGlobMatch/*bar_bar2400=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2401=== CONT TestGlobMatch/*bar_foobar2402=== CONT TestGlobMatch/*_anything2403=== CONT TestGlobMatch/fo?_fo2404=== CONT TestGlobMatch/foo*_foobar2405=== CONT TestGlobMatch/foo*bar_foobar2406=== CONT TestGlobMatch/foo*bar_foo123bar2407--- PASS: TestGlobMatch (0.01s)2408 --- PASS: TestGlobMatch/foo_bar (0.00s)2409 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2410 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2411 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2412 --- PASS: TestGlobMatch/?oo_boo (0.00s)2413 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2414 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2415 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2416 --- PASS: TestGlobMatch/?oo_foo (0.00s)2417 --- PASS: TestGlobMatch/fo?_foo (0.00s)2418 --- PASS: TestGlobMatch/foo*_foo (0.00s)2419 --- PASS: TestGlobMatch/foo*_bar (0.00s)2420 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2421 --- PASS: TestGlobMatch/*_ (0.00s)2422 --- PASS: TestGlobMatch/*bar_foo (0.00s)2423 --- PASS: TestGlobMatch/foo_foo (0.00s)2424 --- PASS: TestGlobMatch/*/*_foo (0.00s)2425 --- PASS: TestGlobMatch/*bar_bar (0.00s)2426 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2427 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2428 --- PASS: TestGlobMatch/fo?_fo (0.00s)2429 --- PASS: TestGlobMatch/*_anything (0.00s)2430 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2431 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2432 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)24332026/10/01 09:22:40 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:36637/oidc2434--- PASS: TestValidateToken_Expired (0.04s)24352026/10/01 09:22:40 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC12324362026/10/01 09:22:40 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:42381/oidc2437--- PASS: TestValidateToken_BoundClaimsMismatch (0.05s)24382026/10/01 09:22:40 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:388512439--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.05s)24402026/10/01 09:22:40 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:46593/oidc2441--- PASS: TestValidateToken_KubernetesServiceAccount (0.06s)2442--- PASS: TestPins_TopLevelShorthand (0.06s)24432026/10/01 09:22:40 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:40839/oidc24442026/10/01 09:22:40 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:42769/oidc2445--- PASS: TestValidateToken_WrongAudience (0.09s)2446--- PASS: TestValidateToken_ValidToken (0.09s)24472026/10/01 09:22:40 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:34947/oidc2448--- PASS: TestValidateToken_BoundSubjectMismatch (0.12s)24492026/10/01 09:22:40 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:40085/oidc2450--- PASS: TestValidateToken_NoMatchingProvider (0.12s)24512026/10/01 09:22:40 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:34443/oidc24522026/10/01 09:22:40 http: TLS handshake error from 127.0.0.1:49084: remote error: tls: bad certificate2453--- PASS: TestNewValidator_KubernetesRequiresCA (0.13s)2454--- PASS: TestPins_ReservedForMatchingRule (0.13s)24552026/10/01 09:22:40 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:36091/oidc2456--- PASS: TestScopes_Rules (0.16s)24572026/10/01 09:22:40 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:40237/oidc24582026/10/01 09:22:40 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:42665/oidc2459--- PASS: TestValidateToken_MultipleProviders (0.18s)2460--- PASS: TestHTTPClientForHasTimeouts (0.20s)24612026/10/01 09:22:40 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:43095/oidc2462--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.27s)2463PASS2464Running signing tests...2465=== RUN TestGenerateFingerprint2466=== PAUSE TestGenerateFingerprint2467=== RUN TestParseSigningKey2468=== PAUSE TestParseSigningKey2469=== RUN TestSignMessage2470=== PAUSE TestSignMessage2471=== RUN TestSignNarinfo2472=== PAUSE TestSignNarinfo2473=== CONT TestParseSigningKey2474=== CONT TestGenerateFingerprint2475=== RUN TestParseSigningKey/valid_32-byte_key2476=== CONT TestSignNarinfo2477=== CONT TestSignMessage2478=== RUN TestGenerateFingerprint/basic_with_references2479=== PAUSE TestParseSigningKey/valid_32-byte_key2480=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2481=== PAUSE TestGenerateFingerprint/basic_with_references2482=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2483=== RUN TestParseSigningKey/no_colon2484=== PAUSE TestParseSigningKey/no_colon2485=== RUN TestParseSigningKey/empty_name2486=== PAUSE TestParseSigningKey/empty_name2487=== RUN TestGenerateFingerprint/no_references2488=== RUN TestParseSigningKey/invalid_base642489=== PAUSE TestGenerateFingerprint/no_references2490=== PAUSE TestParseSigningKey/invalid_base642491=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2492=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2493=== RUN TestParseSigningKey/wrong_length2494=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2495=== PAUSE TestParseSigningKey/wrong_length2496=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2497=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2498=== CONT TestParseSigningKey/empty_name2499=== RUN TestGenerateFingerprint/invalid_nar_hash_length2500=== CONT TestParseSigningKey/wrong_length2501=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2502=== CONT TestParseSigningKey/no_colon2503=== CONT TestParseSigningKey/valid_32-byte_key2504=== CONT TestParseSigningKey/invalid_base642505=== RUN TestGenerateFingerprint/invalid_store_path_prefix2506=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2507=== RUN TestGenerateFingerprint/invalid_reference_prefix2508--- PASS: TestParseSigningKey (0.00s)2509 --- PASS: TestParseSigningKey/empty_name (0.00s)2510 --- PASS: TestParseSigningKey/wrong_length (0.00s)2511 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2512 --- PASS: TestParseSigningKey/no_colon (0.00s)2513 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2514 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2515=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2516=== CONT TestGenerateFingerprint/invalid_nar_hash_length2517=== CONT TestGenerateFingerprint/invalid_store_path_prefix2518=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2519=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2520=== CONT TestGenerateFingerprint/no_references2521=== CONT TestGenerateFingerprint/basic_with_references2522=== CONT TestGenerateFingerprint/invalid_reference_prefix2523--- PASS: TestSignMessage (0.00s)2524--- PASS: TestSignNarinfo (0.00s)2525--- PASS: TestGenerateFingerprint (0.00s)2526 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2527 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2528 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2529 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2530 --- PASS: TestGenerateFingerprint/no_references (0.00s)2531 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2532 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2533PASS2534Running hook tests...2535=== RUN TestSendPathsEmpty2536=== PAUSE TestSendPathsEmpty2537=== RUN TestQueueEnqueueAndFetch2538=== PAUSE TestQueueEnqueueAndFetch2539=== RUN TestQueueDeduplication2540=== PAUSE TestQueueDeduplication2541=== RUN TestQueueRemove2542=== PAUSE TestQueueRemove2543=== RUN TestQueueFetchBatchLimit2544=== PAUSE TestQueueFetchBatchLimit2545=== RUN TestQueueRetryMovesToBack2546=== PAUSE TestQueueRetryMovesToBack2547=== RUN TestQueueFetchRemoveLifecycle2548=== PAUSE TestQueueFetchRemoveLifecycle2549=== RUN TestQueueConcurrentWriters2550=== PAUSE TestQueueConcurrentWriters2551=== RUN TestQueueEnqueueWaitsOutSlowWriter2552=== PAUSE TestQueueEnqueueWaitsOutSlowWriter2553=== RUN TestQueueRemoveLargeClosure2554=== PAUSE TestQueueRemoveLargeClosure2555=== RUN TestServerClientIntegration2556=== PAUSE TestServerClientIntegration2557=== RUN TestServerQueueError2558=== PAUSE TestServerQueueError2559=== RUN TestServerRefusesOversizedAndNonStoreRequests2560=== PAUSE TestServerRefusesOversizedAndNonStoreRequests2561=== RUN TestGetListenerSocketActivation2562 server_test.go:317: === RUN TestGetListenerSocketActivation2563 --- PASS: TestGetListenerSocketActivation (0.00s)2564 PASS2565 2566--- PASS: TestGetListenerSocketActivation (1.02s)2567=== RUN TestServerStalledClientDoesNotBlockShutdown2568=== PAUSE TestServerStalledClientDoesNotBlockShutdown2569=== RUN TestServerBacksOffOnAcceptErrors2570=== PAUSE TestServerBacksOffOnAcceptErrors2571=== RUN TestDrainIsolatesPoisonPath2572=== PAUSE TestDrainIsolatesPoisonPath2573=== RUN TestRunNotBlockedByPoisonHead2574=== PAUSE TestRunNotBlockedByPoisonHead2575=== RUN TestDrainGivesUpWhenServerDown2576=== PAUSE TestDrainGivesUpWhenServerDown2577=== RUN TestFailedPathPrunedByLaterClosure2578=== PAUSE TestFailedPathPrunedByLaterClosure2579=== RUN TestWorkerUploadsAndRemoves2580=== PAUSE TestWorkerUploadsAndRemoves2581=== RUN TestWorkerSkipsGCdPaths2582=== PAUSE TestWorkerSkipsGCdPaths2583=== RUN TestWorkerPrunesClosureDeps2584=== PAUSE TestWorkerPrunesClosureDeps2585=== RUN TestWorkerRemovesCachedPathBatchedWithLargerClosure2586=== PAUSE TestWorkerRemovesCachedPathBatchedWithLargerClosure2587=== RUN TestDrainTimeout2588=== PAUSE TestDrainTimeout2589=== RUN TestDrainTimeoutDuringIsolation2590=== PAUSE TestDrainTimeoutDuringIsolation2591=== RUN TestShutdownFinishesInFlightPush2592=== PAUSE TestShutdownFinishesInFlightPush2593=== RUN TestWorkerRemoveFailureIsNotProgress2594=== PAUSE TestWorkerRemoveFailureIsNotProgress2595=== RUN TestWorkerKeepsPathItCannotStat2596=== PAUSE TestWorkerKeepsPathItCannotStat2597=== CONT TestSendPathsEmpty2598=== CONT TestServerBacksOffOnAcceptErrors2599=== CONT TestQueueRemoveLargeClosure2600=== CONT TestWorkerPrunesClosureDeps2601=== CONT TestWorkerKeepsPathItCannotStat26022026/10/01 09:22:43 ERROR Accept failed error="too many open files"2603=== CONT TestWorkerRemoveFailureIsNotProgress2604=== CONT TestShutdownFinishesInFlightPush2605=== CONT TestDrainTimeoutDuringIsolation2606=== CONT TestWorkerRemovesCachedPathBatchedWithLargerClosure2607=== RUN TestDrainTimeoutDuringIsolation/probe_cut_short2608=== CONT TestDrainTimeout2609=== CONT TestWorkerUploadsAndRemoves2610--- PASS: TestSendPathsEmpty (0.00s)2611=== CONT TestDrainIsolatesPoisonPath2612=== CONT TestServerStalledClientDoesNotBlockShutdown2613=== CONT TestServerQueueError2614=== CONT TestFailedPathPrunedByLaterClosure2615=== CONT TestServerClientIntegration2616=== CONT TestQueueEnqueueWaitsOutSlowWriter2617=== CONT TestServerRefusesOversizedAndNonStoreRequests2618=== CONT TestQueueConcurrentWriters2619=== CONT TestQueueRetryMovesToBack2620=== CONT TestQueueFetchBatchLimit26212026/10/01 09:22:43 ERROR Refusing path outside the store path=/etc/shadow store=/nix/store26222026/10/01 09:22:43 ERROR Failed to queue paths error="permission denied" count=126232026/10/01 09:22:43 ERROR Accept failed error="too many open files"2624=== CONT TestQueueFetchRemoveLifecycle26252026/10/01 09:22:43 ERROR Refusing path outside the store path=/nix/store store=/nix/store2626=== CONT TestQueueRemove2627=== CONT TestQueueEnqueueAndFetch26282026/10/01 09:22:43 ERROR Refusing path outside the store path=/nix/store/ store=/nix/store2629=== CONT TestQueueDeduplication2630=== RUN TestWorkerRemoveFailureIsNotProgress/collected_path2631--- PASS: TestServerQueueError (0.00s)2632=== RUN TestShutdownFinishesInFlightPush/completes2633=== PAUSE TestDrainTimeoutDuringIsolation/probe_cut_short26342026/10/01 09:22:43 ERROR Refusing path outside the store path=/nix/store/../../etc/shadow store=/nix/store2635=== CONT TestRunNotBlockedByPoisonHead2636=== RUN TestDrainTimeoutDuringIsolation/probe_outlasts_the_deadline2637=== PAUSE TestShutdownFinishesInFlightPush/completes2638=== PAUSE TestWorkerRemoveFailureIsNotProgress/collected_path2639--- PASS: TestServerClientIntegration (0.00s)26402026/10/01 09:22:43 ERROR Refusing path outside the store path=/nix/store/0123456789abcdfghijklmnpqrsvwxyz-hello/bin/sh store=/nix/store2641=== CONT TestWorkerSkipsGCdPaths2642=== PAUSE TestDrainTimeoutDuringIsolation/probe_outlasts_the_deadline2643=== RUN TestShutdownFinishesInFlightPush/hung_push_bounded_by_the_drain_timeout26442026/10/01 09:22:43 ERROR Refusing path outside the store path=nix/store/0123456789abcdfghijklmnpqrsvwxyz-hello store=/nix/store2645=== RUN TestWorkerRemoveFailureIsNotProgress/pushed_batch2646=== CONT TestDrainGivesUpWhenServerDown2647=== PAUSE TestShutdownFinishesInFlightPush/hung_push_bounded_by_the_drain_timeout2648=== PAUSE TestWorkerRemoveFailureIsNotProgress/pushed_batch26492026/10/01 09:22:43 ERROR Refusing path outside the store path=/nix/storeX/0123456789abcdfghijklmnpqrsvwxyz-hello store=/nix/store2650=== CONT TestDrainTimeoutDuringIsolation/probe_cut_short2651=== RUN TestWorkerRemoveFailureIsNotProgress/isolated_paths2652=== PAUSE TestWorkerRemoveFailureIsNotProgress/isolated_paths2653=== CONT TestDrainTimeoutDuringIsolation/probe_outlasts_the_deadline26542026/10/01 09:22:43 ERROR Refusing path outside the store path=/nix/store/.links store=/nix/store26552026/10/01 09:22:43 ERROR Refusing path outside the store path=/nix/store/aaa-hello store=/nix/store26562026/10/01 09:22:43 ERROR Refusing path outside the store path=/nix/store/0123456789abcdfghijklmnpqrsvwxyz store=/nix/store26572026/10/01 09:22:43 ERROR Refusing path outside the store path=/nix/store/0123456789abcdfghijklmnpqrsvwxyz- store=/nix/store26582026/10/01 09:22:43 ERROR Refusing path outside the store path=/nix/store/0123456789ebcdfghijklmnpqrsvwxyz-hello store=/nix/store26592026/10/01 09:22:43 ERROR Refusing path outside the store path="/nix/store/0123456789abcdfghijklmnpqrsvwxyz-hel\x00lo" store=/nix/store26602026/10/01 09:22:43 ERROR Refusing path outside the store path=/nix/store/0123456789abcdfghijklmnpqrsvwxyz-hel/lo store=/nix/store26612026/10/01 09:22:43 ERROR Refusing path outside the store path=/nix/store/0123456789abcdfghijklmnpqrsvwxyz-xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx store=/nix/store26622026/10/01 09:22:43 ERROR Accept failed error="too many open files"26632026/10/01 09:22:43 ERROR Failed to decode request error="unexpected EOF"2664--- PASS: TestServerRefusesOversizedAndNonStoreRequests (0.01s)2665=== CONT TestShutdownFinishesInFlightPush/hung_push_bounded_by_the_drain_timeout26662026/10/01 09:22:43 ERROR Accept failed error="too many open files"26672026/10/01 09:22:43 INFO Uploading batch count=226682026/10/01 09:22:43 INFO Upload queue status pending=226692026/10/01 09:22:43 INFO Uploading batch count=126702026/10/01 09:22:43 ERROR Upload failed error="upload failed" count=126712026/10/01 09:22:43 INFO Uploading batch count=426722026/10/01 09:22:43 ERROR Upload failed error="upload failed" count=426732026/10/01 09:22:43 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat2498439126/002/locked/aaa error="lstat /build/TestWorkerKeepsPathItCannotStat2498439126/002/locked/aaa: permission denied"26742026/10/01 09:22:43 INFO Upload queue status pending=226752026/10/01 09:22:43 INFO Uploading batch count=226762026/10/01 09:22:43 INFO Uploading batch count=126772026/10/01 09:22:43 INFO Upload queue status pending=226782026/10/01 09:22:43 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainIsolatesPoisonPath837303465/002/bbb26792026/10/01 09:22:43 INFO Uploading batch count=226802026/10/01 09:22:43 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat2498439126/002/locked/aaa error="lstat /build/TestWorkerKeepsPathItCannotStat2498439126/002/locked/aaa: permission denied"26812026/10/01 09:22:43 INFO Upload queue status pending=326822026/10/01 09:22:43 INFO Uploading batch count=126832026/10/01 09:22:43 INFO Upload queue status pending=32684=== CONT TestShutdownFinishesInFlightPush/completes2685--- PASS: TestQueueEnqueueAndFetch (0.07s)26862026/10/01 09:22:43 INFO Upload queue status pending=226872026/10/01 09:22:43 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerSkipsGCdPaths2314677955/002/nonexistent26882026/10/01 09:22:43 INFO Uploading batch count=126892026/10/01 09:22:43 ERROR Upload failed error="upload failed" count=126902026/10/01 09:22:43 INFO Uploading batch count=226912026/10/01 09:22:43 INFO Uploading batch count=426922026/10/01 09:22:43 ERROR Upload failed error="upload failed" count=426932026/10/01 09:22:43 INFO Uploading batch count=426942026/10/01 09:22:43 ERROR Upload failed error="upload failed" count=426952026/10/01 09:22:43 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat2498439126/002/locked/aaa error="lstat /build/TestWorkerKeepsPathItCannotStat2498439126/002/locked/aaa: permission denied"26962026/10/01 09:22:43 ERROR Accept failed error="too many open files"2697--- PASS: TestQueueRetryMovesToBack (0.07s)26982026/10/01 09:22:43 INFO Uploading batch count=22699=== CONT TestWorkerRemoveFailureIsNotProgress/pushed_batch27002026/10/01 09:22:43 INFO Uploading batch count=12701--- PASS: TestQueueFetchBatchLimit (0.07s)2702=== CONT TestWorkerRemoveFailureIsNotProgress/isolated_paths2703--- PASS: TestQueueDeduplication (0.07s)2704=== CONT TestWorkerRemoveFailureIsNotProgress/collected_path27052026/10/01 09:22:43 ERROR Drain finished with paths left in queue remaining=127062026/10/01 09:22:43 INFO Uploading batch count=227072026/10/01 09:22:43 ERROR Upload failed error="upload failed" count=227082026/10/01 09:22:43 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown3513130985/002/a2709--- PASS: TestQueueRemove (0.07s)27102026/10/01 09:22:43 INFO Uploading batch count=127112026/10/01 09:22:43 ERROR Upload failed error="upload failed" count=127122026/10/01 09:22:43 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown3513130985/002/b27132026/10/01 09:22:43 INFO Uploading batch count=127142026/10/01 09:22:43 ERROR Upload failed error="upload failed" count=12715--- PASS: TestWorkerKeepsPathItCannotStat (0.09s)27162026/10/01 09:22:43 INFO Uploading batch count=227172026/10/01 09:22:43 ERROR Upload failed error="upload failed" count=227182026/10/01 09:22:43 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown3513130985/002/c2719--- PASS: TestFailedPathPrunedByLaterClosure (0.09s)2720--- PASS: TestQueueFetchRemoveLifecycle (0.09s)2721--- PASS: TestWorkerRemovesCachedPathBatchedWithLargerClosure (0.09s)27222026/10/01 09:22:43 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown3513130985/002/d2723--- PASS: TestWorkerPrunesClosureDeps (0.10s)27242026/10/01 09:22:43 INFO Uploading batch count=127252026/10/01 09:22:43 ERROR Upload failed error="upload failed" count=12726--- PASS: TestWorkerSkipsGCdPaths (0.09s)27272026/10/01 09:22:43 ERROR Drain finished with paths left in queue remaining=127282026/10/01 09:22:43 INFO Uploading batch count=227292026/10/01 09:22:43 ERROR Upload failed error="upload failed" count=227302026/10/01 09:22:43 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown3513130985/002/e2731--- PASS: TestWorkerUploadsAndRemoves (0.10s)27322026/10/01 09:22:43 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown3513130985/002/f2733--- PASS: TestDrainIsolatesPoisonPath (0.10s)27342026/10/01 09:22:43 ERROR Drain finished with paths left in queue remaining=1027352026/10/01 09:22:43 INFO Upload queue status pending=227362026/10/01 09:22:43 INFO Uploading batch count=22737--- PASS: TestDrainGivesUpWhenServerDown (0.10s)27382026/10/01 09:22:43 INFO Uploading batch count=227392026/10/01 09:22:43 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgresscollected_path3375147441/001/nonexistent27402026/10/01 09:22:43 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=227412026/10/01 09:22:43 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=127422026/10/01 09:22:43 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgresscollected_path3375147441/001/nonexistent27432026/10/01 09:22:43 INFO Uploading batch count=227442026/10/01 09:22:43 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=127452026/10/01 09:22:43 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=227462026/10/01 09:22:43 INFO Uploading batch count=227472026/10/01 09:22:43 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgresscollected_path3375147441/001/nonexistent27482026/10/01 09:22:43 ERROR Upload failed error="upload failed" count=227492026/10/01 09:22:43 INFO Uploading batch count=227502026/10/01 09:22:43 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=127512026/10/01 09:22:43 ERROR Drain finished with paths left in queue remaining=127522026/10/01 09:22:43 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=227532026/10/01 09:22:43 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=127542026/10/01 09:22:43 ERROR Drain finished with paths left in queue remaining=227552026/10/01 09:22:43 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=127562026/10/01 09:22:43 INFO Uploading batch count=227572026/10/01 09:22:43 ERROR Upload failed error="upload failed" count=227582026/10/01 09:22:43 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=127592026/10/01 09:22:43 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=127602026/10/01 09:22:43 INFO Uploading batch count=227612026/10/01 09:22:43 ERROR Upload failed error="upload failed" count=227622026/10/01 09:22:43 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=127632026/10/01 09:22:43 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=127642026/10/01 09:22:43 ERROR Drain finished with paths left in queue remaining=22765--- PASS: TestWorkerRemoveFailureIsNotProgress (0.01s)2766 --- PASS: TestWorkerRemoveFailureIsNotProgress/collected_path (0.04s)2767 --- PASS: TestWorkerRemoveFailureIsNotProgress/pushed_batch (0.04s)2768 --- PASS: TestWorkerRemoveFailureIsNotProgress/isolated_paths (0.05s)27692026/10/01 09:22:43 ERROR Accept failed error="too many open files"27702026/10/01 09:22:43 ERROR Failed to decode request error="read unix /build/hook2991271935/test.sock->@: i/o timeout"27712026/10/01 09:22:43 ERROR Failed to write response error="write unix /build/hook2991271935/test.sock->@: i/o timeout"2772--- PASS: TestServerStalledClientDoesNotBlockShutdown (0.20s)27732026/10/01 09:22:43 ERROR Upload failed error="context canceled" count=227742026/10/01 09:22:43 ERROR Drain finished with paths left in queue remaining=42775--- PASS: TestDrainTimeout (0.26s)27762026/10/01 09:22:43 ERROR Upload failed error="context canceled" count=227772026/10/01 09:22:43 ERROR Drain finished with paths left in queue remaining=227782026/10/01 09:22:43 ERROR Drain finished with paths left in queue remaining=42779--- PASS: TestShutdownFinishesInFlightPush (0.01s)2780 --- PASS: TestShutdownFinishesInFlightPush/completes (0.14s)2781 --- PASS: TestShutdownFinishesInFlightPush/hung_push_bounded_by_the_drain_timeout (0.26s)27822026/10/01 09:22:43 ERROR Accept failed error="too many open files"27832026/10/01 09:22:43 ERROR Drain finished with paths left in queue remaining=32784--- PASS: TestDrainTimeoutDuringIsolation (0.01s)2785 --- PASS: TestDrainTimeoutDuringIsolation/probe_cut_short (0.27s)2786 --- PASS: TestDrainTimeoutDuringIsolation/probe_outlasts_the_deadline (0.37s)27872026/10/01 09:22:44 ERROR Accept failed error="too many open files"2788--- PASS: TestServerBacksOffOnAcceptErrors (0.64s)2789--- PASS: TestQueueConcurrentWriters (0.68s)27902026/10/01 09:22:44 INFO Uploading batch count=127912026/10/01 09:22:44 INFO Uploading batch count=127922026/10/01 09:22:44 INFO Uploading batch count=127932026/10/01 09:22:44 ERROR Upload failed error="upload failed" count=127942026/10/01 09:22:44 INFO Uploading batch count=127952026/10/01 09:22:44 ERROR Upload failed error="upload failed" count=127962026/10/01 09:22:44 INFO Uploading batch count=127972026/10/01 09:22:44 ERROR Upload failed error="upload failed" count=127982026/10/01 09:22:44 INFO Uploading batch count=127992026/10/01 09:22:44 ERROR Upload failed error="upload failed" count=128002026/10/01 09:22:44 ERROR Drain finished with paths left in queue remaining=12801--- PASS: TestRunNotBlockedByPoisonHead (1.10s)2802--- PASS: TestQueueRemoveLargeClosure (2.05s)2803--- PASS: TestQueueEnqueueWaitsOutSlowWriter (6.06s)2804PASS2805Running niks3-hook command tests...2806=== RUN TestServeSecondSignalEndsDrain2807=== PAUSE TestServeSecondSignalEndsDrain2808=== RUN TestServeThenDrainPushesSendAcceptedBeforeShutdown2809=== PAUSE TestServeThenDrainPushesSendAcceptedBeforeShutdown2810=== CONT TestServeThenDrainPushesSendAcceptedBeforeShutdown2811=== CONT TestServeSecondSignalEndsDrain2812--- PASS: TestServeSecondSignalEndsDrain (0.08s)28132026/10/01 09:22:50 INFO Upload queue status pending=128142026/10/01 09:22:50 INFO Uploading batch count=12815--- PASS: TestServeThenDrainPushesSendAcceptedBeforeShutdown (0.13s)2816PASS2817Running rate limiter tests...2818=== RUN TestAdaptiveRateLimiter_ThreadSafety2819=== PAUSE TestAdaptiveRateLimiter_ThreadSafety2820=== CONT TestAdaptiveRateLimiter_ThreadSafety28212026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=7028222026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=4928232026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=34.328242026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=24.00999999999999828252026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=16.80728262026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=11.76489999999999928272026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=8.2354328282026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=5.76480099999999928292026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528302026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528312026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528322026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528332026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528342026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528352026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528362026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528372026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528382026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528392026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528402026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528412026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528422026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528432026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528442026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528452026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528462026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528472026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528482026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=5.12435000000000128492026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528502026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528512026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528522026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528532026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528542026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528552026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528562026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528572026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528582026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528592026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528602026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528612026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528622026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528632026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528642026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528652026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528662026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528672026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528682026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528692026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528702026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528712026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528722026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528732026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528742026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528752026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528762026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528772026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528782026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528792026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528802026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=8.25281691850000428812026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=5.77697184295000328822026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528832026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528842026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528852026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528862026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528872026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528882026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528892026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528902026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528912026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528922026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528932026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528942026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528952026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528962026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528972026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=528982026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=5.12435000000000128992026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=529002026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=529012026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=8.25281691850000429022026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=5.77697184295000329032026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=529042026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=529052026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=529062026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=529072026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=529082026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=529092026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=529102026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=529112026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=529122026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=529132026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=529142026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=6.200463500000001529152026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=529162026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=529172026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=529182026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=7.50256083500000329192026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=5.25179258450000229202026/10/01 09:22:51 WARN Rate limiter backed off name=test rate=52921--- PASS: TestAdaptiveRateLimiter_ThreadSafety (0.10s)2922PASS