niks3-go-unit-tests
checks.x86_64-linux.go-unit-tests
· build #327
· 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.05s)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.61s)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 TestRegisterUploadedObjectReusesConnections129=== CONT TestScriptTokenScriptFails130=== CONT TestConvertHashToNix32131=== CONT TestStreamPushReportsSignatures132=== CONT TestPathInfoHashCompatibility133=== CONT TestDumpPathSingleFile134=== CONT TestScriptTokenDoesNotWaitForItsChildren135=== CONT TestScriptTokenEmptyCommand136=== CONT TestTruncatedNARDumpIsNotCompleted137=== CONT TestParsePathInfoJSONMultiplePaths138=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths139=== CONT TestEncodeNixBase32140=== RUN TestEncodeNixBase32/test_string_hash141=== CONT TestCompletePendingClosure_NotFoundWithoutKey142=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths143=== CONT TestEncodeNixBase32WithRealHash144=== CONT TestDumpPathMatchesNix145=== CONT TestGetStorePathHash146=== RUN TestGetStorePathHash/valid_store_path147=== CONT TestFilterOversizedClosures148=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica149=== PAUSE TestGetStorePathHash/valid_store_path150=== RUN TestGetStorePathHash/basename_without_hyphen_should_error151=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error152=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error153=== CONT TestUploadMultipart_FailedPartBufferNotReused154=== CONT TestPushPathsReportsOnlyUnuploadablePathsOfSkippedClosure155=== CONT TestRateLimiterFeedback156=== CONT TestResolveStorePath157=== CONT TestSupersededNARStillUploadsListing158=== RUN TestConvertHashToNix32/SRI_format_to_Nix32159=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess160=== CONT TestShellSplitErrors161=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)162=== RUN TestScriptTokenDoesNotWaitForItsChildren/cancelled_while_a_child_runs163=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths164--- PASS: TestEncodeNixBase32WithRealHash (0.00s)165=== CONT TestFileTokenReadsAndCaches166=== CONT TestStreamPushReportsEveryPath167=== PAUSE TestEncodeNixBase32/test_string_hash168=== CONT TestUploadMultipart_ProducerErrorIsNotEOF169=== CONT TestScriptTokenEmptyToken170=== CONT TestScriptTokenNoExpiryRerunsEveryCall171=== RUN TestFilterOversizedClosures/no_limit_keeps_everything172=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error173=== RUN TestRateLimiterFeedback/429_enables_limiter174=== RUN TestSupersededNARStillUploadsListing/small_NAR175=== CONT TestDumpPathWriterError176=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)177=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32178=== PAUSE TestScriptTokenDoesNotWaitForItsChildren/cancelled_while_a_child_runs179=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths180--- PASS: TestScriptTokenEmptyCommand (0.00s)181=== RUN TestUploadMultipart_ProducerErrorIsNotEOF/short_read_inside_a_part182=== RUN TestEncodeNixBase32/empty_input183=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything184=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped185=== PAUSE TestEncodeNixBase32/empty_input186=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped187=== CONT TestParsePathInfoJSON188=== PAUSE TestUploadMultipart_ProducerErrorIsNotEOF/short_read_inside_a_part189=== RUN TestParsePathInfoJSON/Nix_format190=== RUN TestUploadMultipart_ProducerErrorIsNotEOF/empty_read_on_a_part_boundary191=== CONT TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent192=== RUN TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/committed_earlier193=== RUN TestFilterOversizedClosures/all_closures_skipped194=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error195=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error196=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon197=== CONT TestShellSplit198=== CONT TestClientSignaturesByStorePath199=== PAUSE TestSupersededNARStillUploadsListing/small_NAR200=== CONT TestFileTokenEmpty201=== RUN TestScriptTokenDoesNotWaitForItsChildren/child_left_holding_stdout202=== CONT TestUploadMultipart_PartsInParallel203=== RUN TestConvertHashToNix32/already_Nix32_format204--- PASS: TestScriptTokenScriptFails (0.01s)205=== CONT TestPathInfoCACompatibility206=== PAUSE TestRateLimiterFeedback/429_enables_limiter207=== PAUSE TestParsePathInfoJSON/Nix_format208=== PAUSE TestUploadMultipart_ProducerErrorIsNotEOF/empty_read_on_a_part_boundary209=== PAUSE TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/committed_earlier210=== PAUSE TestFilterOversizedClosures/all_closures_skipped211=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun212=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon213=== RUN TestSupersededNARStillUploadsListing/dump_cut_short214=== CONT TestStreamPushRequestLine215=== PAUSE TestScriptTokenDoesNotWaitForItsChildren/child_left_holding_stdout216=== CONT TestStreamPushGivesUpOnDeadServer217=== PAUSE TestConvertHashToNix32/already_Nix32_format218--- PASS: TestStreamPushReportsSignatures (0.01s)219=== RUN TestPathInfoCACompatibility/null_ca_field220=== RUN TestParsePathInfoJSON/Lix_format221=== RUN TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/cleaned_up222=== RUN TestRateLimiterFeedback/503_enables_limiter223=== CONT TestDoWithRetry_FinalResponseBodyReadable224=== CONT TestStreamPushIsolatesFailures225=== CONT TestScriptTokenBadJSON226=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI227=== PAUSE TestSupersededNARStillUploadsListing/dump_cut_short228=== RUN TestConvertHashToNix32/invalid_format229=== CONT TestSetClientTLSDoesNotMutateDefaultTransport230--- PASS: TestCompletePendingClosure_NotFoundWithoutKey (0.01s)231=== PAUSE TestParsePathInfoJSON/Lix_format232=== PAUSE TestPathInfoCACompatibility/null_ca_field233=== PAUSE TestRateLimiterFeedback/503_enables_limiter234=== PAUSE TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/cleaned_up235=== CONT TestScriptTokenCachesUntilRefresh236=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI237=== RUN TestSupersededNARStillUploadsListing/listing_upload_fails238=== PAUSE TestConvertHashToNix32/invalid_format239=== CONT TestFileTokenMissing240=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry241--- PASS: TestStreamPushGivesUpOnDeadServer (0.01s)242=== CONT TestCaseHackSuffix243=== RUN TestParsePathInfoJSON/empty_input244=== RUN TestPathInfoCACompatibility/old_string_format_-_text245=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter246=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512247=== PAUSE TestSupersededNARStillUploadsListing/listing_upload_fails248=== CONT TestSetClientTLSErrors249=== CONT TestUploadMultipart_SupersededByPeer250=== RUN TestUploadMultipart_SupersededByPeer/exists251=== PAUSE TestUploadMultipart_SupersededByPeer/exists252=== PAUSE TestParsePathInfoJSON/empty_input253=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text254=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter255=== CONT TestDoWithRetry_BodyReplayedViaGetBody256=== CONT TestSetClientTLS257=== RUN TestSetClientTLSErrors/missing_cert_file258=== CONT TestStreamPushBatchesUnderLoad259=== RUN TestStreamPushBatchesUnderLoad/together260=== CONT TestPartSizeForNAR261--- PASS: TestShellSplitErrors (0.00s)262=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512263=== CONT TestStaticToken264=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive265=== RUN TestPartSizeForNAR/zero_stays_at_minimum266=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter267=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter268=== CONT TestDoServerRequestAttachesToken269=== PAUSE TestStreamPushBatchesUnderLoad/together270=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum271=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths272=== RUN TestStreamPushBatchesUnderLoad/one_at_a_time273=== RUN TestPartSizeForNAR/small_stays_at_minimum274=== PAUSE TestStreamPushBatchesUnderLoad/one_at_a_time275=== PAUSE TestPartSizeForNAR/small_stays_at_minimum276=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths277=== RUN TestUploadMultipart_SupersededByPeer/missing278=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive279=== PAUSE TestUploadMultipart_SupersededByPeer/missing280=== RUN TestPathInfoCACompatibility/new_structured_format_-_text281=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum282--- PASS: TestResolveStorePath (0.00s)283=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error284=== RUN TestParsePathInfoJSON/whitespace_only285=== PAUSE TestParsePathInfoJSON/whitespace_only286=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error287=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer288=== RUN TestParsePathInfoJSON/invalid_JSON289=== CONT TestGetStorePathHash/basename_without_hyphen_should_error290=== PAUSE TestSetClientTLSErrors/missing_cert_file291=== RUN TestSetClientTLSErrors/missing_key_file292=== CONT TestStreamPushStopsOnCancel293=== RUN TestStreamPushStopsOnCancel/waiting_for_input294=== PAUSE TestSetClientTLSErrors/missing_key_file295=== CONT TestGetStorePathHash/valid_store_path296=== PAUSE TestStreamPushStopsOnCancel/waiting_for_input297=== RUN TestStreamPushStopsOnCancel/partial_batch_waiting_for_a_slot298=== PAUSE TestStreamPushStopsOnCancel/partial_batch_waiting_for_a_slot299=== CONT TestUploadMultipart_ProducerErrorIsNotEOF/short_read_inside_a_part300=== CONT TestEncodeNixBase32/empty_input301=== RUN TestSetClientTLSErrors/missing_ca_file302=== PAUSE TestSetClientTLSErrors/missing_ca_file303=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text304=== CONT TestEncodeNixBase32/test_string_hash305=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum306--- PASS: TestStreamPushReportsEveryPath (0.00s)307=== PAUSE TestParsePathInfoJSON/invalid_JSON308=== CONT TestFilterOversizedClosures/no_limit_keeps_everything309=== CONT TestScriptTokenDoesNotWaitForItsChildren/child_left_holding_stdout310=== CONT TestScriptTokenDoesNotWaitForItsChildren/cancelled_while_a_child_runs311=== RUN TestStreamPushStopsOnCancel/input_closed,_last_batch_waiting_for_a_slot312=== CONT TestFilterOversizedClosures/all_closures_skipped313=== RUN TestSetClientTLSErrors/invalid_ca_file314=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts315=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped316=== CONT TestConvertHashToNix32/invalid_format317=== CONT TestConvertHashToNix32/already_Nix32_format318=== CONT TestConvertHashToNix32/SRI_format_to_Nix32319=== CONT TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/committed_earlier320--- PASS: TestFileTokenReadsAndCaches (0.00s)321=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method322=== CONT TestUploadMultipart_ProducerErrorIsNotEOF/empty_read_on_a_part_boundary323=== CONT TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/cleaned_up324=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts325=== PAUSE TestStreamPushStopsOnCancel/input_closed,_last_batch_waiting_for_a_slot326=== PAUSE TestSetClientTLSErrors/invalid_ca_file327=== CONT TestSupersededNARStillUploadsListing/listing_upload_fails328--- PASS: TestScriptTokenEmptyToken (0.11s)329=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method330=== RUN TestPartSizeForNAR/1_TiB331--- PASS: TestShellSplit (0.00s)332--- PASS: TestClientSignaturesByStorePath (0.00s)333=== CONT TestSupersededNARStillUploadsListing/dump_cut_short334--- PASS: TestDumpPathSingleFile (0.13s)335--- PASS: TestFileTokenEmpty (0.00s)336--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.12s)337=== CONT TestSupersededNARStillUploadsListing/small_NAR338--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.12s)339--- PASS: TestStreamPushIsolatesFailures (0.00s)340--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.01s)341--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.01s)342--- PASS: TestFileTokenMissing (0.00s)343--- PASS: TestScriptTokenBadJSON (0.01s)344--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.01s)345--- PASS: TestStaticToken (0.00s)346--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.01s)347=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512348=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon349=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter350--- PASS: TestDoServerRequestAttachesToken (0.00s)351=== CONT TestRateLimiterFeedback/429_enables_limiter352=== CONT TestRateLimiterFeedback/503_enables_limiter353=== RUN TestStreamPushStopsOnCancel/full_batch_waiting_for_a_slot354=== PAUSE TestStreamPushStopsOnCancel/full_batch_waiting_for_a_slot355=== PAUSE TestPartSizeForNAR/1_TiB356=== RUN TestStreamPushStopsOnCancel/request_line_waiting_for_a_slot357--- PASS: TestScriptTokenCachesUntilRefresh (0.12s)358=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI359=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter360--- PASS: TestCaseHackSuffix (0.12s)361=== RUN TestSetClientTLS/rejects_connection_without_client_cert362=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)363=== PAUSE TestStreamPushStopsOnCancel/request_line_waiting_for_a_slot364=== RUN TestPartSizeForNAR/5_TiB_S3_max_object365--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.12s)366=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert367=== RUN TestStreamPushStopsOnCancel/lines_read_but_not_taken368=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object369=== CONT TestStreamPushBatchesUnderLoad/together370=== CONT TestStreamPushBatchesUnderLoad/one_at_a_time371=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA372=== CONT TestUploadMultipart_SupersededByPeer/exists373=== CONT TestParsePathInfoJSON/empty_input374=== CONT TestParsePathInfoJSON/whitespace_only375--- PASS: TestParsePathInfoJSONMultiplePaths (0.01s)376 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)377 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)378=== PAUSE TestStreamPushStopsOnCancel/lines_read_but_not_taken379=== RUN TestPartSizeForNAR/capped_at_5_GiB380=== CONT TestSetClientTLSErrors/invalid_ca_file381=== PAUSE TestPartSizeForNAR/capped_at_5_GiB382=== CONT TestParsePathInfoJSON/invalid_JSON383=== CONT TestParsePathInfoJSON/Lix_format384=== CONT TestUploadMultipart_SupersededByPeer/missing385=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive386=== CONT TestParsePathInfoJSON/Nix_format387--- PASS: TestGetStorePathHash (0.12s)388 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)389 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)390 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)391 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)392=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA393=== CONT TestSetClientTLSErrors/missing_ca_file394=== CONT TestSetClientTLSErrors/missing_key_file395=== CONT TestSetClientTLSErrors/missing_cert_file396=== CONT TestStreamPushStopsOnCancel/full_batch_waiting_for_a_slot397=== CONT TestStreamPushStopsOnCancel/request_line_waiting_for_a_slot398=== CONT TestPathInfoCACompatibility/null_ca_field399=== CONT TestPathInfoCACompatibility/new_structured_format_-_text400=== CONT TestPathInfoCACompatibility/old_string_format_-_text401=== CONT TestStreamPushStopsOnCancel/partial_batch_waiting_for_a_slot402--- PASS: TestEncodeNixBase32 (0.01s)403 --- PASS: TestEncodeNixBase32/empty_input (0.00s)404 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)405=== RUN TestSetClientTLS/preserves_debug_logging_transport406=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method407=== CONT TestStreamPushStopsOnCancel/lines_read_but_not_taken408=== CONT TestStreamPushStopsOnCancel/input_closed,_last_batch_waiting_for_a_slot409=== CONT TestStreamPushStopsOnCancel/waiting_for_input410=== CONT TestPartSizeForNAR/capped_at_5_GiB411=== CONT TestPartSizeForNAR/5_TiB_S3_max_object412--- PASS: TestPushPathsReportsOnlyUnuploadablePathsOfSkippedClosure (0.25s)413=== PAUSE TestSetClientTLS/preserves_debug_logging_transport414=== CONT TestPartSizeForNAR/zero_stays_at_minimum415=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts416=== CONT TestPartSizeForNAR/1_TiB417--- PASS: TestFilterOversizedClosures (0.12s)418 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)419 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)420 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)421--- PASS: TestConvertHashToNix32 (0.14s)422 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)423 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)424 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)425=== CONT TestPartSizeForNAR/small_stays_at_minimum426=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA427=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum428=== CONT TestSetClientTLS/preserves_debug_logging_transport429=== CONT TestSetClientTLS/rejects_connection_without_client_cert430--- PASS: TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent (0.12s)431 --- PASS: TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/committed_earlier (0.22s)432 --- PASS: TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/cleaned_up (0.11s)433--- PASS: TestPathInfoHashCompatibility (0.15s)434 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)435 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)436 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)437 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)438--- PASS: TestRateLimiterFeedback (0.13s)439 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.01s)440 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)441 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.01s)442 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.01s)443--- PASS: TestStreamPushBatchesUnderLoad (0.00s)444 --- PASS: TestStreamPushBatchesUnderLoad/together (0.00s)445 --- PASS: TestStreamPushBatchesUnderLoad/one_at_a_time (0.00s)446--- PASS: TestParsePathInfoJSON (0.13s)447 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)448 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)449 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)450 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)451 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)452--- PASS: TestSetClientTLSErrors (0.11s)453 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)454 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)455 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)456 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)457--- PASS: TestUploadMultipart_SupersededByPeer (0.01s)458 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)459 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.14s)460--- PASS: TestPathInfoCACompatibility (0.12s)461 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)462 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)463 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)464 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)465 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)466--- PASS: TestPartSizeForNAR (0.13s)467 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)468 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)469 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)470 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)471 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)472 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)473 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)474--- PASS: TestDumpPathWriterError (0.45s)475--- PASS: TestStreamPushStopsOnCancel (0.13s)476 --- PASS: TestStreamPushStopsOnCancel/request_line_waiting_for_a_slot (0.05s)477 --- PASS: TestStreamPushStopsOnCancel/full_batch_waiting_for_a_slot (0.05s)478 --- PASS: TestStreamPushStopsOnCancel/partial_batch_waiting_for_a_slot (0.05s)479 --- PASS: TestStreamPushStopsOnCancel/waiting_for_input (0.05s)480 --- PASS: TestStreamPushStopsOnCancel/input_closed,_last_batch_waiting_for_a_slot (0.05s)481 --- PASS: TestStreamPushStopsOnCancel/lines_read_but_not_taken (0.06s)482--- PASS: TestSetClientTLS (0.28s)483 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.04s)484 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.04s)485 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.09s)486--- PASS: TestRegisterUploadedObjectReusesConnections (0.59s)487--- PASS: TestStreamPushRequestLine (0.49s)488--- PASS: TestDumpPathMatchesNix (0.65s)489--- PASS: TestUploadMultipart_ProducerErrorIsNotEOF (0.12s)490 --- PASS: TestUploadMultipart_ProducerErrorIsNotEOF/empty_read_on_a_part_boundary (0.53s)491 --- PASS: TestUploadMultipart_ProducerErrorIsNotEOF/short_read_inside_a_part (0.56s)492--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)493--- PASS: TestTruncatedNARDumpIsNotCompleted (1.42s)494--- PASS: TestSupersededNARStillUploadsListing (0.13s)495 --- PASS: TestSupersededNARStillUploadsListing/small_NAR (0.16s)496 --- PASS: TestSupersededNARStillUploadsListing/listing_upload_fails (0.19s)497 --- PASS: TestSupersededNARStillUploadsListing/dump_cut_short (1.27s)498--- PASS: TestUploadMultipart_PartsInParallel (1.44s)499--- PASS: TestUploadMultipart_FailedPartBufferNotReused (1.60s)500--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (2.00s)501--- PASS: TestScriptTokenDoesNotWaitForItsChildren (0.13s)502 --- PASS: TestScriptTokenDoesNotWaitForItsChildren/child_left_holding_stdout (2.11s)503 --- PASS: TestScriptTokenDoesNotWaitForItsChildren/cancelled_while_a_child_runs (2.27s)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/postgres113873003/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/postgres113873003/data -l logfile start532533/build/postgres113873003:5432 - no response5342026-10-01 09:57:42.039 UTC [171] LOG: starting PostgreSQL 18.6 on x86_64-pc-linux-gnu, compiled by clang version 21.1.8, 64-bit5352026-10-01 09:57:42.040 UTC [171] LOG: listening on Unix socket "/build/postgres113873003/.s.PGSQL.5432"5362026-10-01 09:57:42.044 UTC [178] LOG: database system was shut down at 2026-10-01 09:57:41 UTC5372026-10-01 09:57:42.047 UTC [171] LOG: database system is ready to accept connections538/build/postgres113873003:5432 - accepting connections539{"timestamp":"2026-10-01T09:57:42.354367833Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"b10521ac-afca-4e36-b4e7-b2ac87215ab0","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":1,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":501,"threadName":"rustfs-worker","threadId":"ThreadId(398)"}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:57:42 INFO lead: acquired remote=192.0.2.1:12345882026/10/01 09:57:43 INFO lead: released remote=192.0.2.1:12345892026/10/01 09:57:43 INFO lead: acquired remote=192.0.2.1:12345902026/10/01 09:57:44 INFO lead: released remote=192.0.2.1:1234591--- PASS: TestLeadIncumbentWinsAfterRestart (2.32s)592=== RUN TestLeadEndsOnShutdown593=== PAUSE TestLeadEndsOnShutdown594=== RUN TestLeadEndsWhenItsConnectionHangs5952026/10/01 09:57:44 INFO lead: acquired remote=192.0.2.1:12345962026-10-01 09:57:46.140 UTC [620] FATAL: terminating connection due to administrator command5972026/10/01 09:57:46 INFO lead: acquired remote=192.0.2.1:12345982026/10/01 09:57:47 WARN lead: lock connection lost error="timeout: context deadline exceeded"5992026/10/01 09:57:47 INFO lead: released remote=192.0.2.1:12346002026/10/01 09:57:47 INFO lead: released remote=192.0.2.1:1234601--- PASS: TestLeadEndsWhenItsConnectionHangs (2.77s)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:57:47 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7702026/10/01 09:57:47 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7712026/10/01 09:57:47 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7722026/10/01 09:57:47 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7732026/10/01 09:57:47 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7742026/10/01 09:57:47 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7752026/10/01 09:57:47 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7762026/10/01 09:57:47 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7772026/10/01 09:57:47 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7782026/10/01 09:57:47 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 TestPush_SignsNarinfosOfItsPendingObjects803=== CONT TestService_AuthMiddleware804=== CONT TestProxyWriteTimeout805=== CONT TestPush_RejectsBadRequests806=== CONT TestPush_CompleteCommitsEveryRoot807=== CONT TestPush_OverlappingRootsStoreOneRowPerKey808=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit809=== CONT TestReadRedirectUsesPublicS3URL810=== CONT TestReadProxyRangeRequest811=== CONT TestReadRedirectNar812=== CONT TestReadProxyDisabled813=== CONT TestReadRedirectKeepsNarinfoProxied814=== CONT TestReadProxyConditionalGet815=== CONT TestReadProxyRootRedirectsToIndexHTML816=== CONT TestReadProxyHead817=== CONT TestReadProxyOutlastsServerWriteTimeout818=== CONT TestReadProxyInvalidPath819=== CONT TestReadProxyNarStreaming820=== CONT TestReadProxy404821=== CONT TestIsValidCachePath822=== RUN TestIsValidCachePath/narinfo823=== CONT TestUploadHandlersRejectOversizedBody824=== CONT TestProxyHeadersOnlyTrustedOnSocket825=== CONT TestReadProxyNarinfo826=== CONT TestParseSingleRange827=== RUN TestProxyWriteTimeout/narinfo828=== PAUSE TestIsValidCachePath/narinfo829=== RUN TestParseSingleRange/none830=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars831=== PAUSE TestParseSingleRange/none832=== PAUSE TestProxyWriteTimeout/narinfo833=== RUN TestParseSingleRange/unknown_unit834=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars835=== RUN TestProxyWriteTimeout/1_GiB_nar836=== PAUSE TestParseSingleRange/unknown_unit837=== PAUSE TestProxyWriteTimeout/1_GiB_nar838=== RUN TestIsValidCachePath/nar_zst839=== RUN TestParseSingleRange/multi-range_ignored840=== RUN TestProxyWriteTimeout/10_GiB_nar841=== PAUSE TestIsValidCachePath/nar_zst842=== PAUSE TestParseSingleRange/multi-range_ignored843=== RUN TestIsValidCachePath/nar_xz844=== RUN TestParseSingleRange/malformed_no_dash845=== PAUSE TestIsValidCachePath/nar_xz846=== PAUSE TestParseSingleRange/malformed_no_dash847=== PAUSE TestProxyWriteTimeout/10_GiB_nar848=== RUN TestParseSingleRange/malformed_both_empty849=== RUN TestProxyWriteTimeout/unknown_size850=== RUN TestIsValidCachePath/nar_bz2851=== PAUSE TestParseSingleRange/malformed_both_empty852=== PAUSE TestProxyWriteTimeout/unknown_size853=== PAUSE TestIsValidCachePath/nar_bz2854=== CONT TestReadProxyNarinfoAlreadyDecompressed855=== RUN TestIsValidCachePath/nar_uncompressed856=== RUN TestParseSingleRange/malformed_end_before_start857=== PAUSE TestIsValidCachePath/nar_uncompressed858=== PAUSE TestParseSingleRange/malformed_end_before_start859=== RUN TestIsValidCachePath/ls860=== RUN TestParseSingleRange/closed861=== PAUSE TestParseSingleRange/closed862=== PAUSE TestIsValidCachePath/ls863=== RUN TestParseSingleRange/open-ended864=== RUN TestIsValidCachePath/log865=== PAUSE TestIsValidCachePath/log866=== PAUSE TestParseSingleRange/open-ended867=== RUN TestParseSingleRange/end_clamped_to_size868=== RUN TestIsValidCachePath/realisation869=== PAUSE TestParseSingleRange/end_clamped_to_size870=== PAUSE TestIsValidCachePath/realisation871=== RUN TestParseSingleRange/suffix872=== RUN TestIsValidCachePath/nix-cache-info873=== PAUSE TestParseSingleRange/suffix874=== PAUSE TestIsValidCachePath/nix-cache-info875=== RUN TestParseSingleRange/suffix_exceeds_size876=== RUN TestIsValidCachePath/index.html877=== PAUSE TestParseSingleRange/suffix_exceeds_size878=== PAUSE TestIsValidCachePath/index.html879=== RUN TestParseSingleRange/single_byte880=== RUN TestIsValidCachePath/traversal_parent881=== PAUSE TestParseSingleRange/single_byte882=== PAUSE TestIsValidCachePath/traversal_parent883=== RUN TestParseSingleRange/start_past_EOF884=== RUN TestIsValidCachePath/traversal_in_middle885=== PAUSE TestIsValidCachePath/traversal_in_middle886=== PAUSE TestParseSingleRange/start_past_EOF887=== RUN TestIsValidCachePath/invalid_char_e888=== RUN TestParseSingleRange/start_far_past_EOF889=== PAUSE TestParseSingleRange/start_far_past_EOF890=== PAUSE TestIsValidCachePath/invalid_char_e891=== CONT TestPresentReportsOnlyClosureRoots892=== RUN TestIsValidCachePath/invalid_char_u893=== PAUSE TestIsValidCachePath/invalid_char_u894=== RUN TestIsValidCachePath/random_path895=== PAUSE TestIsValidCachePath/random_path896=== RUN TestIsValidCachePath/empty897=== PAUSE TestIsValidCachePath/empty898=== RUN TestIsValidCachePath/leading_slash899=== PAUSE TestIsValidCachePath/leading_slash900=== RUN TestIsValidCachePath/wrong_extension901=== PAUSE TestIsValidCachePath/wrong_extension902=== RUN TestIsValidCachePath/short_hash903=== PAUSE TestIsValidCachePath/short_hash904=== CONT TestCompleteMultipartUnregistered9052026/10/01 09:57:48 INFO Received push request method=POST path=/api/pushes906=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure907=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure908=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart909=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart910=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts911=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts912=== CONT TestCreatePinRejectsBadInput9132026/10/01 09:57:48 INFO Received push request method=POST path=/api/pushes9142026/10/01 09:57:48 INFO Received push request method=POST path=/api/pushes9152026/10/01 09:57:48 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign916=== RUN TestPush_RejectsBadRequests/no_objects917=== PAUSE TestPush_RejectsBadRequests/no_objects918=== RUN TestPush_RejectsBadRequests/bad_root919=== PAUSE TestPush_RejectsBadRequests/bad_root920=== RUN TestPush_RejectsBadRequests/root_not_in_objects921=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects922=== RUN TestPush_RejectsBadRequests/no_roots923=== PAUSE TestPush_RejectsBadRequests/no_roots924=== CONT TestService_verifyS3Integrity9252026/10/01 09:57:48 INFO Signed narinfos id=1 count=1926--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (0.56s)927=== CONT TestConcurrentPinUpdatesAgree9282026/10/01 09:57:48 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"929=== CONT TestService_createPendingClosureHandler930--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (0.58s)931--- PASS: TestService_AuthMiddleware (0.59s)932=== CONT TestCreatePin_ReservedPins933--- PASS: TestReadProxyDisabled (0.62s)934=== CONT TestService_cleanupPendingClosuresHandler935--- PASS: TestReadProxyRangeRequest (0.69s)936=== CONT TestPresentNotReportedWhileGCDeletesClosure937--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.68s)938=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT9392026/10/01 09:57:48 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:40317/oidc940--- PASS: TestReadProxyInvalidPath (0.80s)941=== CONT TestOrphanedObjectsGCStressTest942--- PASS: TestReadProxyNarStreaming (0.87s)943=== CONT TestUploadHandlersRejectInvalidKeys944=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info945=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info946=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal947=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal948=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key949=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key950=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key951=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key952=== CONT TestOrphanedObjectsGC953--- PASS: TestReadRedirectUsesPublicS3URL (0.89s)954=== CONT TestIsValidUploadKey955=== RUN TestIsValidUploadKey/narinfo956=== PAUSE TestIsValidUploadKey/narinfo957=== RUN TestIsValidUploadKey/nar_zst958=== PAUSE TestIsValidUploadKey/nar_zst959=== RUN TestIsValidUploadKey/nar_xz960=== PAUSE TestIsValidUploadKey/nar_xz961=== RUN TestIsValidUploadKey/nar_plain962=== PAUSE TestIsValidUploadKey/nar_plain963=== RUN TestIsValidUploadKey/listing9642026/10/01 09:57:48 INFO Received push request method=POST path=/api/pushes965=== PAUSE TestIsValidUploadKey/listing966=== RUN TestIsValidUploadKey/build_log967=== PAUSE TestIsValidUploadKey/build_log968=== RUN TestIsValidUploadKey/build_log_home-manager_file969=== PAUSE TestIsValidUploadKey/build_log_home-manager_file970=== RUN TestIsValidUploadKey/build_log_plus_in_name971=== PAUSE TestIsValidUploadKey/build_log_plus_in_name972=== RUN TestIsValidUploadKey/build_log_question_mark973=== PAUSE TestIsValidUploadKey/build_log_question_mark974=== RUN TestIsValidUploadKey/build_log_equals975=== PAUSE TestIsValidUploadKey/build_log_equals976=== RUN TestIsValidUploadKey/realisation977=== PAUSE TestIsValidUploadKey/realisation978=== RUN TestIsValidUploadKey/realisation_plus_in_output979=== PAUSE TestIsValidUploadKey/realisation_plus_in_output980=== RUN TestIsValidUploadKey/nix-cache-info981=== PAUSE TestIsValidUploadKey/nix-cache-info982=== RUN TestIsValidUploadKey/index.html983=== PAUSE TestIsValidUploadKey/index.html984=== RUN TestIsValidUploadKey/narinfo_key,_nar_type985=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type986=== RUN TestIsValidUploadKey/nar_key,_narinfo_type987=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type988=== RUN TestIsValidUploadKey/listing_key,_narinfo_type989=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type990=== RUN TestIsValidUploadKey/traversal991=== PAUSE TestIsValidUploadKey/traversal992=== RUN TestIsValidUploadKey/traversal_nar993=== PAUSE TestIsValidUploadKey/traversal_nar994=== RUN TestIsValidUploadKey/absolute995=== PAUSE TestIsValidUploadKey/absolute996=== RUN TestIsValidUploadKey/empty_key997=== PAUSE TestIsValidUploadKey/empty_key998=== RUN TestIsValidUploadKey/unknown_type999=== PAUSE TestIsValidUploadKey/unknown_type1000=== CONT TestValidateS3Concurrency1001--- PASS: TestValidateS3Concurrency (0.00s)1002=== CONT TestPendingClosureWriteTimeout1003=== RUN TestPendingClosureWriteTimeout/empty1004=== PAUSE TestPendingClosureWriteTimeout/empty1005=== RUN TestPendingClosureWriteTimeout/negative1006=== PAUSE TestPendingClosureWriteTimeout/negative1007=== RUN TestPendingClosureWriteTimeout/400_objects1008=== PAUSE TestPendingClosureWriteTimeout/400_objects1009=== RUN TestPendingClosureWriteTimeout/670k_objects1010=== PAUSE TestPendingClosureWriteTimeout/670k_objects1011=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1012=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1013=== CONT TestObjectStatsTrigger1014--- PASS: TestPresentReportsOnlyClosureRoots (0.96s)1015=== CONT TestReconnectLeavesObjectsUnlocked10162026/10/01 09:57:48 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10172026/10/01 09:57:48 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst1018=== CONT TestPendingClosureFailureTracksEveryUpload1019--- PASS: TestCompleteMultipartUnregistered (1.00s)1020=== CONT TestDeletePinKeepsRowWhenS3Fails1021--- PASS: TestReadRedirectNar (1.02s)10222026/10/01 09:57:48 INFO Starting HTTP server address=127.0.0.1:339651023=== CONT TestPendingCleanupUsesOneCutoff10242026/10/01 09:57:48 INFO Starting HTTP server address=/build/TestProxyHeadersOnlyTrustedOnSocket3517868221/001/proxy.sock1025--- PASS: TestReadRedirectKeepsNarinfoProxied (1.04s)10262026/10/01 09:57:48 WARN mTLS auth: subject not in bound subjects subject="CN=someone"10272026/10/01 09:57:48 INFO Shutdown signal received, draining in-flight requests timeout=10s1028=== CONT TestMultipartCleanup1029--- PASS: TestReadProxyNarinfoAlreadyDecompressed (1.04s)1030--- PASS: TestReadProxyConditionalGet (1.06s)1031=== CONT TestPendingClosureFailureAbortsItsUploads1032=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded1033--- PASS: TestProxyHeadersOnlyTrustedOnSocket (1.06s)10342026/10/01 09:57:48 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10352026/10/01 09:57:48 INFO Received create pin request method=POST path=/api/pins/deploy10362026/10/01 09:57:48 INFO Received create pin request method=POST path=/api/pins/deploy10372026/10/01 09:57:48 INFO Received create pin request method=POST path=/api/pins/deploy10382026/10/01 09:57:48 INFO Received create pin request method=POST path=/api/pins/deploy10392026/10/01 09:57:48 INFO Received create pin request method=POST path=/api/pins/deploy10402026/10/01 09:57:48 INFO Received create pin request method=POST path=/api/pins/deploy10412026/10/01 09:57:48 INFO Received create pin request method=POST path=/api/pins/deploy10422026/10/01 09:57:48 INFO Received create pin request method=POST path=/api/pins/deploy10432026/10/01 09:57:49 INFO Received uploads request method=POST path=/api/pending_closures10442026/10/01 09:57:49 INFO Completed multipart upload object_key=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa00000000000000000000.nar.zst upload_id=ZDU5YmE3NTQtNjc2NC00Y2RlLThjMDQtODk3NGUzNmEwMjMxLjM2MzM1NGMzLWQ3MGEtNDc5OC05OTJiLTI3ODRjNzAxOGY4ZngxNzkwODQ4NjY4Mjc3NjUzMDky parts=1010452026/10/01 09:57:49 INFO Received create pin request method=POST path=/api/pins/app10462026/10/01 09:57:49 INFO Received uploads request method=POST path=/api/pending_closures10472026/10/01 09:57:49 INFO Received uploads request method=POST path=/api/pending_closures10482026/10/01 09:57:49 INFO Received uploads request method=POST path=/api/pending_closures10492026/10/01 09:57:49 INFO Received create pin request method=POST path=/api/pins/deploy10502026/10/01 09:57:49 INFO Received create pin request method=POST path=/api/pins/app10512026/10/01 09:57:49 INFO Received cleanup request method=DELETE path=/api/pending_closures10522026/10/01 09:57:49 INFO Aborted multipart uploads count=0 kept=010532026/10/01 09:57:49 INFO Received uploads request method=POST path=/api/pending_closures10542026/10/01 09:57:49 INFO Received cleanup request method=DELETE path=/api/pending_closures10552026/10/01 09:57:49 INFO Aborted multipart uploads count=1 kept=010562026/10/01 09:57:49 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10572026-10-01 09:57:49.156 UTC [748] ERROR: Closure does not exist: id=110582026-10-01 09:57:49.156 UTC [748] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 12 at RAISE10592026-10-01 09:57:49.156 UTC [748] STATEMENT: -- name: CommitPendingClosure :exec1060 SELECT commit_pending_closure($1::bigint)1061 1062--- PASS: TestService_cleanupPendingClosuresHandler (0.75s)1063=== CONT TestMetricsInventory10642026/10/01 09:57:49 INFO Received uploads request method=POST path=/api/pending_closures1065--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.72s)1066=== CONT TestServerTLSConfig1067=== RUN TestServerTLSConfig/no_client_CA1068=== PAUSE TestServerTLSConfig/no_client_CA1069=== RUN TestServerTLSConfig/missing_CA_file1070=== PAUSE TestServerTLSConfig/missing_CA_file1071=== RUN TestServerTLSConfig/not_a_PEM_file1072=== PAUSE TestServerTLSConfig/not_a_PEM_file1073=== CONT TestCreatePendingClosureRejectsOversizedNAR10742026/10/01 09:57:49 INFO Received uploads request method=POST path=/api/pending_closures1075=== CONT TestService_NativeMTLS1076--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1077--- PASS: TestReadProxyHead (1.40s)1078=== CONT TestNARDeduplicationMetadataUploadBug10792026/10/01 09:57:49 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux10802026/10/01 09:57:49 WARN Refused reserved pin name=worker-x86_64-linux10812026/10/01 09:57:49 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux10822026/10/01 09:57:49 INFO Received create pin request method=POST path=/api/pins/my-app10832026/10/01 09:57:49 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1084--- PASS: TestCreatePin_ReservedPins (0.86s)1085=== CONT TestGenerateLandingPage1086--- PASS: TestGenerateLandingPage (0.01s)1087=== CONT TestPresignedUploadRegisteredBeforeCommit1088=== CONT TestCompletedNarNotReofferedAcrossClosures1089--- PASS: TestObjectStatsTrigger (0.67s)10902026/10/01 09:57:49 INFO Received create pin request method=POST path=/api/pins/app10912026/10/01 09:57:49 INFO Created/updated pin name=app store_path=/nix/store/cccccccccccccccccccccccccccccccc-app narinfo_key=cccccccccccccccccccccccccccccccc.narinfo10922026/10/01 09:57:49 INFO Received delete pin request method=DELETE path=/api/pins/app10932026/10/01 09:57:49 ERROR Failed to delete pin from S3 key=pins/app error="Get \"http://127.0.0.1:1/bucket38/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"1094=== CONT TestService_readinessHandler1095--- PASS: TestReconnectLeavesObjectsUnlocked (0.63s)10962026/10/01 09:57:49 INFO Received delete pin request method=DELETE path=/api/pins/app10972026/10/01 09:57:49 INFO Received uploads request method=POST path=/api/pending_closures10982026/10/01 09:57:49 INFO Deleted pin name=app10992026/10/01 09:57:49 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11002026/10/01 09:57:49 INFO Received uploads request method=POST path=/api/pending_closures1101--- PASS: TestDeletePinKeepsRowWhenS3Fails (0.63s)1102=== CONT TestCacheConfigHandlerMaxNarSize1103--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1104=== CONT TestCompleteMultipartUpload_ErrorButObjectExists11052026/10/01 09:57:49 INFO Completed multipart upload object_key=nar/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb00000000000000000000.nar.zst upload_id=ZDU5YmE3NTQtNjc2NC00Y2RlLThjMDQtODk3NGUzNmEwMjMxLjYzMjMzOTE1LWJjZDMtNGRlYS05OTNkLThkZjY3NDBjZDc1OXgxNzkwODQ4NjY4NzE0MzE4MzUx parts=1011062026/10/01 09:57:49 INFO Received uploads request method=POST path=/api/pending_closures11072026/10/01 09:57:49 INFO Received uploads request method=POST path=/api/pending_closures1108--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (0.66s)1109=== CONT TestGCTaskStore_Fail1110--- PASS: TestGCTaskStore_Fail (0.00s)1111=== CONT TestService_healthCheckHandler11122026/10/01 09:57:49 INFO Received uploads request method=POST path=/api/pending_closures11132026/10/01 09:57:49 ERROR Failed to decompress narinfo error="decompressed size exceeds configured limit"11142026/10/01 09:57:49 INFO Received uploads request method=POST path=/api/pending_closures1115--- PASS: TestPendingClosureFailureAbortsItsUploads (0.72s)1116=== CONT TestGCTaskStore_CompletedAllowsNewTask1117--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1118=== CONT TestGCTaskStore_GetReturnsLatest1119=== CONT TestGCTaskStore_PhaseUpdates1120--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1121--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1122=== CONT TestGCTaskStore_GetEmpty1123--- PASS: TestGCTaskStore_GetEmpty (0.00s)1124=== CONT TestService_Rustfstest11252026/10/01 09:57:49 INFO Received cleanup request method=DELETE path=/api/pending_closures11262026/10/01 09:57:49 INFO Created/updated pin name=app store_path=/nix/store/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa-app narinfo_key=aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.narinfo11272026/10/01 09:57:49 WARN mTLS auth: subject not in bound subjects subject="CN=reader"11282026/10/01 09:57:49 WARN mTLS auth: subject not in bound subjects subject="CN=reader"11292026/10/01 09:57:49 WARN Rate limiter enabled after throttle name=s3-test rate=511302026/10/01 09:57:49 WARN S3 rate limit hit during proxy key=4hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo error="Please reduce your request rate."11312026/10/01 09:57:49 INFO Created/updated pin name=app store_path=/nix/store/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb-app narinfo_key=bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb.narinfo11322026/10/01 09:57:49 INFO Received cleanup request method=DELETE path=/api/pending_closures1133--- PASS: TestService_NativeMTLS (0.42s)1134=== CONT TestGCTaskStore_ConflictDifferentParams1135=== CONT TestGCEndsOnShutdown11362026/10/01 09:57:49 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket41/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""1137--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)11382026/10/01 09:57:49 INFO Aborted multipart uploads count=0 kept=11139=== RUN TestGCEndsOnShutdown/before_the_run1140=== PAUSE TestGCEndsOnShutdown/before_the_run1141=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1142=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1143=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1144=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1145=== CONT TestGCTaskStore_StartNew1146=== CONT TestGracefulShutdownDrainsInflight1147--- PASS: TestGCTaskStore_StartNew (0.00s)11482026/10/01 09:57:49 INFO Starting HTTP server address=127.0.0.1:3364111492026/10/01 09:57:49 INFO Shutdown signal received, draining in-flight requests timeout=10s11502026/10/01 09:57:49 INFO Received cleanup request method=DELETE path=/api/pending_closures1151--- PASS: TestMetricsInventory (0.47s)11522026/10/01 09:57:49 INFO Aborted multipart uploads count=1 kept=01153=== CONT TestSweepRechecksPendingAfterLocking11542026/10/01 09:57:49 WARN Rate limiter backed off name=s3-test rate=511552026/10/01 09:57:49 WARN S3 rate limit hit during proxy key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhh.nar.zst error="Please reduce your request rate."1156--- PASS: TestConcurrentPinUpdatesAgree (1.30s)1157=== CONT TestParseSize1158--- PASS: TestParseSize (0.00s)1159=== CONT TestService_ReadAuthMiddleware1160--- PASS: TestMultipartCleanup (0.81s)1161=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection1162--- PASS: TestReadProxy404 (1.86s)1163=== CONT TestService_AuthMiddleware_MTLSProxyHeader11642026/10/01 09:57:49 INFO Received uploads request method=POST path=/api/pending_closures1165--- PASS: TestPresentNotReportedWhileGCDeletesClosure (1.19s)1166=== CONT TestDeduplicatedObjectsRecordedAsPending1167=== NAME TestNARDeduplicationMetadataUploadBug1168 metadata_upload_test.go:48: First store path: /build/TestNARDeduplicationMetadataUploadBug1188454322/001/store/w563ymsxbnh5bdlcpnqakaa12i5wgkxf-file1.txt1169=== NAME TestOrphanedObjectsGC1170 orphaned_objects_gc_test.go:290: GC Test Summary:1171 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A1172 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B1173 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)1174 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)1175 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects11762026/10/01 09:57:49 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst11772026/10/01 09:57:49 INFO Received uploads request method=POST path=/api/pending_closures1178--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1179=== CONT TestService_AuthMiddleware_MTLSBoundSubjects11802026/10/01 09:57:49 INFO Received uploads request method=POST path=/api/pending_closures1181--- PASS: TestOrphanedObjectsGC (1.03s)1182=== CONT TestGCMetrics1183--- PASS: TestPresignedUploadRegisteredBeforeCommit (0.46s)1184=== CONT TestPushDedupSurvivesConcurrentGC11852026/10/01 09:57:49 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11862026/10/01 09:57:49 WARN readiness check failed error="closed pool"11872026/10/01 09:57:49 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11882026/10/01 09:57:49 INFO Completed multipart upload object_key=nar/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb00000000000000000000.nar.zst upload_id=ZDU5YmE3NTQtNjc2NC00Y2RlLThjMDQtODk3NGUzNmEwMjMxLjQ1NGJjZGQzLWU5MGYtNGQ4NC05OTJhLTg5NWFlMGE0M2Q3OHgxNzkwODQ4NjY4Mjc3Nzk0MDEy parts=101189=== CONT TestService_ReadScope_PublicByDefault1190--- PASS: TestService_readinessHandler (0.34s)11912026/10/01 09:57:49 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11922026/10/01 09:57:49 INFO Received uploads request method=POST path=/api/pending_closures11932026/10/01 09:57:49 INFO Received push request method=POST path=/api/pushes11942026/10/01 09:57:49 INFO Received create pin request method=POST path=/api/pins/deploy11952026/10/01 09:57:49 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=ZDU5YmE3NTQtNjc2NC00Y2RlLThjMDQtODk3NGUzNmEwMjMxLjhlYzc5Yjk5LWM5Y2ItNDJmYi05ZGZjLWVmZWVlYWIyOTlmM3gxNzkwODQ4NjY5MDMwNDg2NTMy parts=1011962026/10/01 09:57:49 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11972026/10/01 09:57:49 INFO Completed upload id=111982026/10/01 09:57:49 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)11992026/10/01 09:57:49 INFO Uploading w563ymsxbnh5bdlcpnqakaa12i5wgkxf-file1.txt (160B)12002026/10/01 09:57:49 INFO Created/updated pin name=deploy store_path="/nix/store/dddddddddddddddddddddddddddddddd-app-1.0+git_x?y=z" narinfo_key=dddddddddddddddddddddddddddddddd.narinfo12012026/10/01 09:57:49 INFO Received uploads request method=POST path=/api/pending_closures12022026/10/01 09:57:49 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=ZDU5YmE3NTQtNjc2NC00Y2RlLThjMDQtODk3NGUzNmEwMjMxLjYyZmI2OTcxLTA0NzktNDdjYS05ZmU5LTFhYjc4MjY1NmM0N3gxNzkwODQ4NjY5MTAzNzYwMzI1 parts=1012032026/10/01 09:57:49 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12042026/10/01 09:57:49 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"12052026/10/01 09:57:49 INFO Received uploads request method=POST path=/api/pending_closures12062026/10/01 09:57:49 INFO Completed upload id=112072026/10/01 09:57:49 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000012082026/10/01 09:57:49 WARN Failed to register uploaded object key=w563ymsxbnh5bdlcpnqakaa12i5wgkxf.ls error="server returned 404: 404 page not found\n"1209--- PASS: TestService_healthCheckHandler (0.30s)1210=== CONT TestService_RequireScope_OIDC12112026/10/01 09:57:49 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign1212=== CONT TestConnectWaitsForAPeerMigration1213--- PASS: TestCreatePinRejectsBadInput (1.58s)12142026/10/01 09:57:49 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo12152026/10/01 09:57:49 WARN Found objects in DB but missing from S3, will re-upload count=112162026/10/01 09:57:49 INFO Signed narinfos id=1 count=112172026/10/01 09:57:49 INFO Uploading 1 narinfos12182026/10/01 09:57:49 INFO Received uploads request method=POST path=/api/pending_closures12192026/10/01 09:57:49 INFO Received complete upload request method=POST path=/api/pending_closures/3/complete12202026/10/01 09:57:49 INFO Completed upload id=312212026/10/01 09:57:49 INFO Starting cleanup of old closures method=DELETE path=/api/closures12222026/10/01 09:57:49 INFO Aborted multipart uploads count=0 kept=01223=== CONT TestLeadEndsOnShutdown1224--- PASS: TestService_Rustfstest (0.28s)1225--- PASS: TestService_verifyS3Integrity (1.55s)1226=== CONT TestCacheConfigHandler1227=== RUN TestCacheConfigHandler/full_config,_no_issuer1228=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1229=== RUN TestCacheConfigHandler/no_cache_url_configured1230=== PAUSE TestCacheConfigHandler/no_cache_url_configured1231=== RUN TestCacheConfigHandler/no_signing_keys1232=== PAUSE TestCacheConfigHandler/no_signing_keys1233=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1234=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator12352026/10/01 09:57:49 INFO Received complete push request method=POST path=/api/pushes/1/complete1236=== CONT TestGCTaskStore_DeduplicateSameParams12372026/10/01 09:57:49 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=01238=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle12392026/10/01 09:57:49 WARN Failed to register uploaded object key=w563ymsxbnh5bdlcpnqakaa12i5wgkxf.narinfo error="server returned 404: 404 page not found\n"1240--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)12412026/10/01 09:57:49 INFO Vacuumed table table=pending_closures12422026/10/01 09:57:49 INFO Vacuumed table table=pending_objects12432026/10/01 09:57:49 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12442026/10/01 09:57:49 INFO Vacuumed table table=multipart_uploads12452026/10/01 09:57:49 INFO Upload complete. (169ms)12462026/10/01 09:57:49 INFO Vacuumed table table=closures1247=== NAME TestNARDeduplicationMetadataUploadBug1248 metadata_upload_test.go:54: Retrieved narinfo from S3:1249 StorePath: /build/TestNARDeduplicationMetadataUploadBug1188454322/001/store/w563ymsxbnh5bdlcpnqakaa12i5wgkxf-file1.txt1250 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1251 Compression: zstd1252 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1253 NarSize: 1601254 References: 1255 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf12562026/10/01 09:57:49 INFO Vacuumed table table=objects12572026/10/01 09:57:49 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ZDU5YmE3NTQtNjc2NC00Y2RlLThjMDQtODk3NGUzNmEwMjMxLmEwZTY5MDcxLTNjZTktNDkzNy1iYTczLTQ2OGM5ZTBkMWIxY3gxNzkwODQ4NjY5NzkyMDE2Mjg31258 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1259 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1260 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}12612026/10/01 09:57:49 INFO Aborted multipart uploads count=0 kept=012622026/10/01 09:57:49 WARN Force mode enabled - objects will be deleted immediately without grace period12632026/10/01 09:57:49 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000012642026/10/01 09:57:49 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=012652026/10/01 09:57:49 INFO Received uploads request method=POST path=/api/pending_closures1266 metadata_upload_test.go:64: Second store path (same content): /build/TestNARDeduplicationMetadataUploadBug1188454322/001/store/qs3llnrnlhahxbz9n632kzsrc7g5g4xp-file2.txt12672026/10/01 09:57:49 INFO Vacuumed table table=pending_closures12682026/10/01 09:57:49 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:38995/oidc12692026/10/01 09:57:49 INFO Vacuumed table table=pending_objects12702026/10/01 09:57:49 INFO Vacuumed table table=multipart_uploads12712026/10/01 09:57:49 INFO Vacuumed table table=closures12722026/10/01 09:57:49 INFO Vacuumed table table=objects12732026/10/01 09:57:49 WARN Failed to abort multipart upload key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ZDU5YmE3NTQtNjc2NC00Y2RlLThjMDQtODk3NGUzNmEwMjMxLmEwZTY5MDcxLTNjZTktNDkzNy1iYTczLTQ2OGM5ZTBkMWIxY3gxNzkwODQ4NjY5NzkyMDE2Mjg3 error="Delete \"http://localhost:39607/bucket50/nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst?uploadId=ZDU5YmE3NTQtNjc2NC00Y2RlLThjMDQtODk3NGUzNmEwMjMxLmEwZTY5MDcxLTNjZTktNDkzNy1iYTczLTQ2OGM5ZTBkMWIxY3gxNzkwODQ4NjY5NzkyMDE2Mjg3\": injected: abort refused"12742026/10/01 09:57:49 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1275--- PASS: TestService_createPendingClosureHandler (1.60s)1276=== CONT TestCommitRacingPendingCleanupKeepsObjects1277--- PASS: TestDeduplicatedObjectsRecordedAsPending (0.30s)1278=== CONT TestSkippedUploadsHandler12792026/10/01 09:57:49 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ZDU5YmE3NTQtNjc2NC00Y2RlLThjMDQtODk3NGUzNmEwMjMxLmEwZTY5MDcxLTNjZTktNDkzNy1iYTczLTQ2OGM5ZTBkMWIxY3gxNzkwODQ4NjY5NzkyMDE2Mjg312802026/10/01 09:57:49 INFO Client skipped oversized paths paths=3 nar_bytes=50000000001281--- PASS: TestSweepRechecksPendingAfterLocking (0.35s)1282=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock1283--- PASS: TestPendingClosureFailureTracksEveryUpload (1.17s)1284=== CONT TestResolveDBConnectionString12852026/10/01 09:57:49 INFO Received uploads request method=POST path=/api/pending_closures1286=== RUN TestResolveDBConnectionString/flag_wins1287=== PAUSE TestResolveDBConnectionString/flag_wins1288=== RUN TestResolveDBConnectionString/file_when_flag_empty1289=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1290=== RUN TestResolveDBConnectionString/missing_file_is_an_error1291=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1292=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1293=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1294=== RUN TestResolveDBConnectionString/nothing_configured1295=== PAUSE TestResolveDBConnectionString/nothing_configured1296=== CONT TestClientFallsBackToClosures12972026/10/01 09:57:49 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ZDU5YmE3NTQtNjc2NC00Y2RlLThjMDQtODk3NGUzNmEwMjMxLmEwZTY5MDcxLTNjZTktNDkzNy1iYTczLTQ2OGM5ZTBkMWIxY3gxNzkwODQ4NjY5NzkyMDE2Mjg3 parts=11298--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (0.57s)1299=== CONT TestLeadElectsOneAndHandsOver1300--- PASS: TestSkippedUploadsHandler (0.05s)13012026/10/01 09:57:50 INFO Received push request method=POST path=/api/pushes1302=== CONT TestPinProtectsFromGC1303--- PASS: TestService_ReadAuthMiddleware (0.38s)1304=== CONT TestRedundantMultipartUpload13052026/10/01 09:57:50 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)13062026/10/01 09:57:50 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"13072026/10/01 09:57:50 WARN mTLS auth: bound subjects configured but subject DN unavailable13082026/10/01 09:57:50 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"13092026/10/01 09:57:50 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign13102026/10/01 09:57:50 WARN Failed to register uploaded object key=qs3llnrnlhahxbz9n632kzsrc7g5g4xp.ls error="server returned 404: 404 page not found\n"13112026/10/01 09:57:50 INFO Signed narinfos id=2 count=113122026/10/01 09:57:50 INFO Uploading 1 narinfos13132026/10/01 09:57:50 INFO Received complete push request method=POST path=/api/pushes/2/complete13142026/10/01 09:57:50 WARN Failed to register uploaded object key=qs3llnrnlhahxbz9n632kzsrc7g5g4xp.narinfo error="server returned 404: 404 page not found\n"13152026/10/01 09:57:50 INFO Upload complete. (89ms)1316=== NAME TestNARDeduplicationMetadataUploadBug1317 metadata_upload_test.go:76: Retrieved narinfo from S3:1318 StorePath: /build/TestNARDeduplicationMetadataUploadBug1188454322/001/store/qs3llnrnlhahxbz9n632kzsrc7g5g4xp-file2.txt1319 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1320 Compression: zstd1321 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1322 NarSize: 1601323 References: 1324 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1325--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.39s)1326=== CONT TestPushWaitsForSweepHoldingRow1327=== NAME TestNARDeduplicationMetadataUploadBug1328 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1329 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1330 {"version":1,"root":{"type":"regular","size":44}}13312026/10/01 09:57:50 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1332--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.44s)1333=== CONT TestClientSharedPathCommittedMidPush13342026/10/01 09:57:50 INFO Completed multipart upload object_key=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa00000000000000000000.nar.zst upload_id=ZDU5YmE3NTQtNjc2NC00Y2RlLThjMDQtODk3NGUzNmEwMjMxLjQ5MTBjMmQ4LTAxY2YtNGRkOS05OWU0LWQzZGNiYWZkMzc4ZXgxNzkwODQ4NjY4NzExOTE4MjU5 parts=1013352026/10/01 09:57:50 INFO Received complete push request method=POST path=/api/pushes/1/complete13362026/10/01 09:57:50 INFO Aborted multipart uploads count=0 kept=013372026/10/01 09:57:50 WARN Force mode enabled - objects will be deleted immediately without grace period1338--- PASS: TestNARDeduplicationMetadataUploadBug (0.92s)1339=== CONT TestRegisterCompletedObjectNeedsPendingRow13402026/10/01 09:57:50 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=013412026/10/01 09:57:50 INFO Vacuumed table table=pending_closures13422026/10/01 09:57:50 INFO Vacuumed table table=pending_objects13432026/10/01 09:57:50 INFO Vacuumed table table=multipart_uploads13442026/10/01 09:57:50 INFO Vacuumed table table=closures13452026/10/01 09:57:50 INFO Vacuumed table table=objects13462026/10/01 09:57:50 INFO Received push request method=POST path=/api/pushes1347--- PASS: TestService_ReadScope_PublicByDefault (0.42s)1348=== CONT TestClientWithDependencies13492026/10/01 09:57:50 ERROR Refusing narinfo larger than the limit key=5hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=1677721613502026/10/01 09:57:50 INFO Received uploads request method=POST path=/api/pending_closures1351--- PASS: TestGCMetrics (0.49s)1352=== CONT TestSweepSkipsRowsLockedByPush13532026/10/01 09:57:50 INFO lead: acquired remote=192.0.2.1:12341354=== CONT TestClientPushesUseOnePush1355--- PASS: TestReadProxyNarinfo (2.40s)1356--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (0.57s)1357=== CONT TestFailedS3DeleteKeepsTombstone13582026/10/01 09:57:50 INFO Aborted multipart uploads count=0 kept=013592026/10/01 09:57:50 INFO Received uploads request method=POST path=/api/pending_closures13602026/10/01 09:57:50 WARN Force mode enabled - objects will be deleted immediately without grace period13612026/10/01 09:57:50 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=013622026/10/01 09:57:50 INFO Aborted multipart uploads count=0 kept=013632026/10/01 09:57:50 INFO Vacuumed table table=pending_closures13642026/10/01 09:57:50 INFO Vacuumed table table=pending_objects13652026/10/01 09:57:50 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=013662026/10/01 09:57:50 INFO Vacuumed table table=multipart_uploads13672026/10/01 09:57:50 INFO Vacuumed table table=pending_closures13682026/10/01 09:57:50 INFO Vacuumed table table=closures13692026/10/01 09:57:50 INFO Vacuumed table table=pending_objects13702026/10/01 09:57:50 INFO Vacuumed table table=multipart_uploads13712026/10/01 09:57:50 INFO Vacuumed table table=objects13722026/10/01 09:57:50 INFO Vacuumed table table=closures13732026/10/01 09:57:50 INFO Vacuumed table table=objects13742026/10/01 09:57:50 INFO Aborted multipart uploads count=0 kept=013752026/10/01 09:57:50 WARN Force mode enabled - objects will be deleted immediately without grace period13762026/10/01 09:57:50 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=013772026/10/01 09:57:50 INFO Vacuumed table table=pending_closures13782026/10/01 09:57:50 INFO Vacuumed table table=pending_objects13792026/10/01 09:57:50 INFO Vacuumed table table=multipart_uploads13802026/10/01 09:57:50 INFO Vacuumed table table=closures13812026/10/01 09:57:50 INFO Vacuumed table table=objects13822026/10/01 09:57:50 INFO Aborted multipart uploads count=0 kept=013832026/10/01 09:57:50 WARN Force mode enabled - objects will be deleted immediately without grace period1384--- PASS: TestPushDedupSurvivesConcurrentGC (0.64s)1385=== CONT TestClientIntegration13862026/10/01 09:57:50 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=01387=== RUN TestService_RequireScope_OIDC/builder_may_write1388=== PAUSE TestService_RequireScope_OIDC/builder_may_write1389=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1390=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1391=== RUN TestService_RequireScope_OIDC/ops_may_admin1392=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1393=== RUN TestService_RequireScope_OIDC/ops_may_not_write1394=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1395=== RUN TestService_RequireScope_OIDC/reader_may_not_write1396=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1397=== RUN TestService_RequireScope_OIDC/static_token_may_admin1398=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1399=== RUN TestService_RequireScope_OIDC/static_token_may_write1400=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1401=== RUN TestService_RequireScope_OIDC/reader_may_read1402=== PAUSE TestService_RequireScope_OIDC/reader_may_read1403=== RUN TestService_RequireScope_OIDC/writer_implies_read1404=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1405=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1406=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1407=== CONT TestForceGCDuringPushOffersSweptObject14082026/10/01 09:57:50 INFO Vacuumed table table=pending_closures1409=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows1410=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows1411=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check1412=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check1413=== CONT TestClientMultipleUploads14142026/10/01 09:57:50 INFO Vacuumed table table=pending_objects14152026/10/01 09:57:50 INFO Vacuumed table table=multipart_uploads14162026/10/01 09:57:50 INFO Vacuumed table table=closures14172026/10/01 09:57:50 INFO Vacuumed table table=objects14182026/10/01 09:57:50 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14192026/10/01 09:57:50 INFO lead: acquired remote=192.0.2.1:12341420=== CONT TestGetExistingObjectsLocksRows1421--- PASS: TestCommitRacingPendingCleanupKeepsObjects (0.42s)14222026/10/01 09:57:50 INFO Received uploads request method=POST path=/api/pending_closures14232026/10/01 09:57:50 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14242026/10/01 09:57:50 INFO Received uploads request method=POST path=/api/pending_closures14252026/10/01 09:57:50 INFO Received uploads request method=POST path=/api/pending_closures14262026/10/01 09:57:50 INFO Completed multipart upload object_key=nar/cccccccccccccccccccccccccccccccc00000000000000000000.nar.zst upload_id=ZDU5YmE3NTQtNjc2NC00Y2RlLThjMDQtODk3NGUzNmEwMjMxLmNmZTZhMjEyLWY3MzQtNGU1NC1hODIzLWJjNmRkYWEyNDYzYXgxNzkwODQ4NjY4Mjc3NzgzNzAy parts=1014272026/10/01 09:57:50 INFO Received complete push request method=POST path=/api/pushes/1/complete1428=== NAME TestPinProtectsFromGC1429 client_integration_test.go:867: Pinned store path: /build/TestPinProtectsFromGC1532844878/001/store/9d4y30abrjd620b9j63zasfxa2cywz7z-pinned-file.txt1430 client_integration_test.go:868: Unpinned store path: /build/TestPinProtectsFromGC1532844878/001/store/5f7235fhb9zds5m06zbszlrhpnjp7r49-unpinned-file.txt14312026/10/01 09:57:50 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14322026/10/01 09:57:50 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=ZDU5YmE3NTQtNjc2NC00Y2RlLThjMDQtODk3NGUzNmEwMjMxLjQyYmIwNGNiLWJkMTktNDQwZC1hYmQyLThmMzhhMDgyMmJiYngxNzkwODQ4NjY5NzE5MzM4MDc0 parts=1214332026/10/01 09:57:50 INFO Received uploads request method=POST path=/api/pending_closures1434--- PASS: TestPush_CompleteCommitsEveryRoot (2.75s)1435=== CONT TestClientCADerivations1436--- PASS: TestRegisterCompletedObjectNeedsPendingRow (0.42s)1437=== CONT TestGCSweepDeliversEachKeyOnce1438--- PASS: TestCompletedNarNotReofferedAcrossClosures (1.21s)1439=== CONT TestCacheStatsHandler14402026/10/01 09:57:50 INFO Received uploads request method=POST path=/api/pending_closures14412026/10/01 09:57:50 INFO Received push request method=POST path=/api/pushes14422026/10/01 09:57:50 INFO Received uploads request method=POST path=/api/pending_closures14432026/10/01 09:57:50 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14442026/10/01 09:57:50 INFO Uploading 9d4y30abrjd620b9j63zasfxa2cywz7z-pinned-file.txt (128B)14452026/10/01 09:57:50 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)14462026/10/01 09:57:50 INFO Uploading sm6l8s5ynmgqkvsf9q9zikr315cbap5q-b (216B)14472026/10/01 09:57:50 INFO Uploading sp6r19n4nclhvs5zx15z50qvmbxpsyra-shared-dep (136B)14482026/10/01 09:57:50 WARN Failed to register uploaded object key=nar/15g73s50x59lr1skvid40i5l52dcb1vqal6k65ng8vn5zy6xbxv4.nar.zst error="server returned 404: 404 page not found\n"14492026/10/01 09:57:50 WARN Failed to register uploaded object key=7k1cims4waf0368qzadinmr325crfms6.ls error="server returned 404: 404 page not found\n"14502026/10/01 09:57:50 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"14512026/10/01 09:57:50 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"14522026/10/01 09:57:50 WARN Failed to register uploaded object key=sp6r19n4nclhvs5zx15z50qvmbxpsyra.ls error="server returned 404: 404 page not found\n"14532026/10/01 09:57:50 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign14542026/10/01 09:57:50 WARN Failed to register uploaded object key=sm6l8s5ynmgqkvsf9q9zikr315cbap5q.ls error="server returned 404: 404 page not found\n"14552026/10/01 09:57:50 INFO Signed narinfos id=1 count=214562026/10/01 09:57:50 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign14572026/10/01 09:57:50 WARN Failed to register uploaded object key=9d4y30abrjd620b9j63zasfxa2cywz7z.ls error="server returned 404: 404 page not found\n"14582026/10/01 09:57:50 INFO Signed narinfos id=2 count=214592026/10/01 09:57:50 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14602026/10/01 09:57:50 INFO Uploading 4 narinfos14612026/10/01 09:57:50 INFO Signed narinfos id=1 count=114622026/10/01 09:57:50 INFO Uploading 1 narinfos14632026/10/01 09:57:50 WARN Failed to register uploaded object key=7k1cims4waf0368qzadinmr325crfms6.narinfo error="server returned 404: 404 page not found\n"14642026/10/01 09:57:50 WARN Failed to register uploaded object key=sm6l8s5ynmgqkvsf9q9zikr315cbap5q.narinfo error="server returned 404: 404 page not found\n"14652026/10/01 09:57:50 WARN Failed to register uploaded object key=sp6r19n4nclhvs5zx15z50qvmbxpsyra.narinfo error="server returned 404: 404 page not found\n"14662026/10/01 09:57:50 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14672026/10/01 09:57:50 WARN Failed to register uploaded object key=sp6r19n4nclhvs5zx15z50qvmbxpsyra.narinfo error="server returned 404: 404 page not found\n"14682026/10/01 09:57:50 INFO Received complete push request method=POST path=/api/pushes/1/complete14692026/10/01 09:57:50 WARN Failed to register uploaded object key=9d4y30abrjd620b9j63zasfxa2cywz7z.narinfo error="server returned 404: 404 page not found\n"14702026/10/01 09:57:50 INFO Completed upload id=114712026/10/01 09:57:50 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete14722026/10/01 09:57:50 INFO Upload complete. (110ms)14732026/10/01 09:57:50 INFO Received uploads request method=POST path=/api/pending_closures14742026/10/01 09:57:50 INFO Completed upload id=214752026/10/01 09:57:50 INFO Upload complete. (123ms)1476=== NAME TestClientFallsBackToClosures1477 client_pushes_test.go:112: Retrieved narinfo from S3:1478 StorePath: /build/TestClientFallsBackToClosures364716738/001/store/sp6r19n4nclhvs5zx15z50qvmbxpsyra-shared-dep1479 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1480 Compression: zstd1481 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821482 NarSize: 1361483 References: 1484 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n14852026/10/01 09:57:50 INFO Aborted multipart uploads count=0 kept=014862026/10/01 09:57:50 WARN Force mode enabled - objects will be deleted immediately without grace period1487 client_pushes_test.go:112: Retrieved narinfo from S3:1488 StorePath: /build/TestClientFallsBackToClosures364716738/001/store/7k1cims4waf0368qzadinmr325crfms6-a1489 URL: nar/15g73s50x59lr1skvid40i5l52dcb1vqal6k65ng8vn5zy6xbxv4.nar.zst1490 Compression: zstd1491 NarHash: sha256:15g73s50x59lr1skvid40i5l52dcb1vqal6k65ng8vn5zy6xbxv41492 NarSize: 2161493 References: /build/TestClientFallsBackToClosures364716738/001/store/sp6r19n4nclhvs5zx15z50qvmbxpsyra-shared-dep1494 CA: text:sha256:1c3pnwf2g0x1m7mq75kb4ygp6j040fbx4xwfb2fwglf5wqwinh5h1495=== NAME TestClientWithDependencies1496 client_integration_test.go:735: Built derivation: /build/TestClientWithDependencies3427553252/001/store/6fjkaacsqj9486vbd8gbzrzn7qd7qm25-test-script14972026/10/01 09:57:50 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=014982026/10/01 09:57:50 INFO Vacuumed table table=pending_closures14992026/10/01 09:57:50 INFO Vacuumed table table=pending_objects15002026/10/01 09:57:50 INFO Vacuumed table table=multipart_uploads15012026/10/01 09:57:50 INFO Vacuumed table table=closures15022026/10/01 09:57:50 INFO Received push request method=POST path=/api/pushes1503=== NAME TestClientFallsBackToClosures1504 client_pushes_test.go:112: Retrieved narinfo from S3:1505 StorePath: /build/TestClientFallsBackToClosures364716738/001/store/sm6l8s5ynmgqkvsf9q9zikr315cbap5q-b1506 URL: nar/15g73s50x59lr1skvid40i5l52dcb1vqal6k65ng8vn5zy6xbxv4.nar.zst1507 Compression: zstd1508 NarHash: sha256:15g73s50x59lr1skvid40i5l52dcb1vqal6k65ng8vn5zy6xbxv41509 NarSize: 2161510 References: /build/TestClientFallsBackToClosures364716738/001/store/sp6r19n4nclhvs5zx15z50qvmbxpsyra-shared-dep1511 CA: text:sha256:1c3pnwf2g0x1m7mq75kb4ygp6j040fbx4xwfb2fwglf5wqwinh5h15122026/10/01 09:57:50 INFO Vacuumed table table=objects15132026/10/01 09:57:50 INFO Aborted multipart uploads count=0 kept=015142026/10/01 09:57:50 WARN Force mode enabled - objects will be deleted immediately without grace period15152026/10/01 09:57:50 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)15162026/10/01 09:57:50 INFO Uploading hxblxy1shp9jdack9z4navnj6iygiib3-shared-dep (136B)15172026/10/01 09:57:50 INFO Uploading bbxqi47zh7wi8mcin26n7r8smmb5zwlw-top (224B)15182026/10/01 09:57:50 WARN Failed to register uploaded object key=bbxqi47zh7wi8mcin26n7r8smmb5zwlw.ls error="server returned 404: 404 page not found\n"15192026/10/01 09:57:50 WARN Failed to register uploaded object key=nar/0j4ii2xbmn7cr2rwrdnp7fawv9ms7dzwgjw7n4j8al8xjiijna7n.nar.zst error="server returned 404: 404 page not found\n"15202026/10/01 09:57:50 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=1 objects-failed-to-delete=015212026/10/01 09:57:50 INFO Vacuumed table table=pending_closures15222026/10/01 09:57:50 INFO Vacuumed table table=pending_objects15232026/10/01 09:57:50 INFO Vacuumed table table=multipart_uploads15242026/10/01 09:57:50 INFO Vacuumed table table=closures15252026/10/01 09:57:50 INFO Vacuumed table table=objects15262026/10/01 09:57:50 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"1527=== NAME TestClientWithDependencies1528 client_integration_test.go:737: Found 1 dependencies (including self)1529=== CONT TestTombstonedObjectOfferedWithoutWaiting1530--- PASS: TestClientFallsBackToClosures (0.71s)15312026/10/01 09:57:50 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15322026/10/01 09:57:50 WARN Failed to register uploaded object key=hxblxy1shp9jdack9z4navnj6iygiib3.ls error="server returned 404: 404 page not found\n"15332026/10/01 09:57:50 INFO Signed narinfos id=1 count=215342026/10/01 09:57:50 INFO Uploading 2 narinfos1535--- PASS: TestSweepSkipsRowsLockedByPush (0.51s)1536=== CONT TestClientErrorHandling1537=== RUN TestClientErrorHandling/InvalidStorePath1538=== PAUSE TestClientErrorHandling/InvalidStorePath1539=== RUN TestClientErrorHandling/InvalidAuthToken1540=== PAUSE TestClientErrorHandling/InvalidAuthToken1541=== RUN TestClientErrorHandling/ServerNotAvailable1542=== PAUSE TestClientErrorHandling/ServerNotAvailable1543=== CONT TestGCSweepSkipsPendingObjects15442026/10/01 09:57:50 WARN Failed to register uploaded object key=hxblxy1shp9jdack9z4navnj6iygiib3.narinfo error="server returned 404: 404 page not found\n"15452026/10/01 09:57:50 INFO Received push request method=POST path=/api/pushes1546=== NAME TestClientIntegration1547 client_integration_test.go:334: Created store path: /build/TestClientIntegration2503807053/002/store/8yrxlgb3skx1jg8lrgycjakvdaalmzd2-test-file.txt15482026/10/01 09:57:50 INFO Received complete push request method=POST path=/api/pushes/1/complete15492026/10/01 09:57:50 WARN Failed to register uploaded object key=bbxqi47zh7wi8mcin26n7r8smmb5zwlw.narinfo error="server returned 404: 404 page not found\n"15502026/10/01 09:57:50 INFO Aborted multipart uploads count=0 kept=015512026/10/01 09:57:50 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15522026/10/01 09:57:50 INFO Uploading 5f7235fhb9zds5m06zbszlrhpnjp7r49-unpinned-file.txt (128B)15532026/10/01 09:57:50 WARN Force mode enabled - objects will be deleted immediately without grace period15542026/10/01 09:57:50 INFO Upload complete. (110ms)1555=== NAME TestClientSharedPathCommittedMidPush1556 client_integration_test.go:816: Retrieved narinfo from S3:1557 StorePath: /build/TestClientSharedPathCommittedMidPush3477714814/001/store/hxblxy1shp9jdack9z4navnj6iygiib3-shared-dep1558 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1559 Compression: zstd1560 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821561 NarSize: 1361562 References: 1563 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n15642026/10/01 09:57:50 WARN Failed to register uploaded object key=5f7235fhb9zds5m06zbszlrhpnjp7r49.ls error="server returned 404: 404 page not found\n"15652026/10/01 09:57:50 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign15662026/10/01 09:57:50 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"15672026/10/01 09:57:50 INFO Signed narinfos id=2 count=115682026/10/01 09:57:50 INFO Uploading 1 narinfos1569 client_integration_test.go:816: Retrieved narinfo from S3:1570 StorePath: /build/TestClientSharedPathCommittedMidPush3477714814/001/store/bbxqi47zh7wi8mcin26n7r8smmb5zwlw-top1571 URL: nar/0j4ii2xbmn7cr2rwrdnp7fawv9ms7dzwgjw7n4j8al8xjiijna7n.nar.zst1572 Compression: zstd1573 NarHash: sha256:0j4ii2xbmn7cr2rwrdnp7fawv9ms7dzwgjw7n4j8al8xjiijna7n1574 NarSize: 2241575 References: /build/TestClientSharedPathCommittedMidPush3477714814/001/store/hxblxy1shp9jdack9z4navnj6iygiib3-shared-dep1576 CA: text:sha256:07mhrp8wb4qmck05xc7dq8jw7f8r28p8bgi6gi2n3dbbzgfhycv415772026/10/01 09:57:50 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."15782026/10/01 09:57:50 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."15792026/10/01 09:57:50 WARN Failed to register uploaded object key=5f7235fhb9zds5m06zbszlrhpnjp7r49.narinfo error="server returned 404: 404 page not found\n"15802026/10/01 09:57:50 INFO Received complete push request method=POST path=/api/pushes/2/complete15812026/10/01 09:57:50 INFO Upload complete. (62ms)1582=== NAME TestClientMultipleUploads1583 client_integration_test.go:480: Created store path 0: /build/TestClientMultipleUploads4152114229/001/store/lp30bcbbhy0g4kbm8l29pna61wh2y7ww-test-file-0.txt1584--- PASS: TestGetExistingObjectsLocksRows (0.37s)1585=== CONT TestService_AuthMiddleware_OIDC1586--- PASS: TestFailedS3DeleteKeepsTombstone (0.54s)1587=== CONT TestGCBugBareHashReferences1588=== CONT TestGCAdvisoryLockBlocksConcurrentRun1589--- PASS: TestClientSharedPathCommittedMidPush (0.67s)15902026/10/01 09:57:50 INFO Received push request method=POST path=/api/pushes15912026/10/01 09:57:50 INFO Received push request method=POST path=/api/pushes15922026/10/01 09:57:50 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15932026/10/01 09:57:50 INFO Uploading 6fjkaacsqj9486vbd8gbzrzn7qd7qm25-test-script (136B)15942026/10/01 09:57:50 INFO Starting cleanup of old closures method=DELETE path=/api/closures15952026/10/01 09:57:50 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)15962026/10/01 09:57:50 INFO Uploading wm4lqw1lqcc28xlslhs0wwzzbircnfwv-shared-dep (136B)15972026/10/01 09:57:50 INFO Garbage collection started15982026/10/01 09:57:50 INFO Uploading v3ax924n77bba8vmjsl2s62cf1bckb4p-a (208B)1599=== NAME TestClientMultipleUploads1600 client_integration_test.go:480: Created store path 1: /build/TestClientMultipleUploads4152114229/001/store/ccslpgr6sxrdiavviy3r288lhijx86iw-test-file-1.txt16012026/10/01 09:57:50 WARN Failed to register uploaded object key=0xwvvgkaj1bg0jafraak4aqvzb443d7a.ls error="server returned 404: 404 page not found\n"16022026/10/01 09:57:50 INFO Received push request method=POST path=/api/pushes16032026/10/01 09:57:50 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"16042026/10/01 09:57:50 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"16052026/10/01 09:57:50 INFO Aborted multipart uploads count=0 kept=016062026/10/01 09:57:50 WARN Failed to register uploaded object key=log/6jc62b6msn31k8j0yhkf3wcvd70ngaq7-test-script.drv error="server returned 404: 404 page not found\n"16072026/10/01 09:57:50 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16082026/10/01 09:57:50 WARN Failed to register uploaded object key=6fjkaacsqj9486vbd8gbzrzn7qd7qm25.ls error="server returned 404: 404 page not found\n"16092026/10/01 09:57:50 INFO Signed narinfos id=1 count=116102026/10/01 09:57:50 INFO Uploading 1 narinfos16112026/10/01 09:57:50 WARN Failed to register uploaded object key=nar/0apz3csrp0wxg7bfw5r1afsvifrbw858j6x2yvm9xp4zgd5kg1ii.nar.zst error="server returned 404: 404 page not found\n"16122026/10/01 09:57:50 WARN Failed to register uploaded object key=wm4lqw1lqcc28xlslhs0wwzzbircnfwv.ls error="server returned 404: 404 page not found\n"16132026/10/01 09:57:50 WARN Force mode enabled - objects will be deleted immediately without grace period16142026/10/01 09:57:50 INFO Received complete push request method=POST path=/api/pushes/1/complete16152026/10/01 09:57:50 WARN Failed to register uploaded object key=6fjkaacsqj9486vbd8gbzrzn7qd7qm25.narinfo error="server returned 404: 404 page not found\n"16162026/10/01 09:57:50 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16172026/10/01 09:57:50 INFO Uploading 8yrxlgb3skx1jg8lrgycjakvdaalmzd2-test-file.txt (152B)16182026/10/01 09:57:50 WARN Failed to register uploaded object key=v3ax924n77bba8vmjsl2s62cf1bckb4p.ls error="server returned 404: 404 page not found\n"16192026/10/01 09:57:50 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16202026/10/01 09:57:50 INFO Signed narinfos id=1 count=316212026/10/01 09:57:50 INFO Aborted multipart uploads count=0 kept=016222026/10/01 09:57:50 INFO Uploading 3 narinfos16232026/10/01 09:57:50 WARN Force mode enabled - objects will be deleted immediately without grace period16242026/10/01 09:57:50 INFO Upload complete. (98ms)1625 client_integration_test.go:480: Created store path 2: /build/TestClientMultipleUploads4152114229/001/store/qvc8kfmck83yqwnsvfdllkd0l4sb517v-test-file-2.txt16262026/10/01 09:57:50 WARN Failed to register uploaded object key=wm4lqw1lqcc28xlslhs0wwzzbircnfwv.narinfo error="server returned 404: 404 page not found\n"16272026/10/01 09:57:50 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:57:50 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"16292026/10/01 09:57:50 INFO Vacuumed table table=pending_closures16302026/10/01 09:57:50 INFO Vacuumed table table=pending_objects16312026/10/01 09:57:50 INFO Vacuumed table table=multipart_uploads16322026/10/01 09:57:50 WARN Failed to register uploaded object key=8yrxlgb3skx1jg8lrgycjakvdaalmzd2.ls error="server returned 404: 404 page not found\n"16332026/10/01 09:57:50 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16342026/10/01 09:57:50 INFO Signed narinfos id=1 count=116352026/10/01 09:57:50 INFO Uploading 1 narinfos1636=== CONT TestConnectSerialisesConcurrentMigrations16372026/10/01 09:57:50 INFO Aborted multipart uploads count=0 kept=01638--- PASS: TestCacheStatsHandler (0.28s)16392026/10/01 09:57:50 INFO Vacuumed table table=closures16402026/10/01 09:57:50 WARN Force mode enabled - objects will be deleted immediately without grace period16412026/10/01 09:57:50 WARN Failed to register uploaded object key=v3ax924n77bba8vmjsl2s62cf1bckb4p.narinfo error="server returned 404: 404 page not found\n"16422026/10/01 09:57:50 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=016432026/10/01 09:57:50 INFO Received complete push request method=POST path=/api/pushes/1/complete16442026/10/01 09:57:50 INFO Received complete push request method=POST path=/api/pushes/1/complete16452026/10/01 09:57:50 WARN Failed to register uploaded object key=0xwvvgkaj1bg0jafraak4aqvzb443d7a.narinfo error="server returned 404: 404 page not found\n"16462026/10/01 09:57:50 WARN Failed to register uploaded object key=8yrxlgb3skx1jg8lrgycjakvdaalmzd2.narinfo error="server returned 404: 404 page not found\n"16472026/10/01 09:57:50 INFO Vacuumed table table=objects16482026/10/01 09:57:50 INFO Vacuumed table table=pending_closures16492026/10/01 09:57:50 INFO Vacuumed table table=pending_objects16502026/10/01 09:57:50 INFO Vacuumed table table=multipart_uploads16512026/10/01 09:57:50 INFO Vacuumed table table=closures16522026/10/01 09:57:50 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=016532026/10/01 09:57:50 INFO Upload complete. (98ms)16542026/10/01 09:57:50 INFO Vacuumed table table=objects16552026/10/01 09:57:50 INFO Vacuumed table table=pending_closures16562026/10/01 09:57:50 INFO Upload complete. (120ms)16572026/10/01 09:57:50 INFO Vacuumed table table=pending_objects16582026/10/01 09:57:50 INFO Vacuumed table table=multipart_uploads1659=== NAME TestClientPushesUseOnePush1660 client_pushes_test.go:97: Retrieved narinfo from S3:1661 StorePath: /build/TestClientPushesUseOnePush26535308/001/store/wm4lqw1lqcc28xlslhs0wwzzbircnfwv-shared-dep1662 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1663 Compression: zstd1664 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821665 NarSize: 1361666 References: 1667 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n16682026/10/01 09:57:50 INFO Vacuumed table table=closures1669 client_pushes_test.go:97: Retrieved narinfo from S3:1670 StorePath: /build/TestClientPushesUseOnePush26535308/001/store/v3ax924n77bba8vmjsl2s62cf1bckb4p-a16712026/10/01 09:57:50 INFO Vacuumed table table=objects1672 URL: nar/0apz3csrp0wxg7bfw5r1afsvifrbw858j6x2yvm9xp4zgd5kg1ii.nar.zst1673 Compression: zstd1674 NarHash: sha256:0apz3csrp0wxg7bfw5r1afsvifrbw858j6x2yvm9xp4zgd5kg1ii1675 NarSize: 2081676 References: /build/TestClientPushesUseOnePush26535308/001/store/wm4lqw1lqcc28xlslhs0wwzzbircnfwv-shared-dep1677 CA: text:sha256:1c66pgqmy1d0jm36dgyji49k749z1rfin5x5dyxngfqkn1bmhwic1678=== CONT TestProxyWriteTimeout/narinfo1679=== CONT TestProxyWriteTimeout/unknown_size1680--- PASS: TestGCSweepDeliversEachKeyOnce (0.32s)1681=== NAME TestClientWithDependencies1682 client_integration_test.go:753: Skipping nix copy test - isolated store (/build/TestClientWithDependencies3427553252/001/store) requires matching store prefix1683=== CONT TestProxyWriteTimeout/10_GiB_nar1684=== CONT TestProxyWriteTimeout/1_GiB_nar1685=== CONT TestParseSingleRange/none1686--- PASS: TestProxyWriteTimeout (0.02s)1687 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1688 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1689 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1690 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1691=== CONT TestParseSingleRange/start_far_past_EOF1692=== CONT TestParseSingleRange/start_past_EOF1693=== CONT TestParseSingleRange/single_byte1694=== CONT TestParseSingleRange/suffix_exceeds_size1695=== CONT TestParseSingleRange/end_clamped_to_size1696=== CONT TestParseSingleRange/open-ended1697=== CONT TestParseSingleRange/suffix1698=== CONT TestParseSingleRange/malformed_end_before_start1699=== CONT TestParseSingleRange/malformed_both_empty1700=== CONT TestParseSingleRange/closed1701=== CONT TestParseSingleRange/malformed_no_dash1702=== NAME TestClientPushesUseOnePush1703 client_pushes_test.go:97: Retrieved narinfo from S3:1704 StorePath: /build/TestClientPushesUseOnePush26535308/001/store/0xwvvgkaj1bg0jafraak4aqvzb443d7a-b1705 URL: nar/0apz3csrp0wxg7bfw5r1afsvifrbw858j6x2yvm9xp4zgd5kg1ii.nar.zst1706 Compression: zstd1707 NarHash: sha256:0apz3csrp0wxg7bfw5r1afsvifrbw858j6x2yvm9xp4zgd5kg1ii1708 NarSize: 2081709 References: /build/TestClientPushesUseOnePush26535308/001/store/wm4lqw1lqcc28xlslhs0wwzzbircnfwv-shared-dep1710 CA: text:sha256:1c66pgqmy1d0jm36dgyji49k749z1rfin5x5dyxngfqkn1bmhwic1711=== CONT TestParseSingleRange/unknown_unit1712=== CONT TestParseSingleRange/multi-range_ignored1713=== CONT TestIsValidCachePath/narinfo1714--- PASS: TestParseSingleRange (0.01s)1715 --- PASS: TestParseSingleRange/none (0.00s)1716 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1717 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1718 --- PASS: TestParseSingleRange/single_byte (0.00s)1719 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1720 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1721 --- PASS: TestParseSingleRange/open-ended (0.00s)1722 --- PASS: TestParseSingleRange/suffix (0.00s)1723 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1724 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1725 --- PASS: TestParseSingleRange/closed (0.00s)1726 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1727 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1728 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1729=== CONT TestIsValidCachePath/short_hash1730=== CONT TestIsValidCachePath/wrong_extension1731=== CONT TestIsValidCachePath/nix-cache-info1732=== CONT TestIsValidCachePath/empty1733=== CONT TestIsValidCachePath/random_path1734=== CONT TestIsValidCachePath/invalid_char_e1735=== CONT TestIsValidCachePath/index.html1736=== CONT TestIsValidCachePath/traversal_parent1737=== CONT TestIsValidCachePath/traversal_in_middle1738=== CONT TestIsValidCachePath/leading_slash1739=== CONT TestIsValidCachePath/invalid_char_u1740=== CONT TestIsValidCachePath/log1741=== CONT TestIsValidCachePath/nar_xz1742=== CONT TestIsValidCachePath/nar_zst1743=== CONT TestIsValidCachePath/realisation1744=== CONT TestIsValidCachePath/nar_uncompressed1745=== CONT TestIsValidCachePath/nar_bz21746=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1747=== CONT TestIsValidCachePath/ls1748=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure17492026/10/01 09:57:50 INFO Received uploads request method=POST path=/1750--- PASS: TestIsValidCachePath (0.01s)1751 --- PASS: TestIsValidCachePath/narinfo (0.00s)1752 --- PASS: TestIsValidCachePath/short_hash (0.00s)1753 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1754 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1755 --- PASS: TestIsValidCachePath/empty (0.00s)1756 --- PASS: TestIsValidCachePath/random_path (0.00s)1757 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1758 --- PASS: TestIsValidCachePath/index.html (0.00s)1759 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1760 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1761 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1762 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1763 --- PASS: TestIsValidCachePath/log (0.00s)1764 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1765 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1766 --- PASS: TestIsValidCachePath/realisation (0.00s)1767 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1768 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1769 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1770 --- PASS: TestIsValidCachePath/ls (0.00s)17712026/10/01 09:57:50 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1772=== NAME TestClientCADerivations1773 client_ca_test.go:136: Built CA derivation: /build/TestClientCADerivations3567108600/001/store/8iy4g2crg4nqmi63fyrisd087r3nj6cv-ca-test17742026/10/01 09:57:50 INFO All 1 paths already cached1775=== NAME TestClientIntegration1776 client_integration_test.go:360: Retrieved narinfo from S3:1777 StorePath: /build/TestClientIntegration2503807053/002/store/8yrxlgb3skx1jg8lrgycjakvdaalmzd2-test-file.txt1778 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1779 Compression: zstd1780 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11781 NarSize: 1521782 References: 1783 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11784--- PASS: TestClientWithDependencies (0.73s)1785=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts17862026/10/01 09:57:50 INFO Received request for more parts method=POST path=/17872026/10/01 09:57:50 INFO Completed multipart upload object_key=nar/cccccccccccccccccccccccccccccccc00000000000000000000.nar.zst upload_id=ZDU5YmE3NTQtNjc2NC00Y2RlLThjMDQtODk3NGUzNmEwMjMxLmQxZGNhZTdkLTgwNjQtNDQ0Mi04OWZmLWJiZWZlZDJhYmY0ZngxNzkwODQ4NjcwMTY4MjQ4Mzgx parts=1017882026/10/01 09:57:50 INFO Received complete push request method=POST path=/api/pushes/2/complete1789=== NAME TestClientIntegration1790 client_integration_test.go:361: Retrieved .ls file from S3 (compressed size: 77 bytes)1791 client_integration_test.go:361: Decompressed .ls content (64 bytes):1792 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1793--- PASS: TestClientPushesUseOnePush (0.70s)1794=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart17952026/10/01 09:57:50 INFO Received complete multipart upload request method=POST path=/17962026/10/01 09:57:50 INFO Received push request method=POST path=/api/pushes1797=== NAME TestClientCADerivations1798 client_ca_test.go:139: Found 1 dependencies (including self)17992026/10/01 09:57:50 INFO Received uploads request method=POST path=/api/pending_closures1800--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (3.14s)1801=== CONT TestPush_RejectsBadRequests/no_objects18022026/10/01 09:57:50 INFO Received push request method=POST path=/api/pushes1803=== CONT TestPush_RejectsBadRequests/bad_root18042026/10/01 09:57:50 INFO Received push request method=POST path=/api/pushes1805=== CONT TestPush_RejectsBadRequests/no_roots18062026/10/01 09:57:50 INFO Received push request method=POST path=/api/pushes1807=== CONT TestPush_RejectsBadRequests/root_not_in_objects18082026/10/01 09:57:50 INFO Received push request method=POST path=/api/pushes1809=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info18102026/10/01 09:57:50 INFO Received uploads request method=POST path=/1811=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal18122026/10/01 09:57:50 INFO Received uploads request method=POST path=/1813=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key18142026/10/01 09:57:50 INFO Received complete multipart upload request method=POST path=/1815=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key18162026/10/01 09:57:50 INFO Received request for more parts method=POST path=/1817=== CONT TestIsValidUploadKey/narinfo1818--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1819 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1820 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1821 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1822 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1823=== CONT TestIsValidUploadKey/nix-cache-info1824=== CONT TestIsValidUploadKey/unknown_type1825=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1826=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1827=== CONT TestIsValidUploadKey/index.html1828=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1829=== CONT TestIsValidUploadKey/realisation_plus_in_output1830=== CONT TestIsValidUploadKey/absolute1831=== CONT TestIsValidUploadKey/build_log1832=== CONT TestIsValidUploadKey/realisation18332026/10/01 09:57:50 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)1834=== CONT TestIsValidUploadKey/empty_key18352026/10/01 09:57:50 INFO Uploading ccslpgr6sxrdiavviy3r288lhijx86iw-test-file-1.txt (160B)1836=== CONT TestIsValidUploadKey/build_log_equals18372026/10/01 09:57:50 INFO Uploading lp30bcbbhy0g4kbm8l29pna61wh2y7ww-test-file-0.txt (160B)1838=== CONT TestIsValidUploadKey/nar_xz18392026/10/01 09:57:50 INFO Uploading qvc8kfmck83yqwnsvfdllkd0l4sb517v-test-file-2.txt (160B)1840=== CONT TestIsValidUploadKey/traversal_nar1841=== CONT TestIsValidUploadKey/nar_plain1842=== CONT TestIsValidUploadKey/traversal1843=== CONT TestIsValidUploadKey/build_log_question_mark1844=== CONT TestIsValidUploadKey/build_log_plus_in_name1845=== CONT TestIsValidUploadKey/build_log_home-manager_file1846=== CONT TestIsValidUploadKey/nar_zst1847=== CONT TestIsValidUploadKey/listing1848=== CONT TestPendingClosureWriteTimeout/400_objects1849=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1850--- PASS: TestIsValidUploadKey (0.00s)1851 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1852 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1853 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1854 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1855 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1856 --- PASS: TestIsValidUploadKey/index.html (0.00s)1857 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1858 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1859 --- PASS: TestIsValidUploadKey/absolute (0.00s)1860 --- PASS: TestIsValidUploadKey/build_log (0.00s)1861 --- PASS: TestIsValidUploadKey/realisation (0.00s)1862 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1863 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1864 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1865 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1866 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1867 --- PASS: TestIsValidUploadKey/traversal (0.00s)1868 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1869 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1870 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1871 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1872 --- PASS: TestIsValidUploadKey/listing (0.00s)18732026/10/01 09:57:50 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"18742026/10/01 09:57:50 INFO Received uploads request method=POST path=/api/pending_closures18752026/10/01 09:57:50 INFO Aborted multipart uploads count=0 kept=01876--- PASS: TestPush_RejectsBadRequests (0.55s)1877 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)1878 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)1879 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)1880 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)18812026/10/01 09:57:50 WARN Force mode enabled - objects will be deleted immediately without grace period18822026/10/01 09:57:50 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=018832026-10-01 09:57:50.969 UTC [1841] ERROR: duplicate key value violates unique constraint "pg_class_relname_nsp_index"18842026-10-01 09:57:50.969 UTC [1841] DETAIL: Key (relname, relnamespace)=(goose_db_version_id_seq, 2200) already exists.18852026-10-01 09:57:50.969 UTC [1841] STATEMENT: CREATE TABLE goose_db_version (1886 id integer PRIMARY KEY GENERATED BY DEFAULT AS IDENTITY,1887 version_id bigint NOT NULL,1888 is_applied boolean NOT NULL,1889 tstamp timestamp NOT NULL DEFAULT now()1890 )18912026/10/01 09:57:50 INFO Vacuumed table table=pending_closures18922026/10/01 09:57:50 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"18932026/10/01 09:57:50 INFO Vacuumed table table=pending_objects18942026/10/01 09:57:50 WARN Failed to register uploaded object key=lp30bcbbhy0g4kbm8l29pna61wh2y7ww.ls error="server returned 404: 404 page not found\n"18952026/10/01 09:57:50 INFO Vacuumed table table=multipart_uploads18962026/10/01 09:57:50 INFO Vacuumed table table=closures18972026/10/01 09:57:50 WARN Failed to register uploaded object key=qvc8kfmck83yqwnsvfdllkd0l4sb517v.ls error="server returned 404: 404 page not found\n"18982026/10/01 09:57:50 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"18992026/10/01 09:57:50 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19002026/10/01 09:57:50 WARN Failed to register uploaded object key=ccslpgr6sxrdiavviy3r288lhijx86iw.ls error="server returned 404: 404 page not found\n"19012026/10/01 09:57:50 INFO Vacuumed table table=objects19022026/10/01 09:57:50 INFO Signed narinfos id=1 count=319032026/10/01 09:57:50 INFO Uploading 3 narinfos1904--- PASS: TestTombstonedObjectOfferedWithoutWaiting (0.27s)19052026/10/01 09:57:50 WARN Failed to register uploaded object key=ccslpgr6sxrdiavviy3r288lhijx86iw.narinfo error="server returned 404: 404 page not found\n"1906=== CONT TestPendingClosureWriteTimeout/670k_objects19072026/10/01 09:57:50 INFO Received complete push request method=POST path=/api/pushes/1/complete1908=== CONT TestPendingClosureWriteTimeout/negative19092026/10/01 09:57:50 WARN Failed to register uploaded object key=qvc8kfmck83yqwnsvfdllkd0l4sb517v.narinfo error="server returned 404: 404 page not found\n"1910=== CONT TestPendingClosureWriteTimeout/empty19112026/10/01 09:57:50 WARN Failed to register uploaded object key=lp30bcbbhy0g4kbm8l29pna61wh2y7ww.narinfo error="server returned 404: 404 page not found\n"1912=== CONT TestServerTLSConfig/no_client_CA19132026/10/01 09:57:50 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:40097/oidc1914=== CONT TestServerTLSConfig/not_a_PEM_file1915=== CONT TestServerTLSConfig/missing_CA_file1916=== CONT TestGCEndsOnShutdown/before_the_run1917--- PASS: TestServerTLSConfig (0.00s)1918 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1919 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)1920 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)19212026/10/01 09:57:50 INFO Received push request method=POST path=/api/pushes19222026/10/01 09:57:50 INFO Upload complete. (113ms)1923=== NAME TestClientMultipleUploads1924 client_integration_test.go:491: Uploaded 3 paths in 150.541029ms19252026/10/01 09:57:50 INFO Object in database but missing from S3 key=8yrxlgb3skx1jg8lrgycjakvdaalmzd2.ls19262026/10/01 09:57:50 WARN Found objects in DB but missing from S3, will re-upload count=119272026/10/01 09:57:50 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)1928--- PASS: TestGCSweepSkipsPendingObjects (0.28s)1929=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark19302026/10/01 09:57:51 INFO Received complete push request method=POST path=/api/pushes/2/complete1931--- PASS: TestPushWaitsForSweepHoldingRow (0.91s)1932=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete19332026/10/01 09:57:51 WARN Failed to register uploaded object key=8yrxlgb3skx1jg8lrgycjakvdaalmzd2.ls error="server returned 404: 404 page not found\n"19342026/10/01 09:57:51 INFO Upload complete. (54ms)1935=== NAME TestClientIntegration1936 client_integration_test.go:389: Retrieved .ls file from S3 (compressed size: 62 bytes)1937 client_integration_test.go:389: Decompressed .ls content (49 bytes):1938 {"version":1,"root":{"type":"regular","size":39}}19392026/10/01 09:57:51 INFO Received push request method=POST path=/api/pushes1940=== CONT TestCacheConfigHandler/full_config,_no_issuer1941--- PASS: TestClientMultipleUploads (0.68s)1942=== CONT TestCacheConfigHandler/no_cache_url_configured1943=== CONT TestCacheConfigHandler/no_signing_keys1944=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1945=== CONT TestResolveDBConnectionString/flag_wins1946--- PASS: TestCacheConfigHandler (0.00s)1947 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1948 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1949 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1950 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)19512026/10/01 09:57:51 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)1952=== CONT TestResolveDBConnectionString/nothing_configured19532026/10/01 09:57:51 INFO Uploading 8iy4g2crg4nqmi63fyrisd087r3nj6cv-ca-test (144B)1954=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1955=== CONT TestResolveDBConnectionString/missing_file_is_an_error1956=== CONT TestResolveDBConnectionString/file_when_flag_empty1957=== CONT TestService_RequireScope_OIDC/builder_may_not_admin1958--- PASS: TestResolveDBConnectionString (0.00s)1959 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1960 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1961 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1962 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1963 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)1964=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read1965=== CONT TestService_RequireScope_OIDC/writer_implies_read1966=== CONT TestService_RequireScope_OIDC/static_token_may_admin1967=== CONT TestService_RequireScope_OIDC/ops_may_admin1968=== CONT TestService_RequireScope_OIDC/builder_may_write1969=== CONT TestService_RequireScope_OIDC/ops_may_not_write19702026/10/01 09:57:51 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"1971=== CONT TestService_RequireScope_OIDC/reader_may_read1972=== CONT TestService_RequireScope_OIDC/static_token_may_write1973=== CONT TestService_RequireScope_OIDC/reader_may_not_write1974=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check19752026/10/01 09:57:51 WARN Failed to register uploaded object key=8iy4g2crg4nqmi63fyrisd087r3nj6cv.ls error="server returned 404: 404 page not found\n"19762026/10/01 09:57:51 WARN Failed to register uploaded object key=log/vi4qvdz284qrijgqmjpy3vdmywsq6x1f-ca-test.drv error="server returned 404: 404 page not found\n"19772026/10/01 09:57:51 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19782026/10/01 09:57:51 INFO Signed narinfos id=1 count=119792026/10/01 09:57:51 INFO Uploading 1 narinfos19802026/10/01 09:57:51 INFO Received complete push request method=POST path=/api/pushes/1/complete19812026/10/01 09:57:51 WARN Failed to register uploaded object key=8iy4g2crg4nqmi63fyrisd087r3nj6cv.narinfo error="server returned 404: 404 page not found\n"1982--- PASS: TestService_RequireScope_OIDC (0.56s)1983 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)1984 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)1985 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)1986 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)1987 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)1988 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)1989 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)1990 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)1991 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)1992 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)19932026/10/01 09:57:51 INFO Upload complete. (128ms)1994=== NAME TestClientCADerivations1995 client_ca_test.go:180: Narinfo contains CA field: StorePath: /build/TestClientCADerivations3567108600/001/store/8iy4g2crg4nqmi63fyrisd087r3nj6cv-ca-test1996 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1997 Compression: zstd1998 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1999 NarSize: 1442000 References: 2001 Deriver: /build/TestClientCADerivations3567108600/001/store/vi4qvdz284qrijgqmjpy3vdmywsq6x1f-ca-test.drv2002 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2003 client_ca_test.go:185: Checking for realisation files in S3...20042026/10/01 09:57:51 INFO Received push request method=POST path=/api/pushes2005 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations2006 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache20072026/10/01 09:57:51 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)20082026/10/01 09:57:51 INFO Received complete push request method=POST path=/api/pushes/3/complete20092026/10/01 09:57:51 WARN Failed to register uploaded object key=8yrxlgb3skx1jg8lrgycjakvdaalmzd2.ls error="server returned 404: 404 page not found\n"20102026/10/01 09:57:51 INFO Upload complete. (62ms)2011=== NAME TestClientIntegration2012 client_integration_test.go:405: Retrieved .ls file from S3 (compressed size: 62 bytes)2013 client_integration_test.go:405: Decompressed .ls content (49 bytes):2014 {"version":1,"root":{"type":"regular","size":39}}20152026/10/01 09:57:51 INFO Received uploads request method=POST path=/api/pending_closures20162026/10/01 09:57:51 INFO Received complete multipart upload request method=POST path=/api/multipart/complete20172026/10/01 09:57:51 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=ZDU5YmE3NTQtNjc2NC00Y2RlLThjMDQtODk3NGUzNmEwMjMxLjJhMmFmOTY4LWU4YzgtNDU2MC1iMzQxLWQ4ZmIwMTBjNDk3NHgxNzkwODQ4NjcwNDcwMzI5NjUy parts=1220182026/10/01 09:57:51 INFO Received uploads request method=POST path=/api/pending_closures2019=== NAME TestClientCADerivations2020 client_ca_test.go:258: nix copy output: warning: you don't have Internet access; disabling some network-dependent features2021 warning: failed to create TLS context for AWS credential providers; SSO, STS WebIdentity, and ECS container authentication will be unavailable2022 error: binary cache 's3://bucket81?endpoint=http://localhost:39607®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/build/TestClientCADerivations3567108600/001/store'2023 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 120242026/10/01 09:57:51 INFO Received uploads request method=POST path=/api/pending_closures2025--- PASS: TestGCBugBareHashReferences (0.46s)2026=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows2027--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (1.24s)2028=== CONT TestClientErrorHandling/InvalidStorePath20292026/10/01 09:57:51 INFO Received push request method=POST path=/api/pushes2030=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token2031=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token2032=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2033=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2034=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected2035=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected2036=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2037=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2038=== CONT TestClientErrorHandling/ServerNotAvailable2039=== CONT TestClientErrorHandling/InvalidAuthToken20402026/10/01 09:57:51 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)20412026/10/01 09:57:51 INFO Uploading czlldvwx9q6cbrn2fswg1gq2dps6sacc-lost-commit.txt (152B)20422026/10/01 09:57:51 WARN Failed to register uploaded object key=nar/04d5klw9iix884nk82y7nlkps8afh2bg119y7zkvcf1pc1x2y2jl.nar.zst error="server returned 404: 404 page not found\n"20432026/10/01 09:57:51 WARN Failed to register uploaded object key=czlldvwx9q6cbrn2fswg1gq2dps6sacc.ls error="server returned 404: 404 page not found\n"20442026/10/01 09:57:51 INFO Received sign narinfos request method=POST path=/api/pushes/4/sign20452026/10/01 09:57:51 INFO Signed narinfos id=4 count=120462026/10/01 09:57:51 INFO Uploading 1 narinfos2047=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2048--- PASS: TestClientCADerivations (0.70s)2049=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected20502026/10/01 09:57:51 INFO lead: released remote=192.0.2.1:123420512026/10/01 09:57:51 WARN Authentication failed token_preview=eyJhbGciOi...wLGojRBGMA token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2052=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected20532026/10/01 09:57:51 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]2054=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured20552026/10/01 09:57:51 INFO Received complete push request method=POST path=/api/pushes/4/complete20562026/10/01 09:57:51 WARN Failed to register uploaded object key=czlldvwx9q6cbrn2fswg1gq2dps6sacc.narinfo error="server returned 404: 404 page not found\n"20572026/10/01 09:57:51 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Post \"http://127.0.0.1:45147/api/pushes/4/complete\": EOF" url=http://127.0.0.1:45147/api/pushes/4/complete20582026/10/01 09:57:51 INFO Aborted multipart uploads count=0 kept=020592026/10/01 09:57:51 WARN Force mode enabled - objects will be deleted immediately without grace period2060--- PASS: TestService_AuthMiddleware_OIDC (0.49s)2061 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.01s)2062 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)2063 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2064 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2065--- PASS: TestLeadEndsOnShutdown (1.42s)20662026/10/01 09:57:51 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:39607/bucket91/?delete=\": context canceled"20672026/10/01 09:57:51 INFO Aborted multipart uploads count=0 kept=020682026/10/01 09:57:51 WARN Force mode enabled - objects will be deleted immediately without grace period20692026/10/01 09:57:51 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"20702026-10-01 09:57:51.320 UTC [2274] ERROR: canceling statement due to user request20712026-10-01 09:57:51.320 UTC [2274] CONTEXT: PL/pgSQL function object_stats_apply() line 5 at statement block20722026-10-01 09:57:51.320 UTC [2274] STATEMENT: -- name: MarkStaleObjects :execrows2073 WITH RECURSIVE ct AS (2074 SELECT timezone('UTC', now()) AS now2075 ),2076 closure_reach AS (2077 -- Start with all closure keys2078 SELECT o.key, o.refs2079 FROM objects o2080 INNER JOIN closures c ON o.key = c.key2081 UNION2082 -- Recursively add all referenced objects2083 SELECT o.key, o.refs2084 FROM objects o2085 INNER JOIN closure_reach cr ON o.key = ANY(cr.refs)2086 ),2087 reachable_objects AS (2088 SELECT DISTINCT key FROM closure_reach2089 ),2090 stale_objects AS (2091 SELECT o.key2092 FROM objects AS o, ct2093 WHERE2094 NOT EXISTS (2095 SELECT 12096 FROM reachable_objects ro2097 WHERE ro.key = o.key2098 )2099 AND NOT EXISTS (2100 SELECT 12101 FROM pending_objects AS po2102 WHERE po.key = o.key2103 )2104 AND o.deleted_at IS NULL -- Only mark fresh objects2105 ORDER BY o.key COLLATE "C" -- lock in key order, like commit_pending_closure2106 FOR UPDATE2107 )2108 UPDATE objects2109 SET2110 deleted_at = ct.now,2111 first_deleted_at = COALESCE(first_deleted_at, ct.now)2112 FROM stale_objects, ct2113 WHERE objects.key = stale_objects.key2114 21152026/10/01 09:57:51 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/present2116--- PASS: TestGCEndsOnShutdown (0.00s)2117 --- PASS: TestGCEndsOnShutdown/before_the_run (0.25s)2118 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (0.30s)2119 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (0.34s)2120--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.56s)21212026/10/01 09:57:51 INFO Received uploads request method=POST path=/api/pending_closures21222026/10/01 09:57:51 INFO Aborted multipart uploads count=0 kept=021232026/10/01 09:57:51 WARN Force mode enabled - objects will be deleted immediately without grace period21242026/10/01 09:57:51 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=021252026/10/01 09:57:51 INFO Vacuumed table table=pending_closures21262026/10/01 09:57:51 INFO Vacuumed table table=pending_objects21272026/10/01 09:57:51 INFO Vacuumed table table=multipart_uploads21282026/10/01 09:57:51 INFO Vacuumed table table=closures21292026/10/01 09:57:51 INFO Vacuumed table table=objects2130=== NAME TestOrphanedObjectsGCStressTest2131 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains21322026/10/01 09:57:51 INFO Received complete push request method=POST path=/api/pushes/4/complete21332026-10-01 09:57:51.379 UTC [1148] ERROR: Push does not exist: id=421342026-10-01 09:57:51.379 UTC [1148] CONTEXT: PL/pgSQL function commit_push(bigint) line 9 at RAISE21352026-10-01 09:57:51.379 UTC [1148] STATEMENT: -- name: CommitPush :exec2136 SELECT commit_push($1::bigint)2137 21382026/10/01 09:57:51 INFO Upload complete. (181ms)2139=== NAME TestClientIntegration2140 client_integration_test.go:435: Retrieved narinfo from S3:2141 StorePath: /build/TestClientIntegration2503807053/002/store/czlldvwx9q6cbrn2fswg1gq2dps6sacc-lost-commit.txt2142 URL: nar/04d5klw9iix884nk82y7nlkps8afh2bg119y7zkvcf1pc1x2y2jl.nar.zst2143 Compression: zstd2144 NarHash: sha256:04d5klw9iix884nk82y7nlkps8afh2bg119y7zkvcf1pc1x2y2jl2145 NarSize: 1522146 References: 2147 CA: fixed:r:sha256:04d5klw9iix884nk82y7nlkps8afh2bg119y7zkvcf1pc1x2y2jl2148 client_integration_test.go:438: Testing garbage collection...2149=== NAME TestOrphanedObjectsGCStressTest2150 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion21512026/10/01 09:57:51 INFO Starting cleanup of old closures method=DELETE path=/api/closures21522026/10/01 09:57:51 INFO Garbage collection started21532026/10/01 09:57:51 INFO Aborted multipart uploads count=0 kept=021542026/10/01 09:57:51 INFO Received uploads request method=POST path=/api/pending_closures21552026/10/01 09:57:51 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=188.068638ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present21562026/10/01 09:57:51 WARN Force mode enabled - objects will be deleted immediately without grace period21572026/10/01 09:57:51 INFO Aborted multipart uploads count=0 kept=021582026/10/01 09:57:51 WARN Force mode enabled - objects will be deleted immediately without grace period21592026/10/01 09:57:51 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=021602026/10/01 09:57:51 INFO Vacuumed table table=pending_closures21612026/10/01 09:57:51 INFO Vacuumed table table=pending_objects21622026/10/01 09:57:51 INFO Vacuumed table table=multipart_uploads21632026/10/01 09:57:51 INFO Vacuumed table table=closures21642026/10/01 09:57:51 INFO Vacuumed table table=objects21652026/10/01 09:57:51 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=021662026/10/01 09:57:51 INFO Vacuumed table table=pending_closures21672026/10/01 09:57:51 INFO Vacuumed table table=pending_objects21682026/10/01 09:57:51 INFO Vacuumed table table=multipart_uploads21692026/10/01 09:57:51 INFO Vacuumed table table=closures21702026/10/01 09:57:51 INFO Vacuumed table table=objects2171--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2172 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (0.34s)2173 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (0.27s)21742026/10/01 09:57:51 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"21752026/10/01 09:57:51 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"21762026/10/01 09:57:51 INFO lead: released remote=192.0.2.1:123421772026/10/01 09:57:51 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=385.335154ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present21782026/10/01 09:57:51 INFO lead: acquired remote=192.0.2.1:12342179=== NAME TestOrphanedObjectsGCStressTest2180 orphaned_objects_gc_test.go:509: Stress test completed successfully:2181 orphaned_objects_gc_test.go:510: - Active objects preserved: 202182 orphaned_objects_gc_test.go:511: - Objects deleted: 2102183 orphaned_objects_gc_test.go:512: - Total GC'd: 21021842026/10/01 09:57:51 INFO Received complete multipart upload request method=POST path=/api/multipart/complete2185--- PASS: TestOrphanedObjectsGCStressTest (3.31s)21862026/10/01 09:57:51 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=ZDU5YmE3NTQtNjc2NC00Y2RlLThjMDQtODk3NGUzNmEwMjMxLmQwMzBiYTQzLWJiMjAtNDE3Yi1hYjAyLTNlNmQzODJjOTg3NngxNzkwODQ4NjcxMjMwNzkxNjQ2 error="Get \"http://127.0.0.1:1/bucket70/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"21872026/10/01 09:57:51 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=ZDU5YmE3NTQtNjc2NC00Y2RlLThjMDQtODk3NGUzNmEwMjMxLmE1MjM4MDQwLWJjNWMtNDdiYS1iZGU3LTNmZTg0MmY4ZDY5NngxNzkwODQ4NjcxMjE1ODU2MDE1 parts=1221882026/10/01 09:57:51 INFO Received cleanup request method=DELETE path=/api/pending_closures21892026/10/01 09:57:51 INFO Aborted multipart uploads count=1 kept=02190--- PASS: TestRedundantMultipartUpload (1.93s)2191--- PASS: TestPendingClosureWriteTimeout (0.00s)2192 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2193 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2194 --- PASS: TestPendingClosureWriteTimeout/negative (0.00s)2195 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2196 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (1.03s)2197--- PASS: TestConnectSerialisesConcurrentMigrations (1.14s)21982026/10/01 09:57:52 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=783.472194ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present21992026/10/01 09:57:52 INFO lead: released remote=192.0.2.1:12342200--- PASS: TestLeadElectsOneAndHandsOver (2.70s)22012026/10/01 09:57:52 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.694111728s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present22022026/10/01 09:57:52 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=022032026/10/01 09:57:52 INFO Received create pin request method=POST path=/api/pins/myapp22042026/10/01 09:57:52 INFO Created/updated pin name=myapp store_path=/build/TestPinProtectsFromGC1532844878/001/store/9d4y30abrjd620b9j63zasfxa2cywz7z-pinned-file.txt narinfo_key=9d4y30abrjd620b9j63zasfxa2cywz7z.narinfo22052026/10/01 09:57:52 INFO Starting cleanup of old closures method=DELETE path=/api/closures22062026/10/01 09:57:52 INFO Garbage collection started22072026/10/01 09:57:52 INFO Aborted multipart uploads count=0 kept=022082026/10/01 09:57:52 WARN Force mode enabled - objects will be deleted immediately without grace period22092026/10/01 09:57:52 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=022102026/10/01 09:57:52 INFO Vacuumed table table=pending_closures22112026/10/01 09:57:52 INFO Vacuumed table table=pending_objects22122026/10/01 09:57:52 INFO Vacuumed table table=multipart_uploads22132026/10/01 09:57:52 INFO Vacuumed table table=closures22142026/10/01 09:57:52 INFO Vacuumed table table=objects2215--- PASS: TestReadProxyOutlastsServerWriteTimeout (5.15s)22162026/10/01 09:57:53 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=2 objects_marked=6 objects_deleted=6 objects_failed=02217=== NAME TestClientIntegration2218 client_integration_test.go:445: Objects in database after GC:2219 client_integration_test.go:445: Successfully deleted all objects with GC --force2220--- PASS: TestClientIntegration (3.09s)22212026/10/01 09:57:54 WARN Rate limiter enabled after throttle name=s3-test rate=522222026/10/01 09:57:54 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."2223=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle2224 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=102225 throttle_test.go:215: Rate limiter: enabled=true, rate=5.002226--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (4.34s)22272026/10/01 09:57:54 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-config22282026/10/01 09:57:54 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=200.624873ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2229=== NAME TestPinProtectsFromGC2230 client_integration_test.go:976: Pin successfully protected closure from garbage collection2231--- PASS: TestPinProtectsFromGC (4.83s)22322026/10/01 09:57:54 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=406.404338ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2233--- PASS: TestConnectWaitsForAPeerMigration (5.20s)22342026/10/01 09:57:55 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=842.045849ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22352026/10/01 09:57:55 INFO Aborted multipart uploads count=1 kept=022362026/10/01 09:57:55 INFO Received cleanup request method=DELETE path=/api/pending_closures22372026/10/01 09:57:55 INFO Aborted multipart uploads count=1 kept=02238--- PASS: TestPendingCleanupUsesOneCutoff (6.79s)22392026/10/01 09:57:56 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.547782966s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22402026/10/01 09:57:57 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"22412026/10/01 09:57:57 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-config22422026/10/01 09:57:57 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=200.205399ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22432026/10/01 09:57:58 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=438.420086ms 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:57:58 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=865.509657ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2245--- PASS: TestUploadHandlersRejectOversizedBody (0.45s)2246 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.54s)2247 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.61s)2248 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (8.03s)22492026/10/01 09:57:59 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.738243148s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22502026/10/01 09:58:01 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_closures22512026/10/01 09:58:01 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=181.844352ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22522026/10/01 09:58:01 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=413.726858ms 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:58:01 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=863.353725ms 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:58:02 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.732640805s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2255--- PASS: TestClientErrorHandling (0.00s)2256 --- PASS: TestClientErrorHandling/InvalidStorePath (0.21s)2257 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.33s)2258 --- PASS: TestClientErrorHandling/ServerNotAvailable (14.41s)2259PASS2260{"timestamp":"2026-10-01T09:58:05.978260873Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:55480","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(393)"}2261{"timestamp":"2026-10-01T09:58:05.978256943Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:55482","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(390)"}2262{"timestamp":"2026-10-01T09:58:05.978261763Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:55544","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(400)"}22632026-10-01 09:58:07.730 UTC [171] LOG: received smart shutdown request22642026-10-01 09:58:07.855 UTC [171] LOG: background worker "logical replication launcher" (PID 181) exited with exit code 122652026-10-01 09:58:07.889 UTC [176] LOG: shutting down22662026-10-01 09:58:07.891 UTC [176] LOG: checkpoint starting: shutdown immediate22672026-10-01 09:58:14.391 UTC [176] LOG: checkpoint complete: wrote 10611 buffers (64.8%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 28 recycled; write=0.515 s, sync=2.581 s, total=6.502 s; sync files=33361, longest=0.373 s, average=0.001 s; distance=467140 kB, estimate=467140 kB; lsn=0/1DF96CF8, redo lsn=0/1DF96CF822682026-10-01 09:58:16.357 UTC [171] LOG: database system is shut down2269Running OIDC tests...2270=== RUN TestAudienceForIssuer2271=== PAUSE TestAudienceForIssuer2272=== RUN TestHTTPClientForHasTimeouts2273=== PAUSE TestHTTPClientForHasTimeouts2274=== RUN TestGlobMatch2275=== PAUSE TestGlobMatch2276=== RUN TestValidateToken_ValidToken2277=== PAUSE TestValidateToken_ValidToken2278=== RUN TestValidateToken_WrongAudience2279=== PAUSE TestValidateToken_WrongAudience2280=== RUN TestValidateToken_Expired2281=== PAUSE TestValidateToken_Expired2282=== RUN TestValidateToken_BoundClaimsMismatch2283=== PAUSE TestValidateToken_BoundClaimsMismatch2284=== RUN TestValidateToken_BoundSubjectMismatch2285=== PAUSE TestValidateToken_BoundSubjectMismatch2286=== RUN TestValidateToken_MultipleProviders2287=== PAUSE TestValidateToken_MultipleProviders2288=== RUN TestValidateToken_NoMatchingProvider2289=== PAUSE TestValidateToken_NoMatchingProvider2290=== RUN TestValidateToken_KubernetesServiceAccount2291=== PAUSE TestValidateToken_KubernetesServiceAccount2292=== RUN TestNewValidator_KubernetesRequiresCA2293=== PAUSE TestNewValidator_KubernetesRequiresCA2294=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2295=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2296=== RUN TestPins_ReservedForMatchingRule2297=== PAUSE TestPins_ReservedForMatchingRule2298=== RUN TestPins_TopLevelShorthand2299=== PAUSE TestPins_TopLevelShorthand2300=== RUN TestPins_ConfigValidation2301=== PAUSE TestPins_ConfigValidation2302=== RUN TestScopes_LegacyProviderDefaultsToWrite2303=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2304=== RUN TestScopes_Rules2305=== PAUSE TestScopes_Rules2306=== RUN TestScopes_ConfigValidation2307=== PAUSE TestScopes_ConfigValidation2308=== CONT TestAudienceForIssuer2309=== CONT TestValidateToken_WrongAudience2310=== CONT TestValidateToken_BoundSubjectMismatch2311=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2312=== CONT TestScopes_ConfigValidation2313=== CONT TestScopes_Rules2314=== CONT TestPins_ConfigValidation2315=== CONT TestScopes_LegacyProviderDefaultsToWrite2316=== CONT TestPins_ReservedForMatchingRule2317=== CONT TestPins_TopLevelShorthand2318=== CONT TestNewValidator_KubernetesRequiresCA2319=== CONT TestValidateToken_KubernetesServiceAccount2320=== CONT TestHTTPClientForHasTimeouts2321=== CONT TestValidateToken_MultipleProviders2322=== CONT TestValidateToken_NoMatchingProvider2323=== CONT TestValidateToken_BoundClaimsMismatch2324=== CONT TestValidateToken_ValidToken2325=== CONT TestGlobMatch2326=== CONT TestValidateToken_Expired2327--- PASS: TestAudienceForIssuer (0.00s)2328=== RUN TestGlobMatch/foo_foo2329--- PASS: TestScopes_ConfigValidation (0.00s)2330=== PAUSE TestGlobMatch/foo_foo2331--- PASS: TestPins_ConfigValidation (0.00s)2332=== RUN TestGlobMatch/foo_bar2333=== PAUSE TestGlobMatch/foo_bar2334=== RUN TestGlobMatch/*_2335=== PAUSE TestGlobMatch/*_2336=== RUN TestGlobMatch/*_anything2337=== PAUSE TestGlobMatch/*_anything2338=== RUN TestGlobMatch/foo*_foo2339=== PAUSE TestGlobMatch/foo*_foo2340=== RUN TestGlobMatch/foo*_foobar2341=== PAUSE TestGlobMatch/foo*_foobar2342=== RUN TestGlobMatch/foo*_bar2343=== PAUSE TestGlobMatch/foo*_bar2344=== RUN TestGlobMatch/*bar_bar2345=== PAUSE TestGlobMatch/*bar_bar2346=== RUN TestGlobMatch/*bar_foobar2347=== PAUSE TestGlobMatch/*bar_foobar2348=== RUN TestGlobMatch/*bar_foo2349=== PAUSE TestGlobMatch/*bar_foo2350=== RUN TestGlobMatch/foo*bar_foobar2351=== PAUSE TestGlobMatch/foo*bar_foobar2352=== RUN TestGlobMatch/foo*bar_foo123bar2353=== PAUSE TestGlobMatch/foo*bar_foo123bar2354=== RUN TestGlobMatch/foo*bar_foobarbaz2355=== PAUSE TestGlobMatch/foo*bar_foobarbaz2356=== RUN TestGlobMatch/*/*_foo/bar2357=== PAUSE TestGlobMatch/*/*_foo/bar2358=== RUN TestGlobMatch/*/*_foo2359=== PAUSE TestGlobMatch/*/*_foo2360=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2361=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2362=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02363=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02364=== RUN TestGlobMatch/refs/*/main_refs/heads/main2365=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2366=== RUN TestGlobMatch/fo?_foo2367=== PAUSE TestGlobMatch/fo?_foo2368=== RUN TestGlobMatch/fo?_fo2369=== PAUSE TestGlobMatch/fo?_fo2370=== RUN TestGlobMatch/fo?_fooo2371=== PAUSE TestGlobMatch/fo?_fooo2372=== RUN TestGlobMatch/?oo_foo2373=== PAUSE TestGlobMatch/?oo_foo2374=== RUN TestGlobMatch/?oo_boo2375=== PAUSE TestGlobMatch/?oo_boo2376=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2377=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2378=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2379=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2380=== CONT TestGlobMatch/*_2381=== CONT TestGlobMatch/fo?_foo2382=== CONT TestGlobMatch/*bar_foo2383=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2384=== CONT TestGlobMatch/refs/*/main_refs/heads/main2385=== CONT TestGlobMatch/*bar_bar2386=== CONT TestGlobMatch/?oo_foo2387=== CONT TestGlobMatch/*_anything2388=== CONT TestGlobMatch/*/*_foo/bar2389=== CONT TestGlobMatch/foo*_foo2390=== CONT TestGlobMatch/foo*bar_foobarbaz2391=== CONT TestGlobMatch/foo*bar_foobar2392=== CONT TestGlobMatch/foo*_foobar2393=== CONT TestGlobMatch/foo*_bar2394=== CONT TestGlobMatch/?oo_boo2395=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2396=== CONT TestGlobMatch/fo?_fo2397=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02398=== CONT TestGlobMatch/fo?_fooo2399=== CONT TestGlobMatch/*/*_foo2400=== CONT TestGlobMatch/foo_bar2401=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2402=== CONT TestGlobMatch/foo_foo2403=== CONT TestGlobMatch/foo*bar_foo123bar2404=== CONT TestGlobMatch/*bar_foobar2405--- PASS: TestGlobMatch (0.01s)2406 --- PASS: TestGlobMatch/*_ (0.00s)2407 --- PASS: TestGlobMatch/fo?_foo (0.00s)2408 --- PASS: TestGlobMatch/*bar_foo (0.00s)2409 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2410 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2411 --- PASS: TestGlobMatch/*bar_bar (0.00s)2412 --- PASS: TestGlobMatch/?oo_foo (0.00s)2413 --- PASS: TestGlobMatch/*_anything (0.00s)2414 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2415 --- PASS: TestGlobMatch/foo*_foo (0.00s)2416 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2417 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2418 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2419 --- PASS: TestGlobMatch/foo*_bar (0.00s)2420 --- PASS: TestGlobMatch/?oo_boo (0.00s)2421 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2422 --- PASS: TestGlobMatch/fo?_fo (0.00s)2423 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2424 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2425 --- PASS: TestGlobMatch/*/*_foo (0.00s)2426 --- PASS: TestGlobMatch/foo_bar (0.00s)2427 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2428 --- PASS: TestGlobMatch/foo_foo (0.00s)2429 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2430 --- PASS: TestGlobMatch/*bar_foobar (0.00s)24312026/10/01 09:59:56 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232432--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.05s)24332026/10/01 09:59:56 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:43499/oidc2434--- PASS: TestValidateToken_Expired (0.05s)24352026/10/01 09:59:56 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:37831/oidc24362026/10/01 09:59:56 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:39975/oidc24372026/10/01 09:59:56 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:35993/oidc24382026/10/01 09:59:56 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:41973/oidc2439--- PASS: TestValidateToken_BoundClaimsMismatch (0.07s)2440--- PASS: TestValidateToken_BoundSubjectMismatch (0.08s)2441--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.08s)2442--- PASS: TestPins_TopLevelShorthand (0.08s)24432026/10/01 09:59:56 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:43805/oidc24442026/10/01 09:59:56 http: TLS handshake error from 127.0.0.1:48618: remote error: tls: bad certificate2445--- PASS: TestNewValidator_KubernetesRequiresCA (0.09s)2446--- PASS: TestPins_ReservedForMatchingRule (0.09s)24472026/10/01 09:59:56 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:36231/oidc24482026/10/01 09:59:56 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:42155/oidc24492026/10/01 09:59:56 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:437472450--- PASS: TestValidateToken_ValidToken (0.09s)2451--- PASS: TestValidateToken_KubernetesServiceAccount (0.10s)24522026/10/01 09:59:56 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:43569/oidc2453--- PASS: TestScopes_Rules (0.11s)2454--- PASS: TestValidateToken_WrongAudience (0.11s)24552026/10/01 09:59:56 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:35901/oidc24562026/10/01 09:59:56 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:40469/oidc2457--- PASS: TestValidateToken_MultipleProviders (0.15s)2458--- PASS: TestHTTPClientForHasTimeouts (0.20s)24592026/10/01 09:59:56 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:36553/oidc2460--- PASS: TestValidateToken_NoMatchingProvider (0.25s)2461PASS2462Running signing tests...2463=== RUN TestGenerateFingerprint2464=== PAUSE TestGenerateFingerprint2465=== RUN TestParseSigningKey2466=== PAUSE TestParseSigningKey2467=== RUN TestSignMessage2468=== PAUSE TestSignMessage2469=== RUN TestSignNarinfo2470=== PAUSE TestSignNarinfo2471=== CONT TestGenerateFingerprint2472=== CONT TestSignMessage2473=== CONT TestSignNarinfo2474=== RUN TestGenerateFingerprint/basic_with_references2475=== CONT TestParseSigningKey2476=== PAUSE TestGenerateFingerprint/basic_with_references2477=== RUN TestParseSigningKey/valid_32-byte_key2478=== RUN TestGenerateFingerprint/no_references2479=== PAUSE TestGenerateFingerprint/no_references2480=== PAUSE TestParseSigningKey/valid_32-byte_key2481=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2482=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2483=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2484=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2485=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2486=== RUN TestParseSigningKey/no_colon2487=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2488=== PAUSE TestParseSigningKey/no_colon2489=== RUN TestGenerateFingerprint/invalid_nar_hash_length2490=== RUN TestParseSigningKey/empty_name2491=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2492=== PAUSE TestParseSigningKey/empty_name2493=== RUN TestGenerateFingerprint/invalid_store_path_prefix2494=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2495=== RUN TestParseSigningKey/invalid_base642496=== RUN TestGenerateFingerprint/invalid_reference_prefix2497=== PAUSE TestParseSigningKey/invalid_base642498=== RUN TestParseSigningKey/wrong_length2499=== PAUSE TestParseSigningKey/wrong_length2500=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2501=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2502=== CONT TestGenerateFingerprint/basic_with_references2503=== CONT TestGenerateFingerprint/invalid_reference_prefix2504=== CONT TestParseSigningKey/invalid_base642505=== CONT TestGenerateFingerprint/invalid_nar_hash_length2506=== CONT TestParseSigningKey/empty_name2507=== CONT TestParseSigningKey/valid_32-byte_key2508=== CONT TestParseSigningKey/no_colon2509=== CONT TestParseSigningKey/wrong_length2510=== CONT TestGenerateFingerprint/invalid_store_path_prefix2511=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2512=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2513=== CONT TestGenerateFingerprint/no_references2514--- PASS: TestSignMessage (0.00s)2515--- PASS: TestGenerateFingerprint (0.00s)2516 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2517 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2518 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2519 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2520 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2521 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2522 --- PASS: TestGenerateFingerprint/no_references (0.00s)2523--- PASS: TestParseSigningKey (0.00s)2524 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2525 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2526 --- PASS: TestParseSigningKey/empty_name (0.00s)2527 --- PASS: TestParseSigningKey/no_colon (0.00s)2528 --- PASS: TestParseSigningKey/wrong_length (0.00s)2529 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2530--- PASS: TestSignNarinfo (0.00s)2531PASS2532Running hook tests...2533=== RUN TestSendPathsEmpty2534=== PAUSE TestSendPathsEmpty2535=== RUN TestQueueEnqueueAndFetch2536=== PAUSE TestQueueEnqueueAndFetch2537=== RUN TestQueueDeduplication2538=== PAUSE TestQueueDeduplication2539=== RUN TestQueueRemove2540=== PAUSE TestQueueRemove2541=== RUN TestQueueFetchBatchLimit2542=== PAUSE TestQueueFetchBatchLimit2543=== RUN TestQueueRetryMovesToBack2544=== PAUSE TestQueueRetryMovesToBack2545=== RUN TestQueueFetchRemoveLifecycle2546=== PAUSE TestQueueFetchRemoveLifecycle2547=== RUN TestQueueConcurrentWriters2548=== PAUSE TestQueueConcurrentWriters2549=== RUN TestQueueEnqueueWaitsOutSlowWriter2550=== PAUSE TestQueueEnqueueWaitsOutSlowWriter2551=== RUN TestQueueRemoveLargeClosure2552=== PAUSE TestQueueRemoveLargeClosure2553=== RUN TestServerClientIntegration2554=== PAUSE TestServerClientIntegration2555=== RUN TestServerQueueError2556=== PAUSE TestServerQueueError2557=== RUN TestServerRefusesOversizedAndNonStoreRequests2558=== PAUSE TestServerRefusesOversizedAndNonStoreRequests2559=== RUN TestGetListenerSocketActivation2560 server_test.go:317: === RUN TestGetListenerSocketActivation2561 --- PASS: TestGetListenerSocketActivation (0.00s)2562 PASS2563 2564--- PASS: TestGetListenerSocketActivation (1.02s)2565=== RUN TestServerStalledClientDoesNotBlockShutdown2566=== PAUSE TestServerStalledClientDoesNotBlockShutdown2567=== RUN TestServerBacksOffOnAcceptErrors2568=== PAUSE TestServerBacksOffOnAcceptErrors2569=== RUN TestDrainIsolatesPoisonPath2570=== PAUSE TestDrainIsolatesPoisonPath2571=== RUN TestRunNotBlockedByPoisonHead2572=== PAUSE TestRunNotBlockedByPoisonHead2573=== RUN TestDrainGivesUpWhenServerDown2574=== PAUSE TestDrainGivesUpWhenServerDown2575=== RUN TestFailedPathPrunedByLaterClosure2576=== PAUSE TestFailedPathPrunedByLaterClosure2577=== RUN TestWorkerUploadsAndRemoves2578=== PAUSE TestWorkerUploadsAndRemoves2579=== RUN TestWorkerSkipsGCdPaths2580=== PAUSE TestWorkerSkipsGCdPaths2581=== RUN TestWorkerPrunesClosureDeps2582=== PAUSE TestWorkerPrunesClosureDeps2583=== RUN TestWorkerRemovesCachedPathBatchedWithLargerClosure2584=== PAUSE TestWorkerRemovesCachedPathBatchedWithLargerClosure2585=== RUN TestDrainTimeout2586=== PAUSE TestDrainTimeout2587=== RUN TestDrainTimeoutDuringIsolation2588=== PAUSE TestDrainTimeoutDuringIsolation2589=== RUN TestShutdownFinishesInFlightPush2590=== PAUSE TestShutdownFinishesInFlightPush2591=== RUN TestWorkerRemoveFailureIsNotProgress2592=== PAUSE TestWorkerRemoveFailureIsNotProgress2593=== RUN TestWorkerKeepsPathItCannotStat2594=== PAUSE TestWorkerKeepsPathItCannotStat2595=== CONT TestSendPathsEmpty2596=== CONT TestRunNotBlockedByPoisonHead2597=== CONT TestQueueFetchBatchLimit2598--- PASS: TestSendPathsEmpty (0.00s)2599=== CONT TestWorkerKeepsPathItCannotStat2600=== CONT TestShutdownFinishesInFlightPush2601=== RUN TestShutdownFinishesInFlightPush/completes2602=== CONT TestDrainTimeoutDuringIsolation2603=== CONT TestWorkerRemoveFailureIsNotProgress2604=== CONT TestDrainTimeout2605=== CONT TestWorkerRemovesCachedPathBatchedWithLargerClosure2606=== CONT TestWorkerUploadsAndRemoves2607=== CONT TestDrainIsolatesPoisonPath2608=== CONT TestFailedPathPrunedByLaterClosure2609=== CONT TestQueueRemoveLargeClosure2610=== CONT TestServerStalledClientDoesNotBlockShutdown2611=== CONT TestServerQueueError2612=== CONT TestServerRefusesOversizedAndNonStoreRequests2613=== CONT TestServerClientIntegration2614=== CONT TestQueueEnqueueWaitsOutSlowWriter2615=== CONT TestQueueConcurrentWriters2616=== CONT TestServerBacksOffOnAcceptErrors2617=== CONT TestWorkerSkipsGCdPaths2618=== CONT TestQueueFetchRemoveLifecycle2619=== CONT TestQueueRetryMovesToBack2620=== CONT TestQueueRemove2621=== CONT TestWorkerPrunesClosureDeps2622=== PAUSE TestShutdownFinishesInFlightPush/completes2623=== RUN TestDrainTimeoutDuringIsolation/probe_cut_short2624=== RUN TestWorkerRemoveFailureIsNotProgress/collected_path2625=== RUN TestShutdownFinishesInFlightPush/hung_push_bounded_by_the_drain_timeout2626=== PAUSE TestDrainTimeoutDuringIsolation/probe_cut_short26272026/10/01 10:00:00 ERROR Accept failed error="too many open files"2628=== PAUSE TestWorkerRemoveFailureIsNotProgress/collected_path2629=== RUN TestDrainTimeoutDuringIsolation/probe_outlasts_the_deadline2630=== PAUSE TestShutdownFinishesInFlightPush/hung_push_bounded_by_the_drain_timeout2631=== PAUSE TestDrainTimeoutDuringIsolation/probe_outlasts_the_deadline2632=== RUN TestWorkerRemoveFailureIsNotProgress/pushed_batch2633=== PAUSE TestWorkerRemoveFailureIsNotProgress/pushed_batch2634=== RUN TestWorkerRemoveFailureIsNotProgress/isolated_paths2635=== CONT TestQueueEnqueueAndFetch2636=== PAUSE TestWorkerRemoveFailureIsNotProgress/isolated_paths26372026/10/01 10:00:00 ERROR Refusing path outside the store path=/etc/shadow store=/nix/store2638=== CONT TestQueueDeduplication26392026/10/01 10:00:00 ERROR Failed to queue paths error="permission denied" count=12640=== CONT TestDrainGivesUpWhenServerDown26412026/10/01 10:00:00 ERROR Refusing path outside the store path=/nix/store store=/nix/store2642--- PASS: TestServerQueueError (0.00s)26432026/10/01 10:00:00 ERROR Refusing path outside the store path=/nix/store/ store=/nix/store2644=== CONT TestShutdownFinishesInFlightPush/completes2645=== CONT TestShutdownFinishesInFlightPush/hung_push_bounded_by_the_drain_timeout2646--- PASS: TestServerClientIntegration (0.00s)26472026/10/01 10:00:00 ERROR Refusing path outside the store path=/nix/store/../../etc/shadow store=/nix/store26482026/10/01 10:00:00 ERROR Accept failed error="too many open files"26492026/10/01 10:00:00 ERROR Refusing path outside the store path=/nix/store/0123456789abcdfghijklmnpqrsvwxyz-hello/bin/sh store=/nix/store26502026/10/01 10:00:00 ERROR Refusing path outside the store path=nix/store/0123456789abcdfghijklmnpqrsvwxyz-hello store=/nix/store26512026/10/01 10:00:00 ERROR Refusing path outside the store path=/nix/storeX/0123456789abcdfghijklmnpqrsvwxyz-hello store=/nix/store26522026/10/01 10:00:00 ERROR Refusing path outside the store path=/nix/store/.links store=/nix/store26532026/10/01 10:00:00 ERROR Refusing path outside the store path=/nix/store/aaa-hello store=/nix/store26542026/10/01 10:00:00 ERROR Refusing path outside the store path=/nix/store/0123456789abcdfghijklmnpqrsvwxyz store=/nix/store26552026/10/01 10:00:00 ERROR Refusing path outside the store path=/nix/store/0123456789abcdfghijklmnpqrsvwxyz- store=/nix/store26562026/10/01 10:00:00 ERROR Refusing path outside the store path=/nix/store/0123456789ebcdfghijklmnpqrsvwxyz-hello store=/nix/store26572026/10/01 10:00:00 ERROR Refusing path outside the store path="/nix/store/0123456789abcdfghijklmnpqrsvwxyz-hel\x00lo" store=/nix/store26582026/10/01 10:00:00 ERROR Refusing path outside the store path=/nix/store/0123456789abcdfghijklmnpqrsvwxyz-hel/lo store=/nix/store26592026/10/01 10:00:00 ERROR Refusing path outside the store path=/nix/store/0123456789abcdfghijklmnpqrsvwxyz-xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx store=/nix/store26602026/10/01 10:00:00 ERROR Failed to decode request error="unexpected EOF"2661--- PASS: TestServerRefusesOversizedAndNonStoreRequests (0.02s)2662=== CONT TestDrainTimeoutDuringIsolation/probe_cut_short26632026/10/01 10:00:00 ERROR Accept failed error="too many open files"26642026/10/01 10:00:00 ERROR Accept failed error="too many open files"26652026/10/01 10:00:00 INFO Uploading batch count=426662026/10/01 10:00:00 ERROR Upload failed error="upload failed" count=426672026/10/01 10:00:00 INFO Upload queue status pending=326682026/10/01 10:00:00 INFO Uploading batch count=126692026/10/01 10:00:00 INFO Upload queue status pending=326702026/10/01 10:00:00 ERROR Upload failed error="upload failed" count=126712026/10/01 10:00:00 INFO Upload queue status pending=226722026/10/01 10:00:00 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerSkipsGCdPaths179655029/002/nonexistent26732026/10/01 10:00:00 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainIsolatesPoisonPath3020559421/002/bbb26742026/10/01 10:00:00 INFO Uploading batch count=426752026/10/01 10:00:00 ERROR Upload failed error="upload failed" count=426762026/10/01 10:00:00 INFO Uploading batch count=226772026/10/01 10:00:00 INFO Uploading batch count=126782026/10/01 10:00:00 ERROR Upload failed error="upload failed" count=126792026/10/01 10:00:00 INFO Uploading batch count=226802026/10/01 10:00:00 ERROR Accept failed error="too many open files"26812026/10/01 10:00:00 INFO Uploading batch count=226822026/10/01 10:00:00 INFO Uploading batch count=126832026/10/01 10:00:00 INFO Upload queue status pending=22684--- PASS: TestQueueDeduplication (0.13s)2685=== CONT TestDrainTimeoutDuringIsolation/probe_outlasts_the_deadline2686=== CONT TestWorkerRemoveFailureIsNotProgress/isolated_paths2687--- PASS: TestQueueRetryMovesToBack (0.14s)26882026/10/01 10:00:00 INFO Upload queue status pending=226892026/10/01 10:00:00 INFO Uploading batch count=226902026/10/01 10:00:00 ERROR Upload failed error="upload failed" count=226912026/10/01 10:00:00 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1618356429/002/a26922026/10/01 10:00:00 INFO Uploading batch count=226932026/10/01 10:00:00 INFO Uploading batch count=12694--- PASS: TestQueueEnqueueAndFetch (0.14s)2695=== CONT TestWorkerRemoveFailureIsNotProgress/pushed_batch26962026/10/01 10:00:00 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat1920447264/002/locked/aaa error="lstat /build/TestWorkerKeepsPathItCannotStat1920447264/002/locked/aaa: permission denied"2697=== CONT TestWorkerRemoveFailureIsNotProgress/collected_path2698--- PASS: TestQueueFetchBatchLimit (0.15s)26992026/10/01 10:00:00 INFO Upload queue status pending=227002026/10/01 10:00:00 INFO Upload queue status pending=227012026/10/01 10:00:00 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1618356429/002/b27022026/10/01 10:00:00 INFO Uploading batch count=127032026/10/01 10:00:00 ERROR Upload failed error="upload failed" count=127042026/10/01 10:00:00 INFO Uploading batch count=127052026/10/01 10:00:00 INFO Uploading batch count=227062026/10/01 10:00:00 INFO Uploading batch count=227072026/10/01 10:00:00 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat1920447264/002/locked/aaa error="lstat /build/TestWorkerKeepsPathItCannotStat1920447264/002/locked/aaa: permission denied"27082026/10/01 10:00:00 INFO Uploading batch count=227092026/10/01 10:00:00 ERROR Upload failed error="upload failed" count=227102026/10/01 10:00:00 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1618356429/002/c27112026/10/01 10:00:00 INFO Uploading batch count=12712--- PASS: TestQueueFetchRemoveLifecycle (0.15s)27132026/10/01 10:00:00 ERROR Upload failed error="upload failed" count=127142026/10/01 10:00:00 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1618356429/002/d2715--- PASS: TestQueueRemove (0.15s)2716--- PASS: TestWorkerRemovesCachedPathBatchedWithLargerClosure (0.15s)27172026/10/01 10:00:00 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat1920447264/002/locked/aaa error="lstat /build/TestWorkerKeepsPathItCannotStat1920447264/002/locked/aaa: permission denied"2718--- PASS: TestWorkerSkipsGCdPaths (0.16s)27192026/10/01 10:00:00 INFO Uploading batch count=127202026/10/01 10:00:00 ERROR Upload failed error="upload failed" count=127212026/10/01 10:00:00 INFO Uploading batch count=227222026/10/01 10:00:00 ERROR Upload failed error="upload failed" count=227232026/10/01 10:00:00 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1618356429/002/e27242026/10/01 10:00:00 ERROR Drain finished with paths left in queue remaining=12725--- PASS: TestFailedPathPrunedByLaterClosure (0.16s)27262026/10/01 10:00:00 ERROR Drain finished with paths left in queue remaining=127272026/10/01 10:00:00 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1618356429/002/f2728--- PASS: TestWorkerPrunesClosureDeps (0.16s)2729--- PASS: TestWorkerKeepsPathItCannotStat (0.17s)27302026/10/01 10:00:00 ERROR Drain finished with paths left in queue remaining=102731--- PASS: TestDrainIsolatesPoisonPath (0.17s)2732--- PASS: TestWorkerUploadsAndRemoves (0.17s)27332026/10/01 10:00:00 INFO Uploading batch count=427342026/10/01 10:00:00 ERROR Upload failed error="upload failed" count=42735--- PASS: TestDrainGivesUpWhenServerDown (0.17s)27362026/10/01 10:00:00 INFO Uploading batch count=227372026/10/01 10:00:00 ERROR Upload failed error="upload failed" count=227382026/10/01 10:00:00 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=127392026/10/01 10:00:00 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=127402026/10/01 10:00:00 INFO Uploading batch count=227412026/10/01 10:00:00 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=227422026/10/01 10:00:00 INFO Uploading batch count=227432026/10/01 10:00:00 ERROR Upload failed error="upload failed" count=227442026/10/01 10:00:00 INFO Uploading batch count=227452026/10/01 10:00:00 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=127462026/10/01 10:00:00 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=227472026/10/01 10:00:00 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgresscollected_path2604661840/001/nonexistent27482026/10/01 10:00:00 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=127492026/10/01 10:00:00 INFO Uploading batch count=227502026/10/01 10:00:00 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=127512026/10/01 10:00:00 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=227522026/10/01 10:00:00 ERROR Drain finished with paths left in queue remaining=227532026/10/01 10:00:00 INFO Uploading batch count=227542026/10/01 10:00:00 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgresscollected_path2604661840/001/nonexistent27552026/10/01 10:00:00 ERROR Upload failed error="upload failed" count=227562026/10/01 10:00:00 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=127572026/10/01 10:00:00 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=127582026/10/01 10:00:00 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=127592026/10/01 10:00:00 ERROR Drain finished with paths left in queue remaining=227602026/10/01 10:00:00 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgresscollected_path2604661840/001/nonexistent27612026/10/01 10:00:00 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=127622026/10/01 10:00:00 ERROR Drain finished with paths left in queue remaining=12763--- PASS: TestWorkerRemoveFailureIsNotProgress (0.00s)2764 --- PASS: TestWorkerRemoveFailureIsNotProgress/pushed_batch (0.04s)2765 --- PASS: TestWorkerRemoveFailureIsNotProgress/isolated_paths (0.05s)2766 --- PASS: TestWorkerRemoveFailureIsNotProgress/collected_path (0.05s)27672026/10/01 10:00:00 ERROR Failed to decode request error="read unix /build/hook3204351197/test.sock->@: i/o timeout"27682026/10/01 10:00:00 ERROR Failed to write response error="write unix /build/hook3204351197/test.sock->@: i/o timeout"2769--- PASS: TestServerStalledClientDoesNotBlockShutdown (0.20s)27702026/10/01 10:00:00 ERROR Accept failed error="too many open files"27712026/10/01 10:00:00 ERROR Upload failed error="context canceled" count=227722026/10/01 10:00:00 ERROR Drain finished with paths left in queue remaining=427732026/10/01 10:00:00 ERROR Drain finished with paths left in queue remaining=42774--- PASS: TestDrainTimeout (0.28s)27752026/10/01 10:00:00 ERROR Upload failed error="context canceled" count=227762026/10/01 10:00:00 ERROR Drain finished with paths left in queue remaining=22777--- PASS: TestShutdownFinishesInFlightPush (0.00s)2778 --- PASS: TestShutdownFinishesInFlightPush/completes (0.25s)2779 --- PASS: TestShutdownFinishesInFlightPush/hung_push_bounded_by_the_drain_timeout (0.38s)27802026/10/01 10:00:00 ERROR Accept failed error="too many open files"27812026/10/01 10:00:01 ERROR Drain finished with paths left in queue remaining=32782--- PASS: TestDrainTimeoutDuringIsolation (0.00s)2783 --- PASS: TestDrainTimeoutDuringIsolation/probe_cut_short (0.26s)2784 --- PASS: TestDrainTimeoutDuringIsolation/probe_outlasts_the_deadline (0.90s)27852026/10/01 10:00:01 ERROR Accept failed error="too many open files"2786--- PASS: TestServerBacksOffOnAcceptErrors (1.13s)27872026/10/01 10:00:01 INFO Uploading batch count=127882026/10/01 10:00:01 INFO Uploading batch count=127892026/10/01 10:00:01 INFO Uploading batch count=127902026/10/01 10:00:01 ERROR Upload failed error="upload failed" count=127912026/10/01 10:00:01 INFO Uploading batch count=127922026/10/01 10:00:01 ERROR Upload failed error="upload failed" count=127932026/10/01 10:00:01 INFO Uploading batch count=127942026/10/01 10:00:01 ERROR Upload failed error="upload failed" count=127952026/10/01 10:00:01 INFO Uploading batch count=127962026/10/01 10:00:01 ERROR Upload failed error="upload failed" count=127972026/10/01 10:00:01 ERROR Drain finished with paths left in queue remaining=12798--- PASS: TestRunNotBlockedByPoisonHead (1.17s)2799--- PASS: TestQueueConcurrentWriters (1.73s)2800--- PASS: TestQueueEnqueueWaitsOutSlowWriter (10.79s)2801--- PASS: TestQueueRemoveLargeClosure (24.59s)2802PASS2803Running niks3-hook command tests...2804=== RUN TestServeSecondSignalEndsDrain2805=== PAUSE TestServeSecondSignalEndsDrain2806=== RUN TestServeThenDrainPushesSendAcceptedBeforeShutdown2807=== PAUSE TestServeThenDrainPushesSendAcceptedBeforeShutdown2808=== CONT TestServeThenDrainPushesSendAcceptedBeforeShutdown2809=== CONT TestServeSecondSignalEndsDrain2810--- PASS: TestServeSecondSignalEndsDrain (0.08s)28112026/10/01 10:00:26 INFO Upload queue status pending=128122026/10/01 10:00:26 INFO Uploading batch count=12813--- PASS: TestServeThenDrainPushesSendAcceptedBeforeShutdown (0.61s)2814PASS2815Running rate limiter tests...2816=== RUN TestAdaptiveRateLimiter_ThreadSafety2817=== PAUSE TestAdaptiveRateLimiter_ThreadSafety2818=== CONT TestAdaptiveRateLimiter_ThreadSafety28192026/10/01 10:00:30 WARN Rate limiter backed off name=test rate=7028202026/10/01 10:00:30 WARN Rate limiter backed off name=test rate=4928212026/10/01 10:00:30 WARN Rate limiter backed off name=test rate=34.328222026/10/01 10:00:30 WARN Rate limiter backed off name=test rate=24.00999999999999828232026/10/01 10:00:30 WARN Rate limiter backed off name=test rate=16.80728242026/10/01 10:00:30 WARN Rate limiter backed off name=test rate=11.76489999999999928252026/10/01 10:00:30 WARN Rate limiter backed off name=test rate=8.2354328262026/10/01 10:00:30 WARN Rate limiter backed off name=test rate=5.76480099999999928272026/10/01 10:00:30 WARN Rate limiter backed off name=test rate=528282026/10/01 10:00:30 WARN Rate limiter backed off name=test rate=528292026/10/01 10:00:30 WARN Rate limiter backed off name=test rate=9.07809861035000628302026/10/01 10:00:30 WARN Rate limiter backed off name=test rate=6.35466902724500428312026/10/01 10:00:30 WARN Rate limiter backed off name=test rate=528322026/10/01 10:00:30 WARN Rate limiter backed off name=test rate=528332026/10/01 10:00:30 WARN Rate limiter backed off name=test rate=528342026/10/01 10:00:30 WARN Rate limiter backed off name=test rate=528352026/10/01 10:00:30 WARN Rate limiter backed off name=test rate=528362026/10/01 10:00:30 WARN Rate limiter backed off name=test rate=528372026/10/01 10:00:30 WARN Rate limiter backed off name=test rate=528382026/10/01 10:00:30 WARN Rate limiter backed off name=test rate=528392026/10/01 10:00:30 WARN Rate limiter backed off name=test rate=528402026/10/01 10:00:30 WARN Rate limiter backed off name=test rate=528412026/10/01 10:00:30 WARN Rate limiter backed off name=test rate=528422026/10/01 10:00:30 WARN Rate limiter backed off name=test rate=528432026/10/01 10:00:31 WARN Rate limiter backed off name=test rate=528442026/10/01 10:00:31 WARN Rate limiter backed off name=test rate=528452026/10/01 10:00:31 WARN Rate limiter backed off name=test rate=528462026/10/01 10:00:31 WARN Rate limiter backed off name=test rate=528472026/10/01 10:00:31 WARN Rate limiter backed off name=test rate=528482026/10/01 10:00:31 WARN Rate limiter backed off name=test rate=528492026/10/01 10:00:31 WARN Rate limiter backed off name=test rate=528502026/10/01 10:00:31 WARN Rate limiter backed off name=test rate=528512026/10/01 10:00:31 WARN Rate limiter backed off name=test rate=528522026/10/01 10:00:34 WARN Rate limiter backed off name=test rate=528532026/10/01 10:00:34 WARN Rate limiter backed off name=test rate=528542026/10/01 10:00:34 WARN Rate limiter backed off name=test rate=528552026/10/01 10:00:34 WARN Rate limiter backed off name=test rate=528562026/10/01 10:00:34 WARN Rate limiter backed off name=test rate=528572026/10/01 10:00:34 WARN Rate limiter backed off name=test rate=528582026/10/01 10:00:34 WARN Rate limiter backed off name=test rate=528592026/10/01 10:00:34 WARN Rate limiter backed off name=test rate=528602026/10/01 10:00:34 WARN Rate limiter backed off name=test rate=528612026/10/01 10:00:34 WARN Rate limiter backed off name=test rate=528622026/10/01 10:00:34 WARN Rate limiter backed off name=test rate=528632026/10/01 10:00:34 WARN Rate limiter backed off name=test rate=528642026/10/01 10:00:34 WARN Rate limiter backed off name=test rate=528652026/10/01 10:00:34 WARN Rate limiter backed off name=test rate=528662026/10/01 10:00:34 WARN Rate limiter backed off name=test rate=528672026/10/01 10:00:34 WARN Rate limiter backed off name=test rate=528682026/10/01 10:00:35 WARN Rate limiter backed off name=test rate=528692026/10/01 10:00:35 WARN Rate limiter backed off name=test rate=528702026/10/01 10:00:35 WARN Rate limiter backed off name=test rate=528712026/10/01 10:00:35 WARN Rate limiter backed off name=test rate=528722026/10/01 10:00:35 WARN Rate limiter backed off name=test rate=528732026/10/01 10:00:35 WARN Rate limiter backed off name=test rate=528742026/10/01 10:00:35 WARN Rate limiter backed off name=test rate=528752026/10/01 10:00:36 WARN Rate limiter backed off name=test rate=528762026/10/01 10:00:36 WARN Rate limiter backed off name=test rate=528772026/10/01 10:00:36 WARN Rate limiter backed off name=test rate=528782026/10/01 10:00:36 WARN Rate limiter backed off name=test rate=528792026/10/01 10:00:36 WARN Rate limiter backed off name=test rate=528802026/10/01 10:00:36 WARN Rate limiter backed off name=test rate=528812026/10/01 10:00:36 WARN Rate limiter backed off name=test rate=528822026/10/01 10:00:36 WARN Rate limiter backed off name=test rate=528832026/10/01 10:00:36 WARN Rate limiter backed off name=test rate=528842026/10/01 10:00:36 WARN Rate limiter backed off name=test rate=528852026/10/01 10:00:36 WARN Rate limiter backed off name=test rate=528862026/10/01 10:00:36 WARN Rate limiter backed off name=test rate=528872026/10/01 10:00:36 WARN Rate limiter backed off name=test rate=528882026/10/01 10:00:36 WARN Rate limiter backed off name=test rate=528892026/10/01 10:00:36 WARN Rate limiter backed off name=test rate=528902026/10/01 10:00:36 WARN Rate limiter backed off name=test rate=528912026/10/01 10:00:36 WARN Rate limiter backed off name=test rate=528922026/10/01 10:00:36 WARN Rate limiter backed off name=test rate=528932026/10/01 10:00:36 WARN Rate limiter backed off name=test rate=528942026/10/01 10:00:36 WARN Rate limiter backed off name=test rate=528952026/10/01 10:00:36 WARN Rate limiter backed off name=test rate=528962026/10/01 10:00:36 WARN Rate limiter backed off name=test rate=528972026/10/01 10:00:36 WARN Rate limiter backed off name=test rate=6.200463500000001528982026/10/01 10:00:36 WARN Rate limiter backed off name=test rate=528992026/10/01 10:00:36 WARN Rate limiter backed off name=test rate=529002026/10/01 10:00:36 WARN Rate limiter backed off name=test rate=529012026/10/01 10:00:37 WARN Rate limiter backed off name=test rate=529022026/10/01 10:00:37 WARN Rate limiter backed off name=test rate=529032026/10/01 10:00:37 WARN Rate limiter backed off name=test rate=529042026/10/01 10:00:37 WARN Rate limiter backed off name=test rate=529052026/10/01 10:00:37 WARN Rate limiter backed off name=test rate=529062026/10/01 10:00:37 WARN Rate limiter backed off name=test rate=529072026/10/01 10:00:37 WARN Rate limiter backed off name=test rate=529082026/10/01 10:00:37 WARN Rate limiter backed off name=test rate=529092026/10/01 10:00:37 WARN Rate limiter backed off name=test rate=529102026/10/01 10:00:37 WARN Rate limiter backed off name=test rate=529112026/10/01 10:00:37 WARN Rate limiter backed off name=test rate=529122026/10/01 10:00:37 WARN Rate limiter backed off name=test rate=529132026/10/01 10:00:37 WARN Rate limiter backed off name=test rate=529142026/10/01 10:00:37 WARN Rate limiter backed off name=test rate=28.49096228539396229152026/10/01 10:00:37 WARN Rate limiter backed off name=test rate=19.9436735997757729162026/10/01 10:00:37 WARN Rate limiter backed off name=test rate=13.9605715198430429172026/10/01 10:00:37 WARN Rate limiter backed off name=test rate=9.77240006389012629182026/10/01 10:00:37 WARN Rate limiter backed off name=test rate=6.8406800447230882919--- PASS: TestAdaptiveRateLimiter_ThreadSafety (12.41s)2920PASS