niks3-go-unit-tests
checks.x86_64-linux.go-unit-tests
· build #436
· raw
1tribuchet: building on jamie2Running client tests...3=== RUN TestDoServerRequestAttachesToken4=== PAUSE TestDoServerRequestAttachesToken5=== RUN TestUploadBuildLog_FileBodyReplayedOnRetry6=== PAUSE TestUploadBuildLog_FileBodyReplayedOnRetry7=== RUN TestRegisterUploadedObjectReusesConnections8=== PAUSE TestRegisterUploadedObjectReusesConnections9=== RUN TestRunGarbageCollection_FinishedOnAnotherReplica10=== PAUSE TestRunGarbageCollection_FinishedOnAnotherReplica11=== RUN TestRunGarbageCollection_NotFoundAfterLocalRun12=== PAUSE TestRunGarbageCollection_NotFoundAfterLocalRun13=== RUN TestCaseHackSuffix14=== PAUSE TestCaseHackSuffix15=== RUN TestFilterOversizedClosures16=== PAUSE TestFilterOversizedClosures17=== RUN TestPushPathsReportsOnlyUnuploadablePathsOfSkippedClosure18=== PAUSE TestPushPathsReportsOnlyUnuploadablePathsOfSkippedClosure19=== RUN TestUploadMultipart_PartsInParallel20=== PAUSE TestUploadMultipart_PartsInParallel21=== RUN TestUploadMultipart_FailedPartBufferNotReused22=== PAUSE TestUploadMultipart_FailedPartBufferNotReused23=== RUN TestUploadMultipart_ProducerErrorIsNotEOF24=== PAUSE TestUploadMultipart_ProducerErrorIsNotEOF25=== RUN TestPartSizeForNAR26=== PAUSE TestPartSizeForNAR27=== RUN TestUploadMultipart_SupersededByPeer28=== PAUSE TestUploadMultipart_SupersededByPeer29=== RUN TestDumpPathCaseHackMatchesNix30--- PASS: TestDumpPathCaseHackMatchesNix (0.03s)31=== RUN TestDumpPathCaseHackCollision32--- PASS: TestDumpPathCaseHackCollision (0.00s)33=== RUN TestSupersededNARStillUploadsListing34=== PAUSE TestSupersededNARStillUploadsListing35=== RUN TestTruncatedNARDumpIsNotCompleted36=== PAUSE TestTruncatedNARDumpIsNotCompleted37=== RUN TestDumpPathMatchesNix38=== PAUSE TestDumpPathMatchesNix39=== RUN TestDumpPathSingleFile40=== PAUSE TestDumpPathSingleFile41=== RUN TestDumpPathWriterError42=== PAUSE TestDumpPathWriterError43=== RUN TestDumpPathWriterErrorStopsReading44 nar_test.go:289: read 114 of 32768000 bytes45--- PASS: TestDumpPathWriterErrorStopsReading (0.59s)46=== RUN TestEncodeNixBase3247=== PAUSE TestEncodeNixBase3248=== RUN TestEncodeNixBase32WithRealHash49=== PAUSE TestEncodeNixBase32WithRealHash50=== RUN TestConvertHashToNix3251=== PAUSE TestConvertHashToNix3252=== RUN TestGetStorePathHash53=== PAUSE TestGetStorePathHash54=== RUN TestPathInfoHashCompatibility55=== PAUSE TestPathInfoHashCompatibility56=== RUN TestParsePathInfoJSON57=== PAUSE TestParsePathInfoJSON58=== RUN TestParsePathInfoJSONMultiplePaths59=== PAUSE TestParsePathInfoJSONMultiplePaths60=== RUN TestPathInfoCACompatibility61=== PAUSE TestPathInfoCACompatibility62=== RUN TestUploadPendingObjectsStopsStartingAfterFailure63--- PASS: TestUploadPendingObjectsStopsStartingAfterFailure (0.01s)64=== RUN TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent65=== PAUSE TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent66=== RUN TestCompletePendingClosure_NotFoundWithoutKey67=== PAUSE TestCompletePendingClosure_NotFoundWithoutKey68=== RUN TestRateLimiterFeedback69=== PAUSE TestRateLimiterFeedback70=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess71=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess72=== RUN TestRegisterUploadedObject_BoundedAgainstSilentServer73=== PAUSE TestRegisterUploadedObject_BoundedAgainstSilentServer74=== RUN TestResolveStorePath75=== PAUSE TestResolveStorePath76=== RUN TestDoWithRetry_BodyReplayedViaGetBody77=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody78=== RUN TestRetryTimeoutOutlastsMaxRetries79=== PAUSE TestRetryTimeoutOutlastsMaxRetries80=== RUN TestDoWithRetry_FinalResponseBodyReadable81=== PAUSE TestDoWithRetry_FinalResponseBodyReadable82=== RUN TestShellSplit83=== PAUSE TestShellSplit84=== RUN TestShellSplitErrors85=== PAUSE TestShellSplitErrors86=== RUN TestStreamPushReportsEveryPath87=== PAUSE TestStreamPushReportsEveryPath88=== RUN TestStreamPushBatchesUnderLoad89=== PAUSE TestStreamPushBatchesUnderLoad90=== RUN TestStreamPushIsolatesFailures91=== PAUSE TestStreamPushIsolatesFailures92=== RUN TestStreamPushGivesUpOnDeadServer93=== PAUSE TestStreamPushGivesUpOnDeadServer94=== RUN TestStreamPushRequestLine95=== PAUSE TestStreamPushRequestLine96=== RUN TestStreamPushReportsSignatures97=== PAUSE TestStreamPushReportsSignatures98=== RUN TestStreamPushReportsSkippedPaths99=== PAUSE TestStreamPushReportsSkippedPaths100=== RUN TestClientSignaturesByStorePath101=== PAUSE TestClientSignaturesByStorePath102=== RUN TestStreamPushStopsWhenCanceled103=== PAUSE TestStreamPushStopsWhenCanceled104=== RUN TestStreamPushStopsOnCancel105=== PAUSE TestStreamPushStopsOnCancel106=== RUN TestSetClientTLS107=== PAUSE TestSetClientTLS108=== RUN TestSetClientTLSDoesNotMutateDefaultTransport109=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport110=== RUN TestSetClientTLSErrors111=== PAUSE TestSetClientTLSErrors112=== RUN TestStaticToken113=== PAUSE TestStaticToken114=== RUN TestFileTokenReadsAndCaches115=== PAUSE TestFileTokenReadsAndCaches116=== RUN TestFileTokenMissing117=== PAUSE TestFileTokenMissing118=== RUN TestFileTokenEmpty119=== PAUSE TestFileTokenEmpty120=== RUN TestScriptTokenNoExpiryRerunsEveryCall121=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall122=== RUN TestScriptTokenCachesUntilRefresh123=== PAUSE TestScriptTokenCachesUntilRefresh124=== RUN TestScriptTokenEmptyToken125=== PAUSE TestScriptTokenEmptyToken126=== RUN TestScriptTokenBadJSON127=== PAUSE TestScriptTokenBadJSON128=== RUN TestScriptTokenScriptFails129=== PAUSE TestScriptTokenScriptFails130=== RUN TestScriptTokenEmptyCommand131=== PAUSE TestScriptTokenEmptyCommand132=== RUN TestScriptTokenDoesNotWaitForItsChildren133=== PAUSE TestScriptTokenDoesNotWaitForItsChildren134=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry135=== CONT TestStreamPushReportsSkippedPaths136=== CONT TestScriptTokenNoExpiryRerunsEveryCall137=== CONT TestResolveStorePath138=== CONT TestScriptTokenDoesNotWaitForItsChildren139=== CONT TestClientSignaturesByStorePath140=== CONT TestFileTokenReadsAndCaches141=== CONT TestFileTokenMissing142=== CONT TestStaticToken143=== CONT TestStreamPushBatchesUnderLoad144=== CONT TestScriptTokenEmptyCommand145=== RUN TestStreamPushBatchesUnderLoad/together146=== CONT TestDumpPathSingleFile147=== CONT TestScriptTokenScriptFails148=== CONT TestStreamPushReportsEveryPath149=== CONT TestScriptTokenEmptyToken150=== CONT TestDumpPathWriterError151=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess152=== CONT TestStreamPushStopsOnCancel153=== CONT TestDoWithRetry_BodyReplayedViaGetBody154=== RUN TestStreamPushStopsOnCancel/waiting_for_input155=== CONT TestScriptTokenBadJSON156=== PAUSE TestStreamPushStopsOnCancel/waiting_for_input157=== RUN TestStreamPushStopsOnCancel/partial_batch_waiting_for_a_slot158=== CONT TestSetClientTLSDoesNotMutateDefaultTransport159=== CONT TestStreamPushStopsWhenCanceled160=== CONT TestScriptTokenCachesUntilRefresh161=== CONT TestStreamPushRequestLine162=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer163=== CONT TestParsePathInfoJSON164=== CONT TestCompletePendingClosure_NotFoundWithoutKey165=== CONT TestStreamPushReportsSignatures166=== CONT TestPathInfoHashCompatibility167=== RUN TestScriptTokenDoesNotWaitForItsChildren/cancelled_while_a_child_runs168--- PASS: TestClientSignaturesByStorePath (0.00s)169=== CONT TestDoWithRetry_FinalResponseBodyReadable170=== CONT TestFileTokenEmpty171=== PAUSE TestStreamPushBatchesUnderLoad/together172=== CONT TestSetClientTLS173=== PAUSE TestStreamPushStopsOnCancel/partial_batch_waiting_for_a_slot174=== CONT TestTruncatedNARDumpIsNotCompleted175=== RUN TestParsePathInfoJSON/Nix_format176=== CONT TestPushPathsReportsOnlyUnuploadablePathsOfSkippedClosure177=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)178=== PAUSE TestParsePathInfoJSON/Nix_format179--- PASS: TestStaticToken (0.00s)180--- PASS: TestScriptTokenEmptyCommand (0.00s)181--- PASS: TestStreamPushReportsSkippedPaths (0.00s)182=== RUN TestParsePathInfoJSON/Lix_format183=== RUN TestStreamPushStopsOnCancel/input_closed,_last_batch_waiting_for_a_slot184=== RUN TestStreamPushBatchesUnderLoad/one_at_a_time185=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)186=== PAUSE TestScriptTokenDoesNotWaitForItsChildren/cancelled_while_a_child_runs187--- PASS: TestFileTokenMissing (0.00s)188=== CONT TestStreamPushIsolatesFailures189=== PAUSE TestParsePathInfoJSON/Lix_format190=== PAUSE TestStreamPushStopsOnCancel/input_closed,_last_batch_waiting_for_a_slot191=== PAUSE TestStreamPushBatchesUnderLoad/one_at_a_time192=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon193=== CONT TestGetStorePathHash194=== CONT TestStreamPushGivesUpOnDeadServer195=== CONT TestShellSplit196=== RUN TestStreamPushStopsOnCancel/full_batch_waiting_for_a_slot197=== RUN TestGetStorePathHash/valid_store_path198=== CONT TestDumpPathMatchesNix199=== CONT TestEncodeNixBase32WithRealHash200=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon201=== CONT TestRetryTimeoutOutlastsMaxRetries202--- PASS: TestFileTokenReadsAndCaches (0.00s)203=== RUN TestParsePathInfoJSON/empty_input204=== RUN TestScriptTokenDoesNotWaitForItsChildren/child_left_holding_stdout205=== PAUSE TestStreamPushStopsOnCancel/full_batch_waiting_for_a_slot206=== PAUSE TestGetStorePathHash/valid_store_path207=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI208--- PASS: TestResolveStorePath (0.00s)209=== CONT TestShellSplitErrors210=== RUN TestSetClientTLS/rejects_connection_without_client_cert211=== PAUSE TestParsePathInfoJSON/empty_input212=== RUN TestParsePathInfoJSON/whitespace_only213=== CONT TestUploadMultipart_FailedPartBufferNotReused214=== CONT TestUploadMultipart_ProducerErrorIsNotEOF215=== RUN TestUploadMultipart_ProducerErrorIsNotEOF/short_read_inside_a_part216=== CONT TestFilterOversizedClosures217=== PAUSE TestScriptTokenDoesNotWaitForItsChildren/child_left_holding_stdout218=== CONT TestRateLimiterFeedback219=== CONT TestPathInfoCACompatibility220=== CONT TestParsePathInfoJSONMultiplePaths221=== CONT TestUploadMultipart_PartsInParallel222=== CONT TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent223=== RUN TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/committed_earlier224=== PAUSE TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/committed_earlier225=== RUN TestGetStorePathHash/basename_without_hyphen_should_error226=== CONT TestSupersededNARStillUploadsListing227=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error228=== RUN TestSupersededNARStillUploadsListing/small_NAR229--- PASS: TestStreamPushStopsWhenCanceled (0.00s)230=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI231=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert232=== CONT TestConvertHashToNix32233=== PAUSE TestParsePathInfoJSON/whitespace_only234=== PAUSE TestUploadMultipart_ProducerErrorIsNotEOF/short_read_inside_a_part235=== RUN TestFilterOversizedClosures/no_limit_keeps_everything236=== CONT TestSetClientTLSErrors237=== RUN TestStreamPushStopsOnCancel/request_line_waiting_for_a_slot238=== RUN TestRateLimiterFeedback/429_enables_limiter239=== RUN TestPathInfoCACompatibility/null_ca_field240=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths241=== RUN TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/cleaned_up242=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error243--- PASS: TestScriptTokenScriptFails (0.00s)244=== PAUSE TestSupersededNARStillUploadsListing/small_NAR245=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA246=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512247=== RUN TestConvertHashToNix32/SRI_format_to_Nix32248=== RUN TestParsePathInfoJSON/invalid_JSON249=== RUN TestUploadMultipart_ProducerErrorIsNotEOF/empty_read_on_a_part_boundary250=== RUN TestSetClientTLSErrors/missing_cert_file251=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything252=== PAUSE TestStreamPushStopsOnCancel/request_line_waiting_for_a_slot253=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped254=== PAUSE TestPathInfoCACompatibility/null_ca_field255=== PAUSE TestRateLimiterFeedback/429_enables_limiter256--- PASS: TestStreamPushReportsEveryPath (0.00s)257=== RUN TestRateLimiterFeedback/503_enables_limiter258--- PASS: TestScriptTokenBadJSON (0.00s)259=== PAUSE TestRateLimiterFeedback/503_enables_limiter260=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter261=== PAUSE TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/cleaned_up262=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error263=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths264=== RUN TestSupersededNARStillUploadsListing/dump_cut_short265=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths266=== PAUSE TestSupersededNARStillUploadsListing/dump_cut_short267=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512268=== RUN TestSupersededNARStillUploadsListing/listing_upload_fails269=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun270=== RUN TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_committed_earlier271=== PAUSE TestParsePathInfoJSON/invalid_JSON272=== PAUSE TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_committed_earlier273=== CONT TestPartSizeForNAR274=== RUN TestPartSizeForNAR/zero_stays_at_minimum275=== PAUSE TestUploadMultipart_ProducerErrorIsNotEOF/empty_read_on_a_part_boundary276=== RUN TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_cleaned_up,_first_root_committed_by_another_client277=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32278=== PAUSE TestSetClientTLSErrors/missing_cert_file279=== RUN TestConvertHashToNix32/already_Nix32_format280=== RUN TestStreamPushStopsOnCancel/lines_read_but_not_taken281=== CONT TestCaseHackSuffix282=== RUN TestSetClientTLSErrors/missing_key_file283=== PAUSE TestSetClientTLSErrors/missing_key_file284=== RUN TestSetClientTLSErrors/missing_ca_file285=== PAUSE TestStreamPushStopsOnCancel/lines_read_but_not_taken286=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA287=== RUN TestPathInfoCACompatibility/old_string_format_-_text288--- PASS: TestScriptTokenEmptyToken (0.01s)289=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text290--- PASS: TestFileTokenEmpty (0.00s)291=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error292--- PASS: TestStreamPushReportsSignatures (0.01s)293=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error294=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths295=== PAUSE TestSupersededNARStillUploadsListing/listing_upload_fails296=== PAUSE TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_cleaned_up,_first_root_committed_by_another_client297=== CONT TestRegisterUploadedObjectReusesConnections298=== RUN TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_cleaned_up,_last_root_committed_by_another_client299=== PAUSE TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_cleaned_up,_last_root_committed_by_another_client300=== PAUSE TestConvertHashToNix32/already_Nix32_format301=== RUN TestConvertHashToNix32/invalid_format302=== CONT TestEncodeNixBase32303=== RUN TestEncodeNixBase32/test_string_hash304=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum305=== RUN TestPartSizeForNAR/small_stays_at_minimum306=== PAUSE TestEncodeNixBase32/test_string_hash307=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped308=== PAUSE TestSetClientTLSErrors/missing_ca_file309=== CONT TestDoServerRequestAttachesToken310=== RUN TestSetClientTLS/preserves_debug_logging_transport311=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter312=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive313--- PASS: TestShellSplit (0.00s)314=== CONT TestUploadMultipart_SupersededByPeer315=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica316=== PAUSE TestConvertHashToNix32/invalid_format317=== PAUSE TestPartSizeForNAR/small_stays_at_minimum318=== RUN TestEncodeNixBase32/empty_input319=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum320=== RUN TestFilterOversizedClosures/all_closures_skipped321=== RUN TestSetClientTLSErrors/invalid_ca_file322=== PAUSE TestEncodeNixBase32/empty_input323=== PAUSE TestFilterOversizedClosures/all_closures_skipped324=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter325=== PAUSE TestSetClientTLS/preserves_debug_logging_transport326=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive327=== RUN TestUploadMultipart_SupersededByPeer/exists328=== CONT TestScriptTokenDoesNotWaitForItsChildren/child_left_holding_stdout329=== RUN TestPathInfoCACompatibility/new_structured_format_-_text330--- PASS: TestEncodeNixBase32WithRealHash (0.00s)331=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum332=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts333=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text334=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method335=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method336=== CONT TestStreamPushBatchesUnderLoad/one_at_a_time337--- PASS: TestStreamPushIsolatesFailures (0.00s)338=== CONT TestStreamPushBatchesUnderLoad/together339=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter340=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI341=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)342=== CONT TestParsePathInfoJSON/empty_input343=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512344=== PAUSE TestUploadMultipart_SupersededByPeer/exists345=== CONT TestParsePathInfoJSON/invalid_JSON346=== CONT TestParsePathInfoJSON/Lix_format347=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon348=== CONT TestUploadMultipart_ProducerErrorIsNotEOF/empty_read_on_a_part_boundary349=== CONT TestStreamPushStopsOnCancel/waiting_for_input350=== CONT TestStreamPushStopsOnCancel/full_batch_waiting_for_a_slot351--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.01s)352=== PAUSE TestSetClientTLSErrors/invalid_ca_file353=== CONT TestScriptTokenDoesNotWaitForItsChildren/cancelled_while_a_child_runs354=== CONT TestParsePathInfoJSON/whitespace_only355=== CONT TestParsePathInfoJSON/Nix_format356=== CONT TestUploadMultipart_ProducerErrorIsNotEOF/short_read_inside_a_part357=== RUN TestUploadMultipart_SupersededByPeer/missing358=== CONT TestStreamPushStopsOnCancel/lines_read_but_not_taken359=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts360--- PASS: TestScriptTokenCachesUntilRefresh (0.02s)361=== CONT TestStreamPushStopsOnCancel/request_line_waiting_for_a_slot362=== CONT TestStreamPushStopsOnCancel/input_closed,_last_batch_waiting_for_a_slot363=== CONT TestStreamPushStopsOnCancel/partial_batch_waiting_for_a_slot364=== RUN TestPartSizeForNAR/1_TiB365--- PASS: TestCompletePendingClosure_NotFoundWithoutKey (0.13s)366--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.13s)367=== PAUSE TestUploadMultipart_SupersededByPeer/missing368=== PAUSE TestPartSizeForNAR/1_TiB369--- PASS: TestShellSplitErrors (0.00s)370=== CONT TestGetStorePathHash/valid_store_path371=== RUN TestPartSizeForNAR/5_TiB_S3_max_object372=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object373=== RUN TestPartSizeForNAR/capped_at_5_GiB374--- PASS: TestStreamPushGivesUpOnDeadServer (0.12s)375=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error376=== PAUSE TestPartSizeForNAR/capped_at_5_GiB377--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.13s)378=== CONT TestGetStorePathHash/basename_without_hyphen_should_error379=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error380=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths381=== CONT TestSupersededNARStillUploadsListing/small_NAR382--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.13s)383--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.12s)384=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths385--- PASS: TestDumpPathSingleFile (0.13s)386=== CONT TestSupersededNARStillUploadsListing/listing_upload_fails387--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.00s)388--- PASS: TestDoServerRequestAttachesToken (0.00s)389--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.01s)390--- PASS: TestStreamPushBatchesUnderLoad (0.01s)391 --- PASS: TestStreamPushBatchesUnderLoad/one_at_a_time (0.00s)392 --- PASS: TestStreamPushBatchesUnderLoad/together (0.00s)393--- PASS: TestParsePathInfoJSON (0.13s)394 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)395 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)396 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)397 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)398 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)399--- PASS: TestPathInfoHashCompatibility (0.13s)400 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)401 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)402 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)403 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)404--- PASS: TestParsePathInfoJSONMultiplePaths (0.01s)405 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)406 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)407--- PASS: TestGetStorePathHash (0.13s)408 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)409 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)410 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)411 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)412--- PASS: TestCaseHackSuffix (0.05s)413=== CONT TestSupersededNARStillUploadsListing/dump_cut_short414=== CONT TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_committed_earlier415=== CONT TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_cleaned_up,_first_root_committed_by_another_client416=== CONT TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/committed_earlier417=== CONT TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/cleaned_up418=== CONT TestConvertHashToNix32/already_Nix32_format419=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA420--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.44s)421=== CONT TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_cleaned_up,_last_root_committed_by_another_client422=== CONT TestSetClientTLS/preserves_debug_logging_transport423--- PASS: TestStreamPushStopsOnCancel (0.14s)424 --- PASS: TestStreamPushStopsOnCancel/waiting_for_input (0.30s)425 --- PASS: TestStreamPushStopsOnCancel/input_closed,_last_batch_waiting_for_a_slot (0.30s)426 --- PASS: TestStreamPushStopsOnCancel/full_batch_waiting_for_a_slot (0.30s)427 --- PASS: TestStreamPushStopsOnCancel/lines_read_but_not_taken (0.30s)428 --- PASS: TestStreamPushStopsOnCancel/request_line_waiting_for_a_slot (0.30s)429 --- PASS: TestStreamPushStopsOnCancel/partial_batch_waiting_for_a_slot (0.30s)430=== CONT TestSetClientTLS/rejects_connection_without_client_cert431=== CONT TestEncodeNixBase32/empty_input432=== CONT TestConvertHashToNix32/invalid_format433=== CONT TestConvertHashToNix32/SRI_format_to_Nix32434=== CONT TestFilterOversizedClosures/all_closures_skipped435=== CONT TestFilterOversizedClosures/no_limit_keeps_everything436=== CONT TestPathInfoCACompatibility/old_string_format_-_text437=== CONT TestEncodeNixBase32/test_string_hash438=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method439=== CONT TestPathInfoCACompatibility/new_structured_format_-_text440=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive441=== CONT TestPathInfoCACompatibility/null_ca_field442=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped443--- PASS: TestConvertHashToNix32 (0.01s)444 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)445 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)446 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)447=== CONT TestSetClientTLSErrors/missing_cert_file448=== CONT TestSetClientTLSErrors/missing_ca_file449--- PASS: TestEncodeNixBase32 (0.00s)450 --- PASS: TestEncodeNixBase32/empty_input (0.00s)451 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)452=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter453--- PASS: TestPathInfoCACompatibility (0.01s)454 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)455 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)456 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)457 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)458 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)459--- PASS: TestFilterOversizedClosures (0.01s)460 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)461 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)462 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)463=== CONT TestRateLimiterFeedback/503_enables_limiter464=== CONT TestRateLimiterFeedback/429_enables_limiter465=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter466=== CONT TestSetClientTLSErrors/invalid_ca_file467=== CONT TestSetClientTLSErrors/missing_key_file468=== CONT TestUploadMultipart_SupersededByPeer/exists469=== CONT TestPartSizeForNAR/small_stays_at_minimum470=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum471=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts472=== CONT TestUploadMultipart_SupersededByPeer/missing473--- PASS: TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent (0.01s)474 --- PASS: TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/committed_earlier (0.00s)475 --- PASS: TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/cleaned_up (0.00s)476 --- PASS: TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_committed_earlier (0.00s)477 --- PASS: TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_cleaned_up,_first_root_committed_by_another_client (0.00s)478 --- PASS: TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/push_cleaned_up,_last_root_committed_by_another_client (0.00s)479=== CONT TestPartSizeForNAR/capped_at_5_GiB480=== CONT TestPartSizeForNAR/5_TiB_S3_max_object481=== CONT TestPartSizeForNAR/zero_stays_at_minimum482--- PASS: TestPushPathsReportsOnlyUnuploadablePathsOfSkippedClosure (0.45s)483--- PASS: TestSetClientTLSErrors (0.01s)484 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)485 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)486 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)487 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)488=== CONT TestPartSizeForNAR/1_TiB489--- PASS: TestRateLimiterFeedback (0.02s)490 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)491 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)492 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)493 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)494--- PASS: TestPartSizeForNAR (0.02s)495 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)496 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)497 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)498 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)499 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)500 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)501 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)502--- PASS: TestUploadMultipart_SupersededByPeer (0.01s)503 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)504 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)505--- PASS: TestDumpPathWriterError (0.47s)506--- PASS: TestUploadMultipart_ProducerErrorIsNotEOF (0.01s)507 --- PASS: TestUploadMultipart_ProducerErrorIsNotEOF/empty_read_on_a_part_boundary (0.35s)508 --- PASS: TestUploadMultipart_ProducerErrorIsNotEOF/short_read_inside_a_part (0.35s)509--- PASS: TestSetClientTLS (0.14s)510 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.01s)511 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.01s)512 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.06s)513--- PASS: TestRegisterUploadedObjectReusesConnections (0.41s)514--- PASS: TestStreamPushRequestLine (0.55s)515--- PASS: TestDumpPathMatchesNix (0.60s)516--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)517--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (1.00s)518--- PASS: TestTruncatedNARDumpIsNotCompleted (1.15s)519--- PASS: TestUploadMultipart_FailedPartBufferNotReused (1.18s)520--- PASS: TestUploadMultipart_PartsInParallel (1.19s)521--- PASS: TestSupersededNARStillUploadsListing (0.01s)522 --- PASS: TestSupersededNARStillUploadsListing/listing_upload_fails (0.30s)523 --- PASS: TestSupersededNARStillUploadsListing/small_NAR (0.31s)524 --- PASS: TestSupersededNARStillUploadsListing/dump_cut_short (1.21s)525--- PASS: TestScriptTokenDoesNotWaitForItsChildren (0.13s)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/postgres1073931839/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/postgres1073931839/data -l logfile start556557/build/postgres1073931839:5432 - no response5582026-10-25 19:47:53.855 UTC [175] LOG: starting PostgreSQL 18.6 on x86_64-pc-linux-gnu, compiled by clang version 21.1.8, 64-bit5592026-10-25 19:47:53.856 UTC [175] LOG: listening on Unix socket "/build/postgres1073931839/.s.PGSQL.5432"5602026-10-25 19:47:53.860 UTC [182] LOG: database system was shut down at 2026-10-25 19:47:53 UTC5612026-10-25 19:47:53.863 UTC [175] LOG: database system is ready to accept connections562/build/postgres1073931839:5432 - accepting connections563{"timestamp":"2026-10-25T19:47:54.260152Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"6b94d5ef-5133-437a-bfad-9f7d2b1dc049","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":0,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":502,"threadName":"rustfs-worker","threadId":"ThreadId(133)"}564=== RUN TestService_AuthMiddleware565=== PAUSE TestService_AuthMiddleware566=== RUN TestService_AuthMiddleware_MTLSProxyHeader567=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader568=== RUN TestService_AuthMiddleware_MTLSBoundSubjects569=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects570=== RUN TestService_ReadAuthMiddleware571=== PAUSE TestService_ReadAuthMiddleware572=== RUN TestService_AuthMiddleware_OIDC573=== PAUSE TestService_AuthMiddleware_OIDC574=== RUN TestService_RequireScope_OIDC575=== PAUSE TestService_RequireScope_OIDC576=== RUN TestService_ReadScope_PublicByDefault577=== PAUSE TestService_ReadScope_PublicByDefault578=== RUN TestCacheConfigHandler579=== PAUSE TestCacheConfigHandler580=== RUN TestCacheStatsHandler581=== PAUSE TestCacheStatsHandler582=== RUN TestClientCADerivations583=== PAUSE TestClientCADerivations584=== RUN TestClientErrorHandling585=== PAUSE TestClientErrorHandling586=== RUN TestClientIntegration587=== PAUSE TestClientIntegration588=== RUN TestClientMultipleUploads589=== PAUSE TestClientMultipleUploads590=== RUN TestClientWithDependencies591=== PAUSE TestClientWithDependencies592=== RUN TestClientSharedPathCommittedMidPush593=== PAUSE TestClientSharedPathCommittedMidPush594=== RUN TestPinProtectsFromGC595=== PAUSE TestPinProtectsFromGC596=== RUN TestClientPushesUseOnePush597=== PAUSE TestClientPushesUseOnePush598=== RUN TestClientFallsBackToClosures599=== PAUSE TestClientFallsBackToClosures600=== RUN TestDeleteClosuresRacingPins601=== PAUSE TestDeleteClosuresRacingPins602=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock603=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock604=== RUN TestResolveDBConnectionString605=== PAUSE TestResolveDBConnectionString606=== RUN TestConnectWaitsForAPeerMigration607=== PAUSE TestConnectWaitsForAPeerMigration608=== RUN TestConnectSerialisesConcurrentMigrations609=== PAUSE TestConnectSerialisesConcurrentMigrations610=== RUN TestLeadElectsOneAndHandsOver611=== PAUSE TestLeadElectsOneAndHandsOver612=== RUN TestLeadIncumbentWinsAfterRestart6132026/10/25 19:47:54 INFO lead: acquired remote=192.0.2.1:12346142026/10/25 19:47:55 INFO lead: released remote=192.0.2.1:12346152026/10/25 19:47:55 INFO lead: acquired remote=192.0.2.1:12346162026/10/25 19:47:56 INFO lead: released remote=192.0.2.1:1234617--- PASS: TestLeadIncumbentWinsAfterRestart (1.89s)618=== RUN TestLeadIncumbentAnnouncesAtOnce619=== PAUSE TestLeadIncumbentAnnouncesAtOnce620=== RUN TestLeadEndsOnShutdown621=== PAUSE TestLeadEndsOnShutdown622=== RUN TestLeadEndsWhenItsConnectionHangs6232026/10/25 19:47:56 INFO lead: acquired remote=192.0.2.1:12346242026-10-25 19:47:57.787 UTC [371] FATAL: terminating connection due to administrator command6252026/10/25 19:47:57 INFO lead: acquired remote=192.0.2.1:12346262026/10/25 19:47:58 WARN lead: lock connection lost error="timeout: context deadline exceeded"6272026/10/25 19:47:58 INFO lead: released remote=192.0.2.1:12346282026/10/25 19:47:59 INFO lead: released remote=192.0.2.1:1234629--- PASS: TestLeadEndsWhenItsConnectionHangs (3.14s)630=== RUN TestGCAdvisoryLockBlocksConcurrentRun631=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun632=== RUN TestGCBugBareHashReferences633=== PAUSE TestGCBugBareHashReferences634=== RUN TestGCMetrics635=== PAUSE TestGCMetrics636=== RUN TestPushDedupSurvivesConcurrentGC637=== PAUSE TestPushDedupSurvivesConcurrentGC638=== RUN TestDeduplicatedObjectsRecordedAsPending639=== PAUSE TestDeduplicatedObjectsRecordedAsPending640=== RUN TestGCSweepSkipsPendingObjects641=== PAUSE TestGCSweepSkipsPendingObjects642=== RUN TestTombstonedObjectOfferedWithoutWaiting643=== PAUSE TestTombstonedObjectOfferedWithoutWaiting644=== RUN TestGCSweepDeliversEachKeyOnce645=== PAUSE TestGCSweepDeliversEachKeyOnce646=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection647=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection648=== RUN TestForceGCDuringPushOffersSweptObject649=== PAUSE TestForceGCDuringPushOffersSweptObject650=== RUN TestFailedS3DeleteKeepsTombstone651=== PAUSE TestFailedS3DeleteKeepsTombstone652=== RUN TestSweepSkipsRowsLockedByPush653=== PAUSE TestSweepSkipsRowsLockedByPush654=== RUN TestRegisterCompletedObjectNeedsPendingRow655=== PAUSE TestRegisterCompletedObjectNeedsPendingRow656=== RUN TestGetExistingObjectsLocksRows657=== PAUSE TestGetExistingObjectsLocksRows658=== RUN TestSweepRechecksPendingAfterLocking659=== PAUSE TestSweepRechecksPendingAfterLocking660=== RUN TestPushWaitsForSweepHoldingRow661=== PAUSE TestPushWaitsForSweepHoldingRow662=== RUN TestCommitRacingPendingCleanupKeepsObjects663=== PAUSE TestCommitRacingPendingCleanupKeepsObjects664=== RUN TestGCEndsOnShutdown665=== PAUSE TestGCEndsOnShutdown666=== RUN TestGCTaskStore_StartNew667=== PAUSE TestGCTaskStore_StartNew668=== RUN TestGCTaskStore_DeduplicateSameParams669=== PAUSE TestGCTaskStore_DeduplicateSameParams670=== RUN TestGCTaskStore_ConflictDifferentParams671=== PAUSE TestGCTaskStore_ConflictDifferentParams672=== RUN TestGCTaskStore_GetEmpty673=== PAUSE TestGCTaskStore_GetEmpty674=== RUN TestGCTaskStore_GetReturnsLatest675=== PAUSE TestGCTaskStore_GetReturnsLatest676=== RUN TestGCTaskStore_CompletedAllowsNewTask677=== PAUSE TestGCTaskStore_CompletedAllowsNewTask678=== RUN TestGCTaskStore_PhaseUpdates679=== PAUSE TestGCTaskStore_PhaseUpdates680=== RUN TestGCTaskStore_Fail681=== PAUSE TestGCTaskStore_Fail682=== RUN TestGracefulShutdownDrainsInflight683=== PAUSE TestGracefulShutdownDrainsInflight684=== RUN TestService_healthCheckHandler685=== PAUSE TestService_healthCheckHandler686=== RUN TestService_readinessHandler687=== PAUSE TestService_readinessHandler688=== RUN TestGenerateLandingPage689=== PAUSE TestGenerateLandingPage690=== RUN TestChildrenInheritRaisedFileLimit691=== PAUSE TestChildrenInheritRaisedFileLimit692=== RUN TestCacheConfigHandlerMaxNarSize693=== PAUSE TestCacheConfigHandlerMaxNarSize694=== RUN TestCreatePendingClosureRejectsOversizedNAR695=== PAUSE TestCreatePendingClosureRejectsOversizedNAR696=== RUN TestNARDeduplicationMetadataUploadBug697=== PAUSE TestNARDeduplicationMetadataUploadBug698=== RUN TestMetricsInventory699=== PAUSE TestMetricsInventory700=== RUN TestMetricsCommit701=== PAUSE TestMetricsCommit702=== RUN TestService_NativeMTLS703=== PAUSE TestService_NativeMTLS704=== RUN TestServerTLSConfig705=== PAUSE TestServerTLSConfig706=== RUN TestMultipartCleanup707=== PAUSE TestMultipartCleanup708=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded709=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded710=== RUN TestPendingCleanupUsesOneCutoff711=== PAUSE TestPendingCleanupUsesOneCutoff712=== RUN TestPendingClosureFailureTracksEveryUpload713=== PAUSE TestPendingClosureFailureTracksEveryUpload714=== RUN TestPendingClosureFailureAbortsItsUploads715=== PAUSE TestPendingClosureFailureAbortsItsUploads716=== RUN TestObjectStatsTrigger717=== PAUSE TestObjectStatsTrigger718=== RUN TestObjectStatsUpdatedOncePerCommit719=== PAUSE TestObjectStatsUpdatedOncePerCommit720=== RUN TestReconnectLeavesObjectsUnlocked721=== PAUSE TestReconnectLeavesObjectsUnlocked722=== RUN TestOrphanedObjectsGC723=== PAUSE TestOrphanedObjectsGC724=== RUN TestOrphanedObjectsGCStressTest725=== PAUSE TestOrphanedObjectsGCStressTest726=== RUN TestCreatePin_ReservedPins727=== PAUSE TestCreatePin_ReservedPins728=== RUN TestConcurrentPinUpdatesAgree729=== PAUSE TestConcurrentPinUpdatesAgree730=== RUN TestCreatePinRejectsBadInput731=== PAUSE TestCreatePinRejectsBadInput732=== RUN TestDeletePinKeepsRowWhenS3Fails733=== PAUSE TestDeletePinKeepsRowWhenS3Fails734=== RUN TestPresentReportsOnlyClosureRoots735=== PAUSE TestPresentReportsOnlyClosureRoots736=== RUN TestPresentRefreshesOnlyStaleClosures737=== PAUSE TestPresentRefreshesOnlyStaleClosures738=== RUN TestPresentNotReportedWhileGCDeletesClosure739=== PAUSE TestPresentNotReportedWhileGCDeletesClosure740=== RUN TestParseSingleRange741=== PAUSE TestParseSingleRange742=== RUN TestProxyHeadersOnlyTrustedOnSocket7432026/10/25 19:47:59 INFO Starting HTTP server address=127.0.0.1:411957442026/10/25 19:47:59 INFO Starting HTTP server address=proxy.sock7452026/10/25 19:47:59 WARN mTLS auth: subject not in bound subjects subject="CN=someone"7462026/10/25 19:47:59 INFO Shutdown signal received, draining in-flight requests timeout=10s747--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.12s)748=== RUN TestIsValidCachePath749=== PAUSE TestIsValidCachePath750=== RUN TestReadProxyNarinfo751=== PAUSE TestReadProxyNarinfo752=== RUN TestReadProxyNarinfoAlreadyDecompressed753=== PAUSE TestReadProxyNarinfoAlreadyDecompressed754=== RUN TestReadProxyContentNegotiation755=== PAUSE TestReadProxyContentNegotiation756=== RUN TestReadProxyNarStreaming757=== PAUSE TestReadProxyNarStreaming758=== RUN TestReadProxy404759=== PAUSE TestReadProxy404760=== RUN TestReadProxyInvalidPath761=== PAUSE TestReadProxyInvalidPath762=== RUN TestReadProxyHead763=== PAUSE TestReadProxyHead764=== RUN TestReadProxyOutlastsServerWriteTimeout765=== PAUSE TestReadProxyOutlastsServerWriteTimeout766=== RUN TestReadProxyConditionalGet767=== PAUSE TestReadProxyConditionalGet768=== RUN TestReadProxyRootRedirectsToIndexHTML769=== PAUSE TestReadProxyRootRedirectsToIndexHTML770=== RUN TestReadProxyDisabled771=== PAUSE TestReadProxyDisabled772=== RUN TestReadRedirectNar773=== PAUSE TestReadRedirectNar774=== RUN TestReadRedirectKeepsNarinfoProxied775=== PAUSE TestReadRedirectKeepsNarinfoProxied776=== RUN TestReadProxyRangeRequest777=== PAUSE TestReadProxyRangeRequest778=== RUN TestReadRedirectUsesPublicS3URL779=== PAUSE TestReadRedirectUsesPublicS3URL780=== RUN TestPush_OverlappingRootsStoreOneRowPerKey781=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey782=== RUN TestPush_CompleteCommitsEveryRoot783=== PAUSE TestPush_CompleteCommitsEveryRoot784=== RUN TestPush_RepeatedRootCommitsOnce785=== PAUSE TestPush_RepeatedRootCommitsOnce786=== RUN TestPush_CompleteWaitsForCleanupOfThePush787=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush788=== RUN TestPush_RootsAreLockedInByteOrder789=== PAUSE TestPush_RootsAreLockedInByteOrder790=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit791=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit792=== RUN TestPush_RejectsBadRequests793=== PAUSE TestPush_RejectsBadRequests794=== RUN TestPush_SignsNarinfosOfItsPendingObjects795=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects796=== RUN TestRedundantMultipartUpload797=== PAUSE TestRedundantMultipartUpload798=== RUN TestCompleteMultipartUpload_ErrorButObjectExists799=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists800=== RUN TestCompletedNarNotReofferedAcrossClosures801=== PAUSE TestCompletedNarNotReofferedAcrossClosures802=== RUN TestPresignedUploadRegisteredBeforeCommit803=== PAUSE TestPresignedUploadRegisteredBeforeCommit804=== RUN TestService_Rustfstest805=== PAUSE TestService_Rustfstest806=== RUN TestParseSize807=== PAUSE TestParseSize808=== RUN TestSkippedUploadsHandler809=== PAUSE TestSkippedUploadsHandler810=== RUN TestSystemdListenerNotActivated811--- PASS: TestSystemdListenerNotActivated (0.00s)812=== RUN TestWatchdogBeatsWhenHealthy813--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)814=== RUN TestWatchdogSkipsWhenUnhealthy8152026/10/25 19:47:59 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"8162026/10/25 19:47:59 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"8172026/10/25 19:47:59 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"8182026/10/25 19:47:59 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"8192026/10/25 19:47:59 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"8202026/10/25 19:47:59 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"8212026/10/25 19:47:59 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"8222026/10/25 19:47:59 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"8232026/10/25 19:47:59 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"8242026/10/25 19:47:59 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"825--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)826=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle827=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle828=== RUN TestProxyWriteTimeout829=== PAUSE TestProxyWriteTimeout830=== RUN TestPendingClosureWriteTimeout831=== PAUSE TestPendingClosureWriteTimeout832=== RUN TestIsValidUploadKey833=== PAUSE TestIsValidUploadKey834=== RUN TestUploadHandlersRejectInvalidKeys835=== PAUSE TestUploadHandlersRejectInvalidKeys836=== RUN TestUploadHandlersRejectOversizedBody837=== PAUSE TestUploadHandlersRejectOversizedBody838=== RUN TestService_cleanupPendingClosuresHandler839=== PAUSE TestService_cleanupPendingClosuresHandler840=== RUN TestService_createPendingClosureHandler841=== PAUSE TestService_createPendingClosureHandler842=== RUN TestService_verifyS3Integrity843=== PAUSE TestService_verifyS3Integrity844=== RUN TestCompleteMultipartUnregistered845=== PAUSE TestCompleteMultipartUnregistered846=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT847=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT848=== CONT TestProxyWriteTimeout849=== CONT TestGCTaskStore_GetReturnsLatest850=== CONT TestPush_CompleteCommitsEveryRoot851=== CONT TestService_Rustfstest852=== CONT TestGCBugBareHashReferences853=== CONT TestPresignedUploadRegisteredBeforeCommit854=== CONT TestService_healthCheckHandler855=== CONT TestGenerateLandingPage856=== CONT TestGCTaskStore_PhaseUpdates857=== CONT TestGCTaskStore_CompletedAllowsNewTask858=== CONT TestService_readinessHandler859=== CONT TestReadRedirectUsesPublicS3URL860=== CONT TestCompletedNarNotReofferedAcrossClosures861=== CONT TestCompleteMultipartUpload_ErrorButObjectExists862=== CONT TestPush_SignsNarinfosOfItsPendingObjects863=== CONT TestRedundantMultipartUpload864=== CONT TestPush_RejectsBadRequests865=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit866=== CONT TestPush_RepeatedRootCommitsOnce867=== CONT TestPush_CompleteWaitsForCleanupOfThePush868=== CONT TestPush_OverlappingRootsStoreOneRowPerKey869=== CONT TestGCTaskStore_GetEmpty870=== CONT TestGCTaskStore_Fail871=== CONT TestGCTaskStore_ConflictDifferentParams872=== RUN TestProxyWriteTimeout/narinfo873=== CONT TestService_AuthMiddleware_MTLSProxyHeader874--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)875=== CONT TestGCTaskStore_StartNew876=== CONT TestCompleteMultipartUnregistered877=== CONT TestService_cleanupPendingClosuresHandler878=== CONT TestPendingClosureWriteTimeout879=== RUN TestPendingClosureWriteTimeout/empty880=== CONT TestUploadHandlersRejectOversizedBody881=== CONT TestReadRedirectKeepsNarinfoProxied882=== PAUSE TestProxyWriteTimeout/narinfo883--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)884=== PAUSE TestPendingClosureWriteTimeout/empty885=== RUN TestProxyWriteTimeout/1_GiB_nar886--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)887--- PASS: TestGCTaskStore_GetEmpty (0.00s)888=== RUN TestPendingClosureWriteTimeout/400_objects889=== PAUSE TestProxyWriteTimeout/1_GiB_nar890=== PAUSE TestPendingClosureWriteTimeout/400_objects891--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)892=== RUN TestProxyWriteTimeout/10_GiB_nar893=== PAUSE TestProxyWriteTimeout/10_GiB_nar894=== RUN TestPendingClosureWriteTimeout/670k_objects895--- PASS: TestGCTaskStore_Fail (0.00s)896=== RUN TestProxyWriteTimeout/unknown_size897--- PASS: TestGCTaskStore_StartNew (0.00s)898=== PAUSE TestPendingClosureWriteTimeout/670k_objects899=== PAUSE TestProxyWriteTimeout/unknown_size900=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline901=== CONT TestReadRedirectNar902=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline903=== CONT TestUploadHandlersRejectInvalidKeys904=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info905=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info906=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal907=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal908=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key909=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key910=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key911=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key912=== CONT TestSkippedUploadsHandler913--- PASS: TestGenerateLandingPage (0.01s)914=== CONT TestCreatePin_ReservedPins9152026/10/25 19:47:59 INFO Client skipped oversized paths paths=3 nar_bytes=50000000009162026/10/25 19:47:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:38459/oidc917--- PASS: TestSkippedUploadsHandler (0.04s)918=== CONT TestReadProxyInvalidPath9192026/10/25 19:48:00 INFO Received uploads request method=POST path=/api/pending_closures9202026/10/25 19:48:00 WARN readiness check failed error="closed pool"9212026/10/25 19:48:00 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst9222026/10/25 19:48:00 INFO Received uploads request method=POST path=/api/pending_closures923--- PASS: TestService_readinessHandler (0.36s)924=== CONT TestCreatePinRejectsBadInput925=== CONT TestLeadElectsOneAndHandsOver926--- PASS: TestPresignedUploadRegisteredBeforeCommit (0.38s)927=== CONT TestConnectSerialisesConcurrentMigrations928--- PASS: TestService_Rustfstest (0.39s)9292026/10/25 19:48:00 INFO Received uploads request method=POST path=/api/pending_closures9302026/10/25 19:48:00 INFO Received push request method=POST path=/api/pushes9312026/10/25 19:48:00 INFO Received push request method=POST path=/api/pushes9322026/10/25 19:48:00 INFO Received push request method=POST path=/api/pushes933=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts934=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts935=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure936=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure937=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart938=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart939=== CONT TestOrphanedObjectsGC9402026-10-25 19:48:00.241 UTC [485] ERROR: duplicate key value violates unique constraint "pg_type_typname_nsp_index"9412026-10-25 19:48:00.241 UTC [485] DETAIL: Key (typname, typnamespace)=(goose_db_version, 2200) already exists.9422026-10-25 19:48:00.241 UTC [485] STATEMENT: CREATE TABLE goose_db_version (943 id integer PRIMARY KEY GENERATED BY DEFAULT AS IDENTITY,944 version_id bigint NOT NULL,945 is_applied boolean NOT NULL,946 tstamp timestamp NOT NULL DEFAULT now()947 )948--- PASS: TestService_healthCheckHandler (0.50s)949=== CONT TestConnectWaitsForAPeerMigration9502026/10/25 19:48:00 INFO Received uploads request method=POST path=/api/pending_closures9512026/10/25 19:48:00 INFO Received uploads request method=POST path=/api/pending_closures9522026/10/25 19:48:00 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9532026/10/25 19:48:00 INFO Received uploads request method=POST path=/api/pending_closures954=== RUN TestPush_RejectsBadRequests/root_not_in_objects955=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects956=== RUN TestPush_RejectsBadRequests/no_roots957=== PAUSE TestPush_RejectsBadRequests/no_roots958=== RUN TestPush_RejectsBadRequests/no_objects959=== PAUSE TestPush_RejectsBadRequests/no_objects960=== RUN TestPush_RejectsBadRequests/bad_root961=== PAUSE TestPush_RejectsBadRequests/bad_root962=== CONT TestLeadIncumbentAnnouncesAtOnce9632026/10/25 19:48:00 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ZTdjMDA0N2MtM2VjOC00MWU2LTg5NGYtNDMzYWYyOTIwZDA1LmE2OTU0OTY2LThmNDQtNDVmOS04NjI2LTRlMTdlYTZkY2M4NngxNzkyOTU3NjgwMjczMDQxNzgw9642026/10/25 19:48:00 INFO Received push request method=POST path=/api/pushes9652026/10/25 19:48:00 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9662026/10/25 19:48:00 INFO Signed narinfos id=1 count=19672026/10/25 19:48:00 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9682026/10/25 19:48:00 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9692026/10/25 19:48:00 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"9702026/10/25 19:48:00 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9712026/10/25 19:48:00 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"9722026/10/25 19:48:00 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9732026/10/25 19:48:00 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=19742026/10/25 19:48:00 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9752026/10/25 19:48:00 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo976--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.66s)977=== CONT TestClientIntegration9782026/10/25 19:48:00 INFO Received push request method=POST path=/api/pushes9792026/10/25 19:48:00 WARN Failed to abort multipart upload key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ZTdjMDA0N2MtM2VjOC00MWU2LTg5NGYtNDMzYWYyOTIwZDA1LmE2OTU0OTY2LThmNDQtNDVmOS04NjI2LTRlMTdlYTZkY2M4NngxNzkyOTU3NjgwMjczMDQxNzgw error="Delete \"http://localhost:42519/bucket13/nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst?uploadId=ZTdjMDA0N2MtM2VjOC00MWU2LTg5NGYtNDMzYWYyOTIwZDA1LmE2OTU0OTY2LThmNDQtNDVmOS04NjI2LTRlMTdlYTZkY2M4NngxNzkyOTU3NjgwMjczMDQxNzgw\": injected: abort refused"980--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (0.67s)981=== CONT TestParseSingleRange982=== RUN TestParseSingleRange/none983=== PAUSE TestParseSingleRange/none984=== RUN TestParseSingleRange/unknown_unit985=== PAUSE TestParseSingleRange/unknown_unit986=== RUN TestParseSingleRange/multi-range_ignored987=== PAUSE TestParseSingleRange/multi-range_ignored988=== RUN TestParseSingleRange/malformed_no_dash989=== PAUSE TestParseSingleRange/malformed_no_dash990=== RUN TestParseSingleRange/malformed_both_empty991=== PAUSE TestParseSingleRange/malformed_both_empty992=== RUN TestParseSingleRange/malformed_end_before_start993=== PAUSE TestParseSingleRange/malformed_end_before_start994=== RUN TestParseSingleRange/closed995=== PAUSE TestParseSingleRange/closed9962026/10/25 19:48:00 INFO Received complete multipart upload request method=POST path=/api/multipart/complete997=== RUN TestParseSingleRange/open-ended998=== PAUSE TestParseSingleRange/open-ended999=== RUN TestParseSingleRange/end_clamped_to_size1000=== PAUSE TestParseSingleRange/end_clamped_to_size1001=== RUN TestParseSingleRange/suffix1002=== PAUSE TestParseSingleRange/suffix1003=== RUN TestParseSingleRange/suffix_exceeds_size1004=== PAUSE TestParseSingleRange/suffix_exceeds_size1005=== RUN TestParseSingleRange/single_byte1006=== PAUSE TestParseSingleRange/single_byte1007=== RUN TestParseSingleRange/start_past_EOF1008=== PAUSE TestParseSingleRange/start_past_EOF1009=== RUN TestParseSingleRange/start_far_past_EOF1010=== PAUSE TestParseSingleRange/start_far_past_EOF1011=== CONT TestServerTLSConfig1012=== RUN TestServerTLSConfig/no_client_CA1013=== PAUSE TestServerTLSConfig/no_client_CA1014=== RUN TestServerTLSConfig/missing_CA_file1015=== PAUSE TestServerTLSConfig/missing_CA_file1016=== RUN TestServerTLSConfig/not_a_PEM_file1017=== PAUSE TestServerTLSConfig/not_a_PEM_file1018=== CONT TestService_NativeMTLS10192026/10/25 19:48:00 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ZTdjMDA0N2MtM2VjOC00MWU2LTg5NGYtNDMzYWYyOTIwZDA1LmE2OTU0OTY2LThmNDQtNDVmOS04NjI2LTRlMTdlYTZkY2M4NngxNzkyOTU3NjgwMjczMDQxNzgw1020--- PASS: TestGCBugBareHashReferences (0.68s)1021=== CONT TestForceGCDuringPushOffersSweptObject1022=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows1023=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows1024=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check1025=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check1026=== CONT TestCacheConfigHandlerMaxNarSize1027--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1028=== CONT TestGCTaskStore_DeduplicateSameParams1029=== CONT TestConcurrentPinUpdatesAgree1030--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)10312026/10/25 19:48:00 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ZTdjMDA0N2MtM2VjOC00MWU2LTg5NGYtNDMzYWYyOTIwZDA1LmE2OTU0OTY2LThmNDQtNDVmOS04NjI2LTRlMTdlYTZkY2M4NngxNzkyOTU3NjgwMjczMDQxNzgw parts=11032--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (0.71s)1033=== CONT TestPush_RootsAreLockedInByteOrder1034--- PASS: TestReadProxyInvalidPath (0.66s)1035=== CONT TestService_verifyS3Integrity1036--- PASS: TestReadRedirectUsesPublicS3URL (0.71s)1037=== CONT TestOrphanedObjectsGCStressTest1038--- PASS: TestReadRedirectKeepsNarinfoProxied (0.73s)1039=== CONT TestCommitRacingPendingCleanupKeepsObjects10402026/10/25 19:48:00 INFO Received cleanup request method=DELETE path=/api/pending_closures1041=== CONT TestGCEndsOnShutdown1042--- PASS: TestReadRedirectNar (0.74s)1043=== RUN TestGCEndsOnShutdown/before_the_run1044=== PAUSE TestGCEndsOnShutdown/before_the_run1045=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1046=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1047=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark10482026/10/25 19:48:00 INFO Aborted multipart uploads count=0 kept=01049=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1050=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle10512026/10/25 19:48:00 INFO Received uploads request method=POST path=/api/pending_closures10522026/10/25 19:48:00 INFO Received cleanup request method=DELETE path=/api/pending_closures10532026/10/25 19:48:00 INFO Aborted multipart uploads count=1 kept=010542026/10/25 19:48:00 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10552026-10-25 19:48:00.532 UTC [467] ERROR: Closure does not exist: id=110562026-10-25 19:48:00.532 UTC [467] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE10572026-10-25 19:48:00.532 UTC [467] STATEMENT: -- name: CommitPendingClosure :one1058 SELECT commit_pending_closure($1::bigint)::bigint1059 10602026/10/25 19:48:00 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux10612026/10/25 19:48:00 WARN Refused reserved pin name=worker-x86_64-linux10622026/10/25 19:48:00 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux10632026/10/25 19:48:00 INFO Received create pin request method=POST path=/api/pins/my-app10642026/10/25 19:48:00 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux10652026/10/25 19:48:00 INFO Received push request method=POST path=/api/pushes1066--- PASS: TestService_cleanupPendingClosuresHandler (0.79s)1067=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT1068=== CONT TestService_createPendingClosureHandler1069--- PASS: TestCreatePin_ReservedPins (0.78s)10702026/10/25 19:48:00 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10712026/10/25 19:48:00 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst10722026/10/25 19:48:00 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1073--- PASS: TestCompleteMultipartUnregistered (0.84s)1074=== CONT TestIsValidUploadKey1075=== RUN TestIsValidUploadKey/narinfo1076=== PAUSE TestIsValidUploadKey/narinfo1077=== RUN TestIsValidUploadKey/nar_zst1078=== PAUSE TestIsValidUploadKey/nar_zst1079=== RUN TestIsValidUploadKey/nar_xz1080=== PAUSE TestIsValidUploadKey/nar_xz1081=== RUN TestIsValidUploadKey/nar_plain1082=== PAUSE TestIsValidUploadKey/nar_plain1083=== RUN TestIsValidUploadKey/listing1084=== PAUSE TestIsValidUploadKey/listing1085=== RUN TestIsValidUploadKey/build_log1086=== PAUSE TestIsValidUploadKey/build_log1087=== RUN TestIsValidUploadKey/build_log_home-manager_file1088=== PAUSE TestIsValidUploadKey/build_log_home-manager_file1089=== RUN TestIsValidUploadKey/build_log_plus_in_name1090=== PAUSE TestIsValidUploadKey/build_log_plus_in_name1091=== RUN TestIsValidUploadKey/build_log_question_mark1092=== PAUSE TestIsValidUploadKey/build_log_question_mark1093=== RUN TestIsValidUploadKey/build_log_equals1094=== PAUSE TestIsValidUploadKey/build_log_equals1095=== RUN TestIsValidUploadKey/realisation1096=== PAUSE TestIsValidUploadKey/realisation1097=== RUN TestIsValidUploadKey/realisation_plus_in_output1098=== PAUSE TestIsValidUploadKey/realisation_plus_in_output1099=== RUN TestIsValidUploadKey/nix-cache-info1100=== PAUSE TestIsValidUploadKey/nix-cache-info1101=== RUN TestIsValidUploadKey/index.html1102=== PAUSE TestIsValidUploadKey/index.html1103=== RUN TestIsValidUploadKey/narinfo_key,_nar_type1104=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type1105=== RUN TestIsValidUploadKey/nar_key,_narinfo_type1106=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type1107=== RUN TestIsValidUploadKey/listing_key,_narinfo_type1108=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type1109=== RUN TestIsValidUploadKey/traversal1110=== PAUSE TestIsValidUploadKey/traversal1111=== RUN TestIsValidUploadKey/traversal_nar1112=== PAUSE TestIsValidUploadKey/traversal_nar1113=== RUN TestIsValidUploadKey/absolute1114=== PAUSE TestIsValidUploadKey/absolute1115=== RUN TestIsValidUploadKey/empty_key1116=== PAUSE TestIsValidUploadKey/empty_key1117=== RUN TestIsValidUploadKey/unknown_type1118=== PAUSE TestIsValidUploadKey/unknown_type1119=== CONT TestPushWaitsForSweepHoldingRow1120--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (0.85s)1121=== CONT TestSweepRechecksPendingAfterLocking11222026/10/25 19:48:00 INFO Completed multipart upload object_key=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa00000000000000000000.nar.zst upload_id=ZTdjMDA0N2MtM2VjOC00MWU2LTg5NGYtNDMzYWYyOTIwZDA1LjA4MmRlYzlkLWFjMTMtNDhlZS1hYTcxLTg0NTdhYjdjYzhhNHgxNzkyOTU3NjgwMTczNzM1MTY5 parts=1011232026/10/25 19:48:00 INFO lead: acquired remote=192.0.2.1:123411242026/10/25 19:48:00 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11252026/10/25 19:48:00 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11262026/10/25 19:48:00 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11272026/10/25 19:48:00 INFO Completed multipart upload object_key=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa00000000000000000000.nar.zst upload_id=ZTdjMDA0N2MtM2VjOC00MWU2LTg5NGYtNDMzYWYyOTIwZDA1LmNjMzk4MjJhLWRhZmItNGFkOC05ZDMxLWFiMDc5MmNhZDE4MXgxNzkyOTU3NjgwMjEwMjEwMTQ1 parts=1011282026/10/25 19:48:00 INFO Received create pin request method=POST path=/api/pins/deploy11292026/10/25 19:48:00 INFO Received create pin request method=POST path=/api/pins/deploy11302026/10/25 19:48:00 INFO Received create pin request method=POST path=/api/pins/deploy11312026/10/25 19:48:00 INFO Received create pin request method=POST path=/api/pins/deploy11322026/10/25 19:48:00 INFO Received create pin request method=POST path=/api/pins/deploy11332026/10/25 19:48:00 INFO Received create pin request method=POST path=/api/pins/deploy11342026/10/25 19:48:00 INFO Received create pin request method=POST path=/api/pins/deploy11352026/10/25 19:48:00 INFO Received create pin request method=POST path=/api/pins/deploy11362026/10/25 19:48:00 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=ZTdjMDA0N2MtM2VjOC00MWU2LTg5NGYtNDMzYWYyOTIwZDA1LjI3ZmFiYTE5LTk0YmYtNDJlZS1iMzA0LWQ0ZDM4ZDA3NTBlNHgxNzkyOTU3NjgwMTU0NDEzMDQ3 parts=1211372026/10/25 19:48:00 INFO Completed multipart upload object_key=nar/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb00000000000000000000.nar.zst upload_id=ZTdjMDA0N2MtM2VjOC00MWU2LTg5NGYtNDMzYWYyOTIwZDA1LmJkMmQ4ZmEyLTYyZjgtNGQ3ZS04NjRjLTVmZTA1NDEwMDM3ZngxNzkyOTU3NjgwMjQxNjYzNjMy parts=1011382026/10/25 19:48:00 INFO Received uploads request method=POST path=/api/pending_closures11392026/10/25 19:48:00 INFO Received create pin request method=POST path=/api/pins/deploy1140=== CONT TestGetExistingObjectsLocksRows1141--- PASS: TestCompletedNarNotReofferedAcrossClosures (1.00s)11422026/10/25 19:48:00 INFO lead: acquired remote=192.0.2.1:123411432026/10/25 19:48:00 INFO lead: released remote=192.0.2.1:12341144--- PASS: TestLeadIncumbentAnnouncesAtOnce (0.48s)1145=== CONT TestReadProxyDisabled11462026/10/25 19:48:00 INFO Received create pin request method=POST path=/api/pins/app11472026/10/25 19:48:00 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11482026/10/25 19:48:00 WARN mTLS auth: subject not in bound subjects subject="CN=reader"11492026/10/25 19:48:00 INFO Received create pin request method=POST path=/api/pins/app1150=== NAME TestClientIntegration11512026/10/25 19:48:00 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1152 client_integration_test.go:331: Created store path: /build/TestClientIntegration1657185973/002/store/pmxd3mvmn7j4y5p50r1iy4kii1jlw93q-test-file.txt11532026/10/25 19:48:00 INFO Received push request method=POST path=/api/pushes11542026/10/25 19:48:00 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=ZTdjMDA0N2MtM2VjOC00MWU2LTg5NGYtNDMzYWYyOTIwZDA1LjA5MDdkZmI4LTQ2NTAtNGJjMS04OWQzLWQ0NTVjNDI4YWE0YXgxNzkyOTU3NjgwMzE0MTA1MTgz parts=121155--- PASS: TestService_NativeMTLS (0.44s)1156=== CONT TestReadProxyRootRedirectsToIndexHTML11572026/10/25 19:48:00 INFO Received uploads request method=POST path=/api/pending_closures11582026/10/25 19:48:00 INFO Received uploads request method=POST path=/api/pending_closures11592026/10/25 19:48:00 INFO Received uploads request method=POST path=/api/pending_closures11602026/10/25 19:48:00 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11612026/10/25 19:48:00 INFO Completed multipart upload object_key=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa00000000000000000000.nar.zst upload_id=ZTdjMDA0N2MtM2VjOC00MWU2LTg5NGYtNDMzYWYyOTIwZDA1LjM3MzI3MmI2LTMzMzEtNGNkMy04OGEwLTkxMTMxY2IzODRjMXgxNzkyOTU3NjgwNDM3NTk1NDY0 parts=1011622026/10/25 19:48:00 INFO Received push request method=POST path=/api/pushes11632026/10/25 19:48:00 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)11642026/10/25 19:48:00 INFO Uploading pmxd3mvmn7j4y5p50r1iy4kii1jlw93q-test-file.txt (152B)11652026/10/25 19:48:00 INFO Received uploads request method=POST path=/api/pending_closures11662026/10/25 19:48:00 INFO Received uploads request method=POST path=/api/pending_closures11672026/10/25 19:48:00 INFO Received uploads request method=POST path=/api/pending_closures11682026/10/25 19:48:00 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"11692026/10/25 19:48:00 INFO Aborted multipart uploads count=0 kept=011702026/10/25 19:48:00 INFO Received uploads request method=POST path=/api/pending_closures11712026/10/25 19:48:00 WARN Force mode enabled - objects will be deleted immediately without grace period11722026/10/25 19:48:00 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=011732026/10/25 19:48:00 WARN Failed to register uploaded object key=pmxd3mvmn7j4y5p50r1iy4kii1jlw93q.ls error="server returned 404: 404 page not found\n"11742026/10/25 19:48:00 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11752026/10/25 19:48:00 INFO Vacuumed table table=pending_closures11762026/10/25 19:48:00 INFO Signed narinfos id=1 count=111772026/10/25 19:48:00 INFO Uploading 1 narinfos11782026/10/25 19:48:00 INFO Vacuumed table table=pending_objects11792026/10/25 19:48:00 INFO Vacuumed table table=multipart_uploads11802026/10/25 19:48:00 INFO Vacuumed table table=closures11812026/10/25 19:48:00 INFO Vacuumed table table=objects11822026/10/25 19:48:00 INFO Received complete push request method=POST path=/api/pushes/1/complete11832026/10/25 19:48:00 WARN Failed to register uploaded object key=pmxd3mvmn7j4y5p50r1iy4kii1jlw93q.narinfo error="server returned 404: 404 page not found\n"11842026/10/25 19:48:00 INFO Received uploads request method=POST path=/api/pending_closures11852026/10/25 19:48:01 INFO Completed push id=1 objects=3 duration=9.108446ms11862026/10/25 19:48:01 INFO Upload complete. (108ms)1187--- PASS: TestCommitRacingPendingCleanupKeepsObjects (0.52s)1188=== CONT TestMultipartCleanup1189--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.47s)1190=== CONT TestReadProxyConditionalGet11912026/10/25 19:48:01 INFO Aborted multipart uploads count=0 kept=011922026/10/25 19:48:01 WARN Force mode enabled - objects will be deleted immediately without grace period11932026/10/25 19:48:01 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11942026/10/25 19:48:01 INFO Received uploads request method=POST path=/api/pending_closures11952026-10-25 19:48:01.038 UTC [573] ERROR: Push does not exist: id=111962026-10-25 19:48:01.038 UTC [573] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE11972026-10-25 19:48:01.038 UTC [573] STATEMENT: SELECT commit_push($1)11982026/10/25 19:48:01 INFO Completed multipart upload object_key=nar/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb00000000000000000000.nar.zst upload_id=ZTdjMDA0N2MtM2VjOC00MWU2LTg5NGYtNDMzYWYyOTIwZDA1LmMzYzJkZmQ3LWYyZWItNGUyNi05YmE3LWE0ZjExMmNlZWYxYXgxNzkyOTU3NjgwMTc0ODA5NTA5 parts=1011992026/10/25 19:48:01 INFO All 1 paths already cached1200=== NAME TestClientIntegration12012026/10/25 19:48:01 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=01202 client_integration_test.go:357: Retrieved narinfo from S3:1203 StorePath: /build/TestClientIntegration1657185973/002/store/pmxd3mvmn7j4y5p50r1iy4kii1jlw93q-test-file.txt1204 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1205 Compression: zstd1206 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11207 NarSize: 1521208 References: 1209 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk112102026/10/25 19:48:01 INFO Vacuumed table table=pending_closures1211 client_integration_test.go:358: Retrieved .ls file from S3 (compressed size: 77 bytes)1212 client_integration_test.go:358: Decompressed .ls content (64 bytes):1213 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}12142026/10/25 19:48:01 INFO Vacuumed table table=pending_objects1215--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (1.29s)12162026/10/25 19:48:01 INFO Vacuumed table table=multipart_uploads1217=== CONT TestReadProxyRangeRequest12182026/10/25 19:48:01 INFO Vacuumed table table=closures12192026/10/25 19:48:01 INFO Vacuumed table table=objects12202026/10/25 19:48:01 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1221--- PASS: TestSweepRechecksPendingAfterLocking (0.46s)1222=== CONT TestReadProxyOutlastsServerWriteTimeout1223--- PASS: TestGetExistingObjectsLocksRows (0.32s)1224=== CONT TestParseSize1225--- PASS: TestParseSize (0.00s)1226=== CONT TestObjectStatsTrigger1227--- PASS: TestReadProxyDisabled (0.28s)1228=== CONT TestReconnectLeavesObjectsUnlocked12292026/10/25 19:48:01 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1230=== NAME TestOrphanedObjectsGC1231 orphaned_objects_gc_test.go:287: GC Test Summary:1232 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A1233 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B1234 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)1235 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)1236 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects1237--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.24s)1238=== CONT TestPendingClosureFailureAbortsItsUploads12392026/10/25 19:48:01 INFO Completed multipart upload object_key=nar/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb00000000000000000000.nar.zst upload_id=ZTdjMDA0N2MtM2VjOC00MWU2LTg5NGYtNDMzYWYyOTIwZDA1LmM0MTc1MDViLWZhYzAtNGM3NS1iOTNmLTQ0MTc4N2Y2Y2NkMngxNzkyOTU3NjgwMjA4ODg4MjA1 parts=1012402026/10/25 19:48:01 INFO Received complete push request method=POST path=/api/pushes/1/complete1241--- PASS: TestOrphanedObjectsGC (0.89s)12422026/10/25 19:48:01 INFO Completed push id=1 objects=4 duration=7.434177ms1243=== CONT TestReadProxy40412442026/10/25 19:48:01 INFO Received push request method=POST path=/api/pushes12452026/10/25 19:48:01 INFO Received push request method=POST path=/api/pushes12462026/10/25 19:48:01 INFO Object in database but missing from S3 key=pmxd3mvmn7j4y5p50r1iy4kii1jlw93q.ls12472026/10/25 19:48:01 WARN Found objects in DB but missing from S3, will re-upload count=112482026/10/25 19:48:01 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)12492026/10/25 19:48:01 INFO Received complete push request method=POST path=/api/pushes/2/complete12502026/10/25 19:48:01 WARN Failed to register uploaded object key=pmxd3mvmn7j4y5p50r1iy4kii1jlw93q.ls error="server returned 404: 404 page not found\n"12512026/10/25 19:48:01 INFO Completed push id=2 objects=3 duration=12.086725ms12522026/10/25 19:48:01 INFO Upload complete. (68ms)1253=== NAME TestClientIntegration1254 client_integration_test.go:375: Retrieved .ls file from S3 (compressed size: 62 bytes)1255 client_integration_test.go:375: Decompressed .ls content (49 bytes):1256 {"version":1,"root":{"type":"regular","size":39}}12572026/10/25 19:48:01 INFO Aborted multipart uploads count=0 kept=012582026/10/25 19:48:01 WARN Force mode enabled - objects will be deleted immediately without grace period12592026/10/25 19:48:01 INFO Received uploads request method=POST path=/api/pending_closures12602026/10/25 19:48:01 INFO Received create pin request method=POST path=/api/pins/deploy12612026/10/25 19:48:01 INFO Created/updated pin name=deploy store_path="/nix/store/dddddddddddddddddddddddddddddddd-app-1.0+git_x?y=z" narinfo_key=dddddddddddddddddddddddddddddddd.narinfo1262=== CONT TestObjectStatsUpdatedOncePerCommit1263--- PASS: TestCreatePinRejectsBadInput (1.14s)1264=== CONT TestReadProxyNarStreaming1265--- PASS: TestConnectSerialisesConcurrentMigrations (1.12s)12662026/10/25 19:48:01 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=012672026/10/25 19:48:01 INFO Vacuumed table table=pending_closures12682026/10/25 19:48:01 INFO Vacuumed table table=pending_objects12692026/10/25 19:48:01 INFO Vacuumed table table=multipart_uploads12702026/10/25 19:48:01 INFO Vacuumed table table=closures12712026/10/25 19:48:01 INFO Received push request method=POST path=/api/pushes12722026/10/25 19:48:01 INFO Vacuumed table table=objects12732026/10/25 19:48:01 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)12742026/10/25 19:48:01 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12752026/10/25 19:48:01 INFO Received complete push request method=POST path=/api/pushes/3/complete12762026/10/25 19:48:01 WARN Failed to register uploaded object key=pmxd3mvmn7j4y5p50r1iy4kii1jlw93q.ls error="server returned 404: 404 page not found\n"12772026/10/25 19:48:01 INFO Completed push id=3 objects=3 duration=2.03891ms12782026/10/25 19:48:01 INFO Upload complete. (56ms)1279=== NAME TestClientIntegration1280 client_integration_test.go:392: Retrieved .ls file from S3 (compressed size: 62 bytes)1281 client_integration_test.go:392: Decompressed .ls content (49 bytes):1282 {"version":1,"root":{"type":"regular","size":39}}1283=== CONT TestClientCADerivations1284--- PASS: TestReadProxyRangeRequest (0.24s)12852026/10/25 19:48:01 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=ZTdjMDA0N2MtM2VjOC00MWU2LTg5NGYtNDMzYWYyOTIwZDA1LjI1NzQ0ZTA3LWRmYjItNGZkMC04MGIyLTdlN2E1M2NkMDc1ZXgxNzkyOTU3NjgwOTA2ODE4MDc4 parts=1012862026/10/25 19:48:01 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12872026/10/25 19:48:01 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12882026/10/25 19:48:01 INFO Completed upload id=1 objects=2 duration=5.927958ms12892026/10/25 19:48:01 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12902026/10/25 19:48:01 INFO Completed multipart upload object_key=nar/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb00000000000000000000.nar.zst upload_id=ZTdjMDA0N2MtM2VjOC00MWU2LTg5NGYtNDMzYWYyOTIwZDA1LjFjN2RlMmFiLTExYTgtNDRlMS04MTBkLTQxMzY2ZWM4ZDk3OXgxNzkyOTU3NjgwNDM4NzkzMTY0 parts=1012912026/10/25 19:48:01 INFO Received complete push request method=POST path=/api/pushes/1/complete12922026/10/25 19:48:01 INFO Received uploads request method=POST path=/api/pending_closures12932026/10/25 19:48:01 INFO Received cleanup request method=DELETE path=/api/pending_closures12942026/10/25 19:48:01 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket46/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""12952026/10/25 19:48:01 INFO Aborted multipart uploads count=0 kept=112962026/10/25 19:48:01 INFO Received uploads request method=POST path=/api/pending_closures12972026/10/25 19:48:01 INFO Completed push id=1 objects=4 duration=11.350775ms12982026/10/25 19:48:01 INFO Received cleanup request method=DELETE path=/api/pending_closures12992026/10/25 19:48:01 INFO Aborted multipart uploads count=1 kept=01300--- PASS: TestObjectStatsTrigger (0.27s)1301=== CONT TestPresentRefreshesOnlyStaleClosures13022026/10/25 19:48:01 INFO Completed multipart upload object_key=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa00000000000000000000.nar.zst upload_id=ZTdjMDA0N2MtM2VjOC00MWU2LTg5NGYtNDMzYWYyOTIwZDA1LmZlYTE0NDkzLTAwYTQtNDQ0Ni05MzZhLTc4MGEyYzQwY2UyM3gxNzkyOTU3NjgwODkxNDc2NjE0 parts=1013032026/10/25 19:48:01 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo13042026/10/25 19:48:01 WARN Found objects in DB but missing from S3, will re-upload count=11305--- PASS: TestPush_RepeatedRootCommitsOnce (1.60s)1306=== CONT TestPresentNotReportedWhileGCDeletesClosure1307=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh1308=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh1309=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale1310=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale1311=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock13122026/10/25 19:48:01 INFO Created/updated pin name=app store_path=/nix/store/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa-app narinfo_key=aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.narinfo1313=== CONT TestReadProxyContentNegotiation1314--- PASS: TestMultipartCleanup (0.36s)13152026/10/25 19:48:01 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13162026/10/25 19:48:01 INFO Received complete upload request method=POST path=/api/pending_closures/3/complete13172026/10/25 19:48:01 INFO Completed upload id=3 objects=2 duration=7.184247ms13182026/10/25 19:48:01 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13192026/10/25 19:48:01 INFO Created/updated pin name=app store_path=/nix/store/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb-app narinfo_key=bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb.narinfo1320--- PASS: TestReconnectLeavesObjectsUnlocked (0.33s)1321=== CONT TestDeleteClosuresRacingPins1322=== CONT TestCacheStatsHandler1323--- PASS: TestReadProxyConditionalGet (0.39s)13242026/10/25 19:48:01 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=ZTdjMDA0N2MtM2VjOC00MWU2LTg5NGYtNDMzYWYyOTIwZDA1LmU0M2JlZjRlLWIyOTctNGNiZC1hYTM3LTY5MGJmYzViNmRiMXgxNzkyOTU3NjgwODkzMzU2ODQz error="Get \"http://127.0.0.1:1/bucket14/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"13252026/10/25 19:48:01 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=ZTdjMDA0N2MtM2VjOC00MWU2LTg5NGYtNDMzYWYyOTIwZDA1LjRlZTVkOTVjLTQ3ZTctNDczZC1iODZmLTc1YWE1N2ZhOGEyM3gxNzkyOTU3NjgwODg0MDk0NjQ3 parts=121326--- PASS: TestService_verifyS3Integrity (0.95s)1327=== CONT TestReadProxyHead13282026/10/25 19:48:01 INFO Received push request method=POST path=/api/pushes13292026/10/25 19:48:01 INFO Received cleanup request method=DELETE path=/api/pending_closures13302026/10/25 19:48:01 INFO Received uploads request method=POST path=/api/pending_closures13312026/10/25 19:48:01 INFO Aborted multipart uploads count=1 kept=013322026/10/25 19:48:01 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)13332026/10/25 19:48:01 INFO Uploading hcxkpbrrfw4nrdc546zi2dz85yb8sbir-lost-commit.txt (152B)13342026/10/25 19:48:01 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=ZTdjMDA0N2MtM2VjOC00MWU2LTg5NGYtNDMzYWYyOTIwZDA1LjExOTIwNmNmLWJiZGItNGZiZC05MWYzLTFkYTQzZjZmNWY3NXgxNzkyOTU3NjgwOTY2MDI4Nzc0 parts=1013352026/10/25 19:48:01 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13362026/10/25 19:48:01 INFO Completed upload id=1 objects=2 duration=3.929519ms1337=== CONT TestClientFallsBackToClosures1338--- PASS: TestConcurrentPinUpdatesAgree (0.99s)13392026/10/25 19:48:01 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000013402026/10/25 19:48:01 INFO Received uploads request method=POST path=/api/pending_closures13412026/10/25 19:48:01 INFO Starting cleanup of old closures method=DELETE path=/api/closures13422026/10/25 19:48:01 WARN Failed to register uploaded object key=nar/04d5klw9iix884nk82y7nlkps8afh2bg119y7zkvcf1pc1x2y2jl.nar.zst error="server returned 404: 404 page not found\n"13432026/10/25 19:48:01 INFO Received sign narinfos request method=POST path=/api/pushes/4/sign13442026/10/25 19:48:01 INFO Aborted multipart uploads count=0 kept=013452026/10/25 19:48:01 WARN Failed to register uploaded object key=hcxkpbrrfw4nrdc546zi2dz85yb8sbir.ls error="server returned 404: 404 page not found\n"13462026/10/25 19:48:01 INFO Signed narinfos id=4 count=113472026/10/25 19:48:01 INFO Uploading 1 narinfos1348--- PASS: TestRedundantMultipartUpload (1.70s)1349=== CONT TestCacheConfigHandler1350=== RUN TestCacheConfigHandler/full_config,_no_issuer1351=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1352=== RUN TestCacheConfigHandler/no_cache_url_configured1353=== PAUSE TestCacheConfigHandler/no_cache_url_configured1354=== RUN TestCacheConfigHandler/no_signing_keys1355=== PAUSE TestCacheConfigHandler/no_signing_keys1356=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1357=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1358=== CONT TestClientPushesUseOnePush13592026/10/25 19:48:01 INFO Received complete push request method=POST path=/api/pushes/4/complete13602026/10/25 19:48:01 WARN Failed to register uploaded object key=hcxkpbrrfw4nrdc546zi2dz85yb8sbir.narinfo error="server returned 404: 404 page not found\n"13612026/10/25 19:48:01 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=013622026/10/25 19:48:01 INFO Completed push id=4 objects=3 duration=5.142438ms13632026/10/25 19:48:01 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:41947/api/pushes/4/complete\": EOF" url=http://127.0.0.1:41947/api/pushes/4/complete13642026/10/25 19:48:01 INFO Vacuumed table table=pending_closures1365--- PASS: TestPendingClosureFailureAbortsItsUploads (0.37s)1366=== CONT TestReadProxyNarinfoAlreadyDecompressed13672026/10/25 19:48:01 INFO Vacuumed table table=pending_objects13682026/10/25 19:48:01 INFO Vacuumed table table=multipart_uploads13692026/10/25 19:48:01 INFO Vacuumed table table=closures13702026/10/25 19:48:01 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13712026/10/25 19:48:01 INFO Vacuumed table table=objects1372=== CONT TestPinProtectsFromGC1373--- PASS: TestReadProxyNarStreaming (0.27s)1374=== CONT TestService_RequireScope_OIDC1375--- PASS: TestObjectStatsUpdatedOncePerCommit (0.27s)13762026/10/25 19:48:01 INFO Completed multipart upload object_key=nar/cccccccccccccccccccccccccccccccc00000000000000000000.nar.zst upload_id=ZTdjMDA0N2MtM2VjOC00MWU2LTg5NGYtNDMzYWYyOTIwZDA1LjUxOWI2NGM4LWNhODMtNDQ3My1hOThjLTc2YWI4MmQ3N2MwMXgxNzkyOTU3NjgwMTc0NDI4MTE5 parts=1013772026/10/25 19:48:01 INFO Received complete push request method=POST path=/api/pushes/1/complete13782026/10/25 19:48:01 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000013792026/10/25 19:48:01 INFO Completed push id=1 objects=6 duration=16.345763ms1380--- PASS: TestPushWaitsForSweepHoldingRow (0.95s)1381=== CONT TestClientSharedPathCommittedMidPush1382--- PASS: TestService_createPendingClosureHandler (1.01s)1383=== CONT TestReadProxyNarinfo1384--- PASS: TestPush_CompleteCommitsEveryRoot (1.82s)1385=== CONT TestClientWithDependencies13862026/10/25 19:48:01 INFO Received complete push request method=POST path=/api/pushes/4/complete13872026-10-25 19:48:01.582 UTC [535] ERROR: Push does not exist: id=413882026-10-25 19:48:01.582 UTC [535] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE13892026-10-25 19:48:01.582 UTC [535] STATEMENT: -- name: CommitPush :one1390 SELECT commit_push($1::bigint)::bigint1391 13922026/10/25 19:48:01 WARN Push not found id=413932026/10/25 19:48:01 INFO Upload complete. (210ms)1394=== NAME TestClientIntegration1395 client_integration_test.go:422: Retrieved narinfo from S3:1396 StorePath: /build/TestClientIntegration1657185973/002/store/hcxkpbrrfw4nrdc546zi2dz85yb8sbir-lost-commit.txt1397 URL: nar/04d5klw9iix884nk82y7nlkps8afh2bg119y7zkvcf1pc1x2y2jl.nar.zst1398 Compression: zstd1399 NarHash: sha256:04d5klw9iix884nk82y7nlkps8afh2bg119y7zkvcf1pc1x2y2jl1400 NarSize: 1521401 References: 1402 CA: fixed:r:sha256:04d5klw9iix884nk82y7nlkps8afh2bg119y7zkvcf1pc1x2y2jl1403 client_integration_test.go:425: Testing garbage collection...1404=== NAME TestClientCADerivations1405 client_ca_test.go:136: Built CA derivation: /build/TestClientCADerivations779411879/001/store/wmhsi665hgk67f1iz5f4n3my4di2ld8f-ca-test14062026/10/25 19:48:01 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:44033/oidc14072026/10/25 19:48:01 INFO Starting cleanup of old closures method=DELETE path=/api/closures14082026/10/25 19:48:01 INFO Garbage collection started14092026/10/25 19:48:01 INFO Aborted multipart uploads count=0 kept=01410 client_ca_test.go:139: Found 1 dependencies (including self)14112026/10/25 19:48:01 WARN Force mode enabled - objects will be deleted immediately without grace period1412--- PASS: TestPresentRefreshesOnlyStaleClosures (0.40s)1413=== CONT TestClientMultipleUploads14142026/10/25 19:48:01 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=014152026/10/25 19:48:01 INFO Vacuumed table table=pending_closures14162026/10/25 19:48:01 INFO Vacuumed table table=pending_objects14172026/10/25 19:48:01 INFO Vacuumed table table=multipart_uploads1418--- PASS: TestReadProxyHead (0.35s)1419=== CONT TestService_ReadScope_PublicByDefault14202026/10/25 19:48:01 INFO Vacuumed table table=closures14212026/10/25 19:48:01 INFO Received push request method=POST path=/api/pushes14222026/10/25 19:48:01 INFO Vacuumed table table=objects1423--- PASS: TestCacheStatsHandler (0.36s)1424=== CONT TestResolveDBConnectionString14252026/10/25 19:48:01 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1426=== RUN TestResolveDBConnectionString/flag_wins1427=== PAUSE TestResolveDBConnectionString/flag_wins1428=== RUN TestResolveDBConnectionString/file_when_flag_empty1429=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1430=== RUN TestResolveDBConnectionString/missing_file_is_an_error1431=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1432=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1433=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1434=== RUN TestResolveDBConnectionString/nothing_configured1435=== PAUSE TestResolveDBConnectionString/nothing_configured1436=== CONT TestService_AuthMiddleware_OIDC14372026/10/25 19:48:01 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14382026/10/25 19:48:01 INFO Uploading wmhsi665hgk67f1iz5f4n3my4di2ld8f-ca-test (144B)14392026/10/25 19:48:01 WARN Failed to register uploaded object key=log/wh7zdm785s1z24dj6j4y1vvfn8q187fy-ca-test.drv error="server returned 404: 404 page not found\n"14402026/10/25 19:48:01 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"14412026/10/25 19:48:01 INFO Completed multipart upload object_key=nar/cccccccccccccccccccccccccccccccc00000000000000000000.nar.zst upload_id=ZTdjMDA0N2MtM2VjOC00MWU2LTg5NGYtNDMzYWYyOTIwZDA1Ljg0YTFjNzFhLWVkNzYtNDNjNi04NGI1LWNhZjhjMjU0NmI3MXgxNzkyOTU3NjgxMTQyNjgxODA0 parts=1014422026/10/25 19:48:01 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14432026/10/25 19:48:01 WARN Failed to register uploaded object key=wmhsi665hgk67f1iz5f4n3my4di2ld8f.ls error="server returned 404: 404 page not found\n"14442026/10/25 19:48:01 INFO Signed narinfos id=1 count=114452026/10/25 19:48:01 INFO Received complete push request method=POST path=/api/pushes/2/complete14462026/10/25 19:48:01 INFO Uploading 1 narinfos14472026/10/25 19:48:01 INFO Received complete push request method=POST path=/api/pushes/1/complete14482026/10/25 19:48:01 WARN Failed to register uploaded object key=wmhsi665hgk67f1iz5f4n3my4di2ld8f.narinfo error="server returned 404: 404 page not found\n"14492026/10/25 19:48:01 INFO Completed push id=2 objects=4 duration=18.209253ms14502026/10/25 19:48:01 WARN Rate limiter enabled after throttle name=s3-test rate=514512026/10/25 19:48:01 WARN S3 rate limit hit during proxy key=4hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo error="Please reduce your request rate."14522026/10/25 19:48:01 INFO Completed push id=1 objects=4 duration=14.153384ms14532026/10/25 19:48:01 INFO Upload complete. (145ms)1454=== NAME TestClientCADerivations1455 client_ca_test.go:180: Narinfo contains CA field: StorePath: /build/TestClientCADerivations779411879/001/store/wmhsi665hgk67f1iz5f4n3my4di2ld8f-ca-test1456 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1457 Compression: zstd1458 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1459 NarSize: 1441460 References: 1461 Deriver: /build/TestClientCADerivations779411879/001/store/wh7zdm785s1z24dj6j4y1vvfn8q187fy-ca-test.drv1462 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1463 client_ca_test.go:185: Checking for realisation files in S3...1464 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1465 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache14662026/10/25 19:48:01 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1467--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (2.08s)1468=== CONT TestIsValidCachePath1469=== RUN TestIsValidCachePath/narinfo1470=== PAUSE TestIsValidCachePath/narinfo1471=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1472=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1473=== RUN TestIsValidCachePath/nar_zst1474=== PAUSE TestIsValidCachePath/nar_zst1475=== RUN TestIsValidCachePath/nar_xz1476=== PAUSE TestIsValidCachePath/nar_xz1477=== RUN TestIsValidCachePath/nar_bz21478=== PAUSE TestIsValidCachePath/nar_bz21479=== RUN TestIsValidCachePath/nar_uncompressed14802026/10/25 19:48:01 INFO lead: released remote=192.0.2.1:12341481=== PAUSE TestIsValidCachePath/nar_uncompressed1482=== RUN TestIsValidCachePath/ls1483=== PAUSE TestIsValidCachePath/ls1484=== RUN TestIsValidCachePath/log1485=== PAUSE TestIsValidCachePath/log1486=== RUN TestIsValidCachePath/realisation1487=== PAUSE TestIsValidCachePath/realisation1488=== RUN TestIsValidCachePath/nix-cache-info1489=== PAUSE TestIsValidCachePath/nix-cache-info1490=== RUN TestIsValidCachePath/index.html1491=== PAUSE TestIsValidCachePath/index.html1492=== RUN TestIsValidCachePath/traversal_parent1493=== PAUSE TestIsValidCachePath/traversal_parent1494=== RUN TestIsValidCachePath/traversal_in_middle1495=== PAUSE TestIsValidCachePath/traversal_in_middle1496=== RUN TestIsValidCachePath/invalid_char_e1497=== PAUSE TestIsValidCachePath/invalid_char_e1498=== RUN TestIsValidCachePath/invalid_char_u1499=== PAUSE TestIsValidCachePath/invalid_char_u1500=== RUN TestIsValidCachePath/random_path1501=== PAUSE TestIsValidCachePath/random_path1502=== RUN TestIsValidCachePath/empty1503=== PAUSE TestIsValidCachePath/empty1504=== RUN TestIsValidCachePath/leading_slash1505=== PAUSE TestIsValidCachePath/leading_slash1506=== RUN TestIsValidCachePath/wrong_extension1507=== PAUSE TestIsValidCachePath/wrong_extension1508=== RUN TestIsValidCachePath/short_hash1509=== PAUSE TestIsValidCachePath/short_hash1510=== CONT TestService_AuthMiddleware_MTLSBoundSubjects15112026/10/25 19:48:01 INFO Completed multipart upload object_key=nar/cccccccccccccccccccccccccccccccc00000000000000000000.nar.zst upload_id=ZTdjMDA0N2MtM2VjOC00MWU2LTg5NGYtNDMzYWYyOTIwZDA1Ljk1NDQ4YjBmLWZlNGQtNGU2Yy05MTFiLTFkYzQ4OWE5OTA3MHgxNzkyOTU3NjgwODkxNzYyODA0 parts=1015122026/10/25 19:48:01 WARN Rate limiter backed off name=s3-test rate=515132026/10/25 19:48:01 WARN S3 rate limit hit during proxy key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhh.nar.zst error="Please reduce your request rate."15142026/10/25 19:48:01 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:34547/oidc1515--- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.41s)15162026/10/25 19:48:01 INFO lead: acquired remote=192.0.2.1:12341517=== CONT TestService_ReadAuthMiddleware1518--- PASS: TestReadProxy404 (0.76s)1519=== CONT TestPresentReportsOnlyClosureRoots1520=== NAME TestPinProtectsFromGC1521 client_integration_test.go:854: Pinned store path: /build/TestPinProtectsFromGC1833250761/001/store/xwrynsxjcsj8w1mg2a9lvbys9db32n0d-pinned-file.txt1522 client_integration_test.go:855: Unpinned store path: /build/TestPinProtectsFromGC1833250761/001/store/9z7s45q7dn1qhsga7zmwnw31kgwjryh7-unpinned-file.txt1523=== RUN TestService_RequireScope_OIDC/builder_may_write1524=== PAUSE TestService_RequireScope_OIDC/builder_may_write1525=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1526=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1527=== RUN TestService_RequireScope_OIDC/ops_may_admin1528=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1529=== RUN TestService_RequireScope_OIDC/ops_may_not_write1530=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1531=== RUN TestService_RequireScope_OIDC/reader_may_not_write1532=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1533=== RUN TestService_RequireScope_OIDC/static_token_may_admin1534=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1535=== RUN TestService_RequireScope_OIDC/static_token_may_write1536=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1537=== RUN TestService_RequireScope_OIDC/reader_may_read1538=== PAUSE TestService_RequireScope_OIDC/reader_may_read1539=== RUN TestService_RequireScope_OIDC/writer_implies_read1540=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1541=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1542=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1543=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1544=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc1545=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1546=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1547=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1548=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1549=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1550=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1551=== CONT TestService_AuthMiddleware1552=== NAME TestClientCADerivations1553 client_ca_test.go:258: nix copy output: warning: you don't have Internet access; disabling some network-dependent features1554 warning: failed to create TLS context for AWS credential providers; SSO, STS WebIdentity, and ECS container authentication will be unavailable1555 error: binary cache 's3://bucket56?endpoint=http://localhost:42519®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/build/TestClientCADerivations779411879/001/store'1556 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 11557=== NAME TestClientWithDependencies1558 client_integration_test.go:722: Built derivation: /build/TestClientWithDependencies438745056/001/store/ph744dh892i53gwhnihz9fbkhs9ax5x1-test-script1559=== CONT TestNARDeduplicationMetadataUploadBug1560--- PASS: TestClientCADerivations (0.83s)1561=== NAME TestClientWithDependencies1562 client_integration_test.go:724: Found 1 dependencies (including self)15632026/10/25 19:48:02 INFO Received push request method=POST path=/api/pushes15642026/10/25 19:48:02 INFO Received uploads request method=POST path=/api/pending_closures15652026/10/25 19:48:02 INFO Received push request method=POST path=/api/pushes1566--- PASS: TestService_ReadScope_PublicByDefault (0.37s)1567=== CONT TestDeletePinKeepsRowWhenS3Fails15682026/10/25 19:48:02 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15692026/10/25 19:48:02 INFO Uploading xwrynsxjcsj8w1mg2a9lvbys9db32n0d-pinned-file.txt (128B)1570=== NAME TestClientMultipleUploads1571 client_integration_test.go:467: Created store path 0: /build/TestClientMultipleUploads822515139/001/store/36zni4v1dx9frz7d3pwnmgy2vrrwrwgc-test-file-0.txt15722026/10/25 19:48:02 INFO Received uploads request method=POST path=/api/pending_closures15732026/10/25 19:48:02 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)15742026/10/25 19:48:02 INFO Uploading vgfa9lr9f3a8knwb0arnfmp1p4fb7683-shared-dep (136B)15752026/10/25 19:48:02 INFO Uploading bj9y5lvhy1n5vx1d1yxss4l61hlg731j-b (216B)15762026/10/25 19:48:02 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)15772026/10/25 19:48:02 INFO Uploading g3n7ygizwq8a00k0ck25wyg5469bv3x9-shared-dep (136B)15782026/10/25 19:48:02 INFO Uploading j62ifliyvpfxr4bj19dwjylmhsp3igds-b (216B)15792026/10/25 19:48:02 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"15802026/10/25 19:48:02 WARN mTLS auth: bound subjects configured but subject DN unavailable15812026/10/25 19:48:02 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"15822026/10/25 19:48:02 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"15832026/10/25 19:48:02 WARN Failed to register uploaded object key=3cx9kkfmlphcwsd7rnbnx9s9s6isncby.ls error="server returned 404: 404 page not found\n"15842026/10/25 19:48:02 WARN Failed to register uploaded object key=nar/0balj7iwwrxa35mal8bdk8birhiqi3z0v49wp17wyczsc7j6yrhm.nar.zst error="server returned 404: 404 page not found\n"1585--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.32s)15862026/10/25 19:48:02 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"1587=== CONT TestMetricsCommit15882026/10/25 19:48:02 WARN Failed to register uploaded object key=xwrynsxjcsj8w1mg2a9lvbys9db32n0d.ls error="server returned 404: 404 page not found\n"15892026/10/25 19:48:02 WARN Failed to register uploaded object key=8s3sk5cyw49ibikd5pzya1fhy4kn5zsv.ls error="server returned 404: 404 page not found\n"15902026/10/25 19:48:02 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15912026/10/25 19:48:02 WARN Failed to register uploaded object key=g3n7ygizwq8a00k0ck25wyg5469bv3x9.ls error="server returned 404: 404 page not found\n"15922026/10/25 19:48:02 WARN Failed to register uploaded object key=nar/1icpdfxqhjr23c0l0am887v2piiaayiwd968ir0ji2qsnfhp854a.nar.zst error="server returned 404: 404 page not found\n"15932026/10/25 19:48:02 INFO Signed narinfos id=1 count=115942026/10/25 19:48:02 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"15952026/10/25 19:48:02 INFO Uploading 1 narinfos1596=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1597=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1598=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1599=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected16002026/10/25 19:48:02 WARN Failed to register uploaded object key=bj9y5lvhy1n5vx1d1yxss4l61hlg731j.ls error="server returned 404: 404 page not found\n"1601=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected16022026/10/25 19:48:02 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign1603=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected16042026/10/25 19:48:02 WARN Failed to register uploaded object key=vgfa9lr9f3a8knwb0arnfmp1p4fb7683.ls error="server returned 404: 404 page not found\n"1605=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1606=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1607=== CONT TestChildrenInheritRaisedFileLimit16082026/10/25 19:48:02 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign16092026/10/25 19:48:02 INFO Signed narinfos id=1 count=316102026/10/25 19:48:02 INFO Received push request method=POST path=/api/pushes16112026/10/25 19:48:02 WARN Failed to register uploaded object key=j62ifliyvpfxr4bj19dwjylmhsp3igds.ls error="server returned 404: 404 page not found\n"16122026/10/25 19:48:02 INFO Uploading 3 narinfos16132026/10/25 19:48:02 INFO Received complete push request method=POST path=/api/pushes/1/complete16142026/10/25 19:48:02 INFO Signed narinfos id=2 count=216152026/10/25 19:48:02 WARN Failed to register uploaded object key=xwrynsxjcsj8w1mg2a9lvbys9db32n0d.narinfo error="server returned 404: 404 page not found\n"1616--- PASS: TestChildrenInheritRaisedFileLimit (0.00s)16172026/10/25 19:48:02 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign1618=== CONT TestPendingClosureFailureTracksEveryUpload1619=== RUN TestPendingClosureFailureTracksEveryUpload/refuse_aborts=false1620=== PAUSE TestPendingClosureFailureTracksEveryUpload/refuse_aborts=false1621=== RUN TestPendingClosureFailureTracksEveryUpload/refuse_aborts=true1622=== PAUSE TestPendingClosureFailureTracksEveryUpload/refuse_aborts=true16232026/10/25 19:48:02 INFO Signed narinfos id=1 count=21624=== CONT TestGCAdvisoryLockBlocksConcurrentRun16252026/10/25 19:48:02 INFO Uploading 4 narinfos1626=== NAME TestClientMultipleUploads1627 client_integration_test.go:467: Created store path 1: /build/TestClientMultipleUploads822515139/001/store/wgxc287k7h869vsrl7wbjmbg47jm7842-test-file-1.txt16282026/10/25 19:48:02 INFO Completed push id=1 objects=3 duration=4.686348ms16292026/10/25 19:48:02 INFO Upload complete. (178ms)16302026/10/25 19:48:02 WARN Failed to register uploaded object key=bj9y5lvhy1n5vx1d1yxss4l61hlg731j.narinfo error="server returned 404: 404 page not found\n"16312026/10/25 19:48:02 WARN Failed to register uploaded object key=3cx9kkfmlphcwsd7rnbnx9s9s6isncby.narinfo error="server returned 404: 404 page not found\n"16322026/10/25 19:48:02 WARN Failed to register uploaded object key=g3n7ygizwq8a00k0ck25wyg5469bv3x9.narinfo error="server returned 404: 404 page not found\n"16332026/10/25 19:48:02 WARN Failed to register uploaded object key=8s3sk5cyw49ibikd5pzya1fhy4kn5zsv.narinfo error="server returned 404: 404 page not found\n"16342026/10/25 19:48:02 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)16352026/10/25 19:48:02 INFO Uploading gilf6gh3cba9992759j9hj3w07j5l03j-shared-dep (136B)16362026/10/25 19:48:02 INFO Uploading mm3d2l3j5l7cwcgjy7y8dww5qm4gid04-top (224B)16372026/10/25 19:48:02 INFO Received complete push request method=POST path=/api/pushes/1/complete16382026/10/25 19:48:02 WARN Failed to register uploaded object key=vgfa9lr9f3a8knwb0arnfmp1p4fb7683.narinfo error="server returned 404: 404 page not found\n"16392026/10/25 19:48:02 WARN Failed to register uploaded object key=gilf6gh3cba9992759j9hj3w07j5l03j.ls error="server returned 404: 404 page not found\n"16402026/10/25 19:48:02 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"16412026/10/25 19:48:02 WARN Failed to register uploaded object key=g3n7ygizwq8a00k0ck25wyg5469bv3x9.narinfo error="server returned 404: 404 page not found\n"16422026/10/25 19:48:02 WARN Failed to register uploaded object key=j62ifliyvpfxr4bj19dwjylmhsp3igds.narinfo error="server returned 404: 404 page not found\n"16432026/10/25 19:48:02 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete16442026/10/25 19:48:02 WARN Failed to register uploaded object key=nar/181lxrqcs1w0hviza9rgziv3wbvj5bz8c09brvkd7jiah24isi94.nar.zst error="server returned 404: 404 page not found\n"16452026/10/25 19:48:02 WARN Failed to register uploaded object key=mm3d2l3j5l7cwcgjy7y8dww5qm4gid04.ls error="server returned 404: 404 page not found\n"16462026/10/25 19:48:02 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16472026/10/25 19:48:02 INFO Signed narinfos id=1 count=216482026/10/25 19:48:02 INFO Received push request method=POST path=/api/pushes16492026/10/25 19:48:02 INFO Uploading 2 narinfos16502026/10/25 19:48:02 INFO Completed upload id=1 objects=6 duration=14.421144ms16512026/10/25 19:48:02 INFO Completed push id=1 objects=8 duration=17.607433ms16522026/10/25 19:48:02 INFO Upload complete. (215ms)16532026/10/25 19:48:02 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete1654=== NAME TestClientPushesUseOnePush1655 client_pushes_test.go:97: Retrieved narinfo from S3:1656 StorePath: /build/TestClientPushesUseOnePush1747330685/001/store/vgfa9lr9f3a8knwb0arnfmp1p4fb7683-shared-dep1657 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1658 Compression: zstd1659 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821660 NarSize: 1361661 References: 1662 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n16632026/10/25 19:48:02 INFO Completed upload id=2 objects=6 duration=2.272089ms16642026/10/25 19:48:02 INFO Upload complete. (234ms)1665--- PASS: TestService_ReadAuthMiddleware (0.31s)1666=== CONT TestCreatePendingClosureRejectsOversizedNAR16672026/10/25 19:48:02 INFO Received complete push request method=POST path=/api/pushes/1/complete16682026/10/25 19:48:02 INFO Received uploads request method=POST path=/api/pending_closures16692026/10/25 19:48:02 WARN Failed to register uploaded object key=gilf6gh3cba9992759j9hj3w07j5l03j.narinfo error="server returned 404: 404 page not found\n"1670=== NAME TestClientFallsBackToClosures16712026/10/25 19:48:02 WARN Failed to register uploaded object key=mm3d2l3j5l7cwcgjy7y8dww5qm4gid04.narinfo error="server returned 404: 404 page not found\n"1672 client_pushes_test.go:112: Retrieved narinfo from S3:1673 StorePath: /build/TestClientFallsBackToClosures898320453/001/store/g3n7ygizwq8a00k0ck25wyg5469bv3x9-shared-dep1674 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst16752026/10/25 19:48:02 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)1676 Compression: zstd16772026/10/25 19:48:02 INFO Uploading ph744dh892i53gwhnihz9fbkhs9ax5x1-test-script (136B)1678--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1679=== CONT TestGCMetrics1680=== NAME TestClientMultipleUploads1681 client_integration_test.go:467: Created store path 2: /build/TestClientMultipleUploads822515139/001/store/anfj6fi6jzfncv74w445lnjnzdx8k8hb-test-file-2.txt1682=== NAME TestClientFallsBackToClosures1683 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821684=== NAME TestClientPushesUseOnePush1685 client_pushes_test.go:97: Retrieved narinfo from S3:1686 StorePath: /build/TestClientPushesUseOnePush1747330685/001/store/3cx9kkfmlphcwsd7rnbnx9s9s6isncby-a1687 URL: nar/0balj7iwwrxa35mal8bdk8birhiqi3z0v49wp17wyczsc7j6yrhm.nar.zst1688 Compression: zstd1689 NarHash: sha256:0balj7iwwrxa35mal8bdk8birhiqi3z0v49wp17wyczsc7j6yrhm1690 NarSize: 2161691 References: /build/TestClientPushesUseOnePush1747330685/001/store/vgfa9lr9f3a8knwb0arnfmp1p4fb7683-shared-dep1692 CA: text:sha256:12lnf270ap5qkr3ad5943kf9y4ah480jbzanklqchj6p7mhgxz8r1693=== NAME TestClientFallsBackToClosures1694 NarSize: 1361695 References: 1696 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n16972026/10/25 19:48:02 INFO Completed push id=1 objects=6 duration=6.469357ms16982026/10/25 19:48:02 INFO Upload complete. (79ms)1699=== NAME TestClientPushesUseOnePush1700 client_pushes_test.go:97: Retrieved narinfo from S3:1701 StorePath: /build/TestClientPushesUseOnePush1747330685/001/store/bj9y5lvhy1n5vx1d1yxss4l61hlg731j-b1702 URL: nar/0balj7iwwrxa35mal8bdk8birhiqi3z0v49wp17wyczsc7j6yrhm.nar.zst1703 Compression: zstd1704 NarHash: sha256:0balj7iwwrxa35mal8bdk8birhiqi3z0v49wp17wyczsc7j6yrhm1705 NarSize: 2161706 References: /build/TestClientPushesUseOnePush1747330685/001/store/vgfa9lr9f3a8knwb0arnfmp1p4fb7683-shared-dep1707 CA: text:sha256:12lnf270ap5qkr3ad5943kf9y4ah480jbzanklqchj6p7mhgxz8r1708=== NAME TestClientFallsBackToClosures1709 client_pushes_test.go:112: Retrieved narinfo from S3:1710 StorePath: /build/TestClientFallsBackToClosures898320453/001/store/8s3sk5cyw49ibikd5pzya1fhy4kn5zsv-a1711 URL: nar/1icpdfxqhjr23c0l0am887v2piiaayiwd968ir0ji2qsnfhp854a.nar.zst1712 Compression: zstd1713 NarHash: sha256:1icpdfxqhjr23c0l0am887v2piiaayiwd968ir0ji2qsnfhp854a1714 NarSize: 2161715 References: /build/TestClientFallsBackToClosures898320453/001/store/g3n7ygizwq8a00k0ck25wyg5469bv3x9-shared-dep1716 CA: text:sha256:131zklcib21d395v3y4fzllnd1cj232c9fvcprs6fag2zar72qv417172026/10/25 19:48:02 WARN Failed to register uploaded object key=log/1ayjfgjz4nl2hxxqh3390sabx620w9gd-test-script.drv error="server returned 404: 404 page not found\n"1718=== NAME TestClientSharedPathCommittedMidPush1719 client_integration_test.go:803: Retrieved narinfo from S3:1720 StorePath: /build/TestClientSharedPathCommittedMidPush3611140159/001/store/gilf6gh3cba9992759j9hj3w07j5l03j-shared-dep1721 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1722 Compression: zstd1723 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y8217242026/10/25 19:48:02 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"1725 NarSize: 1361726 References: 1727 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1728=== NAME TestClientFallsBackToClosures1729 client_pushes_test.go:112: Retrieved narinfo from S3:1730 StorePath: /build/TestClientFallsBackToClosures898320453/001/store/j62ifliyvpfxr4bj19dwjylmhsp3igds-b1731 URL: nar/1icpdfxqhjr23c0l0am887v2piiaayiwd968ir0ji2qsnfhp854a.nar.zst1732 Compression: zstd1733 NarHash: sha256:1icpdfxqhjr23c0l0am887v2piiaayiwd968ir0ji2qsnfhp854a1734 NarSize: 2161735 References: /build/TestClientFallsBackToClosures898320453/001/store/g3n7ygizwq8a00k0ck25wyg5469bv3x9-shared-dep1736 CA: text:sha256:131zklcib21d395v3y4fzllnd1cj232c9fvcprs6fag2zar72qv41737=== NAME TestClientSharedPathCommittedMidPush1738 client_integration_test.go:803: Retrieved narinfo from S3:1739 StorePath: /build/TestClientSharedPathCommittedMidPush3611140159/001/store/mm3d2l3j5l7cwcgjy7y8dww5qm4gid04-top1740 URL: nar/181lxrqcs1w0hviza9rgziv3wbvj5bz8c09brvkd7jiah24isi94.nar.zst1741 Compression: zstd1742 NarHash: sha256:181lxrqcs1w0hviza9rgziv3wbvj5bz8c09brvkd7jiah24isi941743 NarSize: 2241744 References: /build/TestClientSharedPathCommittedMidPush3611140159/001/store/gilf6gh3cba9992759j9hj3w07j5l03j-shared-dep1745 CA: text:sha256:1cbzs8mv5vzfvyzqc901h2zcjbc5l4k2kdc039fwhm99yji29fhw17462026/10/25 19:48:02 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17472026/10/25 19:48:02 WARN Failed to register uploaded object key=ph744dh892i53gwhnihz9fbkhs9ax5x1.ls error="server returned 404: 404 page not found\n"17482026/10/25 19:48:02 INFO Signed narinfos id=1 count=117492026/10/25 19:48:02 INFO Uploading 1 narinfos17502026/10/25 19:48:02 INFO Received complete push request method=POST path=/api/pushes/1/complete17512026/10/25 19:48:02 WARN Failed to register uploaded object key=ph744dh892i53gwhnihz9fbkhs9ax5x1.narinfo error="server returned 404: 404 page not found\n"1752--- PASS: TestPresentReportsOnlyClosureRoots (0.34s)1753=== CONT TestPushDedupSurvivesConcurrentGC17542026/10/25 19:48:02 INFO Completed push id=1 objects=4 duration=5.986708ms17552026/10/25 19:48:02 INFO Upload complete. (72ms)1756--- PASS: TestClientPushesUseOnePush (0.78s)1757=== CONT TestRegisterCompletedObjectNeedsPendingRow17582026/10/25 19:48:02 INFO Received push request method=POST path=/api/pushes1759--- PASS: TestClientSharedPathCommittedMidPush (0.69s)1760=== CONT TestLeadEndsOnShutdown1761=== CONT TestFailedS3DeleteKeepsTombstone1762--- PASS: TestClientFallsBackToClosures (0.81s)17632026/10/25 19:48:02 INFO Aborted multipart uploads count=0 kept=017642026/10/25 19:48:02 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17652026/10/25 19:48:02 INFO Uploading 9z7s45q7dn1qhsga7zmwnw31kgwjryh7-unpinned-file.txt (128B)17662026/10/25 19:48:02 WARN Force mode enabled - objects will be deleted immediately without grace period17672026/10/25 19:48:02 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"17682026/10/25 19:48:02 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=017692026/10/25 19:48:02 INFO Vacuumed table table=pending_closures17702026/10/25 19:48:02 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"17712026/10/25 19:48:02 INFO Received push request method=POST path=/api/pushes17722026/10/25 19:48:02 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign17732026/10/25 19:48:02 WARN Failed to register uploaded object key=9z7s45q7dn1qhsga7zmwnw31kgwjryh7.ls error="server returned 404: 404 page not found\n"17742026/10/25 19:48:02 INFO Vacuumed table table=pending_objects17752026/10/25 19:48:02 INFO Signed narinfos id=2 count=117762026/10/25 19:48:02 INFO Uploading 1 narinfos17772026/10/25 19:48:02 INFO Vacuumed table table=multipart_uploads1778--- PASS: TestService_AuthMiddleware (0.28s)1779=== CONT TestGCSweepDeliversEachKeyOnce17802026/10/25 19:48:02 INFO Vacuumed table table=closures17812026/10/25 19:48:02 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)17822026/10/25 19:48:02 INFO Uploading 36zni4v1dx9frz7d3pwnmgy2vrrwrwgc-test-file-0.txt (160B)17832026/10/25 19:48:02 INFO Uploading anfj6fi6jzfncv74w445lnjnzdx8k8hb-test-file-2.txt (160B)17842026/10/25 19:48:02 INFO Uploading wgxc287k7h869vsrl7wbjmbg47jm7842-test-file-1.txt (160B)17852026/10/25 19:48:02 INFO Vacuumed table table=objects1786=== NAME TestClientWithDependencies1787 client_integration_test.go:740: Skipping nix copy test - isolated store (/build/TestClientWithDependencies438745056/001/store) requires matching store prefix17882026/10/25 19:48:02 INFO Received complete push request method=POST path=/api/pushes/2/complete17892026/10/25 19:48:02 WARN Failed to register uploaded object key=9z7s45q7dn1qhsga7zmwnw31kgwjryh7.narinfo error="server returned 404: 404 page not found\n"17902026/10/25 19:48:02 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"17912026/10/25 19:48:02 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"17922026/10/25 19:48:02 INFO Completed push id=2 objects=3 duration=11.042255ms17932026/10/25 19:48:02 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"17942026/10/25 19:48:02 INFO Upload complete. (98ms)17952026/10/25 19:48:02 WARN Failed to register uploaded object key=36zni4v1dx9frz7d3pwnmgy2vrrwrwgc.ls error="server returned 404: 404 page not found\n"17962026/10/25 19:48:02 WARN Failed to register uploaded object key=wgxc287k7h869vsrl7wbjmbg47jm7842.ls error="server returned 404: 404 page not found\n"17972026/10/25 19:48:02 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17982026/10/25 19:48:02 WARN Failed to register uploaded object key=anfj6fi6jzfncv74w445lnjnzdx8k8hb.ls error="server returned 404: 404 page not found\n"17992026/10/25 19:48:02 INFO Signed narinfos id=1 count=318002026/10/25 19:48:02 INFO Uploading 3 narinfos1801--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (0.95s)1802=== CONT TestSweepSkipsRowsLockedByPush1803=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded1804--- PASS: TestClientWithDependencies (0.74s)18052026/10/25 19:48:02 WARN Failed to register uploaded object key=36zni4v1dx9frz7d3pwnmgy2vrrwrwgc.narinfo error="server returned 404: 404 page not found\n"18062026/10/25 19:48:02 INFO Received complete push request method=POST path=/api/pushes/1/complete18072026/10/25 19:48:02 WARN Failed to register uploaded object key=anfj6fi6jzfncv74w445lnjnzdx8k8hb.narinfo error="server returned 404: 404 page not found\n"18082026/10/25 19:48:02 WARN Failed to register uploaded object key=wgxc287k7h869vsrl7wbjmbg47jm7842.narinfo error="server returned 404: 404 page not found\n"18092026/10/25 19:48:02 INFO Completed push id=1 objects=9 duration=10.474386ms18102026/10/25 19:48:02 INFO Upload complete. (95ms)1811=== NAME TestClientMultipleUploads1812 client_integration_test.go:478: Uploaded 3 paths in 126.90294ms18132026/10/25 19:48:02 INFO Starting cleanup of old closures method=DELETE path=/api/closures18142026/10/25 19:48:02 INFO Garbage collection started1815--- PASS: TestReadProxyContentNegotiation (0.99s)1816=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection18172026/10/25 19:48:02 INFO Aborted multipart uploads count=0 kept=018182026/10/25 19:48:02 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1819=== CONT TestGracefulShutdownDrainsInflight1820--- PASS: TestClientMultipleUploads (0.61s)18212026/10/25 19:48:02 INFO Starting HTTP server address=127.0.0.1:3911118222026/10/25 19:48:02 WARN Force mode enabled - objects will be deleted immediately without grace period18232026/10/25 19:48:02 INFO Shutdown signal received, draining in-flight requests timeout=10s18242026/10/25 19:48:02 INFO Received create pin request method=POST path=/api/pins/app18252026/10/25 19:48:02 INFO Completed multipart upload object_key=nar/dddddddddddddddddddddddddddddddd00000000000000000000.nar.zst upload_id=ZTdjMDA0N2MtM2VjOC00MWU2LTg5NGYtNDMzYWYyOTIwZDA1LmFmMWQwNjJkLTVhYWQtNDc5OC1hMmM1LWRhZDg4MTA4NWZkY3gxNzkyOTU3NjgwODkxMzUzOTI0 parts=1018262026/10/25 19:48:02 INFO Created/updated pin name=app store_path=/nix/store/cccccccccccccccccccccccccccccccc-app narinfo_key=cccccccccccccccccccccccccccccccc.narinfo18272026/10/25 19:48:02 INFO Received delete pin request method=DELETE path=/api/pins/app18282026/10/25 19:48:02 ERROR Failed to delete pin from S3 key=pins/app error="Get \"http://127.0.0.1:1/bucket79/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"1829=== NAME TestNARDeduplicationMetadataUploadBug1830 metadata_upload_test.go:48: First store path: /build/TestNARDeduplicationMetadataUploadBug2242570024/001/store/grx99c9qi713yb2w9simrdkil9nx5jcd-file1.txt18312026/10/25 19:48:02 INFO Received delete pin request method=DELETE path=/api/pins/app18322026/10/25 19:48:02 INFO Received push request method=POST path=/api/pushes18332026/10/25 19:48:02 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=018342026/10/25 19:48:02 INFO Deleted pin name=app18352026/10/25 19:48:02 INFO Vacuumed table table=pending_closures18362026/10/25 19:48:02 INFO Vacuumed table table=pending_objects18372026/10/25 19:48:02 INFO Vacuumed table table=multipart_uploads18382026/10/25 19:48:02 INFO Vacuumed table table=closures18392026/10/25 19:48:02 INFO Vacuumed table table=objects1840--- PASS: TestDeletePinKeepsRowWhenS3Fails (0.29s)1841=== CONT TestMetricsInventory1842=== CONT TestDeduplicatedObjectsRecordedAsPending1843--- PASS: TestGracefulShutdownDrainsInflight (0.07s)18442026/10/25 19:48:02 INFO Aborted multipart uploads count=0 kept=018452026/10/25 19:48:02 WARN Force mode enabled - objects will be deleted immediately without grace period18462026/10/25 19:48:02 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=018472026/10/25 19:48:02 INFO Vacuumed table table=pending_closures18482026/10/25 19:48:02 INFO Vacuumed table table=pending_objects18492026/10/25 19:48:02 INFO Vacuumed table table=multipart_uploads18502026/10/25 19:48:02 INFO Vacuumed table table=closures18512026/10/25 19:48:02 INFO Vacuumed table table=objects18522026/10/25 19:48:02 INFO Received push request method=POST path=/api/pushes18532026/10/25 19:48:02 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18542026/10/25 19:48:02 INFO Uploading grx99c9qi713yb2w9simrdkil9nx5jcd-file1.txt (160B)18552026/10/25 19:48:02 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"18562026/10/25 19:48:02 INFO Received uploads request method=POST path=/api/pending_closures18572026/10/25 19:48:02 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18582026/10/25 19:48:02 WARN Failed to register uploaded object key=grx99c9qi713yb2w9simrdkil9nx5jcd.ls error="server returned 404: 404 page not found\n"18592026/10/25 19:48:02 INFO Signed narinfos id=1 count=118602026/10/25 19:48:02 INFO Uploading 1 narinfos18612026/10/25 19:48:02 INFO Received complete push request method=POST path=/api/pushes/1/complete18622026/10/25 19:48:02 WARN Failed to register uploaded object key=grx99c9qi713yb2w9simrdkil9nx5jcd.narinfo error="server returned 404: 404 page not found\n"1863=== CONT TestTombstonedObjectOfferedWithoutWaiting1864--- PASS: TestRegisterCompletedObjectNeedsPendingRow (0.25s)18652026/10/25 19:48:02 INFO Completed push id=1 objects=3 duration=6.340557ms18662026/10/25 19:48:02 INFO Upload complete. (73ms)1867=== NAME TestNARDeduplicationMetadataUploadBug1868 metadata_upload_test.go:54: Retrieved narinfo from S3:1869 StorePath: /build/TestNARDeduplicationMetadataUploadBug2242570024/001/store/grx99c9qi713yb2w9simrdkil9nx5jcd-file1.txt1870 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1871 Compression: zstd1872 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1873 NarSize: 1601874 References: 1875 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf18762026/10/25 19:48:02 INFO lead: acquired remote=192.0.2.1:12341877 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1878 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1879 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}1880--- PASS: TestGCMetrics (0.29s)1881=== CONT TestPendingCleanupUsesOneCutoff18822026/10/25 19:48:02 INFO Received uploads request method=POST path=/api/pending_closures1883=== NAME TestNARDeduplicationMetadataUploadBug1884 metadata_upload_test.go:64: Second store path (same content): /build/TestNARDeduplicationMetadataUploadBug2242570024/001/store/npp87ifjn4pszyh7z1z27ybinp5b9dg3-file2.txt18852026/10/25 19:48:02 INFO Aborted multipart uploads count=0 kept=018862026/10/25 19:48:02 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=018872026/10/25 19:48:02 INFO Vacuumed table table=pending_closures18882026/10/25 19:48:02 INFO Vacuumed table table=pending_objects18892026/10/25 19:48:02 INFO Vacuumed table table=multipart_uploads18902026/10/25 19:48:02 INFO Vacuumed table table=closures18912026/10/25 19:48:02 INFO Vacuumed table table=objects18922026/10/25 19:48:02 INFO Received uploads request method=POST path=/api/pending_closures18932026/10/25 19:48:02 INFO Aborted multipart uploads count=0 kept=018942026/10/25 19:48:02 WARN Force mode enabled - objects will be deleted immediately without grace period18952026/10/25 19:48:02 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=018962026/10/25 19:48:02 INFO Received push request method=POST path=/api/pushes18972026/10/25 19:48:02 INFO Aborted multipart uploads count=0 kept=018982026/10/25 19:48:02 INFO Vacuumed table table=pending_closures18992026/10/25 19:48:02 INFO Aborted multipart uploads count=0 kept=019002026/10/25 19:48:02 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)19012026/10/25 19:48:02 INFO Vacuumed table table=pending_objects19022026/10/25 19:48:02 INFO Vacuumed table table=multipart_uploads19032026/10/25 19:48:02 WARN Force mode enabled - objects will be deleted immediately without grace period19042026/10/25 19:48:02 WARN Force mode enabled - objects will be deleted immediately without grace period19052026/10/25 19:48:02 INFO Vacuumed table table=closures19062026/10/25 19:48:02 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=019072026/10/25 19:48:02 INFO Vacuumed table table=pending_closures19082026/10/25 19:48:02 INFO Vacuumed table table=pending_objects19092026/10/25 19:48:02 INFO Vacuumed table table=objects19102026/10/25 19:48:02 INFO Vacuumed table table=multipart_uploads19112026/10/25 19:48:02 INFO Vacuumed table table=closures19122026/10/25 19:48:02 INFO Vacuumed table table=objects19132026/10/25 19:48:02 INFO Aborted multipart uploads count=0 kept=019142026/10/25 19:48:02 INFO Received uploads request method=POST path=/api/pending_closures19152026/10/25 19:48:02 INFO Aborted multipart uploads count=0 kept=019162026/10/25 19:48:02 WARN Force mode enabled - objects will be deleted immediately without grace period19172026/10/25 19:48:02 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign19182026/10/25 19:48:02 WARN Failed to register uploaded object key=npp87ifjn4pszyh7z1z27ybinp5b9dg3.ls error="server returned 404: 404 page not found\n"19192026/10/25 19:48:02 INFO Signed narinfos id=2 count=119202026/10/25 19:48:02 INFO Uploading 1 narinfos19212026/10/25 19:48:02 WARN Force mode enabled - objects will be deleted immediately without grace period1922--- PASS: TestPushDedupSurvivesConcurrentGC (0.38s)1923=== CONT TestClientErrorHandling1924=== RUN TestClientErrorHandling/InvalidStorePath1925=== PAUSE TestClientErrorHandling/InvalidStorePath1926=== RUN TestClientErrorHandling/InvalidAuthToken1927=== PAUSE TestClientErrorHandling/InvalidAuthToken1928=== RUN TestClientErrorHandling/ServerNotAvailable1929=== PAUSE TestClientErrorHandling/ServerNotAvailable1930=== CONT TestGCSweepSkipsPendingObjects19312026/10/25 19:48:02 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."19322026/10/25 19:48:02 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."19332026/10/25 19:48:02 INFO Received complete push request method=POST path=/api/pushes/2/complete19342026/10/25 19:48:02 WARN Failed to register uploaded object key=npp87ifjn4pszyh7z1z27ybinp5b9dg3.narinfo error="server returned 404: 404 page not found\n"19352026/10/25 19:48:02 INFO Completed push id=2 objects=3 duration=1.500939ms19362026/10/25 19:48:02 INFO Upload complete. (66ms)1937=== CONT TestProxyWriteTimeout/1_GiB_nar1938--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (0.31s)1939=== CONT TestProxyWriteTimeout/10_GiB_nar1940=== CONT TestProxyWriteTimeout/unknown_size1941=== CONT TestProxyWriteTimeout/narinfo1942=== CONT TestPendingClosureWriteTimeout/empty1943--- PASS: TestProxyWriteTimeout (0.01s)1944 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1945 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1946 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1947 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1948=== CONT TestPendingClosureWriteTimeout/400_objects1949=== NAME TestNARDeduplicationMetadataUploadBug1950 metadata_upload_test.go:76: Retrieved narinfo from S3:1951 StorePath: /build/TestNARDeduplicationMetadataUploadBug2242570024/001/store/npp87ifjn4pszyh7z1z27ybinp5b9dg3-file2.txt1952 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1953 Compression: zstd1954 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1955 NarSize: 1601956 References: 1957 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1958=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline19592026/10/25 19:48:02 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=019602026/10/25 19:48:02 INFO Vacuumed table table=pending_closures19612026/10/25 19:48:02 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"19622026/10/25 19:48:02 INFO Vacuumed table table=pending_objects1963=== NAME TestNARDeduplicationMetadataUploadBug19642026/10/25 19:48:02 INFO Vacuumed table table=multipart_uploads1965 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1966 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1967 {"version":1,"root":{"type":"regular","size":44}}19682026/10/25 19:48:02 INFO Vacuumed table table=closures19692026/10/25 19:48:02 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=019702026/10/25 19:48:02 INFO Vacuumed table table=pending_closures19712026/10/25 19:48:02 INFO Vacuumed table table=pending_objects19722026/10/25 19:48:02 INFO Vacuumed table table=multipart_uploads19732026/10/25 19:48:02 INFO Vacuumed table table=closures19742026/10/25 19:48:02 INFO Vacuumed table table=objects19752026/10/25 19:48:02 INFO Vacuumed table table=objects1976--- PASS: TestFailedS3DeleteKeepsTombstone (0.40s)1977=== CONT TestPendingClosureWriteTimeout/670k_objects1978=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key19792026/10/25 19:48:02 INFO Received complete multipart upload request method=POST path=/1980=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key19812026/10/25 19:48:02 INFO Received request for more parts method=POST path=/1982=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal19832026/10/25 19:48:02 INFO Received uploads request method=POST path=/1984=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info19852026/10/25 19:48:02 INFO Received uploads request method=POST path=/1986=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts1987--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1988 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1989 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1990 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1991 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)19922026/10/25 19:48:02 INFO Received request for more parts method=POST path=/1993--- PASS: TestGCSweepDeliversEachKeyOnce (0.37s)1994=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart19952026/10/25 19:48:02 INFO Received complete multipart upload request method=POST path=/1996--- PASS: TestSweepSkipsRowsLockedByPush (0.34s)1997=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure19982026/10/25 19:48:02 INFO Received uploads request method=POST path=/1999--- PASS: TestNARDeduplicationMetadataUploadBug (0.53s)2000=== CONT TestPush_RejectsBadRequests/no_objects20012026/10/25 19:48:02 INFO Received push request method=POST path=/api/pushes2002=== CONT TestPush_RejectsBadRequests/bad_root20032026/10/25 19:48:02 INFO Received push request method=POST path=/api/pushes2004=== CONT TestPush_RejectsBadRequests/no_roots2005=== CONT TestPush_RejectsBadRequests/root_not_in_objects20062026/10/25 19:48:02 INFO Received push request method=POST path=/api/pushes2007--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.49s)2008=== CONT TestParseSingleRange/unknown_unit20092026/10/25 19:48:02 INFO Received push request method=POST path=/api/pushes2010=== CONT TestParseSingleRange/start_far_past_EOF2011=== CONT TestParseSingleRange/start_past_EOF2012=== CONT TestParseSingleRange/closed2013=== CONT TestParseSingleRange/single_byte2014=== CONT TestParseSingleRange/suffix2015=== CONT TestParseSingleRange/end_clamped_to_size2016=== CONT TestParseSingleRange/suffix_exceeds_size2017=== CONT TestParseSingleRange/open-ended2018=== CONT TestParseSingleRange/malformed_end_before_start2019=== CONT TestParseSingleRange/malformed_both_empty2020=== CONT TestParseSingleRange/multi-range_ignored2021=== CONT TestParseSingleRange/malformed_no_dash2022=== CONT TestParseSingleRange/none2023=== CONT TestServerTLSConfig/missing_CA_file2024=== CONT TestServerTLSConfig/not_a_PEM_file2025=== CONT TestServerTLSConfig/no_client_CA2026=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows2027--- PASS: TestParseSingleRange (0.00s)2028 --- PASS: TestParseSingleRange/unknown_unit (0.00s)2029 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)2030 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)2031 --- PASS: TestParseSingleRange/closed (0.00s)2032 --- PASS: TestParseSingleRange/single_byte (0.00s)2033 --- PASS: TestParseSingleRange/suffix (0.00s)2034 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)2035 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)2036 --- PASS: TestParseSingleRange/open-ended (0.00s)2037 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)2038 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)2039 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)2040 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)2041 --- PASS: TestParseSingleRange/none (0.00s)2042=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check2043--- PASS: TestServerTLSConfig (0.00s)2044 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)2045 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)2046 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)20472026/10/25 19:48:02 INFO Received uploads request method=POST path=/api/pending_closures20482026/10/25 19:48:02 INFO Received uploads request method=POST path=/api/pending_closures2049--- PASS: TestMetricsInventory (0.28s)2050=== CONT TestGCEndsOnShutdown/before_the_run20512026/10/25 19:48:02 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>20522026/10/25 19:48:02 INFO Received uploads request method=POST path=/api/pending_closures20532026/10/25 19:48:02 INFO Received cleanup request method=DELETE path=/api/pending_closures2054--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (0.52s)2055=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark2056--- PASS: TestDeduplicatedObjectsRecordedAsPending (0.44s)2057=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete2058--- PASS: TestPush_RejectsBadRequests (0.78s)2059 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)2060 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)2061 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)2062 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)2063--- PASS: TestReadProxyNarinfo (1.32s)2064=== CONT TestIsValidUploadKey/unknown_type2065=== CONT TestIsValidUploadKey/build_log_equals2066=== CONT TestIsValidUploadKey/nar_plain2067=== CONT TestIsValidUploadKey/realisation2068=== CONT TestIsValidUploadKey/traversal_nar2069=== CONT TestIsValidUploadKey/index.html2070=== CONT TestIsValidUploadKey/build_log_question_mark2071=== CONT TestIsValidUploadKey/nar_xz2072=== CONT TestIsValidUploadKey/empty_key2073=== CONT TestIsValidUploadKey/realisation_plus_in_output2074=== CONT TestIsValidUploadKey/narinfo2075=== CONT TestIsValidUploadKey/nar_zst2076=== CONT TestIsValidUploadKey/listing_key,_narinfo_type2077=== CONT TestIsValidUploadKey/build_log_plus_in_name2078=== CONT TestIsValidUploadKey/narinfo_key,_nar_type2079=== CONT TestIsValidUploadKey/build_log_home-manager_file2080=== CONT TestIsValidUploadKey/nix-cache-info2081=== CONT TestIsValidUploadKey/build_log2082=== CONT TestIsValidUploadKey/listing2083=== CONT TestIsValidUploadKey/nar_key,_narinfo_type2084=== CONT TestIsValidUploadKey/traversal2085=== CONT TestIsValidUploadKey/absolute2086=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale2087--- PASS: TestIsValidUploadKey (0.00s)2088 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)2089 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)2090 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)2091 --- PASS: TestIsValidUploadKey/realisation (0.00s)2092 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)2093 --- PASS: TestIsValidUploadKey/index.html (0.00s)2094 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)2095 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)2096 --- PASS: TestIsValidUploadKey/empty_key (0.00s)2097 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)2098 --- PASS: TestIsValidUploadKey/narinfo (0.00s)2099 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)2100 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)2101 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)2102 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)2103 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)2104 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)2105 --- PASS: TestIsValidUploadKey/build_log (0.00s)2106 --- PASS: TestIsValidUploadKey/listing (0.00s)2107 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)2108 --- PASS: TestIsValidUploadKey/traversal (0.00s)2109 --- PASS: TestIsValidUploadKey/absolute (0.00s)21102026/10/25 19:48:02 INFO Received uploads request method=POST path=/api/pending_closures21112026/10/25 19:48:02 INFO Received uploads request method=POST path=/api/pending_closures21122026/10/25 19:48:02 INFO Received complete multipart upload request method=POST path=/api/multipart/complete2113--- PASS: TestTombstonedObjectOfferedWithoutWaiting (0.43s)21142026/10/25 19:48:02 INFO Received complete multipart upload request method=POST path=/api/multipart/complete2115=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh21162026/10/25 19:48:02 INFO Completed multipart upload object_key=nar/ffffffffffffffffffffffffffffffff00000000000000000000.nar.zst upload_id=ZTdjMDA0N2MtM2VjOC00MWU2LTg5NGYtNDMzYWYyOTIwZDA1LmRkODZiMzc1LWQwNWItNDgxNi1iZWU2LTc0MGI3OGE2MTMxMXgxNzkyOTU3NjgwODkxNzEzNzc0 parts=1021172026/10/25 19:48:02 INFO Received uploads request method=POST path=/api/pending_closures21182026/10/25 19:48:02 INFO lead: released remote=192.0.2.1:123421192026/10/25 19:48:02 INFO Aborted multipart uploads count=0 kept=021202026/10/25 19:48:02 WARN Force mode enabled - objects will be deleted immediately without grace period21212026/10/25 19:48:02 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=021222026/10/25 19:48:02 INFO Vacuumed table table=pending_closures21232026/10/25 19:48:02 INFO Completed multipart upload object_key=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa00000000000000000000.nar.zst upload_id=ZTdjMDA0N2MtM2VjOC00MWU2LTg5NGYtNDMzYWYyOTIwZDA1LmFmMzYyZGEyLWZmNjQtNDQ5OC05NTc2LWQ2NTA5MzEzNWIzM3gxNzkyOTU3NjgyNDAyMzAwNTUz parts=1021242026/10/25 19:48:02 INFO Vacuumed table table=pending_objects21252026/10/25 19:48:02 INFO Vacuumed table table=multipart_uploads21262026/10/25 19:48:02 INFO Vacuumed table table=closures21272026/10/25 19:48:02 INFO Received uploads request method=POST path=/api/pending_closures21282026/10/25 19:48:02 INFO Vacuumed table table=objects2129--- PASS: TestLeadElectsOneAndHandsOver (2.85s)2130=== CONT TestCacheConfigHandler/no_cache_url_configured2131=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2132=== CONT TestCacheConfigHandler/full_config,_no_issuer2133=== CONT TestCacheConfigHandler/no_signing_keys2134=== CONT TestResolveDBConnectionString/flag_wins2135--- PASS: TestCacheConfigHandler (0.00s)2136 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)2137 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)2138 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)2139 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)2140=== CONT TestResolveDBConnectionString/missing_file_is_an_error2141=== CONT TestResolveDBConnectionString/file_when_flag_empty2142=== CONT TestResolveDBConnectionString/nothing_configured2143=== CONT TestResolveDBConnectionString/PGHOST_allows_empty2144=== CONT TestIsValidCachePath/nar_xz2145=== CONT TestIsValidCachePath/nix-cache-info2146=== CONT TestIsValidCachePath/short_hash2147=== CONT TestIsValidCachePath/leading_slash2148=== CONT TestIsValidCachePath/wrong_extension2149=== CONT TestIsValidCachePath/empty2150=== CONT TestIsValidCachePath/invalid_char_u2151--- PASS: TestResolveDBConnectionString (0.00s)2152 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)2153 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)2154 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)2155 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)2156 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)2157=== CONT TestIsValidCachePath/invalid_char_e2158=== CONT TestIsValidCachePath/traversal_in_middle2159=== CONT TestIsValidCachePath/nar_bz22160=== CONT TestIsValidCachePath/random_path2161=== CONT TestIsValidCachePath/traversal_parent2162=== CONT TestIsValidCachePath/index.html2163=== CONT TestIsValidCachePath/nar_uncompressed2164=== CONT TestIsValidCachePath/log2165=== CONT TestIsValidCachePath/realisation2166=== CONT TestIsValidCachePath/ls2167=== CONT TestIsValidCachePath/nar_zst2168=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars2169=== CONT TestIsValidCachePath/narinfo2170=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2171--- PASS: TestIsValidCachePath (0.00s)2172 --- PASS: TestIsValidCachePath/nar_xz (0.00s)2173 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)2174 --- PASS: TestIsValidCachePath/short_hash (0.00s)2175 --- PASS: TestIsValidCachePath/leading_slash (0.00s)2176 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)2177 --- PASS: TestIsValidCachePath/empty (0.00s)2178 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)2179 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)2180 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)2181 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)2182 --- PASS: TestIsValidCachePath/random_path (0.00s)2183 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)2184 --- PASS: TestIsValidCachePath/index.html (0.00s)2185 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)2186 --- PASS: TestIsValidCachePath/log (0.00s)2187 --- PASS: TestIsValidCachePath/realisation (0.00s)2188 --- PASS: TestIsValidCachePath/ls (0.00s)2189 --- PASS: TestIsValidCachePath/nar_zst (0.00s)2190 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)2191 --- PASS: TestIsValidCachePath/narinfo (0.00s)2192=== CONT TestService_RequireScope_OIDC/static_token_may_write2193=== CONT TestService_RequireScope_OIDC/reader_may_read21942026/10/25 19:48:02 INFO Aborted multipart uploads count=0 kept=02195=== CONT TestService_RequireScope_OIDC/static_token_may_admin2196=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read2197=== CONT TestService_RequireScope_OIDC/ops_may_not_write2198=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc2199=== CONT TestService_RequireScope_OIDC/ops_may_admin2200=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc2201=== CONT TestService_RequireScope_OIDC/reader_may_not_write2202=== CONT TestService_RequireScope_OIDC/writer_implies_read22032026/10/25 19:48:02 WARN Force mode enabled - objects will be deleted immediately without grace period2204=== CONT TestService_RequireScope_OIDC/builder_may_write2205=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2206=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read22072026/10/25 19:48:02 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]2208=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token22092026/10/25 19:48:02 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=022102026/10/25 19:48:02 INFO Received uploads request method=POST path=/api/pending_closures2211--- PASS: TestGCSweepSkipsPendingObjects (0.37s)2212=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2213=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2214=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected22152026/10/25 19:48:02 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]2216=== CONT TestPendingClosureFailureTracksEveryUpload/refuse_aborts=false22172026/10/25 19:48:02 INFO Vacuumed table table=pending_closures22182026/10/25 19:48:03 INFO Aborted multipart uploads count=0 kept=022192026/10/25 19:48:03 WARN Authentication failed token_preview=eyJhbGciOi...LbR23CnWkA token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]22202026/10/25 19:48:03 INFO Vacuumed table table=pending_objects2221=== CONT TestPendingClosureFailureTracksEveryUpload/refuse_aborts=true22222026/10/25 19:48:03 INFO Vacuumed table table=multipart_uploads22232026/10/25 19:48:03 INFO Vacuumed table table=closures22242026/10/25 19:48:03 WARN Force mode enabled - objects will be deleted immediately without grace period22252026/10/25 19:48:03 INFO Vacuumed table table=objects2226--- PASS: TestService_RequireScope_OIDC (0.50s)2227 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2228 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2229 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2230 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2231 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)2232 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2233 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)2234 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2235 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)2236 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2237 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2238 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2239 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2240 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)2241--- PASS: TestService_AuthMiddleware_OIDC (0.41s)2242 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2243 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2244 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2245 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)2246--- PASS: TestDeleteClosuresRacingPins (1.60s)2247=== CONT TestClientErrorHandling/InvalidAuthToken2248=== CONT TestClientErrorHandling/ServerNotAvailable2249=== CONT TestClientErrorHandling/InvalidStorePath22502026/10/25 19:48:03 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=022512026/10/25 19:48:03 INFO Vacuumed table table=pending_closures22522026/10/25 19:48:03 INFO Vacuumed table table=pending_objects22532026/10/25 19:48:03 INFO Vacuumed table table=multipart_uploads22542026/10/25 19:48:03 INFO Vacuumed table table=closures22552026/10/25 19:48:03 INFO Vacuumed table table=objects22562026-10-25 19:48:03.065 UTC [180] LOG: checkpoints are occurring too frequently (10 seconds apart)22572026-10-25 19:48:03.065 UTC [180] HINT: Consider increasing the configuration parameter "max_wal_size".22582026-10-25 19:48:03.065 UTC [180] LOG: checkpoint starting: wal22592026/10/25 19:48:03 INFO Aborted multipart uploads count=0 kept=022602026/10/25 19:48:03 WARN Force mode enabled - objects will be deleted immediately without grace period2261--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2262 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (0.36s)2263 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (0.43s)22642026/10/25 19:48:03 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present22652026/10/25 19:48:03 INFO Aborted multipart uploads count=0 kept=022662026/10/25 19:48:03 WARN Force mode enabled - objects will be deleted immediately without grace period22672026/10/25 19:48:03 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:42519/bucket103/?delete=\": context canceled"2268--- PASS: TestGCEndsOnShutdown (0.00s)2269 --- PASS: TestGCEndsOnShutdown/before_the_run (0.32s)2270 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (0.23s)2271 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (0.27s)22722026/10/25 19:48:03 INFO Received uploads request method=POST path=/api/pending_closures22732026/10/25 19:48:03 INFO Received uploads request method=POST path=/api/pending_closures22742026/10/25 19:48:03 WARN Request failed, retrying attempt=2 backoff=209.258471ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present22752026/10/25 19:48:03 WARN Request failed, retrying attempt=3 backoff=390.615635ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present22762026/10/25 19:48:03 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"2277=== NAME TestOrphanedObjectsGCStressTest2278 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains22792026/10/25 19:48:03 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"2280 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion22812026/10/25 19:48:03 INFO lead: released remote=192.0.2.1:12342282--- PASS: TestLeadEndsOnShutdown (1.37s)22832026/10/25 19:48:03 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=2 objects_marked=6 objects_deleted=6 objects_failed=02284=== NAME TestClientIntegration2285 client_integration_test.go:432: Objects in database after GC:2286 client_integration_test.go:432: Successfully deleted all objects with GC --force2287--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2288 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (0.72s)2289 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (0.74s)2290--- PASS: TestClientIntegration (3.24s)22912026/10/25 19:48:03 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22922026/10/25 19:48:03 WARN Failed to abort multipart upload key=nar/ssssssssssssssssssssssssssssssssssssssssssssssssssss.nar.zst upload_id=ZTdjMDA0N2MtM2VjOC00MWU2LTg5NGYtNDMzYWYyOTIwZDA1LjRjMzY3NmRkLWU3MWItNGYxOS1iMjgwLTdmZThhMTRkZTY2ZXgxNzkyOTU3NjgzMTczODI4MTI3 error="Access Denied"22932026/10/25 19:48:03 WARN keeping failed pending closure for cleanup to retry the abort id=122942026/10/25 19:48:03 INFO Completed multipart upload object_key=nar/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb00000000000000000000.nar.zst upload_id=ZTdjMDA0N2MtM2VjOC00MWU2LTg5NGYtNDMzYWYyOTIwZDA1LmNmMjY0ZTVjLWQ0MDQtNDlkNi1hNmQyLTY1NTczYTAyZjRjN3gxNzkyOTU3NjgwODkwODk1NzY0 parts=1022952026/10/25 19:48:03 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22962026/10/25 19:48:03 INFO Completed multipart upload object_key=nar/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb00000000000000000000.nar.zst upload_id=ZTdjMDA0N2MtM2VjOC00MWU2LTg5NGYtNDMzYWYyOTIwZDA1LjI0NWM3NjllLTY0NWUtNDAwNS1hYTc0LTMyYmNiZjQ4YjUxOXgxNzkyOTU3NjgyNDAxNDg5MTc0 parts=1022972026/10/25 19:48:03 INFO Received complete push request method=POST path=/api/pushes/1/complete22982026/10/25 19:48:03 INFO Completed push id=1 objects=4 duration=3.733258ms22992026/10/25 19:48:03 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete23002026/10/25 19:48:03 INFO Completed upload id=2 objects=2 duration=741.95µs2301--- PASS: TestPendingClosureFailureTracksEveryUpload (0.00s)2302 --- PASS: TestPendingClosureFailureTracksEveryUpload/refuse_aborts=true (0.70s)2303 --- PASS: TestPendingClosureFailureTracksEveryUpload/refuse_aborts=false (0.73s)2304--- PASS: TestPendingClosureWriteTimeout (0.00s)2305 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2306 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2307 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2308 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (1.10s)2309--- PASS: TestMetricsCommit (1.59s)23102026/10/25 19:48:03 WARN Request failed, retrying attempt=4 backoff=802.864235ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present23112026/10/25 19:48:04 INFO Received complete multipart upload request method=POST path=/api/multipart/complete23122026/10/25 19:48:04 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggggg00000000000000000000.nar.zst upload_id=ZTdjMDA0N2MtM2VjOC00MWU2LTg5NGYtNDMzYWYyOTIwZDA1LmI4Y2NlN2JhLWE4NzEtNDIxOC1iZjYyLTc1ODJlYmUwMDhjM3gxNzkyOTU3NjgwODkxNTY3Mjc0 parts=1023132026-10-25 19:48:04.105 UTC [627] ERROR: could not obtain lock on row in relation "closures"23142026-10-25 19:48:04.105 UTC [627] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT23152026-10-25 19:48:04.106 UTC [627] ERROR: could not obtain lock on row in relation "closures"23162026-10-25 19:48:04.106 UTC [627] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT23172026-10-25 19:48:04.106 UTC [627] ERROR: could not obtain lock on row in relation "closures"23182026-10-25 19:48:04.106 UTC [627] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT23192026-10-25 19:48:04.106 UTC [627] ERROR: could not obtain lock on row in relation "closures"23202026-10-25 19:48:04.106 UTC [627] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT23212026-10-25 19:48:04.107 UTC [627] ERROR: could not obtain lock on row in relation "closures"23222026-10-25 19:48:04.107 UTC [627] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT2323--- PASS: TestPush_RootsAreLockedInByteOrder (3.66s)23242026/10/25 19:48:04 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=023252026/10/25 19:48:04 INFO Received create pin request method=POST path=/api/pins/myapp23262026/10/25 19:48:04 INFO Created/updated pin name=myapp store_path=/build/TestPinProtectsFromGC1833250761/001/store/xwrynsxjcsj8w1mg2a9lvbys9db32n0d-pinned-file.txt narinfo_key=xwrynsxjcsj8w1mg2a9lvbys9db32n0d.narinfo23272026/10/25 19:48:04 INFO Starting cleanup of old closures method=DELETE path=/api/closures23282026/10/25 19:48:04 INFO Garbage collection started23292026/10/25 19:48:04 INFO Aborted multipart uploads count=0 kept=023302026/10/25 19:48:04 WARN Force mode enabled - objects will be deleted immediately without grace period23312026/10/25 19:48:04 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=023322026/10/25 19:48:04 INFO Vacuumed table table=pending_closures23332026/10/25 19:48:04 INFO Vacuumed table table=pending_objects23342026/10/25 19:48:04 INFO Vacuumed table table=multipart_uploads23352026/10/25 19:48:04 INFO Vacuumed table table=closures23362026/10/25 19:48:04 INFO Vacuumed table table=objects23372026/10/25 19:48:04 WARN Request failed, retrying attempt=5 backoff=1.738442195s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2338=== NAME TestOrphanedObjectsGCStressTest2339 orphaned_objects_gc_test.go:503: Stress test completed successfully:2340 orphaned_objects_gc_test.go:504: - Active objects preserved: 202341 orphaned_objects_gc_test.go:505: - Objects deleted: 2102342 orphaned_objects_gc_test.go:506: - Total GC'd: 2102343--- PASS: TestOrphanedObjectsGCStressTest (4.16s)2344--- PASS: TestConnectWaitsForAPeerMigration (5.17s)2345--- PASS: TestReadProxyOutlastsServerWriteTimeout (4.59s)2346=== NAME TestPinProtectsFromGC2347 client_integration_test.go:963: Pin successfully protected closure from garbage collection23482026/10/25 19:48:06 WARN Request failed, retrying attempt=1 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2349--- PASS: TestPinProtectsFromGC (4.87s)23502026/10/25 19:48:06 WARN Request failed, retrying attempt=2 backoff=198.972236ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config23512026/10/25 19:48:06 WARN Rate limiter enabled after throttle name=s3-test rate=523522026/10/25 19:48:06 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."2353=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle2354 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=102355 throttle_test.go:215: Rate limiter: enabled=true, rate=5.002356--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (6.16s)23572026/10/25 19:48:06 WARN Request failed, retrying attempt=3 backoff=413.112028ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config23582026/10/25 19:48:07 WARN Request failed, retrying attempt=4 backoff=841.286683ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config23592026/10/25 19:48:07 WARN Request failed, retrying attempt=5 backoff=1.669613169s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2360--- PASS: TestUploadHandlersRejectOversizedBody (0.48s)2361 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.55s)2362 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.57s)2363 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (6.06s)23642026/10/25 19:48:08 INFO Aborted multipart uploads count=1 kept=023652026/10/25 19:48:08 INFO Received cleanup request method=DELETE path=/api/pending_closures23662026/10/25 19:48:08 INFO Aborted multipart uploads count=1 kept=02367--- PASS: TestPendingCleanupUsesOneCutoff (6.36s)23682026/10/25 19:48:09 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"23692026/10/25 19:48:09 WARN Request failed, retrying attempt=1 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config23702026/10/25 19:48:09 WARN Request failed, retrying attempt=2 backoff=202.267694ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config23712026/10/25 19:48:09 WARN Request failed, retrying attempt=3 backoff=434.380216ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config23722026/10/25 19:48:10 WARN Request failed, retrying attempt=4 backoff=817.890167ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config23732026/10/25 19:48:11 WARN Request failed, retrying attempt=5 backoff=1.555631684s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config23742026/10/25 19:48:12 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures23752026/10/25 19:48:12 WARN Request failed, retrying attempt=2 backoff=207.558681ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures23762026/10/25 19:48:13 WARN Request failed, retrying attempt=3 backoff=366.55526ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures23772026/10/25 19:48:13 WARN Request failed, retrying attempt=4 backoff=728.06032ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures23782026/10/25 19:48:14 WARN Request failed, retrying attempt=5 backoff=1.485626653s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2379--- PASS: TestClientErrorHandling (0.00s)2380 --- PASS: TestClientErrorHandling/InvalidStorePath (0.24s)2381 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.52s)2382 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.61s)2383PASS2384{"timestamp":"2026-10-25T19:48:15.644474551Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:36500","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(138)"}2385{"timestamp":"2026-10-25T19:48:15.645132201Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:36492","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(143)"}23862026-10-25 19:48:15.938 UTC [175] LOG: received smart shutdown request23872026-10-25 19:48:16.060 UTC [175] LOG: background worker "logical replication launcher" (PID 185) exited with exit code 123882026-10-25 19:48:16.849 UTC [180] LOG: checkpoint complete: wrote 9548 buffers (58.3%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 33 recycled; write=13.179 s, sync=0.543 s, total=13.784 s; sync files=37079, longest=0.010 s, average=0.001 s; distance=533595 kB, estimate=533595 kB; lsn=0/229DC3D0, redo lsn=0/2207CB6023892026-10-25 19:48:16.851 UTC [180] LOG: shutting down23902026-10-25 19:48:16.852 UTC [180] LOG: checkpoint starting: shutdown immediate23912026-10-25 19:48:16.974 UTC [180] LOG: checkpoint complete: wrote 1082 buffers (6.6%), wrote 1 SLRU buffers; 0 WAL file(s) added, 0 removed, 0 recycled; write=0.021 s, sync=0.099 s, total=0.123 s; sync files=418, longest=0.001 s, average=0.001 s; distance=9598 kB, estimate=481195 kB; lsn=0/229DC448, redo lsn=0/229DC44823922026-10-25 19:48:17.046 UTC [175] LOG: database system is shut down2393Running OIDC tests...2394=== RUN TestAudienceForIssuer2395=== PAUSE TestAudienceForIssuer2396=== RUN TestHTTPClientForHasTimeouts2397=== PAUSE TestHTTPClientForHasTimeouts2398=== RUN TestGlobMatch2399=== PAUSE TestGlobMatch2400=== RUN TestValidateToken_ValidToken2401=== PAUSE TestValidateToken_ValidToken2402=== RUN TestValidateToken_WrongAudience2403=== PAUSE TestValidateToken_WrongAudience2404=== RUN TestValidateToken_Expired2405=== PAUSE TestValidateToken_Expired2406=== RUN TestValidateToken_BoundClaimsMismatch2407=== PAUSE TestValidateToken_BoundClaimsMismatch2408=== RUN TestValidateToken_BoundSubjectMismatch2409=== PAUSE TestValidateToken_BoundSubjectMismatch2410=== RUN TestValidateToken_MultipleProviders2411=== PAUSE TestValidateToken_MultipleProviders2412=== RUN TestValidateToken_NoMatchingProvider2413=== PAUSE TestValidateToken_NoMatchingProvider2414=== RUN TestValidateToken_KubernetesServiceAccount2415=== PAUSE TestValidateToken_KubernetesServiceAccount2416=== RUN TestNewValidator_KubernetesRequiresCA2417=== PAUSE TestNewValidator_KubernetesRequiresCA2418=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2419=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2420=== RUN TestPins_ReservedForMatchingRule2421=== PAUSE TestPins_ReservedForMatchingRule2422=== RUN TestPins_TopLevelShorthand2423=== PAUSE TestPins_TopLevelShorthand2424=== RUN TestPins_ConfigValidation2425=== PAUSE TestPins_ConfigValidation2426=== RUN TestScopes_LegacyProviderDefaultsToWrite2427=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2428=== RUN TestScopes_Rules2429=== PAUSE TestScopes_Rules2430=== RUN TestScopes_ConfigValidation2431=== PAUSE TestScopes_ConfigValidation2432=== CONT TestHTTPClientForHasTimeouts2433=== CONT TestValidateToken_KubernetesServiceAccount2434=== CONT TestNewValidator_KubernetesRequiresCA2435=== CONT TestValidateToken_BoundSubjectMismatch2436=== CONT TestValidateToken_WrongAudience2437=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2438=== CONT TestValidateToken_MultipleProviders2439=== CONT TestValidateToken_NoMatchingProvider2440=== CONT TestValidateToken_Expired2441=== CONT TestValidateToken_ValidToken2442=== CONT TestGlobMatch2443=== RUN TestGlobMatch/foo_foo2444=== PAUSE TestGlobMatch/foo_foo2445=== RUN TestGlobMatch/foo_bar2446=== PAUSE TestGlobMatch/foo_bar2447=== RUN TestGlobMatch/*_2448=== CONT TestAudienceForIssuer2449=== CONT TestPins_TopLevelShorthand2450=== CONT TestScopes_ConfigValidation2451=== CONT TestScopes_Rules2452=== CONT TestPins_ConfigValidation2453=== CONT TestPins_ReservedForMatchingRule2454=== CONT TestScopes_LegacyProviderDefaultsToWrite2455=== CONT TestValidateToken_BoundClaimsMismatch2456=== PAUSE TestGlobMatch/*_2457--- PASS: TestAudienceForIssuer (0.00s)2458=== RUN TestGlobMatch/*_anything2459=== PAUSE TestGlobMatch/*_anything2460=== RUN TestGlobMatch/foo*_foo2461=== PAUSE TestGlobMatch/foo*_foo2462=== RUN TestGlobMatch/foo*_foobar2463=== PAUSE TestGlobMatch/foo*_foobar2464=== RUN TestGlobMatch/foo*_bar2465=== PAUSE TestGlobMatch/foo*_bar2466=== RUN TestGlobMatch/*bar_bar2467=== PAUSE TestGlobMatch/*bar_bar2468=== RUN TestGlobMatch/*bar_foobar2469=== PAUSE TestGlobMatch/*bar_foobar2470=== RUN TestGlobMatch/*bar_foo2471=== PAUSE TestGlobMatch/*bar_foo2472=== RUN TestGlobMatch/foo*bar_foobar2473=== PAUSE TestGlobMatch/foo*bar_foobar2474=== RUN TestGlobMatch/foo*bar_foo123bar2475=== PAUSE TestGlobMatch/foo*bar_foo123bar2476=== RUN TestGlobMatch/foo*bar_foobarbaz2477=== PAUSE TestGlobMatch/foo*bar_foobarbaz2478=== RUN TestGlobMatch/*/*_foo/bar2479=== PAUSE TestGlobMatch/*/*_foo/bar2480=== RUN TestGlobMatch/*/*_foo2481=== PAUSE TestGlobMatch/*/*_foo2482=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2483=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2484=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02485=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02486=== RUN TestGlobMatch/refs/*/main_refs/heads/main2487=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2488=== RUN TestGlobMatch/fo?_foo2489=== PAUSE TestGlobMatch/fo?_foo2490=== RUN TestGlobMatch/fo?_fo2491=== PAUSE TestGlobMatch/fo?_fo2492=== RUN TestGlobMatch/fo?_fooo2493=== PAUSE TestGlobMatch/fo?_fooo2494=== RUN TestGlobMatch/?oo_foo2495=== PAUSE TestGlobMatch/?oo_foo2496=== RUN TestGlobMatch/?oo_boo2497=== PAUSE TestGlobMatch/?oo_boo2498=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2499=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2500=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2501=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2502=== CONT TestGlobMatch/foo_bar2503=== CONT TestGlobMatch/*/*_foo/bar2504--- PASS: TestScopes_ConfigValidation (0.01s)2505=== CONT TestGlobMatch/foo*bar_foobar2506--- PASS: TestPins_ConfigValidation (0.01s)2507=== CONT TestGlobMatch/fo?_foo2508=== CONT TestGlobMatch/fo?_fo2509=== CONT TestGlobMatch/refs/*/main_refs/heads/main2510=== CONT TestGlobMatch/*/*_foo2511=== CONT TestGlobMatch/?oo_boo2512=== CONT TestGlobMatch/foo_foo2513=== CONT TestGlobMatch/*_2514=== CONT TestGlobMatch/fo?_fooo2515=== CONT TestGlobMatch/foo*bar_foobarbaz2516=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2517=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2518=== CONT TestGlobMatch/foo*_bar2519=== CONT TestGlobMatch/*bar_foobar2520=== CONT TestGlobMatch/*bar_foo2521=== CONT TestGlobMatch/foo*bar_foo123bar2522=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02523=== CONT TestGlobMatch/*_anything2524=== CONT TestGlobMatch/foo*_foobar2525=== CONT TestGlobMatch/foo*_foo2526=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2527=== CONT TestGlobMatch/*bar_bar2528=== CONT TestGlobMatch/?oo_foo2529--- PASS: TestGlobMatch (0.01s)2530 --- PASS: TestGlobMatch/foo_bar (0.00s)2531 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2532 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2533 --- PASS: TestGlobMatch/fo?_foo (0.00s)2534 --- PASS: TestGlobMatch/fo?_fo (0.00s)2535 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2536 --- PASS: TestGlobMatch/*/*_foo (0.00s)2537 --- PASS: TestGlobMatch/?oo_boo (0.00s)2538 --- PASS: TestGlobMatch/foo_foo (0.00s)2539 --- PASS: TestGlobMatch/*_ (0.00s)2540 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2541 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2542 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2543 --- PASS: TestGlobMatch/foo*_bar (0.00s)2544 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2545 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2546 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2547 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2548 --- PASS: TestGlobMatch/*bar_foo (0.00s)2549 --- PASS: TestGlobMatch/*_anything (0.00s)2550 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2551 --- PASS: TestGlobMatch/foo*_foo (0.00s)2552 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2553 --- PASS: TestGlobMatch/*bar_bar (0.00s)2554 --- PASS: TestGlobMatch/?oo_foo (0.00s)25552026/10/25 19:48:20 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:36387/oidc2556--- PASS: TestValidateToken_WrongAudience (0.05s)25572026/10/25 19:48:20 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:46801/oidc2558--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.06s)25592026/10/25 19:48:20 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:44223/oidc25602026/10/25 19:48:20 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:44387/oidc2561--- PASS: TestPins_TopLevelShorthand (0.07s)2562--- PASS: TestValidateToken_ValidToken (0.08s)25632026/10/25 19:48:20 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:44207/oidc25642026/10/25 19:48:20 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:43607/oidc2565--- PASS: TestValidateToken_NoMatchingProvider (0.09s)2566--- PASS: TestScopes_Rules (0.09s)25672026/10/25 19:48:20 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:43233/oidc25682026/10/25 19:48:20 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:40467/oidc2569--- PASS: TestValidateToken_MultipleProviders (0.11s)25702026/10/25 19:48:20 http: TLS handshake error from 127.0.0.1:60872: remote error: tls: bad certificate2571--- PASS: TestNewValidator_KubernetesRequiresCA (0.12s)25722026/10/25 19:48:20 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:40787/oidc2573--- PASS: TestValidateToken_Expired (0.13s)25742026/10/25 19:48:20 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:37113/oidc2575--- PASS: TestValidateToken_BoundSubjectMismatch (0.14s)25762026/10/25 19:48:20 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232577--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.17s)25782026/10/25 19:48:20 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:36685/oidc2579--- PASS: TestValidateToken_BoundClaimsMismatch (0.18s)2580--- PASS: TestHTTPClientForHasTimeouts (0.20s)25812026/10/25 19:48:20 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:401872582--- PASS: TestValidateToken_KubernetesServiceAccount (0.21s)25832026/10/25 19:48:20 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:32823/oidc2584--- PASS: TestPins_ReservedForMatchingRule (0.23s)2585PASS2586Running hook tests...2587=== RUN TestSendPathsEmpty2588=== PAUSE TestSendPathsEmpty2589=== RUN TestQueueEnqueueAndFetch2590=== PAUSE TestQueueEnqueueAndFetch2591=== RUN TestQueueDeduplication2592=== PAUSE TestQueueDeduplication2593=== RUN TestQueueRemove2594=== PAUSE TestQueueRemove2595=== RUN TestQueueFetchBatchLimit2596=== PAUSE TestQueueFetchBatchLimit2597=== RUN TestQueueRetryMovesToBack2598=== PAUSE TestQueueRetryMovesToBack2599=== RUN TestQueueFetchRemoveLifecycle2600=== PAUSE TestQueueFetchRemoveLifecycle2601=== RUN TestQueueConcurrentWriters2602=== PAUSE TestQueueConcurrentWriters2603=== RUN TestQueueEnqueueWaitsOutSlowWriter2604=== PAUSE TestQueueEnqueueWaitsOutSlowWriter2605=== RUN TestQueueRemoveLargeClosure2606=== PAUSE TestQueueRemoveLargeClosure2607=== RUN TestServerClientIntegration2608--- PASS: TestServerClientIntegration (0.00s)2609=== RUN TestServerQueueError26102026/10/25 19:48:21 ERROR Failed to queue paths error="permission denied" count=12611--- PASS: TestServerQueueError (0.00s)2612=== RUN TestServerRefusesOversizedAndNonStoreRequests2613=== PAUSE TestServerRefusesOversizedAndNonStoreRequests2614=== RUN TestGetListenerSocketActivation2615 server_test.go:309: === RUN TestGetListenerSocketActivation2616 --- PASS: TestGetListenerSocketActivation (0.00s)2617 PASS2618 2619--- PASS: TestGetListenerSocketActivation (1.02s)2620=== RUN TestServerStalledClientDoesNotBlockShutdown2621=== PAUSE TestServerStalledClientDoesNotBlockShutdown2622=== RUN TestServerBacksOffOnAcceptErrors2623=== PAUSE TestServerBacksOffOnAcceptErrors2624=== RUN TestDrainIsolatesPoisonPath2625=== PAUSE TestDrainIsolatesPoisonPath2626=== RUN TestRunNotBlockedByPoisonHead2627=== PAUSE TestRunNotBlockedByPoisonHead2628=== RUN TestDrainGivesUpWhenServerDown2629=== PAUSE TestDrainGivesUpWhenServerDown2630=== RUN TestFailedPathPrunedByLaterClosure2631=== PAUSE TestFailedPathPrunedByLaterClosure2632=== RUN TestWorkerUploadsAndRemoves2633=== PAUSE TestWorkerUploadsAndRemoves2634=== RUN TestWorkerSkipsGCdPaths2635=== PAUSE TestWorkerSkipsGCdPaths2636=== RUN TestWorkerPrunesClosureDeps2637=== PAUSE TestWorkerPrunesClosureDeps2638=== RUN TestWorkerRemovesCachedPathBatchedWithLargerClosure2639=== PAUSE TestWorkerRemovesCachedPathBatchedWithLargerClosure2640=== RUN TestDrainTimeout2641=== PAUSE TestDrainTimeout2642=== RUN TestDrainTimeoutDuringIsolation2643=== PAUSE TestDrainTimeoutDuringIsolation2644=== RUN TestShutdownFinishesInFlightPush2645=== PAUSE TestShutdownFinishesInFlightPush2646=== RUN TestWorkerRemoveFailureIsNotProgress2647=== PAUSE TestWorkerRemoveFailureIsNotProgress2648=== RUN TestWorkerKeepsPathItCannotStat2649=== PAUSE TestWorkerKeepsPathItCannotStat2650=== CONT TestSendPathsEmpty2651=== CONT TestWorkerSkipsGCdPaths2652--- PASS: TestSendPathsEmpty (0.00s)2653=== CONT TestServerStalledClientDoesNotBlockShutdown2654=== CONT TestWorkerRemoveFailureIsNotProgress2655=== CONT TestRunNotBlockedByPoisonHead2656=== CONT TestQueueRemoveLargeClosure2657=== CONT TestQueueEnqueueWaitsOutSlowWriter2658=== CONT TestServerRefusesOversizedAndNonStoreRequests2659=== CONT TestQueueConcurrentWriters26602026/10/25 19:48:22 ERROR Refusing path outside the store path=/etc/shadow store=/nix/store2661=== CONT TestQueueFetchBatchLimit2662=== CONT TestQueueRemove26632026/10/25 19:48:22 ERROR Refusing path outside the store path=/nix/store store=/nix/store2664=== CONT TestQueueFetchRemoveLifecycle2665=== CONT TestQueueDeduplication2666=== CONT TestWorkerUploadsAndRemoves26672026/10/25 19:48:22 ERROR Refusing path outside the store path=/nix/store/ store=/nix/store2668=== CONT TestQueueEnqueueAndFetch2669=== CONT TestServerBacksOffOnAcceptErrors2670=== CONT TestWorkerKeepsPathItCannotStat26712026/10/25 19:48:22 ERROR Accept failed error="too many open files"26722026/10/25 19:48:22 ERROR Refusing path outside the store path=/nix/store/../../etc/shadow store=/nix/store2673=== CONT TestFailedPathPrunedByLaterClosure2674=== CONT TestShutdownFinishesInFlightPush2675=== RUN TestShutdownFinishesInFlightPush/completes2676=== CONT TestWorkerPrunesClosureDeps2677=== CONT TestDrainTimeoutDuringIsolation2678=== CONT TestQueueRetryMovesToBack2679=== CONT TestWorkerRemovesCachedPathBatchedWithLargerClosure2680=== CONT TestDrainGivesUpWhenServerDown26812026/10/25 19:48:22 ERROR Refusing path outside the store path=/nix/store/0123456789abcdfghijklmnpqrsvwxyz-hello/bin/sh store=/nix/store2682=== CONT TestDrainTimeout2683=== RUN TestWorkerRemoveFailureIsNotProgress/collected_path2684=== PAUSE TestShutdownFinishesInFlightPush/completes2685=== RUN TestDrainTimeoutDuringIsolation/probe_cut_short2686=== RUN TestShutdownFinishesInFlightPush/hung_push_bounded_by_the_drain_timeout2687=== PAUSE TestWorkerRemoveFailureIsNotProgress/collected_path26882026/10/25 19:48:22 ERROR Refusing path outside the store path=nix/store/0123456789abcdfghijklmnpqrsvwxyz-hello store=/nix/store2689=== PAUSE TestDrainTimeoutDuringIsolation/probe_cut_short2690=== PAUSE TestShutdownFinishesInFlightPush/hung_push_bounded_by_the_drain_timeout2691=== RUN TestWorkerRemoveFailureIsNotProgress/pushed_batch26922026/10/25 19:48:22 ERROR Refusing path outside the store path=/nix/storeX/0123456789abcdfghijklmnpqrsvwxyz-hello store=/nix/store2693=== RUN TestDrainTimeoutDuringIsolation/probe_outlasts_the_deadline2694=== CONT TestDrainIsolatesPoisonPath2695=== PAUSE TestWorkerRemoveFailureIsNotProgress/pushed_batch2696=== RUN TestWorkerRemoveFailureIsNotProgress/isolated_paths26972026/10/25 19:48:22 ERROR Refusing path outside the store path=/nix/store/.links store=/nix/store2698=== PAUSE TestDrainTimeoutDuringIsolation/probe_outlasts_the_deadline2699=== PAUSE TestWorkerRemoveFailureIsNotProgress/isolated_paths27002026/10/25 19:48:22 ERROR Accept failed error="too many open files"2701=== CONT TestShutdownFinishesInFlightPush/completes2702=== CONT TestShutdownFinishesInFlightPush/hung_push_bounded_by_the_drain_timeout27032026/10/25 19:48:22 ERROR Refusing path outside the store path=/nix/store/aaa-hello store=/nix/store27042026/10/25 19:48:22 ERROR Refusing path outside the store path=/nix/store/0123456789abcdfghijklmnpqrsvwxyz store=/nix/store27052026/10/25 19:48:22 ERROR Refusing path outside the store path=/nix/store/0123456789abcdfghijklmnpqrsvwxyz- store=/nix/store27062026/10/25 19:48:22 ERROR Refusing path outside the store path=/nix/store/0123456789ebcdfghijklmnpqrsvwxyz-hello store=/nix/store27072026/10/25 19:48:22 ERROR Refusing path outside the store path="/nix/store/0123456789abcdfghijklmnpqrsvwxyz-hel\x00lo" store=/nix/store27082026/10/25 19:48:22 ERROR Refusing path outside the store path=/nix/store/0123456789abcdfghijklmnpqrsvwxyz-hel/lo store=/nix/store27092026/10/25 19:48:22 ERROR Refusing path outside the store path=/nix/store/0123456789abcdfghijklmnpqrsvwxyz-xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx store=/nix/store27102026/10/25 19:48:22 ERROR Failed to decode request error="unexpected EOF"2711--- PASS: TestServerRefusesOversizedAndNonStoreRequests (0.01s)2712=== CONT TestDrainTimeoutDuringIsolation/probe_cut_short27132026/10/25 19:48:22 ERROR Accept failed error="too many open files"27142026/10/25 19:48:22 ERROR Accept failed error="too many open files"27152026/10/25 19:48:22 INFO Upload queue status pending=227162026/10/25 19:48:22 INFO Uploading batch count=127172026/10/25 19:48:22 ERROR Upload failed error="upload failed" count=127182026/10/25 19:48:22 INFO Upload queue status pending=227192026/10/25 19:48:22 INFO Uploading batch count=227202026/10/25 19:48:22 INFO Uploading batch count=127212026/10/25 19:48:22 INFO Upload queue status pending=327222026/10/25 19:48:22 INFO Uploading batch count=427232026/10/25 19:48:22 INFO Upload queue status pending=227242026/10/25 19:48:22 ERROR Upload failed error="upload failed" count=427252026/10/25 19:48:22 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerSkipsGCdPaths1934910664/002/nonexistent27262026/10/25 19:48:22 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat2156833062/002/locked/aaa error="lstat /build/TestWorkerKeepsPathItCannotStat2156833062/002/locked/aaa: permission denied"27272026/10/25 19:48:22 INFO Upload queue status pending=227282026/10/25 19:48:22 INFO Uploading batch count=127292026/10/25 19:48:22 INFO Uploading batch count=227302026/10/25 19:48:22 INFO Upload queue status pending=327312026/10/25 19:48:22 INFO Uploading batch count=427322026/10/25 19:48:22 ERROR Upload failed error="upload failed" count=42733=== CONT TestDrainTimeoutDuringIsolation/probe_outlasts_the_deadline27342026/10/25 19:48:22 INFO Uploading batch count=22735--- PASS: TestQueueEnqueueAndFetch (0.06s)27362026/10/25 19:48:22 INFO Uploading batch count=227372026/10/25 19:48:22 INFO Uploading batch count=127382026/10/25 19:48:22 INFO Upload queue status pending=22739--- PASS: TestQueueFetchBatchLimit (0.06s)2740=== CONT TestWorkerRemoveFailureIsNotProgress/isolated_paths27412026/10/25 19:48:22 ERROR Upload failed error="upload failed" count=127422026/10/25 19:48:22 INFO Uploading batch count=227432026/10/25 19:48:22 INFO Uploading batch count=227442026/10/25 19:48:22 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainIsolatesPoisonPath2642663145/002/bbb27452026/10/25 19:48:22 INFO Uploading batch count=227462026/10/25 19:48:22 ERROR Upload failed error="upload failed" count=227472026/10/25 19:48:22 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown657911014/002/a27482026/10/25 19:48:22 INFO Uploading batch count=12749--- PASS: TestQueueDeduplication (0.06s)2750=== CONT TestWorkerRemoveFailureIsNotProgress/pushed_batch27512026/10/25 19:48:22 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat2156833062/002/locked/aaa error="lstat /build/TestWorkerKeepsPathItCannotStat2156833062/002/locked/aaa: permission denied"27522026/10/25 19:48:22 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown657911014/002/b27532026/10/25 19:48:22 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat2156833062/002/locked/aaa error="lstat /build/TestWorkerKeepsPathItCannotStat2156833062/002/locked/aaa: permission denied"2754--- PASS: TestQueueRemove (0.06s)2755=== CONT TestWorkerRemoveFailureIsNotProgress/collected_path27562026/10/25 19:48:22 INFO Uploading batch count=22757--- PASS: TestQueueRetryMovesToBack (0.06s)27582026/10/25 19:48:22 ERROR Drain finished with paths left in queue remaining=127592026/10/25 19:48:22 ERROR Upload failed error="upload failed" count=227602026/10/25 19:48:22 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown657911014/002/c2761--- PASS: TestQueueFetchRemoveLifecycle (0.06s)27622026/10/25 19:48:22 INFO Uploading batch count=127632026/10/25 19:48:22 ERROR Upload failed error="upload failed" count=127642026/10/25 19:48:22 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown657911014/002/d2765--- PASS: TestFailedPathPrunedByLaterClosure (0.07s)2766--- PASS: TestWorkerKeepsPathItCannotStat (0.07s)27672026/10/25 19:48:22 INFO Uploading batch count=227682026/10/25 19:48:22 ERROR Upload failed error="upload failed" count=227692026/10/25 19:48:22 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown657911014/002/e27702026/10/25 19:48:22 INFO Uploading batch count=127712026/10/25 19:48:22 ERROR Upload failed error="upload failed" count=127722026/10/25 19:48:22 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown657911014/002/f27732026/10/25 19:48:22 INFO Uploading batch count=427742026/10/25 19:48:22 ERROR Drain finished with paths left in queue remaining=1027752026/10/25 19:48:22 ERROR Upload failed error="upload failed" count=427762026/10/25 19:48:22 INFO Uploading batch count=12777--- PASS: TestWorkerPrunesClosureDeps (0.07s)27782026/10/25 19:48:22 ERROR Upload failed error="upload failed" count=127792026/10/25 19:48:22 ERROR Accept failed error="too many open files"2780--- PASS: TestDrainGivesUpWhenServerDown (0.08s)2781--- PASS: TestWorkerSkipsGCdPaths (0.08s)2782--- PASS: TestWorkerRemovesCachedPathBatchedWithLargerClosure (0.08s)27832026/10/25 19:48:22 ERROR Drain finished with paths left in queue remaining=127842026/10/25 19:48:22 INFO Uploading batch count=227852026/10/25 19:48:22 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=22786--- PASS: TestDrainIsolatesPoisonPath (0.08s)2787--- PASS: TestWorkerUploadsAndRemoves (0.08s)27882026/10/25 19:48:22 INFO Uploading batch count=227892026/10/25 19:48:22 INFO Uploading batch count=227902026/10/25 19:48:22 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=227912026/10/25 19:48:22 ERROR Upload failed error="upload failed" count=227922026/10/25 19:48:22 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgresscollected_path1397564437/001/nonexistent27932026/10/25 19:48:22 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=127942026/10/25 19:48:22 INFO Uploading batch count=227952026/10/25 19:48:22 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=127962026/10/25 19:48:22 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=127972026/10/25 19:48:22 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=227982026/10/25 19:48:22 ERROR Drain finished with paths left in queue remaining=227992026/10/25 19:48:22 INFO Uploading batch count=228002026/10/25 19:48:22 ERROR Upload failed error="upload failed" count=228012026/10/25 19:48:22 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=128022026/10/25 19:48:22 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgresscollected_path1397564437/001/nonexistent28032026/10/25 19:48:22 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=128042026/10/25 19:48:22 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=128052026/10/25 19:48:22 INFO Uploading batch count=228062026/10/25 19:48:22 ERROR Upload failed error="upload failed" count=228072026/10/25 19:48:22 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgresscollected_path1397564437/001/nonexistent28082026/10/25 19:48:22 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=128092026/10/25 19:48:22 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=128102026/10/25 19:48:22 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=128112026/10/25 19:48:22 ERROR Drain finished with paths left in queue remaining=128122026/10/25 19:48:22 ERROR Drain finished with paths left in queue remaining=22813--- PASS: TestWorkerRemoveFailureIsNotProgress (0.01s)2814 --- PASS: TestWorkerRemoveFailureIsNotProgress/pushed_batch (0.03s)2815 --- PASS: TestWorkerRemoveFailureIsNotProgress/collected_path (0.03s)2816 --- PASS: TestWorkerRemoveFailureIsNotProgress/isolated_paths (0.04s)28172026/10/25 19:48:22 ERROR Accept failed error="too many open files"28182026/10/25 19:48:22 ERROR Failed to decode request error="read unix /build/hook1746396778/test.sock->@: i/o timeout"28192026/10/25 19:48:22 ERROR Failed to write response error="write unix /build/hook1746396778/test.sock->@: i/o timeout"2820--- PASS: TestServerStalledClientDoesNotBlockShutdown (0.20s)28212026/10/25 19:48:22 ERROR Drain finished with paths left in queue remaining=428222026/10/25 19:48:22 ERROR Upload failed error="context canceled" count=228232026/10/25 19:48:22 ERROR Drain finished with paths left in queue remaining=428242026/10/25 19:48:22 ERROR Upload failed error="context canceled" count=228252026/10/25 19:48:22 ERROR Drain finished with paths left in queue remaining=228262026/10/25 19:48:22 ERROR Accept failed error="too many open files"28272026/10/25 19:48:23 ERROR Accept failed error="too many open files"2828--- PASS: TestServerBacksOffOnAcceptErrors (0.64s)28292026/10/25 19:48:23 ERROR Drain finished with paths left in queue remaining=32830--- PASS: TestDrainTimeout (0.86s)2831--- PASS: TestShutdownFinishesInFlightPush (0.00s)2832 --- PASS: TestShutdownFinishesInFlightPush/completes (0.15s)2833 --- PASS: TestShutdownFinishesInFlightPush/hung_push_bounded_by_the_drain_timeout (0.86s)2834--- PASS: TestDrainTimeoutDuringIsolation (0.00s)2835 --- PASS: TestDrainTimeoutDuringIsolation/probe_cut_short (0.85s)2836 --- PASS: TestDrainTimeoutDuringIsolation/probe_outlasts_the_deadline (0.88s)28372026/10/25 19:48:23 INFO Uploading batch count=128382026/10/25 19:48:23 INFO Uploading batch count=128392026/10/25 19:48:23 INFO Uploading batch count=128402026/10/25 19:48:23 ERROR Upload failed error="upload failed" count=128412026/10/25 19:48:23 INFO Uploading batch count=128422026/10/25 19:48:23 ERROR Upload failed error="upload failed" count=128432026/10/25 19:48:23 INFO Uploading batch count=128442026/10/25 19:48:23 ERROR Upload failed error="upload failed" count=128452026/10/25 19:48:23 INFO Uploading batch count=128462026/10/25 19:48:23 ERROR Upload failed error="upload failed" count=128472026/10/25 19:48:23 ERROR Drain finished with paths left in queue remaining=12848--- PASS: TestRunNotBlockedByPoisonHead (1.14s)2849--- PASS: TestQueueRemoveLargeClosure (1.50s)2850--- PASS: TestQueueConcurrentWriters (1.53s)2851--- PASS: TestQueueEnqueueWaitsOutSlowWriter (6.10s)2852PASS2853Running signing tests...2854=== RUN TestExternalSigner2855=== PAUSE TestExternalSigner2856=== RUN TestExternalSignerWrongPublicKey2857=== PAUSE TestExternalSignerWrongPublicKey2858=== RUN TestExternalSignerErrors2859=== PAUSE TestExternalSignerErrors2860=== RUN TestExternalSignerRestartsAfterCrash2861=== PAUSE TestExternalSignerRestartsAfterCrash2862=== RUN TestExternalSignerProgramErrorKeepsProcess2863=== PAUSE TestExternalSignerProgramErrorKeepsProcess2864=== RUN TestExternalSignerClose2865=== PAUSE TestExternalSignerClose2866=== RUN TestExternalSignerRejectsInvalidPublicKey2867=== PAUSE TestExternalSignerRejectsInvalidPublicKey2868=== RUN TestExternalSignerCancellation2869=== PAUSE TestExternalSignerCancellation2870=== RUN TestGenerateFingerprint2871=== PAUSE TestGenerateFingerprint2872=== RUN TestParseSigningKey2873=== PAUSE TestParseSigningKey2874=== RUN TestSign2875=== PAUSE TestSign2876=== RUN TestSignBatch2877=== PAUSE TestSignBatch2878=== RUN TestNilKeyPublicKey2879=== PAUSE TestNilKeyPublicKey2880=== RUN TestSignErrors2881=== PAUSE TestSignErrors2882=== CONT TestExternalSigner2883=== CONT TestExternalSignerRejectsInvalidPublicKey2884=== CONT TestSign2885=== CONT TestNilKeyPublicKey2886=== CONT TestSignBatch2887=== CONT TestExternalSignerCancellation2888=== CONT TestExternalSignerRestartsAfterCrash2889=== CONT TestExternalSignerClose2890=== CONT TestExternalSignerProgramErrorKeepsProcess2891=== CONT TestExternalSignerWrongPublicKey2892=== CONT TestGenerateFingerprint2893=== RUN TestGenerateFingerprint/basic_with_references2894=== PAUSE TestGenerateFingerprint/basic_with_references2895=== CONT TestParseSigningKey2896=== RUN TestParseSigningKey/valid_32-byte_key2897=== PAUSE TestParseSigningKey/valid_32-byte_key2898=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2899=== RUN TestGenerateFingerprint/no_references2900=== PAUSE TestGenerateFingerprint/no_references2901=== CONT TestExternalSignerErrors2902=== CONT TestSignErrors2903=== RUN TestExternalSignerRejectsInvalidPublicKey/#002904--- PASS: TestNilKeyPublicKey (0.00s)2905=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2906=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2907=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2908=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2909=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002910=== RUN TestGenerateFingerprint/invalid_nar_hash_length2911=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2912=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2913=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2914=== RUN TestExternalSignerErrors/too_few_signatures2915=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2916=== PAUSE TestExternalSignerErrors/too_few_signatures2917=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2918=== RUN TestExternalSignerErrors/missing_signature_name2919=== RUN TestGenerateFingerprint/invalid_store_path_prefix2920=== RUN TestParseSigningKey/no_colon2921=== RUN TestSignErrors/nil_key2922=== PAUSE TestParseSigningKey/no_colon2923=== PAUSE TestSignErrors/nil_key2924=== PAUSE TestExternalSignerErrors/missing_signature_name2925=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2926=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2927=== RUN TestExternalSignerErrors/wrong_signature_name2928--- PASS: TestSign (0.00s)2929=== PAUSE TestExternalSignerErrors/wrong_signature_name2930=== RUN TestParseSigningKey/empty_name2931=== RUN TestSignErrors/nil_narinfo2932=== RUN TestExternalSignerErrors/null2933=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2934=== RUN TestGenerateFingerprint/invalid_reference_prefix2935=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2936=== CONT TestGenerateFingerprint/no_references2937=== CONT TestGenerateFingerprint/basic_with_references2938=== PAUSE TestExternalSignerErrors/null2939=== PAUSE TestSignErrors/nil_narinfo2940=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2941=== PAUSE TestParseSigningKey/empty_name2942=== CONT TestGenerateFingerprint/invalid_nar_hash_length2943=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2944=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2945=== RUN TestParseSigningKey/invalid_base642946=== PAUSE TestParseSigningKey/invalid_base642947=== CONT TestGenerateFingerprint/invalid_reference_prefix2948=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2949=== CONT TestGenerateFingerprint/invalid_store_path_prefix2950=== RUN TestSignErrors/invalid_narinfo2951=== RUN TestExternalSignerErrors/null_signatures2952=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2953=== PAUSE TestExternalSignerErrors/null_signatures2954=== RUN TestParseSigningKey/wrong_length2955--- PASS: TestExternalSignerClose (0.00s)2956=== PAUSE TestParseSigningKey/wrong_length2957=== PAUSE TestSignErrors/invalid_narinfo2958=== CONT TestExternalSignerRejectsInvalidPublicKey/#002959=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2960=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2961=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2962=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2963=== RUN TestExternalSignerErrors/invalid_signature_base642964--- PASS: TestExternalSignerWrongPublicKey (0.00s)2965=== CONT TestParseSigningKey/no_colon2966=== CONT TestParseSigningKey/invalid_base642967=== CONT TestParseSigningKey/wrong_length2968=== CONT TestParseSigningKey/valid_32-byte_key2969=== CONT TestParseSigningKey/empty_name2970=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2971=== RUN TestSignErrors/canceled2972=== PAUSE TestExternalSignerErrors/invalid_signature_base642973--- PASS: TestExternalSignerProgramErrorKeepsProcess (0.01s)2974=== PAUSE TestSignErrors/canceled2975=== RUN TestExternalSignerErrors/wrong_signature_length2976--- PASS: TestSignBatch (0.01s)2977=== PAUSE TestExternalSignerErrors/wrong_signature_length2978--- PASS: TestGenerateFingerprint (0.00s)2979 --- PASS: TestGenerateFingerprint/no_references (0.00s)2980 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2981 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2982 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2983 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2984 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2985 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2986=== CONT TestSignErrors/nil_key2987--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.01s)2988 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2989 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2990 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2991 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2992 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2993=== CONT TestSignErrors/canceled2994=== CONT TestSignErrors/invalid_narinfo2995--- PASS: TestParseSigningKey (0.00s)2996 --- PASS: TestParseSigningKey/no_colon (0.00s)2997 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2998 --- PASS: TestParseSigningKey/wrong_length (0.00s)2999 --- PASS: TestParseSigningKey/empty_name (0.00s)3000 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)3001 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)3002=== CONT TestSignErrors/nil_narinfo3003=== RUN TestExternalSignerErrors/exit_on_request3004--- PASS: TestSignErrors (0.00s)3005 --- PASS: TestSignErrors/nil_key (0.00s)3006 --- PASS: TestSignErrors/canceled (0.00s)3007 --- PASS: TestSignErrors/invalid_narinfo (0.00s)3008 --- PASS: TestSignErrors/nil_narinfo (0.00s)3009=== PAUSE TestExternalSignerErrors/exit_on_request3010=== RUN TestExternalSignerErrors/wrong_signatures_shape3011=== PAUSE TestExternalSignerErrors/wrong_signatures_shape3012=== RUN TestExternalSignerErrors/unrequested_key3013=== PAUSE TestExternalSignerErrors/unrequested_key3014=== RUN TestExternalSignerErrors/program_error3015=== PAUSE TestExternalSignerErrors/program_error3016=== RUN TestExternalSignerErrors/exit_at_startup3017=== PAUSE TestExternalSignerErrors/exit_at_startup3018=== RUN TestExternalSignerErrors/wrong_shape3019=== PAUSE TestExternalSignerErrors/wrong_shape3020=== RUN TestExternalSignerErrors/missing_signatures3021=== PAUSE TestExternalSignerErrors/missing_signatures3022=== RUN TestExternalSignerErrors/invalid_JSON3023=== PAUSE TestExternalSignerErrors/invalid_JSON3024=== RUN TestExternalSignerErrors/wrong_id3025=== PAUSE TestExternalSignerErrors/wrong_id3026--- PASS: TestExternalSignerRestartsAfterCrash (0.01s)3027=== CONT TestExternalSignerErrors/too_few_signatures3028=== CONT TestExternalSignerErrors/program_error3029=== CONT TestExternalSignerErrors/invalid_signature_base643030=== CONT TestExternalSignerErrors/null_signatures3031=== CONT TestExternalSignerErrors/wrong_signature_length3032=== CONT TestExternalSignerErrors/null3033=== CONT TestExternalSignerErrors/wrong_signature_name3034=== CONT TestExternalSignerErrors/exit_at_startup3035=== CONT TestExternalSignerErrors/exit_on_request3036=== CONT TestExternalSignerErrors/unrequested_key3037=== CONT TestExternalSignerErrors/wrong_signatures_shape3038=== CONT TestExternalSignerErrors/missing_signature_name3039=== CONT TestExternalSignerErrors/invalid_JSON3040=== CONT TestExternalSignerErrors/wrong_id3041=== CONT TestExternalSignerErrors/wrong_shape3042=== CONT TestExternalSignerErrors/missing_signatures3043--- PASS: TestExternalSigner (0.01s)3044--- PASS: TestExternalSignerErrors (0.01s)3045 --- PASS: TestExternalSignerErrors/too_few_signatures (0.00s)3046 --- PASS: TestExternalSignerErrors/program_error (0.00s)3047 --- PASS: TestExternalSignerErrors/wrong_signature_length (0.00s)3048 --- PASS: TestExternalSignerErrors/null_signatures (0.00s)3049 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (0.00s)3050 --- PASS: TestExternalSignerErrors/wrong_signature_name (0.00s)3051 --- PASS: TestExternalSignerErrors/exit_at_startup (0.01s)3052 --- PASS: TestExternalSignerErrors/invalid_JSON (0.00s)3053 --- PASS: TestExternalSignerErrors/exit_on_request (0.01s)3054 --- PASS: TestExternalSignerErrors/unrequested_key (0.01s)3055 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (0.01s)3056 --- PASS: TestExternalSignerErrors/missing_signature_name (0.01s)3057 --- PASS: TestExternalSignerErrors/wrong_shape (0.00s)3058 --- PASS: TestExternalSignerErrors/wrong_id (0.01s)3059 --- PASS: TestExternalSignerErrors/null (0.01s)3060 --- PASS: TestExternalSignerErrors/missing_signatures (0.00s)3061--- PASS: TestExternalSignerCancellation (0.02s)3062PASS3063Running OpenBao signer tests...3064=== RUN TestSign3065=== PAUSE TestSign3066=== RUN TestSignErrors3067=== PAUSE TestSignErrors3068=== RUN TestServe3069=== PAUSE TestServe3070=== RUN TestServeRejectsGarbage3071=== PAUSE TestServeRejectsGarbage3072=== CONT TestSign3073=== CONT TestSignErrors3074=== CONT TestServeRejectsGarbage3075=== RUN TestSignErrors/http_error3076=== CONT TestServe3077--- PASS: TestServeRejectsGarbage (0.00s)3078=== PAUSE TestSignErrors/http_error3079=== RUN TestSignErrors/invalid_json3080=== PAUSE TestSignErrors/invalid_json3081=== RUN TestSignErrors/no_prefix3082=== PAUSE TestSignErrors/no_prefix3083=== RUN TestSignErrors/invalid_base643084=== PAUSE TestSignErrors/invalid_base643085=== CONT TestSignErrors/http_error3086=== CONT TestSignErrors/invalid_base643087=== CONT TestSignErrors/invalid_json3088=== CONT TestSignErrors/no_prefix3089--- PASS: TestServe (0.00s)3090--- PASS: TestSign (0.01s)3091--- PASS: TestSignErrors (0.00s)3092 --- PASS: TestSignErrors/invalid_json (0.00s)3093 --- PASS: TestSignErrors/invalid_base64 (0.00s)3094 --- PASS: TestSignErrors/no_prefix (0.00s)3095 --- PASS: TestSignErrors/http_error (0.00s)3096PASS3097Running niks3-hook command tests...3098=== RUN TestServeSecondSignalEndsDrain3099=== PAUSE TestServeSecondSignalEndsDrain3100=== RUN TestServeThenDrainPushesSendAcceptedBeforeShutdown3101=== PAUSE TestServeThenDrainPushesSendAcceptedBeforeShutdown3102=== CONT TestServeThenDrainPushesSendAcceptedBeforeShutdown3103=== CONT TestServeSecondSignalEndsDrain31042026/10/25 19:48:32 INFO Upload queue status pending=131052026/10/25 19:48:32 INFO Uploading batch count=13106--- PASS: TestServeThenDrainPushesSendAcceptedBeforeShutdown (0.87s)3107--- PASS: TestServeSecondSignalEndsDrain (1.04s)3108PASS3109Running rate limiter tests...3110=== RUN TestAdaptiveRateLimiter_ThreadSafety3111=== PAUSE TestAdaptiveRateLimiter_ThreadSafety3112=== CONT TestAdaptiveRateLimiter_ThreadSafety31132026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=7031142026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=4931152026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=34.331162026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=24.00999999999999831172026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=16.80731182026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=11.76489999999999931192026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=8.2354331202026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=5.76480099999999931212026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531222026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531232026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531242026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531252026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531262026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531272026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531282026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531292026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531302026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531312026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531322026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531332026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531342026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531352026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531362026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531372026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531382026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531392026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531402026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531412026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531422026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531432026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531442026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531452026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531462026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531472026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531482026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531492026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531502026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531512026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531522026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531532026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531542026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531552026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531562026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=6.82050985000000231572026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531582026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531592026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531602026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531612026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531622026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531632026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531642026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531652026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531662026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531672026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531682026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531692026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531702026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531712026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531722026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531732026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531742026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531752026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531762026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531772026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531782026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531792026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531802026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531812026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531822026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531832026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531842026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531852026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531862026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531872026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531882026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531892026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531902026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531912026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=5.12435000000000131922026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531932026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531942026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531952026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531962026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531972026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531982026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=531992026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=532002026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=5.12435000000000132012026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=532022026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=532032026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=532042026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=532052026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=532062026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=532072026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=8.25281691850000432082026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=5.77697184295000332092026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=532102026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=532112026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=532122026/10/25 19:48:33 WARN Rate limiter backed off name=test rate=53213--- PASS: TestAdaptiveRateLimiter_ThreadSafety (2.43s)3214PASS