niks3-go-unit-tests
checks.x86_64-linux.go-unit-tests
· build #390
· raw
1tribuchet: building on jamie2Running client tests...3=== RUN TestDoServerRequestAttachesToken4=== PAUSE TestDoServerRequestAttachesToken5=== RUN TestUploadBuildLog_FileBodyReplayedOnRetry6=== PAUSE TestUploadBuildLog_FileBodyReplayedOnRetry7=== RUN TestRegisterUploadedObjectReusesConnections8=== PAUSE TestRegisterUploadedObjectReusesConnections9=== RUN TestRunGarbageCollection_FinishedOnAnotherReplica10=== PAUSE TestRunGarbageCollection_FinishedOnAnotherReplica11=== RUN TestRunGarbageCollection_NotFoundAfterLocalRun12=== PAUSE TestRunGarbageCollection_NotFoundAfterLocalRun13=== RUN TestCaseHackSuffix14=== PAUSE TestCaseHackSuffix15=== RUN TestFilterOversizedClosures16=== PAUSE TestFilterOversizedClosures17=== RUN TestPushPathsReportsOnlyUnuploadablePathsOfSkippedClosure18=== PAUSE TestPushPathsReportsOnlyUnuploadablePathsOfSkippedClosure19=== RUN TestUploadMultipart_PartsInParallel20=== PAUSE TestUploadMultipart_PartsInParallel21=== RUN TestUploadMultipart_ProducerErrorIsNotEOF22=== PAUSE TestUploadMultipart_ProducerErrorIsNotEOF23=== RUN TestUploadMultipart_FailedPartBufferNotReused24=== PAUSE TestUploadMultipart_FailedPartBufferNotReused25=== RUN TestPartSizeForNAR26=== PAUSE TestPartSizeForNAR27=== RUN TestUploadMultipart_SupersededByPeer28=== PAUSE TestUploadMultipart_SupersededByPeer29=== RUN TestDumpPathCaseHackMatchesNix30--- PASS: TestDumpPathCaseHackMatchesNix (0.04s)31=== RUN TestDumpPathCaseHackCollision32--- PASS: TestDumpPathCaseHackCollision (0.00s)33=== RUN TestSupersededNARStillUploadsListing34=== PAUSE TestSupersededNARStillUploadsListing35=== RUN TestTruncatedNARDumpIsNotCompleted36=== PAUSE TestTruncatedNARDumpIsNotCompleted37=== RUN TestDumpPathMatchesNix38=== PAUSE TestDumpPathMatchesNix39=== RUN TestDumpPathSingleFile40=== PAUSE TestDumpPathSingleFile41=== RUN TestDumpPathWriterError42=== PAUSE TestDumpPathWriterError43=== RUN TestDumpPathWriterErrorStopsReading44 nar_test.go:289: read 118 of 32768000 bytes45--- PASS: TestDumpPathWriterErrorStopsReading (0.67s)46=== RUN TestEncodeNixBase3247=== PAUSE TestEncodeNixBase3248=== RUN TestEncodeNixBase32WithRealHash49=== PAUSE TestEncodeNixBase32WithRealHash50=== RUN TestConvertHashToNix3251=== PAUSE TestConvertHashToNix3252=== RUN TestGetStorePathHash53=== PAUSE TestGetStorePathHash54=== RUN TestPathInfoHashCompatibility55=== PAUSE TestPathInfoHashCompatibility56=== RUN TestParsePathInfoJSON57=== PAUSE TestParsePathInfoJSON58=== RUN TestParsePathInfoJSONMultiplePaths59=== PAUSE TestParsePathInfoJSONMultiplePaths60=== RUN TestPathInfoCACompatibility61=== PAUSE TestPathInfoCACompatibility62=== RUN TestUploadPendingObjectsStopsStartingAfterFailure63--- PASS: TestUploadPendingObjectsStopsStartingAfterFailure (0.02s)64=== RUN TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent65=== PAUSE TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent66=== RUN TestCompletePendingClosure_NotFoundWithoutKey67=== PAUSE TestCompletePendingClosure_NotFoundWithoutKey68=== RUN TestRateLimiterFeedback69=== PAUSE TestRateLimiterFeedback70=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess71=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess72=== RUN TestRegisterUploadedObject_BoundedAgainstSilentServer73=== PAUSE TestRegisterUploadedObject_BoundedAgainstSilentServer74=== RUN TestResolveStorePath75=== PAUSE TestResolveStorePath76=== RUN TestDoWithRetry_BodyReplayedViaGetBody77=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody78=== RUN TestDoWithRetry_ClosesBodyWhenNoAttemptIsMade79=== PAUSE TestDoWithRetry_ClosesBodyWhenNoAttemptIsMade80=== 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 TestClientSignaturesByStorePath99=== PAUSE TestClientSignaturesByStorePath100=== RUN TestStreamPushStopsOnCancel101=== PAUSE TestStreamPushStopsOnCancel102=== RUN TestSetClientTLS103=== PAUSE TestSetClientTLS104=== RUN TestSetClientTLSDoesNotMutateDefaultTransport105=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport106=== RUN TestSetClientTLSErrors107=== PAUSE TestSetClientTLSErrors108=== RUN TestStaticToken109=== PAUSE TestStaticToken110=== RUN TestFileTokenReadsAndCaches111=== PAUSE TestFileTokenReadsAndCaches112=== RUN TestFileTokenMissing113=== PAUSE TestFileTokenMissing114=== RUN TestFileTokenEmpty115=== PAUSE TestFileTokenEmpty116=== RUN TestScriptTokenNoExpiryRerunsEveryCall117=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall118=== RUN TestScriptTokenCachesUntilRefresh119=== PAUSE TestScriptTokenCachesUntilRefresh120=== RUN TestScriptTokenEmptyToken121=== PAUSE TestScriptTokenEmptyToken122=== RUN TestScriptTokenBadJSON123=== PAUSE TestScriptTokenBadJSON124=== RUN TestScriptTokenScriptFails125=== PAUSE TestScriptTokenScriptFails126=== RUN TestScriptTokenEmptyCommand127=== PAUSE TestScriptTokenEmptyCommand128=== RUN TestScriptTokenDoesNotWaitForItsChildren129=== PAUSE TestScriptTokenDoesNotWaitForItsChildren130=== CONT TestRegisterUploadedObjectReusesConnections131=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer132=== CONT TestPathInfoHashCompatibility133=== CONT TestCaseHackSuffix134=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)135=== CONT TestScriptTokenEmptyCommand136--- PASS: TestScriptTokenEmptyCommand (0.00s)137=== CONT TestTruncatedNARDumpIsNotCompleted138=== CONT TestDumpPathMatchesNix139=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)140=== CONT TestScriptTokenDoesNotWaitForItsChildren141=== CONT TestRateLimiterFeedback142=== CONT TestCompletePendingClosure_NotFoundWithoutKey143=== CONT TestStreamPushReportsEveryPath144=== CONT TestScriptTokenScriptFails145=== CONT TestParsePathInfoJSON146=== CONT TestGetStorePathHash147=== CONT TestStreamPushGivesUpOnDeadServer148=== CONT TestDumpPathWriterError149=== CONT TestStreamPushBatchesUnderLoad150=== CONT TestSetClientTLS151=== CONT TestShellSplitErrors152=== CONT TestPushPathsReportsOnlyUnuploadablePathsOfSkippedClosure153=== CONT TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent154=== CONT TestFilterOversizedClosures155=== CONT TestPartSizeForNAR156=== CONT TestUploadMultipart_FailedPartBufferNotReused157=== CONT TestSetClientTLSErrors158=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon159=== RUN TestRateLimiterFeedback/429_enables_limiter160=== RUN TestScriptTokenDoesNotWaitForItsChildren/cancelled_while_a_child_runs161=== RUN TestGetStorePathHash/valid_store_path162=== RUN TestParsePathInfoJSON/Nix_format163=== RUN TestStreamPushBatchesUnderLoad/together164=== RUN TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/committed_earlier165=== PAUSE TestStreamPushBatchesUnderLoad/together166=== PAUSE TestScriptTokenDoesNotWaitForItsChildren/cancelled_while_a_child_runs167=== RUN TestFilterOversizedClosures/no_limit_keeps_everything168=== RUN TestScriptTokenDoesNotWaitForItsChildren/child_left_holding_stdout169--- PASS: TestShellSplitErrors (0.00s)170=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything171=== CONT TestDoServerRequestAttachesToken172=== RUN TestPartSizeForNAR/zero_stays_at_minimum173=== CONT TestUploadMultipart_PartsInParallel174=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry175=== CONT TestParsePathInfoJSONMultiplePaths176=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon177=== PAUSE TestRateLimiterFeedback/429_enables_limiter178=== PAUSE TestParsePathInfoJSON/Nix_format179=== PAUSE TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/committed_earlier180=== PAUSE TestGetStorePathHash/valid_store_path181=== RUN TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/cleaned_up182=== RUN TestGetStorePathHash/basename_without_hyphen_should_error183=== RUN TestParsePathInfoJSON/Lix_format184=== RUN TestSetClientTLSErrors/missing_cert_file185=== PAUSE TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/cleaned_up186=== PAUSE TestSetClientTLSErrors/missing_cert_file187=== PAUSE TestScriptTokenDoesNotWaitForItsChildren/child_left_holding_stdout188=== RUN TestSetClientTLSErrors/missing_key_file189=== CONT TestConvertHashToNix32190=== RUN TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_committed_earlier191=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum192=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths193=== RUN TestPartSizeForNAR/small_stays_at_minimum194=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI195=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths196=== RUN TestStreamPushBatchesUnderLoad/one_at_a_time197=== RUN TestRateLimiterFeedback/503_enables_limiter198=== CONT TestScriptTokenBadJSON199=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths200=== CONT TestScriptTokenEmptyToken201=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths202=== CONT TestStreamPushStopsOnCancel203=== RUN TestStreamPushStopsOnCancel/waiting_for_input204=== PAUSE TestRateLimiterFeedback/503_enables_limiter205=== PAUSE TestStreamPushBatchesUnderLoad/one_at_a_time206=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter207=== PAUSE TestStreamPushStopsOnCancel/waiting_for_input208=== CONT TestEncodeNixBase32WithRealHash209=== RUN TestStreamPushStopsOnCancel/partial_batch_waiting_for_a_slot210=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter211=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter212=== PAUSE TestStreamPushStopsOnCancel/partial_batch_waiting_for_a_slot213=== CONT TestClientSignaturesByStorePath214=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter215=== RUN TestSetClientTLS/rejects_connection_without_client_cert216=== CONT TestStreamPushRequestLine217=== CONT TestDumpPathSingleFile218=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert219=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA220=== PAUSE TestParsePathInfoJSON/Lix_format221=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error222=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error223=== RUN TestParsePathInfoJSON/empty_input224=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped225=== PAUSE TestSetClientTLSErrors/missing_key_file226=== PAUSE TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_committed_earlier227=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI228=== PAUSE TestPartSizeForNAR/small_stays_at_minimum229=== RUN TestStreamPushStopsOnCancel/input_closed,_last_batch_waiting_for_a_slot230=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA231=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error232=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error233=== PAUSE TestStreamPushStopsOnCancel/input_closed,_last_batch_waiting_for_a_slot234=== RUN TestSetClientTLS/preserves_debug_logging_transport235=== RUN TestStreamPushStopsOnCancel/full_batch_waiting_for_a_slot236=== PAUSE TestSetClientTLS/preserves_debug_logging_transport237=== PAUSE TestStreamPushStopsOnCancel/full_batch_waiting_for_a_slot238=== RUN TestConvertHashToNix32/SRI_format_to_Nix32239=== RUN TestStreamPushStopsOnCancel/request_line_waiting_for_a_slot240--- PASS: TestScriptTokenScriptFails (0.00s)241=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped242--- PASS: TestStreamPushReportsEveryPath (0.13s)243--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)244=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512245=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512246--- PASS: TestCompletePendingClosure_NotFoundWithoutKey (0.14s)247--- PASS: TestDoServerRequestAttachesToken (0.01s)248=== RUN TestFilterOversizedClosures/all_closures_skipped249=== CONT TestScriptTokenCachesUntilRefresh250=== PAUSE TestFilterOversizedClosures/all_closures_skipped251=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum252=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess253=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum254=== CONT TestFileTokenMissing255=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts256=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts257=== RUN TestPartSizeForNAR/1_TiB258=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32259=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error260=== RUN TestConvertHashToNix32/already_Nix32_format261=== CONT TestScriptTokenNoExpiryRerunsEveryCall262=== PAUSE TestConvertHashToNix32/already_Nix32_format263=== RUN TestConvertHashToNix32/invalid_format264=== PAUSE TestConvertHashToNix32/invalid_format265=== CONT TestPathInfoCACompatibility266=== CONT TestFileTokenReadsAndCaches267=== RUN TestPathInfoCACompatibility/null_ca_field268=== PAUSE TestPathInfoCACompatibility/null_ca_field269=== RUN TestPathInfoCACompatibility/old_string_format_-_text270=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text271=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive272=== PAUSE TestParsePathInfoJSON/empty_input273=== PAUSE TestStreamPushStopsOnCancel/request_line_waiting_for_a_slot274=== CONT TestFileTokenEmpty275--- PASS: TestEncodeNixBase32WithRealHash (0.00s)276=== CONT TestStaticToken277=== RUN TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_cleaned_up,_first_root_committed_by_another_client278=== RUN TestSetClientTLSErrors/missing_ca_file279=== PAUSE TestPartSizeForNAR/1_TiB280=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive281=== RUN TestParsePathInfoJSON/whitespace_only282=== RUN TestStreamPushStopsOnCancel/lines_read_but_not_taken283=== PAUSE TestStreamPushStopsOnCancel/lines_read_but_not_taken284--- PASS: TestClientSignaturesByStorePath (0.00s)285=== PAUSE TestParsePathInfoJSON/whitespace_only286=== CONT TestDoWithRetry_ClosesBodyWhenNoAttemptIsMade287=== CONT TestStreamPushReportsSignatures288=== RUN TestDoWithRetry_ClosesBodyWhenNoAttemptIsMade/retries=0289=== PAUSE TestSetClientTLSErrors/missing_ca_file290=== RUN TestSetClientTLSErrors/invalid_ca_file291=== RUN TestPartSizeForNAR/5_TiB_S3_max_object292=== PAUSE TestDoWithRetry_ClosesBodyWhenNoAttemptIsMade/retries=0293=== PAUSE TestSetClientTLSErrors/invalid_ca_file294--- PASS: TestScriptTokenEmptyToken (0.00s)295--- PASS: TestScriptTokenBadJSON (0.01s)296=== PAUSE TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_cleaned_up,_first_root_committed_by_another_client297--- PASS: TestFileTokenMissing (0.00s)298=== RUN TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_cleaned_up,_last_root_committed_by_another_client299--- PASS: TestStreamPushReportsSignatures (0.00s)300--- PASS: TestStaticToken (0.00s)301=== RUN TestPathInfoCACompatibility/new_structured_format_-_text302=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object303--- PASS: TestFileTokenReadsAndCaches (0.00s)304--- PASS: TestFileTokenEmpty (0.00s)305=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text306=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method307=== RUN TestPartSizeForNAR/capped_at_5_GiB308=== PAUSE TestPartSizeForNAR/capped_at_5_GiB309=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method310=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun311=== CONT TestDoWithRetry_FinalResponseBodyReadable312=== RUN TestDoWithRetry_ClosesBodyWhenNoAttemptIsMade/retries=5313=== PAUSE TestDoWithRetry_ClosesBodyWhenNoAttemptIsMade/retries=5314=== CONT TestStreamPushIsolatesFailures315=== CONT TestUploadMultipart_ProducerErrorIsNotEOF316=== CONT TestSetClientTLSDoesNotMutateDefaultTransport317=== PAUSE TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_cleaned_up,_last_root_committed_by_another_client318=== RUN TestParsePathInfoJSON/invalid_JSON319=== PAUSE TestParsePathInfoJSON/invalid_JSON320=== CONT TestSupersededNARStillUploadsListing321=== RUN TestSupersededNARStillUploadsListing/small_NAR322=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica323=== CONT TestEncodeNixBase32324=== RUN TestEncodeNixBase32/test_string_hash325=== RUN TestUploadMultipart_ProducerErrorIsNotEOF/short_read_inside_a_part326--- PASS: TestStreamPushIsolatesFailures (0.00s)327=== CONT TestUploadMultipart_SupersededByPeer328=== CONT TestResolveStorePath329=== CONT TestShellSplit330=== CONT TestScriptTokenDoesNotWaitForItsChildren/child_left_holding_stdout331=== RUN TestUploadMultipart_SupersededByPeer/exists332=== PAUSE TestSupersededNARStillUploadsListing/small_NAR333=== PAUSE TestEncodeNixBase32/test_string_hash334=== PAUSE TestUploadMultipart_ProducerErrorIsNotEOF/short_read_inside_a_part335=== RUN TestUploadMultipart_ProducerErrorIsNotEOF/empty_read_on_a_part_boundary336=== CONT TestScriptTokenDoesNotWaitForItsChildren/cancelled_while_a_child_runs337=== PAUSE TestUploadMultipart_ProducerErrorIsNotEOF/empty_read_on_a_part_boundary338=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths339=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths340=== PAUSE TestUploadMultipart_SupersededByPeer/exists341=== RUN TestSupersededNARStillUploadsListing/dump_cut_short342=== RUN TestEncodeNixBase32/empty_input343=== PAUSE TestEncodeNixBase32/empty_input344--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.00s)345=== CONT TestStreamPushBatchesUnderLoad/together346=== CONT TestDoWithRetry_BodyReplayedViaGetBody347=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter348=== CONT TestStreamPushBatchesUnderLoad/one_at_a_time349=== RUN TestUploadMultipart_SupersededByPeer/missing350=== PAUSE TestSupersededNARStillUploadsListing/dump_cut_short351--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)352--- PASS: TestShellSplit (0.00s)353=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter354=== CONT TestRateLimiterFeedback/503_enables_limiter355=== CONT TestRateLimiterFeedback/429_enables_limiter356=== CONT TestSetClientTLS/preserves_debug_logging_transport357=== PAUSE TestUploadMultipart_SupersededByPeer/missing358=== RUN TestSupersededNARStillUploadsListing/listing_upload_fails359=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA360=== CONT TestSetClientTLS/rejects_connection_without_client_cert361--- PASS: TestResolveStorePath (0.00s)362=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)363--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.01s)364=== PAUSE TestSupersededNARStillUploadsListing/listing_upload_fails365=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon366=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped367=== CONT TestFilterOversizedClosures/all_closures_skipped368=== CONT TestGetStorePathHash/basename_without_hyphen_should_error369--- PASS: TestScriptTokenCachesUntilRefresh (0.01s)370=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI371=== CONT TestFilterOversizedClosures/no_limit_keeps_everything372=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512373=== CONT TestConvertHashToNix32/already_Nix32_format374=== CONT TestConvertHashToNix32/invalid_format375=== CONT TestGetStorePathHash/valid_store_path376=== CONT TestStreamPushStopsOnCancel/lines_read_but_not_taken377=== CONT TestStreamPushStopsOnCancel/request_line_waiting_for_a_slot378=== CONT TestStreamPushStopsOnCancel/waiting_for_input379--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.01s)380=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error381=== CONT TestStreamPushStopsOnCancel/partial_batch_waiting_for_a_slot382=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error383=== CONT TestSetClientTLSErrors/missing_cert_file384--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.01s)385=== CONT TestStreamPushStopsOnCancel/input_closed,_last_batch_waiting_for_a_slot386=== CONT TestSetClientTLSErrors/invalid_ca_file387=== CONT TestSetClientTLSErrors/missing_key_file388=== CONT TestConvertHashToNix32/SRI_format_to_Nix32389=== CONT TestSetClientTLSErrors/missing_ca_file390=== CONT TestPartSizeForNAR/capped_at_5_GiB391--- PASS: TestStreamPushBatchesUnderLoad (0.01s)392 --- PASS: TestStreamPushBatchesUnderLoad/together (0.00s)393 --- PASS: TestStreamPushBatchesUnderLoad/one_at_a_time (0.00s)394=== CONT TestStreamPushStopsOnCancel/full_batch_waiting_for_a_slot395=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum396=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts397=== CONT TestPartSizeForNAR/1_TiB398--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.00s)399=== CONT TestPartSizeForNAR/zero_stays_at_minimum400=== CONT TestPartSizeForNAR/5_TiB_S3_max_object401--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.04s)402=== CONT TestPartSizeForNAR/small_stays_at_minimum403=== CONT TestPathInfoCACompatibility/null_ca_field404--- PASS: TestCaseHackSuffix (0.17s)405=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method406=== CONT TestPathInfoCACompatibility/new_structured_format_-_text407=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive408--- PASS: TestParsePathInfoJSONMultiplePaths (0.01s)409 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)410 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)411=== CONT TestPathInfoCACompatibility/old_string_format_-_text412=== CONT TestDoWithRetry_ClosesBodyWhenNoAttemptIsMade/retries=0413=== CONT TestDoWithRetry_ClosesBodyWhenNoAttemptIsMade/retries=5414--- PASS: TestFilterOversizedClosures (0.02s)415 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)416 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)417 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)418=== CONT TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/cleaned_up419=== CONT TestParsePathInfoJSON/Nix_format420=== CONT TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_cleaned_up,_first_root_committed_by_another_client421--- PASS: TestSetClientTLSErrors (0.02s)422 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)423 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)424 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)425 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)426=== CONT TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_cleaned_up,_last_root_committed_by_another_client427--- PASS: TestDumpPathSingleFile (0.04s)428--- PASS: TestRateLimiterFeedback (0.14s)429 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)430 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)431 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)432 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)433--- PASS: TestGetStorePathHash (0.02s)434 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)435 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)436 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)437 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)438--- PASS: TestConvertHashToNix32 (0.01s)439 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)440 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)441 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)442--- PASS: TestPathInfoHashCompatibility (0.14s)443 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)444 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)445 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)446 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)447--- PASS: TestPartSizeForNAR (0.02s)448 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)449 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)450 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)451 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)452 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)453 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)454 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)455--- PASS: TestDoWithRetry_ClosesBodyWhenNoAttemptIsMade (0.00s)456 --- PASS: TestDoWithRetry_ClosesBodyWhenNoAttemptIsMade/retries=0 (0.00s)457 --- PASS: TestDoWithRetry_ClosesBodyWhenNoAttemptIsMade/retries=5 (0.00s)458--- PASS: TestPathInfoCACompatibility (0.00s)459 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)460 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)461 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)462 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)463 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)464=== CONT TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_committed_earlier465=== CONT TestParsePathInfoJSON/Lix_format466=== CONT TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/committed_earlier467=== CONT TestParsePathInfoJSON/whitespace_only468=== CONT TestParsePathInfoJSON/empty_input469=== CONT TestParsePathInfoJSON/invalid_JSON470=== CONT TestUploadMultipart_ProducerErrorIsNotEOF/short_read_inside_a_part471=== CONT TestEncodeNixBase32/test_string_hash472=== CONT TestUploadMultipart_ProducerErrorIsNotEOF/empty_read_on_a_part_boundary473--- PASS: TestParsePathInfoJSON (0.03s)474 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)475 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)476 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)477 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)478 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)479=== CONT TestEncodeNixBase32/empty_input480=== CONT TestUploadMultipart_SupersededByPeer/missing481=== CONT TestUploadMultipart_SupersededByPeer/exists482--- PASS: TestEncodeNixBase32 (0.01s)483 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)484 --- PASS: TestEncodeNixBase32/empty_input (0.00s)485=== CONT TestSupersededNARStillUploadsListing/dump_cut_short486--- PASS: TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent (0.02s)487 --- PASS: TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/cleaned_up (0.01s)488 --- PASS: TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_cleaned_up,_first_root_committed_by_another_client (0.01s)489 --- PASS: TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_cleaned_up,_last_root_committed_by_another_client (0.01s)490 --- PASS: TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_committed_earlier (0.00s)491 --- PASS: TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/committed_earlier (0.00s)492=== CONT TestSupersededNARStillUploadsListing/listing_upload_fails493=== CONT TestSupersededNARStillUploadsListing/small_NAR494--- PASS: TestUploadMultipart_SupersededByPeer (0.01s)495 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.27s)496 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.27s)497--- PASS: TestStreamPushStopsOnCancel (0.01s)498 --- PASS: TestStreamPushStopsOnCancel/waiting_for_input (0.29s)499 --- PASS: TestStreamPushStopsOnCancel/partial_batch_waiting_for_a_slot (0.29s)500 --- PASS: TestStreamPushStopsOnCancel/request_line_waiting_for_a_slot (0.30s)501 --- PASS: TestStreamPushStopsOnCancel/lines_read_but_not_taken (0.30s)502 --- PASS: TestStreamPushStopsOnCancel/full_batch_waiting_for_a_slot (0.29s)503 --- PASS: TestStreamPushStopsOnCancel/input_closed,_last_batch_waiting_for_a_slot (0.30s)504--- PASS: TestPushPathsReportsOnlyUnuploadablePathsOfSkippedClosure (0.34s)505--- PASS: TestDumpPathWriterError (0.36s)506--- PASS: TestUploadMultipart_ProducerErrorIsNotEOF (0.01s)507 --- PASS: TestUploadMultipart_ProducerErrorIsNotEOF/empty_read_on_a_part_boundary (0.33s)508 --- PASS: TestUploadMultipart_ProducerErrorIsNotEOF/short_read_inside_a_part (0.36s)509--- PASS: TestSetClientTLS (0.02s)510 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.02s)511 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.02s)512 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.39s)513--- PASS: TestRegisterUploadedObjectReusesConnections (0.62s)514--- PASS: TestStreamPushRequestLine (0.52s)515--- PASS: TestDumpPathMatchesNix (0.69s)516--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)517--- PASS: TestUploadMultipart_PartsInParallel (1.33s)518--- PASS: TestUploadMultipart_FailedPartBufferNotReused (1.35s)519--- PASS: TestTruncatedNARDumpIsNotCompleted (1.52s)520--- PASS: TestSupersededNARStillUploadsListing (0.01s)521 --- PASS: TestSupersededNARStillUploadsListing/small_NAR (0.05s)522 --- PASS: TestSupersededNARStillUploadsListing/listing_upload_fails (0.06s)523 --- PASS: TestSupersededNARStillUploadsListing/dump_cut_short (1.37s)524--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (2.00s)525--- PASS: TestScriptTokenDoesNotWaitForItsChildren (0.14s)526 --- PASS: TestScriptTokenDoesNotWaitForItsChildren/child_left_holding_stdout (2.01s)527 --- PASS: TestScriptTokenDoesNotWaitForItsChildren/cancelled_while_a_child_runs (2.31s)528PASS529Running server tests...530The files belonging to this database system will be owned by user "nixbld".531This user must also own the server process.532533The database cluster will be initialized with locale "C".534The default database encoding has accordingly been set to "SQL_ASCII".535The default text search configuration will be set to "english".536537Data page checksums are enabled.538539creating directory /build/postgres1810665275/data ... ok540creating subdirectories ... ok541selecting dynamic shared memory implementation ... posix542selecting default "max_connections" ... 100543selecting default "shared_buffers" ... 128MB544selecting default time zone ... UTC545creating configuration files ... ok546running bootstrap script ... ok547performing post-bootstrap initialization ... ok548syncing data to disk ... ok549550initdb: warning: enabling "trust" authentication for local connections551initdb: 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.552553Success. You can now start the database server using:554555 pg_ctl -D /build/postgres1810665275/data -l logfile start556557/build/postgres1810665275:5432 - no response5582026-10-06 23:00:43.140 UTC [173] LOG: starting PostgreSQL 18.6 on x86_64-pc-linux-gnu, compiled by clang version 21.1.8, 64-bit5592026-10-06 23:00:43.140 UTC [173] LOG: listening on Unix socket "/build/postgres1810665275/.s.PGSQL.5432"5602026-10-06 23:00:43.145 UTC [180] LOG: database system was shut down at 2026-10-06 23:00:42 UTC5612026-10-06 23:00:43.149 UTC [173] LOG: database system is ready to accept connections562/build/postgres1810665275:5432 - accepting connections563=== RUN TestService_AuthMiddleware564=== PAUSE TestService_AuthMiddleware565=== RUN TestService_AuthMiddleware_MTLSProxyHeader566=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader567=== RUN TestService_AuthMiddleware_MTLSBoundSubjects568=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects569=== RUN TestService_ReadAuthMiddleware570=== PAUSE TestService_ReadAuthMiddleware571=== RUN TestService_AuthMiddleware_OIDC572=== PAUSE TestService_AuthMiddleware_OIDC573=== RUN TestService_RequireScope_OIDC574=== PAUSE TestService_RequireScope_OIDC575=== RUN TestService_ReadScope_PublicByDefault576=== PAUSE TestService_ReadScope_PublicByDefault577=== RUN TestCacheConfigHandler578=== PAUSE TestCacheConfigHandler579=== RUN TestCacheStatsHandler580=== PAUSE TestCacheStatsHandler581=== RUN TestClientCADerivations582=== PAUSE TestClientCADerivations583=== RUN TestClientErrorHandling584=== PAUSE TestClientErrorHandling585=== RUN TestClientIntegration586=== PAUSE TestClientIntegration587=== RUN TestClientMultipleUploads588=== PAUSE TestClientMultipleUploads589=== RUN TestClientWithDependencies590=== PAUSE TestClientWithDependencies591=== RUN TestClientSharedPathCommittedMidPush592=== PAUSE TestClientSharedPathCommittedMidPush593=== RUN TestPinProtectsFromGC594=== PAUSE TestPinProtectsFromGC595=== RUN TestClientPushesUseOnePush596=== PAUSE TestClientPushesUseOnePush597=== RUN TestClientFallsBackToClosures598=== PAUSE TestClientFallsBackToClosures599=== RUN TestDeleteClosuresRacingPins600=== PAUSE TestDeleteClosuresRacingPins601=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock602=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock603=== RUN TestResolveDBConnectionString604=== PAUSE TestResolveDBConnectionString605=== RUN TestConnectWaitsForAPeerMigration606=== PAUSE TestConnectWaitsForAPeerMigration607=== RUN TestConnectSerialisesConcurrentMigrations608=== PAUSE TestConnectSerialisesConcurrentMigrations609=== RUN TestLeadElectsOneAndHandsOver610=== PAUSE TestLeadElectsOneAndHandsOver611=== RUN TestLeadIncumbentWinsAfterRestart6122026/10/06 23:00:43 INFO lead: acquired remote=192.0.2.1:12346132026/10/06 23:00:44 INFO lead: released remote=192.0.2.1:12346142026/10/06 23:00:44 INFO lead: acquired remote=192.0.2.1:12346152026/10/06 23:00:45 INFO lead: released remote=192.0.2.1:1234616--- PASS: TestLeadIncumbentWinsAfterRestart (1.95s)617=== RUN TestLeadIncumbentAnnouncesAtOnce618=== PAUSE TestLeadIncumbentAnnouncesAtOnce619=== RUN TestLeadEndsOnShutdown620=== PAUSE TestLeadEndsOnShutdown621=== RUN TestLeadEndsWhenItsConnectionHangs6222026/10/06 23:00:45 INFO lead: acquired remote=192.0.2.1:12346232026-10-06 23:00:46.943 UTC [625] FATAL: terminating connection due to administrator command6242026/10/06 23:00:47 INFO lead: acquired remote=192.0.2.1:12346252026/10/06 23:00:48 WARN lead: lock connection lost error="timeout: context deadline exceeded"6262026/10/06 23:00:48 INFO lead: released remote=192.0.2.1:12346272026/10/06 23:00:48 INFO lead: released remote=192.0.2.1:1234628--- PASS: TestLeadEndsWhenItsConnectionHangs (3.16s)629=== RUN TestGCAdvisoryLockBlocksConcurrentRun630=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun631=== RUN TestGCBugBareHashReferences632=== PAUSE TestGCBugBareHashReferences633=== RUN TestGCMetrics634=== PAUSE TestGCMetrics635=== RUN TestPushDedupSurvivesConcurrentGC636=== PAUSE TestPushDedupSurvivesConcurrentGC637=== RUN TestDeduplicatedObjectsRecordedAsPending638=== PAUSE TestDeduplicatedObjectsRecordedAsPending639=== RUN TestGCSweepSkipsPendingObjects640=== PAUSE TestGCSweepSkipsPendingObjects641=== RUN TestTombstonedObjectOfferedWithoutWaiting642=== PAUSE TestTombstonedObjectOfferedWithoutWaiting643=== RUN TestGCSweepDeliversEachKeyOnce644=== PAUSE TestGCSweepDeliversEachKeyOnce645=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection646=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection647=== RUN TestForceGCDuringPushOffersSweptObject648=== PAUSE TestForceGCDuringPushOffersSweptObject649=== RUN TestFailedS3DeleteKeepsTombstone650=== PAUSE TestFailedS3DeleteKeepsTombstone651=== RUN TestSweepSkipsRowsLockedByPush652=== PAUSE TestSweepSkipsRowsLockedByPush653=== RUN TestRegisterCompletedObjectNeedsPendingRow654=== PAUSE TestRegisterCompletedObjectNeedsPendingRow655=== RUN TestGetExistingObjectsLocksRows656=== PAUSE TestGetExistingObjectsLocksRows657=== RUN TestSweepRechecksPendingAfterLocking658=== PAUSE TestSweepRechecksPendingAfterLocking659=== RUN TestPushWaitsForSweepHoldingRow660=== PAUSE TestPushWaitsForSweepHoldingRow661=== RUN TestCommitRacingPendingCleanupKeepsObjects662=== PAUSE TestCommitRacingPendingCleanupKeepsObjects663=== RUN TestGCEndsOnShutdown664=== PAUSE TestGCEndsOnShutdown665=== RUN TestGCTaskStore_StartNew666=== PAUSE TestGCTaskStore_StartNew667=== RUN TestGCTaskStore_DeduplicateSameParams668=== PAUSE TestGCTaskStore_DeduplicateSameParams669=== RUN TestGCTaskStore_ConflictDifferentParams670=== PAUSE TestGCTaskStore_ConflictDifferentParams671=== RUN TestGCTaskStore_GetEmpty672=== PAUSE TestGCTaskStore_GetEmpty673=== RUN TestGCTaskStore_GetReturnsLatest674=== PAUSE TestGCTaskStore_GetReturnsLatest675=== RUN TestGCTaskStore_CompletedAllowsNewTask676=== PAUSE TestGCTaskStore_CompletedAllowsNewTask677=== RUN TestGCTaskStore_PhaseUpdates678=== PAUSE TestGCTaskStore_PhaseUpdates679=== RUN TestGCTaskStore_Fail680=== PAUSE TestGCTaskStore_Fail681=== RUN TestGracefulShutdownDrainsInflight682=== PAUSE TestGracefulShutdownDrainsInflight683=== RUN TestService_healthCheckHandler684=== PAUSE TestService_healthCheckHandler685=== RUN TestService_readinessHandler686=== PAUSE TestService_readinessHandler687=== RUN TestGenerateLandingPage688=== PAUSE TestGenerateLandingPage689=== RUN TestCacheConfigHandlerMaxNarSize690=== PAUSE TestCacheConfigHandlerMaxNarSize691=== RUN TestCreatePendingClosureRejectsOversizedNAR692=== PAUSE TestCreatePendingClosureRejectsOversizedNAR693=== RUN TestNARDeduplicationMetadataUploadBug694=== PAUSE TestNARDeduplicationMetadataUploadBug695=== RUN TestMetricsInventory696=== PAUSE TestMetricsInventory697=== RUN TestService_NativeMTLS698=== PAUSE TestService_NativeMTLS699=== RUN TestServerTLSConfig700=== PAUSE TestServerTLSConfig701=== RUN TestMultipartCleanup702=== PAUSE TestMultipartCleanup703=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded704=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded705=== RUN TestPendingCleanupUsesOneCutoff706=== PAUSE TestPendingCleanupUsesOneCutoff707=== RUN TestPendingClosureFailureTracksEveryUpload708=== PAUSE TestPendingClosureFailureTracksEveryUpload709=== RUN TestPendingClosureFailureAbortsItsUploads710=== PAUSE TestPendingClosureFailureAbortsItsUploads711=== RUN TestObjectStatsTrigger712=== PAUSE TestObjectStatsTrigger713=== RUN TestObjectStatsLargeCommit714=== PAUSE TestObjectStatsLargeCommit715=== RUN TestReconnectLeavesObjectsUnlocked716=== PAUSE TestReconnectLeavesObjectsUnlocked717=== RUN TestOrphanedObjectsGC718=== PAUSE TestOrphanedObjectsGC719=== RUN TestOrphanedObjectsGCStressTest720=== PAUSE TestOrphanedObjectsGCStressTest721=== RUN TestCreatePin_ReservedPins722=== PAUSE TestCreatePin_ReservedPins723=== RUN TestConcurrentPinUpdatesAgree724=== PAUSE TestConcurrentPinUpdatesAgree725=== RUN TestCreatePinRejectsBadInput726=== PAUSE TestCreatePinRejectsBadInput727=== RUN TestDeletePinKeepsRowWhenS3Fails728=== PAUSE TestDeletePinKeepsRowWhenS3Fails729=== RUN TestPresentReportsOnlyClosureRoots730=== PAUSE TestPresentReportsOnlyClosureRoots731=== RUN TestPresentRefreshesOnlyStaleClosures732=== PAUSE TestPresentRefreshesOnlyStaleClosures733=== RUN TestPresentNotReportedWhileGCDeletesClosure734=== PAUSE TestPresentNotReportedWhileGCDeletesClosure735=== RUN TestParseSingleRange736=== PAUSE TestParseSingleRange737=== RUN TestProxyHeadersOnlyTrustedOnSocket738=== PAUSE TestProxyHeadersOnlyTrustedOnSocket739=== RUN TestIsValidCachePath740=== PAUSE TestIsValidCachePath741=== RUN TestReadProxyNarinfo742=== PAUSE TestReadProxyNarinfo743=== RUN TestReadProxyNarinfoAlreadyDecompressed744=== PAUSE TestReadProxyNarinfoAlreadyDecompressed745=== RUN TestReadProxyContentNegotiation746=== PAUSE TestReadProxyContentNegotiation747=== RUN TestReadProxyNarStreaming748=== PAUSE TestReadProxyNarStreaming749=== RUN TestReadProxy404750=== PAUSE TestReadProxy404751=== RUN TestReadProxyInvalidPath752=== PAUSE TestReadProxyInvalidPath753=== RUN TestReadProxyHead754=== PAUSE TestReadProxyHead755=== RUN TestReadProxyOutlastsServerWriteTimeout756=== PAUSE TestReadProxyOutlastsServerWriteTimeout757=== RUN TestReadProxyConditionalGet758=== PAUSE TestReadProxyConditionalGet759=== RUN TestReadProxyRootRedirectsToIndexHTML760=== PAUSE TestReadProxyRootRedirectsToIndexHTML761=== RUN TestReadProxyDisabled762=== PAUSE TestReadProxyDisabled763=== RUN TestReadRedirectNar764=== PAUSE TestReadRedirectNar765=== RUN TestReadRedirectKeepsNarinfoProxied766=== PAUSE TestReadRedirectKeepsNarinfoProxied767=== RUN TestReadProxyRangeRequest768=== PAUSE TestReadProxyRangeRequest769=== RUN TestReadRedirectUsesPublicS3URL770=== PAUSE TestReadRedirectUsesPublicS3URL771=== RUN TestPush_OverlappingRootsStoreOneRowPerKey772=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey773=== RUN TestPush_CompleteCommitsEveryRoot774=== PAUSE TestPush_CompleteCommitsEveryRoot775=== RUN TestPush_RepeatedRootCommitsOnce776=== PAUSE TestPush_RepeatedRootCommitsOnce777=== RUN TestPush_CompleteWaitsForCleanupOfThePush778=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush779=== RUN TestPush_RootsAreLockedInByteOrder780=== PAUSE TestPush_RootsAreLockedInByteOrder781=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit782=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit783=== RUN TestPush_RejectsBadRequests784=== PAUSE TestPush_RejectsBadRequests785=== RUN TestPush_SignsNarinfosOfItsPendingObjects786=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects787=== RUN TestRedundantMultipartUpload788=== PAUSE TestRedundantMultipartUpload789=== RUN TestCompleteMultipartUpload_ErrorButObjectExists790=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists791=== RUN TestCompletedNarNotReofferedAcrossClosures792=== PAUSE TestCompletedNarNotReofferedAcrossClosures793=== RUN TestPresignedUploadRegisteredBeforeCommit794=== PAUSE TestPresignedUploadRegisteredBeforeCommit795=== RUN TestService_Rustfstest796=== PAUSE TestService_Rustfstest797=== RUN TestParseSize798=== PAUSE TestParseSize799=== RUN TestSkippedUploadsHandler800=== PAUSE TestSkippedUploadsHandler801=== RUN TestSystemdListenerNotActivated802--- PASS: TestSystemdListenerNotActivated (0.00s)803=== RUN TestWatchdogBeatsWhenHealthy804--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)805=== RUN TestWatchdogSkipsWhenUnhealthy8062026/10/06 23:00:48 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"8072026/10/06 23:00:48 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"8082026/10/06 23:00:48 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"8092026/10/06 23:00:48 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"8102026/10/06 23:00:48 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"8112026/10/06 23:00:48 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"8122026/10/06 23:00:48 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"8132026/10/06 23:00:48 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"8142026/10/06 23:00:48 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"8152026/10/06 23:00:48 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"816--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)817=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle818=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle819=== RUN TestProxyWriteTimeout820=== PAUSE TestProxyWriteTimeout821=== RUN TestPendingClosureWriteTimeout822=== PAUSE TestPendingClosureWriteTimeout823=== RUN TestIsValidUploadKey824=== PAUSE TestIsValidUploadKey825=== RUN TestUploadHandlersRejectInvalidKeys826=== PAUSE TestUploadHandlersRejectInvalidKeys827=== RUN TestUploadHandlersRejectOversizedBody828=== PAUSE TestUploadHandlersRejectOversizedBody829=== RUN TestService_cleanupPendingClosuresHandler830=== PAUSE TestService_cleanupPendingClosuresHandler831=== RUN TestService_createPendingClosureHandler832=== PAUSE TestService_createPendingClosureHandler833=== RUN TestService_verifyS3Integrity834=== PAUSE TestService_verifyS3Integrity835=== RUN TestCompleteMultipartUnregistered836=== PAUSE TestCompleteMultipartUnregistered837=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT838=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT839=== CONT TestService_ReadAuthMiddleware840=== CONT TestUploadHandlersRejectOversizedBody841=== CONT TestPush_RejectsBadRequests842=== CONT TestPush_RepeatedRootCommitsOnce843=== CONT TestPush_OverlappingRootsStoreOneRowPerKey844=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT845=== CONT TestCompleteMultipartUnregistered846=== CONT TestService_verifyS3Integrity847=== CONT TestService_createPendingClosureHandler848=== CONT TestService_cleanupPendingClosuresHandler849=== CONT TestIsValidUploadKey850=== RUN TestIsValidUploadKey/narinfo851=== PAUSE TestIsValidUploadKey/narinfo852=== RUN TestIsValidUploadKey/nar_zst853=== CONT TestPendingClosureWriteTimeout854=== CONT TestProxyWriteTimeout855=== CONT TestUploadHandlersRejectInvalidKeys856=== CONT TestSkippedUploadsHandler857=== CONT TestParseSize858=== CONT TestService_Rustfstest859=== CONT TestPresignedUploadRegisteredBeforeCommit860=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle861=== CONT TestCompleteMultipartUpload_ErrorButObjectExists862=== CONT TestCompletedNarNotReofferedAcrossClosures863=== CONT TestRedundantMultipartUpload864=== CONT TestPush_SignsNarinfosOfItsPendingObjects865=== CONT TestPresentNotReportedWhileGCDeletesClosure866=== RUN TestPendingClosureWriteTimeout/empty867=== RUN TestProxyWriteTimeout/narinfo868=== PAUSE TestIsValidUploadKey/nar_zst869=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info870--- PASS: TestParseSize (0.00s)871=== CONT TestPush_RootsAreLockedInByteOrder872=== PAUSE TestPendingClosureWriteTimeout/empty873=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale874=== PAUSE TestProxyWriteTimeout/narinfo875=== RUN TestIsValidUploadKey/nar_xz876=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale877=== RUN TestProxyWriteTimeout/1_GiB_nar878=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info879=== PAUSE TestIsValidUploadKey/nar_xz880=== RUN TestPendingClosureWriteTimeout/400_objects881=== RUN TestIsValidUploadKey/nar_plain882=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh883=== PAUSE TestProxyWriteTimeout/1_GiB_nar884=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal885=== PAUSE TestPendingClosureWriteTimeout/400_objects886=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal887=== RUN TestPendingClosureWriteTimeout/670k_objects888=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key889=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key890=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key891=== PAUSE TestPendingClosureWriteTimeout/670k_objects892=== RUN TestProxyWriteTimeout/10_GiB_nar893=== PAUSE TestProxyWriteTimeout/10_GiB_nar894=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline895=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh896=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key897=== PAUSE TestIsValidUploadKey/nar_plain898=== RUN TestIsValidUploadKey/listing899=== PAUSE TestIsValidUploadKey/listing900=== RUN TestProxyWriteTimeout/unknown_size901=== PAUSE TestProxyWriteTimeout/unknown_size902=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit903=== CONT TestDeletePinKeepsRowWhenS3Fails904=== CONT TestSweepSkipsRowsLockedByPush905=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline906=== RUN TestIsValidUploadKey/build_log907=== PAUSE TestIsValidUploadKey/build_log908=== RUN TestIsValidUploadKey/build_log_home-manager_file909=== PAUSE TestIsValidUploadKey/build_log_home-manager_file910=== CONT TestPresentReportsOnlyClosureRoots911=== RUN TestIsValidUploadKey/build_log_plus_in_name912=== PAUSE TestIsValidUploadKey/build_log_plus_in_name913=== RUN TestIsValidUploadKey/build_log_question_mark914=== PAUSE TestIsValidUploadKey/build_log_question_mark915=== RUN TestIsValidUploadKey/build_log_equals916=== PAUSE TestIsValidUploadKey/build_log_equals9172026/10/06 23:00:48 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000918=== RUN TestIsValidUploadKey/realisation919=== PAUSE TestIsValidUploadKey/realisation920=== RUN TestIsValidUploadKey/realisation_plus_in_output921=== PAUSE TestIsValidUploadKey/realisation_plus_in_output922=== RUN TestIsValidUploadKey/nix-cache-info923=== PAUSE TestIsValidUploadKey/nix-cache-info924=== RUN TestIsValidUploadKey/index.html925=== PAUSE TestIsValidUploadKey/index.html926=== RUN TestIsValidUploadKey/narinfo_key,_nar_type927=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type928=== RUN TestIsValidUploadKey/nar_key,_narinfo_type929=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type930=== RUN TestIsValidUploadKey/listing_key,_narinfo_type931=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type932=== RUN TestIsValidUploadKey/traversal933=== PAUSE TestIsValidUploadKey/traversal934=== RUN TestIsValidUploadKey/traversal_nar935=== PAUSE TestIsValidUploadKey/traversal_nar936=== RUN TestIsValidUploadKey/absolute937=== PAUSE TestIsValidUploadKey/absolute938=== RUN TestIsValidUploadKey/empty_key939=== PAUSE TestIsValidUploadKey/empty_key940=== RUN TestIsValidUploadKey/unknown_type941=== PAUSE TestIsValidUploadKey/unknown_type942=== CONT TestCreatePinRejectsBadInput943--- PASS: TestSkippedUploadsHandler (0.04s)944=== CONT TestConcurrentPinUpdatesAgree945=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure946=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure947=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart948=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart949=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts950=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts951=== CONT TestOrphanedObjectsGCStressTest952--- PASS: TestService_ReadAuthMiddleware (0.65s)953=== CONT TestCreatePin_ReservedPins9542026/10/06 23:00:49 INFO Received push request method=POST path=/api/pushes9552026/10/06 23:00:49 INFO Received uploads request method=POST path=/api/pending_closures9562026/10/06 23:00:49 INFO Received uploads request method=POST path=/api/pending_closures9572026/10/06 23:00:49 INFO Received uploads request method=POST path=/api/pending_closures9582026/10/06 23:00:49 INFO Received cleanup request method=DELETE path=/api/pending_closures9592026/10/06 23:00:49 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:37871/oidc9602026/10/06 23:00:49 INFO Aborted multipart uploads count=0 kept=09612026/10/06 23:00:49 INFO Received uploads request method=POST path=/api/pending_closures9622026/10/06 23:00:49 INFO Received cleanup request method=DELETE path=/api/pending_closures9632026/10/06 23:00:49 INFO Aborted multipart uploads count=1 kept=09642026/10/06 23:00:49 INFO Received uploads request method=POST path=/api/pending_closures9652026/10/06 23:00:49 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9662026-10-06 23:00:49.555 UTC [696] ERROR: Closure does not exist: id=19672026-10-06 23:00:49.555 UTC [696] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 12 at RAISE9682026-10-06 23:00:49.555 UTC [696] STATEMENT: -- name: CommitPendingClosure :exec969 SELECT commit_pending_closure($1::bigint)970 971=== CONT TestOrphanedObjectsGC972--- PASS: TestService_cleanupPendingClosuresHandler (0.77s)973=== RUN TestPush_RejectsBadRequests/bad_root974=== PAUSE TestPush_RejectsBadRequests/bad_root975=== RUN TestPush_RejectsBadRequests/root_not_in_objects976=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects977=== RUN TestPush_RejectsBadRequests/no_roots978=== PAUSE TestPush_RejectsBadRequests/no_roots979=== RUN TestPush_RejectsBadRequests/no_objects980=== PAUSE TestPush_RejectsBadRequests/no_objects981=== CONT TestReconnectLeavesObjectsUnlocked9822026/10/06 23:00:49 INFO Received create pin request method=POST path=/api/pins/deploy9832026/10/06 23:00:49 INFO Received create pin request method=POST path=/api/pins/deploy9842026/10/06 23:00:49 INFO Received create pin request method=POST path=/api/pins/deploy9852026/10/06 23:00:49 INFO Received create pin request method=POST path=/api/pins/deploy9862026/10/06 23:00:49 INFO Received create pin request method=POST path=/api/pins/deploy9872026/10/06 23:00:49 INFO Received create pin request method=POST path=/api/pins/deploy9882026/10/06 23:00:49 INFO Received create pin request method=POST path=/api/pins/deploy9892026/10/06 23:00:49 INFO Received create pin request method=POST path=/api/pins/deploy9902026/10/06 23:00:49 INFO Received push request method=POST path=/api/pushes9912026/10/06 23:00:49 INFO Received uploads request method=POST path=/api/pending_closures9922026/10/06 23:00:49 INFO Received create pin request method=POST path=/api/pins/deploy9932026/10/06 23:00:49 INFO Received uploads request method=POST path=/api/pending_closures994--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.91s)995=== CONT TestObjectStatsTrigger9962026/10/06 23:00:49 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9972026/10/06 23:00:49 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst998=== CONT TestObjectStatsLargeCommit999--- PASS: TestCompleteMultipartUnregistered (0.95s)10002026/10/06 23:00:49 INFO Received uploads request method=POST path=/api/pending_closures1001--- PASS: TestPresentReportsOnlyClosureRoots (0.99s)1002=== CONT TestPendingClosureFailureAbortsItsUploads10032026/10/06 23:00:49 INFO Received create pin request method=POST path=/api/pins/app10042026/10/06 23:00:49 INFO Received create pin request method=POST path=/api/pins/app10052026/10/06 23:00:49 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10062026/10/06 23:00:49 INFO Received create pin request method=POST path=/api/pins/app10072026/10/06 23:00:49 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=YWRmMTJmZmQtMWEwMy00Y2IzLTgyODYtYWQxNDM2MDI0YmY5LmY1MjE4MGNiLTNmNGMtNDE0MS04MzNlLTdlYjA1NTFhZmY5ZXgxNzkxMzI3NjQ5ODEyMDc0MDAw10082026/10/06 23:00:49 INFO Created/updated pin name=app store_path=/nix/store/cccccccccccccccccccccccccccccccc-app narinfo_key=cccccccccccccccccccccccccccccccc.narinfo10092026/10/06 23:00:49 INFO Received delete pin request method=DELETE path=/api/pins/app10102026/10/06 23:00:49 ERROR Failed to delete pin from S3 key=pins/app error="Get \"http://127.0.0.1:1/bucket17/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"10112026/10/06 23:00:49 INFO Received delete pin request method=DELETE path=/api/pins/app10122026/10/06 23:00:49 INFO Received push request method=POST path=/api/pushes10132026/10/06 23:00:49 INFO Deleted pin name=app1014--- PASS: TestDeletePinKeepsRowWhenS3Fails (1.10s)1015=== CONT TestPendingClosureFailureTracksEveryUpload1016=== RUN TestPendingClosureFailureTracksEveryUpload/refuse_aborts=false1017=== PAUSE TestPendingClosureFailureTracksEveryUpload/refuse_aborts=false1018=== RUN TestPendingClosureFailureTracksEveryUpload/refuse_aborts=true1019=== PAUSE TestPendingClosureFailureTracksEveryUpload/refuse_aborts=true1020=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded10212026/10/06 23:00:49 INFO Received uploads request method=POST path=/api/pending_closures10222026/10/06 23:00:49 INFO Received push request method=POST path=/api/pushes10232026/10/06 23:00:49 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10242026/10/06 23:00:49 WARN Failed to abort multipart upload key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=YWRmMTJmZmQtMWEwMy00Y2IzLTgyODYtYWQxNDM2MDI0YmY5LmY1MjE4MGNiLTNmNGMtNDE0MS04MzNlLTdlYjA1NTFhZmY5ZXgxNzkxMzI3NjQ5ODEyMDc0MDAw error="Delete \"http://localhost:46519/bucket15/nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst?uploadId=YWRmMTJmZmQtMWEwMy00Y2IzLTgyODYtYWQxNDM2MDI0YmY5LmY1MjE4MGNiLTNmNGMtNDE0MS04MzNlLTdlYjA1NTFhZmY5ZXgxNzkxMzI3NjQ5ODEyMDc0MDAw\": injected: abort refused"10252026/10/06 23:00:49 INFO Signed narinfos id=1 count=110262026/10/06 23:00:49 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10272026/10/06 23:00:49 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10282026/10/06 23:00:49 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10292026/10/06 23:00:49 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"10302026/10/06 23:00:49 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10312026/10/06 23:00:49 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"10322026/10/06 23:00:49 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10332026/10/06 23:00:49 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=110342026/10/06 23:00:49 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10352026/10/06 23:00:49 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo10362026/10/06 23:00:50 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=YWRmMTJmZmQtMWEwMy00Y2IzLTgyODYtYWQxNDM2MDI0YmY5LmY1MjE4MGNiLTNmNGMtNDE0MS04MzNlLTdlYjA1NTFhZmY5ZXgxNzkxMzI3NjQ5ODEyMDc0MDAw10372026/10/06 23:00:50 INFO Received uploads request method=POST path=/api/pending_closures10382026/10/06 23:00:50 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=YWRmMTJmZmQtMWEwMy00Y2IzLTgyODYtYWQxNDM2MDI0YmY5LmY1MjE4MGNiLTNmNGMtNDE0MS04MzNlLTdlYjA1NTFhZmY5ZXgxNzkxMzI3NjQ5ODEyMDc0MDAw parts=11039--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (1.21s)1040=== CONT TestMultipartCleanup10412026/10/06 23:00:50 INFO Received uploads request method=POST path=/api/pending_closures10422026/10/06 23:00:50 INFO Received uploads request method=POST path=/api/pending_closures1043--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (1.23s)1044=== CONT TestPendingCleanupUsesOneCutoff10452026/10/06 23:00:50 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10462026/10/06 23:00:50 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst10472026/10/06 23:00:50 INFO Received uploads request method=POST path=/api/pending_closures10482026/10/06 23:00:50 INFO Received push request method=POST path=/api/pushes1049--- PASS: TestPresignedUploadRegisteredBeforeCommit (1.28s)1050=== CONT TestServerTLSConfig1051=== RUN TestServerTLSConfig/no_client_CA1052=== PAUSE TestServerTLSConfig/no_client_CA1053=== RUN TestServerTLSConfig/missing_CA_file1054=== PAUSE TestServerTLSConfig/missing_CA_file1055=== RUN TestServerTLSConfig/not_a_PEM_file1056=== PAUSE TestServerTLSConfig/not_a_PEM_file1057=== CONT TestMetricsInventory10582026/10/06 23:00:50 INFO Aborted multipart uploads count=0 kept=010592026/10/06 23:00:50 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10602026/10/06 23:00:50 WARN Force mode enabled - objects will be deleted immediately without grace period1061--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (1.33s)1062=== CONT TestNARDeduplicationMetadataUploadBug10632026/10/06 23:00:50 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=010642026/10/06 23:00:50 INFO Vacuumed table table=pending_closures10652026/10/06 23:00:50 INFO Vacuumed table table=pending_objects10662026/10/06 23:00:50 INFO Vacuumed table table=multipart_uploads1067--- PASS: TestService_Rustfstest (1.33s)1068=== CONT TestCreatePendingClosureRejectsOversizedNAR10692026/10/06 23:00:50 INFO Vacuumed table table=closures10702026/10/06 23:00:50 INFO Received uploads request method=POST path=/api/pending_closures1071--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1072=== CONT TestService_NativeMTLS10732026/10/06 23:00:50 INFO Vacuumed table table=objects10742026/10/06 23:00:50 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10752026/10/06 23:00:50 INFO Aborted multipart uploads count=0 kept=010762026/10/06 23:00:50 WARN Force mode enabled - objects will be deleted immediately without grace period10772026/10/06 23:00:50 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=YWRmMTJmZmQtMWEwMy00Y2IzLTgyODYtYWQxNDM2MDI0YmY5LjAyZTEyMjZjLTg2MDMtNDdhMy04MDBkLTMxYTM1OWUyNTMxMXgxNzkxMzI3NjQ5NTAyOTIzMjM0 parts=1010782026/10/06 23:00:50 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10792026/10/06 23:00:50 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux10802026/10/06 23:00:50 WARN Refused reserved pin name=worker-x86_64-linux10812026/10/06 23:00:50 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux10822026/10/06 23:00:50 INFO Received create pin request method=POST path=/api/pins/my-app10832026/10/06 23:00:50 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux10842026/10/06 23:00:50 INFO Completed upload id=110852026/10/06 23:00:50 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000010862026/10/06 23:00:50 INFO Received uploads request method=POST path=/api/pending_closures10872026/10/06 23:00:50 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=1 objects-failed-to-delete=010882026/10/06 23:00:50 INFO Vacuumed table table=pending_closures10892026/10/06 23:00:50 INFO Vacuumed table table=pending_objects10902026/10/06 23:00:50 INFO Vacuumed table table=multipart_uploads10912026/10/06 23:00:50 INFO Vacuumed table table=closures10922026/10/06 23:00:50 INFO Starting cleanup of old closures method=DELETE path=/api/closures10932026/10/06 23:00:50 INFO Vacuumed table table=objects10942026/10/06 23:00:50 INFO Completed multipart upload object_key=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa00000000000000000000.nar.zst upload_id=YWRmMTJmZmQtMWEwMy00Y2IzLTgyODYtYWQxNDM2MDI0YmY5LjYyMWY5MzJiLTE1N2YtNDY0NC1iNTliLTA5ZTk5M2I1YTIwN3gxNzkxMzI3NjQ5NDc3ODM5NDky parts=1010952026/10/06 23:00:50 INFO Aborted multipart uploads count=0 kept=01096--- PASS: TestCreatePin_ReservedPins (0.73s)1097=== CONT TestService_readinessHandler10982026/10/06 23:00:50 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=010992026/10/06 23:00:50 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11002026/10/06 23:00:50 INFO Vacuumed table table=pending_closures1101--- PASS: TestSweepSkipsRowsLockedByPush (1.39s)1102=== CONT TestDeleteClosuresRacingPins11032026/10/06 23:00:50 INFO Vacuumed table table=pending_objects11042026/10/06 23:00:50 INFO Vacuumed table table=multipart_uploads11052026/10/06 23:00:50 INFO Vacuumed table table=closures11062026/10/06 23:00:50 INFO Vacuumed table table=objects11072026/10/06 23:00:50 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000011082026/10/06 23:00:50 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=YWRmMTJmZmQtMWEwMy00Y2IzLTgyODYtYWQxNDM2MDI0YmY5LmQ1Mzc0NWJjLTBkYTAtNGNlZS1hYTdmLTQ5NDMyNjNiMTUzOXgxNzkxMzI3NjQ5NTYzMjIzODYw parts=1011092026/10/06 23:00:50 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete1110--- PASS: TestService_createPendingClosureHandler (1.44s)11112026/10/06 23:00:50 INFO Completed upload id=11112=== CONT TestService_healthCheckHandler11132026/10/06 23:00:50 INFO Received uploads request method=POST path=/api/pending_closures11142026/10/06 23:00:50 INFO Received create pin request method=POST path=/api/pins/deploy11152026/10/06 23:00:50 INFO Received uploads request method=POST path=/api/pending_closures11162026/10/06 23:00:50 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo11172026/10/06 23:00:50 WARN Found objects in DB but missing from S3, will re-upload count=111182026/10/06 23:00:50 INFO Created/updated pin name=deploy store_path="/nix/store/dddddddddddddddddddddddddddddddd-app-1.0+git_x?y=z" narinfo_key=dddddddddddddddddddddddddddddddd.narinfo1119=== CONT TestGracefulShutdownDrainsInflight1120--- PASS: TestReconnectLeavesObjectsUnlocked (0.69s)11212026/10/06 23:00:50 INFO Starting HTTP server address=127.0.0.1:4123911222026/10/06 23:00:50 INFO Shutdown signal received, draining in-flight requests timeout=10s11232026/10/06 23:00:50 INFO Received complete upload request method=POST path=/api/pending_closures/3/complete11242026/10/06 23:00:50 INFO Completed upload id=311252026/10/06 23:00:50 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1126--- PASS: TestCreatePinRejectsBadInput (1.47s)1127=== CONT TestFailedS3DeleteKeepsTombstone1128--- PASS: TestObjectStatsTrigger (0.58s)1129=== CONT TestGCTaskStore_Fail1130--- PASS: TestGCTaskStore_Fail (0.00s)1131=== CONT TestRegisterCompletedObjectNeedsPendingRow1132--- PASS: TestService_verifyS3Integrity (1.49s)1133=== CONT TestGCTaskStore_GetReturnsLatest1134--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1135=== CONT TestGCTaskStore_CompletedAllowsNewTask1136=== CONT TestPushWaitsForSweepHoldingRow1137--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)11382026/10/06 23:00:50 INFO Received uploads request method=POST path=/api/pending_closures1139--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1140=== CONT TestGCEndsOnShutdown1141=== RUN TestGCEndsOnShutdown/before_the_run1142=== PAUSE TestGCEndsOnShutdown/before_the_run1143=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1144=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1145=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1146=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1147=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection11482026/10/06 23:00:50 INFO Completed multipart upload object_key=nar/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb00000000000000000000.nar.zst upload_id=YWRmMTJmZmQtMWEwMy00Y2IzLTgyODYtYWQxNDM2MDI0YmY5LmFmZDFhNzA4LTNlOTYtNDMwYy05ODA0LWJiZTU5N2ExOGJmMHgxNzkxMzI3NjQ5NjUzNDcyODk1 parts=1011492026/10/06 23:00:50 INFO Received uploads request method=POST path=/api/pending_closures11502026/10/06 23:00:50 INFO Created/updated pin name=app store_path=/nix/store/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa-app narinfo_key=aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.narinfo11512026/10/06 23:00:50 INFO Created/updated pin name=app store_path=/nix/store/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb-app narinfo_key=bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb.narinfo11522026/10/06 23:00:50 INFO Received uploads request method=POST path=/api/pending_closures1153=== CONT TestGCTaskStore_StartNew1154--- PASS: TestConcurrentPinUpdatesAgree (1.55s)1155=== CONT TestDeduplicatedObjectsRecordedAsPending1156--- PASS: TestGCTaskStore_StartNew (0.00s)1157--- PASS: TestPendingClosureFailureAbortsItsUploads (0.59s)1158=== CONT TestGCTaskStore_DeduplicateSameParams1159=== CONT TestGCMetrics1160--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)11612026/10/06 23:00:50 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1162--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (0.49s)1163=== CONT TestLeadElectsOneAndHandsOver11642026/10/06 23:00:50 INFO Received uploads request method=POST path=/api/pending_closures11652026/10/06 23:00:50 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=YWRmMTJmZmQtMWEwMy00Y2IzLTgyODYtYWQxNDM2MDI0YmY5Ljc3NDcyMWZlLTYwOTctNGZmMC1iMDdjLWIxYTI5OTlkZmJkMngxNzkxMzI3NjQ5NzEzODI0MDYx parts=1211662026/10/06 23:00:50 INFO Received uploads request method=POST path=/api/pending_closures11672026/10/06 23:00:50 INFO Received uploads request method=POST path=/api/pending_closures1168--- PASS: TestCompletedNarNotReofferedAcrossClosures (1.77s)1169=== CONT TestConnectWaitsForAPeerMigration11702026/10/06 23:00:50 INFO Received cleanup request method=DELETE path=/api/pending_closures11712026/10/06 23:00:50 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11722026/10/06 23:00:50 INFO Completed multipart upload object_key=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa00000000000000000000.nar.zst upload_id=YWRmMTJmZmQtMWEwMy00Y2IzLTgyODYtYWQxNDM2MDI0YmY5LjdhYmM3MTIwLWU3ZGItNGE1MS04N2Y3LWQ4MDU3N2Q1MGVkZHgxNzkxMzI3NjQ5OTAzMDc3NjQ0 parts=1011732026/10/06 23:00:50 WARN mTLS auth: subject not in bound subjects subject="CN=reader"11742026/10/06 23:00:50 WARN mTLS auth: subject not in bound subjects subject="CN=reader"11752026/10/06 23:00:50 INFO Received cleanup request method=DELETE path=/api/pending_closures11762026/10/06 23:00:50 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket34/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""11772026/10/06 23:00:50 INFO Aborted multipart uploads count=0 kept=11178=== NAME TestNARDeduplicationMetadataUploadBug1179 metadata_upload_test.go:48: First store path: /build/TestNARDeduplicationMetadataUploadBug3061945893/001/store/nw5c48xs208d3jqha1q748brdh5l5nhq-file1.txt1180--- PASS: TestService_NativeMTLS (0.52s)1181=== CONT TestGCSweepSkipsPendingObjects11822026/10/06 23:00:50 INFO Received cleanup request method=DELETE path=/api/pending_closures11832026/10/06 23:00:50 INFO Aborted multipart uploads count=1 kept=01184--- PASS: TestMetricsInventory (0.58s)1185=== CONT TestSweepRechecksPendingAfterLocking1186=== NAME TestOrphanedObjectsGC1187 orphaned_objects_gc_test.go:287: GC Test Summary:1188 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A1189 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B1190 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)1191 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)1192 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects1193--- PASS: TestMultipartCleanup (0.68s)1194=== CONT TestReadProxyInvalidPath11952026/10/06 23:00:50 WARN readiness check failed error="closed pool"1196--- PASS: TestOrphanedObjectsGC (1.14s)1197=== CONT TestPush_CompleteCommitsEveryRoot1198--- PASS: TestService_readinessHandler (0.54s)1199=== CONT TestClientErrorHandling1200=== RUN TestClientErrorHandling/InvalidStorePath1201=== PAUSE TestClientErrorHandling/InvalidStorePath1202=== RUN TestClientErrorHandling/InvalidAuthToken1203=== PAUSE TestClientErrorHandling/InvalidAuthToken1204=== RUN TestClientErrorHandling/ServerNotAvailable1205=== PAUSE TestClientErrorHandling/ServerNotAvailable1206=== CONT TestCommitRacingPendingCleanupKeepsObjects12072026/10/06 23:00:50 INFO Received push request method=POST path=/api/pushes12082026/10/06 23:00:50 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12092026/10/06 23:00:50 INFO Uploading nw5c48xs208d3jqha1q748brdh5l5nhq-file1.txt (160B)1210--- PASS: TestService_healthCheckHandler (0.53s)1211=== CONT TestReadProxyDisabled12122026/10/06 23:00:50 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"12132026/10/06 23:00:50 WARN Failed to register uploaded object key=nw5c48xs208d3jqha1q748brdh5l5nhq.ls error="server returned 404: 404 page not found\n"12142026/10/06 23:00:50 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12152026/10/06 23:00:50 INFO Signed narinfos id=1 count=112162026/10/06 23:00:50 INFO Uploading 1 narinfos1217--- PASS: TestRegisterCompletedObjectNeedsPendingRow (0.52s)1218=== CONT TestReadProxyNarinfoAlreadyDecompressed12192026/10/06 23:00:50 WARN Failed to register uploaded object key=nw5c48xs208d3jqha1q748brdh5l5nhq.narinfo error="server returned 404: 404 page not found\n"12202026/10/06 23:00:50 INFO Received complete push request method=POST path=/api/pushes/1/complete12212026/10/06 23:00:50 INFO Completed push id=112222026/10/06 23:00:50 INFO Upload complete. (147ms)12232026/10/06 23:00:50 INFO Received uploads request method=POST path=/api/pending_closures1224=== NAME TestNARDeduplicationMetadataUploadBug1225 metadata_upload_test.go:54: Retrieved narinfo from S3:1226 StorePath: /build/TestNARDeduplicationMetadataUploadBug3061945893/001/store/nw5c48xs208d3jqha1q748brdh5l5nhq-file1.txt1227 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1228 Compression: zstd1229 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1230 NarSize: 1601231 References: 1232 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf12332026/10/06 23:00:50 INFO Received uploads request method=POST path=/api/pending_closures1234 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1235 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1236 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}12372026/10/06 23:00:50 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1238 metadata_upload_test.go:64: Second store path (same content): /build/TestNARDeduplicationMetadataUploadBug3061945893/001/store/plz2h573yrn3799lkqkifnk6mmzhjb1v-file2.txt12392026/10/06 23:00:50 INFO Received uploads request method=POST path=/api/pending_closures12402026/10/06 23:00:50 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=YWRmMTJmZmQtMWEwMy00Y2IzLTgyODYtYWQxNDM2MDI0YmY5LjNmYTMwYjljLTQwMzEtNDU1Ny1hODQ1LThjMjBkYzBjOTgwZngxNzkxMzI3NjUwMDE3ODYyMDAw parts=1212412026/10/06 23:00:50 INFO Received uploads request method=POST path=/api/pending_closures12422026/10/06 23:00:50 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12432026/10/06 23:00:50 INFO Received uploads request method=POST path=/api/pending_closures12442026/10/06 23:00:50 INFO Completed multipart upload object_key=nar/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb00000000000000000000.nar.zst upload_id=YWRmMTJmZmQtMWEwMy00Y2IzLTgyODYtYWQxNDM2MDI0YmY5LjA2MjNjZGJmLTZhODUtNDE0ZS04MDNmLTZjZjUzZDI3NTUwYXgxNzkxMzI3NjQ5NDc3MDQ3MjMz parts=1012452026/10/06 23:00:50 INFO Received complete push request method=POST path=/api/pushes/1/complete12462026/10/06 23:00:50 INFO Aborted multipart uploads count=0 kept=012472026/10/06 23:00:50 INFO Completed push id=112482026/10/06 23:00:50 WARN Force mode enabled - objects will be deleted immediately without grace period12492026/10/06 23:00:50 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=012502026/10/06 23:00:50 INFO Vacuumed table table=pending_closures12512026/10/06 23:00:50 INFO Vacuumed table table=pending_objects12522026/10/06 23:00:50 INFO Vacuumed table table=multipart_uploads12532026/10/06 23:00:50 INFO Vacuumed table table=closures12542026/10/06 23:00:50 INFO Vacuumed table table=objects12552026/10/06 23:00:50 INFO Aborted multipart uploads count=0 kept=012562026/10/06 23:00:50 WARN Force mode enabled - objects will be deleted immediately without grace period12572026/10/06 23:00:50 INFO Received uploads request method=POST path=/api/pending_closures12582026/10/06 23:00:50 INFO Received push request method=POST path=/api/pushes12592026/10/06 23:00:50 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."12602026/10/06 23:00:50 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."12612026/10/06 23:00:50 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)1262--- PASS: TestPush_RepeatedRootCommitsOnce (2.17s)1263=== CONT TestPresentRefreshesOnlyStaleClosures12642026/10/06 23:00:50 INFO lead: acquired remote=192.0.2.1:12341265--- PASS: TestDeduplicatedObjectsRecordedAsPending (0.60s)1266=== CONT TestService_AuthMiddleware_MTLSBoundSubjects1267--- PASS: TestFailedS3DeleteKeepsTombstone (0.70s)1268=== CONT TestParseSingleRange1269=== RUN TestParseSingleRange/none1270=== PAUSE TestParseSingleRange/none1271=== RUN TestParseSingleRange/unknown_unit1272=== PAUSE TestParseSingleRange/unknown_unit1273=== RUN TestParseSingleRange/multi-range_ignored1274=== PAUSE TestParseSingleRange/multi-range_ignored1275=== RUN TestParseSingleRange/malformed_no_dash1276=== PAUSE TestParseSingleRange/malformed_no_dash1277=== RUN TestParseSingleRange/malformed_both_empty1278=== PAUSE TestParseSingleRange/malformed_both_empty1279=== RUN TestParseSingleRange/malformed_end_before_start1280=== PAUSE TestParseSingleRange/malformed_end_before_start1281=== RUN TestParseSingleRange/closed1282=== PAUSE TestParseSingleRange/closed1283=== RUN TestParseSingleRange/open-ended1284=== PAUSE TestParseSingleRange/open-ended1285=== RUN TestParseSingleRange/end_clamped_to_size1286=== PAUSE TestParseSingleRange/end_clamped_to_size1287=== RUN TestParseSingleRange/suffix1288=== PAUSE TestParseSingleRange/suffix1289=== RUN TestParseSingleRange/suffix_exceeds_size1290=== PAUSE TestParseSingleRange/suffix_exceeds_size1291=== RUN TestParseSingleRange/single_byte1292=== PAUSE TestParseSingleRange/single_byte12932026/10/06 23:00:51 WARN Failed to register uploaded object key=plz2h573yrn3799lkqkifnk6mmzhjb1v.ls error="server returned 404: 404 page not found\n"1294=== RUN TestParseSingleRange/start_past_EOF1295=== PAUSE TestParseSingleRange/start_past_EOF1296=== RUN TestParseSingleRange/start_far_past_EOF1297=== PAUSE TestParseSingleRange/start_far_past_EOF12982026/10/06 23:00:51 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign1299=== CONT TestPushDedupSurvivesConcurrentGC13002026/10/06 23:00:51 INFO Signed narinfos id=2 count=113012026/10/06 23:00:51 INFO Uploading 1 narinfos13022026/10/06 23:00:51 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1303--- PASS: TestGCMetrics (0.61s)1304=== CONT TestPush_CompleteWaitsForCleanupOfThePush13052026/10/06 23:00:51 INFO Received complete push request method=POST path=/api/pushes/2/complete13062026/10/06 23:00:51 WARN Failed to register uploaded object key=plz2h573yrn3799lkqkifnk6mmzhjb1v.narinfo error="server returned 404: 404 page not found\n"13072026/10/06 23:00:51 INFO Completed push id=213082026/10/06 23:00:51 INFO Received uploads request method=POST path=/api/pending_closures13092026/10/06 23:00:51 INFO Upload complete. (93ms)1310=== NAME TestNARDeduplicationMetadataUploadBug1311 metadata_upload_test.go:76: Retrieved narinfo from S3:1312 StorePath: /build/TestNARDeduplicationMetadataUploadBug3061945893/001/store/plz2h573yrn3799lkqkifnk6mmzhjb1v-file2.txt1313 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1314 Compression: zstd1315 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1316 NarSize: 1601317 References: 1318 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf13192026/10/06 23:00:51 INFO Completed multipart upload object_key=nar/cccccccccccccccccccccccccccccccc00000000000000000000.nar.zst upload_id=YWRmMTJmZmQtMWEwMy00Y2IzLTgyODYtYWQxNDM2MDI0YmY5LjNjYTAxNDExLWNjNWEtNDllNy1hMjRhLWQ5YTBkOTEwODcxM3gxNzkxMzI3NjQ5NjU1MzA2NTk0 parts=101320 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1321 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1322 {"version":1,"root":{"type":"regular","size":44}}13232026/10/06 23:00:51 INFO Aborted multipart uploads count=0 kept=013242026/10/06 23:00:51 WARN Force mode enabled - objects will be deleted immediately without grace period1325=== CONT TestForceGCDuringPushOffersSweptObject13262026/10/06 23:00:51 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=01327--- PASS: TestNARDeduplicationMetadataUploadBug (0.95s)1328=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows1329=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows1330=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check1331=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check1332=== CONT TestGCTaskStore_GetEmpty1333=== CONT TestTombstonedObjectOfferedWithoutWaiting1334--- PASS: TestGCTaskStore_GetEmpty (0.00s)13352026/10/06 23:00:51 INFO Vacuumed table table=pending_closures13362026/10/06 23:00:51 INFO Aborted multipart uploads count=0 kept=013372026/10/06 23:00:51 INFO Vacuumed table table=pending_objects13382026/10/06 23:00:51 INFO Vacuumed table table=multipart_uploads13392026/10/06 23:00:51 INFO Vacuumed table table=closures13402026/10/06 23:00:51 WARN Force mode enabled - objects will be deleted immediately without grace period13412026/10/06 23:00:51 INFO Vacuumed table table=objects1342--- PASS: TestReadProxyInvalidPath (0.43s)1343=== CONT TestGCTaskStore_ConflictDifferentParams1344--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1345=== CONT TestGCSweepDeliversEachKeyOnce13462026/10/06 23:00:51 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=01347--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (0.80s)1348=== CONT TestGCTaskStore_PhaseUpdates1349--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1350=== CONT TestGCAdvisoryLockBlocksConcurrentRun13512026/10/06 23:00:51 INFO Vacuumed table table=pending_closures13522026/10/06 23:00:51 INFO Received push request method=POST path=/api/pushes13532026/10/06 23:00:51 INFO Vacuumed table table=pending_objects13542026/10/06 23:00:51 INFO Vacuumed table table=multipart_uploads13552026/10/06 23:00:51 INFO Vacuumed table table=closures13562026/10/06 23:00:51 INFO Vacuumed table table=objects1357--- PASS: TestGCSweepSkipsPendingObjects (0.49s)1358=== CONT TestConnectSerialisesConcurrentMigrations13592026/10/06 23:00:51 INFO Aborted multipart uploads count=0 kept=01360--- PASS: TestSweepRechecksPendingAfterLocking (0.50s)1361=== CONT TestResolveDBConnectionString1362=== RUN TestResolveDBConnectionString/flag_wins1363=== PAUSE TestResolveDBConnectionString/flag_wins1364=== RUN TestResolveDBConnectionString/file_when_flag_empty1365=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1366=== RUN TestResolveDBConnectionString/missing_file_is_an_error1367=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1368=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1369=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1370=== RUN TestResolveDBConnectionString/nothing_configured1371=== PAUSE TestResolveDBConnectionString/nothing_configured1372=== CONT TestGenerateLandingPage13732026/10/06 23:00:51 WARN Force mode enabled - objects will be deleted immediately without grace period13742026/10/06 23:00:51 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=01375--- PASS: TestGenerateLandingPage (0.01s)1376=== CONT TestGCBugBareHashReferences13772026/10/06 23:00:51 INFO Vacuumed table table=pending_closures1378--- PASS: TestReadProxyDisabled (0.41s)1379=== CONT TestCacheConfigHandlerMaxNarSize1380--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1381=== CONT TestLeadIncumbentAnnouncesAtOnce13822026/10/06 23:00:51 INFO Vacuumed table table=pending_objects13832026/10/06 23:00:51 INFO Vacuumed table table=multipart_uploads13842026/10/06 23:00:51 INFO Vacuumed table table=closures13852026/10/06 23:00:51 INFO Vacuumed table table=objects13862026/10/06 23:00:51 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1387--- PASS: TestCommitRacingPendingCleanupKeepsObjects (0.51s)1388=== CONT TestLeadEndsOnShutdown1389=== CONT TestReadProxyRangeRequest1390--- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.42s)13912026/10/06 23:00:51 INFO Completed multipart upload object_key=nar/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb00000000000000000000.nar.zst upload_id=YWRmMTJmZmQtMWEwMy00Y2IzLTgyODYtYWQxNDM2MDI0YmY5LmViZDY3MzlmLTYzZTMtNDY2Zi1iZDA4LTQ3ZjBhMzdhODhlYngxNzkxMzI3NjQ5OTA0MzQ5MDEz parts=1013922026/10/06 23:00:51 INFO Received complete push request method=POST path=/api/pushes/1/complete13932026/10/06 23:00:51 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"13942026/10/06 23:00:51 WARN mTLS auth: bound subjects configured but subject DN unavailable13952026/10/06 23:00:51 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"13962026-10-06 23:00:51.276 UTC [1045] ERROR: duplicate key value violates unique constraint "pg_type_typname_nsp_index"13972026-10-06 23:00:51.276 UTC [1045] DETAIL: Key (typname, typnamespace)=(goose_db_version, 2200) already exists.13982026-10-06 23:00:51.276 UTC [1045] STATEMENT: CREATE TABLE goose_db_version (1399 id integer PRIMARY KEY GENERATED BY DEFAULT AS IDENTITY,1400 version_id bigint NOT NULL,1401 is_applied boolean NOT NULL,1402 tstamp timestamp NOT NULL DEFAULT now()1403 )14042026/10/06 23:00:51 INFO Completed push id=114052026/10/06 23:00:51 INFO Received push request method=POST path=/api/pushes1406=== CONT TestReadRedirectUsesPublicS3URL1407--- PASS: TestPresentRefreshesOnlyStaleClosures (0.31s)1408--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.30s)1409=== CONT TestReadProxyRootRedirectsToIndexHTML14102026/10/06 23:00:51 INFO Received push request method=POST path=/api/pushes14112026/10/06 23:00:51 INFO Aborted multipart uploads count=0 kept=01412=== CONT TestReadRedirectKeepsNarinfoProxied1413--- PASS: TestPushWaitsForSweepHoldingRow (1.08s)14142026/10/06 23:00:51 WARN Force mode enabled - objects will be deleted immediately without grace period14152026/10/06 23:00:51 INFO Received uploads request method=POST path=/api/pending_closures14162026/10/06 23:00:51 INFO Received uploads request method=POST path=/api/pending_closures14172026/10/06 23:00:51 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=014182026/10/06 23:00:51 INFO Vacuumed table table=pending_closures1419--- PASS: TestTombstonedObjectOfferedWithoutWaiting (0.33s)1420=== CONT TestReadProxyConditionalGet14212026/10/06 23:00:51 INFO Vacuumed table table=pending_objects14222026/10/06 23:00:51 INFO Vacuumed table table=multipart_uploads14232026/10/06 23:00:51 INFO Vacuumed table table=closures14242026/10/06 23:00:51 INFO Vacuumed table table=objects14252026/10/06 23:00:51 INFO Aborted multipart uploads count=0 kept=014262026/10/06 23:00:51 INFO Aborted multipart uploads count=0 kept=014272026/10/06 23:00:51 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=014282026/10/06 23:00:51 WARN Force mode enabled - objects will be deleted immediately without grace period14292026/10/06 23:00:51 INFO Vacuumed table table=pending_closures14302026/10/06 23:00:51 INFO Vacuumed table table=pending_objects14312026/10/06 23:00:51 INFO Vacuumed table table=multipart_uploads14322026/10/06 23:00:51 INFO Vacuumed table table=closures14332026/10/06 23:00:51 INFO Vacuumed table table=objects14342026/10/06 23:00:51 INFO lead: acquired remote=192.0.2.1:123414352026/10/06 23:00:51 INFO lead: released remote=192.0.2.1:123414362026/10/06 23:00:51 INFO Aborted multipart uploads count=0 kept=014372026/10/06 23:00:51 WARN Force mode enabled - objects will be deleted immediately without grace period14382026/10/06 23:00:51 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=01439--- PASS: TestLeadIncumbentAnnouncesAtOnce (0.32s)1440=== CONT TestReadProxyHead14412026/10/06 23:00:51 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=014422026/10/06 23:00:51 INFO Vacuumed table table=pending_closures14432026/10/06 23:00:51 INFO Vacuumed table table=pending_objects14442026/10/06 23:00:51 INFO Vacuumed table table=multipart_uploads14452026/10/06 23:00:51 INFO Vacuumed table table=closures14462026/10/06 23:00:51 INFO Vacuumed table table=pending_closures14472026/10/06 23:00:51 INFO Vacuumed table table=pending_objects14482026/10/06 23:00:51 INFO Vacuumed table table=multipart_uploads14492026/10/06 23:00:51 INFO Vacuumed table table=objects14502026/10/06 23:00:51 INFO Vacuumed table table=closures14512026/10/06 23:00:51 INFO lead: acquired remote=192.0.2.1:123414522026/10/06 23:00:51 INFO Vacuumed table table=objects1453--- PASS: TestGCSweepDeliversEachKeyOnce (0.41s)1454=== CONT TestReadRedirectNar1455--- PASS: TestPushDedupSurvivesConcurrentGC (0.55s)1456=== CONT TestGetExistingObjectsLocksRows1457--- PASS: TestObjectStatsLargeCommit (1.82s)1458=== CONT TestReadProxyOutlastsServerWriteTimeout1459--- PASS: TestReadProxyRangeRequest (0.34s)1460=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock1461=== CONT TestService_RequireScope_OIDC1462--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.34s)14632026/10/06 23:00:51 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14642026/10/06 23:00:51 INFO Completed multipart upload object_key=nar/ffffffffffffffffffffffffffffffff00000000000000000000.nar.zst upload_id=YWRmMTJmZmQtMWEwMy00Y2IzLTgyODYtYWQxNDM2MDI0YmY5LmRkY2UzM2M0LTg1N2EtNDJkZi04NzVjLTRkMWRlZjkyYzcwNXgxNzkxMzI3NjQ5NjU1MTUyODQ0 parts=101465--- PASS: TestReadRedirectUsesPublicS3URL (0.41s)1466=== CONT TestProxyHeadersOnlyTrustedOnSocket14672026/10/06 23:00:51 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1468=== CONT TestClientPushesUseOnePush1469--- PASS: TestGCBugBareHashReferences (0.55s)14702026/10/06 23:00:51 ERROR failed to check GC advisory lock error="query pg_locks: failed to connect to `user=nixbld database=niks3`: /nonexistent/.s.PGSQL.5432 (/nonexistent): dial error: dial unix /nonexistent/.s.PGSQL.5432: connect: no such file or directory"14712026/10/06 23:00:51 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=YWRmMTJmZmQtMWEwMy00Y2IzLTgyODYtYWQxNDM2MDI0YmY5LjMzNjhjZTlkLTI3NmYtNDcxZi1iOWRkLTBjNzk2ZGZmYmZiMngxNzkxMzI3NjUwOTI3NjA1MDAw error="Get \"http://127.0.0.1:1/bucket22/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"14722026/10/06 23:00:51 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=YWRmMTJmZmQtMWEwMy00Y2IzLTgyODYtYWQxNDM2MDI0YmY5LmU0MzkyMzFjLTVlZTItNDA3OS04YmRjLWJlODEwN2Y0MTAwM3gxNzkxMzI3NjUwOTA4NjQ4ODM0 parts=1214732026/10/06 23:00:51 INFO Received cleanup request method=DELETE path=/api/pending_closures14742026/10/06 23:00:51 INFO Aborted multipart uploads count=1 kept=01475--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.66s)1476=== CONT TestCacheConfigHandler1477=== RUN TestCacheConfigHandler/full_config,_no_issuer1478=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1479=== RUN TestCacheConfigHandler/no_cache_url_configured1480=== PAUSE TestCacheConfigHandler/no_cache_url_configured1481=== RUN TestCacheConfigHandler/no_signing_keys1482=== PAUSE TestCacheConfigHandler/no_signing_keys1483=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1484=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1485=== CONT TestService_ReadScope_PublicByDefault1486--- PASS: TestRedundantMultipartUpload (3.02s)1487=== CONT TestPinProtectsFromGC14882026/10/06 23:00:51 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14892026/10/06 23:00:51 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:37493/oidc1490--- PASS: TestReadRedirectNar (0.34s)1491=== CONT TestClientSharedPathCommittedMidPush1492--- PASS: TestReadRedirectKeepsNarinfoProxied (0.51s)1493=== CONT TestCacheStatsHandler14942026/10/06 23:00:51 INFO Completed multipart upload object_key=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa00000000000000000000.nar.zst upload_id=YWRmMTJmZmQtMWEwMy00Y2IzLTgyODYtYWQxNDM2MDI0YmY5LjJiMDk0MzI5LWY3Y2YtNGMxZS04Y2VhLWVjMWJlNjI5ODlkYXgxNzkxMzI3NjUxMTUyODc4NDk2 parts=101495=== CONT TestIsValidCachePath1496--- PASS: TestReadProxyConditionalGet (0.53s)1497=== RUN TestIsValidCachePath/narinfo1498=== PAUSE TestIsValidCachePath/narinfo1499=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1500=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1501=== RUN TestIsValidCachePath/nar_zst1502=== PAUSE TestIsValidCachePath/nar_zst1503=== RUN TestIsValidCachePath/nar_xz1504=== PAUSE TestIsValidCachePath/nar_xz1505=== RUN TestIsValidCachePath/nar_bz21506=== PAUSE TestIsValidCachePath/nar_bz21507=== RUN TestIsValidCachePath/nar_uncompressed1508=== PAUSE TestIsValidCachePath/nar_uncompressed1509=== RUN TestIsValidCachePath/ls1510=== PAUSE TestIsValidCachePath/ls1511=== RUN TestIsValidCachePath/log1512=== PAUSE TestIsValidCachePath/log1513=== RUN TestIsValidCachePath/realisation1514=== PAUSE TestIsValidCachePath/realisation1515=== RUN TestIsValidCachePath/nix-cache-info1516=== PAUSE TestIsValidCachePath/nix-cache-info1517=== RUN TestIsValidCachePath/index.html1518=== PAUSE TestIsValidCachePath/index.html1519=== RUN TestIsValidCachePath/traversal_parent1520=== PAUSE TestIsValidCachePath/traversal_parent1521=== RUN TestIsValidCachePath/traversal_in_middle1522=== PAUSE TestIsValidCachePath/traversal_in_middle1523=== RUN TestIsValidCachePath/invalid_char_e1524=== PAUSE TestIsValidCachePath/invalid_char_e1525=== RUN TestIsValidCachePath/invalid_char_u1526=== PAUSE TestIsValidCachePath/invalid_char_u1527=== RUN TestIsValidCachePath/random_path1528=== PAUSE TestIsValidCachePath/random_path1529=== RUN TestIsValidCachePath/empty1530=== PAUSE TestIsValidCachePath/empty1531=== RUN TestIsValidCachePath/leading_slash1532=== PAUSE TestIsValidCachePath/leading_slash1533=== RUN TestIsValidCachePath/wrong_extension1534=== PAUSE TestIsValidCachePath/wrong_extension1535=== RUN TestIsValidCachePath/short_hash1536=== PAUSE TestIsValidCachePath/short_hash1537=== CONT TestService_AuthMiddleware_OIDC15382026/10/06 23:00:51 INFO Starting HTTP server address=127.0.0.1:4147315392026/10/06 23:00:51 INFO Starting HTTP server address=/build/TestProxyHeadersOnlyTrustedOnSocket3877839306/001/proxy.sock15402026/10/06 23:00:51 WARN mTLS auth: subject not in bound subjects subject="CN=someone"1541--- PASS: TestGetExistingObjectsLocksRows (0.41s)1542=== CONT TestReadProxy40415432026/10/06 23:00:51 INFO Shutdown signal received, draining in-flight requests timeout=10s1544--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.28s)1545=== CONT TestClientWithDependencies15462026/10/06 23:00:52 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1547=== CONT TestReadProxyNarStreaming1548--- PASS: TestReadProxyHead (0.51s)1549--- PASS: TestService_ReadScope_PublicByDefault (0.23s)1550=== CONT TestReadProxyNarinfo15512026/10/06 23:00:52 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:40741/oidc15522026/10/06 23:00:52 INFO Completed multipart upload object_key=nar/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb00000000000000000000.nar.zst upload_id=YWRmMTJmZmQtMWEwMy00Y2IzLTgyODYtYWQxNDM2MDI0YmY5LmEyMjlmY2FmLTBhY2UtNDFjZC04MWM1LWI3MDVjYmRiM2UzYngxNzkxMzI3NjUxMzIxMDQxMTA0 parts=1015532026/10/06 23:00:52 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1554=== RUN TestService_RequireScope_OIDC/builder_may_write1555=== PAUSE TestService_RequireScope_OIDC/builder_may_write1556=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1557=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1558=== RUN TestService_RequireScope_OIDC/ops_may_admin1559=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1560=== RUN TestService_RequireScope_OIDC/ops_may_not_write1561=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1562=== RUN TestService_RequireScope_OIDC/reader_may_not_write1563=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1564=== RUN TestService_RequireScope_OIDC/static_token_may_admin1565=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1566=== RUN TestService_RequireScope_OIDC/static_token_may_write1567=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1568=== RUN TestService_RequireScope_OIDC/reader_may_read1569=== PAUSE TestService_RequireScope_OIDC/reader_may_read1570=== RUN TestService_RequireScope_OIDC/writer_implies_read1571=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1572=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1573=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1574=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1575=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc1576=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1577=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1578=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1579=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1580=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1581=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1582=== CONT TestClientFallsBackToClosures15832026/10/06 23:00:52 INFO Completed multipart upload object_key=nar/cccccccccccccccccccccccccccccccc00000000000000000000.nar.zst upload_id=YWRmMTJmZmQtMWEwMy00Y2IzLTgyODYtYWQxNDM2MDI0YmY5LmQ2OWNmZjc0LTg0MmItNDMwMS05ZjRhLTlhODI2ZWMxYWI1MngxNzkxMzI3NjUxMjk5NzIyNTUw parts=1015842026/10/06 23:00:52 INFO Received complete push request method=POST path=/api/pushes/2/complete15852026/10/06 23:00:52 INFO Completed push id=21586=== NAME TestPinProtectsFromGC1587 client_integration_test.go:867: Pinned store path: /build/TestPinProtectsFromGC2537293887/001/store/fn64z29yh4f7jhw1yqh6y4zmv71979la-pinned-file.txt1588 client_integration_test.go:868: Unpinned store path: /build/TestPinProtectsFromGC2537293887/001/store/005gycpq0al5kbbbdws60vr4yaqlhbkr-unpinned-file.txt1589=== CONT TestReadProxyContentNegotiation1590--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (3.31s)1591=== CONT TestClientIntegration1592--- PASS: TestDeleteClosuresRacingPins (1.95s)1593--- PASS: TestCacheStatsHandler (0.27s)1594=== CONT TestService_AuthMiddleware_MTLSProxyHeader15952026/10/06 23:00:52 INFO Received push request method=POST path=/api/pushes15962026/10/06 23:00:52 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)15972026/10/06 23:00:52 INFO Uploading fmnh5zlpakxqcph93947pl6s80ghq15q-shared-dep (136B)15982026/10/06 23:00:52 INFO Uploading x2bm6ykad17x0ahl8xh6qsgqc5wpill7-a (216B)15992026/10/06 23:00:52 INFO Received push request method=POST path=/api/pushes16002026/10/06 23:00:52 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16012026/10/06 23:00:52 INFO Uploading fn64z29yh4f7jhw1yqh6y4zmv71979la-pinned-file.txt (128B)16022026/10/06 23:00:52 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"16032026/10/06 23:00:52 WARN Failed to register uploaded object key=nar/0sldsq610mw6w277q9qyb9n4jcif5z40jdkv3sg7l8b1ygm1hmjh.nar.zst error="server returned 404: 404 page not found\n"16042026/10/06 23:00:52 WARN Failed to register uploaded object key=0i5jz2alag13hmy5zx19nl5nslnqd6aw.ls error="server returned 404: 404 page not found\n"16052026/10/06 23:00:52 INFO lead: released remote=192.0.2.1:123416062026/10/06 23:00:52 WARN Failed to register uploaded object key=x2bm6ykad17x0ahl8xh6qsgqc5wpill7.ls error="server returned 404: 404 page not found\n"16072026/10/06 23:00:52 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16082026/10/06 23:00:52 INFO Signed narinfos id=1 count=316092026/10/06 23:00:52 INFO Uploading 3 narinfos16102026/10/06 23:00:52 WARN Failed to register uploaded object key=fmnh5zlpakxqcph93947pl6s80ghq15q.ls error="server returned 404: 404 page not found\n"16112026/10/06 23:00:52 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"16122026/10/06 23:00:52 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16132026/10/06 23:00:52 WARN Failed to register uploaded object key=fn64z29yh4f7jhw1yqh6y4zmv71979la.ls error="server returned 404: 404 page not found\n"16142026/10/06 23:00:52 WARN Failed to register uploaded object key=0i5jz2alag13hmy5zx19nl5nslnqd6aw.narinfo error="server returned 404: 404 page not found\n"16152026/10/06 23:00:52 INFO Signed narinfos id=1 count=116162026/10/06 23:00:52 INFO Uploading 1 narinfos16172026/10/06 23:00:52 INFO Received complete push request method=POST path=/api/pushes/1/complete16182026/10/06 23:00:52 WARN Failed to register uploaded object key=fn64z29yh4f7jhw1yqh6y4zmv71979la.narinfo error="server returned 404: 404 page not found\n"16192026/10/06 23:00:52 INFO Received complete multipart upload request method=POST path=/api/multipart/complete16202026/10/06 23:00:52 INFO Received complete push request method=POST path=/api/pushes/1/complete16212026/10/06 23:00:52 INFO lead: acquired remote=192.0.2.1:123416222026/10/06 23:00:52 WARN Failed to register uploaded object key=fmnh5zlpakxqcph93947pl6s80ghq15q.narinfo error="server returned 404: 404 page not found\n"16232026/10/06 23:00:52 WARN Failed to register uploaded object key=x2bm6ykad17x0ahl8xh6qsgqc5wpill7.narinfo error="server returned 404: 404 page not found\n"16242026/10/06 23:00:52 INFO Completed push id=116252026/10/06 23:00:52 INFO Upload complete. (134ms)16262026/10/06 23:00:52 INFO Completed push id=116272026/10/06 23:00:52 INFO Upload complete. (152ms)16282026/10/06 23:00:52 INFO Received push request method=POST path=/api/pushes1629=== NAME TestClientPushesUseOnePush1630 client_pushes_test.go:97: Retrieved narinfo from S3:1631 StorePath: /build/TestClientPushesUseOnePush3527096070/001/store/fmnh5zlpakxqcph93947pl6s80ghq15q-shared-dep1632 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1633 Compression: zstd1634 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821635 NarSize: 1361636 References: 1637 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1638=== CONT TestClientCADerivations1639--- PASS: TestReadProxyNarStreaming (0.28s)16402026/10/06 23:00:52 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggggg00000000000000000000.nar.zst upload_id=YWRmMTJmZmQtMWEwMy00Y2IzLTgyODYtYWQxNDM2MDI0YmY5LjY1MmY4NGI0LTY4YzktNDY4Yi1hNWZhLWE3NGJjYzMxNzFmNHgxNzkxMzI3NjQ5NjU1Mjc4MTc0 parts=101641--- PASS: TestConnectSerialisesConcurrentMigrations (1.16s)1642=== CONT TestClientMultipleUploads1643=== NAME TestClientPushesUseOnePush1644 client_pushes_test.go:97: Retrieved narinfo from S3:1645 StorePath: /build/TestClientPushesUseOnePush3527096070/001/store/x2bm6ykad17x0ahl8xh6qsgqc5wpill7-a1646 URL: nar/0sldsq610mw6w277q9qyb9n4jcif5z40jdkv3sg7l8b1ygm1hmjh.nar.zst1647 Compression: zstd1648 NarHash: sha256:0sldsq610mw6w277q9qyb9n4jcif5z40jdkv3sg7l8b1ygm1hmjh1649 NarSize: 2161650 References: /build/TestClientPushesUseOnePush3527096070/001/store/fmnh5zlpakxqcph93947pl6s80ghq15q-shared-dep1651 CA: text:sha256:1nwnn12fz0vd581cc03cf1jb4a0mk4c4bsalq5njr0bgj4zibbh616522026/10/06 23:00:52 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)16532026/10/06 23:00:52 INFO Uploading vb2yjm4zc69x6gh6f3rc2qwfmnmabin4-shared-dep (136B)16542026/10/06 23:00:52 INFO Uploading 0a294hzjpcn3x90cmgwpc8lmlrd38c9q-top (224B)1655 client_pushes_test.go:97: Retrieved narinfo from S3:16562026/10/06 23:00:52 WARN Failed to register uploaded object key=nar/1ihw07w9mbbcnyvr32prs300bkr66q8jy3bsdxlii5qkkj2yl317.nar.zst error="server returned 404: 404 page not found\n"1657 StorePath: /build/TestClientPushesUseOnePush3527096070/001/store/0i5jz2alag13hmy5zx19nl5nslnqd6aw-b1658 URL: nar/0sldsq610mw6w277q9qyb9n4jcif5z40jdkv3sg7l8b1ygm1hmjh.nar.zst1659 Compression: zstd1660 NarHash: sha256:0sldsq610mw6w277q9qyb9n4jcif5z40jdkv3sg7l8b1ygm1hmjh1661 NarSize: 2161662 References: /build/TestClientPushesUseOnePush3527096070/001/store/fmnh5zlpakxqcph93947pl6s80ghq15q-shared-dep1663 CA: text:sha256:1nwnn12fz0vd581cc03cf1jb4a0mk4c4bsalq5njr0bgj4zibbh616642026/10/06 23:00:52 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"16652026/10/06 23:00:52 WARN Failed to register uploaded object key=vb2yjm4zc69x6gh6f3rc2qwfmnmabin4.ls error="server returned 404: 404 page not found\n"1666=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1667=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1668=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1669=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1670=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected16712026/10/06 23:00:52 WARN Failed to register uploaded object key=0a294hzjpcn3x90cmgwpc8lmlrd38c9q.ls error="server returned 404: 404 page not found\n"1672=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1673=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured16742026/10/06 23:00:52 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign1675=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1676=== CONT TestService_AuthMiddleware16772026/10/06 23:00:52 INFO Signed narinfos id=1 count=216782026/10/06 23:00:52 INFO Uploading 2 narinfos16792026/10/06 23:00:52 WARN Failed to register uploaded object key=0a294hzjpcn3x90cmgwpc8lmlrd38c9q.narinfo error="server returned 404: 404 page not found\n"1680=== NAME TestClientWithDependencies1681 client_integration_test.go:735: Built derivation: /build/TestClientWithDependencies1022632205/001/store/47aw15whk94icqc51p4dlfwqpgxnhb99-test-script16822026-10-06 23:00:52.353 UTC [1157] ERROR: Push does not exist: id=116832026-10-06 23:00:52.353 UTC [1157] CONTEXT: PL/pgSQL function commit_push(bigint) line 10 at RAISE16842026-10-06 23:00:52.353 UTC [1157] STATEMENT: SELECT commit_push($1)16852026/10/06 23:00:52 INFO Received complete push request method=POST path=/api/pushes/1/complete16862026/10/06 23:00:52 WARN Failed to register uploaded object key=vb2yjm4zc69x6gh6f3rc2qwfmnmabin4.narinfo error="server returned 404: 404 page not found\n"1687--- PASS: TestClientPushesUseOnePush (0.62s)1688=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh16892026/10/06 23:00:52 INFO Completed push id=116902026/10/06 23:00:52 INFO Upload complete. (155ms)1691--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (1.36s)1692=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info16932026/10/06 23:00:52 INFO Received uploads request method=POST path=/1694=== NAME TestClientSharedPathCommittedMidPush1695 client_integration_test.go:816: Retrieved narinfo from S3:1696 StorePath: /build/TestClientSharedPathCommittedMidPush2418779212/001/store/vb2yjm4zc69x6gh6f3rc2qwfmnmabin4-shared-dep1697 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1698 Compression: zstd1699 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821700 NarSize: 1361701 References: 1702 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1703=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key17042026/10/06 23:00:52 INFO Received complete multipart upload request method=POST path=/1705=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key17062026/10/06 23:00:52 INFO Received request for more parts method=POST path=/1707=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1708=== NAME TestClientWithDependencies17092026/10/06 23:00:52 INFO Received uploads request method=POST path=/1710 client_integration_test.go:737: Found 1 dependencies (including self)1711=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale1712--- PASS: TestUploadHandlersRejectInvalidKeys (0.01s)1713 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1714 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1715 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1716 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)17172026/10/06 23:00:52 INFO Received push request method=POST path=/api/pushes1718=== NAME TestClientSharedPathCommittedMidPush1719 client_integration_test.go:816: Retrieved narinfo from S3:1720 StorePath: /build/TestClientSharedPathCommittedMidPush2418779212/001/store/0a294hzjpcn3x90cmgwpc8lmlrd38c9q-top1721 URL: nar/1ihw07w9mbbcnyvr32prs300bkr66q8jy3bsdxlii5qkkj2yl317.nar.zst1722 Compression: zstd1723 NarHash: sha256:1ihw07w9mbbcnyvr32prs300bkr66q8jy3bsdxlii5qkkj2yl3171724 NarSize: 2241725 References: /build/TestClientSharedPathCommittedMidPush2418779212/001/store/vb2yjm4zc69x6gh6f3rc2qwfmnmabin4-shared-dep1726 CA: text:sha256:0zxgq2bpjnhkv5fbibdmwlzix35xgpk8rm9nvhdlqsmw3pbldyp217272026/10/06 23:00:52 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17282026/10/06 23:00:52 INFO Uploading 005gycpq0al5kbbbdws60vr4yaqlhbkr-unpinned-file.txt (128B)17292026/10/06 23:00:52 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"17302026/10/06 23:00:52 WARN Failed to register uploaded object key=005gycpq0al5kbbbdws60vr4yaqlhbkr.ls error="server returned 404: 404 page not found\n"17312026/10/06 23:00:52 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign17322026/10/06 23:00:52 INFO Signed narinfos id=2 count=117332026/10/06 23:00:52 INFO Uploading 1 narinfos17342026/10/06 23:00:52 INFO Received complete push request method=POST path=/api/pushes/2/complete1735=== CONT TestProxyWriteTimeout/10_GiB_nar1736--- PASS: TestClientSharedPathCommittedMidPush (0.57s)17372026/10/06 23:00:52 WARN Failed to register uploaded object key=005gycpq0al5kbbbdws60vr4yaqlhbkr.narinfo error="server returned 404: 404 page not found\n"1738=== CONT TestProxyWriteTimeout/unknown_size1739=== CONT TestProxyWriteTimeout/narinfo1740=== CONT TestProxyWriteTimeout/1_GiB_nar1741=== CONT TestPendingClosureWriteTimeout/empty1742--- PASS: TestProxyWriteTimeout (0.01s)1743 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1744 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1745 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1746 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1747=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline17482026/10/06 23:00:52 INFO Received push request method=POST path=/api/pushes17492026/10/06 23:00:52 INFO Completed push id=217502026/10/06 23:00:52 INFO Upload complete. (220ms)1751=== CONT TestPendingClosureWriteTimeout/670k_objects1752--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.40s)1753=== CONT TestPendingClosureWriteTimeout/400_objects17542026/10/06 23:00:52 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)1755=== CONT TestIsValidUploadKey/nar_zst1756=== CONT TestIsValidUploadKey/unknown_type17572026/10/06 23:00:52 INFO Uploading 47aw15whk94icqc51p4dlfwqpgxnhb99-test-script (136B)1758=== CONT TestIsValidUploadKey/empty_key1759=== CONT TestIsValidUploadKey/traversal_nar1760=== CONT TestIsValidUploadKey/absolute1761=== CONT TestIsValidUploadKey/traversal1762=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1763=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1764=== CONT TestIsValidUploadKey/index.html1765=== CONT TestIsValidUploadKey/nix-cache-info1766=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1767=== CONT TestIsValidUploadKey/realisation1768=== CONT TestIsValidUploadKey/build_log_equals1769=== CONT TestIsValidUploadKey/realisation_plus_in_output1770=== CONT TestIsValidUploadKey/build_log_plus_in_name1771=== CONT TestIsValidUploadKey/build_log_home-manager_file1772=== CONT TestIsValidUploadKey/build_log1773=== CONT TestIsValidUploadKey/listing1774=== CONT TestIsValidUploadKey/nar_plain1775=== CONT TestIsValidUploadKey/narinfo1776=== CONT TestIsValidUploadKey/nar_xz1777=== CONT TestIsValidUploadKey/build_log_question_mark1778=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure1779--- PASS: TestIsValidUploadKey (0.01s)1780 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1781 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1782 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1783 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1784 --- PASS: TestIsValidUploadKey/absolute (0.00s)1785 --- PASS: TestIsValidUploadKey/traversal (0.00s)1786 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1787 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1788 --- PASS: TestIsValidUploadKey/index.html (0.00s)1789 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1790 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1791 --- PASS: TestIsValidUploadKey/realisation (0.00s)1792 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1793 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1794 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1795 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1796 --- PASS: TestIsValidUploadKey/build_log (0.00s)1797 --- PASS: TestIsValidUploadKey/listing (0.00s)1798 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1799 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1800 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1801 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)18022026/10/06 23:00:52 INFO Received uploads request method=POST path=/18032026/10/06 23:00:52 WARN Failed to register uploaded object key=log/1fivn3bjffm0b01w7n2k57jyyn36in5f-test-script.drv error="server returned 404: 404 page not found\n"18042026/10/06 23:00:52 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"18052026/10/06 23:00:52 WARN Failed to register uploaded object key=47aw15whk94icqc51p4dlfwqpgxnhb99.ls error="server returned 404: 404 page not found\n"18062026/10/06 23:00:52 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18072026/10/06 23:00:52 INFO Signed narinfos id=1 count=118082026/10/06 23:00:52 INFO Uploading 1 narinfos18092026/10/06 23:00:52 INFO Starting cleanup of old closures method=DELETE path=/api/closures18102026/10/06 23:00:52 INFO Garbage collection started18112026/10/06 23:00:52 INFO Received complete multipart upload request method=POST path=/api/multipart/complete18122026/10/06 23:00:52 INFO Aborted multipart uploads count=0 kept=01813=== NAME TestClientIntegration1814 client_integration_test.go:334: Created store path: /build/TestClientIntegration4167778686/002/store/19k9gm79g7xskmrwh1zizpnk949g7gdj-test-file.txt18152026/10/06 23:00:52 INFO Received complete push request method=POST path=/api/pushes/1/complete18162026/10/06 23:00:52 WARN Failed to register uploaded object key=47aw15whk94icqc51p4dlfwqpgxnhb99.narinfo error="server returned 404: 404 page not found\n"18172026/10/06 23:00:52 WARN Force mode enabled - objects will be deleted immediately without grace period18182026/10/06 23:00:52 INFO lead: released remote=192.0.2.1:123418192026/10/06 23:00:52 INFO Completed multipart upload object_key=nar/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb00000000000000000000.nar.zst upload_id=YWRmMTJmZmQtMWEwMy00Y2IzLTgyODYtYWQxNDM2MDI0YmY5LmI4NjU5MmU1LWViZDctNGE3OS1hZDYyLWY2NmRkMGNjZjNlOXgxNzkxMzI3NjUxMTUzNzU0Mjc2 parts=1018202026/10/06 23:00:52 INFO Completed push id=118212026/10/06 23:00:52 INFO Upload complete. (202ms)18222026/10/06 23:00:52 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=018232026/10/06 23:00:52 INFO Vacuumed table table=pending_closures18242026/10/06 23:00:52 INFO Aborted multipart uploads count=0 kept=018252026/10/06 23:00:52 INFO Vacuumed table table=pending_objects1826=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts1827--- PASS: TestLeadEndsOnShutdown (1.42s)18282026/10/06 23:00:52 INFO Received request for more parts method=POST path=/18292026/10/06 23:00:52 INFO Vacuumed table table=multipart_uploads18302026/10/06 23:00:52 WARN Force mode enabled - objects will be deleted immediately without grace period18312026/10/06 23:00:52 INFO Vacuumed table table=closures18322026/10/06 23:00:52 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=018332026/10/06 23:00:52 INFO Vacuumed table table=objects18342026/10/06 23:00:52 INFO Vacuumed table table=pending_closures18352026/10/06 23:00:52 INFO Vacuumed table table=pending_objects18362026/10/06 23:00:52 INFO Received uploads request method=POST path=/api/pending_closures18372026/10/06 23:00:52 INFO Vacuumed table table=multipart_uploads18382026/10/06 23:00:52 INFO Vacuumed table table=closures18392026/10/06 23:00:52 INFO Vacuumed table table=objects1840=== NAME TestClientWithDependencies1841 client_integration_test.go:753: Skipping nix copy test - isolated store (/build/TestClientWithDependencies1022632205/001/store) requires matching store prefix18422026/10/06 23:00:52 INFO Received uploads request method=POST path=/api/pending_closures18432026/10/06 23:00:52 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"18442026/10/06 23:00:52 INFO Received push request method=POST path=/api/pushes18452026/10/06 23:00:52 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)18462026/10/06 23:00:52 INFO Uploading yc852njk895slk43z20iy7wdcwxqx4wn-shared-dep (136B)18472026/10/06 23:00:52 INFO Uploading fnvbiamyg451af8wsdca07d5xp1xp7f4-a (216B)18482026/10/06 23:00:52 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18492026/10/06 23:00:52 INFO Uploading 19k9gm79g7xskmrwh1zizpnk949g7gdj-test-file.txt (152B)1850=== NAME TestClientMultipleUploads1851 client_integration_test.go:480: Created store path 0: /build/TestClientMultipleUploads271326687/001/store/hcjjmyfqcgfjfy1njb6xn78fdc11m58q-test-file-0.txt1852--- PASS: TestClientWithDependencies (0.75s)1853=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart1854--- PASS: TestService_AuthMiddleware (0.40s)18552026/10/06 23:00:52 INFO Received complete multipart upload request method=POST path=/1856=== CONT TestPush_RejectsBadRequests/bad_root1857=== NAME TestClientCADerivations18582026/10/06 23:00:52 INFO Received push request method=POST path=/api/pushes1859 client_ca_test.go:136: Built CA derivation: /build/TestClientCADerivations4113813741/001/store/gjhcyj6rj7nbblsr30k34z2yjzlzjch6-ca-test1860=== CONT TestPush_RejectsBadRequests/no_roots18612026/10/06 23:00:52 WARN Failed to register uploaded object key=0rbpjd1icm4lqz6arfpa6apakjv22k3d.ls error="server returned 404: 404 page not found\n"18622026/10/06 23:00:52 INFO Received push request method=POST path=/api/pushes1863=== CONT TestPush_RejectsBadRequests/no_objects18642026/10/06 23:00:52 INFO Received push request method=POST path=/api/pushes1865=== CONT TestPush_RejectsBadRequests/root_not_in_objects18662026/10/06 23:00:52 INFO Received push request method=POST path=/api/pushes1867=== CONT TestPendingClosureFailureTracksEveryUpload/refuse_aborts=true18682026/10/06 23:00:52 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"18692026/10/06 23:00:52 WARN Failed to register uploaded object key=nar/136qk5qqqrbs2cd0z6bmvlgxc160q9q8lxsa7fx2553876qq0yng.nar.zst error="server returned 404: 404 page not found\n"1870=== NAME TestOrphanedObjectsGCStressTest1871 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains18722026/10/06 23:00:52 WARN Failed to register uploaded object key=yc852njk895slk43z20iy7wdcwxqx4wn.ls error="server returned 404: 404 page not found\n"18732026/10/06 23:00:52 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign18742026/10/06 23:00:52 WARN Failed to register uploaded object key=fnvbiamyg451af8wsdca07d5xp1xp7f4.ls error="server returned 404: 404 page not found\n"18752026/10/06 23:00:52 INFO Signed narinfos id=1 count=218762026/10/06 23:00:52 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign18772026/10/06 23:00:52 INFO Signed narinfos id=2 count=218782026/10/06 23:00:52 INFO Uploading 4 narinfos18792026-10-06 23:00:52.760 UTC [178] LOG: checkpoints are occurring too frequently (9 seconds apart)18802026-10-06 23:00:52.760 UTC [178] HINT: Consider increasing the configuration parameter "max_wal_size".18812026-10-06 23:00:52.760 UTC [178] LOG: checkpoint starting: wal18822026/10/06 23:00:52 WARN Failed to register uploaded object key=0rbpjd1icm4lqz6arfpa6apakjv22k3d.narinfo error="server returned 404: 404 page not found\n"1883--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (1.18s)1884=== CONT TestPendingClosureFailureTracksEveryUpload/refuse_aborts=false18852026/10/06 23:00:52 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"1886=== NAME TestClientCADerivations1887 client_ca_test.go:139: Found 1 dependencies (including self)1888=== NAME TestClientMultipleUploads1889 client_integration_test.go:480: Created store path 1: /build/TestClientMultipleUploads271326687/001/store/sn7q6icckgl8c96j8j984rcxah6f1l7d-test-file-1.txt1890--- PASS: TestPush_RejectsBadRequests (0.81s)1891 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)1892 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)1893 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)1894 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)18952026/10/06 23:00:52 WARN Failed to register uploaded object key=yc852njk895slk43z20iy7wdcwxqx4wn.narinfo error="server returned 404: 404 page not found\n"18962026/10/06 23:00:52 WARN Failed to register uploaded object key=19k9gm79g7xskmrwh1zizpnk949g7gdj.ls error="server returned 404: 404 page not found\n"18972026/10/06 23:00:52 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18982026/10/06 23:00:52 WARN Failed to register uploaded object key=fnvbiamyg451af8wsdca07d5xp1xp7f4.narinfo error="server returned 404: 404 page not found\n"18992026/10/06 23:00:52 INFO Signed narinfos id=1 count=119002026/10/06 23:00:52 INFO Uploading 1 narinfos19012026/10/06 23:00:52 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete19022026/10/06 23:00:52 WARN Failed to register uploaded object key=yc852njk895slk43z20iy7wdcwxqx4wn.narinfo error="server returned 404: 404 page not found\n"19032026/10/06 23:00:52 INFO Completed upload id=119042026/10/06 23:00:52 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete1905=== NAME TestOrphanedObjectsGCStressTest1906 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion19072026/10/06 23:00:52 INFO Completed upload id=219082026/10/06 23:00:52 INFO Upload complete. (176ms)1909=== NAME TestClientFallsBackToClosures1910 client_pushes_test.go:112: Retrieved narinfo from S3:1911 StorePath: /build/TestClientFallsBackToClosures3012536043/001/store/yc852njk895slk43z20iy7wdcwxqx4wn-shared-dep1912 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1913 Compression: zstd1914 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821915 NarSize: 1361916 References: 19172026/10/06 23:00:52 INFO Received complete push request method=POST path=/api/pushes/1/complete1918 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n19192026/10/06 23:00:52 WARN Failed to register uploaded object key=19k9gm79g7xskmrwh1zizpnk949g7gdj.narinfo error="server returned 404: 404 page not found\n"1920 client_pushes_test.go:112: Retrieved narinfo from S3:1921 StorePath: /build/TestClientFallsBackToClosures3012536043/001/store/fnvbiamyg451af8wsdca07d5xp1xp7f4-a1922 URL: nar/136qk5qqqrbs2cd0z6bmvlgxc160q9q8lxsa7fx2553876qq0yng.nar.zst1923 Compression: zstd1924 NarHash: sha256:136qk5qqqrbs2cd0z6bmvlgxc160q9q8lxsa7fx2553876qq0yng1925 NarSize: 2161926 References: /build/TestClientFallsBackToClosures3012536043/001/store/yc852njk895slk43z20iy7wdcwxqx4wn-shared-dep1927 CA: text:sha256:0bpv9hhb0zp8yl6ncrkkybar6irwjw4g66y9fa5c6dwr8f6h9h6c1928=== NAME TestClientMultipleUploads1929 client_integration_test.go:480: Created store path 2: /build/TestClientMultipleUploads271326687/001/store/98y178qgx8yrbrq74d2m66xqjdd3qjs6-test-file-2.txt19302026/10/06 23:00:52 INFO Completed push id=119312026/10/06 23:00:52 INFO Upload complete. (158ms)1932=== NAME TestClientFallsBackToClosures1933 client_pushes_test.go:112: Retrieved narinfo from S3:1934 StorePath: /build/TestClientFallsBackToClosures3012536043/001/store/0rbpjd1icm4lqz6arfpa6apakjv22k3d-b1935 URL: nar/136qk5qqqrbs2cd0z6bmvlgxc160q9q8lxsa7fx2553876qq0yng.nar.zst1936 Compression: zstd1937 NarHash: sha256:136qk5qqqrbs2cd0z6bmvlgxc160q9q8lxsa7fx2553876qq0yng1938 NarSize: 2161939 References: /build/TestClientFallsBackToClosures3012536043/001/store/yc852njk895slk43z20iy7wdcwxqx4wn-shared-dep1940 CA: text:sha256:0bpv9hhb0zp8yl6ncrkkybar6irwjw4g66y9fa5c6dwr8f6h9h6c19412026/10/06 23:00:52 INFO Received uploads request method=POST path=/api/pending_closures19422026/10/06 23:00:52 INFO All 1 paths already cached1943=== NAME TestClientIntegration1944 client_integration_test.go:360: Retrieved narinfo from S3:1945 StorePath: /build/TestClientIntegration4167778686/002/store/19k9gm79g7xskmrwh1zizpnk949g7gdj-test-file.txt1946 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1947 Compression: zstd1948 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11949 NarSize: 1521950 References: 1951 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11952 client_integration_test.go:361: Retrieved .ls file from S3 (compressed size: 77 bytes)1953 client_integration_test.go:361: Decompressed .ls content (64 bytes):1954 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1955--- PASS: TestClientFallsBackToClosures (0.78s)1956=== CONT TestServerTLSConfig/no_client_CA1957=== CONT TestServerTLSConfig/missing_CA_file1958=== CONT TestServerTLSConfig/not_a_PEM_file1959=== CONT TestGCEndsOnShutdown/before_the_run1960--- PASS: TestServerTLSConfig (0.00s)1961 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1962 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1963 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)19642026/10/06 23:00:52 WARN Rate limiter enabled after throttle name=s3-test rate=519652026/10/06 23:00:52 WARN S3 rate limit hit during proxy key=4hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo error="Please reduce your request rate."19662026/10/06 23:00:52 INFO Received push request method=POST path=/api/pushes19672026/10/06 23:00:52 INFO Received push request method=POST path=/api/pushes19682026/10/06 23:00:52 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)19692026/10/06 23:00:52 INFO Uploading sn7q6icckgl8c96j8j984rcxah6f1l7d-test-file-1.txt (160B)19702026/10/06 23:00:52 INFO Uploading hcjjmyfqcgfjfy1njb6xn78fdc11m58q-test-file-0.txt (160B)19712026/10/06 23:00:52 INFO Uploading 98y178qgx8yrbrq74d2m66xqjdd3qjs6-test-file-2.txt (160B)19722026/10/06 23:00:52 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)19732026/10/06 23:00:52 INFO Uploading gjhcyj6rj7nbblsr30k34z2yjzlzjch6-ca-test (144B)19742026/10/06 23:00:52 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"19752026/10/06 23:00:52 WARN Failed to register uploaded object key=log/lcq9bgy8x66k5njw8g2z506l4117kma2-ca-test.drv error="server returned 404: 404 page not found\n"19762026/10/06 23:00:52 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"19772026/10/06 23:00:52 WARN Failed to register uploaded object key=98y178qgx8yrbrq74d2m66xqjdd3qjs6.ls error="server returned 404: 404 page not found\n"19782026/10/06 23:00:52 WARN Failed to register uploaded object key=hcjjmyfqcgfjfy1njb6xn78fdc11m58q.ls error="server returned 404: 404 page not found\n"19792026/10/06 23:00:52 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"19802026/10/06 23:00:52 WARN Failed to register uploaded object key=sn7q6icckgl8c96j8j984rcxah6f1l7d.ls error="server returned 404: 404 page not found\n"19812026/10/06 23:00:52 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19822026/10/06 23:00:52 INFO Signed narinfos id=1 count=319832026/10/06 23:00:52 INFO Uploading 3 narinfos19842026/10/06 23:00:52 WARN Failed to register uploaded object key=gjhcyj6rj7nbblsr30k34z2yjzlzjch6.ls error="server returned 404: 404 page not found\n"19852026/10/06 23:00:52 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"19862026/10/06 23:00:52 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19872026/10/06 23:00:52 INFO Signed narinfos id=1 count=119882026/10/06 23:00:52 INFO Uploading 1 narinfos19892026/10/06 23:00:52 WARN Failed to register uploaded object key=sn7q6icckgl8c96j8j984rcxah6f1l7d.narinfo error="server returned 404: 404 page not found\n"19902026/10/06 23:00:52 WARN Failed to register uploaded object key=98y178qgx8yrbrq74d2m66xqjdd3qjs6.narinfo error="server returned 404: 404 page not found\n"19912026/10/06 23:00:52 INFO Received complete push request method=POST path=/api/pushes/1/complete19922026/10/06 23:00:52 WARN Failed to register uploaded object key=gjhcyj6rj7nbblsr30k34z2yjzlzjch6.narinfo error="server returned 404: 404 page not found\n"19932026/10/06 23:00:52 INFO Received push request method=POST path=/api/pushes19942026/10/06 23:00:52 INFO Completed push id=119952026/10/06 23:00:52 INFO Upload complete. (154ms)19962026/10/06 23:00:52 INFO Object in database but missing from S3 key=19k9gm79g7xskmrwh1zizpnk949g7gdj.ls19972026/10/06 23:00:52 WARN Found objects in DB but missing from S3, will re-upload count=119982026/10/06 23:00:52 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)19992026/10/06 23:00:52 INFO Received complete push request method=POST path=/api/pushes/1/complete20002026/10/06 23:00:52 WARN Failed to register uploaded object key=hcjjmyfqcgfjfy1njb6xn78fdc11m58q.narinfo error="server returned 404: 404 page not found\n"2001=== NAME TestClientCADerivations2002 client_ca_test.go:180: Narinfo contains CA field: StorePath: /build/TestClientCADerivations4113813741/001/store/gjhcyj6rj7nbblsr30k34z2yjzlzjch6-ca-test2003 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst2004 Compression: zstd2005 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2006 NarSize: 1442007 References: 2008 Deriver: /build/TestClientCADerivations4113813741/001/store/lcq9bgy8x66k5njw8g2z506l4117kma2-ca-test.drv2009 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n20102026/10/06 23:00:52 INFO Completed push id=12011 client_ca_test.go:185: Checking for realisation files in S3...20122026/10/06 23:00:52 INFO Upload complete. (128ms)2013=== NAME TestClientMultipleUploads2014 client_integration_test.go:491: Uploaded 3 paths in 163.326062ms2015=== NAME TestClientCADerivations2016 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations2017 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache20182026/10/06 23:00:52 INFO Received complete push request method=POST path=/api/pushes/2/complete20192026/10/06 23:00:52 WARN Failed to register uploaded object key=19k9gm79g7xskmrwh1zizpnk949g7gdj.ls error="server returned 404: 404 page not found\n"20202026/10/06 23:00:52 INFO Completed push id=220212026/10/06 23:00:52 INFO Upload complete. (67ms)2022=== NAME TestClientIntegration2023 client_integration_test.go:389: Retrieved .ls file from S3 (compressed size: 62 bytes)2024 client_integration_test.go:389: Decompressed .ls content (49 bytes):2025 {"version":1,"root":{"type":"regular","size":39}}20262026/10/06 23:00:53 WARN Rate limiter backed off name=s3-test rate=520272026/10/06 23:00:53 WARN S3 rate limit hit during proxy key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhh.nar.zst error="Please reduce your request rate."20282026/10/06 23:00:53 INFO Received uploads request method=POST path=/api/pending_closures20292026/10/06 23:00:53 INFO Received uploads request method=POST path=/api/pending_closures2030--- PASS: TestReadProxy404 (1.08s)2031=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark2032--- PASS: TestClientMultipleUploads (0.74s)2033=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete2034=== NAME TestClientCADerivations2035 client_ca_test.go:258: nix copy output: warning: you don't have Internet access; disabling some network-dependent features2036 warning: failed to create TLS context for AWS credential providers; SSO, STS WebIdentity, and ECS container authentication will be unavailable2037 error: binary cache 's3://bucket93?endpoint=http://localhost:46519®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/build/TestClientCADerivations4113813741/001/store'2038 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 12039=== CONT TestClientErrorHandling/InvalidStorePath20402026/10/06 23:00:53 INFO Received push request method=POST path=/api/pushes20412026/10/06 23:00:53 INFO Received complete multipart upload request method=POST path=/api/multipart/complete2042--- PASS: TestClientCADerivations (0.81s)2043=== CONT TestClientErrorHandling/ServerNotAvailable20442026/10/06 23:00:53 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)20452026/10/06 23:00:53 INFO Completed multipart upload object_key=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa00000000000000000000.nar.zst upload_id=YWRmMTJmZmQtMWEwMy00Y2IzLTgyODYtYWQxNDM2MDI0YmY5LjgyZGM0MTM2LWE4YmEtNDFhZC1iZDFhLTIwZjVmNTM4YzBjOHgxNzkxMzI3NjQ5NjU1MDAxMTE0 parts=1020462026/10/06 23:00:53 WARN Failed to register uploaded object key=19k9gm79g7xskmrwh1zizpnk949g7gdj.ls error="server returned 404: 404 page not found\n"20472026/10/06 23:00:53 INFO Received complete push request method=POST path=/api/pushes/3/complete20482026/10/06 23:00:53 INFO Completed push id=320492026/10/06 23:00:53 INFO Upload complete. (86ms)2050=== NAME TestClientIntegration2051 client_integration_test.go:405: Retrieved .ls file from S3 (compressed size: 62 bytes)2052 client_integration_test.go:405: Decompressed .ls content (49 bytes):2053 {"version":1,"root":{"type":"regular","size":39}}20542026/10/06 23:00:53 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2055--- PASS: TestReadProxyContentNegotiation (1.10s)2056=== CONT TestClientErrorHandling/InvalidAuthToken20572026/10/06 23:00:53 INFO Aborted multipart uploads count=0 kept=020582026/10/06 23:00:53 WARN Force mode enabled - objects will be deleted immediately without grace period20592026/10/06 23:00:53 INFO Received push request method=POST path=/api/pushes2060=== NAME TestOrphanedObjectsGCStressTest2061 orphaned_objects_gc_test.go:503: Stress test completed successfully:2062 orphaned_objects_gc_test.go:504: - Active objects preserved: 202063 orphaned_objects_gc_test.go:505: - Objects deleted: 2102064 orphaned_objects_gc_test.go:506: - Total GC'd: 21020652026/10/06 23:00:53 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:46519/bucket102/?delete=\": context canceled"2066=== CONT TestParseSingleRange/none2067=== CONT TestParseSingleRange/start_past_EOF20682026/10/06 23:00:53 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)2069=== CONT TestParseSingleRange/open-ended20702026/10/06 23:00:53 INFO Uploading mjsnmlnci80psyj0qz8b86v7isn3cya2-lost-commit.txt (152B)2071=== CONT TestParseSingleRange/malformed_end_before_start2072=== CONT TestParseSingleRange/malformed_no_dash2073=== CONT TestParseSingleRange/malformed_both_empty2074=== CONT TestParseSingleRange/unknown_unit2075=== CONT TestParseSingleRange/multi-range_ignored2076=== CONT TestParseSingleRange/closed2077=== CONT TestParseSingleRange/single_byte2078=== CONT TestParseSingleRange/suffix2079=== CONT TestParseSingleRange/end_clamped_to_size2080=== CONT TestParseSingleRange/suffix_exceeds_size2081=== CONT TestParseSingleRange/start_far_past_EOF2082=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check2083--- PASS: TestParseSingleRange (0.00s)2084 --- PASS: TestParseSingleRange/none (0.00s)2085 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)2086 --- PASS: TestParseSingleRange/open-ended (0.00s)2087 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)2088 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)2089 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)2090 --- PASS: TestParseSingleRange/unknown_unit (0.00s)2091 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)2092 --- PASS: TestParseSingleRange/closed (0.00s)2093 --- PASS: TestParseSingleRange/single_byte (0.00s)2094 --- PASS: TestParseSingleRange/suffix (0.00s)2095 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)2096 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)2097 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)2098=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows20992026/10/06 23:00:53 WARN Failed to register uploaded object key=nar/04d5klw9iix884nk82y7nlkps8afh2bg119y7zkvcf1pc1x2y2jl.nar.zst error="server returned 404: 404 page not found\n"21002026/10/06 23:00:53 INFO Aborted multipart uploads count=0 kept=021012026/10/06 23:00:53 WARN Force mode enabled - objects will be deleted immediately without grace period21022026/10/06 23:00:53 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=186.365027ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present21032026/10/06 23:00:53 INFO Received sign narinfos request method=POST path=/api/pushes/4/sign21042026/10/06 23:00:53 INFO Signed narinfos id=4 count=121052026/10/06 23:00:53 WARN Failed to register uploaded object key=mjsnmlnci80psyj0qz8b86v7isn3cya2.ls error="server returned 404: 404 page not found\n"21062026/10/06 23:00:53 INFO Uploading 1 narinfos2107--- PASS: TestOrphanedObjectsGCStressTest (3.99s)2108=== CONT TestResolveDBConnectionString/flag_wins2109=== CONT TestResolveDBConnectionString/file_when_flag_empty2110=== CONT TestResolveDBConnectionString/PGHOST_allows_empty2111--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2112 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (0.90s)2113 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (0.91s)2114=== CONT TestResolveDBConnectionString/missing_file_is_an_error2115=== CONT TestResolveDBConnectionString/nothing_configured2116=== CONT TestCacheConfigHandler/full_config,_no_issuer2117=== CONT TestCacheConfigHandler/no_signing_keys2118=== CONT TestCacheConfigHandler/no_cache_url_configured2119=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2120=== CONT TestIsValidCachePath/narinfo2121=== CONT TestIsValidCachePath/nix-cache-info2122=== CONT TestIsValidCachePath/invalid_char_u2123=== CONT TestIsValidCachePath/nar_uncompressed2124--- PASS: TestCacheConfigHandler (0.00s)2125 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)2126 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)2127 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)2128 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)2129--- PASS: TestResolveDBConnectionString (0.00s)2130 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)2131 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)2132 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)2133 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)2134 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)2135=== CONT TestIsValidCachePath/nar_bz22136=== CONT TestIsValidCachePath/random_path2137=== CONT TestIsValidCachePath/index.html2138=== CONT TestIsValidCachePath/empty2139=== CONT TestIsValidCachePath/traversal_parent2140=== CONT TestIsValidCachePath/short_hash2141=== CONT TestIsValidCachePath/realisation2142=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars2143=== CONT TestIsValidCachePath/nar_xz2144=== CONT TestIsValidCachePath/ls2145=== CONT TestIsValidCachePath/invalid_char_e2146=== CONT TestIsValidCachePath/traversal_in_middle2147=== CONT TestIsValidCachePath/log2148=== CONT TestIsValidCachePath/leading_slash2149=== CONT TestIsValidCachePath/nar_zst2150=== CONT TestIsValidCachePath/wrong_extension2151=== CONT TestService_RequireScope_OIDC/builder_may_write2152=== CONT TestService_RequireScope_OIDC/reader_may_read2153--- PASS: TestIsValidCachePath (0.01s)2154 --- PASS: TestIsValidCachePath/narinfo (0.00s)2155 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)2156 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)2157 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)2158 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)2159 --- PASS: TestIsValidCachePath/random_path (0.00s)2160 --- PASS: TestIsValidCachePath/index.html (0.00s)2161 --- PASS: TestIsValidCachePath/empty (0.00s)2162 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)2163 --- PASS: TestIsValidCachePath/short_hash (0.00s)2164 --- PASS: TestIsValidCachePath/realisation (0.00s)2165 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)2166 --- PASS: TestIsValidCachePath/nar_xz (0.00s)2167 --- PASS: TestIsValidCachePath/ls (0.00s)2168 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)2169 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)2170 --- PASS: TestIsValidCachePath/log (0.00s)2171 --- PASS: TestIsValidCachePath/leading_slash (0.00s)2172 --- PASS: TestIsValidCachePath/nar_zst (0.00s)2173 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)21742026-10-06 23:00:53.303 UTC [2349] ERROR: canceling statement due to user request21752026-10-06 23:00:53.303 UTC [2349] CONTEXT: PL/pgSQL function object_stats_update() line 2 at statement block21762026-10-06 23:00:53.303 UTC [2349] STATEMENT: -- name: MarkStaleObjects :execrows2177 WITH RECURSIVE ct AS (2178 SELECT timezone('UTC', now()) AS now2179 ),2180 closure_reach AS (2181 -- Start with all closure keys2182 SELECT o.key, o.refs2183 FROM objects o2184 INNER JOIN closures c ON o.key = c.key2185 UNION2186 -- Recursively add all referenced objects2187 SELECT o.key, o.refs2188 FROM objects o2189 INNER JOIN closure_reach cr ON o.key = ANY(cr.refs)2190 ),2191 reachable_objects AS (2192 SELECT DISTINCT key FROM closure_reach2193 ),2194 stale_objects AS (2195 SELECT o.key2196 FROM objects AS o, ct2197 WHERE2198 NOT EXISTS (2199 SELECT 12200 FROM reachable_objects ro2201 WHERE ro.key = o.key2202 )2203 AND NOT EXISTS (2204 SELECT 12205 FROM pending_objects AS po2206 WHERE po.key = o.key2207 )2208 AND o.deleted_at IS NULL -- Only mark fresh objects2209 ORDER BY o.key COLLATE "C" -- lock in key order, like commit_pending_closure2210 FOR UPDATE2211 )2212 UPDATE objects2213 SET2214 deleted_at = ct.now,2215 first_deleted_at = COALESCE(first_deleted_at, ct.now)2216 FROM stale_objects, ct2217 WHERE objects.key = stale_objects.key2218 2219=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read2220=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read2221=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc2222=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read22232026/10/06 23:00:53 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]2224=== CONT TestService_RequireScope_OIDC/static_token_may_write2225=== CONT TestService_RequireScope_OIDC/writer_implies_read2226=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc2227=== CONT TestService_RequireScope_OIDC/static_token_may_admin2228=== CONT TestService_RequireScope_OIDC/ops_may_not_write2229=== CONT TestService_RequireScope_OIDC/reader_may_not_write2230=== CONT TestService_RequireScope_OIDC/ops_may_admin2231=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2232=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2233=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2234=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected22352026/10/06 23:00:53 INFO Received complete push request method=POST path=/api/pushes/4/complete22362026/10/06 23:00:53 WARN Failed to register uploaded object key=mjsnmlnci80psyj0qz8b86v7isn3cya2.narinfo error="server returned 404: 404 page not found\n"22372026/10/06 23:00:53 WARN Authentication failed token_preview=eyJhbGciOi...XciQVoCyBw token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2238=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected22392026/10/06 23:00:53 WARN Authentication failed token_preview=not-a-valid-jwt token_length=15 oidc_error="no provider could verify the token (signature or issuer mismatch)" oidc_provider="" tried_providers=[test]22402026/10/06 23:00:53 INFO Completed push id=422412026/10/06 23:00:53 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Post \"http://127.0.0.1:42513/api/pushes/4/complete\": EOF" url=http://127.0.0.1:42513/api/pushes/4/complete2242--- PASS: TestGCEndsOnShutdown (0.00s)2243 --- PASS: TestGCEndsOnShutdown/before_the_run (0.21s)2244 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (0.23s)2245 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (0.28s)2246--- PASS: TestService_RequireScope_OIDC (0.47s)2247 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2248 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2249 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)2250 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)2251 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)2252 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2253 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2254 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2255 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2256 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)2257 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2258 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2259 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2260 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)22612026/10/06 23:00:53 INFO Received complete multipart upload request method=POST path=/api/multipart/complete2262--- PASS: TestService_AuthMiddleware_OIDC (0.41s)2263 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2264 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)2265 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2266 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.01s)22672026/10/06 23:00:53 INFO Completed multipart upload object_key=nar/cccccccccccccccccccccccccccccccc00000000000000000000.nar.zst upload_id=YWRmMTJmZmQtMWEwMy00Y2IzLTgyODYtYWQxNDM2MDI0YmY5LjFlODMxZmM4LWFlMjAtNDFhZS1hZjI3LWE1ZjRlZmRlYTViNXgxNzkxMzI3NjUxMTUzNjk5ODg2 parts=1022682026/10/06 23:00:53 INFO Received complete push request method=POST path=/api/pushes/1/complete22692026/10/06 23:00:53 INFO Completed push id=122702026/10/06 23:00:53 INFO lead: released remote=192.0.2.1:12342271--- PASS: TestPush_CompleteCommitsEveryRoot (2.69s)22722026/10/06 23:00:53 INFO Received complete push request method=POST path=/api/pushes/4/complete22732026-10-06 23:00:53.420 UTC [1376] ERROR: Push does not exist: id=422742026-10-06 23:00:53.420 UTC [1376] CONTEXT: PL/pgSQL function commit_push(bigint) line 10 at RAISE22752026-10-06 23:00:53.420 UTC [1376] STATEMENT: -- name: CommitPush :exec2276 SELECT commit_push($1::bigint)2277 22782026/10/06 23:00:53 WARN Push not found id=42279--- PASS: TestLeadElectsOneAndHandsOver (3.01s)22802026/10/06 23:00:53 INFO Upload complete. (201ms)2281=== NAME TestClientIntegration2282 client_integration_test.go:435: Retrieved narinfo from S3:2283 StorePath: /build/TestClientIntegration4167778686/002/store/mjsnmlnci80psyj0qz8b86v7isn3cya2-lost-commit.txt2284 URL: nar/04d5klw9iix884nk82y7nlkps8afh2bg119y7zkvcf1pc1x2y2jl.nar.zst2285 Compression: zstd2286 NarHash: sha256:04d5klw9iix884nk82y7nlkps8afh2bg119y7zkvcf1pc1x2y2jl2287 NarSize: 1522288 References: 2289 CA: fixed:r:sha256:04d5klw9iix884nk82y7nlkps8afh2bg119y7zkvcf1pc1x2y2jl2290 client_integration_test.go:438: Testing garbage collection...22912026/10/06 23:00:53 INFO Received uploads request method=POST path=/api/pending_closures22922026/10/06 23:00:53 INFO Starting cleanup of old closures method=DELETE path=/api/closures22932026/10/06 23:00:53 INFO Garbage collection started22942026/10/06 23:00:53 INFO Aborted multipart uploads count=0 kept=022952026/10/06 23:00:53 INFO Aborted multipart uploads count=0 kept=022962026/10/06 23:00:53 WARN Force mode enabled - objects will be deleted immediately without grace period22972026/10/06 23:00:53 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=399.500688ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present22982026/10/06 23:00:53 WARN Force mode enabled - objects will be deleted immediately without grace period22992026/10/06 23:00:53 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=023002026/10/06 23:00:53 INFO Vacuumed table table=pending_closures23012026/10/06 23:00:53 INFO Received uploads request method=POST path=/api/pending_closures23022026/10/06 23:00:53 INFO Vacuumed table table=pending_objects23032026/10/06 23:00:53 INFO Vacuumed table table=multipart_uploads23042026/10/06 23:00:53 INFO Vacuumed table table=closures23052026/10/06 23:00:53 INFO Vacuumed table table=objects23062026/10/06 23:00:53 INFO Aborted multipart uploads count=0 kept=023072026/10/06 23:00:53 WARN Force mode enabled - objects will be deleted immediately without grace period23082026/10/06 23:00:53 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=023092026/10/06 23:00:53 INFO Vacuumed table table=pending_closures23102026/10/06 23:00:53 INFO Vacuumed table table=pending_objects23112026/10/06 23:00:53 INFO Vacuumed table table=multipart_uploads23122026/10/06 23:00:53 INFO Vacuumed table table=closures23132026/10/06 23:00:53 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"23142026/10/06 23:00:53 INFO Vacuumed table table=objects23152026/10/06 23:00:53 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=023162026/10/06 23:00:53 INFO Vacuumed table table=pending_closures23172026/10/06 23:00:53 INFO Vacuumed table table=pending_objects23182026/10/06 23:00:53 INFO Vacuumed table table=multipart_uploads23192026/10/06 23:00:53 INFO Vacuumed table table=closures23202026/10/06 23:00:53 INFO Vacuumed table table=objects23212026/10/06 23:00:53 WARN Failed to abort multipart upload key=nar/ssssssssssssssssssssssssssssssssssssssssssssssssssss.nar.zst upload_id=YWRmMTJmZmQtMWEwMy00Y2IzLTgyODYtYWQxNDM2MDI0YmY5LjM3NmRlNDBiLWZlOTItNDczYi1iYjQ3LTRjMTBmNWY5YjFmNngxNzkxMzI3NjUzMDMxMDg1MDYz error="Access Denied"23222026/10/06 23:00:53 WARN keeping failed pending closure for cleanup to retry the abort id=123232026/10/06 23:00:53 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"2324--- PASS: TestPendingClosureFailureTracksEveryUpload (0.00s)2325 --- PASS: TestPendingClosureFailureTracksEveryUpload/refuse_aborts=true (0.82s)2326 --- PASS: TestPendingClosureFailureTracksEveryUpload/refuse_aborts=false (0.79s)2327--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2328 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (0.26s)2329 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (0.28s)2330--- PASS: TestPendingClosureWriteTimeout (0.01s)2331 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2332 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2333 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2334 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (1.20s)23352026/10/06 23:00:53 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>2336--- PASS: TestReadProxyNarinfo (1.73s)23372026/10/06 23:00:53 INFO Received complete multipart upload request method=POST path=/api/multipart/complete23382026/10/06 23:00:53 INFO Completed multipart upload object_key=nar/dddddddddddddddddddddddddddddddd00000000000000000000.nar.zst upload_id=YWRmMTJmZmQtMWEwMy00Y2IzLTgyODYtYWQxNDM2MDI0YmY5LjBlMjhiMjRkLWJmNDYtNDg2Yi1hYmQ3LTc3MGQzMGVmNWFjM3gxNzkxMzI3NjQ5NjU1OTY4Njkz parts=1023392026-10-06 23:00:53.861 UTC [734] ERROR: could not obtain lock on row in relation "closures"23402026-10-06 23:00:53.861 UTC [734] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT23412026-10-06 23:00:53.861 UTC [734] ERROR: could not obtain lock on row in relation "closures"23422026-10-06 23:00:53.861 UTC [734] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT23432026-10-06 23:00:53.862 UTC [734] ERROR: could not obtain lock on row in relation "closures"23442026-10-06 23:00:53.862 UTC [734] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT23452026-10-06 23:00:53.862 UTC [734] ERROR: could not obtain lock on row in relation "closures"23462026-10-06 23:00:53.862 UTC [734] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT23472026-10-06 23:00:53.863 UTC [734] ERROR: could not obtain lock on row in relation "closures"23482026-10-06 23:00:53.863 UTC [734] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT23492026/10/06 23:00:53 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=798.837887ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2350--- PASS: TestPush_RootsAreLockedInByteOrder (5.09s)23512026/10/06 23:00:54 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=023522026/10/06 23:00:54 INFO Received create pin request method=POST path=/api/pins/myapp23532026/10/06 23:00:54 INFO Created/updated pin name=myapp store_path=/build/TestPinProtectsFromGC2537293887/001/store/fn64z29yh4f7jhw1yqh6y4zmv71979la-pinned-file.txt narinfo_key=fn64z29yh4f7jhw1yqh6y4zmv71979la.narinfo23542026/10/06 23:00:54 INFO Starting cleanup of old closures method=DELETE path=/api/closures23552026/10/06 23:00:54 INFO Garbage collection started23562026/10/06 23:00:54 INFO Aborted multipart uploads count=0 kept=023572026/10/06 23:00:54 WARN Force mode enabled - objects will be deleted immediately without grace period23582026/10/06 23:00:54 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=023592026/10/06 23:00:54 INFO Vacuumed table table=pending_closures23602026/10/06 23:00:54 INFO Vacuumed table table=pending_objects23612026/10/06 23:00:54 INFO Vacuumed table table=multipart_uploads23622026/10/06 23:00:54 INFO Vacuumed table table=closures23632026/10/06 23:00:54 INFO Vacuumed table table=objects23642026/10/06 23:00:54 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.524568688s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present23652026/10/06 23:00:54 WARN Rate limiter enabled after throttle name=s3-test rate=523662026/10/06 23:00:54 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."2367=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle2368 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=102369 throttle_test.go:215: Rate limiter: enabled=true, rate=5.002370--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (6.12s)23712026/10/06 23:00:55 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=2 objects_marked=6 objects_deleted=6 objects_failed=02372=== NAME TestClientIntegration2373 client_integration_test.go:445: Objects in database after GC:2374 client_integration_test.go:445: Successfully deleted all objects with GC --force2375--- PASS: TestClientIntegration (3.34s)2376--- PASS: TestConnectWaitsForAPeerMigration (5.21s)23772026/10/06 23:00:56 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2378--- PASS: TestReadProxyOutlastsServerWriteTimeout (4.74s)23792026/10/06 23:00:56 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=188.817757ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config23802026/10/06 23:00:56 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=371.687948ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config23812026/10/06 23:00:56 INFO Aborted multipart uploads count=1 kept=023822026/10/06 23:00:57 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=736.397439ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config23832026/10/06 23:00:57 INFO Received cleanup request method=DELETE path=/api/pending_closures2384=== NAME TestPinProtectsFromGC2385 client_integration_test.go:976: Pin successfully protected closure from garbage collection23862026/10/06 23:00:57 INFO Aborted multipart uploads count=1 kept=02387--- PASS: TestPendingCleanupUsesOneCutoff (7.03s)2388--- PASS: TestPinProtectsFromGC (5.25s)23892026/10/06 23:00:57 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.705030618s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config23902026/10/06 23:00:59 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: sending request: request failed after retries: Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused"23912026/10/06 23:00:59 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config23922026/10/06 23:00:59 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=202.456963ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config23932026/10/06 23:00:59 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=386.32788ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2394--- PASS: TestUploadHandlersRejectOversizedBody (0.50s)2395 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.76s)2396 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.79s)2397 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (7.52s)23982026/10/06 23:01:00 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=761.305491ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config23992026/10/06 23:01:00 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.491463209s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config24002026/10/06 23:01:02 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures24012026/10/06 23:01:02 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=217.923628ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures24022026/10/06 23:01:02 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=405.082968ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures24032026/10/06 23:01:03 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=727.321562ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures24042026/10/06 23:01:03 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.550462743s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2405--- PASS: TestClientErrorHandling (0.00s)2406 --- PASS: TestClientErrorHandling/InvalidStorePath (0.26s)2407 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.34s)2408 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.36s)2409PASS2410{"timestamp":"2026-10-06T23:01:05.477011567Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:41172","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2354,"threadName":"rustfs-worker","threadId":"ThreadId(401)"}2411{"timestamp":"2026-10-06T23:01:05.477897616Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:41680","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2354,"threadName":"rustfs-worker","threadId":"ThreadId(394)"}2412{"timestamp":"2026-10-06T23:01:05.478301446Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:41666","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2354,"threadName":"rustfs-worker","threadId":"ThreadId(397)"}24132026-10-06 23:01:05.944 UTC [173] LOG: received smart shutdown request24142026-10-06 23:01:05.948 UTC [173] LOG: background worker "logical replication launcher" (PID 183) exited with exit code 124152026-10-06 23:01:06.876 UTC [178] LOG: checkpoint complete: wrote 5535 buffers (33.8%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 33 recycled; write=13.297 s, sync=0.754 s, total=14.116 s; sync files=36743, longest=0.027 s, average=0.001 s; distance=533167 kB, estimate=533167 kB; lsn=0/249CD670, redo lsn=0/22011AD824162026-10-06 23:01:06.879 UTC [178] LOG: shutting down24172026-10-06 23:01:06.879 UTC [178] LOG: checkpoint starting: shutdown immediate24182026-10-06 23:01:07.444 UTC [178] LOG: checkpoint complete: wrote 5766 buffers (35.2%), wrote 1 SLRU buffers; 0 WAL file(s) added, 0 removed, 2 recycled; write=0.109 s, sync=0.443 s, total=0.565 s; sync files=1739, longest=0.009 s, average=0.001 s; distance=42735 kB, estimate=484124 kB; lsn=0/249CD6E8, redo lsn=0/249CD6E824192026-10-06 23:01:07.527 UTC [173] LOG: database system is shut down2420Running OIDC tests...2421=== RUN TestAudienceForIssuer2422=== PAUSE TestAudienceForIssuer2423=== RUN TestHTTPClientForHasTimeouts2424=== PAUSE TestHTTPClientForHasTimeouts2425=== RUN TestGlobMatch2426=== PAUSE TestGlobMatch2427=== RUN TestValidateToken_ValidToken2428=== PAUSE TestValidateToken_ValidToken2429=== RUN TestValidateToken_WrongAudience2430=== PAUSE TestValidateToken_WrongAudience2431=== RUN TestValidateToken_Expired2432=== PAUSE TestValidateToken_Expired2433=== RUN TestValidateToken_BoundClaimsMismatch2434=== PAUSE TestValidateToken_BoundClaimsMismatch2435=== RUN TestValidateToken_BoundSubjectMismatch2436=== PAUSE TestValidateToken_BoundSubjectMismatch2437=== RUN TestValidateToken_MultipleProviders2438=== PAUSE TestValidateToken_MultipleProviders2439=== RUN TestValidateToken_NoMatchingProvider2440=== PAUSE TestValidateToken_NoMatchingProvider2441=== RUN TestValidateToken_KubernetesServiceAccount2442=== PAUSE TestValidateToken_KubernetesServiceAccount2443=== RUN TestNewValidator_KubernetesRequiresCA2444=== PAUSE TestNewValidator_KubernetesRequiresCA2445=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2446=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2447=== RUN TestPins_ReservedForMatchingRule2448=== PAUSE TestPins_ReservedForMatchingRule2449=== RUN TestPins_TopLevelShorthand2450=== PAUSE TestPins_TopLevelShorthand2451=== RUN TestPins_ConfigValidation2452=== PAUSE TestPins_ConfigValidation2453=== RUN TestScopes_LegacyProviderDefaultsToWrite2454=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2455=== RUN TestScopes_Rules2456=== PAUSE TestScopes_Rules2457=== RUN TestScopes_ConfigValidation2458=== PAUSE TestScopes_ConfigValidation2459=== CONT TestHTTPClientForHasTimeouts2460=== CONT TestValidateToken_Expired2461=== CONT TestPins_TopLevelShorthand2462=== CONT TestScopes_ConfigValidation2463=== CONT TestScopes_Rules2464=== CONT TestValidateToken_NoMatchingProvider2465=== CONT TestPins_ConfigValidation2466=== CONT TestPins_ReservedForMatchingRule2467=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2468=== CONT TestNewValidator_KubernetesRequiresCA2469=== CONT TestScopes_LegacyProviderDefaultsToWrite2470=== CONT TestValidateToken_ValidToken2471=== CONT TestValidateToken_WrongAudience2472=== CONT TestAudienceForIssuer2473=== CONT TestValidateToken_MultipleProviders2474=== CONT TestValidateToken_BoundSubjectMismatch2475=== CONT TestValidateToken_BoundClaimsMismatch2476=== CONT TestValidateToken_KubernetesServiceAccount2477=== CONT TestGlobMatch2478=== RUN TestGlobMatch/foo_foo2479=== PAUSE TestGlobMatch/foo_foo2480=== RUN TestGlobMatch/foo_bar2481=== PAUSE TestGlobMatch/foo_bar2482=== RUN TestGlobMatch/*_2483=== PAUSE TestGlobMatch/*_2484--- PASS: TestScopes_ConfigValidation (0.00s)2485=== RUN TestGlobMatch/*_anything2486--- PASS: TestPins_ConfigValidation (0.00s)2487=== PAUSE TestGlobMatch/*_anything2488--- PASS: TestAudienceForIssuer (0.00s)2489=== RUN TestGlobMatch/foo*_foo2490=== PAUSE TestGlobMatch/foo*_foo2491=== RUN TestGlobMatch/foo*_foobar2492=== PAUSE TestGlobMatch/foo*_foobar2493=== RUN TestGlobMatch/foo*_bar2494=== PAUSE TestGlobMatch/foo*_bar2495=== RUN TestGlobMatch/*bar_bar2496=== PAUSE TestGlobMatch/*bar_bar2497=== RUN TestGlobMatch/*bar_foobar2498=== PAUSE TestGlobMatch/*bar_foobar2499=== RUN TestGlobMatch/*bar_foo2500=== PAUSE TestGlobMatch/*bar_foo2501=== RUN TestGlobMatch/foo*bar_foobar2502=== PAUSE TestGlobMatch/foo*bar_foobar2503=== RUN TestGlobMatch/foo*bar_foo123bar2504=== PAUSE TestGlobMatch/foo*bar_foo123bar2505=== RUN TestGlobMatch/foo*bar_foobarbaz2506=== PAUSE TestGlobMatch/foo*bar_foobarbaz2507=== RUN TestGlobMatch/*/*_foo/bar2508=== PAUSE TestGlobMatch/*/*_foo/bar2509=== RUN TestGlobMatch/*/*_foo2510=== PAUSE TestGlobMatch/*/*_foo2511=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2512=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2513=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02514=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02515=== RUN TestGlobMatch/refs/*/main_refs/heads/main2516=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2517=== RUN TestGlobMatch/fo?_foo2518=== PAUSE TestGlobMatch/fo?_foo2519=== RUN TestGlobMatch/fo?_fo2520=== PAUSE TestGlobMatch/fo?_fo2521=== RUN TestGlobMatch/fo?_fooo2522=== PAUSE TestGlobMatch/fo?_fooo2523=== RUN TestGlobMatch/?oo_foo2524=== PAUSE TestGlobMatch/?oo_foo2525=== RUN TestGlobMatch/?oo_boo2526=== PAUSE TestGlobMatch/?oo_boo2527=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2528=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2529=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2530=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2531=== CONT TestGlobMatch/foo_foo2532=== CONT TestGlobMatch/foo*bar_foobarbaz2533=== CONT TestGlobMatch/foo_bar2534=== CONT TestGlobMatch/refs/*/main_refs/heads/main2535=== CONT TestGlobMatch/*/*_foo2536=== CONT TestGlobMatch/foo*_bar2537=== CONT TestGlobMatch/*bar_foobar2538=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2539=== CONT TestGlobMatch/foo*bar_foo123bar2540=== CONT TestGlobMatch/?oo_boo2541=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2542=== CONT TestGlobMatch/foo*_foo2543=== CONT TestGlobMatch/*bar_foo2544=== CONT TestGlobMatch/*bar_bar2545=== CONT TestGlobMatch/*/*_foo/bar2546=== CONT TestGlobMatch/foo*bar_foobar2547=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2548=== CONT TestGlobMatch/?oo_foo2549=== CONT TestGlobMatch/*_anything2550=== CONT TestGlobMatch/fo?_fooo2551=== CONT TestGlobMatch/fo?_foo2552=== CONT TestGlobMatch/*_2553=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02554=== CONT TestGlobMatch/foo*_foobar2555=== CONT TestGlobMatch/fo?_fo2556--- PASS: TestGlobMatch (0.01s)2557 --- PASS: TestGlobMatch/foo_foo (0.00s)2558 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2559 --- PASS: TestGlobMatch/foo_bar (0.00s)2560 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2561 --- PASS: TestGlobMatch/*/*_foo (0.00s)2562 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2563 --- PASS: TestGlobMatch/foo*_bar (0.00s)2564 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2565 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2566 --- PASS: TestGlobMatch/?oo_boo (0.00s)2567 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2568 --- PASS: TestGlobMatch/foo*_foo (0.00s)2569 --- PASS: TestGlobMatch/*bar_foo (0.00s)2570 --- PASS: TestGlobMatch/*bar_bar (0.00s)2571 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2572 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2573 --- PASS: TestGlobMatch/?oo_foo (0.00s)2574 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2575 --- PASS: TestGlobMatch/*_anything (0.00s)2576 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2577 --- PASS: TestGlobMatch/fo?_foo (0.00s)2578 --- PASS: TestGlobMatch/*_ (0.00s)2579 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2580 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2581 --- PASS: TestGlobMatch/fo?_fo (0.00s)25822026/10/06 23:01:11 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:37119/oidc2583--- PASS: TestPins_TopLevelShorthand (0.05s)25842026/10/06 23:01:11 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:42383/oidc25852026/10/06 23:01:11 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:33937/oidc25862026/10/06 23:01:11 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:33627/oidc25872026/10/06 23:01:11 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:40713/oidc2588--- PASS: TestPins_ReservedForMatchingRule (0.06s)2589--- PASS: TestValidateToken_BoundSubjectMismatch (0.05s)25902026/10/06 23:01:11 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:33025/oidc2591--- PASS: TestValidateToken_MultipleProviders (0.06s)2592--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.06s)25932026/10/06 23:01:11 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:3639325942026/10/06 23:01:11 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:32889/oidc25952026/10/06 23:01:11 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:38793/oidc2596--- PASS: TestValidateToken_ValidToken (0.09s)2597--- PASS: TestValidateToken_KubernetesServiceAccount (0.09s)2598--- PASS: TestValidateToken_WrongAudience (0.09s)25992026/10/06 23:01:11 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC12326002026/10/06 23:01:11 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:44107/oidc2601--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.10s)2602--- PASS: TestValidateToken_BoundClaimsMismatch (0.10s)26032026/10/06 23:01:11 http: TLS handshake error from 127.0.0.1:41114: remote error: tls: bad certificate2604--- PASS: TestNewValidator_KubernetesRequiresCA (0.12s)26052026/10/06 23:01:11 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:45303/oidc2606--- PASS: TestValidateToken_Expired (0.16s)26072026/10/06 23:01:11 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:43221/oidc2608--- PASS: TestValidateToken_NoMatchingProvider (0.16s)26092026/10/06 23:01:11 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:33959/oidc2610--- PASS: TestScopes_Rules (0.20s)2611--- PASS: TestHTTPClientForHasTimeouts (0.20s)2612PASS2613Running hook tests...2614=== RUN TestSendPathsEmpty2615=== PAUSE TestSendPathsEmpty2616=== RUN TestQueueEnqueueAndFetch2617=== PAUSE TestQueueEnqueueAndFetch2618=== RUN TestQueueDeduplication2619=== PAUSE TestQueueDeduplication2620=== RUN TestQueueRemove2621=== PAUSE TestQueueRemove2622=== RUN TestQueueFetchBatchLimit2623=== PAUSE TestQueueFetchBatchLimit2624=== RUN TestQueueRetryMovesToBack2625=== PAUSE TestQueueRetryMovesToBack2626=== RUN TestQueueFetchRemoveLifecycle2627=== PAUSE TestQueueFetchRemoveLifecycle2628=== RUN TestQueueConcurrentWriters2629=== PAUSE TestQueueConcurrentWriters2630=== RUN TestQueueEnqueueWaitsOutSlowWriter2631=== PAUSE TestQueueEnqueueWaitsOutSlowWriter2632=== RUN TestQueueRemoveLargeClosure2633=== PAUSE TestQueueRemoveLargeClosure2634=== RUN TestServerClientIntegration2635=== PAUSE TestServerClientIntegration2636=== RUN TestServerQueueError2637=== PAUSE TestServerQueueError2638=== RUN TestServerRefusesOversizedAndNonStoreRequests2639=== PAUSE TestServerRefusesOversizedAndNonStoreRequests2640=== RUN TestGetListenerSocketActivation2641 server_test.go:317: === RUN TestGetListenerSocketActivation2642 --- PASS: TestGetListenerSocketActivation (0.00s)2643 PASS2644 2645--- PASS: TestGetListenerSocketActivation (1.02s)2646=== RUN TestServerStalledClientDoesNotBlockShutdown2647=== PAUSE TestServerStalledClientDoesNotBlockShutdown2648=== RUN TestServerBacksOffOnAcceptErrors2649=== PAUSE TestServerBacksOffOnAcceptErrors2650=== RUN TestDrainIsolatesPoisonPath2651=== PAUSE TestDrainIsolatesPoisonPath2652=== RUN TestRunNotBlockedByPoisonHead2653=== PAUSE TestRunNotBlockedByPoisonHead2654=== RUN TestDrainGivesUpWhenServerDown2655=== PAUSE TestDrainGivesUpWhenServerDown2656=== RUN TestFailedPathPrunedByLaterClosure2657=== PAUSE TestFailedPathPrunedByLaterClosure2658=== RUN TestWorkerUploadsAndRemoves2659=== PAUSE TestWorkerUploadsAndRemoves2660=== RUN TestWorkerSkipsGCdPaths2661=== PAUSE TestWorkerSkipsGCdPaths2662=== RUN TestWorkerPrunesClosureDeps2663=== PAUSE TestWorkerPrunesClosureDeps2664=== RUN TestWorkerRemovesCachedPathBatchedWithLargerClosure2665=== PAUSE TestWorkerRemovesCachedPathBatchedWithLargerClosure2666=== RUN TestDrainTimeout2667=== PAUSE TestDrainTimeout2668=== RUN TestDrainTimeoutDuringIsolation2669=== PAUSE TestDrainTimeoutDuringIsolation2670=== RUN TestShutdownFinishesInFlightPush2671=== PAUSE TestShutdownFinishesInFlightPush2672=== RUN TestWorkerRemoveFailureIsNotProgress2673=== PAUSE TestWorkerRemoveFailureIsNotProgress2674=== RUN TestWorkerKeepsPathItCannotStat2675=== PAUSE TestWorkerKeepsPathItCannotStat2676=== CONT TestSendPathsEmpty2677=== CONT TestDrainIsolatesPoisonPath2678--- PASS: TestSendPathsEmpty (0.00s)2679=== CONT TestQueueFetchRemoveLifecycle2680=== CONT TestQueueRetryMovesToBack2681=== CONT TestQueueFetchBatchLimit2682=== CONT TestServerRefusesOversizedAndNonStoreRequests2683=== CONT TestQueueEnqueueWaitsOutSlowWriter2684=== CONT TestQueueRemove2685=== CONT TestServerQueueError2686=== CONT TestQueueEnqueueAndFetch2687=== CONT TestQueueDeduplication2688=== CONT TestWorkerSkipsGCdPaths26892026/10/06 23:01:13 ERROR Refusing path outside the store path=/etc/shadow store=/nix/store2690=== CONT TestDrainTimeout26912026/10/06 23:01:13 ERROR Failed to queue paths error="permission denied" count=12692=== CONT TestServerStalledClientDoesNotBlockShutdown2693=== CONT TestDrainTimeoutDuringIsolation26942026/10/06 23:01:13 ERROR Refusing path outside the store path=/nix/store store=/nix/store2695=== CONT TestWorkerPrunesClosureDeps2696=== RUN TestDrainTimeoutDuringIsolation/probe_cut_short2697--- PASS: TestServerQueueError (0.00s)26982026/10/06 23:01:13 ERROR Refusing path outside the store path=/nix/store/ store=/nix/store2699=== PAUSE TestDrainTimeoutDuringIsolation/probe_cut_short2700=== CONT TestQueueRemoveLargeClosure2701=== RUN TestDrainTimeoutDuringIsolation/probe_outlasts_the_deadline2702=== PAUSE TestDrainTimeoutDuringIsolation/probe_outlasts_the_deadline2703=== CONT TestQueueConcurrentWriters2704=== CONT TestWorkerRemoveFailureIsNotProgress27052026/10/06 23:01:13 ERROR Refusing path outside the store path=/nix/store/../../etc/shadow store=/nix/store2706=== CONT TestDrainGivesUpWhenServerDown2707=== CONT TestWorkerRemovesCachedPathBatchedWithLargerClosure2708=== CONT TestWorkerUploadsAndRemoves27092026/10/06 23:01:13 ERROR Refusing path outside the store path=/nix/store/0123456789abcdfghijklmnpqrsvwxyz-hello/bin/sh store=/nix/store2710=== CONT TestRunNotBlockedByPoisonHead2711=== CONT TestShutdownFinishesInFlightPush2712=== RUN TestShutdownFinishesInFlightPush/completes2713=== CONT TestFailedPathPrunedByLaterClosure2714=== CONT TestServerClientIntegration2715=== CONT TestServerBacksOffOnAcceptErrors2716=== RUN TestWorkerRemoveFailureIsNotProgress/collected_path2717=== PAUSE TestShutdownFinishesInFlightPush/completes2718=== PAUSE TestWorkerRemoveFailureIsNotProgress/collected_path27192026/10/06 23:01:13 ERROR Refusing path outside the store path=nix/store/0123456789abcdfghijklmnpqrsvwxyz-hello store=/nix/store2720=== RUN TestShutdownFinishesInFlightPush/hung_push_bounded_by_the_drain_timeout2721=== RUN TestWorkerRemoveFailureIsNotProgress/pushed_batch27222026/10/06 23:01:13 ERROR Accept failed error="too many open files"2723=== PAUSE TestShutdownFinishesInFlightPush/hung_push_bounded_by_the_drain_timeout27242026/10/06 23:01:13 ERROR Refusing path outside the store path=/nix/storeX/0123456789abcdfghijklmnpqrsvwxyz-hello store=/nix/store2725=== PAUSE TestWorkerRemoveFailureIsNotProgress/pushed_batch2726=== CONT TestWorkerKeepsPathItCannotStat2727=== RUN TestWorkerRemoveFailureIsNotProgress/isolated_paths2728=== PAUSE TestWorkerRemoveFailureIsNotProgress/isolated_paths27292026/10/06 23:01:13 ERROR Refusing path outside the store path=/nix/store/.links store=/nix/store2730=== CONT TestDrainTimeoutDuringIsolation/probe_outlasts_the_deadline2731--- PASS: TestServerClientIntegration (0.00s)2732=== CONT TestDrainTimeoutDuringIsolation/probe_cut_short27332026/10/06 23:01:13 ERROR Refusing path outside the store path=/nix/store/aaa-hello store=/nix/store27342026/10/06 23:01:13 ERROR Refusing path outside the store path=/nix/store/0123456789abcdfghijklmnpqrsvwxyz store=/nix/store27352026/10/06 23:01:13 ERROR Refusing path outside the store path=/nix/store/0123456789abcdfghijklmnpqrsvwxyz- store=/nix/store27362026/10/06 23:01:13 ERROR Accept failed error="too many open files"27372026/10/06 23:01:13 ERROR Refusing path outside the store path=/nix/store/0123456789ebcdfghijklmnpqrsvwxyz-hello store=/nix/store27382026/10/06 23:01:13 ERROR Refusing path outside the store path="/nix/store/0123456789abcdfghijklmnpqrsvwxyz-hel\x00lo" store=/nix/store27392026/10/06 23:01:13 ERROR Refusing path outside the store path=/nix/store/0123456789abcdfghijklmnpqrsvwxyz-hel/lo store=/nix/store27402026/10/06 23:01:13 ERROR Refusing path outside the store path=/nix/store/0123456789abcdfghijklmnpqrsvwxyz-xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx store=/nix/store27412026/10/06 23:01:13 ERROR Failed to decode request error="unexpected EOF"2742--- PASS: TestServerRefusesOversizedAndNonStoreRequests (0.02s)2743=== CONT TestShutdownFinishesInFlightPush/completes27442026/10/06 23:01:13 ERROR Accept failed error="too many open files"27452026/10/06 23:01:13 ERROR Accept failed error="too many open files"27462026/10/06 23:01:13 INFO Uploading batch count=427472026/10/06 23:01:13 ERROR Upload failed error="upload failed" count=427482026/10/06 23:01:13 INFO Uploading batch count=227492026/10/06 23:01:13 INFO Upload queue status pending=327502026/10/06 23:01:13 INFO Uploading batch count=127512026/10/06 23:01:13 ERROR Upload failed error="upload failed" count=127522026/10/06 23:01:13 INFO Upload queue status pending=327532026/10/06 23:01:13 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainIsolatesPoisonPath2271643306/002/bbb2754--- PASS: TestQueueFetchBatchLimit (0.07s)27552026/10/06 23:01:13 INFO Upload queue status pending=22756=== CONT TestShutdownFinishesInFlightPush/hung_push_bounded_by_the_drain_timeout27572026/10/06 23:01:13 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat3819808098/002/locked/aaa error="lstat /build/TestWorkerKeepsPathItCannotStat3819808098/002/locked/aaa: permission denied"2758=== CONT TestWorkerRemoveFailureIsNotProgress/collected_path27592026/10/06 23:01:13 INFO Uploading batch count=227602026/10/06 23:01:13 INFO Upload queue status pending=22761--- PASS: TestQueueRetryMovesToBack (0.07s)27622026/10/06 23:01:13 INFO Upload queue status pending=227632026/10/06 23:01:13 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerSkipsGCdPaths3744995448/002/nonexistent27642026/10/06 23:01:13 INFO Uploading batch count=12765--- PASS: TestQueueFetchRemoveLifecycle (0.08s)2766=== CONT TestWorkerRemoveFailureIsNotProgress/isolated_paths27672026/10/06 23:01:13 INFO Uploading batch count=22768=== CONT TestWorkerRemoveFailureIsNotProgress/pushed_batch27692026/10/06 23:01:13 INFO Uploading batch count=22770--- PASS: TestQueueEnqueueAndFetch (0.07s)2771--- PASS: TestQueueDeduplication (0.07s)27722026/10/06 23:01:13 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat3819808098/002/locked/aaa error="lstat /build/TestWorkerKeepsPathItCannotStat3819808098/002/locked/aaa: permission denied"27732026/10/06 23:01:13 INFO Uploading batch count=227742026/10/06 23:01:13 ERROR Upload failed error="upload failed" count=227752026/10/06 23:01:13 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown784017013/002/a27762026/10/06 23:01:13 INFO Upload queue status pending=227772026/10/06 23:01:13 INFO Uploading batch count=127782026/10/06 23:01:13 ERROR Upload failed error="upload failed" count=12779--- PASS: TestQueueRemove (0.08s)27802026/10/06 23:01:13 INFO Uploading batch count=427812026/10/06 23:01:13 ERROR Accept failed error="too many open files"27822026/10/06 23:01:13 ERROR Upload failed error="upload failed" count=427832026/10/06 23:01:13 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat3819808098/002/locked/aaa error="lstat /build/TestWorkerKeepsPathItCannotStat3819808098/002/locked/aaa: permission denied"27842026/10/06 23:01:13 INFO Uploading batch count=227852026/10/06 23:01:13 INFO Uploading batch count=127862026/10/06 23:01:13 ERROR Upload failed error="upload failed" count=127872026/10/06 23:01:13 INFO Uploading batch count=427882026/10/06 23:01:13 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown784017013/002/b27892026/10/06 23:01:13 ERROR Upload failed error="upload failed" count=427902026/10/06 23:01:13 INFO Uploading batch count=127912026/10/06 23:01:13 ERROR Upload failed error="upload failed" count=127922026/10/06 23:01:13 ERROR Drain finished with paths left in queue remaining=127932026/10/06 23:01:13 INFO Uploading batch count=127942026/10/06 23:01:13 INFO Uploading batch count=227952026/10/06 23:01:13 ERROR Upload failed error="upload failed" count=227962026/10/06 23:01:13 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown784017013/002/c27972026/10/06 23:01:13 INFO Uploading batch count=127982026/10/06 23:01:13 ERROR Upload failed error="upload failed" count=12799--- PASS: TestWorkerKeepsPathItCannotStat (0.09s)28002026/10/06 23:01:13 INFO Uploading batch count=128012026/10/06 23:01:13 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown784017013/002/d2802--- PASS: TestWorkerSkipsGCdPaths (0.09s)2803--- PASS: TestWorkerUploadsAndRemoves (0.09s)28042026/10/06 23:01:13 ERROR Drain finished with paths left in queue remaining=128052026/10/06 23:01:13 INFO Uploading batch count=228062026/10/06 23:01:13 ERROR Upload failed error="upload failed" count=228072026/10/06 23:01:13 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown784017013/002/e28082026/10/06 23:01:13 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown784017013/002/f2809--- PASS: TestWorkerRemovesCachedPathBatchedWithLargerClosure (0.09s)2810--- PASS: TestWorkerPrunesClosureDeps (0.10s)28112026/10/06 23:01:13 ERROR Drain finished with paths left in queue remaining=1028122026/10/06 23:01:13 INFO Upload queue status pending=22813--- PASS: TestFailedPathPrunedByLaterClosure (0.10s)28142026/10/06 23:01:13 INFO Uploading batch count=22815--- PASS: TestDrainIsolatesPoisonPath (0.11s)2816--- PASS: TestDrainGivesUpWhenServerDown (0.10s)28172026/10/06 23:01:13 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgresscollected_path328250292/001/nonexistent28182026/10/06 23:01:13 INFO Uploading batch count=228192026/10/06 23:01:13 ERROR Upload failed error="upload failed" count=228202026/10/06 23:01:13 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=128212026/10/06 23:01:13 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=128222026/10/06 23:01:13 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=128232026/10/06 23:01:13 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgresscollected_path328250292/001/nonexistent28242026/10/06 23:01:13 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=128252026/10/06 23:01:13 INFO Uploading batch count=228262026/10/06 23:01:13 ERROR Upload failed error="upload failed" count=228272026/10/06 23:01:13 INFO Uploading batch count=228282026/10/06 23:01:13 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgresscollected_path328250292/001/nonexistent28292026/10/06 23:01:13 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=128302026/10/06 23:01:13 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=128312026/10/06 23:01:13 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=128322026/10/06 23:01:13 ERROR Drain finished with paths left in queue remaining=128332026/10/06 23:01:13 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=228342026/10/06 23:01:13 INFO Uploading batch count=228352026/10/06 23:01:13 ERROR Upload failed error="upload failed" count=228362026/10/06 23:01:13 INFO Uploading batch count=228372026/10/06 23:01:13 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=128382026/10/06 23:01:13 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=228392026/10/06 23:01:13 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=128402026/10/06 23:01:13 INFO Uploading batch count=228412026/10/06 23:01:13 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=228422026/10/06 23:01:13 ERROR Drain finished with paths left in queue remaining=228432026/10/06 23:01:13 ERROR Drain finished with paths left in queue remaining=22844--- PASS: TestWorkerRemoveFailureIsNotProgress (0.00s)2845 --- PASS: TestWorkerRemoveFailureIsNotProgress/collected_path (0.05s)2846 --- PASS: TestWorkerRemoveFailureIsNotProgress/pushed_batch (0.04s)2847 --- PASS: TestWorkerRemoveFailureIsNotProgress/isolated_paths (0.05s)28482026/10/06 23:01:13 ERROR Accept failed error="too many open files"28492026/10/06 23:01:14 ERROR Failed to decode request error="read unix /build/hook2158749694/test.sock->@: i/o timeout"28502026/10/06 23:01:14 ERROR Failed to write response error="write unix /build/hook2158749694/test.sock->@: i/o timeout"2851--- PASS: TestServerStalledClientDoesNotBlockShutdown (0.20s)28522026/10/06 23:01:14 ERROR Upload failed error="context canceled" count=228532026/10/06 23:01:14 ERROR Drain finished with paths left in queue remaining=42854--- PASS: TestDrainTimeout (0.27s)28552026/10/06 23:01:14 ERROR Drain finished with paths left in queue remaining=428562026/10/06 23:01:14 ERROR Upload failed error="context canceled" count=228572026/10/06 23:01:14 ERROR Drain finished with paths left in queue remaining=22858--- PASS: TestShutdownFinishesInFlightPush (0.00s)2859 --- PASS: TestShutdownFinishesInFlightPush/completes (0.18s)2860 --- PASS: TestShutdownFinishesInFlightPush/hung_push_bounded_by_the_drain_timeout (0.24s)28612026/10/06 23:01:14 ERROR Accept failed error="too many open files"28622026/10/06 23:01:14 ERROR Drain finished with paths left in queue remaining=32863--- PASS: TestDrainTimeoutDuringIsolation (0.00s)2864 --- PASS: TestDrainTimeoutDuringIsolation/probe_cut_short (0.28s)2865 --- PASS: TestDrainTimeoutDuringIsolation/probe_outlasts_the_deadline (0.39s)2866--- PASS: TestQueueConcurrentWriters (0.62s)28672026/10/06 23:01:14 ERROR Accept failed error="too many open files"2868--- PASS: TestServerBacksOffOnAcceptErrors (0.64s)28692026/10/06 23:01:14 INFO Uploading batch count=128702026/10/06 23:01:14 INFO Uploading batch count=128712026/10/06 23:01:14 INFO Uploading batch count=128722026/10/06 23:01:14 ERROR Upload failed error="upload failed" count=128732026/10/06 23:01:14 INFO Uploading batch count=128742026/10/06 23:01:14 ERROR Upload failed error="upload failed" count=128752026/10/06 23:01:14 INFO Uploading batch count=128762026/10/06 23:01:14 ERROR Upload failed error="upload failed" count=128772026/10/06 23:01:14 INFO Uploading batch count=128782026/10/06 23:01:14 ERROR Upload failed error="upload failed" count=128792026/10/06 23:01:14 ERROR Drain finished with paths left in queue remaining=12880--- PASS: TestRunNotBlockedByPoisonHead (1.10s)2881--- PASS: TestQueueRemoveLargeClosure (1.58s)2882--- PASS: TestQueueEnqueueWaitsOutSlowWriter (6.07s)2883PASS2884Running signing tests...2885=== RUN TestExternalSigner2886=== PAUSE TestExternalSigner2887=== RUN TestExternalSignerWrongPublicKey2888=== PAUSE TestExternalSignerWrongPublicKey2889=== RUN TestExternalSignerErrors2890=== PAUSE TestExternalSignerErrors2891=== RUN TestExternalSignerRestartsAfterCrash2892=== PAUSE TestExternalSignerRestartsAfterCrash2893=== RUN TestExternalSignerProgramErrorKeepsProcess2894=== PAUSE TestExternalSignerProgramErrorKeepsProcess2895=== RUN TestExternalSignerClose2896=== PAUSE TestExternalSignerClose2897=== RUN TestExternalSignerRejectsInvalidPublicKey2898=== PAUSE TestExternalSignerRejectsInvalidPublicKey2899=== RUN TestExternalSignerCancellation2900=== PAUSE TestExternalSignerCancellation2901=== RUN TestGenerateFingerprint2902=== PAUSE TestGenerateFingerprint2903=== RUN TestParseSigningKey2904=== PAUSE TestParseSigningKey2905=== RUN TestSign2906=== PAUSE TestSign2907=== RUN TestSignBatch2908=== PAUSE TestSignBatch2909=== RUN TestNilKeyPublicKey2910=== PAUSE TestNilKeyPublicKey2911=== RUN TestSignErrors2912=== PAUSE TestSignErrors2913=== CONT TestExternalSigner2914=== CONT TestExternalSignerCancellation2915=== CONT TestSignBatch2916=== CONT TestSignErrors2917=== CONT TestNilKeyPublicKey2918=== CONT TestExternalSignerClose2919--- PASS: TestNilKeyPublicKey (0.00s)2920=== CONT TestExternalSignerRejectsInvalidPublicKey2921=== CONT TestExternalSignerProgramErrorKeepsProcess2922=== CONT TestExternalSignerWrongPublicKey2923=== RUN TestSignErrors/nil_key2924=== CONT TestExternalSignerErrors2925=== CONT TestParseSigningKey2926=== CONT TestExternalSignerRestartsAfterCrash2927=== CONT TestSign2928=== CONT TestGenerateFingerprint2929=== RUN TestGenerateFingerprint/basic_with_references2930=== PAUSE TestGenerateFingerprint/basic_with_references2931=== RUN TestGenerateFingerprint/no_references2932=== PAUSE TestGenerateFingerprint/no_references2933=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2934=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2935=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2936=== RUN TestExternalSignerRejectsInvalidPublicKey/#002937=== PAUSE TestSignErrors/nil_key2938=== RUN TestParseSigningKey/valid_32-byte_key2939=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002940=== RUN TestExternalSignerErrors/missing_signature_name2941=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2942=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2943=== PAUSE TestExternalSignerErrors/missing_signature_name2944=== PAUSE TestParseSigningKey/valid_32-byte_key2945=== RUN TestGenerateFingerprint/invalid_nar_hash_length2946=== RUN TestSignErrors/nil_narinfo2947=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2948=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2949=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2950--- PASS: TestSign (0.00s)2951=== RUN TestExternalSignerErrors/missing_signatures2952=== PAUSE TestExternalSignerErrors/missing_signatures2953=== PAUSE TestSignErrors/nil_narinfo2954=== RUN TestExternalSignerErrors/null_signatures2955--- PASS: TestExternalSignerClose (0.01s)2956=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2957=== RUN TestGenerateFingerprint/invalid_store_path_prefix2958=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2959=== RUN TestSignErrors/invalid_narinfo2960=== PAUSE TestExternalSignerErrors/null_signatures2961=== RUN TestExternalSignerErrors/too_few_signatures2962=== RUN TestParseSigningKey/no_colon2963=== PAUSE TestParseSigningKey/no_colon2964--- PASS: TestExternalSignerProgramErrorKeepsProcess (0.00s)2965=== RUN TestParseSigningKey/empty_name2966=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2967=== PAUSE TestSignErrors/invalid_narinfo2968=== RUN TestSignErrors/canceled2969=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2970=== RUN TestGenerateFingerprint/invalid_reference_prefix2971=== PAUSE TestExternalSignerErrors/too_few_signatures2972--- PASS: TestSignBatch (0.01s)2973=== PAUSE TestParseSigningKey/empty_name2974=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2975=== PAUSE TestSignErrors/canceled2976=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2977=== CONT TestSignErrors/invalid_narinfo2978=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2979=== CONT TestGenerateFingerprint/invalid_nar_hash_length2980=== RUN TestExternalSignerErrors/unrequested_key2981=== RUN TestParseSigningKey/invalid_base642982=== CONT TestGenerateFingerprint/invalid_reference_prefix2983=== PAUSE TestParseSigningKey/invalid_base642984=== RUN TestParseSigningKey/wrong_length2985=== CONT TestSignErrors/nil_key2986=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2987=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2988=== CONT TestSignErrors/nil_narinfo2989=== CONT TestSignErrors/canceled2990=== CONT TestGenerateFingerprint/no_references2991=== CONT TestGenerateFingerprint/invalid_store_path_prefix2992=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2993=== CONT TestGenerateFingerprint/basic_with_references2994=== PAUSE TestExternalSignerErrors/unrequested_key2995--- PASS: TestExternalSignerWrongPublicKey (0.01s)2996=== PAUSE TestParseSigningKey/wrong_length2997=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2998--- PASS: TestSignErrors (0.01s)2999 --- PASS: TestSignErrors/invalid_narinfo (0.00s)3000 --- PASS: TestSignErrors/nil_key (0.00s)3001 --- PASS: TestSignErrors/nil_narinfo (0.00s)3002 --- PASS: TestSignErrors/canceled (0.00s)3003=== RUN TestExternalSignerErrors/invalid_signature_base643004=== PAUSE TestExternalSignerErrors/invalid_signature_base643005=== CONT TestParseSigningKey/wrong_length3006=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name3007=== RUN TestExternalSignerErrors/program_error3008=== CONT TestParseSigningKey/invalid_base643009=== CONT TestParseSigningKey/no_colon3010=== CONT TestParseSigningKey/valid_32-byte_key3011=== CONT TestParseSigningKey/empty_name3012=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!3013=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon3014=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==3015=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=3016=== CONT TestExternalSignerRejectsInvalidPublicKey/#003017--- PASS: TestGenerateFingerprint (0.00s)3018 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)3019 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)3020 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)3021 --- PASS: TestGenerateFingerprint/no_references (0.00s)3022 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)3023 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)3024 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)3025=== PAUSE TestExternalSignerErrors/program_error3026=== RUN TestExternalSignerErrors/null3027=== PAUSE TestExternalSignerErrors/null3028--- PASS: TestParseSigningKey (0.01s)3029 --- PASS: TestParseSigningKey/wrong_length (0.00s)3030 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)3031 --- PASS: TestParseSigningKey/no_colon (0.00s)3032 --- PASS: TestParseSigningKey/empty_name (0.00s)3033 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)3034 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)3035=== RUN TestExternalSignerErrors/wrong_signature_length3036--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.01s)3037 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)3038 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)3039 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)3040 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)3041 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)3042=== PAUSE TestExternalSignerErrors/wrong_signature_length3043=== RUN TestExternalSignerErrors/invalid_JSON3044=== PAUSE TestExternalSignerErrors/invalid_JSON3045=== RUN TestExternalSignerErrors/wrong_id3046=== PAUSE TestExternalSignerErrors/wrong_id3047=== RUN TestExternalSignerErrors/wrong_signature_name3048=== PAUSE TestExternalSignerErrors/wrong_signature_name3049=== RUN TestExternalSignerErrors/exit_at_startup3050=== PAUSE TestExternalSignerErrors/exit_at_startup3051=== RUN TestExternalSignerErrors/exit_on_request3052=== PAUSE TestExternalSignerErrors/exit_on_request3053=== RUN TestExternalSignerErrors/wrong_shape3054=== PAUSE TestExternalSignerErrors/wrong_shape3055=== RUN TestExternalSignerErrors/wrong_signatures_shape3056=== PAUSE TestExternalSignerErrors/wrong_signatures_shape3057=== CONT TestExternalSignerErrors/missing_signature_name3058=== CONT TestExternalSignerErrors/wrong_shape3059=== CONT TestExternalSignerErrors/wrong_signature_length3060=== CONT TestExternalSignerErrors/wrong_signatures_shape3061=== CONT TestExternalSignerErrors/wrong_id3062=== CONT TestExternalSignerErrors/exit_on_request3063=== CONT TestExternalSignerErrors/invalid_JSON3064=== CONT TestExternalSignerErrors/wrong_signature_name3065=== CONT TestExternalSignerErrors/unrequested_key3066=== CONT TestExternalSignerErrors/exit_at_startup3067=== CONT TestExternalSignerErrors/invalid_signature_base643068=== CONT TestExternalSignerErrors/program_error3069=== CONT TestExternalSignerErrors/null3070=== CONT TestExternalSignerErrors/missing_signatures3071=== CONT TestExternalSignerErrors/too_few_signatures3072=== CONT TestExternalSignerErrors/null_signatures3073--- PASS: TestExternalSigner (0.01s)3074--- PASS: TestExternalSignerRestartsAfterCrash (0.01s)3075--- PASS: TestExternalSignerErrors (0.01s)3076 --- PASS: TestExternalSignerErrors/missing_signature_name (0.00s)3077 --- PASS: TestExternalSignerErrors/wrong_shape (0.01s)3078 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (0.01s)3079 --- PASS: TestExternalSignerErrors/wrong_signature_length (0.01s)3080 --- PASS: TestExternalSignerErrors/unrequested_key (0.01s)3081 --- PASS: TestExternalSignerErrors/exit_at_startup (0.01s)3082 --- PASS: TestExternalSignerErrors/wrong_signature_name (0.01s)3083 --- PASS: TestExternalSignerErrors/invalid_JSON (0.01s)3084 --- PASS: TestExternalSignerErrors/wrong_id (0.01s)3085 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (0.01s)3086 --- PASS: TestExternalSignerErrors/exit_on_request (0.01s)3087 --- PASS: TestExternalSignerErrors/too_few_signatures (0.00s)3088 --- PASS: TestExternalSignerErrors/null (0.00s)3089 --- PASS: TestExternalSignerErrors/missing_signatures (0.00s)3090 --- PASS: TestExternalSignerErrors/program_error (0.01s)3091 --- PASS: TestExternalSignerErrors/null_signatures (0.01s)3092--- PASS: TestExternalSignerCancellation (0.02s)3093PASS3094Running OpenBao signer tests...3095=== RUN TestSign3096=== PAUSE TestSign3097=== RUN TestSignErrors3098=== PAUSE TestSignErrors3099=== RUN TestServe3100=== PAUSE TestServe3101=== RUN TestServeRejectsGarbage3102=== PAUSE TestServeRejectsGarbage3103=== CONT TestSign3104=== CONT TestServeRejectsGarbage3105=== CONT TestServe3106=== CONT TestSignErrors3107--- PASS: TestServeRejectsGarbage (0.00s)3108=== RUN TestSignErrors/http_error3109=== PAUSE TestSignErrors/http_error3110=== RUN TestSignErrors/invalid_json3111=== PAUSE TestSignErrors/invalid_json3112--- PASS: TestServe (0.00s)3113=== RUN TestSignErrors/no_prefix3114=== PAUSE TestSignErrors/no_prefix3115=== RUN TestSignErrors/invalid_base643116=== PAUSE TestSignErrors/invalid_base643117=== CONT TestSignErrors/no_prefix3118=== CONT TestSignErrors/invalid_json3119=== CONT TestSignErrors/invalid_base643120=== CONT TestSignErrors/http_error3121--- PASS: TestSign (0.01s)3122--- PASS: TestSignErrors (0.00s)3123 --- PASS: TestSignErrors/invalid_json (0.00s)3124 --- PASS: TestSignErrors/no_prefix (0.00s)3125 --- PASS: TestSignErrors/http_error (0.00s)3126 --- PASS: TestSignErrors/invalid_base64 (0.00s)3127PASS3128Running niks3-hook command tests...3129=== RUN TestServeSecondSignalEndsDrain3130=== PAUSE TestServeSecondSignalEndsDrain3131=== RUN TestServeThenDrainPushesSendAcceptedBeforeShutdown3132=== PAUSE TestServeThenDrainPushesSendAcceptedBeforeShutdown3133=== CONT TestServeThenDrainPushesSendAcceptedBeforeShutdown3134=== CONT TestServeSecondSignalEndsDrain3135--- PASS: TestServeSecondSignalEndsDrain (0.08s)31362026/10/06 23:01:23 INFO Upload queue status pending=131372026/10/06 23:01:23 INFO Uploading batch count=13138--- PASS: TestServeThenDrainPushesSendAcceptedBeforeShutdown (0.13s)3139PASS3140Running rate limiter tests...3141=== RUN TestAdaptiveRateLimiter_ThreadSafety3142=== PAUSE TestAdaptiveRateLimiter_ThreadSafety3143=== CONT TestAdaptiveRateLimiter_ThreadSafety31442026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=84.7000000000000231452026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=59.29000000000000631462026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=41.50331472026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=29.052131482026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=20.3364731492026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=14.23552899999999831502026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=9.96487029999999831512026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=6.97540920999999831522026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=531532026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=531542026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=531552026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=531562026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=531572026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=531582026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=531592026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=531602026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=531612026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=531622026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=531632026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=531642026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=531652026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=531662026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=531672026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=531682026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=531692026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=531702026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=531712026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=531722026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=531732026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=531742026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=17.69064599747530431752026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=12.38345219823271231762026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=8.66841653876289831772026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=6.06789157713402831782026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=531792026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=531802026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=531812026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=531822026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=531832026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=531842026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=531852026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=531862026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=531872026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=531882026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=531892026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=531902026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=531912026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=531922026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=531932026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=6.200463500000001531942026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=531952026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=531962026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=531972026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=531982026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=531992026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=532002026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=532012026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=532022026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=532032026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=532042026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=532052026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=532062026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=532072026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=532082026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=532092026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=532102026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=532112026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=532122026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=532132026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=532142026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=5.12435000000000132152026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=532162026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=532172026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=532182026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=532192026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=532202026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=532212026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=532222026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=532232026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=532242026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=532252026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=532262026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=532272026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=532282026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=532292026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=532302026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=532312026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=532322026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=532332026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=532342026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=532352026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=532362026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=532372026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=532382026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=532392026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=532402026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=532412026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=532422026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=532432026/10/06 23:01:24 WARN Rate limiter backed off name=test rate=53244--- PASS: TestAdaptiveRateLimiter_ThreadSafety (0.10s)3245PASS