niks3-go-unit-tests
checks.x86_64-linux.go-unit-tests
· build #444
· 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_FailedPartBufferNotReused22=== PAUSE TestUploadMultipart_FailedPartBufferNotReused23=== RUN TestUploadMultipart_ProducerErrorIsNotEOF24=== PAUSE TestUploadMultipart_ProducerErrorIsNotEOF25=== RUN TestPartSizeForNAR26=== PAUSE TestPartSizeForNAR27=== RUN TestUploadMultipart_SupersededByPeer28=== PAUSE TestUploadMultipart_SupersededByPeer29=== RUN TestDumpPathCaseHackMatchesNix30--- PASS: TestDumpPathCaseHackMatchesNix (0.04s)31=== RUN TestDumpPathCaseHackCollision32--- PASS: TestDumpPathCaseHackCollision (0.00s)33=== RUN TestSupersededNARStillUploadsListing34=== PAUSE TestSupersededNARStillUploadsListing35=== RUN TestTruncatedNARDumpIsNotCompleted36=== PAUSE TestTruncatedNARDumpIsNotCompleted37=== RUN TestDumpPathMatchesNix38=== PAUSE TestDumpPathMatchesNix39=== RUN TestDumpPathSingleFile40=== PAUSE TestDumpPathSingleFile41=== RUN TestDumpPathWriterError42=== PAUSE TestDumpPathWriterError43=== RUN TestDumpPathWriterErrorStopsReading44 nar_test.go:289: read 57458 of 32768000 bytes45--- PASS: TestDumpPathWriterErrorStopsReading (0.65s)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 TestRetryTimeoutOutlastsMaxRetries79=== PAUSE TestRetryTimeoutOutlastsMaxRetries80=== RUN TestDoWithRetry_FinalResponseBodyReadable81=== PAUSE TestDoWithRetry_FinalResponseBodyReadable82=== RUN TestShellSplit83=== PAUSE TestShellSplit84=== RUN TestShellSplitErrors85=== PAUSE TestShellSplitErrors86=== RUN TestStreamPushReportsEveryPath87=== PAUSE TestStreamPushReportsEveryPath88=== RUN TestStreamPushBatchesUnderLoad89=== PAUSE TestStreamPushBatchesUnderLoad90=== RUN TestStreamPushIsolatesFailures91=== PAUSE TestStreamPushIsolatesFailures92=== RUN TestStreamPushGivesUpOnDeadServer93=== PAUSE TestStreamPushGivesUpOnDeadServer94=== RUN TestStreamPushRequestLine95=== PAUSE TestStreamPushRequestLine96=== RUN TestStreamPushReportsSignatures97=== PAUSE TestStreamPushReportsSignatures98=== RUN TestStreamPushReportsSkippedPaths99=== PAUSE TestStreamPushReportsSkippedPaths100=== RUN TestClientSignaturesByStorePath101=== PAUSE TestClientSignaturesByStorePath102=== RUN TestStreamPushStopsWhenCanceled103=== PAUSE TestStreamPushStopsWhenCanceled104=== RUN TestStreamPushStopsOnCancel105=== PAUSE TestStreamPushStopsOnCancel106=== RUN TestStreamPushStartsNothingOnSlotFreedByCancel107=== PAUSE TestStreamPushStartsNothingOnSlotFreedByCancel108=== RUN TestSetClientTLS109=== PAUSE TestSetClientTLS110=== RUN TestSetClientTLSDoesNotMutateDefaultTransport111=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport112=== RUN TestSetClientTLSErrors113=== PAUSE TestSetClientTLSErrors114=== RUN TestStaticToken115=== PAUSE TestStaticToken116=== RUN TestFileTokenReadsAndCaches117=== PAUSE TestFileTokenReadsAndCaches118=== RUN TestFileTokenMissing119=== PAUSE TestFileTokenMissing120=== RUN TestFileTokenEmpty121=== PAUSE TestFileTokenEmpty122=== RUN TestScriptTokenNoExpiryRerunsEveryCall123=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall124=== RUN TestScriptTokenCachesUntilRefresh125=== PAUSE TestScriptTokenCachesUntilRefresh126=== RUN TestScriptTokenEmptyToken127=== PAUSE TestScriptTokenEmptyToken128=== RUN TestScriptTokenBadJSON129=== PAUSE TestScriptTokenBadJSON130=== RUN TestScriptTokenScriptFails131=== PAUSE TestScriptTokenScriptFails132=== RUN TestScriptTokenEmptyCommand133=== PAUSE TestScriptTokenEmptyCommand134=== RUN TestScriptTokenDoesNotWaitForItsChildren135=== PAUSE TestScriptTokenDoesNotWaitForItsChildren136=== CONT TestDoServerRequestAttachesToken137=== CONT TestScriptTokenScriptFails138=== CONT TestUploadMultipart_FailedPartBufferNotReused139=== CONT TestDumpPathMatchesNix140=== CONT TestStreamPushReportsSkippedPaths141=== CONT TestScriptTokenEmptyCommand142--- PASS: TestScriptTokenEmptyCommand (0.00s)143=== CONT TestCaseHackSuffix144=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer145=== CONT TestPushPathsReportsOnlyUnuploadablePathsOfSkippedClosure146=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess147=== CONT TestTruncatedNARDumpIsNotCompleted148=== CONT TestCompletePendingClosure_NotFoundWithoutKey149=== CONT TestEncodeNixBase32150=== CONT TestSupersededNARStillUploadsListing151=== RUN TestEncodeNixBase32/test_string_hash152=== RUN TestSupersededNARStillUploadsListing/small_NAR153=== CONT TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent154=== CONT TestPathInfoCACompatibility155=== CONT TestGetStorePathHash156=== RUN TestPathInfoCACompatibility/null_ca_field157=== CONT TestScriptTokenEmptyToken158=== RUN TestGetStorePathHash/valid_store_path159=== CONT TestPartSizeForNAR160=== CONT TestUploadMultipart_ProducerErrorIsNotEOF161=== RUN TestUploadMultipart_ProducerErrorIsNotEOF/short_read_inside_a_part162=== CONT TestScriptTokenBadJSON163=== PAUSE TestUploadMultipart_ProducerErrorIsNotEOF/short_read_inside_a_part164=== CONT TestStreamPushStartsNothingOnSlotFreedByCancel165=== RUN TestUploadMultipart_ProducerErrorIsNotEOF/empty_read_on_a_part_boundary166=== CONT TestRegisterUploadedObjectReusesConnections167=== CONT TestRetryTimeoutOutlastsMaxRetries168=== CONT TestScriptTokenDoesNotWaitForItsChildren169--- PASS: TestScriptTokenScriptFails (0.00s)170=== CONT TestUploadMultipart_SupersededByPeer171=== PAUSE TestEncodeNixBase32/test_string_hash172=== RUN TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/committed_earlier173=== CONT TestScriptTokenNoExpiryRerunsEveryCall174=== PAUSE TestSupersededNARStillUploadsListing/small_NAR175=== PAUSE TestPathInfoCACompatibility/null_ca_field176=== PAUSE TestGetStorePathHash/valid_store_path177=== CONT TestPathInfoHashCompatibility178=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)179=== RUN TestSupersededNARStillUploadsListing/dump_cut_short180=== PAUSE TestUploadMultipart_ProducerErrorIsNotEOF/empty_read_on_a_part_boundary181=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)182=== PAUSE TestSupersededNARStillUploadsListing/dump_cut_short183=== RUN TestPathInfoCACompatibility/old_string_format_-_text184=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text185=== RUN TestSupersededNARStillUploadsListing/listing_upload_fails186=== RUN TestPartSizeForNAR/zero_stays_at_minimum187=== CONT TestParsePathInfoJSONMultiplePaths188=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum189=== RUN TestPartSizeForNAR/small_stays_at_minimum190=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive191=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive192=== CONT TestConvertHashToNix32193=== RUN TestConvertHashToNix32/SRI_format_to_Nix32194=== CONT TestEncodeNixBase32WithRealHash195=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths196=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32197=== RUN TestPathInfoCACompatibility/new_structured_format_-_text198=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths199=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths200=== CONT TestRateLimiterFeedback201=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths202=== CONT TestDumpPathSingleFile203=== RUN TestRateLimiterFeedback/429_enables_limiter204=== RUN TestScriptTokenDoesNotWaitForItsChildren/cancelled_while_a_child_runs205=== PAUSE TestRateLimiterFeedback/429_enables_limiter206=== RUN TestUploadMultipart_SupersededByPeer/exists207=== RUN TestRateLimiterFeedback/503_enables_limiter208=== PAUSE TestUploadMultipart_SupersededByPeer/exists209=== RUN TestUploadMultipart_SupersededByPeer/missing210=== PAUSE TestRateLimiterFeedback/503_enables_limiter211=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter212=== PAUSE TestScriptTokenDoesNotWaitForItsChildren/cancelled_while_a_child_runs213=== PAUSE TestUploadMultipart_SupersededByPeer/missing214=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter215=== RUN TestScriptTokenDoesNotWaitForItsChildren/child_left_holding_stdout216=== PAUSE TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/committed_earlier217=== RUN TestGetStorePathHash/basename_without_hyphen_should_error218=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error219=== CONT TestParsePathInfoJSON220=== CONT TestDoWithRetry_FinalResponseBodyReadable221=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter222=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter223=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text224=== PAUSE TestScriptTokenDoesNotWaitForItsChildren/child_left_holding_stdout225=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method226=== RUN TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/cleaned_up227=== RUN TestParsePathInfoJSON/Nix_format228=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon229=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon230=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error231=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error232=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun233=== PAUSE TestSupersededNARStillUploadsListing/listing_upload_fails234=== PAUSE TestParsePathInfoJSON/Nix_format235=== RUN TestConvertHashToNix32/already_Nix32_format236=== CONT TestDumpPathWriterError237=== PAUSE TestPartSizeForNAR/small_stays_at_minimum238=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum239=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum240=== PAUSE TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/cleaned_up241=== RUN TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_committed_earlier242=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method243=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts244=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI245=== CONT TestFileTokenEmpty246=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI247=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error248=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error249=== PAUSE TestConvertHashToNix32/already_Nix32_format250=== RUN TestConvertHashToNix32/invalid_format251=== CONT TestFilterOversizedClosures252=== PAUSE TestConvertHashToNix32/invalid_format253=== RUN TestFilterOversizedClosures/no_limit_keeps_everything254=== RUN TestParsePathInfoJSON/Lix_format255=== PAUSE TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_committed_earlier256--- PASS: TestStreamPushReportsSkippedPaths (0.00s)257--- PASS: TestScriptTokenEmptyToken (0.00s)258=== CONT TestScriptTokenCachesUntilRefresh259=== CONT TestFileTokenMissing260=== RUN TestEncodeNixBase32/empty_input261=== CONT TestFileTokenReadsAndCaches262--- PASS: TestFileTokenEmpty (0.00s)263=== PAUSE TestParsePathInfoJSON/Lix_format264--- PASS: TestDoServerRequestAttachesToken (0.17s)265=== RUN TestParsePathInfoJSON/empty_input266=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512267=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512268--- PASS: TestCompletePendingClosure_NotFoundWithoutKey (0.17s)269--- PASS: TestCaseHackSuffix (0.17s)270=== PAUSE TestParsePathInfoJSON/empty_input271=== RUN TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_cleaned_up,_first_root_committed_by_another_client272--- PASS: TestEncodeNixBase32WithRealHash (0.00s)273--- PASS: TestScriptTokenBadJSON (0.01s)274=== RUN TestParsePathInfoJSON/whitespace_only275=== PAUSE TestEncodeNixBase32/empty_input276=== PAUSE TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_cleaned_up,_first_root_committed_by_another_client277=== CONT TestUploadMultipart_PartsInParallel278=== CONT TestStreamPushIsolatesFailures279=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts280--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.00s)281=== CONT TestStaticToken282--- PASS: TestFileTokenMissing (0.00s)283--- PASS: TestStaticToken (0.00s)284=== CONT TestSetClientTLSErrors285--- PASS: TestFileTokenReadsAndCaches (0.00s)286=== CONT TestStreamPushBatchesUnderLoad287=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=false288=== RUN TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_cleaned_up,_last_root_committed_by_another_client289=== CONT TestDoWithRetry_BodyReplayedViaGetBody290=== PAUSE TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_cleaned_up,_last_root_committed_by_another_client291=== CONT TestStreamPushReportsEveryPath292=== CONT TestShellSplitErrors293--- PASS: TestShellSplitErrors (0.00s)294=== RUN TestPartSizeForNAR/1_TiB295=== CONT TestStreamPushGivesUpOnDeadServer296=== CONT TestSetClientTLSDoesNotMutateDefaultTransport297--- PASS: TestStreamPushIsolatesFailures (0.00s)298=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything299=== PAUSE TestParsePathInfoJSON/whitespace_only300=== RUN TestParsePathInfoJSON/invalid_JSON301=== PAUSE TestPartSizeForNAR/1_TiB302=== PAUSE TestParsePathInfoJSON/invalid_JSON303=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=false304=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped305--- PASS: TestStreamPushReportsEveryPath (0.00s)306=== CONT TestSetClientTLS307=== RUN TestPartSizeForNAR/5_TiB_S3_max_object308=== CONT TestShellSplit309=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=true310=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=true311--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.01s)312=== CONT TestResolveStorePath313=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped314=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object315=== CONT TestStreamPushStopsOnCancel316=== RUN TestPartSizeForNAR/capped_at_5_GiB317=== RUN TestStreamPushStopsOnCancel/waiting_for_input318=== RUN TestSetClientTLSErrors/missing_cert_file319=== PAUSE TestStreamPushStopsOnCancel/waiting_for_input320=== PAUSE TestSetClientTLSErrors/missing_cert_file321--- PASS: TestShellSplit (0.00s)322=== RUN TestStreamPushStopsOnCancel/partial_batch_waiting_for_a_slot323--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.01s)324=== CONT TestStreamPushReportsSignatures325=== PAUSE TestStreamPushStopsOnCancel/partial_batch_waiting_for_a_slot326=== CONT TestClientSignaturesByStorePath327=== RUN TestStreamPushStopsOnCancel/input_closed,_last_batch_waiting_for_a_slot328=== RUN TestFilterOversizedClosures/all_closures_skipped329=== PAUSE TestFilterOversizedClosures/all_closures_skipped330=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry331=== CONT TestStreamPushRequestLine332=== PAUSE TestPartSizeForNAR/capped_at_5_GiB333=== CONT TestStreamPushStopsWhenCanceled334=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths335=== RUN TestSetClientTLSErrors/missing_key_file336--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)337=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica338=== PAUSE TestStreamPushStopsOnCancel/input_closed,_last_batch_waiting_for_a_slot339=== CONT TestUploadMultipart_ProducerErrorIsNotEOF/empty_read_on_a_part_boundary340=== CONT TestUploadMultipart_ProducerErrorIsNotEOF/short_read_inside_a_part341=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths342=== RUN TestSetClientTLS/rejects_connection_without_client_cert343=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert344=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA345=== CONT TestUploadMultipart_SupersededByPeer/exists346=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter347=== CONT TestScriptTokenDoesNotWaitForItsChildren/cancelled_while_a_child_runs348=== PAUSE TestSetClientTLSErrors/missing_key_file349--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.00s)350=== CONT TestUploadMultipart_SupersededByPeer/missing351=== RUN TestStreamPushStopsOnCancel/full_batch_waiting_for_a_slot352=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA353=== RUN TestSetClientTLSErrors/missing_ca_file354--- PASS: TestClientSignaturesByStorePath (0.00s)355=== PAUSE TestStreamPushStopsOnCancel/full_batch_waiting_for_a_slot356=== RUN TestSetClientTLS/preserves_debug_logging_transport357=== PAUSE TestSetClientTLS/preserves_debug_logging_transport358=== PAUSE TestSetClientTLSErrors/missing_ca_file359=== RUN TestSetClientTLSErrors/invalid_ca_file360--- PASS: TestResolveStorePath (0.00s)361--- PASS: TestStreamPushReportsSignatures (0.00s)362=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter363=== RUN TestStreamPushStopsOnCancel/request_line_waiting_for_a_slot364=== PAUSE TestStreamPushStopsOnCancel/request_line_waiting_for_a_slot365=== RUN TestStreamPushStopsOnCancel/lines_read_but_not_taken366=== PAUSE TestSetClientTLSErrors/invalid_ca_file367--- PASS: TestStreamPushStopsWhenCanceled (0.00s)368=== PAUSE TestStreamPushStopsOnCancel/lines_read_but_not_taken369=== CONT TestSupersededNARStillUploadsListing/small_NAR370=== CONT TestScriptTokenDoesNotWaitForItsChildren/child_left_holding_stdout371=== CONT TestRateLimiterFeedback/503_enables_limiter372--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.01s)373=== CONT TestRateLimiterFeedback/429_enables_limiter374=== CONT TestPathInfoCACompatibility/old_string_format_-_text375=== CONT TestGetStorePathHash/basename_without_hyphen_should_error376--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)377 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)378 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.01s)379=== CONT TestSupersededNARStillUploadsListing/dump_cut_short380--- PASS: TestScriptTokenCachesUntilRefresh (0.02s)381--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.02s)382=== CONT TestSupersededNARStillUploadsListing/listing_upload_fails383--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.01s)384=== CONT TestConvertHashToNix32/SRI_format_to_Nix32385=== CONT TestConvertHashToNix32/invalid_format386--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)387 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)388 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)389=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error390=== CONT TestGetStorePathHash/valid_store_path391=== CONT TestConvertHashToNix32/already_Nix32_format392=== CONT TestPathInfoCACompatibility/new_structured_format_-_text393=== CONT TestPathInfoCACompatibility/null_ca_field394=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error395=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive396--- PASS: TestConvertHashToNix32 (0.01s)397 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)398 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)399 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)400--- PASS: TestGetStorePathHash (0.17s)401 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)402 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)403 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)404 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)405=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method406=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI407=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512408=== CONT TestEncodeNixBase32/test_string_hash409--- PASS: TestRateLimiterFeedback (0.00s)410 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)411 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)412 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)413 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)414=== CONT TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/committed_earlier415--- PASS: TestPathInfoCACompatibility (0.17s)416 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)417 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)418 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)419 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)420 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)421=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon422=== CONT TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_cleaned_up,_last_root_committed_by_another_client423=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)424=== CONT TestEncodeNixBase32/empty_input425=== CONT TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_committed_earlier426=== CONT TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_cleaned_up,_first_root_committed_by_another_client427--- PASS: TestPathInfoHashCompatibility (0.01s)428 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)429 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)430 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)431 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)432--- PASS: TestEncodeNixBase32 (0.18s)433 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)434 --- PASS: TestEncodeNixBase32/empty_input (0.00s)435=== CONT TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/cleaned_up436=== CONT TestParsePathInfoJSON/invalid_JSON437=== CONT TestParsePathInfoJSON/whitespace_only438--- PASS: TestDumpPathSingleFile (0.04s)439=== CONT TestParsePathInfoJSON/empty_input440=== CONT TestParsePathInfoJSON/Lix_format441=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=false442=== CONT TestFilterOversizedClosures/no_limit_keeps_everything443=== CONT TestFilterOversizedClosures/all_closures_skipped444=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped445=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=true446=== CONT TestParsePathInfoJSON/Nix_format447=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum448=== CONT TestPartSizeForNAR/5_TiB_S3_max_object449=== CONT TestPartSizeForNAR/small_stays_at_minimum450=== CONT TestSetClientTLS/rejects_connection_without_client_cert451=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts452=== CONT TestSetClientTLS/preserves_debug_logging_transport453=== CONT TestPartSizeForNAR/zero_stays_at_minimum454--- PASS: TestPushPathsReportsOnlyUnuploadablePathsOfSkippedClosure (0.21s)455=== CONT TestSetClientTLSErrors/missing_cert_file456=== CONT TestPartSizeForNAR/1_TiB457=== CONT TestPartSizeForNAR/capped_at_5_GiB458=== CONT TestSetClientTLSErrors/missing_key_file459=== CONT TestSetClientTLSErrors/invalid_ca_file460=== CONT TestSetClientTLSErrors/missing_ca_file461=== CONT TestStreamPushStopsOnCancel/input_closed,_last_batch_waiting_for_a_slot462=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA463--- PASS: TestFilterOversizedClosures (0.01s)464 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)465 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)466 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)467=== CONT TestStreamPushStopsOnCancel/full_batch_waiting_for_a_slot468--- PASS: TestStreamPushBatchesUnderLoad (0.00s)469 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=false (0.00s)470 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=true (0.00s)471--- PASS: TestParsePathInfoJSON (0.01s)472 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)473 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)474 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)475 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)476 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)477--- PASS: TestPartSizeForNAR (0.02s)478 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)479 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)480 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)481 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)482 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)483 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)484 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)485--- PASS: TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent (0.18s)486 --- PASS: TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/committed_earlier (0.00s)487 --- PASS: TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_cleaned_up,_last_root_committed_by_another_client (0.00s)488 --- PASS: TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_cleaned_up,_first_root_committed_by_another_client (0.00s)489 --- PASS: TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_committed_earlier (0.00s)490 --- PASS: TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/cleaned_up (0.00s)491=== CONT TestStreamPushStopsOnCancel/lines_read_but_not_taken492--- PASS: TestSetClientTLSErrors (0.02s)493 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)494 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)495 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)496 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)497--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.06s)498=== CONT TestStreamPushStopsOnCancel/request_line_waiting_for_a_slot499=== CONT TestStreamPushStopsOnCancel/partial_batch_waiting_for_a_slot500=== CONT TestStreamPushStopsOnCancel/waiting_for_input501--- PASS: TestDumpPathWriterError (0.08s)502--- PASS: TestStreamPushStartsNothingOnSlotFreedByCancel (0.11s)503--- PASS: TestStreamPushStopsOnCancel (0.02s)504 --- PASS: TestStreamPushStopsOnCancel/input_closed,_last_batch_waiting_for_a_slot (0.05s)505 --- PASS: TestStreamPushStopsOnCancel/full_batch_waiting_for_a_slot (0.05s)506 --- PASS: TestStreamPushStopsOnCancel/lines_read_but_not_taken (0.05s)507 --- PASS: TestStreamPushStopsOnCancel/waiting_for_input (0.16s)508 --- PASS: TestStreamPushStopsOnCancel/partial_batch_waiting_for_a_slot (0.16s)509 --- PASS: TestStreamPushStopsOnCancel/request_line_waiting_for_a_slot (0.17s)510--- PASS: TestSetClientTLS (0.02s)511 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.01s)512 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.01s)513 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.21s)514--- PASS: TestRegisterUploadedObjectReusesConnections (0.30s)515--- PASS: TestStreamPushRequestLine (0.32s)516--- PASS: TestDumpPathMatchesNix (0.53s)517--- PASS: TestUploadMultipart_ProducerErrorIsNotEOF (0.00s)518 --- PASS: TestUploadMultipart_ProducerErrorIsNotEOF/empty_read_on_a_part_boundary (0.34s)519 --- PASS: TestUploadMultipart_ProducerErrorIsNotEOF/short_read_inside_a_part (0.36s)520--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (1.00s)521--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)522--- PASS: TestTruncatedNARDumpIsNotCompleted (1.13s)523--- PASS: TestUploadMultipart_FailedPartBufferNotReused (1.21s)524--- PASS: TestSupersededNARStillUploadsListing (0.17s)525 --- PASS: TestSupersededNARStillUploadsListing/small_NAR (0.04s)526 --- PASS: TestSupersededNARStillUploadsListing/listing_upload_fails (0.04s)527 --- PASS: TestSupersededNARStillUploadsListing/dump_cut_short (1.14s)528--- PASS: TestUploadMultipart_PartsInParallel (1.19s)529--- PASS: TestScriptTokenDoesNotWaitForItsChildren (0.01s)530 --- PASS: TestScriptTokenDoesNotWaitForItsChildren/child_left_holding_stdout (2.00s)531 --- PASS: TestScriptTokenDoesNotWaitForItsChildren/cancelled_while_a_child_runs (2.20s)532PASS533Running server tests...534The files belonging to this database system will be owned by user "nixbld".535This user must also own the server process.536537The database cluster will be initialized with locale "C".538The default database encoding has accordingly been set to "SQL_ASCII".539The default text search configuration will be set to "english".540541Data page checksums are enabled.542543creating directory /build/postgres494858589/data ... ok544creating subdirectories ... ok545selecting dynamic shared memory implementation ... posix546selecting default "max_connections" ... 100547selecting default "shared_buffers" ... 128MB548selecting default time zone ... UTC549creating configuration files ... ok550running bootstrap script ... ok551performing post-bootstrap initialization ... ok552syncing data to disk ... ok553554initdb: warning: enabling "trust" authentication for local connections555initdb: hint: You can change this by editing pg_hba.conf or using the option -A, or --auth-local and --auth-host, the next time you run initdb.556557Success. You can now start the database server using:558559 pg_ctl -D /build/postgres494858589/data -l logfile start560561/build/postgres494858589:5432 - no response5622026-10-27 13:03:31.709 UTC [172] LOG: starting PostgreSQL 18.6 on x86_64-pc-linux-gnu, compiled by clang version 21.1.8, 64-bit5632026-10-27 13:03:31.710 UTC [172] LOG: listening on Unix socket "/build/postgres494858589/.s.PGSQL.5432"5642026-10-27 13:03:31.715 UTC [179] LOG: database system was shut down at 2026-10-27 13:03:31 UTC5652026-10-27 13:03:31.718 UTC [172] LOG: database system is ready to accept connections566/build/postgres494858589:5432 - accepting connections567=== RUN TestService_AuthMiddleware568=== PAUSE TestService_AuthMiddleware569=== RUN TestService_AuthMiddleware_MTLSProxyHeader570=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader571=== RUN TestService_AuthMiddleware_MTLSBoundSubjects572=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects573=== RUN TestService_ReadAuthMiddleware574=== PAUSE TestService_ReadAuthMiddleware575=== RUN TestService_AuthMiddleware_OIDC576=== PAUSE TestService_AuthMiddleware_OIDC577=== RUN TestService_RequireScope_OIDC578=== PAUSE TestService_RequireScope_OIDC579=== RUN TestService_ReadScope_PublicByDefault580=== PAUSE TestService_ReadScope_PublicByDefault581=== RUN TestCacheConfigHandler582=== PAUSE TestCacheConfigHandler583=== RUN TestCacheStatsHandler584=== PAUSE TestCacheStatsHandler585=== RUN TestClientCADerivations586=== PAUSE TestClientCADerivations587=== RUN TestClientErrorHandling588=== PAUSE TestClientErrorHandling589=== RUN TestClientIntegration590=== PAUSE TestClientIntegration591=== RUN TestClientMultipleUploads592=== PAUSE TestClientMultipleUploads593=== RUN TestClientWithDependencies594=== PAUSE TestClientWithDependencies595=== RUN TestClientSharedPathCommittedMidPush596=== PAUSE TestClientSharedPathCommittedMidPush597=== RUN TestPinProtectsFromGC598=== PAUSE TestPinProtectsFromGC599=== RUN TestClientPushesUseOnePush600=== PAUSE TestClientPushesUseOnePush601=== RUN TestClientFallsBackToClosures602=== PAUSE TestClientFallsBackToClosures603=== RUN TestDeleteClosuresRacingPins604=== PAUSE TestDeleteClosuresRacingPins605=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock606=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock607=== RUN TestResolveDBConnectionString608=== PAUSE TestResolveDBConnectionString609=== RUN TestConnectWaitsForAPeerMigration610=== PAUSE TestConnectWaitsForAPeerMigration611=== RUN TestConnectSerialisesConcurrentMigrations612=== PAUSE TestConnectSerialisesConcurrentMigrations613=== RUN TestLeadElectsOneAndHandsOver614=== PAUSE TestLeadElectsOneAndHandsOver615=== RUN TestLeadIncumbentWinsAfterRestart6162026/10/27 13:03:32 INFO lead: acquired remote=192.0.2.1:12346172026/10/27 13:03:32 INFO lead: released remote=192.0.2.1:12346182026/10/27 13:03:32 INFO lead: acquired remote=192.0.2.1:12346192026/10/27 13:03:33 INFO lead: released remote=192.0.2.1:1234620--- PASS: TestLeadIncumbentWinsAfterRestart (1.91s)621=== RUN TestLeadIncumbentAnnouncesAtOnce622=== PAUSE TestLeadIncumbentAnnouncesAtOnce623=== RUN TestLeadEndsOnShutdown624=== PAUSE TestLeadEndsOnShutdown625=== RUN TestLeadEndsWhenItsConnectionHangs6262026/10/27 13:03:34 INFO lead: acquired remote=192.0.2.1:12346272026-10-27 13:03:35.459 UTC [364] FATAL: terminating connection due to administrator command6282026/10/27 13:03:35 INFO lead: acquired remote=192.0.2.1:12346292026/10/27 13:03:36 WARN lead: lock connection lost error="timeout: context deadline exceeded"6302026/10/27 13:03:36 INFO lead: released remote=192.0.2.1:12346312026/10/27 13:03:37 INFO lead: released remote=192.0.2.1:1234632--- PASS: TestLeadEndsWhenItsConnectionHangs (3.15s)633=== RUN TestGCAdvisoryLockBlocksConcurrentRun634=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun635=== RUN TestGCBugBareHashReferences636=== PAUSE TestGCBugBareHashReferences637=== RUN TestGCMetrics638=== PAUSE TestGCMetrics639=== RUN TestPushDedupSurvivesConcurrentGC640=== PAUSE TestPushDedupSurvivesConcurrentGC641=== RUN TestDeduplicatedObjectsRecordedAsPending642=== PAUSE TestDeduplicatedObjectsRecordedAsPending643=== RUN TestGCSweepSkipsPendingObjects644=== PAUSE TestGCSweepSkipsPendingObjects645=== RUN TestTombstonedObjectOfferedWithoutWaiting646=== PAUSE TestTombstonedObjectOfferedWithoutWaiting647=== RUN TestGCSweepDeliversEachKeyOnce648=== PAUSE TestGCSweepDeliversEachKeyOnce649=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection650=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection651=== RUN TestForceGCDuringPushOffersSweptObject652=== PAUSE TestForceGCDuringPushOffersSweptObject653=== RUN TestFailedS3DeleteKeepsTombstone654=== PAUSE TestFailedS3DeleteKeepsTombstone655=== RUN TestSweepSkipsRowsLockedByPush656=== PAUSE TestSweepSkipsRowsLockedByPush657=== RUN TestRegisterCompletedObjectNeedsPendingRow658=== PAUSE TestRegisterCompletedObjectNeedsPendingRow659=== RUN TestGetExistingObjectsLocksRows660=== PAUSE TestGetExistingObjectsLocksRows661=== RUN TestSweepRechecksPendingAfterLocking662=== PAUSE TestSweepRechecksPendingAfterLocking663=== RUN TestPushWaitsForSweepHoldingRow664=== PAUSE TestPushWaitsForSweepHoldingRow665=== RUN TestCommitRacingPendingCleanupKeepsObjects666=== PAUSE TestCommitRacingPendingCleanupKeepsObjects667=== RUN TestGCEndsOnShutdown668=== PAUSE TestGCEndsOnShutdown669=== RUN TestGCTaskStore_StartNew670=== PAUSE TestGCTaskStore_StartNew671=== RUN TestGCTaskStore_DeduplicateSameParams672=== PAUSE TestGCTaskStore_DeduplicateSameParams673=== RUN TestGCTaskStore_ConflictDifferentParams674=== PAUSE TestGCTaskStore_ConflictDifferentParams675=== RUN TestGCTaskStore_GetEmpty676=== PAUSE TestGCTaskStore_GetEmpty677=== RUN TestGCTaskStore_GetReturnsLatest678=== PAUSE TestGCTaskStore_GetReturnsLatest679=== RUN TestGCTaskStore_CompletedAllowsNewTask680=== PAUSE TestGCTaskStore_CompletedAllowsNewTask681=== RUN TestGCTaskStore_PhaseUpdates682=== PAUSE TestGCTaskStore_PhaseUpdates683=== RUN TestGCTaskStore_Fail684=== PAUSE TestGCTaskStore_Fail685=== RUN TestGracefulShutdownDrainsInflight686=== PAUSE TestGracefulShutdownDrainsInflight687=== RUN TestService_healthCheckHandler688=== PAUSE TestService_healthCheckHandler689=== RUN TestService_readinessHandler690=== PAUSE TestService_readinessHandler691=== RUN TestGenerateLandingPage692=== PAUSE TestGenerateLandingPage693=== RUN TestChildrenInheritRaisedFileLimit694=== PAUSE TestChildrenInheritRaisedFileLimit695=== RUN TestCacheConfigHandlerMaxNarSize696=== PAUSE TestCacheConfigHandlerMaxNarSize697=== RUN TestCreatePendingClosureRejectsOversizedNAR698=== PAUSE TestCreatePendingClosureRejectsOversizedNAR699=== RUN TestNARDeduplicationMetadataUploadBug700=== PAUSE TestNARDeduplicationMetadataUploadBug701=== RUN TestMetricsInventory702=== PAUSE TestMetricsInventory703=== RUN TestMetricsCommit704=== PAUSE TestMetricsCommit705=== RUN TestService_NativeMTLS706=== PAUSE TestService_NativeMTLS707=== RUN TestServerTLSConfig708=== PAUSE TestServerTLSConfig709=== RUN TestMultipartCleanup710=== PAUSE TestMultipartCleanup711=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded712=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded713=== RUN TestPendingCleanupUsesOneCutoff714=== PAUSE TestPendingCleanupUsesOneCutoff715=== RUN TestPendingClosureFailureTracksEveryUpload716=== PAUSE TestPendingClosureFailureTracksEveryUpload717=== RUN TestPendingClosureFailureAbortsItsUploads718=== PAUSE TestPendingClosureFailureAbortsItsUploads719=== RUN TestObjectStatsTrigger720=== PAUSE TestObjectStatsTrigger721=== RUN TestObjectStatsUpdatedOncePerCommit722=== PAUSE TestObjectStatsUpdatedOncePerCommit723=== RUN TestReconnectLeavesObjectsUnlocked724=== PAUSE TestReconnectLeavesObjectsUnlocked725=== RUN TestOrphanedObjectsGC726=== PAUSE TestOrphanedObjectsGC727=== RUN TestOrphanedObjectsGCStressTest728=== PAUSE TestOrphanedObjectsGCStressTest729=== RUN TestCreatePin_ReservedPins730=== PAUSE TestCreatePin_ReservedPins731=== RUN TestConcurrentPinUpdatesAgree732=== PAUSE TestConcurrentPinUpdatesAgree733=== RUN TestCreatePinRejectsBadInput734=== PAUSE TestCreatePinRejectsBadInput735=== RUN TestDeletePinKeepsRowWhenS3Fails736=== PAUSE TestDeletePinKeepsRowWhenS3Fails737=== RUN TestPresentReportsOnlyClosureRoots738=== PAUSE TestPresentReportsOnlyClosureRoots739=== RUN TestPresentRefreshesOnlyStaleClosures740=== PAUSE TestPresentRefreshesOnlyStaleClosures741=== RUN TestPresentNotReportedWhileGCDeletesClosure742=== PAUSE TestPresentNotReportedWhileGCDeletesClosure743=== RUN TestParseSingleRange744=== PAUSE TestParseSingleRange745=== RUN TestProxyHeadersOnlyTrustedOnSocket7462026/10/27 13:03:37 INFO Starting HTTP server address=127.0.0.1:436517472026/10/27 13:03:37 INFO Starting HTTP server address=proxy.sock7482026/10/27 13:03:37 WARN mTLS auth: subject not in bound subjects subject="CN=someone"7492026/10/27 13:03:37 INFO Shutdown signal received, draining in-flight requests timeout=10s750--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.14s)751=== RUN TestIsValidCachePath752=== PAUSE TestIsValidCachePath753=== RUN TestReadProxyNarinfo754=== PAUSE TestReadProxyNarinfo755=== RUN TestReadProxyNarinfoAlreadyDecompressed756=== PAUSE TestReadProxyNarinfoAlreadyDecompressed757=== RUN TestReadProxyContentNegotiation758=== PAUSE TestReadProxyContentNegotiation759=== RUN TestReadProxyNarStreaming760=== PAUSE TestReadProxyNarStreaming761=== RUN TestReadProxy404And429762=== PAUSE TestReadProxy404And429763=== RUN TestReadProxyInvalidPath764=== PAUSE TestReadProxyInvalidPath765=== RUN TestReadProxyHead766=== PAUSE TestReadProxyHead767=== RUN TestReadProxyOutlastsServerWriteTimeout768=== PAUSE TestReadProxyOutlastsServerWriteTimeout769=== RUN TestReadProxyConditionalGet770=== PAUSE TestReadProxyConditionalGet771=== RUN TestReadProxyRootRedirectsToIndexHTML772=== PAUSE TestReadProxyRootRedirectsToIndexHTML773=== RUN TestReadProxyDisabled774=== PAUSE TestReadProxyDisabled775=== RUN TestReadRedirectNar776=== PAUSE TestReadRedirectNar777=== RUN TestReadRedirectKeepsNarinfoProxied778=== PAUSE TestReadRedirectKeepsNarinfoProxied779=== RUN TestReadProxyRangeRequest780=== PAUSE TestReadProxyRangeRequest781=== RUN TestReadRedirectUsesPublicS3URL782=== PAUSE TestReadRedirectUsesPublicS3URL783=== RUN TestPush_OverlappingRootsStoreOneRowPerKey784=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey785=== RUN TestPush_CompleteCommitsEveryRoot786=== PAUSE TestPush_CompleteCommitsEveryRoot787=== RUN TestPush_RepeatedRootCommitsOnce788=== PAUSE TestPush_RepeatedRootCommitsOnce789=== RUN TestPush_CompleteWaitsForCleanupOfThePush790=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush791=== RUN TestPush_RootsAreLockedInByteOrder792=== PAUSE TestPush_RootsAreLockedInByteOrder793=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit794=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit795=== RUN TestPush_RejectsBadRequests796=== PAUSE TestPush_RejectsBadRequests797=== RUN TestPush_SignsNarinfosOfItsPendingObjects798=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects799=== RUN TestRedundantMultipartUpload800=== PAUSE TestRedundantMultipartUpload801=== RUN TestCompleteMultipartUpload_ErrorButObjectExists802=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists803=== RUN TestCompletedNarNotReofferedAcrossClosures804=== PAUSE TestCompletedNarNotReofferedAcrossClosures805=== RUN TestPresignedUploadRegisteredBeforeCommit806=== PAUSE TestPresignedUploadRegisteredBeforeCommit807=== RUN TestService_Rustfstest808=== PAUSE TestService_Rustfstest809=== RUN TestParseSize810=== PAUSE TestParseSize811=== RUN TestSkippedUploadsHandler812=== PAUSE TestSkippedUploadsHandler813=== RUN TestSystemdListenerNotActivated814--- PASS: TestSystemdListenerNotActivated (0.00s)815=== RUN TestWatchdogBeatsWhenHealthy816--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)817=== RUN TestWatchdogSkipsWhenUnhealthy8182026/10/27 13:03:37 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"8192026/10/27 13:03:37 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"8202026/10/27 13:03:37 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"8212026/10/27 13:03:37 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"8222026/10/27 13:03:37 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"8232026/10/27 13:03:37 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"8242026/10/27 13:03:37 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"8252026/10/27 13:03:37 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"8262026/10/27 13:03:37 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"8272026/10/27 13:03:37 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"828--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)829=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle830=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle831=== RUN TestProxyWriteTimeout832=== PAUSE TestProxyWriteTimeout833=== RUN TestPendingClosureWriteTimeout834=== PAUSE TestPendingClosureWriteTimeout835=== RUN TestIsValidUploadKey836=== PAUSE TestIsValidUploadKey837=== RUN TestUploadHandlersRejectInvalidKeys838=== PAUSE TestUploadHandlersRejectInvalidKeys839=== RUN TestUploadHandlersRejectOversizedBody840=== PAUSE TestUploadHandlersRejectOversizedBody841=== RUN TestService_cleanupPendingClosuresHandler842=== PAUSE TestService_cleanupPendingClosuresHandler843=== RUN TestService_createPendingClosureHandler844=== PAUSE TestService_createPendingClosureHandler845=== RUN TestService_verifyS3Integrity846=== PAUSE TestService_verifyS3Integrity847=== RUN TestCompleteMultipartUnregistered848=== PAUSE TestCompleteMultipartUnregistered849=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT850=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT851=== CONT TestService_AuthMiddleware_MTLSBoundSubjects852=== CONT TestUploadHandlersRejectInvalidKeys853=== CONT TestPush_RejectsBadRequests854=== CONT TestRedundantMultipartUpload855=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit856=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT857=== CONT TestCompleteMultipartUnregistered858=== CONT TestService_createPendingClosureHandler859=== CONT TestService_cleanupPendingClosuresHandler860=== CONT TestService_verifyS3Integrity861=== CONT TestIsValidUploadKey862=== CONT TestPendingClosureWriteTimeout863=== CONT TestProxyWriteTimeout864=== CONT TestUploadHandlersRejectOversizedBody865=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle866=== CONT TestParseSize867=== CONT TestSkippedUploadsHandler868=== CONT TestService_Rustfstest869=== CONT TestCompletedNarNotReofferedAcrossClosures870=== CONT TestCompleteMultipartUpload_ErrorButObjectExists871=== CONT TestPresignedUploadRegisteredBeforeCommit872=== CONT TestPush_SignsNarinfosOfItsPendingObjects873=== CONT TestPush_RootsAreLockedInByteOrder874=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info875=== CONT TestReadProxyInvalidPath876=== RUN TestIsValidUploadKey/narinfo877=== RUN TestProxyWriteTimeout/narinfo878=== PAUSE TestIsValidUploadKey/narinfo879=== PAUSE TestProxyWriteTimeout/narinfo880=== CONT TestPush_CompleteWaitsForCleanupOfThePush8812026/10/27 13:03:37 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000882=== RUN TestProxyWriteTimeout/1_GiB_nar883=== RUN TestIsValidUploadKey/nar_zst884=== PAUSE TestProxyWriteTimeout/1_GiB_nar885=== PAUSE TestIsValidUploadKey/nar_zst886=== RUN TestProxyWriteTimeout/10_GiB_nar887=== PAUSE TestProxyWriteTimeout/10_GiB_nar888=== RUN TestPendingClosureWriteTimeout/empty889=== PAUSE TestPendingClosureWriteTimeout/empty890=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info891=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal892=== RUN TestProxyWriteTimeout/unknown_size893=== RUN TestIsValidUploadKey/nar_xz894=== PAUSE TestProxyWriteTimeout/unknown_size895=== PAUSE TestIsValidUploadKey/nar_xz896=== RUN TestIsValidUploadKey/nar_plain897=== RUN TestPendingClosureWriteTimeout/400_objects898=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal899--- PASS: TestParseSize (0.00s)900=== CONT TestPush_CompleteCommitsEveryRoot901=== PAUSE TestIsValidUploadKey/nar_plain902=== PAUSE TestPendingClosureWriteTimeout/400_objects903=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key904=== RUN TestIsValidUploadKey/listing905=== PAUSE TestIsValidUploadKey/listing906=== RUN TestPendingClosureWriteTimeout/670k_objects907=== RUN TestIsValidUploadKey/build_log908=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key909=== PAUSE TestPendingClosureWriteTimeout/670k_objects910=== PAUSE TestIsValidUploadKey/build_log911=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline912=== RUN TestIsValidUploadKey/build_log_home-manager_file913=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key914=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline915=== PAUSE TestIsValidUploadKey/build_log_home-manager_file916=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key917=== CONT TestPush_RepeatedRootCommitsOnce918=== CONT TestPush_OverlappingRootsStoreOneRowPerKey919=== RUN TestIsValidUploadKey/build_log_plus_in_name920=== PAUSE TestIsValidUploadKey/build_log_plus_in_name921=== RUN TestIsValidUploadKey/build_log_question_mark922=== PAUSE TestIsValidUploadKey/build_log_question_mark923=== RUN TestIsValidUploadKey/build_log_equals924=== PAUSE TestIsValidUploadKey/build_log_equals925=== RUN TestIsValidUploadKey/realisation926=== PAUSE TestIsValidUploadKey/realisation927=== RUN TestIsValidUploadKey/realisation_plus_in_output928=== PAUSE TestIsValidUploadKey/realisation_plus_in_output929=== RUN TestIsValidUploadKey/nix-cache-info930=== PAUSE TestIsValidUploadKey/nix-cache-info931=== RUN TestIsValidUploadKey/index.html932=== PAUSE TestIsValidUploadKey/index.html933=== RUN TestIsValidUploadKey/narinfo_key,_nar_type934=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type935=== RUN TestIsValidUploadKey/nar_key,_narinfo_type936=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type937=== RUN TestIsValidUploadKey/listing_key,_narinfo_type938=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type939=== RUN TestIsValidUploadKey/traversal940=== PAUSE TestIsValidUploadKey/traversal941=== RUN TestIsValidUploadKey/traversal_nar942=== PAUSE TestIsValidUploadKey/traversal_nar943=== RUN TestIsValidUploadKey/absolute944=== PAUSE TestIsValidUploadKey/absolute945=== RUN TestIsValidUploadKey/empty_key946=== PAUSE TestIsValidUploadKey/empty_key947=== RUN TestIsValidUploadKey/unknown_type948=== PAUSE TestIsValidUploadKey/unknown_type949=== CONT TestGCEndsOnShutdown950=== RUN TestGCEndsOnShutdown/before_the_run951=== PAUSE TestGCEndsOnShutdown/before_the_run952=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete953=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete954=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark955=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark956=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded957--- PASS: TestSkippedUploadsHandler (0.03s)958=== CONT TestPendingCleanupUsesOneCutoff959=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart960=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart961=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts962=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts963=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure964=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure965=== CONT TestServerTLSConfig966=== RUN TestServerTLSConfig/no_client_CA967=== PAUSE TestServerTLSConfig/no_client_CA968=== RUN TestServerTLSConfig/missing_CA_file969=== PAUSE TestServerTLSConfig/missing_CA_file970=== RUN TestServerTLSConfig/not_a_PEM_file971=== PAUSE TestServerTLSConfig/not_a_PEM_file972=== CONT TestMultipartCleanup973=== RUN TestPush_RejectsBadRequests/no_roots974=== PAUSE TestPush_RejectsBadRequests/no_roots975=== RUN TestPush_RejectsBadRequests/no_objects976=== PAUSE TestPush_RejectsBadRequests/no_objects977=== RUN TestPush_RejectsBadRequests/bad_root978=== PAUSE TestPush_RejectsBadRequests/bad_root979=== RUN TestPush_RejectsBadRequests/root_not_in_objects980=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects981=== CONT TestService_NativeMTLS9822026/10/27 13:03:37 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"9832026/10/27 13:03:37 WARN mTLS auth: bound subjects configured but subject DN unavailable9842026/10/27 13:03:37 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"985--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.47s)986=== CONT TestPendingClosureFailureAbortsItsUploads9872026/10/27 13:03:37 INFO Received uploads request method=POST path=/api/pending_closures9882026/10/27 13:03:37 INFO Received uploads request method=POST path=/api/pending_closures9892026/10/27 13:03:37 INFO Received uploads request method=POST path=/api/pending_closures990--- PASS: TestService_Rustfstest (0.53s)991=== CONT TestNARDeduplicationMetadataUploadBug9922026/10/27 13:03:38 INFO Received uploads request method=POST path=/api/pending_closures9932026/10/27 13:03:38 INFO Received uploads request method=POST path=/api/pending_closures9942026/10/27 13:03:38 INFO Received uploads request method=POST path=/api/pending_closures9952026/10/27 13:03:38 INFO Received push request method=POST path=/api/pushes9962026/10/27 13:03:38 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9972026/10/27 13:03:38 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst998--- PASS: TestCompleteMultipartUnregistered (0.62s)999=== CONT TestReadProxy404And42910002026/10/27 13:03:38 INFO Received cleanup request method=DELETE path=/api/pending_closures10012026/10/27 13:03:38 INFO Aborted multipart uploads count=0 kept=010022026/10/27 13:03:38 INFO Received uploads request method=POST path=/api/pending_closures10032026/10/27 13:03:38 INFO Received push request method=POST path=/api/pushes10042026/10/27 13:03:38 INFO Received cleanup request method=DELETE path=/api/pending_closures10052026/10/27 13:03:38 INFO Aborted multipart uploads count=1 kept=010062026/10/27 13:03:38 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10072026-10-27 13:03:38.109 UTC [450] ERROR: Closure does not exist: id=110082026-10-27 13:03:38.109 UTC [450] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE10092026-10-27 13:03:38.109 UTC [450] STATEMENT: -- name: CommitPendingClosure :one1010 SELECT commit_pending_closure($1::bigint)::bigint1011 1012--- PASS: TestService_cleanupPendingClosuresHandler (0.66s)1013=== CONT TestCreatePendingClosureRejectsOversizedNAR10142026/10/27 13:03:38 INFO Received uploads request method=POST path=/api/pending_closures10152026/10/27 13:03:38 INFO Received push request method=POST path=/api/pushes1016--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1017=== CONT TestReadProxyNarStreaming10182026/10/27 13:03:38 INFO Received uploads request method=POST path=/api/pending_closures1019--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (0.69s)1020=== CONT TestCacheConfigHandlerMaxNarSize1021--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1022=== CONT TestReadProxyConditionalGet10232026/10/27 13:03:38 INFO Received push request method=POST path=/api/pushes10242026/10/27 13:03:38 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10252026/10/27 13:03:38 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10262026/10/27 13:03:38 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MWYwZWQ5MzQtMzk0OC00NzkxLWFmMzAtMTMwN2E1NTgzMDY2LjliYWUxY2YyLWQ5ZTgtNGQwNC04MzVjLTQwYmIxYzMwM2QxYXgxNzkzMTA2MjE4MTYwMzQ0ODEz10272026/10/27 13:03:38 INFO Signed narinfos id=1 count=110282026/10/27 13:03:38 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10292026/10/27 13:03:38 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10302026/10/27 13:03:38 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"10312026/10/27 13:03:38 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10322026/10/27 13:03:38 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"10332026/10/27 13:03:38 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign1034--- PASS: TestReadProxyInvalidPath (0.76s)1035=== CONT TestChildrenInheritRaisedFileLimit10362026/10/27 13:03:38 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=110372026/10/27 13:03:38 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10382026/10/27 13:03:38 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo1039--- PASS: TestChildrenInheritRaisedFileLimit (0.00s)1040=== CONT TestReadProxyContentNegotiation10412026/10/27 13:03:38 INFO Received uploads request method=POST path=/api/pending_closures1042--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (0.78s)1043=== CONT TestMetricsInventory10442026/10/27 13:03:38 INFO Received push request method=POST path=/api/pushes10452026/10/27 13:03:38 INFO Received push request method=POST path=/api/pushes10462026/10/27 13:03:38 INFO Received uploads request method=POST path=/api/pending_closures10472026/10/27 13:03:38 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10482026/10/27 13:03:38 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst10492026/10/27 13:03:38 INFO Received uploads request method=POST path=/api/pending_closures10502026/10/27 13:03:38 INFO Received uploads request method=POST path=/api/pending_closures1051--- PASS: TestPresignedUploadRegisteredBeforeCommit (0.88s)1052=== CONT TestReadProxyNarinfo10532026/10/27 13:03:38 INFO Received uploads request method=POST path=/api/pending_closures10542026/10/27 13:03:38 INFO Received uploads request method=POST path=/api/pending_closures10552026/10/27 13:03:38 WARN Failed to abort multipart upload key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MWYwZWQ5MzQtMzk0OC00NzkxLWFmMzAtMTMwN2E1NTgzMDY2LjliYWUxY2YyLWQ5ZTgtNGQwNC04MzVjLTQwYmIxYzMwM2QxYXgxNzkzMTA2MjE4MTYwMzQ0ODEz error="Delete \"http://localhost:36545/bucket15/nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst?uploadId=MWYwZWQ5MzQtMzk0OC00NzkxLWFmMzAtMTMwN2E1NTgzMDY2LjliYWUxY2YyLWQ5ZTgtNGQwNC04MzVjLTQwYmIxYzMwM2QxYXgxNzkzMTA2MjE4MTYwMzQ0ODEz\": injected: abort refused"10562026/10/27 13:03:38 INFO Received uploads request method=POST path=/api/pending_closures1057--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (0.93s)1058=== CONT TestGenerateLandingPage10592026/10/27 13:03:38 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1060--- PASS: TestGenerateLandingPage (0.00s)1061=== CONT TestReadProxyNarinfoAlreadyDecompressed10622026/10/27 13:03:38 INFO Received push request method=POST path=/api/pushes10632026/10/27 13:03:38 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MWYwZWQ5MzQtMzk0OC00NzkxLWFmMzAtMTMwN2E1NTgzMDY2LjliYWUxY2YyLWQ5ZTgtNGQwNC04MzVjLTQwYmIxYzMwM2QxYXgxNzkzMTA2MjE4MTYwMzQ0ODEz10642026/10/27 13:03:38 ERROR Failed to register completed object error="get pending object \"nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst\": context canceled" object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst10652026/10/27 13:03:38 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10662026/10/27 13:03:38 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified multipart upload does not exist. The upload ID may be invalid, or the upload may have been aborted or completed." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MWYwZWQ5MzQtMzk0OC00NzkxLWFmMzAtMTMwN2E1NTgzMDY2LjliYWUxY2YyLWQ5ZTgtNGQwNC04MzVjLTQwYmIxYzMwM2QxYXgxNzkzMTA2MjE4MTYwMzQ0ODEz10672026/10/27 13:03:38 INFO Received cleanup request method=DELETE path=/api/pending_closures10682026/10/27 13:03:38 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MWYwZWQ5MzQtMzk0OC00NzkxLWFmMzAtMTMwN2E1NTgzMDY2LjliYWUxY2YyLWQ5ZTgtNGQwNC04MzVjLTQwYmIxYzMwM2QxYXgxNzkzMTA2MjE4MTYwMzQ0ODEz parts=110692026/10/27 13:03:38 INFO Received uploads request method=POST path=/api/pending_closures1070--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (0.98s)1071=== CONT TestService_readinessHandler10722026/10/27 13:03:38 INFO Received uploads request method=POST path=/api/pending_closures1073--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (1.01s)1074=== CONT TestParseSingleRange1075=== RUN TestParseSingleRange/none1076=== PAUSE TestParseSingleRange/none1077=== RUN TestParseSingleRange/unknown_unit1078=== PAUSE TestParseSingleRange/unknown_unit1079=== RUN TestParseSingleRange/multi-range_ignored1080=== PAUSE TestParseSingleRange/multi-range_ignored1081=== RUN TestParseSingleRange/malformed_no_dash1082=== PAUSE TestParseSingleRange/malformed_no_dash1083=== RUN TestParseSingleRange/malformed_both_empty1084=== PAUSE TestParseSingleRange/malformed_both_empty1085=== RUN TestParseSingleRange/malformed_end_before_start1086=== PAUSE TestParseSingleRange/malformed_end_before_start1087=== RUN TestParseSingleRange/closed1088=== PAUSE TestParseSingleRange/closed1089=== RUN TestParseSingleRange/open-ended1090=== PAUSE TestParseSingleRange/open-ended1091=== RUN TestParseSingleRange/end_clamped_to_size1092=== PAUSE TestParseSingleRange/end_clamped_to_size1093=== RUN TestParseSingleRange/suffix1094=== PAUSE TestParseSingleRange/suffix1095=== RUN TestParseSingleRange/suffix_exceeds_size1096=== PAUSE TestParseSingleRange/suffix_exceeds_size1097=== RUN TestParseSingleRange/single_byte1098=== PAUSE TestParseSingleRange/single_byte1099=== RUN TestParseSingleRange/start_past_EOF1100=== PAUSE TestParseSingleRange/start_past_EOF1101=== RUN TestParseSingleRange/start_far_past_EOF1102=== PAUSE TestParseSingleRange/start_far_past_EOF1103=== CONT TestGracefulShutdownDrainsInflight11042026/10/27 13:03:38 INFO Starting HTTP server address=127.0.0.1:4184911052026/10/27 13:03:38 INFO Shutdown signal received, draining in-flight requests timeout=10s11062026/10/27 13:03:38 WARN mTLS auth: subject not in bound subjects subject="CN=reader"11072026/10/27 13:03:38 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11082026/10/27 13:03:38 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1109--- PASS: TestService_NativeMTLS (0.61s)1110=== CONT TestPresentNotReportedWhileGCDeletesClosure1111=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale1112=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale1113=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh1114=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh1115=== CONT TestGCTaskStore_Fail1116--- PASS: TestGCTaskStore_Fail (0.00s)1117=== CONT TestPresentRefreshesOnlyStaleClosures11182026/10/27 13:03:38 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=MWYwZWQ5MzQtMzk0OC00NzkxLWFmMzAtMTMwN2E1NTgzMDY2LjFkMTU2ZjdhLTIzNWQtNDhlNS1hMDRhLWE5OGEwNmE1MzUwZXgxNzkzMTA2MjE3OTQyNzYwODY4 parts=1011192026/10/27 13:03:38 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11202026/10/27 13:03:38 INFO Received uploads request method=POST path=/api/pending_closures11212026/10/27 13:03:38 INFO Completed upload id=1 objects=2 duration=3.69395ms11222026/10/27 13:03:38 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1123--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1124=== CONT TestService_healthCheckHandler11252026/10/27 13:03:38 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11262026/10/27 13:03:38 INFO Received uploads request method=POST path=/api/pending_closures11272026/10/27 13:03:38 INFO Received uploads request method=POST path=/api/pending_closures11282026/10/27 13:03:38 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=MWYwZWQ5MzQtMzk0OC00NzkxLWFmMzAtMTMwN2E1NTgzMDY2LmJiMjgwYTE0LTIyZmYtNGY0Ni04YzJmLTI0Y2VmNDYxNjdiMXgxNzkzMTA2MjE4MDExNjc2NDI3 parts=1011292026/10/27 13:03:38 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11302026/10/27 13:03:38 INFO Completed upload id=1 objects=2 duration=3.43011ms11312026/10/27 13:03:38 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000011322026/10/27 13:03:38 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo11332026/10/27 13:03:38 WARN Found objects in DB but missing from S3, will re-upload count=111342026/10/27 13:03:38 INFO Received uploads request method=POST path=/api/pending_closures11352026/10/27 13:03:38 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11362026/10/27 13:03:38 INFO Starting cleanup of old closures method=DELETE path=/api/closures11372026/10/27 13:03:38 INFO Received complete upload request method=POST path=/api/pending_closures/3/complete11382026/10/27 13:03:38 INFO Completed upload id=3 objects=2 duration=2.21526ms11392026/10/27 13:03:38 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=MWYwZWQ5MzQtMzk0OC00NzkxLWFmMzAtMTMwN2E1NTgzMDY2LmU4N2Y3N2M4LWM0ZDAtNDM5YS1hNzYxLWUzOWU1ZmIzMWZjMngxNzkzMTA2MjE3OTU4ODM1MDQ4 parts=121140--- PASS: TestPendingClosureFailureAbortsItsUploads (0.64s)1141=== CONT TestIsValidCachePath1142=== RUN TestIsValidCachePath/narinfo11432026/10/27 13:03:38 INFO Received uploads request method=POST path=/api/pending_closures1144=== PAUSE TestIsValidCachePath/narinfo1145=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1146=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1147=== RUN TestIsValidCachePath/nar_zst1148=== PAUSE TestIsValidCachePath/nar_zst1149=== RUN TestIsValidCachePath/nar_xz1150=== PAUSE TestIsValidCachePath/nar_xz1151=== RUN TestIsValidCachePath/nar_bz21152=== PAUSE TestIsValidCachePath/nar_bz21153=== RUN TestIsValidCachePath/nar_uncompressed1154=== PAUSE TestIsValidCachePath/nar_uncompressed1155=== RUN TestIsValidCachePath/ls1156=== PAUSE TestIsValidCachePath/ls1157=== RUN TestIsValidCachePath/log1158=== PAUSE TestIsValidCachePath/log1159=== RUN TestIsValidCachePath/realisation1160=== PAUSE TestIsValidCachePath/realisation1161=== RUN TestIsValidCachePath/nix-cache-info1162=== PAUSE TestIsValidCachePath/nix-cache-info1163=== RUN TestIsValidCachePath/index.html1164=== PAUSE TestIsValidCachePath/index.html1165=== RUN TestIsValidCachePath/traversal_parent1166=== PAUSE TestIsValidCachePath/traversal_parent1167=== RUN TestIsValidCachePath/traversal_in_middle1168=== PAUSE TestIsValidCachePath/traversal_in_middle1169=== RUN TestIsValidCachePath/invalid_char_e1170=== PAUSE TestIsValidCachePath/invalid_char_e1171=== RUN TestIsValidCachePath/invalid_char_u1172=== PAUSE TestIsValidCachePath/invalid_char_u1173=== RUN TestIsValidCachePath/random_path1174=== PAUSE TestIsValidCachePath/random_path11752026/10/27 13:03:38 INFO Aborted multipart uploads count=0 kept=01176=== RUN TestIsValidCachePath/empty1177=== PAUSE TestIsValidCachePath/empty1178=== RUN TestIsValidCachePath/leading_slash1179=== PAUSE TestIsValidCachePath/leading_slash1180=== RUN TestIsValidCachePath/wrong_extension1181=== PAUSE TestIsValidCachePath/wrong_extension1182=== RUN TestIsValidCachePath/short_hash1183=== PAUSE TestIsValidCachePath/short_hash1184=== CONT TestGCTaskStore_CompletedAllowsNewTask1185--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1186=== CONT TestPresentReportsOnlyClosureRoots11872026/10/27 13:03:38 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=011882026/10/27 13:03:38 INFO Received uploads request method=POST path=/api/pending_closures1189--- PASS: TestService_verifyS3Integrity (1.12s)1190=== CONT TestGCTaskStore_PhaseUpdates1191=== CONT TestCreatePinRejectsBadInput1192--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)11932026/10/27 13:03:38 INFO Vacuumed table table=pending_closures11942026/10/27 13:03:38 INFO Received cleanup request method=DELETE path=/api/pending_closures11952026/10/27 13:03:38 INFO Vacuumed table table=pending_objects11962026/10/27 13:03:38 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket27/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""11972026/10/27 13:03:38 INFO Aborted multipart uploads count=0 kept=111982026/10/27 13:03:38 INFO Completed multipart upload object_key=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa00000000000000000000.nar.zst upload_id=MWYwZWQ5MzQtMzk0OC00NzkxLWFmMzAtMTMwN2E1NTgzMDY2LjdmMmE5OWVjLWMwODItNDllMi1hYWQ0LTI0YmY2NzZkOTg0Y3gxNzkzMTA2MjE4MDM4NTg0OTQ2 parts=1011992026/10/27 13:03:38 INFO Vacuumed table table=multipart_uploads1200=== NAME TestNARDeduplicationMetadataUploadBug1201 metadata_upload_test.go:48: First store path: /build/TestNARDeduplicationMetadataUploadBug1401025275/001/store/z62vwkp0imrxbpqz9f4krcdvigc9pq9v-file1.txt12022026/10/27 13:03:38 INFO Vacuumed table table=closures12032026/10/27 13:03:38 INFO Vacuumed table table=objects12042026/10/27 13:03:38 INFO Received cleanup request method=DELETE path=/api/pending_closures12052026/10/27 13:03:38 INFO Aborted multipart uploads count=1 kept=012062026/10/27 13:03:38 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001207--- PASS: TestMultipartCleanup (0.82s)1208=== CONT TestGCTaskStore_GetEmpty1209=== CONT TestReadProxyDisabled1210--- PASS: TestGCTaskStore_GetEmpty (0.00s)12112026/10/27 13:03:38 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1212--- PASS: TestService_createPendingClosureHandler (1.17s)1213=== CONT TestPushWaitsForSweepHoldingRow1214=== CONT TestReadRedirectUsesPublicS3URL1215--- PASS: TestReadProxyNarStreaming (0.51s)12162026/10/27 13:03:38 INFO Completed multipart upload object_key=nar/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb00000000000000000000.nar.zst upload_id=MWYwZWQ5MzQtMzk0OC00NzkxLWFmMzAtMTMwN2E1NTgzMDY2LjQyYjM5NzA2LTViNjctNDFkNi1iMjllLWM2MWQ3YTNmMmFmN3gxNzkzMTA2MjE4MTM2OTE1Njcz parts=1012172026/10/27 13:03:38 INFO Received push request method=POST path=/api/pushes12182026/10/27 13:03:38 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12192026/10/27 13:03:38 INFO Uploading z62vwkp0imrxbpqz9f4krcdvigc9pq9v-file1.txt (160B)12202026/10/27 13:03:38 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"12212026/10/27 13:03:38 WARN Failed to register uploaded object key=z62vwkp0imrxbpqz9f4krcdvigc9pq9v.ls error="server returned 404: 404 page not found\n"12222026/10/27 13:03:38 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12232026/10/27 13:03:38 INFO Signed narinfos id=1 count=112242026/10/27 13:03:38 INFO Uploading 1 narinfos12252026/10/27 13:03:38 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12262026/10/27 13:03:38 INFO Received complete push request method=POST path=/api/pushes/1/complete12272026/10/27 13:03:38 WARN Failed to register uploaded object key=z62vwkp0imrxbpqz9f4krcdvigc9pq9v.narinfo error="server returned 404: 404 page not found\n"12282026/10/27 13:03:38 INFO Completed push id=1 objects=3 duration=9.84195ms12292026/10/27 13:03:38 INFO Upload complete. (109ms)12302026/10/27 13:03:38 INFO Completed multipart upload object_key=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa00000000000000000000.nar.zst upload_id=MWYwZWQ5MzQtMzk0OC00NzkxLWFmMzAtMTMwN2E1NTgzMDY2LjBiZTRjZDNjLTI2YzMtNDM2ZS05NTcyLTgzOTk0OTU5YjhlOXgxNzkzMTA2MjE4MjYxOTg4NzQw parts=101231=== NAME TestNARDeduplicationMetadataUploadBug1232 metadata_upload_test.go:54: Retrieved narinfo from S3:1233 StorePath: /build/TestNARDeduplicationMetadataUploadBug1401025275/001/store/z62vwkp0imrxbpqz9f4krcdvigc9pq9v-file1.txt1234 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1235 Compression: zstd1236 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1237 NarSize: 1601238 References: 1239 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1240--- PASS: TestMetricsInventory (0.51s)1241=== CONT TestObjectStatsTrigger1242=== NAME TestNARDeduplicationMetadataUploadBug1243 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1244 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1245 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}1246--- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.35s)1247=== CONT TestGetExistingObjectsLocksRows12482026/10/27 13:03:38 WARN readiness check failed error="closed pool"1249--- PASS: TestService_readinessHandler (0.33s)1250=== CONT TestCreatePin_ReservedPins1251=== NAME TestNARDeduplicationMetadataUploadBug1252 metadata_upload_test.go:64: Second store path (same content): /build/TestNARDeduplicationMetadataUploadBug1401025275/001/store/rycbvivxg3prmhgx6z6mq1i402bdvkrc-file2.txt12532026/10/27 13:03:38 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1254--- PASS: TestReadProxyConditionalGet (0.65s)1255=== CONT TestFailedS3DeleteKeepsTombstone1256=== CONT TestResolveDBConnectionString1257--- PASS: TestPresentRefreshesOnlyStaleClosures (0.30s)1258=== RUN TestResolveDBConnectionString/flag_wins1259=== PAUSE TestResolveDBConnectionString/flag_wins1260=== RUN TestResolveDBConnectionString/file_when_flag_empty1261=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1262=== RUN TestResolveDBConnectionString/missing_file_is_an_error1263=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1264=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1265=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1266=== RUN TestResolveDBConnectionString/nothing_configured1267=== PAUSE TestResolveDBConnectionString/nothing_configured1268=== CONT TestLeadIncumbentAnnouncesAtOnce12692026/10/27 13:03:38 INFO Completed multipart upload object_key=nar/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb00000000000000000000.nar.zst upload_id=MWYwZWQ5MzQtMzk0OC00NzkxLWFmMzAtMTMwN2E1NTgzMDY2Ljc3Mjg1YzhhLTViNDQtNDE2My1iZGY5LTg3YmIxMTExOTMyNHgxNzkzMTA2MjE4MzAyNTkxMjM5 parts=101270--- PASS: TestService_healthCheckHandler (0.28s)1271=== CONT TestCacheConfigHandler1272=== RUN TestCacheConfigHandler/full_config,_no_issuer1273=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1274=== RUN TestCacheConfigHandler/no_cache_url_configured1275=== PAUSE TestCacheConfigHandler/no_cache_url_configured1276=== RUN TestCacheConfigHandler/no_signing_keys1277=== PAUSE TestCacheConfigHandler/no_signing_keys1278=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1279=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1280=== CONT TestLeadEndsOnShutdown12812026/10/27 13:03:38 INFO Received push request method=POST path=/api/pushes1282=== CONT TestClientErrorHandling1283=== RUN TestClientErrorHandling/InvalidStorePath1284--- PASS: TestPresentReportsOnlyClosureRoots (0.29s)1285=== PAUSE TestClientErrorHandling/InvalidStorePath1286=== RUN TestClientErrorHandling/InvalidAuthToken1287=== PAUSE TestClientErrorHandling/InvalidAuthToken1288=== RUN TestClientErrorHandling/ServerNotAvailable1289=== PAUSE TestClientErrorHandling/ServerNotAvailable1290=== CONT TestMetricsCommit12912026/10/27 13:03:38 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)12922026/10/27 13:03:38 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:34747/oidc12932026/10/27 13:03:38 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12942026/10/27 13:03:38 INFO Received create pin request method=POST path=/api/pins/deploy12952026/10/27 13:03:38 INFO Received create pin request method=POST path=/api/pins/deploy12962026/10/27 13:03:38 INFO Received create pin request method=POST path=/api/pins/deploy12972026/10/27 13:03:38 WARN Failed to register uploaded object key=rycbvivxg3prmhgx6z6mq1i402bdvkrc.ls error="server returned 404: 404 page not found\n"12982026/10/27 13:03:38 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign12992026/10/27 13:03:38 INFO Received create pin request method=POST path=/api/pins/deploy13002026/10/27 13:03:38 INFO Received create pin request method=POST path=/api/pins/deploy13012026/10/27 13:03:38 INFO Signed narinfos id=2 count=113022026/10/27 13:03:38 INFO Received create pin request method=POST path=/api/pins/deploy13032026/10/27 13:03:38 INFO Received create pin request method=POST path=/api/pins/deploy13042026/10/27 13:03:38 INFO Uploading 1 narinfos13052026/10/27 13:03:38 INFO Received create pin request method=POST path=/api/pins/deploy13062026/10/27 13:03:38 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=MWYwZWQ5MzQtMzk0OC00NzkxLWFmMzAtMTMwN2E1NTgzMDY2LjgwOGQzMTNiLTRkYTctNDBkYy04M2RiLTlhYjk4MWE5NjVmNHgxNzkzMTA2MjE4MzM3ODk0MDQ4 parts=1213072026/10/27 13:03:38 INFO Received complete push request method=POST path=/api/pushes/2/complete13082026/10/27 13:03:38 WARN Failed to register uploaded object key=rycbvivxg3prmhgx6z6mq1i402bdvkrc.narinfo error="server returned 404: 404 page not found\n"13092026/10/27 13:03:38 INFO Received uploads request method=POST path=/api/pending_closures13102026/10/27 13:03:38 INFO Completed push id=2 objects=3 duration=3.07392ms13112026/10/27 13:03:38 INFO Upload complete. (77ms)1312=== NAME TestNARDeduplicationMetadataUploadBug1313 metadata_upload_test.go:76: Retrieved narinfo from S3:1314 StorePath: /build/TestNARDeduplicationMetadataUploadBug1401025275/001/store/rycbvivxg3prmhgx6z6mq1i402bdvkrc-file2.txt1315 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1316 Compression: zstd1317 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1318 NarSize: 1601319 References: 1320 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1321 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1322 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1323 {"version":1,"root":{"type":"regular","size":44}}1324--- PASS: TestCompletedNarNotReofferedAcrossClosures (1.46s)1325=== CONT TestGCMetrics13262026/10/27 13:03:38 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1327--- PASS: TestNARDeduplicationMetadataUploadBug (0.94s)1328=== CONT TestCacheStatsHandler13292026/10/27 13:03:38 INFO Received uploads request method=POST path=/api/pending_closures1330--- PASS: TestReadProxyDisabled (0.32s)1331=== CONT TestService_AuthMiddleware13322026/10/27 13:03:38 INFO Received create pin request method=POST path=/api/pins/deploy13332026-10-27 13:03:38.963 UTC [613] ERROR: Push does not exist: id=113342026-10-27 13:03:38.963 UTC [613] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE13352026-10-27 13:03:38.963 UTC [613] STATEMENT: SELECT commit_push($1)13362026/10/27 13:03:38 INFO Completed multipart upload object_key=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa00000000000000000000.nar.zst upload_id=MWYwZWQ5MzQtMzk0OC00NzkxLWFmMzAtMTMwN2E1NTgzMDY2LjAzNGZhNjQ5LWUwOGYtNGEwZC1hNGEwLTQ2NDQ4NTU3YTk3ZngxNzkzMTA2MjE4NDA4OTgwMDY3 parts=101337=== CONT TestGCTaskStore_GetReturnsLatest1338--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (1.52s)1339=== CONT TestClientSharedPathCommittedMidPush1340--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1341--- PASS: TestObjectStatsTrigger (0.25s)1342=== CONT TestConnectSerialisesConcurrentMigrations1343--- PASS: TestGetExistingObjectsLocksRows (0.27s)1344=== CONT TestObjectStatsUpdatedOncePerCommit13452026/10/27 13:03:39 INFO Received uploads request method=POST path=/api/pending_closures13462026/10/27 13:03:39 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13472026/10/27 13:03:39 INFO lead: acquired remote=192.0.2.1:123413482026/10/27 13:03:39 INFO lead: released remote=192.0.2.1:123413492026/10/27 13:03:39 INFO Completed multipart upload object_key=nar/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb00000000000000000000.nar.zst upload_id=MWYwZWQ5MzQtMzk0OC00NzkxLWFmMzAtMTMwN2E1NTgzMDY2LjkzZTA1YTA5LWY5OGUtNDZiNy05OWZlLTk0ZDVlMjNjMjRhM3gxNzkzMTA2MjE4MDM3MzkxMDU2 parts=1013502026/10/27 13:03:39 INFO Received complete push request method=POST path=/api/pushes/1/complete13512026/10/27 13:03:39 INFO Completed push id=1 objects=4 duration=10.98325ms1352--- PASS: TestLeadIncumbentAnnouncesAtOnce (0.25s)1353=== CONT TestLeadElectsOneAndHandsOver13542026/10/27 13:03:39 INFO Received push request method=POST path=/api/pushes13552026/10/27 13:03:39 INFO lead: acquired remote=192.0.2.1:12341356=== CONT TestGCTaskStore_ConflictDifferentParams1357--- PASS: TestReadRedirectUsesPublicS3URL (0.45s)1358--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1359=== CONT TestReadRedirectKeepsNarinfoProxied13602026/10/27 13:03:39 INFO Aborted multipart uploads count=0 kept=013612026-10-27 13:03:39.106 UTC [749] ERROR: duplicate key value violates unique constraint "pg_class_relname_nsp_index"13622026-10-27 13:03:39.106 UTC [749] DETAIL: Key (relname, relnamespace)=(goose_db_version_id_seq, 2200) already exists.13632026-10-27 13:03:39.106 UTC [749] STATEMENT: CREATE TABLE goose_db_version (1364 id integer PRIMARY KEY GENERATED BY DEFAULT AS IDENTITY,1365 version_id bigint NOT NULL,1366 is_applied boolean NOT NULL,1367 tstamp timestamp NOT NULL DEFAULT now()1368 )13692026/10/27 13:03:39 WARN Force mode enabled - objects will be deleted immediately without grace period13702026/10/27 13:03:39 WARN Rate limiter enabled after throttle name=s3-test rate=513712026/10/27 13:03:39 WARN S3 rate limit hit during proxy key=4hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo error="Please reduce your request rate."13722026/10/27 13:03:39 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux13732026/10/27 13:03:39 WARN Refused reserved pin name=worker-x86_64-linux13742026/10/27 13:03:39 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux13752026/10/27 13:03:39 INFO Received create pin request method=POST path=/api/pins/my-app13762026/10/27 13:03:39 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux13772026/10/27 13:03:39 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."13782026/10/27 13:03:39 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."13792026/10/27 13:03:39 INFO Received push request method=POST path=/api/pushes13802026/10/27 13:03:39 INFO Aborted multipart uploads count=0 kept=01381--- PASS: TestCreatePin_ReservedPins (0.37s)1382=== CONT TestGCTaskStore_DeduplicateSameParams1383--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1384=== CONT TestReadRedirectNar13852026/10/27 13:03:39 WARN Force mode enabled - objects will be deleted immediately without grace period1386--- PASS: TestFailedS3DeleteKeepsTombstone (0.34s)1387=== CONT TestGCTaskStore_StartNew1388=== CONT TestReadProxyOutlastsServerWriteTimeout1389--- PASS: TestGCTaskStore_StartNew (0.00s)13902026/10/27 13:03:39 INFO Aborted multipart uploads count=0 kept=013912026/10/27 13:03:39 WARN Force mode enabled - objects will be deleted immediately without grace period13922026/10/27 13:03:39 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=013932026/10/27 13:03:39 INFO Vacuumed table table=pending_closures13942026/10/27 13:03:39 INFO Vacuumed table table=pending_objects13952026/10/27 13:03:39 INFO Vacuumed table table=multipart_uploads13962026/10/27 13:03:39 INFO Vacuumed table table=closures13972026/10/27 13:03:39 INFO Vacuumed table table=objects13982026/10/27 13:03:39 WARN Rate limiter backed off name=s3-test rate=513992026/10/27 13:03:39 WARN S3 rate limit hit during proxy key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhh.nar.zst error="Please reduce your request rate."1400--- PASS: TestReadProxy404And429 (1.13s)1401=== CONT TestReadProxyRootRedirectsToIndexHTML14022026/10/27 13:03:39 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=014032026/10/27 13:03:39 INFO Vacuumed table table=pending_closures14042026/10/27 13:03:39 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"1405--- PASS: TestGCMetrics (0.29s)1406=== CONT TestReadProxyHead1407=== CONT TestClientWithDependencies1408--- PASS: TestCacheStatsHandler (0.28s)14092026/10/27 13:03:39 INFO Vacuumed table table=pending_objects14102026/10/27 13:03:39 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14112026/10/27 13:03:39 INFO Vacuumed table table=multipart_uploads14122026/10/27 13:03:39 INFO Vacuumed table table=closures14132026/10/27 13:03:39 INFO Vacuumed table table=objects1414--- PASS: TestService_AuthMiddleware (0.28s)1415=== CONT TestOrphanedObjectsGCStressTest14162026/10/27 13:03:39 INFO Completed multipart upload object_key=nar/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb00000000000000000000.nar.zst upload_id=MWYwZWQ5MzQtMzk0OC00NzkxLWFmMzAtMTMwN2E1NTgzMDY2LjNkYWE4NGExLTg1NGMtNDJhZC05ODY2LTI5OGQzMjE4YjNmMHgxNzkzMTA2MjE4MjYyODM3NjUw parts=101417=== CONT TestConnectWaitsForAPeerMigration1418--- PASS: TestReadProxyContentNegotiation (1.05s)14192026/10/27 13:03:39 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14202026/10/27 13:03:39 INFO lead: acquired remote=192.0.2.1:123414212026/10/27 13:03:39 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=MWYwZWQ5MzQtMzk0OC00NzkxLWFmMzAtMTMwN2E1NTgzMDY2Ljc5MDFlN2M5LTNlODEtNGZjYS05NDY1LTNjYzZlZWUwYjRiM3gxNzkzMTA2MjE4NTgzMDI0MjMy error="Get \"http://127.0.0.1:1/bucket7/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"14222026/10/27 13:03:39 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=MWYwZWQ5MzQtMzk0OC00NzkxLWFmMzAtMTMwN2E1NTgzMDY2LmY5YzQ5NTQwLTZkNWMtNDljOC04Nzg1LWRmZWU2MzJmYTA3N3gxNzkzMTA2MjE4NTcwNDkyNzYy parts=1214232026/10/27 13:03:39 INFO Received cleanup request method=DELETE path=/api/pending_closures14242026/10/27 13:03:39 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14252026/10/27 13:03:39 INFO Aborted multipart uploads count=1 kept=01426=== CONT TestTombstonedObjectOfferedWithoutWaiting1427--- PASS: TestObjectStatsUpdatedOncePerCommit (0.32s)14282026/10/27 13:03:39 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggggg00000000000000000000.nar.zst upload_id=MWYwZWQ5MzQtMzk0OC00NzkxLWFmMzAtMTMwN2E1NTgzMDY2LjJjM2M0ZWViLTJhZTMtNGU0YS1iNjRmLTgxMmE3YTJlOTc4NXgxNzkzMTA2MjE4MzAyNDg2NjY5 parts=101429--- PASS: TestRedundantMultipartUpload (1.89s)1430=== CONT TestConcurrentPinUpdatesAgree1431--- PASS: TestReadRedirectNar (0.25s)1432=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock14332026/10/27 13:03:39 INFO Received push request method=POST path=/api/pushes14342026/10/27 13:03:39 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)14352026/10/27 13:03:39 INFO Uploading 7nzf73qv56y58i3m1b54khrch7r169qd-shared-dep (136B)14362026/10/27 13:03:39 INFO Uploading nyxmyy9gbg2b7q8bw08k3rj02zi1fyy1-top (224B)14372026/10/27 13:03:39 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"14382026/10/27 13:03:39 WARN Failed to register uploaded object key=nar/1mra96mfxa4hibnf9p1vlmnlgfy3zcy8ykpihlsalg3wbzmv272h.nar.zst error="server returned 404: 404 page not found\n"1439--- PASS: TestPushWaitsForSweepHoldingRow (0.83s)1440=== CONT TestRegisterCompletedObjectNeedsPendingRow14412026/10/27 13:03:39 WARN Failed to register uploaded object key=7nzf73qv56y58i3m1b54khrch7r169qd.ls error="server returned 404: 404 page not found\n"14422026/10/27 13:03:39 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14432026/10/27 13:03:39 WARN Failed to register uploaded object key=nyxmyy9gbg2b7q8bw08k3rj02zi1fyy1.ls error="server returned 404: 404 page not found\n"14442026/10/27 13:03:39 INFO Signed narinfos id=1 count=214452026/10/27 13:03:39 INFO Uploading 2 narinfos1446--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.27s)1447=== CONT TestSweepRechecksPendingAfterLocking14482026/10/27 13:03:39 WARN Failed to register uploaded object key=7nzf73qv56y58i3m1b54khrch7r169qd.narinfo error="server returned 404: 404 page not found\n"14492026/10/27 13:03:39 INFO Received complete push request method=POST path=/api/pushes/1/complete14502026/10/27 13:03:39 WARN Failed to register uploaded object key=nyxmyy9gbg2b7q8bw08k3rj02zi1fyy1.narinfo error="server returned 404: 404 page not found\n"14512026/10/27 13:03:39 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14522026/10/27 13:03:39 INFO Completed push id=1 objects=6 duration=10.186979ms14532026/10/27 13:03:39 INFO Upload complete. (135ms)1454=== NAME TestClientSharedPathCommittedMidPush1455 client_integration_test.go:803: Retrieved narinfo from S3:1456 StorePath: /build/TestClientSharedPathCommittedMidPush2970979683/001/store/7nzf73qv56y58i3m1b54khrch7r169qd-shared-dep1457 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1458 Compression: zstd1459 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821460 NarSize: 1361461 References: 1462 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1463 client_integration_test.go:803: Retrieved narinfo from S3:1464 StorePath: /build/TestClientSharedPathCommittedMidPush2970979683/001/store/nyxmyy9gbg2b7q8bw08k3rj02zi1fyy1-top1465 URL: nar/1mra96mfxa4hibnf9p1vlmnlgfy3zcy8ykpihlsalg3wbzmv272h.nar.zst1466 Compression: zstd1467 NarHash: sha256:1mra96mfxa4hibnf9p1vlmnlgfy3zcy8ykpihlsalg3wbzmv272h14682026/10/27 13:03:39 INFO Completed multipart upload object_key=nar/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb00000000000000000000.nar.zst upload_id=MWYwZWQ5MzQtMzk0OC00NzkxLWFmMzAtMTMwN2E1NTgzMDY2LjJmNWFiZGRlLWI4NzgtNGY1Yi1hMDliLWZjYTVlODU5MWM3NHgxNzkzMTA2MjE4NDA5MTAzNDE3 parts=101469 NarSize: 2241470 References: /build/TestClientSharedPathCommittedMidPush2970979683/001/store/7nzf73qv56y58i3m1b54khrch7r169qd-shared-dep1471 CA: text:sha256:0k90s86mg8hka9cki3wjdcpndv528dssrbm4bimh6nbjpmrra6bb14722026/10/27 13:03:39 INFO Received complete push request method=POST path=/api/pushes/1/complete14732026/10/27 13:03:39 INFO Received uploads request method=POST path=/api/pending_closures14742026/10/27 13:03:39 INFO Completed push id=1 objects=4 duration=5.86337ms1475=== NAME TestClientWithDependencies1476 client_integration_test.go:722: Built derivation: /build/TestClientWithDependencies2005232600/001/store/824c34n9m0k3qgw77hmpc3qvmlpdxl13-test-script1477--- PASS: TestPush_RepeatedRootCommitsOnce (2.18s)14782026/10/27 13:03:39 INFO Received create pin request method=POST path=/api/pins/app1479=== CONT TestSweepSkipsRowsLockedByPush1480=== CONT TestDeletePinKeepsRowWhenS3Fails1481--- PASS: TestTombstonedObjectOfferedWithoutWaiting (0.32s)1482--- PASS: TestReadRedirectKeepsNarinfoProxied (0.57s)1483=== CONT TestCommitRacingPendingCleanupKeepsObjects14842026/10/27 13:03:39 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>1485--- PASS: TestClientSharedPathCommittedMidPush (0.67s)1486=== CONT TestDeleteClosuresRacingPins14872026/10/27 13:03:39 INFO Received create pin request method=POST path=/api/pins/app1488--- PASS: TestReadProxyHead (0.45s)1489=== CONT TestReconnectLeavesObjectsUnlocked1490=== NAME TestClientWithDependencies1491 client_integration_test.go:724: Found 1 dependencies (including self)1492--- PASS: TestReadProxyNarinfo (1.34s)1493=== CONT TestOrphanedObjectsGC14942026/10/27 13:03:39 INFO Received create pin request method=POST path=/api/pins/deploy14952026/10/27 13:03:39 INFO Created/updated pin name=deploy store_path="/nix/store/dddddddddddddddddddddddddddddddd-app-1.0+git_x?y=z" narinfo_key=dddddddddddddddddddddddddddddddd.narinfo14962026/10/27 13:03:39 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1497--- PASS: TestCreatePinRejectsBadInput (1.15s)1498=== CONT TestClientFallsBackToClosures1499--- PASS: TestRegisterCompletedObjectNeedsPendingRow (0.28s)1500=== CONT TestForceGCDuringPushOffersSweptObject1501=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows1502=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows1503=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check1504=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check1505=== CONT TestPendingClosureFailureTracksEveryUpload1506=== RUN TestPendingClosureFailureTracksEveryUpload/refuse_aborts=false1507=== PAUSE TestPendingClosureFailureTracksEveryUpload/refuse_aborts=false1508=== RUN TestPendingClosureFailureTracksEveryUpload/refuse_aborts=true1509=== PAUSE TestPendingClosureFailureTracksEveryUpload/refuse_aborts=true1510=== CONT TestGCSweepDeliversEachKeyOnce15112026/10/27 13:03:39 INFO Received push request method=POST path=/api/pushes15122026/10/27 13:03:39 INFO Completed multipart upload object_key=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa00000000000000000000.nar.zst upload_id=MWYwZWQ5MzQtMzk0OC00NzkxLWFmMzAtMTMwN2E1NTgzMDY2LjcyMTVhOTMxLTkyYTEtNDU4MS1hZDRjLTc4ZTI3MmY5MzRjMngxNzkzMTA2MjE5MTUxNDUyNDI4 parts=1015132026/10/27 13:03:39 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15142026/10/27 13:03:39 INFO Uploading 824c34n9m0k3qgw77hmpc3qvmlpdxl13-test-script (136B)15152026/10/27 13:03:39 INFO Aborted multipart uploads count=0 kept=015162026/10/27 13:03:39 WARN Force mode enabled - objects will be deleted immediately without grace period15172026/10/27 13:03:39 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"15182026/10/27 13:03:39 WARN Failed to register uploaded object key=log/1ncqj5sx52ghkay7s3gz7y76ig3mnvkp-test-script.drv error="server returned 404: 404 page not found\n"15192026/10/27 13:03:39 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15202026/10/27 13:03:39 INFO Received complete multipart upload request method=POST path=/api/multipart/complete15212026/10/27 13:03:39 WARN Failed to register uploaded object key=824c34n9m0k3qgw77hmpc3qvmlpdxl13.ls error="server returned 404: 404 page not found\n"15222026/10/27 13:03:39 INFO Signed narinfos id=1 count=115232026/10/27 13:03:39 INFO Uploading 1 narinfos15242026/10/27 13:03:39 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=015252026/10/27 13:03:39 INFO Vacuumed table table=pending_closures15262026/10/27 13:03:39 INFO Received complete push request method=POST path=/api/pushes/1/complete15272026/10/27 13:03:39 WARN Failed to register uploaded object key=824c34n9m0k3qgw77hmpc3qvmlpdxl13.narinfo error="server returned 404: 404 page not found\n"15282026/10/27 13:03:39 INFO Vacuumed table table=pending_objects15292026/10/27 13:03:39 INFO Vacuumed table table=multipart_uploads15302026/10/27 13:03:39 INFO Vacuumed table table=closures15312026/10/27 13:03:39 INFO Vacuumed table table=objects15322026/10/27 13:03:39 INFO Completed multipart upload object_key=nar/cccccccccccccccccccccccccccccccc00000000000000000000.nar.zst upload_id=MWYwZWQ5MzQtMzk0OC00NzkxLWFmMzAtMTMwN2E1NTgzMDY2LjMzZTI4Y2JhLThhOTQtNGQ4My1hNzE2LWNiNjUzMjFkODc4MngxNzkzMTA2MjE5MDc3NDE3NDM5 parts=1015332026/10/27 13:03:39 INFO Received complete push request method=POST path=/api/pushes/2/complete15342026/10/27 13:03:39 INFO Completed push id=2 objects=4 duration=4.0338ms15352026/10/27 13:03:39 INFO Completed push id=1 objects=4 duration=11.89713ms15362026/10/27 13:03:39 INFO Upload complete. (97ms)15372026/10/27 13:03:39 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1538--- PASS: TestSweepRechecksPendingAfterLocking (0.35s)1539=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection15402026/10/27 13:03:39 INFO Aborted multipart uploads count=0 kept=015412026/10/27 13:03:39 WARN Force mode enabled - objects will be deleted immediately without grace period15422026/10/27 13:03:39 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=01543--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (2.37s)1544=== CONT TestClientMultipleUploads15452026/10/27 13:03:39 INFO Vacuumed table table=pending_closures15462026/10/27 13:03:39 INFO Completed multipart upload object_key=nar/cccccccccccccccccccccccccccccccc00000000000000000000.nar.zst upload_id=MWYwZWQ5MzQtMzk0OC00NzkxLWFmMzAtMTMwN2E1NTgzMDY2LjMxYzVmNzZjLWZmYTEtNDY0Ni04MmY3LThlYTE2NWFmMDk4NHgxNzkzMTA2MjE4MjYzMDk5NTgw parts=1015472026/10/27 13:03:39 INFO Vacuumed table table=pending_objects15482026/10/27 13:03:39 INFO Vacuumed table table=multipart_uploads15492026/10/27 13:03:39 INFO Vacuumed table table=closures15502026/10/27 13:03:39 INFO Vacuumed table table=objects15512026/10/27 13:03:39 INFO Received complete push request method=POST path=/api/pushes/1/complete15522026/10/27 13:03:39 INFO Aborted multipart uploads count=0 kept=01553=== NAME TestClientWithDependencies1554 client_integration_test.go:740: Skipping nix copy test - isolated store (/build/TestClientWithDependencies2005232600/001/store) requires matching store prefix15552026/10/27 13:03:39 WARN Force mode enabled - objects will be deleted immediately without grace period15562026/10/27 13:03:39 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=015572026/10/27 13:03:39 INFO Vacuumed table table=pending_closures15582026/10/27 13:03:39 INFO Vacuumed table table=pending_objects15592026/10/27 13:03:39 INFO Vacuumed table table=multipart_uploads15602026/10/27 13:03:39 INFO Vacuumed table table=closures15612026/10/27 13:03:39 INFO Completed push id=1 objects=6 duration=11.392339ms15622026/10/27 13:03:39 INFO Vacuumed table table=objects15632026/10/27 13:03:39 INFO Aborted multipart uploads count=0 kept=015642026/10/27 13:03:39 WARN Force mode enabled - objects will be deleted immediately without grace period1565--- PASS: TestClientWithDependencies (0.65s)1566=== CONT TestPinProtectsFromGC1567--- PASS: TestPush_CompleteCommitsEveryRoot (2.42s)1568=== CONT TestClientPushesUseOnePush15692026/10/27 13:03:39 INFO Aborted multipart uploads count=0 kept=015702026/10/27 13:03:39 WARN Force mode enabled - objects will be deleted immediately without grace period15712026/10/27 13:03:39 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=015722026/10/27 13:03:39 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=015732026/10/27 13:03:39 INFO Vacuumed table table=pending_closures15742026/10/27 13:03:39 INFO Vacuumed table table=pending_objects15752026/10/27 13:03:39 INFO Vacuumed table table=multipart_uploads15762026/10/27 13:03:39 INFO Vacuumed table table=closures15772026/10/27 13:03:39 INFO Vacuumed table table=pending_closures15782026/10/27 13:03:39 INFO Vacuumed table table=pending_objects15792026/10/27 13:03:39 INFO Vacuumed table table=objects15802026/10/27 13:03:39 INFO Vacuumed table table=multipart_uploads15812026/10/27 13:03:39 INFO Vacuumed table table=closures15822026/10/27 13:03:39 INFO Received create pin request method=POST path=/api/pins/app15832026/10/27 13:03:39 INFO Vacuumed table table=objects1584--- PASS: TestReconnectLeavesObjectsUnlocked (0.25s)1585=== CONT TestGCSweepSkipsPendingObjects15862026/10/27 13:03:39 INFO Created/updated pin name=app store_path=/nix/store/cccccccccccccccccccccccccccccccc-app narinfo_key=cccccccccccccccccccccccccccccccc.narinfo15872026/10/27 13:03:39 INFO Received delete pin request method=DELETE path=/api/pins/app15882026/10/27 13:03:39 ERROR Failed to delete pin from S3 key=pins/app error="Get \"http://127.0.0.1:1/bucket74/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"1589--- PASS: TestSweepSkipsRowsLockedByPush (0.27s)1590=== CONT TestGCAdvisoryLockBlocksConcurrentRun15912026/10/27 13:03:39 INFO Received delete pin request method=DELETE path=/api/pins/app1592--- PASS: TestCommitRacingPendingCleanupKeepsObjects (0.28s)1593=== CONT TestPushDedupSurvivesConcurrentGC15942026/10/27 13:03:39 INFO Deleted pin name=app1595--- PASS: TestDeletePinKeepsRowWhenS3Fails (0.31s)1596=== CONT TestClientIntegration15972026/10/27 13:03:39 INFO Received complete multipart upload request method=POST path=/api/multipart/complete15982026/10/27 13:03:40 INFO Completed multipart upload object_key=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa00000000000000000000.nar.zst upload_id=MWYwZWQ5MzQtMzk0OC00NzkxLWFmMzAtMTMwN2E1NTgzMDY2LjQ2ZWRmYTBiLTA2NjAtNDE3YS04NzEzLWRlYTQyODJhZTViNXgxNzkzMTA2MjE4MzAyNDA0NDQ5 parts=1015992026/10/27 13:03:40 INFO Aborted multipart uploads count=0 kept=016002026/10/27 13:03:40 INFO Received uploads request method=POST path=/api/pending_closures16012026/10/27 13:03:40 WARN Force mode enabled - objects will be deleted immediately without grace period16022026/10/27 13:03:40 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=016032026/10/27 13:03:40 INFO Vacuumed table table=pending_closures16042026/10/27 13:03:40 INFO Vacuumed table table=pending_objects16052026/10/27 13:03:40 INFO Vacuumed table table=multipart_uploads16062026/10/27 13:03:40 INFO Vacuumed table table=closures16072026/10/27 13:03:40 INFO Vacuumed table table=objects1608--- PASS: TestConnectSerialisesConcurrentMigrations (1.12s)1609=== CONT TestDeduplicatedObjectsRecordedAsPending1610--- PASS: TestGCSweepDeliversEachKeyOnce (0.39s)1611=== CONT TestGCBugBareHashReferences1612=== NAME TestClientMultipleUploads1613 client_integration_test.go:467: Created store path 0: /build/TestClientMultipleUploads27819019/001/store/kfx6mkj0wm1443d1rd86f91fx4czrfv2-test-file-0.txt16142026/10/27 13:03:40 INFO Created/updated pin name=app store_path=/nix/store/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa-app narinfo_key=aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.narinfo16152026/10/27 13:03:40 INFO Received uploads request method=POST path=/api/pending_closures1616 client_integration_test.go:467: Created store path 1: /build/TestClientMultipleUploads27819019/001/store/ym4cnzl5psw258n45bw5h6vi2azp2fpc-test-file-1.txt16172026/10/27 13:03:40 INFO lead: released remote=192.0.2.1:123416182026/10/27 13:03:40 INFO Created/updated pin name=app store_path=/nix/store/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb-app narinfo_key=bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb.narinfo1619=== NAME TestPinProtectsFromGC1620 client_integration_test.go:854: Pinned store path: /build/TestPinProtectsFromGC2045624380/001/store/lmv12kjgv285b73c3pjk0ank72vzzvmj-pinned-file.txt1621 client_integration_test.go:855: Unpinned store path: /build/TestPinProtectsFromGC2045624380/001/store/c1mp4sdi853mrm4adfsalpm54bxgvsjs-unpinned-file.txt16222026/10/27 13:03:40 INFO Aborted multipart uploads count=0 kept=016232026/10/27 13:03:40 WARN Force mode enabled - objects will be deleted immediately without grace period16242026/10/27 13:03:40 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=01625=== CONT TestService_AuthMiddleware_MTLSProxyHeader1626--- PASS: TestLeadEndsOnShutdown (1.39s)16272026/10/27 13:03:40 INFO Vacuumed table table=pending_closures16282026/10/27 13:03:40 INFO Vacuumed table table=pending_objects16292026/10/27 13:03:40 INFO Vacuumed table table=multipart_uploads16302026/10/27 13:03:40 INFO Vacuumed table table=closures16312026/10/27 13:03:40 INFO Vacuumed table table=objects1632=== CONT TestService_ReadAuthMiddleware1633--- PASS: TestConcurrentPinUpdatesAgree (0.87s)1634=== NAME TestClientMultipleUploads1635 client_integration_test.go:467: Created store path 2: /build/TestClientMultipleUploads27819019/001/store/kfkz52kj0y6wczsfj42vf185vf2nw983-test-file-2.txt16362026/10/27 13:03:40 INFO Received uploads request method=POST path=/api/pending_closures1637--- PASS: TestGCSweepSkipsPendingObjects (0.32s)1638=== CONT TestService_RequireScope_OIDC16392026/10/27 13:03:40 INFO Received uploads request method=POST path=/api/pending_closures16402026/10/27 13:03:40 INFO Received uploads request method=POST path=/api/pending_closures16412026/10/27 13:03:40 INFO Received complete multipart upload request method=POST path=/api/multipart/complete16422026/10/27 13:03:40 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)16432026/10/27 13:03:40 INFO Uploading qcbixnqg3r47gfbzlii0q82lk0miw1ds-b (216B)16442026/10/27 13:03:40 INFO Uploading i7fgh0n4imydj4mimyf850bnac2359g9-shared-dep (136B)16452026/10/27 13:03:40 WARN Failed to register uploaded object key=nar/0vs71jwpl1lri5bzcx9g99mjb3fc76rakl8b8krbn94rbi0lx8hm.nar.zst error="server returned 404: 404 page not found\n"16462026/10/27 13:03:40 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"16472026/10/27 13:03:40 WARN Failed to register uploaded object key=qcbixnqg3r47gfbzlii0q82lk0miw1ds.ls error="server returned 404: 404 page not found\n"16482026/10/27 13:03:40 WARN Failed to register uploaded object key=67jf9ydc6kd21l7wmx7ccd9gsm6ya2cm.ls error="server returned 404: 404 page not found\n"16492026/10/27 13:03:40 INFO Completed multipart upload object_key=nar/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb00000000000000000000.nar.zst upload_id=MWYwZWQ5MzQtMzk0OC00NzkxLWFmMzAtMTMwN2E1NTgzMDY2Ljk5MWZmYmYzLTAzNDctNGJjYi1iNmUzLTEyMGRjMzU4MmU2NHgxNzkzMTA2MjE5MTUwMjEzMjA4 parts=1016502026/10/27 13:03:40 INFO Received complete push request method=POST path=/api/pushes/1/complete16512026/10/27 13:03:40 INFO Received push request method=POST path=/api/pushes16522026/10/27 13:03:40 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign16532026/10/27 13:03:40 WARN Failed to register uploaded object key=i7fgh0n4imydj4mimyf850bnac2359g9.ls error="server returned 404: 404 page not found\n"16542026/10/27 13:03:40 INFO Signed narinfos id=1 count=216552026/10/27 13:03:40 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign16562026/10/27 13:03:40 INFO Signed narinfos id=2 count=216572026/10/27 13:03:40 INFO Uploading 4 narinfos16582026/10/27 13:03:40 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16592026/10/27 13:03:40 INFO Uploading lmv12kjgv285b73c3pjk0ank72vzzvmj-pinned-file.txt (128B)16602026/10/27 13:03:40 WARN Failed to register uploaded object key=67jf9ydc6kd21l7wmx7ccd9gsm6ya2cm.narinfo error="server returned 404: 404 page not found\n"16612026/10/27 13:03:40 INFO Completed push id=1 objects=4 duration=10.710569ms16622026/10/27 13:03:40 INFO Received uploads request method=POST path=/api/pending_closures1663--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (0.89s)1664=== CONT TestClientCADerivations1665--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (0.47s)1666=== CONT TestService_AuthMiddleware_OIDC16672026/10/27 13:03:40 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete1668=== NAME TestClientIntegration16692026/10/27 13:03:40 INFO Completed upload id=2 objects=2 duration=1.90717ms1670 client_integration_test.go:331: Created store path: /build/TestClientIntegration388782499/002/store/1ap1fbyg942rhasxpxdz19npcfngx9wx-test-file.txt16712026/10/27 13:03:40 WARN Failed to register uploaded object key=qcbixnqg3r47gfbzlii0q82lk0miw1ds.narinfo error="server returned 404: 404 page not found\n"16722026/10/27 13:03:40 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"16732026/10/27 13:03:40 WARN Failed to register uploaded object key=i7fgh0n4imydj4mimyf850bnac2359g9.narinfo error="server returned 404: 404 page not found\n"16742026/10/27 13:03:40 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete16752026/10/27 13:03:40 INFO Received push request method=POST path=/api/pushes16762026/10/27 13:03:40 WARN Failed to register uploaded object key=i7fgh0n4imydj4mimyf850bnac2359g9.narinfo error="server returned 404: 404 page not found\n"16772026/10/27 13:03:40 INFO Completed upload id=1 objects=6 duration=7.09ms1678--- PASS: TestDeduplicatedObjectsRecordedAsPending (0.18s)1679=== CONT TestReadProxyRangeRequest16802026/10/27 13:03:40 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete16812026/10/27 13:03:40 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:42043/oidc16822026/10/27 13:03:40 INFO Completed upload id=2 objects=6 duration=1.87846ms16832026/10/27 13:03:40 INFO Upload complete. (150ms)16842026/10/27 13:03:40 INFO Aborted multipart uploads count=0 kept=01685=== NAME TestClientFallsBackToClosures1686 client_pushes_test.go:112: Retrieved narinfo from S3:1687 StorePath: /build/TestClientFallsBackToClosures853827463/001/store/i7fgh0n4imydj4mimyf850bnac2359g9-shared-dep1688 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1689 Compression: zstd1690 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821691 NarSize: 1361692 References: 1693 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n16942026/10/27 13:03:40 WARN Failed to register uploaded object key=lmv12kjgv285b73c3pjk0ank72vzzvmj.ls error="server returned 404: 404 page not found\n"16952026/10/27 13:03:40 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16962026/10/27 13:03:40 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)16972026/10/27 13:03:40 INFO Uploading kfx6mkj0wm1443d1rd86f91fx4czrfv2-test-file-0.txt (160B)16982026/10/27 13:03:40 INFO Uploading kfkz52kj0y6wczsfj42vf185vf2nw983-test-file-2.txt (160B)16992026/10/27 13:03:40 INFO Uploading ym4cnzl5psw258n45bw5h6vi2azp2fpc-test-file-1.txt (160B)17002026/10/27 13:03:40 INFO Signed narinfos id=1 count=117012026/10/27 13:03:40 INFO Uploading 1 narinfos1702 client_pushes_test.go:112: Retrieved narinfo from S3:1703 StorePath: /build/TestClientFallsBackToClosures853827463/001/store/67jf9ydc6kd21l7wmx7ccd9gsm6ya2cm-a1704 URL: nar/0vs71jwpl1lri5bzcx9g99mjb3fc76rakl8b8krbn94rbi0lx8hm.nar.zst1705 Compression: zstd1706 NarHash: sha256:0vs71jwpl1lri5bzcx9g99mjb3fc76rakl8b8krbn94rbi0lx8hm1707 NarSize: 2161708 References: /build/TestClientFallsBackToClosures853827463/001/store/i7fgh0n4imydj4mimyf850bnac2359g9-shared-dep1709 CA: text:sha256:07vhs1f03j8y3abn7zs0jk42n2ipanj95pckiyqggk7mcvffc24b17102026/10/27 13:03:40 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=017112026/10/27 13:03:40 INFO Vacuumed table table=pending_closures1712 client_pushes_test.go:112: Retrieved narinfo from S3:1713 StorePath: /build/TestClientFallsBackToClosures853827463/001/store/qcbixnqg3r47gfbzlii0q82lk0miw1ds-b1714 URL: nar/0vs71jwpl1lri5bzcx9g99mjb3fc76rakl8b8krbn94rbi0lx8hm.nar.zst1715 Compression: zstd1716 NarHash: sha256:0vs71jwpl1lri5bzcx9g99mjb3fc76rakl8b8krbn94rbi0lx8hm1717 NarSize: 2161718 References: /build/TestClientFallsBackToClosures853827463/001/store/i7fgh0n4imydj4mimyf850bnac2359g9-shared-dep1719 CA: text:sha256:07vhs1f03j8y3abn7zs0jk42n2ipanj95pckiyqggk7mcvffc24b17202026/10/27 13:03:40 INFO Vacuumed table table=pending_objects17212026/10/27 13:03:40 INFO Vacuumed table table=multipart_uploads17222026/10/27 13:03:40 INFO Vacuumed table table=closures17232026/10/27 13:03:40 INFO Received complete push request method=POST path=/api/pushes/1/complete17242026/10/27 13:03:40 WARN Failed to register uploaded object key=lmv12kjgv285b73c3pjk0ank72vzzvmj.narinfo error="server returned 404: 404 page not found\n"17252026/10/27 13:03:40 INFO Vacuumed table table=objects1726--- PASS: TestMetricsCommit (1.47s)17272026/10/27 13:03:40 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"1728=== CONT TestService_ReadScope_PublicByDefault17292026/10/27 13:03:40 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"17302026/10/27 13:03:40 WARN Failed to register uploaded object key=kfkz52kj0y6wczsfj42vf185vf2nw983.ls error="server returned 404: 404 page not found\n"17312026/10/27 13:03:40 WARN Failed to register uploaded object key=ym4cnzl5psw258n45bw5h6vi2azp2fpc.ls error="server returned 404: 404 page not found\n"17322026/10/27 13:03:40 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"17332026/10/27 13:03:40 WARN Failed to register uploaded object key=kfx6mkj0wm1443d1rd86f91fx4czrfv2.ls error="server returned 404: 404 page not found\n"17342026/10/27 13:03:40 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17352026/10/27 13:03:40 INFO Signed narinfos id=1 count=317362026/10/27 13:03:40 INFO Uploading 3 narinfos17372026/10/27 13:03:40 INFO Received push request method=POST path=/api/pushes17382026/10/27 13:03:40 WARN Failed to register uploaded object key=ym4cnzl5psw258n45bw5h6vi2azp2fpc.narinfo error="server returned 404: 404 page not found\n"17392026/10/27 13:03:40 INFO Completed push id=1 objects=3 duration=15.03475ms17402026/10/27 13:03:40 WARN Failed to register uploaded object key=kfkz52kj0y6wczsfj42vf185vf2nw983.narinfo error="server returned 404: 404 page not found\n"17412026/10/27 13:03:40 INFO Upload complete. (114ms)17422026/10/27 13:03:40 INFO Aborted multipart uploads count=0 kept=017432026/10/27 13:03:40 WARN Force mode enabled - objects will be deleted immediately without grace period17442026/10/27 13:03:40 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=017452026/10/27 13:03:40 INFO Vacuumed table table=pending_closures17462026/10/27 13:03:40 INFO Received complete push request method=POST path=/api/pushes/1/complete17472026/10/27 13:03:40 WARN Failed to register uploaded object key=kfx6mkj0wm1443d1rd86f91fx4czrfv2.narinfo error="server returned 404: 404 page not found\n"17482026/10/27 13:03:40 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)17492026/10/27 13:03:40 INFO Uploading 47clqg44dv4qfnqnd4ni86c324qdcvcv-shared-dep (136B)17502026/10/27 13:03:40 INFO Uploading j1nhgdsayq87z1ffhdz38vfb904ii3lq-a (208B)1751=== CONT TestProxyWriteTimeout/narinfo1752--- PASS: TestClientFallsBackToClosures (0.63s)1753=== CONT TestProxyWriteTimeout/unknown_size1754=== CONT TestProxyWriteTimeout/10_GiB_nar1755=== CONT TestProxyWriteTimeout/1_GiB_nar17562026/10/27 13:03:40 INFO Received push request method=POST path=/api/pushes1757=== CONT TestPendingClosureWriteTimeout/400_objects1758--- PASS: TestProxyWriteTimeout (0.01s)1759 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1760 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1761 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1762 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1763=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline17642026/10/27 13:03:40 INFO Vacuumed table table=pending_objects17652026/10/27 13:03:40 INFO Vacuumed table table=multipart_uploads17662026/10/27 13:03:40 INFO Completed push id=1 objects=9 duration=7.87222ms17672026/10/27 13:03:40 INFO Upload complete. (108ms)1768=== NAME TestClientMultipleUploads1769 client_integration_test.go:478: Uploaded 3 paths in 138.373976ms17702026/10/27 13:03:40 INFO Vacuumed table table=closures17712026/10/27 13:03:40 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17722026/10/27 13:03:40 INFO Uploading 1ap1fbyg942rhasxpxdz19npcfngx9wx-test-file.txt (152B)17732026/10/27 13:03:40 INFO Vacuumed table table=objects1774=== NAME TestOrphanedObjectsGC1775 orphaned_objects_gc_test.go:287: GC Test Summary:1776 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A1777 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B1778 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)1779 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)1780 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects17812026/10/27 13:03:40 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"17822026/10/27 13:03:40 WARN Failed to register uploaded object key=d86br69dxw3k7k5lij80v0wab2mgi266.ls error="server returned 404: 404 page not found\n"17832026/10/27 13:03:40 WARN Failed to register uploaded object key=j1nhgdsayq87z1ffhdz38vfb904ii3lq.ls error="server returned 404: 404 page not found\n"17842026/10/27 13:03:40 WARN Failed to register uploaded object key=nar/1h2bpy573xx9wn2kgpv7v3pdz8433y3aj55j184jcbrjlxv0v4ys.nar.zst error="server returned 404: 404 page not found\n"17852026/10/27 13:03:40 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17862026/10/27 13:03:40 WARN Failed to register uploaded object key=47clqg44dv4qfnqnd4ni86c324qdcvcv.ls error="server returned 404: 404 page not found\n"17872026/10/27 13:03:40 INFO Signed narinfos id=1 count=317882026/10/27 13:03:40 INFO Uploading 3 narinfos1789--- PASS: TestPushDedupSurvivesConcurrentGC (0.45s)1790=== CONT TestPendingClosureWriteTimeout/670k_objects1791=== CONT TestPendingClosureWriteTimeout/empty1792=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info17932026/10/27 13:03:40 WARN Failed to register uploaded object key=d86br69dxw3k7k5lij80v0wab2mgi266.narinfo error="server returned 404: 404 page not found\n"17942026/10/27 13:03:40 INFO Received uploads request method=POST path=/17952026/10/27 13:03:40 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"17962026/10/27 13:03:40 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"1797=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal17982026/10/27 13:03:40 INFO Received uploads request method=POST path=/1799--- PASS: TestOrphanedObjectsGC (0.70s)1800=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key18012026/10/27 13:03:40 INFO Received request for more parts method=POST path=/1802=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1803=== CONT TestIsValidUploadKey/nar_xz18042026/10/27 13:03:40 INFO Received complete multipart upload request method=POST path=/1805=== CONT TestIsValidUploadKey/realisation_plus_in_output1806=== CONT TestIsValidUploadKey/build_log_equals1807=== CONT TestIsValidUploadKey/build_log_plus_in_name1808=== CONT TestIsValidUploadKey/build_log_home-manager_file1809--- PASS: TestUploadHandlersRejectInvalidKeys (0.01s)1810 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1811 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1812 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1813 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1814=== CONT TestIsValidUploadKey/build_log_question_mark1815=== CONT TestIsValidUploadKey/listing1816=== CONT TestIsValidUploadKey/build_log1817=== CONT TestIsValidUploadKey/nar_plain1818=== CONT TestIsValidUploadKey/nar_zst1819=== CONT TestIsValidUploadKey/narinfo1820=== CONT TestIsValidUploadKey/traversal1821=== CONT TestIsValidUploadKey/unknown_type1822=== CONT TestIsValidUploadKey/absolute1823=== CONT TestIsValidUploadKey/empty_key1824=== CONT TestIsValidUploadKey/traversal_nar1825=== CONT TestIsValidUploadKey/index.html1826=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1827=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1828=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1829=== CONT TestIsValidUploadKey/nix-cache-info1830=== CONT TestIsValidUploadKey/realisation1831=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1832=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1833--- PASS: TestIsValidUploadKey (0.01s)1834 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1835 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1836 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1837 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1838 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1839 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1840 --- PASS: TestIsValidUploadKey/listing (0.00s)1841 --- PASS: TestIsValidUploadKey/build_log (0.00s)1842 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1843 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1844 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1845 --- PASS: TestIsValidUploadKey/traversal (0.00s)1846 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1847 --- PASS: TestIsValidUploadKey/absolute (0.00s)1848 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1849 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1850 --- PASS: TestIsValidUploadKey/index.html (0.00s)1851 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1852 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1853 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1854 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1855 --- PASS: TestIsValidUploadKey/realisation (0.00s)18562026/10/27 13:03:40 WARN Failed to register uploaded object key=j1nhgdsayq87z1ffhdz38vfb904ii3lq.narinfo error="server returned 404: 404 page not found\n"18572026/10/27 13:03:40 WARN Failed to register uploaded object key=47clqg44dv4qfnqnd4ni86c324qdcvcv.narinfo error="server returned 404: 404 page not found\n"18582026/10/27 13:03:40 INFO Received complete push request method=POST path=/api/pushes/1/complete18592026/10/27 13:03:40 WARN Failed to register uploaded object key=1ap1fbyg942rhasxpxdz19npcfngx9wx.ls error="server returned 404: 404 page not found\n"18602026/10/27 13:03:40 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18612026/10/27 13:03:40 INFO Signed narinfos id=1 count=118622026/10/27 13:03:40 INFO Uploading 1 narinfos1863--- PASS: TestClientMultipleUploads (0.57s)1864=== CONT TestGCEndsOnShutdown/before_the_run18652026/10/27 13:03:40 INFO Received complete push request method=POST path=/api/pushes/1/complete18662026/10/27 13:03:40 WARN Failed to register uploaded object key=1ap1fbyg942rhasxpxdz19npcfngx9wx.narinfo error="server returned 404: 404 page not found\n"18672026/10/27 13:03:40 INFO Completed push id=1 objects=8 duration=15.35454ms18682026/10/27 13:03:40 INFO Upload complete. (112ms)1869=== NAME TestClientPushesUseOnePush1870 client_pushes_test.go:97: Retrieved narinfo from S3:1871 StorePath: /build/TestClientPushesUseOnePush916632577/001/store/47clqg44dv4qfnqnd4ni86c324qdcvcv-shared-dep1872 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1873 Compression: zstd1874 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821875 NarSize: 1361876 References: 1877 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n18782026/10/27 13:03:40 INFO Completed push id=1 objects=3 duration=10.27408ms18792026/10/27 13:03:40 INFO Upload complete. (94ms)1880 client_pushes_test.go:97: Retrieved narinfo from S3:1881 StorePath: /build/TestClientPushesUseOnePush916632577/001/store/j1nhgdsayq87z1ffhdz38vfb904ii3lq-a1882 URL: nar/1h2bpy573xx9wn2kgpv7v3pdz8433y3aj55j184jcbrjlxv0v4ys.nar.zst1883 Compression: zstd1884 NarHash: sha256:1h2bpy573xx9wn2kgpv7v3pdz8433y3aj55j184jcbrjlxv0v4ys1885 NarSize: 2081886 References: /build/TestClientPushesUseOnePush916632577/001/store/47clqg44dv4qfnqnd4ni86c324qdcvcv-shared-dep1887 CA: text:sha256:103rc1bywc4p9v8bwkhk20hbk41xbi93m0q7mb3klr18siril43z1888 client_pushes_test.go:97: Retrieved narinfo from S3:1889 StorePath: /build/TestClientPushesUseOnePush916632577/001/store/d86br69dxw3k7k5lij80v0wab2mgi266-b1890 URL: nar/1h2bpy573xx9wn2kgpv7v3pdz8433y3aj55j184jcbrjlxv0v4ys.nar.zst1891 Compression: zstd1892 NarHash: sha256:1h2bpy573xx9wn2kgpv7v3pdz8433y3aj55j184jcbrjlxv0v4ys1893 NarSize: 2081894 References: /build/TestClientPushesUseOnePush916632577/001/store/47clqg44dv4qfnqnd4ni86c324qdcvcv-shared-dep1895 CA: text:sha256:103rc1bywc4p9v8bwkhk20hbk41xbi93m0q7mb3klr18siril43z1896--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.22s)1897=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts18982026/10/27 13:03:40 INFO Received request for more parts method=POST path=/1899--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.50s)1900=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure19012026/10/27 13:03:40 INFO Received uploads request method=POST path=/19022026/10/27 13:03:40 INFO Received push request method=POST path=/api/pushes19032026/10/27 13:03:40 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)19042026/10/27 13:03:40 INFO Uploading c1mp4sdi853mrm4adfsalpm54bxgvsjs-unpinned-file.txt (128B)19052026/10/27 13:03:40 INFO All 1 paths already cached1906=== NAME TestClientIntegration1907 client_integration_test.go:357: Retrieved narinfo from S3:1908 StorePath: /build/TestClientIntegration388782499/002/store/1ap1fbyg942rhasxpxdz19npcfngx9wx-test-file.txt1909 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1910 Compression: zstd1911 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11912 NarSize: 1521913 References: 1914 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11915=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart1916--- PASS: TestClientPushesUseOnePush (0.57s)19172026/10/27 13:03:40 INFO Received complete multipart upload request method=POST path=/1918--- PASS: TestService_ReadAuthMiddleware (0.24s)1919=== CONT TestServerTLSConfig/no_client_CA1920=== CONT TestServerTLSConfig/not_a_PEM_file1921=== NAME TestClientIntegration1922 client_integration_test.go:358: Retrieved .ls file from S3 (compressed size: 77 bytes)19232026/10/27 13:03:40 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"1924 client_integration_test.go:358: Decompressed .ls content (64 bytes):1925 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1926=== CONT TestServerTLSConfig/missing_CA_file1927=== CONT TestPush_RejectsBadRequests/no_objects1928--- PASS: TestServerTLSConfig (0.00s)1929 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1930 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)1931 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)19322026/10/27 13:03:40 INFO Received push request method=POST path=/api/pushes1933=== CONT TestPush_RejectsBadRequests/root_not_in_objects19342026/10/27 13:03:40 INFO Received push request method=POST path=/api/pushes1935=== CONT TestPush_RejectsBadRequests/bad_root19362026/10/27 13:03:40 INFO Received push request method=POST path=/api/pushes1937=== CONT TestPush_RejectsBadRequests/no_roots19382026/10/27 13:03:40 INFO Received push request method=POST path=/api/pushes1939=== CONT TestParseSingleRange/none1940=== CONT TestParseSingleRange/start_far_past_EOF1941=== CONT TestParseSingleRange/open-ended1942=== CONT TestParseSingleRange/end_clamped_to_size1943=== CONT TestParseSingleRange/suffix1944=== CONT TestParseSingleRange/suffix_exceeds_size1945=== CONT TestParseSingleRange/start_past_EOF1946=== CONT TestParseSingleRange/single_byte1947=== CONT TestParseSingleRange/malformed_both_empty1948=== CONT TestParseSingleRange/malformed_no_dash1949=== CONT TestParseSingleRange/malformed_end_before_start1950=== CONT TestParseSingleRange/closed1951=== CONT TestParseSingleRange/multi-range_ignored1952=== CONT TestParseSingleRange/unknown_unit1953=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale1954--- PASS: TestParseSingleRange (0.00s)1955 --- PASS: TestParseSingleRange/none (0.00s)1956 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1957 --- PASS: TestParseSingleRange/open-ended (0.00s)1958 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1959 --- PASS: TestParseSingleRange/suffix (0.00s)1960 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1961 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1962 --- PASS: TestParseSingleRange/single_byte (0.00s)1963 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1964 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1965 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1966 --- PASS: TestParseSingleRange/closed (0.00s)1967 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1968 --- PASS: TestParseSingleRange/unknown_unit (0.00s)19692026/10/27 13:03:40 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign19702026/10/27 13:03:40 WARN Failed to register uploaded object key=c1mp4sdi853mrm4adfsalpm54bxgvsjs.ls error="server returned 404: 404 page not found\n"19712026/10/27 13:03:40 INFO Signed narinfos id=2 count=119722026/10/27 13:03:40 INFO Uploading 1 narinfos19732026/10/27 13:03:40 INFO Received complete multipart upload request method=POST path=/api/multipart/complete19742026/10/27 13:03:40 INFO Received complete push request method=POST path=/api/pushes/2/complete19752026/10/27 13:03:40 WARN Failed to register uploaded object key=c1mp4sdi853mrm4adfsalpm54bxgvsjs.narinfo error="server returned 404: 404 page not found\n"19762026/10/27 13:03:40 INFO Completed push id=2 objects=3 duration=4.44946ms19772026/10/27 13:03:40 INFO Upload complete. (104ms)1978--- PASS: TestPush_RejectsBadRequests (0.46s)1979 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)1980 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)1981 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)1982 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)19832026/10/27 13:03:40 INFO Completed multipart upload object_key=nar/cccccccccccccccccccccccccccccccc00000000000000000000.nar.zst upload_id=MWYwZWQ5MzQtMzk0OC00NzkxLWFmMzAtMTMwN2E1NTgzMDY2LjQyZGJiOGVjLTY1NTktNDhiYS1hMjY1LTU5NDYyZmI4NmY2OXgxNzkzMTA2MjE4MzAxNzQwODU5 parts=1019842026/10/27 13:03:40 INFO lead: released remote=192.0.2.1:123419852026/10/27 13:03:40 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:45183/oidc19862026/10/27 13:03:40 INFO Starting cleanup of old closures method=DELETE path=/api/closures19872026/10/27 13:03:40 INFO Garbage collection started19882026/10/27 13:03:40 INFO Aborted multipart uploads count=0 kept=019892026/10/27 13:03:40 WARN Force mode enabled - objects will be deleted immediately without grace period19902026/10/27 13:03:40 INFO Received push request method=POST path=/api/pushes1991=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh1992--- PASS: TestReadProxyRangeRequest (0.24s)19932026/10/27 13:03:40 INFO lead: acquired remote=192.0.2.1:12341994=== RUN TestService_RequireScope_OIDC/builder_may_write1995=== PAUSE TestService_RequireScope_OIDC/builder_may_write1996=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1997=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1998=== RUN TestService_RequireScope_OIDC/ops_may_admin1999=== PAUSE TestService_RequireScope_OIDC/ops_may_admin2000=== RUN TestService_RequireScope_OIDC/ops_may_not_write2001=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write2002=== RUN TestService_RequireScope_OIDC/reader_may_not_write2003=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write2004=== RUN TestService_RequireScope_OIDC/static_token_may_admin2005=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin2006=== RUN TestService_RequireScope_OIDC/static_token_may_write2007=== PAUSE TestService_RequireScope_OIDC/static_token_may_write2008=== RUN TestService_RequireScope_OIDC/reader_may_read2009=== PAUSE TestService_RequireScope_OIDC/reader_may_read2010=== RUN TestService_RequireScope_OIDC/writer_implies_read2011=== PAUSE TestService_RequireScope_OIDC/writer_implies_read2012=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read2013=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read2014=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc2015=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc2016=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc2017=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc2018=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read2019=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read2020=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read2021=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read2022=== CONT TestIsValidCachePath/nar_bz22023=== CONT TestIsValidCachePath/traversal_in_middle2024=== CONT TestIsValidCachePath/invalid_char_e2025=== CONT TestIsValidCachePath/index.html2026=== CONT TestIsValidCachePath/nix-cache-info2027=== CONT TestIsValidCachePath/traversal_parent2028=== CONT TestIsValidCachePath/log2029=== CONT TestIsValidCachePath/nar_uncompressed2030=== CONT TestIsValidCachePath/invalid_char_u2031=== CONT TestIsValidCachePath/ls2032=== CONT TestIsValidCachePath/nar_xz2033=== CONT TestIsValidCachePath/leading_slash2034=== CONT TestIsValidCachePath/empty2035=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars2036=== CONT TestIsValidCachePath/realisation2037=== CONT TestIsValidCachePath/wrong_extension20382026/10/27 13:03:40 INFO Object in database but missing from S3 key=1ap1fbyg942rhasxpxdz19npcfngx9wx.ls2039=== CONT TestIsValidCachePath/random_path20402026/10/27 13:03:40 WARN Found objects in DB but missing from S3, will re-upload count=12041=== CONT TestIsValidCachePath/nar_zst2042=== CONT TestIsValidCachePath/narinfo2043=== CONT TestIsValidCachePath/short_hash2044=== CONT TestResolveDBConnectionString/PGHOST_allows_empty2045--- PASS: TestIsValidCachePath (0.00s)2046 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)2047 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)2048 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)2049 --- PASS: TestIsValidCachePath/index.html (0.00s)2050 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)2051 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)2052 --- PASS: TestIsValidCachePath/log (0.00s)2053 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)2054 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)2055 --- PASS: TestIsValidCachePath/ls (0.00s)2056 --- PASS: TestIsValidCachePath/nar_xz (0.00s)2057 --- PASS: TestIsValidCachePath/leading_slash (0.00s)2058 --- PASS: TestIsValidCachePath/empty (0.00s)2059 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)2060 --- PASS: TestIsValidCachePath/realisation (0.00s)2061 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)2062 --- PASS: TestIsValidCachePath/random_path (0.00s)2063 --- PASS: TestIsValidCachePath/nar_zst (0.00s)2064 --- PASS: TestIsValidCachePath/narinfo (0.00s)2065 --- PASS: TestIsValidCachePath/short_hash (0.00s)2066=== CONT TestResolveDBConnectionString/nothing_configured2067=== CONT TestResolveDBConnectionString/file_when_flag_empty2068=== CONT TestResolveDBConnectionString/missing_file_is_an_error20692026/10/27 13:03:40 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)2070=== CONT TestResolveDBConnectionString/flag_wins2071=== CONT TestCacheConfigHandler/full_config,_no_issuer2072=== CONT TestCacheConfigHandler/no_signing_keys2073=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2074=== CONT TestCacheConfigHandler/no_cache_url_configured2075--- PASS: TestResolveDBConnectionString (0.00s)2076 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)2077 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)2078 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)2079 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)2080 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)2081=== CONT TestClientErrorHandling/InvalidStorePath2082--- PASS: TestCacheConfigHandler (0.00s)2083 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)2084 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)2085 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)2086 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)2087=== CONT TestClientErrorHandling/InvalidAuthToken2088--- PASS: TestGCBugBareHashReferences (0.42s)20892026/10/27 13:03:40 INFO Received complete push request method=POST path=/api/pushes/2/complete2090=== NAME TestClientCADerivations2091 client_ca_test.go:136: Built CA derivation: /build/TestClientCADerivations1956252140/001/store/fs4f66dkv9c2m87vp0ibhn6z795dixc3-ca-test20922026/10/27 13:03:40 WARN Failed to register uploaded object key=1ap1fbyg942rhasxpxdz19npcfngx9wx.ls error="server returned 404: 404 page not found\n"20932026/10/27 13:03:40 INFO Completed push id=2 objects=3 duration=3.75697ms20942026/10/27 13:03:40 INFO Upload complete. (53ms)2095=== NAME TestClientIntegration2096 client_integration_test.go:375: Retrieved .ls file from S3 (compressed size: 62 bytes)2097 client_integration_test.go:375: Decompressed .ls content (49 bytes):2098 {"version":1,"root":{"type":"regular","size":39}}20992026/10/27 13:03:40 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=021002026/10/27 13:03:40 INFO Vacuumed table table=pending_closures21012026/10/27 13:03:40 INFO Vacuumed table table=pending_objects21022026/10/27 13:03:40 INFO Vacuumed table table=multipart_uploads2103=== NAME TestClientCADerivations2104 client_ca_test.go:139: Found 1 dependencies (including self)21052026/10/27 13:03:40 INFO Vacuumed table table=closures21062026/10/27 13:03:40 INFO Vacuumed table table=objects21072026/10/27 13:03:40 INFO Received uploads request method=POST path=/api/pending_closures2108--- PASS: TestService_ReadScope_PublicByDefault (0.29s)2109=== CONT TestClientErrorHandling/ServerNotAvailable21102026/10/27 13:03:40 INFO Aborted multipart uploads count=0 kept=021112026/10/27 13:03:40 WARN Force mode enabled - objects will be deleted immediately without grace period21122026/10/27 13:03:40 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:36545/bucket97/?delete=\": context canceled"21132026/10/27 13:03:40 INFO Received push request method=POST path=/api/pushes2114=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows21152026/10/27 13:03:40 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)2116=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check21172026/10/27 13:03:40 INFO Received complete push request method=POST path=/api/pushes/3/complete21182026/10/27 13:03:40 WARN Failed to register uploaded object key=1ap1fbyg942rhasxpxdz19npcfngx9wx.ls error="server returned 404: 404 page not found\n"21192026/10/27 13:03:40 INFO Completed push id=3 objects=3 duration=4.03002ms21202026/10/27 13:03:40 INFO Upload complete. (56ms)2121=== NAME TestClientIntegration2122 client_integration_test.go:392: Retrieved .ls file from S3 (compressed size: 62 bytes)2123 client_integration_test.go:392: Decompressed .ls content (49 bytes):2124 {"version":1,"root":{"type":"regular","size":39}}21252026/10/27 13:03:40 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present21262026/10/27 13:03:40 INFO Aborted multipart uploads count=0 kept=021272026/10/27 13:03:40 INFO Received push request method=POST path=/api/pushes21282026/10/27 13:03:40 WARN Force mode enabled - objects will be deleted immediately without grace period21292026/10/27 13:03:40 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)21302026/10/27 13:03:40 INFO Uploading fs4f66dkv9c2m87vp0ibhn6z795dixc3-ca-test (144B)21312026/10/27 13:03:40 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"2132=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token21332026/10/27 13:03:40 WARN Failed to register uploaded object key=fs4f66dkv9c2m87vp0ibhn6z795dixc3.ls error="server returned 404: 404 page not found\n"2134=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token2135=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2136=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2137=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected2138=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected2139=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2140=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2141=== CONT TestPendingClosureFailureTracksEveryUpload/refuse_aborts=false2142=== CONT TestPendingClosureFailureTracksEveryUpload/refuse_aborts=true2143--- PASS: TestGCEndsOnShutdown (0.00s)2144 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (0.28s)2145 --- PASS: TestGCEndsOnShutdown/before_the_run (0.28s)2146 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (0.35s)21472026/10/27 13:03:40 WARN Failed to register uploaded object key=log/abcxkk0b0sh52a7ylnlj1fi86l5xqby4-ca-test.drv error="server returned 404: 404 page not found\n"21482026/10/27 13:03:40 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign21492026/10/27 13:03:40 INFO Signed narinfos id=1 count=121502026/10/27 13:03:40 INFO Uploading 1 narinfos21512026/10/27 13:03:40 INFO Received complete push request method=POST path=/api/pushes/1/complete21522026/10/27 13:03:40 WARN Failed to register uploaded object key=fs4f66dkv9c2m87vp0ibhn6z795dixc3.narinfo error="server returned 404: 404 page not found\n"21532026/10/27 13:03:40 INFO Completed push id=1 objects=4 duration=7.18955ms21542026/10/27 13:03:40 INFO Upload complete. (128ms)2155=== NAME TestClientCADerivations2156 client_ca_test.go:180: Narinfo contains CA field: StorePath: /build/TestClientCADerivations1956252140/001/store/fs4f66dkv9c2m87vp0ibhn6z795dixc3-ca-test2157 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst2158 Compression: zstd2159 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2160 NarSize: 1442161 References: 2162 Deriver: /build/TestClientCADerivations1956252140/001/store/abcxkk0b0sh52a7ylnlj1fi86l5xqby4-ca-test.drv2163 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2164 client_ca_test.go:185: Checking for realisation files in S3...2165 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations2166 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache21672026/10/27 13:03:40 WARN Request failed, retrying attempt=2 backoff=213.59511ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present21682026-10-27 13:03:40.801 UTC [177] LOG: checkpoints are occurring too frequently (9 seconds apart)21692026-10-27 13:03:40.801 UTC [177] HINT: Consider increasing the configuration parameter "max_wal_size".21702026-10-27 13:03:40.801 UTC [177] LOG: checkpoint starting: wal21712026/10/27 13:03:40 INFO Received push request method=POST path=/api/pushes21722026/10/27 13:03:40 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)21732026/10/27 13:03:40 INFO Uploading qnv0x0kj83n411cp0n4j2q2frxf59knn-lost-commit.txt (152B)21742026/10/27 13:03:40 WARN Failed to register uploaded object key=qnv0x0kj83n411cp0n4j2q2frxf59knn.ls error="server returned 404: 404 page not found\n"21752026/10/27 13:03:40 INFO Received sign narinfos request method=POST path=/api/pushes/4/sign21762026/10/27 13:03:40 WARN Failed to register uploaded object key=nar/04d5klw9iix884nk82y7nlkps8afh2bg119y7zkvcf1pc1x2y2jl.nar.zst error="server returned 404: 404 page not found\n"21772026/10/27 13:03:40 INFO Signed narinfos id=4 count=121782026/10/27 13:03:40 INFO Uploading 1 narinfos21792026/10/27 13:03:40 INFO Received complete push request method=POST path=/api/pushes/4/complete21802026/10/27 13:03:40 WARN Failed to register uploaded object key=qnv0x0kj83n411cp0n4j2q2frxf59knn.narinfo error="server returned 404: 404 page not found\n"21812026/10/27 13:03:40 INFO Completed push id=4 objects=3 duration=1.92543ms21822026/10/27 13:03:40 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:37379/api/pushes/4/complete\": EOF" url=http://127.0.0.1:37379/api/pushes/4/complete2183 client_ca_test.go:258: nix copy output: warning: you don't have Internet access; disabling some network-dependent features2184 warning: failed to create TLS context for AWS credential providers; SSO, STS WebIdentity, and ECS container authentication will be unavailable2185 error: binary cache 's3://bucket92?endpoint=http://localhost:36545®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/build/TestClientCADerivations1956252140/001/store'2186 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 121872026/10/27 13:03:40 INFO Received uploads request method=POST path=/api/pending_closures21882026/10/27 13:03:40 INFO Aborted multipart uploads count=0 kept=02189=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2190=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read2191=== CONT TestService_RequireScope_OIDC/static_token_may_write2192=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read21932026/10/27 13:03:40 WARN Authentication failed token_preview=wrong token_length=5 oidc_error="no provider could verify the token (signature or issuer mismatch)" oidc_provider="" tried_providers=[test]2194=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc2195=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc21962026/10/27 13:03:40 WARN Force mode enabled - objects will be deleted immediately without grace period2197=== CONT TestService_RequireScope_OIDC/writer_implies_read2198--- PASS: TestClientCADerivations (0.59s)2199=== CONT TestService_RequireScope_OIDC/reader_may_read2200=== CONT TestService_RequireScope_OIDC/static_token_may_admin2201=== CONT TestService_RequireScope_OIDC/reader_may_not_write2202=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2203=== CONT TestService_RequireScope_OIDC/ops_may_not_write2204=== CONT TestService_RequireScope_OIDC/builder_may_write2205=== CONT TestService_RequireScope_OIDC/ops_may_admin2206=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2207=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected22082026/10/27 13:03:40 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=02209=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured22102026/10/27 13:03:40 INFO Vacuumed table table=pending_closures2211=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected22122026/10/27 13:03:40 WARN Authentication failed token_preview=eyJhbGciOi...4NroVxawrA token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]22132026/10/27 13:03:40 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]22142026/10/27 13:03:40 INFO Vacuumed table table=pending_objects22152026/10/27 13:03:40 INFO Vacuumed table table=multipart_uploads22162026/10/27 13:03:40 INFO Vacuumed table table=closures22172026/10/27 13:03:40 INFO Received uploads request method=POST path=/api/pending_closures22182026/10/27 13:03:40 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"22192026/10/27 13:03:40 INFO Vacuumed table table=objects22202026/10/27 13:03:40 INFO Aborted multipart uploads count=0 kept=02221--- PASS: TestService_AuthMiddleware_OIDC (0.46s)2222 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2223 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2224 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)2225 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)22262026/10/27 13:03:40 WARN Force mode enabled - objects will be deleted immediately without grace period2227--- PASS: TestService_RequireScope_OIDC (0.34s)2228 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2229 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)2230 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2231 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)2232 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)2233 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)2234 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2235 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2236 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2237 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2238 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2239 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2240 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2241 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)22422026/10/27 13:03:40 INFO Received uploads request method=POST path=/api/pending_closures22432026/10/27 13:03:40 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=022442026/10/27 13:03:40 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"22452026/10/27 13:03:40 INFO Vacuumed table table=pending_closures22462026/10/27 13:03:40 INFO Vacuumed table table=pending_objects22472026/10/27 13:03:40 INFO Vacuumed table table=multipart_uploads22482026/10/27 13:03:40 INFO Vacuumed table table=closures22492026/10/27 13:03:40 INFO Vacuumed table table=objects22502026/10/27 13:03:40 INFO Received uploads request method=POST path=/api/pending_closures22512026/10/27 13:03:40 INFO Received complete push request method=POST path=/api/pushes/4/complete22522026-10-27 13:03:40.947 UTC [1057] ERROR: Push does not exist: id=422532026-10-27 13:03:40.947 UTC [1057] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE22542026-10-27 13:03:40.947 UTC [1057] STATEMENT: -- name: CommitPush :one2255 SELECT commit_push($1::bigint)::bigint2256 22572026/10/27 13:03:40 WARN Push not found id=422582026/10/27 13:03:40 INFO Upload complete. (186ms)2259=== NAME TestClientIntegration2260 client_integration_test.go:422: Retrieved narinfo from S3:2261 StorePath: /build/TestClientIntegration388782499/002/store/qnv0x0kj83n411cp0n4j2q2frxf59knn-lost-commit.txt2262 URL: nar/04d5klw9iix884nk82y7nlkps8afh2bg119y7zkvcf1pc1x2y2jl.nar.zst2263 Compression: zstd2264 NarHash: sha256:04d5klw9iix884nk82y7nlkps8afh2bg119y7zkvcf1pc1x2y2jl2265 NarSize: 1522266 References: 2267 CA: fixed:r:sha256:04d5klw9iix884nk82y7nlkps8afh2bg119y7zkvcf1pc1x2y2jl2268 client_integration_test.go:425: Testing garbage collection...2269--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2270 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (0.24s)2271 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (0.28s)22722026/10/27 13:03:40 INFO Starting cleanup of old closures method=DELETE path=/api/closures22732026/10/27 13:03:40 INFO Garbage collection started22742026/10/27 13:03:40 INFO Aborted multipart uploads count=0 kept=022752026/10/27 13:03:41 WARN Force mode enabled - objects will be deleted immediately without grace period22762026/10/27 13:03:41 WARN Request failed, retrying attempt=3 backoff=386.857073ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present22772026/10/27 13:03:41 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22782026/10/27 13:03:41 INFO Completed multipart upload object_key=nar/dddddddddddddddddddddddddddddddd00000000000000000000.nar.zst upload_id=MWYwZWQ5MzQtMzk0OC00NzkxLWFmMzAtMTMwN2E1NTgzMDY2LjcxNTg0YTI1LTg5MzgtNDdjYS1hZWZhLThkZTNhMmNjYjZmYXgxNzkzMTA2MjE4MzAyMzgzNDc5 parts=1022792026/10/27 13:03:41 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=022802026/10/27 13:03:41 INFO Vacuumed table table=pending_closures22812026/10/27 13:03:41 INFO Vacuumed table table=pending_objects22822026/10/27 13:03:41 INFO Vacuumed table table=multipart_uploads22832026/10/27 13:03:41 INFO Vacuumed table table=closures22842026/10/27 13:03:41 INFO Vacuumed table table=objects2285--- PASS: TestDeleteClosuresRacingPins (1.50s)2286--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2287 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (0.77s)2288 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (0.74s)22892026/10/27 13:03:41 WARN Request failed, retrying attempt=4 backoff=877.639537ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present22902026/10/27 13:03:41 WARN Rate limiter enabled after throttle name=s3-test rate=522912026/10/27 13:03:41 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."2292=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle2293 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=102294 throttle_test.go:215: Rate limiter: enabled=true, rate=5.0022952026/10/27 13:03:41 WARN Failed to abort multipart upload key=nar/ssssssssssssssssssssssssssssssssssssssssssssssssssss.nar.zst upload_id=MWYwZWQ5MzQtMzk0OC00NzkxLWFmMzAtMTMwN2E1NTgzMDY2LjNiNTliZWM5LTBjNWItNDRjZC1iY2IwLWUxM2FkMWZjYWE2ZXgxNzkzMTA2MjIwOTA4NDcxMjQy error="Access Denied"22962026/10/27 13:03:41 WARN keeping failed pending closure for cleanup to retry the abort id=12297--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (3.97s)2298--- PASS: TestPendingClosureWriteTimeout (0.01s)2299 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2300 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2301 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2302 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (1.07s)2303--- PASS: TestPendingClosureFailureTracksEveryUpload (0.00s)2304 --- PASS: TestPendingClosureFailureTracksEveryUpload/refuse_aborts=true (0.70s)2305 --- PASS: TestPendingClosureFailureTracksEveryUpload/refuse_aborts=false (0.73s)23062026/10/27 13:03:41 INFO Received complete multipart upload request method=POST path=/api/multipart/complete23072026/10/27 13:03:41 INFO Completed multipart upload object_key=nar/ffffffffffffffffffffffffffffffff00000000000000000000.nar.zst upload_id=MWYwZWQ5MzQtMzk0OC00NzkxLWFmMzAtMTMwN2E1NTgzMDY2LjEzZmRlOWI5LTg4M2QtNGJkNy1hNzlkLWYwZjIxMTAwMmY5N3gxNzkzMTA2MjE4MzAyNTgzMTM5 parts=1023082026-10-27 13:03:41.639 UTC [515] ERROR: could not obtain lock on row in relation "closures"23092026-10-27 13:03:41.639 UTC [515] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT23102026-10-27 13:03:41.639 UTC [515] ERROR: could not obtain lock on row in relation "closures"23112026-10-27 13:03:41.639 UTC [515] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT23122026-10-27 13:03:41.640 UTC [515] ERROR: could not obtain lock on row in relation "closures"23132026-10-27 13:03:41.640 UTC [515] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT23142026-10-27 13:03:41.640 UTC [515] ERROR: could not obtain lock on row in relation "closures"23152026-10-27 13:03:41.640 UTC [515] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT23162026-10-27 13:03:41.641 UTC [515] ERROR: could not obtain lock on row in relation "closures"23172026-10-27 13:03:41.641 UTC [515] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT23182026/10/27 13:03:41 INFO lead: released remote=192.0.2.1:12342319=== NAME TestOrphanedObjectsGCStressTest2320 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains2321--- PASS: TestPush_RootsAreLockedInByteOrder (4.21s)2322--- PASS: TestLeadElectsOneAndHandsOver (2.61s)2323=== NAME TestOrphanedObjectsGCStressTest2324 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion23252026/10/27 13:03:42 WARN Request failed, retrying attempt=5 backoff=1.713460499s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present23262026/10/27 13:03:42 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=023272026/10/27 13:03:42 INFO Received create pin request method=POST path=/api/pins/myapp23282026/10/27 13:03:42 INFO Created/updated pin name=myapp store_path=/build/TestPinProtectsFromGC2045624380/001/store/lmv12kjgv285b73c3pjk0ank72vzzvmj-pinned-file.txt narinfo_key=lmv12kjgv285b73c3pjk0ank72vzzvmj.narinfo23292026/10/27 13:03:42 INFO Starting cleanup of old closures method=DELETE path=/api/closures23302026/10/27 13:03:42 INFO Garbage collection started23312026/10/27 13:03:42 INFO Aborted multipart uploads count=0 kept=023322026/10/27 13:03:42 WARN Force mode enabled - objects will be deleted immediately without grace period23332026/10/27 13:03:42 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=023342026/10/27 13:03:42 INFO Vacuumed table table=pending_closures23352026/10/27 13:03:42 INFO Vacuumed table table=pending_objects23362026/10/27 13:03:42 INFO Vacuumed table table=multipart_uploads23372026/10/27 13:03:42 INFO Vacuumed table table=closures23382026/10/27 13:03:42 INFO Vacuumed table table=objects2339 orphaned_objects_gc_test.go:503: Stress test completed successfully:2340 orphaned_objects_gc_test.go:504: - Active objects preserved: 202341 orphaned_objects_gc_test.go:505: - Objects deleted: 2102342 orphaned_objects_gc_test.go:506: - Total GC'd: 2102343--- PASS: TestOrphanedObjectsGCStressTest (3.64s)23442026/10/27 13:03:42 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=2 objects_marked=6 objects_deleted=6 objects_failed=02345=== NAME TestClientIntegration2346 client_integration_test.go:432: Objects in database after GC:2347 client_integration_test.go:432: Successfully deleted all objects with GC --force2348--- PASS: TestClientIntegration (3.05s)2349--- PASS: TestReadProxyOutlastsServerWriteTimeout (4.76s)23502026/10/27 13:03:44 WARN Request failed, retrying attempt=1 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config23512026/10/27 13:03:44 WARN Request failed, retrying attempt=2 backoff=203.642092ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config23522026/10/27 13:03:44 WARN Request failed, retrying attempt=3 backoff=393.683284ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config23532026/10/27 13:03:44 INFO Aborted multipart uploads count=1 kept=02354--- PASS: TestConnectWaitsForAPeerMigration (5.14s)23552026/10/27 13:03:44 INFO Received cleanup request method=DELETE path=/api/pending_closures23562026/10/27 13:03:44 INFO Aborted multipart uploads count=1 kept=02357--- PASS: TestPendingCleanupUsesOneCutoff (6.97s)2358=== NAME TestPinProtectsFromGC2359 client_integration_test.go:963: Pin successfully protected closure from garbage collection2360--- PASS: TestPinProtectsFromGC (4.70s)23612026/10/27 13:03:44 WARN Request failed, retrying attempt=4 backoff=877.988262ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config23622026/10/27 13:03:45 WARN Request failed, retrying attempt=5 backoff=1.677652759s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2363--- PASS: TestUploadHandlersRejectOversizedBody (0.35s)2364 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.59s)2365 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.60s)2366 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (5.96s)23672026/10/27 13:03:47 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"23682026/10/27 13:03:47 WARN Request failed, retrying attempt=1 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config23692026/10/27 13:03:47 WARN Request failed, retrying attempt=2 backoff=215.057003ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config23702026/10/27 13:03:47 WARN Request failed, retrying attempt=3 backoff=388.066788ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config23712026/10/27 13:03:48 WARN Request failed, retrying attempt=4 backoff=850.681623ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config23722026/10/27 13:03:48 WARN Request failed, retrying attempt=5 backoff=1.577166811s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config23732026/10/27 13:03:50 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures23742026/10/27 13:03:50 WARN Request failed, retrying attempt=2 backoff=202.667669ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures23752026/10/27 13:03:50 WARN Request failed, retrying attempt=3 backoff=366.892483ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures23762026/10/27 13:03:51 WARN Request failed, retrying attempt=4 backoff=773.029808ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures23772026/10/27 13:03:51 WARN Request failed, retrying attempt=5 backoff=1.519559548s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2378--- PASS: TestClientErrorHandling (0.00s)2379 --- PASS: TestClientErrorHandling/InvalidStorePath (0.31s)2380 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.37s)2381 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.80s)2382PASS2383{"timestamp":"2026-10-27T13:03:53.424936942Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:49192","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(130)"}2384{"timestamp":"2026-10-27T13:03:53.425330262Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:49198","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(131)"}2385{"timestamp":"2026-10-27T13:03:53.425466732Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:49334","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(139)"}23862026-10-27 13:03:53.698 UTC [172] LOG: received smart shutdown request23872026-10-27 13:03:53.703 UTC [172] LOG: background worker "logical replication launcher" (PID 182) exited with exit code 123882026-10-27 13:03:54.959 UTC [177] LOG: checkpoint complete: wrote 10398 buffers (63.5%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 33 recycled; write=13.070 s, sync=1.032 s, total=14.159 s; sync files=37078, longest=0.001 s, average=0.001 s; distance=533390 kB, estimate=533390 kB; lsn=0/22A7D788, redo lsn=0/2204952823892026-10-27 13:03:54.961 UTC [177] LOG: shutting down23902026-10-27 13:03:54.962 UTC [177] LOG: checkpoint starting: shutdown immediate23912026-10-27 13:03:55.020 UTC [177] LOG: checkpoint complete: wrote 328 buffers (2.0%), wrote 1 SLRU buffers; 0 WAL file(s) added, 0 removed, 0 recycled; write=0.007 s, sync=0.049 s, total=0.059 s; sync files=213, longest=0.001 s, average=0.001 s; distance=10448 kB, estimate=481095 kB; lsn=0/22A7D800, redo lsn=0/22A7D80023922026-10-27 13:03:55.088 UTC [172] LOG: database system is shut down2393Running OIDC tests...2394=== RUN TestAudienceForIssuer2395=== PAUSE TestAudienceForIssuer2396=== RUN TestHTTPClientForHasTimeouts2397=== PAUSE TestHTTPClientForHasTimeouts2398=== RUN TestGlobMatch2399=== PAUSE TestGlobMatch2400=== RUN TestValidateToken_ValidToken2401=== PAUSE TestValidateToken_ValidToken2402=== RUN TestValidateToken_WrongAudience2403=== PAUSE TestValidateToken_WrongAudience2404=== RUN TestValidateToken_Expired2405=== PAUSE TestValidateToken_Expired2406=== RUN TestValidateToken_BoundClaimsMismatch2407=== PAUSE TestValidateToken_BoundClaimsMismatch2408=== RUN TestValidateToken_BoundSubjectMismatch2409=== PAUSE TestValidateToken_BoundSubjectMismatch2410=== RUN TestValidateToken_MultipleProviders2411=== PAUSE TestValidateToken_MultipleProviders2412=== RUN TestValidateToken_NoMatchingProvider2413=== PAUSE TestValidateToken_NoMatchingProvider2414=== RUN TestValidateToken_KubernetesServiceAccount2415=== PAUSE TestValidateToken_KubernetesServiceAccount2416=== RUN TestNewValidator_KubernetesRequiresCA2417=== PAUSE TestNewValidator_KubernetesRequiresCA2418=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2419=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2420=== RUN TestPins_ReservedForMatchingRule2421=== PAUSE TestPins_ReservedForMatchingRule2422=== RUN TestPins_TopLevelShorthand2423=== PAUSE TestPins_TopLevelShorthand2424=== RUN TestPins_ConfigValidation2425=== PAUSE TestPins_ConfigValidation2426=== RUN TestScopes_LegacyProviderDefaultsToWrite2427=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2428=== RUN TestScopes_Rules2429=== PAUSE TestScopes_Rules2430=== RUN TestScopes_ConfigValidation2431=== PAUSE TestScopes_ConfigValidation2432=== CONT TestHTTPClientForHasTimeouts2433=== CONT TestValidateToken_Expired2434=== CONT TestValidateToken_MultipleProviders2435=== CONT TestValidateToken_KubernetesServiceAccount2436=== CONT TestScopes_ConfigValidation2437=== CONT TestScopes_Rules2438=== CONT TestPins_ConfigValidation2439=== CONT TestScopes_LegacyProviderDefaultsToWrite2440=== CONT TestPins_ReservedForMatchingRule2441=== CONT TestPins_TopLevelShorthand2442=== CONT TestNewValidator_KubernetesRequiresCA2443=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2444=== CONT TestValidateToken_NoMatchingProvider2445=== CONT TestGlobMatch2446=== CONT TestValidateToken_ValidToken2447=== RUN TestGlobMatch/foo_foo2448=== PAUSE TestGlobMatch/foo_foo2449=== CONT TestValidateToken_BoundSubjectMismatch2450=== CONT TestValidateToken_WrongAudience2451=== CONT TestValidateToken_BoundClaimsMismatch2452=== CONT TestAudienceForIssuer2453--- PASS: TestScopes_ConfigValidation (0.00s)2454--- PASS: TestPins_ConfigValidation (0.00s)2455--- PASS: TestAudienceForIssuer (0.00s)2456=== RUN TestGlobMatch/foo_bar2457=== PAUSE TestGlobMatch/foo_bar2458=== RUN TestGlobMatch/*_2459=== PAUSE TestGlobMatch/*_2460=== RUN TestGlobMatch/*_anything2461=== PAUSE TestGlobMatch/*_anything2462=== RUN TestGlobMatch/foo*_foo2463=== PAUSE TestGlobMatch/foo*_foo2464=== RUN TestGlobMatch/foo*_foobar2465=== PAUSE TestGlobMatch/foo*_foobar2466=== RUN TestGlobMatch/foo*_bar2467=== PAUSE TestGlobMatch/foo*_bar2468=== RUN TestGlobMatch/*bar_bar2469=== PAUSE TestGlobMatch/*bar_bar2470=== RUN TestGlobMatch/*bar_foobar2471=== PAUSE TestGlobMatch/*bar_foobar2472=== RUN TestGlobMatch/*bar_foo2473=== PAUSE TestGlobMatch/*bar_foo2474=== RUN TestGlobMatch/foo*bar_foobar2475=== PAUSE TestGlobMatch/foo*bar_foobar2476=== RUN TestGlobMatch/foo*bar_foo123bar2477=== PAUSE TestGlobMatch/foo*bar_foo123bar2478=== RUN TestGlobMatch/foo*bar_foobarbaz2479=== PAUSE TestGlobMatch/foo*bar_foobarbaz2480=== RUN TestGlobMatch/*/*_foo/bar2481=== PAUSE TestGlobMatch/*/*_foo/bar2482=== RUN TestGlobMatch/*/*_foo2483=== PAUSE TestGlobMatch/*/*_foo2484=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2485=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2486=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02487=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02488=== RUN TestGlobMatch/refs/*/main_refs/heads/main2489=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2490=== RUN TestGlobMatch/fo?_foo2491=== PAUSE TestGlobMatch/fo?_foo2492=== RUN TestGlobMatch/fo?_fo2493=== PAUSE TestGlobMatch/fo?_fo2494=== RUN TestGlobMatch/fo?_fooo2495=== PAUSE TestGlobMatch/fo?_fooo2496=== RUN TestGlobMatch/?oo_foo2497=== PAUSE TestGlobMatch/?oo_foo2498=== RUN TestGlobMatch/?oo_boo2499=== PAUSE TestGlobMatch/?oo_boo2500=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2501=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2502=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2503=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2504=== CONT TestGlobMatch/foo_bar2505=== CONT TestGlobMatch/foo*_bar2506=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2507=== CONT TestGlobMatch/*/*_foo/bar2508=== CONT TestGlobMatch/foo*bar_foobarbaz2509=== CONT TestGlobMatch/foo*_foo2510=== CONT TestGlobMatch/fo?_foo2511=== CONT TestGlobMatch/foo*bar_foo123bar2512=== CONT TestGlobMatch/refs/*/main_refs/heads/main2513=== CONT TestGlobMatch/?oo_boo2514=== CONT TestGlobMatch/fo?_fooo2515=== CONT TestGlobMatch/*_anything2516=== CONT TestGlobMatch/?oo_foo2517=== CONT TestGlobMatch/fo?_fo2518=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2519=== CONT TestGlobMatch/foo_foo2520=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02521=== CONT TestGlobMatch/*bar_foo2522=== CONT TestGlobMatch/foo*bar_foobar2523=== CONT TestGlobMatch/foo*_foobar2524=== CONT TestGlobMatch/*bar_foobar2525=== CONT TestGlobMatch/*_2526=== CONT TestGlobMatch/*/*_foo2527=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2528=== CONT TestGlobMatch/*bar_bar2529--- PASS: TestGlobMatch (0.01s)2530 --- PASS: TestGlobMatch/foo_bar (0.00s)2531 --- PASS: TestGlobMatch/foo*_bar (0.00s)2532 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2533 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2534 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2535 --- PASS: TestGlobMatch/foo*_foo (0.00s)2536 --- PASS: TestGlobMatch/fo?_foo (0.00s)2537 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2538 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2539 --- PASS: TestGlobMatch/?oo_boo (0.00s)2540 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2541 --- PASS: TestGlobMatch/*_anything (0.00s)2542 --- PASS: TestGlobMatch/?oo_foo (0.00s)2543 --- PASS: TestGlobMatch/fo?_fo (0.00s)2544 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2545 --- PASS: TestGlobMatch/foo_foo (0.00s)2546 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2547 --- PASS: TestGlobMatch/*bar_foo (0.00s)2548 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2549 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2550 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2551 --- PASS: TestGlobMatch/*_ (0.00s)2552 --- PASS: TestGlobMatch/*/*_foo (0.00s)2553 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2554 --- PASS: TestGlobMatch/*bar_bar (0.00s)25552026/10/27 13:03:58 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:35985/oidc2556--- PASS: TestScopes_Rules (0.03s)25572026/10/27 13:03:58 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:45679/oidc25582026/10/27 13:03:58 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:35099/oidc2559--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.05s)25602026/10/27 13:03:58 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:34279/oidc2561--- PASS: TestValidateToken_BoundClaimsMismatch (0.05s)2562--- PASS: TestPins_TopLevelShorthand (0.06s)25632026/10/27 13:03:58 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:36481/oidc2564--- PASS: TestValidateToken_WrongAudience (0.06s)25652026/10/27 13:03:58 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:46107/oidc2566--- PASS: TestValidateToken_BoundSubjectMismatch (0.08s)25672026/10/27 13:03:58 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC12325682026/10/27 13:03:58 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:37373/oidc2569--- PASS: TestPins_ReservedForMatchingRule (0.09s)2570--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.09s)25712026/10/27 13:03:58 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:35217/oidc2572--- PASS: TestValidateToken_NoMatchingProvider (0.11s)25732026/10/27 13:03:58 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:41539/oidc25742026/10/27 13:03:58 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:42475/oidc25752026/10/27 13:03:58 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:45867/oidc2576--- PASS: TestValidateToken_MultipleProviders (0.15s)25772026/10/27 13:03:58 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:417152578--- PASS: TestValidateToken_ValidToken (0.15s)2579--- PASS: TestValidateToken_KubernetesServiceAccount (0.16s)25802026/10/27 13:03:58 http: TLS handshake error from 127.0.0.1:55442: remote error: tls: bad certificate2581--- PASS: TestNewValidator_KubernetesRequiresCA (0.16s)25822026/10/27 13:03:58 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:33487/oidc2583--- PASS: TestValidateToken_Expired (0.25s)2584--- PASS: TestHTTPClientForHasTimeouts (0.41s)2585PASS2586Running hook tests...2587=== RUN TestSendPathsEmpty2588=== PAUSE TestSendPathsEmpty2589=== RUN TestQueueEnqueueAndFetch2590=== PAUSE TestQueueEnqueueAndFetch2591=== RUN TestQueueDeduplication2592=== PAUSE TestQueueDeduplication2593=== RUN TestQueueRemove2594=== PAUSE TestQueueRemove2595=== RUN TestQueueFetchBatchLimit2596=== PAUSE TestQueueFetchBatchLimit2597=== RUN TestQueueRetryMovesToBack2598=== PAUSE TestQueueRetryMovesToBack2599=== RUN TestQueueFetchRemoveLifecycle2600=== PAUSE TestQueueFetchRemoveLifecycle2601=== RUN TestQueueConcurrentWriters2602=== PAUSE TestQueueConcurrentWriters2603=== RUN TestQueueRemoveLargeClosure2604=== PAUSE TestQueueRemoveLargeClosure2605=== RUN TestServerClientIntegration2606--- PASS: TestServerClientIntegration (0.00s)2607=== RUN TestServerQueueError26082026/10/27 13:03:59 ERROR Failed to queue paths error="permission denied" count=12609--- PASS: TestServerQueueError (0.00s)2610=== RUN TestServerRefusesOversizedAndNonStoreRequests2611=== PAUSE TestServerRefusesOversizedAndNonStoreRequests2612=== RUN TestGetListenerSocketActivation2613 server_test.go:309: === RUN TestGetListenerSocketActivation2614 --- PASS: TestGetListenerSocketActivation (0.00s)2615 PASS2616 2617--- PASS: TestGetListenerSocketActivation (1.02s)2618=== RUN TestServerStalledClientDoesNotBlockShutdown2619=== PAUSE TestServerStalledClientDoesNotBlockShutdown2620=== RUN TestServerBacksOffOnAcceptErrors2621=== PAUSE TestServerBacksOffOnAcceptErrors2622=== RUN TestDrainIsolatesPoisonPath2623=== PAUSE TestDrainIsolatesPoisonPath2624=== RUN TestRunNotBlockedByPoisonHead2625=== PAUSE TestRunNotBlockedByPoisonHead2626=== RUN TestDrainGivesUpWhenServerDown2627=== PAUSE TestDrainGivesUpWhenServerDown2628=== RUN TestFailedPathPrunedByLaterClosure2629=== PAUSE TestFailedPathPrunedByLaterClosure2630=== RUN TestWorkerUploadsAndRemoves2631=== PAUSE TestWorkerUploadsAndRemoves2632=== RUN TestWorkerSkipsGCdPaths2633=== PAUSE TestWorkerSkipsGCdPaths2634=== RUN TestWorkerPrunesClosureDeps2635=== PAUSE TestWorkerPrunesClosureDeps2636=== RUN TestWorkerRemovesCachedPathBatchedWithLargerClosure2637=== PAUSE TestWorkerRemovesCachedPathBatchedWithLargerClosure2638=== RUN TestDrainTimeout2639=== PAUSE TestDrainTimeout2640=== RUN TestDrainTimeoutDuringIsolation2641=== PAUSE TestDrainTimeoutDuringIsolation2642=== RUN TestShutdownFinishesInFlightPush2643=== PAUSE TestShutdownFinishesInFlightPush2644=== RUN TestWorkerRemoveFailureIsNotProgress2645=== PAUSE TestWorkerRemoveFailureIsNotProgress2646=== RUN TestWorkerKeepsPathItCannotStat2647=== PAUSE TestWorkerKeepsPathItCannotStat2648=== CONT TestSendPathsEmpty2649=== CONT TestFailedPathPrunedByLaterClosure2650=== CONT TestWorkerUploadsAndRemoves2651=== CONT TestQueueFetchRemoveLifecycle2652=== CONT TestWorkerRemoveFailureIsNotProgress2653=== CONT TestShutdownFinishesInFlightPush2654=== CONT TestWorkerKeepsPathItCannotStat2655=== CONT TestDrainTimeout2656=== CONT TestWorkerRemovesCachedPathBatchedWithLargerClosure2657=== CONT TestServerRefusesOversizedAndNonStoreRequests2658=== CONT TestServerBacksOffOnAcceptErrors2659=== CONT TestDrainIsolatesPoisonPath26602026/10/27 13:04:00 ERROR Accept failed error="too many open files"2661=== CONT TestQueueRemoveLargeClosure2662=== CONT TestWorkerSkipsGCdPaths2663=== CONT TestServerStalledClientDoesNotBlockShutdown2664=== CONT TestQueueRemove2665=== CONT TestQueueRetryMovesToBack26662026/10/27 13:04:00 ERROR Refusing path outside the store path=/etc/shadow store=/nix/store2667--- PASS: TestSendPathsEmpty (0.00s)2668=== CONT TestQueueFetchBatchLimit2669=== CONT TestQueueConcurrentWriters2670=== CONT TestQueueEnqueueAndFetch26712026/10/27 13:04:00 ERROR Refusing path outside the store path=/nix/store store=/nix/store2672=== CONT TestQueueDeduplication2673=== CONT TestDrainTimeoutDuringIsolation2674=== CONT TestWorkerPrunesClosureDeps2675=== RUN TestDrainTimeoutDuringIsolation/probe_cut_short2676=== CONT TestDrainGivesUpWhenServerDown26772026/10/27 13:04:00 ERROR Refusing path outside the store path=/nix/store/ store=/nix/store2678=== CONT TestRunNotBlockedByPoisonHead2679=== RUN TestShutdownFinishesInFlightPush/completes26802026/10/27 13:04:00 ERROR Refusing path outside the store path=/nix/store/../../etc/shadow store=/nix/store2681=== RUN TestWorkerRemoveFailureIsNotProgress/collected_path2682=== PAUSE TestDrainTimeoutDuringIsolation/probe_cut_short2683=== PAUSE TestWorkerRemoveFailureIsNotProgress/collected_path2684=== PAUSE TestShutdownFinishesInFlightPush/completes2685=== RUN TestWorkerRemoveFailureIsNotProgress/pushed_batch2686=== RUN TestShutdownFinishesInFlightPush/hung_push_bounded_by_the_drain_timeout2687=== RUN TestDrainTimeoutDuringIsolation/probe_outlasts_the_deadline26882026/10/27 13:04:00 ERROR Refusing path outside the store path=/nix/store/0123456789abcdfghijklmnpqrsvwxyz-hello/bin/sh store=/nix/store2689=== PAUSE TestWorkerRemoveFailureIsNotProgress/pushed_batch2690=== PAUSE TestShutdownFinishesInFlightPush/hung_push_bounded_by_the_drain_timeout2691=== PAUSE TestDrainTimeoutDuringIsolation/probe_outlasts_the_deadline2692=== CONT TestShutdownFinishesInFlightPush/completes2693=== RUN TestWorkerRemoveFailureIsNotProgress/isolated_paths2694=== CONT TestShutdownFinishesInFlightPush/hung_push_bounded_by_the_drain_timeout26952026/10/27 13:04:00 ERROR Refusing path outside the store path=nix/store/0123456789abcdfghijklmnpqrsvwxyz-hello store=/nix/store2696=== PAUSE TestWorkerRemoveFailureIsNotProgress/isolated_paths2697=== CONT TestDrainTimeoutDuringIsolation/probe_cut_short26982026/10/27 13:04:00 ERROR Refusing path outside the store path=/nix/storeX/0123456789abcdfghijklmnpqrsvwxyz-hello store=/nix/store26992026/10/27 13:04:00 ERROR Refusing path outside the store path=/nix/store/.links store=/nix/store27002026/10/27 13:04:00 ERROR Refusing path outside the store path=/nix/store/aaa-hello store=/nix/store27012026/10/27 13:04:00 ERROR Refusing path outside the store path=/nix/store/0123456789abcdfghijklmnpqrsvwxyz store=/nix/store27022026/10/27 13:04:00 ERROR Accept failed error="too many open files"27032026/10/27 13:04:00 ERROR Refusing path outside the store path=/nix/store/0123456789abcdfghijklmnpqrsvwxyz- store=/nix/store27042026/10/27 13:04:00 ERROR Refusing path outside the store path=/nix/store/0123456789ebcdfghijklmnpqrsvwxyz-hello store=/nix/store27052026/10/27 13:04:00 ERROR Refusing path outside the store path="/nix/store/0123456789abcdfghijklmnpqrsvwxyz-hel\x00lo" store=/nix/store27062026/10/27 13:04:00 ERROR Refusing path outside the store path=/nix/store/0123456789abcdfghijklmnpqrsvwxyz-hel/lo store=/nix/store27072026/10/27 13:04:00 ERROR Refusing path outside the store path=/nix/store/0123456789abcdfghijklmnpqrsvwxyz-xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx store=/nix/store27082026/10/27 13:04:00 ERROR Failed to decode request error="unexpected EOF"2709--- PASS: TestServerRefusesOversizedAndNonStoreRequests (0.01s)2710=== CONT TestDrainTimeoutDuringIsolation/probe_outlasts_the_deadline27112026/10/27 13:04:00 ERROR Accept failed error="too many open files"27122026/10/27 13:04:00 ERROR Accept failed error="too many open files"27132026/10/27 13:04:00 INFO Upload queue status pending=327142026/10/27 13:04:00 INFO Upload queue status pending=327152026/10/27 13:04:00 INFO Uploading batch count=127162026/10/27 13:04:00 ERROR Upload failed error="upload failed" count=127172026/10/27 13:04:00 INFO Uploading batch count=427182026/10/27 13:04:00 ERROR Upload failed error="upload failed" count=427192026/10/27 13:04:00 INFO Uploading batch count=127202026/10/27 13:04:00 ERROR Upload failed error="upload failed" count=127212026/10/27 13:04:00 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerSkipsGCdPaths1988534292/002/nonexistent27222026/10/27 13:04:00 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainIsolatesPoisonPath2791420506/002/bbb27232026/10/27 13:04:00 INFO Upload queue status pending=227242026/10/27 13:04:00 INFO Upload queue status pending=22725--- PASS: TestQueueEnqueueAndFetch (0.05s)27262026/10/27 13:04:00 INFO Uploading batch count=22727=== CONT TestWorkerRemoveFailureIsNotProgress/collected_path27282026/10/27 13:04:00 INFO Uploading batch count=227292026/10/27 13:04:00 INFO Uploading batch count=227302026/10/27 13:04:00 ERROR Upload failed error="upload failed" count=227312026/10/27 13:04:00 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown356861081/002/a27322026/10/27 13:04:00 INFO Uploading batch count=227332026/10/27 13:04:00 INFO Uploading batch count=127342026/10/27 13:04:00 INFO Uploading batch count=22735--- PASS: TestQueueFetchRemoveLifecycle (0.06s)2736=== CONT TestWorkerRemoveFailureIsNotProgress/isolated_paths27372026/10/27 13:04:00 INFO Upload queue status pending=227382026/10/27 13:04:00 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat3171042013/002/locked/aaa error="lstat /build/TestWorkerKeepsPathItCannotStat3171042013/002/locked/aaa: permission denied"27392026/10/27 13:04:00 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown356861081/002/b27402026/10/27 13:04:00 INFO Uploading batch count=22741--- PASS: TestQueueRemove (0.06s)2742=== CONT TestWorkerRemoveFailureIsNotProgress/pushed_batch27432026/10/27 13:04:00 INFO Upload queue status pending=227442026/10/27 13:04:00 INFO Uploading batch count=127452026/10/27 13:04:00 INFO Upload queue status pending=22746--- PASS: TestQueueFetchBatchLimit (0.06s)27472026/10/27 13:04:00 INFO Uploading batch count=427482026/10/27 13:04:00 ERROR Upload failed error="upload failed" count=427492026/10/27 13:04:00 INFO Uploading batch count=227502026/10/27 13:04:00 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat3171042013/002/locked/aaa error="lstat /build/TestWorkerKeepsPathItCannotStat3171042013/002/locked/aaa: permission denied"27512026/10/27 13:04:00 INFO Uploading batch count=127522026/10/27 13:04:00 INFO Uploading batch count=227532026/10/27 13:04:00 INFO Uploading batch count=42754--- PASS: TestQueueDeduplication (0.06s)27552026/10/27 13:04:00 ERROR Upload failed error="upload failed" count=227562026/10/27 13:04:00 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown356861081/002/c27572026/10/27 13:04:00 ERROR Upload failed error="upload failed" count=42758--- PASS: TestQueueRetryMovesToBack (0.06s)27592026/10/27 13:04:00 INFO Uploading batch count=127602026/10/27 13:04:00 ERROR Upload failed error="upload failed" count=127612026/10/27 13:04:00 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown356861081/002/d27622026/10/27 13:04:00 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat3171042013/002/locked/aaa error="lstat /build/TestWorkerKeepsPathItCannotStat3171042013/002/locked/aaa: permission denied"27632026/10/27 13:04:00 ERROR Drain finished with paths left in queue remaining=127642026/10/27 13:04:00 INFO Uploading batch count=227652026/10/27 13:04:00 ERROR Upload failed error="upload failed" count=227662026/10/27 13:04:00 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown356861081/002/e2767--- PASS: TestFailedPathPrunedByLaterClosure (0.07s)27682026/10/27 13:04:00 INFO Uploading batch count=127692026/10/27 13:04:00 ERROR Upload failed error="upload failed" count=127702026/10/27 13:04:00 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown356861081/002/f2771--- PASS: TestWorkerKeepsPathItCannotStat (0.07s)2772--- PASS: TestWorkerSkipsGCdPaths (0.07s)27732026/10/27 13:04:00 INFO Uploading batch count=127742026/10/27 13:04:00 ERROR Drain finished with paths left in queue remaining=1027752026/10/27 13:04:00 ERROR Upload failed error="upload failed" count=12776--- PASS: TestWorkerRemovesCachedPathBatchedWithLargerClosure (0.08s)27772026/10/27 13:04:00 ERROR Accept failed error="too many open files"2778--- PASS: TestDrainGivesUpWhenServerDown (0.07s)27792026/10/27 13:04:00 ERROR Drain finished with paths left in queue remaining=12780--- PASS: TestDrainIsolatesPoisonPath (0.08s)27812026/10/27 13:04:00 INFO Uploading batch count=227822026/10/27 13:04:00 ERROR Upload failed error="upload failed" count=22783--- PASS: TestWorkerUploadsAndRemoves (0.08s)27842026/10/27 13:04:00 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=127852026/10/27 13:04:00 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=127862026/10/27 13:04:00 INFO Uploading batch count=227872026/10/27 13:04:00 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgresscollected_path1923281775/001/nonexistent27882026/10/27 13:04:00 ERROR Upload failed error="upload failed" count=227892026/10/27 13:04:00 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=127902026/10/27 13:04:00 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=127912026/10/27 13:04:00 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=127922026/10/27 13:04:00 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgresscollected_path1923281775/001/nonexistent27932026/10/27 13:04:00 INFO Uploading batch count=227942026/10/27 13:04:00 ERROR Upload failed error="upload failed" count=227952026/10/27 13:04:00 INFO Uploading batch count=227962026/10/27 13:04:00 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=127972026/10/27 13:04:00 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=127982026/10/27 13:04:00 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=227992026/10/27 13:04:00 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=128002026/10/27 13:04:00 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgresscollected_path1923281775/001/nonexistent28012026/10/27 13:04:00 ERROR Drain finished with paths left in queue remaining=228022026/10/27 13:04:00 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=128032026/10/27 13:04:00 INFO Uploading batch count=22804--- PASS: TestWorkerPrunesClosureDeps (0.09s)28052026/10/27 13:04:00 ERROR Drain finished with paths left in queue remaining=128062026/10/27 13:04:00 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=228072026/10/27 13:04:00 INFO Uploading batch count=228082026/10/27 13:04:00 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=228092026/10/27 13:04:00 ERROR Drain finished with paths left in queue remaining=22810--- PASS: TestWorkerRemoveFailureIsNotProgress (0.00s)2811 --- PASS: TestWorkerRemoveFailureIsNotProgress/isolated_paths (0.03s)2812 --- PASS: TestWorkerRemoveFailureIsNotProgress/collected_path (0.03s)2813 --- PASS: TestWorkerRemoveFailureIsNotProgress/pushed_batch (0.03s)28142026/10/27 13:04:01 ERROR Accept failed error="too many open files"28152026/10/27 13:04:01 ERROR Failed to decode request error="read unix /build/hook2557974317/test.sock->@: i/o timeout"28162026/10/27 13:04:01 ERROR Failed to write response error="write unix /build/hook2557974317/test.sock->@: i/o timeout"2817--- PASS: TestServerStalledClientDoesNotBlockShutdown (0.20s)28182026/10/27 13:04:01 ERROR Upload failed error="context canceled" count=228192026/10/27 13:04:01 ERROR Drain finished with paths left in queue remaining=42820--- PASS: TestDrainTimeout (0.26s)28212026/10/27 13:04:01 ERROR Drain finished with paths left in queue remaining=428222026/10/27 13:04:01 ERROR Upload failed error="context canceled" count=228232026/10/27 13:04:01 ERROR Drain finished with paths left in queue remaining=22824--- PASS: TestShutdownFinishesInFlightPush (0.00s)2825 --- PASS: TestShutdownFinishesInFlightPush/completes (0.16s)2826 --- PASS: TestShutdownFinishesInFlightPush/hung_push_bounded_by_the_drain_timeout (0.27s)28272026/10/27 13:04:01 ERROR Accept failed error="too many open files"28282026/10/27 13:04:01 ERROR Drain finished with paths left in queue remaining=32829--- PASS: TestDrainTimeoutDuringIsolation (0.00s)2830 --- PASS: TestDrainTimeoutDuringIsolation/probe_cut_short (0.26s)2831 --- PASS: TestDrainTimeoutDuringIsolation/probe_outlasts_the_deadline (0.36s)2832--- PASS: TestQueueConcurrentWriters (0.58s)28332026/10/27 13:04:01 ERROR Accept failed error="too many open files"2834--- PASS: TestServerBacksOffOnAcceptErrors (0.64s)28352026/10/27 13:04:01 INFO Uploading batch count=128362026/10/27 13:04:01 INFO Uploading batch count=128372026/10/27 13:04:01 INFO Uploading batch count=128382026/10/27 13:04:01 ERROR Upload failed error="upload failed" count=128392026/10/27 13:04:01 INFO Uploading batch count=128402026/10/27 13:04:01 ERROR Upload failed error="upload failed" count=128412026/10/27 13:04:01 INFO Uploading batch count=128422026/10/27 13:04:01 ERROR Upload failed error="upload failed" count=128432026/10/27 13:04:01 INFO Uploading batch count=128442026/10/27 13:04:01 ERROR Upload failed error="upload failed" count=128452026/10/27 13:04:01 ERROR Drain finished with paths left in queue remaining=12846--- PASS: TestRunNotBlockedByPoisonHead (1.07s)2847--- PASS: TestQueueRemoveLargeClosure (1.43s)2848PASS2849Running signing tests...2850=== RUN TestExternalSigner2851=== PAUSE TestExternalSigner2852=== RUN TestExternalSignerWrongPublicKey2853=== PAUSE TestExternalSignerWrongPublicKey2854=== RUN TestExternalSignerErrors2855=== PAUSE TestExternalSignerErrors2856=== RUN TestExternalSignerRestartsAfterCrash2857=== PAUSE TestExternalSignerRestartsAfterCrash2858=== RUN TestExternalSignerProgramErrorKeepsProcess2859=== PAUSE TestExternalSignerProgramErrorKeepsProcess2860=== RUN TestExternalSignerClose2861=== PAUSE TestExternalSignerClose2862=== RUN TestExternalSignerRejectsInvalidPublicKey2863=== PAUSE TestExternalSignerRejectsInvalidPublicKey2864=== RUN TestExternalSignerCancellation2865=== PAUSE TestExternalSignerCancellation2866=== RUN TestGenerateFingerprint2867=== PAUSE TestGenerateFingerprint2868=== RUN TestParseSigningKey2869=== PAUSE TestParseSigningKey2870=== RUN TestSign2871=== PAUSE TestSign2872=== RUN TestSignBatch2873=== PAUSE TestSignBatch2874=== RUN TestNilKeyPublicKey2875=== PAUSE TestNilKeyPublicKey2876=== RUN TestSignErrors2877=== PAUSE TestSignErrors2878=== CONT TestExternalSignerWrongPublicKey2879=== CONT TestExternalSignerCancellation2880=== CONT TestExternalSignerProgramErrorKeepsProcess2881=== CONT TestExternalSignerRestartsAfterCrash2882=== CONT TestExternalSignerClose2883=== CONT TestExternalSignerRejectsInvalidPublicKey2884=== RUN TestExternalSignerRejectsInvalidPublicKey/#002885=== CONT TestExternalSignerErrors2886=== RUN TestExternalSignerErrors/null2887=== PAUSE TestExternalSignerErrors/null2888=== RUN TestExternalSignerErrors/null_signatures2889=== PAUSE TestExternalSignerErrors/null_signatures2890=== CONT TestExternalSigner2891=== CONT TestSignBatch2892=== CONT TestSignErrors2893=== CONT TestNilKeyPublicKey2894=== CONT TestParseSigningKey2895=== CONT TestSign2896=== CONT TestGenerateFingerprint2897=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002898=== RUN TestExternalSignerErrors/wrong_signature_name2899--- PASS: TestNilKeyPublicKey (0.00s)2900=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2901=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2902=== RUN TestParseSigningKey/valid_32-byte_key2903=== PAUSE TestParseSigningKey/valid_32-byte_key2904=== RUN TestGenerateFingerprint/basic_with_references2905=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2906=== PAUSE TestGenerateFingerprint/basic_with_references2907=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2908--- PASS: TestExternalSignerProgramErrorKeepsProcess (0.00s)2909=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2910=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2911=== RUN TestGenerateFingerprint/no_references2912=== PAUSE TestExternalSignerErrors/wrong_signature_name2913--- PASS: TestExternalSignerWrongPublicKey (0.01s)2914=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2915=== PAUSE TestGenerateFingerprint/no_references2916=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2917--- PASS: TestExternalSignerClose (0.00s)2918=== RUN TestParseSigningKey/no_colon2919=== RUN TestSignErrors/nil_key2920=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2921=== RUN TestExternalSignerErrors/exit_on_request2922=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2923=== PAUSE TestParseSigningKey/no_colon2924=== PAUSE TestSignErrors/nil_key2925=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2926=== PAUSE TestExternalSignerErrors/exit_on_request2927=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2928=== RUN TestParseSigningKey/empty_name2929=== RUN TestSignErrors/nil_narinfo2930=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2931=== RUN TestExternalSignerErrors/missing_signature_name2932=== CONT TestExternalSignerRejectsInvalidPublicKey/#002933=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2934--- PASS: TestSign (0.00s)2935=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2936=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2937=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2938=== PAUSE TestParseSigningKey/empty_name2939=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2940=== PAUSE TestSignErrors/nil_narinfo2941=== RUN TestSignErrors/invalid_narinfo2942=== RUN TestGenerateFingerprint/invalid_nar_hash_length2943=== PAUSE TestSignErrors/invalid_narinfo2944=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2945=== PAUSE TestExternalSignerErrors/missing_signature_name2946--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2947 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2948 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2949 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2950 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2951 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2952=== RUN TestParseSigningKey/invalid_base642953=== PAUSE TestParseSigningKey/invalid_base642954=== RUN TestParseSigningKey/wrong_length2955=== PAUSE TestParseSigningKey/wrong_length2956=== RUN TestSignErrors/canceled2957=== RUN TestGenerateFingerprint/invalid_store_path_prefix2958=== RUN TestExternalSignerErrors/invalid_signature_base642959=== CONT TestParseSigningKey/valid_32-byte_key2960=== CONT TestParseSigningKey/invalid_base642961=== CONT TestParseSigningKey/no_colon2962=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2963=== CONT TestParseSigningKey/wrong_length2964=== CONT TestParseSigningKey/empty_name2965=== PAUSE TestSignErrors/canceled2966=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2967=== PAUSE TestExternalSignerErrors/invalid_signature_base642968=== CONT TestSignErrors/nil_narinfo2969=== RUN TestGenerateFingerprint/invalid_reference_prefix2970=== CONT TestSignErrors/invalid_narinfo2971=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2972=== CONT TestSignErrors/nil_key2973=== CONT TestSignErrors/canceled2974=== RUN TestExternalSignerErrors/invalid_JSON2975--- PASS: TestParseSigningKey (0.00s)2976 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2977 --- PASS: TestParseSigningKey/no_colon (0.00s)2978 --- PASS: TestParseSigningKey/wrong_length (0.00s)2979 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2980 --- PASS: TestParseSigningKey/empty_name (0.00s)2981 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2982=== CONT TestGenerateFingerprint/no_references2983--- PASS: TestSignErrors (0.00s)2984 --- PASS: TestSignErrors/nil_narinfo (0.00s)2985 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2986 --- PASS: TestSignErrors/nil_key (0.00s)2987 --- PASS: TestSignErrors/canceled (0.00s)2988=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2989=== CONT TestGenerateFingerprint/invalid_reference_prefix2990=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2991=== CONT TestGenerateFingerprint/invalid_nar_hash_length2992=== CONT TestGenerateFingerprint/basic_with_references2993=== CONT TestGenerateFingerprint/invalid_store_path_prefix2994=== PAUSE TestExternalSignerErrors/invalid_JSON2995--- PASS: TestGenerateFingerprint (0.00s)2996 --- PASS: TestGenerateFingerprint/no_references (0.00s)2997 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2998 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2999 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)3000 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)3001 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)3002 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)3003=== RUN TestExternalSignerErrors/wrong_id3004=== PAUSE TestExternalSignerErrors/wrong_id3005=== RUN TestExternalSignerErrors/missing_signatures3006=== PAUSE TestExternalSignerErrors/missing_signatures3007=== RUN TestExternalSignerErrors/unrequested_key3008=== PAUSE TestExternalSignerErrors/unrequested_key3009=== RUN TestExternalSignerErrors/wrong_signature_length3010=== PAUSE TestExternalSignerErrors/wrong_signature_length3011=== RUN TestExternalSignerErrors/wrong_signatures_shape3012=== PAUSE TestExternalSignerErrors/wrong_signatures_shape3013=== RUN TestExternalSignerErrors/too_few_signatures3014=== PAUSE TestExternalSignerErrors/too_few_signatures3015=== RUN TestExternalSignerErrors/program_error3016=== PAUSE TestExternalSignerErrors/program_error3017=== RUN TestExternalSignerErrors/exit_at_startup3018=== PAUSE TestExternalSignerErrors/exit_at_startup3019=== RUN TestExternalSignerErrors/wrong_shape3020=== PAUSE TestExternalSignerErrors/wrong_shape3021=== CONT TestExternalSignerErrors/invalid_signature_base643022=== CONT TestExternalSignerErrors/wrong_signatures_shape3023=== CONT TestExternalSignerErrors/program_error3024=== CONT TestExternalSignerErrors/wrong_shape3025=== CONT TestExternalSignerErrors/exit_on_request3026=== CONT TestExternalSignerErrors/exit_at_startup3027=== CONT TestExternalSignerErrors/too_few_signatures3028=== CONT TestExternalSignerErrors/invalid_JSON3029=== CONT TestExternalSignerErrors/wrong_signature_length3030=== CONT TestExternalSignerErrors/unrequested_key3031=== CONT TestExternalSignerErrors/missing_signatures3032=== CONT TestExternalSignerErrors/null_signatures3033=== CONT TestExternalSignerErrors/wrong_signature_name3034=== CONT TestExternalSignerErrors/wrong_id3035=== CONT TestExternalSignerErrors/null3036=== CONT TestExternalSignerErrors/missing_signature_name3037--- PASS: TestSignBatch (0.01s)3038--- PASS: TestExternalSignerRestartsAfterCrash (0.01s)3039--- PASS: TestExternalSigner (0.01s)3040--- PASS: TestExternalSignerErrors (0.01s)3041 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (0.00s)3042 --- PASS: TestExternalSignerErrors/exit_at_startup (0.01s)3043 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (0.01s)3044 --- PASS: TestExternalSignerErrors/exit_on_request (0.01s)3045 --- PASS: TestExternalSignerErrors/missing_signatures (0.01s)3046 --- PASS: TestExternalSignerErrors/program_error (0.01s)3047 --- PASS: TestExternalSignerErrors/null_signatures (0.01s)3048 --- PASS: TestExternalSignerErrors/invalid_JSON (0.01s)3049 --- PASS: TestExternalSignerErrors/too_few_signatures (0.01s)3050 --- PASS: TestExternalSignerErrors/unrequested_key (0.01s)3051 --- PASS: TestExternalSignerErrors/wrong_shape (0.01s)3052 --- PASS: TestExternalSignerErrors/missing_signature_name (0.01s)3053 --- PASS: TestExternalSignerErrors/wrong_signature_name (0.01s)3054 --- PASS: TestExternalSignerErrors/wrong_id (0.01s)3055 --- PASS: TestExternalSignerErrors/wrong_signature_length (0.01s)3056 --- PASS: TestExternalSignerErrors/null (0.01s)3057--- PASS: TestExternalSignerCancellation (0.02s)3058PASS3059Running OpenBao signer tests...3060=== RUN TestSign3061=== PAUSE TestSign3062=== RUN TestSignErrors3063=== PAUSE TestSignErrors3064=== RUN TestServe3065=== PAUSE TestServe3066=== RUN TestServeRejectsGarbage3067=== PAUSE TestServeRejectsGarbage3068=== CONT TestServe3069=== CONT TestSignErrors3070=== CONT TestSign3071=== CONT TestServeRejectsGarbage3072=== RUN TestSignErrors/http_error3073=== PAUSE TestSignErrors/http_error3074--- PASS: TestServeRejectsGarbage (0.00s)3075--- PASS: TestServe (0.00s)3076=== RUN TestSignErrors/invalid_json3077=== PAUSE TestSignErrors/invalid_json3078=== RUN TestSignErrors/no_prefix3079=== PAUSE TestSignErrors/no_prefix3080=== RUN TestSignErrors/invalid_base643081=== PAUSE TestSignErrors/invalid_base643082=== CONT TestSignErrors/invalid_base643083=== CONT TestSignErrors/http_error3084=== CONT TestSignErrors/invalid_json3085=== CONT TestSignErrors/no_prefix3086--- PASS: TestSign (0.01s)3087--- PASS: TestSignErrors (0.00s)3088 --- PASS: TestSignErrors/invalid_json (0.01s)3089 --- PASS: TestSignErrors/http_error (0.01s)3090 --- PASS: TestSignErrors/no_prefix (0.01s)3091 --- PASS: TestSignErrors/invalid_base64 (0.01s)3092PASS3093Running niks3-hook command tests...3094=== RUN TestServeSecondSignalEndsDrain3095=== PAUSE TestServeSecondSignalEndsDrain3096=== RUN TestServeThenDrainPushesSendAcceptedBeforeShutdown3097=== PAUSE TestServeThenDrainPushesSendAcceptedBeforeShutdown3098=== CONT TestServeThenDrainPushesSendAcceptedBeforeShutdown3099=== CONT TestServeSecondSignalEndsDrain3100--- PASS: TestServeSecondSignalEndsDrain (0.05s)31012026/10/27 13:04:05 INFO Upload queue status pending=131022026/10/27 13:04:05 INFO Uploading batch count=13103--- PASS: TestServeThenDrainPushesSendAcceptedBeforeShutdown (0.13s)3104PASS3105Running rate limiter tests...3106=== RUN TestAdaptiveRateLimiter_ThreadSafety3107=== PAUSE TestAdaptiveRateLimiter_ThreadSafety3108=== CONT TestAdaptiveRateLimiter_ThreadSafety31092026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=7031102026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=4931112026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=34.331122026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=24.00999999999999831132026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=16.80731142026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=11.76489999999999931152026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=8.2354331162026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=5.76480099999999931172026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531182026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531192026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531202026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531212026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531222026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531232026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531242026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531252026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=5.63678500000000131262026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531272026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531282026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531292026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531302026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531312026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531322026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531332026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531342026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531352026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531362026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531372026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531382026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531392026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531402026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531412026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531422026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531432026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531442026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531452026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531462026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531472026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531482026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531492026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531502026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=5.12435000000000131512026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531522026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531532026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531542026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531552026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531562026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531572026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531582026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531592026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531602026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531612026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531622026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531632026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=13.29124417541344831642026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=9.30387092278941331652026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=6.51270964595258831662026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531672026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531682026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531692026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531702026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531712026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531722026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531732026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531742026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531752026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531762026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531772026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531782026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531792026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531802026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531812026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531822026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531832026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531842026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531852026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531862026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=8.25281691850000431872026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=5.77697184295000331882026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531892026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531902026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531912026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531922026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531932026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=5.12435000000000131942026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531952026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531962026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531972026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531982026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=531992026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=532002026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=532012026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=5.12435000000000132022026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=532032026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=532042026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=532052026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=532062026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=532072026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=5.12435000000000132082026/10/27 13:04:06 WARN Rate limiter backed off name=test rate=53209--- PASS: TestAdaptiveRateLimiter_ThreadSafety (0.06s)3210PASS