niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #273
· raw
1Running client tests...2=== RUN TestDoServerRequestAttachesToken3=== PAUSE TestDoServerRequestAttachesToken4=== RUN TestUploadBuildLog_FileBodyReplayedOnRetry5=== PAUSE TestUploadBuildLog_FileBodyReplayedOnRetry6=== RUN TestRegisterUploadedObjectReusesConnections7=== PAUSE TestRegisterUploadedObjectReusesConnections8=== RUN TestRunGarbageCollection_FinishedOnAnotherReplica9=== PAUSE TestRunGarbageCollection_FinishedOnAnotherReplica10=== RUN TestRunGarbageCollection_NotFoundAfterLocalRun11=== PAUSE TestRunGarbageCollection_NotFoundAfterLocalRun12=== RUN TestCaseHackSuffix13=== PAUSE TestCaseHackSuffix14=== RUN TestFilterOversizedClosures15=== PAUSE TestFilterOversizedClosures16=== RUN TestPushPathsReportsOnlyUnuploadablePathsOfSkippedClosure17=== PAUSE TestPushPathsReportsOnlyUnuploadablePathsOfSkippedClosure18=== RUN TestUploadMultipart_PartsInParallel19=== PAUSE TestUploadMultipart_PartsInParallel20=== RUN TestUploadMultipart_ProducerErrorIsNotEOF21=== PAUSE TestUploadMultipart_ProducerErrorIsNotEOF22=== RUN TestUploadMultipart_FailedPartBufferNotReused23=== PAUSE TestUploadMultipart_FailedPartBufferNotReused24=== RUN TestPartSizeForNAR25=== PAUSE TestPartSizeForNAR26=== RUN TestUploadMultipart_SupersededByPeer27=== PAUSE TestUploadMultipart_SupersededByPeer28=== RUN TestDumpPathCaseHackMatchesNix29--- PASS: TestDumpPathCaseHackMatchesNix (0.05s)30=== RUN TestDumpPathCaseHackCollision31--- PASS: TestDumpPathCaseHackCollision (0.00s)32=== RUN TestSupersededNARStillUploadsListing33=== PAUSE TestSupersededNARStillUploadsListing34=== RUN TestTruncatedNARDumpIsNotCompleted35=== PAUSE TestTruncatedNARDumpIsNotCompleted36=== RUN TestDumpPathMatchesNix37=== PAUSE TestDumpPathMatchesNix38=== RUN TestDumpPathSingleFile39=== PAUSE TestDumpPathSingleFile40=== RUN TestDumpPathWriterError41=== PAUSE TestDumpPathWriterError42=== RUN TestDumpPathWriterErrorStopsReading43 nar_test.go:280: no /proc/self/io: open /proc/self/io: no such file or directory44--- SKIP: TestDumpPathWriterErrorStopsReading (0.34s)45=== RUN TestEncodeNixBase3246=== PAUSE TestEncodeNixBase3247=== RUN TestEncodeNixBase32WithRealHash48=== PAUSE TestEncodeNixBase32WithRealHash49=== RUN TestConvertHashToNix3250=== PAUSE TestConvertHashToNix3251=== RUN TestGetStorePathHash52=== PAUSE TestGetStorePathHash53=== RUN TestPathInfoHashCompatibility54=== PAUSE TestPathInfoHashCompatibility55=== RUN TestParsePathInfoJSON56=== PAUSE TestParsePathInfoJSON57=== RUN TestParsePathInfoJSONMultiplePaths58=== PAUSE TestParsePathInfoJSONMultiplePaths59=== RUN TestPathInfoCACompatibility60=== PAUSE TestPathInfoCACompatibility61=== RUN TestUploadPendingObjectsStopsStartingAfterFailure62--- PASS: TestUploadPendingObjectsStopsStartingAfterFailure (0.01s)63=== RUN TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent64=== PAUSE TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent65=== RUN TestCompletePendingClosure_NotFoundWithoutKey66=== PAUSE TestCompletePendingClosure_NotFoundWithoutKey67=== RUN TestRateLimiterFeedback68=== PAUSE TestRateLimiterFeedback69=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess70=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess71=== RUN TestRegisterUploadedObject_BoundedAgainstSilentServer72=== PAUSE TestRegisterUploadedObject_BoundedAgainstSilentServer73=== RUN TestResolveStorePath74=== PAUSE TestResolveStorePath75=== RUN TestDoWithRetry_BodyReplayedViaGetBody76=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody77=== RUN TestDoWithRetry_FinalResponseBodyReadable78=== PAUSE TestDoWithRetry_FinalResponseBodyReadable79=== RUN TestShellSplit80=== PAUSE TestShellSplit81=== RUN TestShellSplitErrors82=== PAUSE TestShellSplitErrors83=== RUN TestStreamPushReportsEveryPath84=== PAUSE TestStreamPushReportsEveryPath85=== RUN TestStreamPushBatchesUnderLoad86=== PAUSE TestStreamPushBatchesUnderLoad87=== RUN TestStreamPushIsolatesFailures88=== PAUSE TestStreamPushIsolatesFailures89=== RUN TestStreamPushGivesUpOnDeadServer90=== PAUSE TestStreamPushGivesUpOnDeadServer91=== RUN TestStreamPushRequestLine92=== PAUSE TestStreamPushRequestLine93=== RUN TestStreamPushReportsSignatures94=== PAUSE TestStreamPushReportsSignatures95=== RUN TestClientSignaturesByStorePath96=== PAUSE TestClientSignaturesByStorePath97=== RUN TestStreamPushStopsOnCancel98=== PAUSE TestStreamPushStopsOnCancel99=== RUN TestSetClientTLS100=== PAUSE TestSetClientTLS101=== RUN TestSetClientTLSDoesNotMutateDefaultTransport102=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport103=== RUN TestSetClientTLSErrors104=== PAUSE TestSetClientTLSErrors105=== RUN TestStaticToken106=== PAUSE TestStaticToken107=== RUN TestFileTokenReadsAndCaches108=== PAUSE TestFileTokenReadsAndCaches109=== RUN TestFileTokenMissing110=== PAUSE TestFileTokenMissing111=== RUN TestFileTokenEmpty112=== PAUSE TestFileTokenEmpty113=== RUN TestScriptTokenNoExpiryRerunsEveryCall114=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall115=== RUN TestScriptTokenCachesUntilRefresh116=== PAUSE TestScriptTokenCachesUntilRefresh117=== RUN TestScriptTokenEmptyToken118=== PAUSE TestScriptTokenEmptyToken119=== RUN TestScriptTokenBadJSON120=== PAUSE TestScriptTokenBadJSON121=== RUN TestScriptTokenScriptFails122=== PAUSE TestScriptTokenScriptFails123=== RUN TestScriptTokenEmptyCommand124=== PAUSE TestScriptTokenEmptyCommand125=== RUN TestScriptTokenDoesNotWaitForItsChildren126=== PAUSE TestScriptTokenDoesNotWaitForItsChildren127=== CONT TestDoServerRequestAttachesToken128=== CONT TestScriptTokenCachesUntilRefresh129=== CONT TestRateLimiterFeedback130=== CONT TestScriptTokenDoesNotWaitForItsChildren131=== CONT TestStreamPushRequestLine132=== CONT TestScriptTokenEmptyCommand133=== CONT TestScriptTokenScriptFails134--- PASS: TestScriptTokenEmptyCommand (0.00s)135=== CONT TestFileTokenMissing136=== CONT TestScriptTokenBadJSON137=== CONT TestScriptTokenNoExpiryRerunsEveryCall138=== CONT TestFileTokenEmpty139=== RUN TestRateLimiterFeedback/429_enables_limiter140=== RUN TestScriptTokenDoesNotWaitForItsChildren/cancelled_while_a_child_runs141--- PASS: TestFileTokenMissing (0.00s)142=== CONT TestFileTokenReadsAndCaches143=== PAUSE TestRateLimiterFeedback/429_enables_limiter144=== PAUSE TestScriptTokenDoesNotWaitForItsChildren/cancelled_while_a_child_runs145=== RUN TestScriptTokenDoesNotWaitForItsChildren/child_left_holding_stdout146=== PAUSE TestScriptTokenDoesNotWaitForItsChildren/child_left_holding_stdout147=== RUN TestRateLimiterFeedback/503_enables_limiter148=== CONT TestStaticToken149=== PAUSE TestRateLimiterFeedback/503_enables_limiter150=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter151=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter152=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter153=== CONT TestScriptTokenEmptyToken154=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter155--- PASS: TestStaticToken (0.00s)156=== CONT TestSetClientTLSErrors157--- PASS: TestScriptTokenScriptFails (0.01s)158=== CONT TestSetClientTLS159--- PASS: TestDoServerRequestAttachesToken (0.01s)160=== CONT TestSetClientTLSDoesNotMutateDefaultTransport161=== CONT TestStreamPushStopsOnCancel162=== RUN TestStreamPushStopsOnCancel/waiting_for_input163=== CONT TestStreamPushReportsSignatures164=== PAUSE TestStreamPushStopsOnCancel/waiting_for_input165=== RUN TestStreamPushStopsOnCancel/partial_batch_waiting_for_a_slot166--- PASS: TestFileTokenReadsAndCaches (0.00s)167--- PASS: TestFileTokenEmpty (0.01s)168=== PAUSE TestStreamPushStopsOnCancel/partial_batch_waiting_for_a_slot169=== RUN TestStreamPushStopsOnCancel/input_closed,_last_batch_waiting_for_a_slot170=== PAUSE TestStreamPushStopsOnCancel/input_closed,_last_batch_waiting_for_a_slot171=== RUN TestStreamPushStopsOnCancel/full_batch_waiting_for_a_slot172=== PAUSE TestStreamPushStopsOnCancel/full_batch_waiting_for_a_slot173=== RUN TestStreamPushStopsOnCancel/request_line_waiting_for_a_slot174=== PAUSE TestStreamPushStopsOnCancel/request_line_waiting_for_a_slot175=== RUN TestStreamPushStopsOnCancel/lines_read_but_not_taken176=== PAUSE TestStreamPushStopsOnCancel/lines_read_but_not_taken177=== RUN TestSetClientTLSErrors/missing_cert_file178=== PAUSE TestSetClientTLSErrors/missing_cert_file179=== RUN TestSetClientTLSErrors/missing_key_file180=== PAUSE TestSetClientTLSErrors/missing_key_file181=== RUN TestSetClientTLSErrors/missing_ca_file182--- PASS: TestStreamPushReportsSignatures (0.00s)183=== CONT TestSupersededNARStillUploadsListing184=== PAUSE TestSetClientTLSErrors/missing_ca_file185=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer186=== RUN TestSetClientTLSErrors/invalid_ca_file187=== RUN TestSupersededNARStillUploadsListing/small_NAR188=== PAUSE TestSetClientTLSErrors/invalid_ca_file189=== PAUSE TestSupersededNARStillUploadsListing/small_NAR190=== CONT TestCompletePendingClosure_NotFoundWithoutKey191=== RUN TestSupersededNARStillUploadsListing/dump_cut_short192=== PAUSE TestSupersededNARStillUploadsListing/dump_cut_short193--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)194=== RUN TestSupersededNARStillUploadsListing/listing_upload_fails195=== PAUSE TestSupersededNARStillUploadsListing/listing_upload_fails196=== CONT TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent197=== RUN TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/committed_earlier198=== PAUSE TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/committed_earlier199=== RUN TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/cleaned_up200=== PAUSE TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/cleaned_up201=== CONT TestPathInfoCACompatibility202=== RUN TestPathInfoCACompatibility/null_ca_field203=== PAUSE TestPathInfoCACompatibility/null_ca_field204=== RUN TestPathInfoCACompatibility/old_string_format_-_text205=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text206=== CONT TestParsePathInfoJSON207=== RUN TestParsePathInfoJSON/Nix_format208=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive209=== PAUSE TestParsePathInfoJSON/Nix_format210=== RUN TestParsePathInfoJSON/Lix_format211=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive212=== PAUSE TestParsePathInfoJSON/Lix_format213=== RUN TestPathInfoCACompatibility/new_structured_format_-_text214=== RUN TestParsePathInfoJSON/empty_input215=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text216=== PAUSE TestParsePathInfoJSON/empty_input217=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method218=== RUN TestParsePathInfoJSON/whitespace_only219=== PAUSE TestParsePathInfoJSON/whitespace_only220=== RUN TestParsePathInfoJSON/invalid_JSON221=== PAUSE TestParsePathInfoJSON/invalid_JSON222=== CONT TestParsePathInfoJSONMultiplePaths223=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method224=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths225=== CONT TestPathInfoHashCompatibility226=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths227=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)228=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths229=== RUN TestSetClientTLS/rejects_connection_without_client_cert230=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)231=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon232=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert233=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA234=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths235--- PASS: TestCompletePendingClosure_NotFoundWithoutKey (0.00s)236=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA237=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon238=== CONT TestGetStorePathHash239=== CONT TestConvertHashToNix32240=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI241=== RUN TestGetStorePathHash/valid_store_path242=== RUN TestSetClientTLS/preserves_debug_logging_transport243=== PAUSE TestGetStorePathHash/valid_store_path244=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI245=== RUN TestConvertHashToNix32/SRI_format_to_Nix32246=== PAUSE TestSetClientTLS/preserves_debug_logging_transport247=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512248=== CONT TestEncodeNixBase32WithRealHash249=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512250--- PASS: TestEncodeNixBase32WithRealHash (0.00s)251=== CONT TestEncodeNixBase32252=== RUN TestEncodeNixBase32/test_string_hash253=== RUN TestGetStorePathHash/basename_without_hyphen_should_error254=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32255=== PAUSE TestEncodeNixBase32/test_string_hash256=== CONT TestDumpPathWriterError257=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error258=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error259=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error260=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error261=== RUN TestConvertHashToNix32/already_Nix32_format262=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error263=== PAUSE TestConvertHashToNix32/already_Nix32_format264=== RUN TestEncodeNixBase32/empty_input265=== PAUSE TestEncodeNixBase32/empty_input266=== CONT TestDumpPathSingleFile267=== CONT TestDumpPathMatchesNix268=== RUN TestConvertHashToNix32/invalid_format269=== PAUSE TestConvertHashToNix32/invalid_format270=== CONT TestFilterOversizedClosures271=== RUN TestFilterOversizedClosures/no_limit_keeps_everything272=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything273=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped274=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped275=== RUN TestFilterOversizedClosures/all_closures_skipped276=== PAUSE TestFilterOversizedClosures/all_closures_skipped277=== CONT TestUploadMultipart_ProducerErrorIsNotEOF278=== RUN TestUploadMultipart_ProducerErrorIsNotEOF/short_read_inside_a_part279=== PAUSE TestUploadMultipart_ProducerErrorIsNotEOF/short_read_inside_a_part280=== RUN TestUploadMultipart_ProducerErrorIsNotEOF/empty_read_on_a_part_boundary281=== PAUSE TestUploadMultipart_ProducerErrorIsNotEOF/empty_read_on_a_part_boundary282=== CONT TestUploadMultipart_FailedPartBufferNotReused283--- PASS: TestScriptTokenBadJSON (0.01s)284=== CONT TestPushPathsReportsOnlyUnuploadablePathsOfSkippedClosure285--- PASS: TestScriptTokenEmptyToken (0.01s)286=== CONT TestTruncatedNARDumpIsNotCompleted287--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.03s)288=== CONT TestUploadMultipart_SupersededByPeer289=== RUN TestUploadMultipart_SupersededByPeer/exists290=== PAUSE TestUploadMultipart_SupersededByPeer/exists291=== RUN TestUploadMultipart_SupersededByPeer/missing292=== PAUSE TestUploadMultipart_SupersededByPeer/missing293=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica294--- PASS: TestScriptTokenCachesUntilRefresh (0.03s)295=== CONT TestUploadMultipart_PartsInParallel296--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.01s)297=== CONT TestCaseHackSuffix298--- PASS: TestDumpPathSingleFile (0.05s)299=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun300--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.00s)301=== CONT TestRegisterUploadedObjectReusesConnections302--- PASS: TestStreamPushRequestLine (0.10s)303=== CONT TestShellSplit304--- PASS: TestShellSplit (0.00s)305=== CONT TestClientSignaturesByStorePath306--- PASS: TestClientSignaturesByStorePath (0.00s)307=== CONT TestStreamPushIsolatesFailures308--- PASS: TestStreamPushIsolatesFailures (0.00s)309=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry310--- PASS: TestCaseHackSuffix (0.07s)311=== CONT TestStreamPushReportsEveryPath312--- PASS: TestStreamPushReportsEveryPath (0.00s)313=== CONT TestStreamPushBatchesUnderLoad314=== RUN TestStreamPushBatchesUnderLoad/together315=== PAUSE TestStreamPushBatchesUnderLoad/together316=== RUN TestStreamPushBatchesUnderLoad/one_at_a_time317=== PAUSE TestStreamPushBatchesUnderLoad/one_at_a_time318=== CONT TestDoWithRetry_FinalResponseBodyReadable319--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.00s)320=== CONT TestResolveStorePath321--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.01s)322=== CONT TestDoWithRetry_BodyReplayedViaGetBody323--- PASS: TestResolveStorePath (0.00s)324=== CONT TestShellSplitErrors325--- PASS: TestShellSplitErrors (0.00s)326=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess327--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.00s)328=== CONT TestStreamPushGivesUpOnDeadServer329--- PASS: TestStreamPushGivesUpOnDeadServer (0.01s)330=== CONT TestPartSizeForNAR331=== RUN TestPartSizeForNAR/zero_stays_at_minimum332=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum333=== RUN TestPartSizeForNAR/small_stays_at_minimum334--- PASS: TestDumpPathWriterError (0.11s)335=== PAUSE TestPartSizeForNAR/small_stays_at_minimum336=== CONT TestScriptTokenDoesNotWaitForItsChildren/child_left_holding_stdout337=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum338=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum339=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts340=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts341=== RUN TestPartSizeForNAR/1_TiB342=== PAUSE TestPartSizeForNAR/1_TiB343=== RUN TestPartSizeForNAR/5_TiB_S3_max_object344=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object345=== RUN TestPartSizeForNAR/capped_at_5_GiB346=== PAUSE TestPartSizeForNAR/capped_at_5_GiB347=== CONT TestScriptTokenDoesNotWaitForItsChildren/cancelled_while_a_child_runs348--- PASS: TestDumpPathMatchesNix (0.14s)349=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter350=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter351=== CONT TestRateLimiterFeedback/503_enables_limiter352=== CONT TestRateLimiterFeedback/429_enables_limiter353=== CONT TestStreamPushStopsOnCancel/waiting_for_input354--- PASS: TestRateLimiterFeedback (0.01s)355 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)356 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)357 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)358 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)359--- PASS: TestPushPathsReportsOnlyUnuploadablePathsOfSkippedClosure (0.16s)360=== CONT TestStreamPushStopsOnCancel/request_line_waiting_for_a_slot361--- PASS: TestRegisterUploadedObjectReusesConnections (0.13s)362=== CONT TestStreamPushStopsOnCancel/lines_read_but_not_taken363=== CONT TestStreamPushStopsOnCancel/full_batch_waiting_for_a_slot364=== CONT TestStreamPushStopsOnCancel/input_closed,_last_batch_waiting_for_a_slot365=== CONT TestStreamPushStopsOnCancel/partial_batch_waiting_for_a_slot366=== CONT TestSetClientTLSErrors/missing_ca_file367=== CONT TestSetClientTLSErrors/invalid_ca_file368=== CONT TestSetClientTLSErrors/missing_key_file369=== CONT TestSupersededNARStillUploadsListing/small_NAR370=== CONT TestSupersededNARStillUploadsListing/dump_cut_short371=== CONT TestSupersededNARStillUploadsListing/listing_upload_fails372=== CONT TestSetClientTLSErrors/missing_cert_file373=== CONT TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/committed_earlier374--- PASS: TestSetClientTLSErrors (0.00s)375 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)376 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)377 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)378 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)379=== CONT TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/cleaned_up380=== CONT TestParsePathInfoJSON/Nix_format381--- PASS: TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent (0.00s)382 --- PASS: TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/committed_earlier (0.00s)383 --- PASS: TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/cleaned_up (0.00s)384=== CONT TestParsePathInfoJSON/invalid_JSON385=== CONT TestParsePathInfoJSON/whitespace_only386=== CONT TestParsePathInfoJSON/empty_input387=== CONT TestParsePathInfoJSON/Lix_format388=== CONT TestPathInfoCACompatibility/old_string_format_-_text389--- PASS: TestParsePathInfoJSON (0.00s)390 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)391 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)392 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)393 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)394 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)395=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method396=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive397=== CONT TestPathInfoCACompatibility/new_structured_format_-_text398=== CONT TestPathInfoCACompatibility/null_ca_field399=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths400--- PASS: TestPathInfoCACompatibility (0.00s)401 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)402 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)403 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)404 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)405 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)406=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths407=== CONT TestSetClientTLS/preserves_debug_logging_transport408--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)409 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)410 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)411=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA412=== CONT TestSetClientTLS/rejects_connection_without_client_cert413=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI414--- PASS: TestStreamPushStopsOnCancel (0.00s)415 --- PASS: TestStreamPushStopsOnCancel/waiting_for_input (0.05s)416 --- PASS: TestStreamPushStopsOnCancel/request_line_waiting_for_a_slot (0.05s)417 --- PASS: TestStreamPushStopsOnCancel/lines_read_but_not_taken (0.05s)418 --- PASS: TestStreamPushStopsOnCancel/full_batch_waiting_for_a_slot (0.05s)419 --- PASS: TestStreamPushStopsOnCancel/input_closed,_last_batch_waiting_for_a_slot (0.05s)420 --- PASS: TestStreamPushStopsOnCancel/partial_batch_waiting_for_a_slot (0.05s)421=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512422=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon423=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)424=== CONT TestEncodeNixBase32/test_string_hash425--- PASS: TestPathInfoHashCompatibility (0.00s)426 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)427 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)428 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)429 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)430=== CONT TestGetStorePathHash/valid_store_path431=== CONT TestEncodeNixBase32/empty_input432=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error433--- PASS: TestEncodeNixBase32 (0.00s)434 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)435 --- PASS: TestEncodeNixBase32/empty_input (0.00s)436=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error437=== CONT TestGetStorePathHash/basename_without_hyphen_should_error438=== CONT TestConvertHashToNix32/invalid_format439=== CONT TestConvertHashToNix32/already_Nix32_format440=== CONT TestConvertHashToNix32/SRI_format_to_Nix32441--- PASS: TestGetStorePathHash (0.00s)442 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)443 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)444 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)445 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)446=== CONT TestFilterOversizedClosures/all_closures_skipped447--- PASS: TestConvertHashToNix32 (0.00s)448 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)449 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)450 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)451=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped452=== CONT TestFilterOversizedClosures/no_limit_keeps_everything453=== CONT TestUploadMultipart_ProducerErrorIsNotEOF/empty_read_on_a_part_boundary454--- PASS: TestFilterOversizedClosures (0.00s)455 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)456 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)457 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)458=== CONT TestUploadMultipart_ProducerErrorIsNotEOF/short_read_inside_a_part459--- PASS: TestSetClientTLS (0.01s)460 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.01s)461 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)462 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.02s)463=== CONT TestUploadMultipart_SupersededByPeer/missing464=== CONT TestUploadMultipart_SupersededByPeer/exists465=== CONT TestStreamPushBatchesUnderLoad/one_at_a_time466--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)467 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)468 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)469=== CONT TestStreamPushBatchesUnderLoad/together470--- PASS: TestStreamPushBatchesUnderLoad (0.00s)471 --- PASS: TestStreamPushBatchesUnderLoad/one_at_a_time (0.00s)472 --- PASS: TestStreamPushBatchesUnderLoad/together (0.00s)473=== CONT TestPartSizeForNAR/small_stays_at_minimum474=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts475=== CONT TestPartSizeForNAR/5_TiB_S3_max_object476=== CONT TestPartSizeForNAR/1_TiB477=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum478=== CONT TestPartSizeForNAR/capped_at_5_GiB479=== CONT TestPartSizeForNAR/zero_stays_at_minimum480--- PASS: TestPartSizeForNAR (0.00s)481 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)482 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)483 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)484 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)485 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)486 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)487 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)488--- PASS: TestUploadMultipart_ProducerErrorIsNotEOF (0.00s)489 --- PASS: TestUploadMultipart_ProducerErrorIsNotEOF/empty_read_on_a_part_boundary (0.03s)490 --- PASS: TestUploadMultipart_ProducerErrorIsNotEOF/short_read_inside_a_part (0.03s)491--- PASS: TestTruncatedNARDumpIsNotCompleted (0.39s)492--- PASS: TestUploadMultipart_FailedPartBufferNotReused (0.64s)493--- PASS: TestUploadMultipart_PartsInParallel (0.67s)494--- PASS: TestSupersededNARStillUploadsListing (0.00s)495 --- PASS: TestSupersededNARStillUploadsListing/small_NAR (0.00s)496 --- PASS: TestSupersededNARStillUploadsListing/listing_upload_fails (0.00s)497 --- PASS: TestSupersededNARStillUploadsListing/dump_cut_short (0.60s)498--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)499--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (2.00s)500--- PASS: TestScriptTokenDoesNotWaitForItsChildren (0.00s)501 --- PASS: TestScriptTokenDoesNotWaitForItsChildren/child_left_holding_stdout (2.02s)502 --- PASS: TestScriptTokenDoesNotWaitForItsChildren/cancelled_while_a_child_runs (2.20s)503PASS504Running server tests...505The files belonging to this database system will be owned by user "_nixbld1".506This user must also own the server process.507508The database cluster will be initialized with locale "C".509The default database encoding has accordingly been set to "SQL_ASCII".510The default text search configuration will be set to "english".511512Data page checksums are enabled.513514creating directory /nix/var/nix/builds/nix-16695-3377832867/postgres3829647661/data ... ok515creating subdirectories ... ok516selecting dynamic shared memory implementation ... posix517selecting default "max_connections" ... 100518selecting default "shared_buffers" ... 128MB519selecting default time zone ... UTC520creating configuration files ... ok521running bootstrap script ... ok522performing post-bootstrap initialization ... ok523syncing data to disk ... ok524525initdb: warning: enabling "trust" authentication for local connections526initdb: 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.527528Success. You can now start the database server using:529530 pg_ctl -D /nix/var/nix/builds/nix-16695-3377832867/postgres3829647661/data -l logfile start531532/nix/var/nix/builds/nix-16695-3377832867/postgres3829647661:5432 - no response5332026-09-24 18:04:52.691 UTC [16741] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit5342026-09-24 18:04:52.691 UTC [16741] LOG: listening on Unix socket "/nix/var/nix/builds/nix-16695-3377832867/postgres3829647661/.s.PGSQL.5432"5352026-09-24 18:04:52.693 UTC [16748] LOG: database system was shut down at 2026-09-24 18:04:52 UTC5362026-09-24 18:04:52.694 UTC [16741] LOG: database system is ready to accept connections537/nix/var/nix/builds/nix-16695-3377832867/postgres3829647661:5432 - accepting connections538{"timestamp":"2026-09-24T18:04:52.910969Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"8fa84354-2131-461f-a6c7-c4c39ef80fc2","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":463,"threadName":"rustfs-worker","threadId":"ThreadId(6)"}539=== RUN TestService_AuthMiddleware540=== PAUSE TestService_AuthMiddleware541=== RUN TestService_AuthMiddleware_MTLSProxyHeader542=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader543=== RUN TestService_AuthMiddleware_MTLSBoundSubjects544=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects545=== RUN TestService_ReadAuthMiddleware546=== PAUSE TestService_ReadAuthMiddleware547=== RUN TestService_AuthMiddleware_OIDC548=== PAUSE TestService_AuthMiddleware_OIDC549=== RUN TestService_RequireScope_OIDC550=== PAUSE TestService_RequireScope_OIDC551=== RUN TestService_ReadScope_PublicByDefault552=== PAUSE TestService_ReadScope_PublicByDefault553=== RUN TestCacheConfigHandler554=== PAUSE TestCacheConfigHandler555=== RUN TestCacheStatsHandler556=== PAUSE TestCacheStatsHandler557=== RUN TestClientCADerivations558=== PAUSE TestClientCADerivations559=== RUN TestClientErrorHandling560=== PAUSE TestClientErrorHandling561=== RUN TestClientIntegration562=== PAUSE TestClientIntegration563=== RUN TestClientMultipleUploads564=== PAUSE TestClientMultipleUploads565=== RUN TestClientWithDependencies566=== PAUSE TestClientWithDependencies567=== RUN TestClientSharedPathCommittedMidPush568=== PAUSE TestClientSharedPathCommittedMidPush569=== RUN TestPinProtectsFromGC570=== PAUSE TestPinProtectsFromGC571=== RUN TestClientPushesUseOnePush572=== PAUSE TestClientPushesUseOnePush573=== RUN TestClientFallsBackToClosures574=== PAUSE TestClientFallsBackToClosures575=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock576=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock577=== RUN TestResolveDBConnectionString578=== PAUSE TestResolveDBConnectionString579=== RUN TestConnectWaitsForAPeerMigration580=== PAUSE TestConnectWaitsForAPeerMigration581=== RUN TestConnectSerialisesConcurrentMigrations582=== PAUSE TestConnectSerialisesConcurrentMigrations583=== RUN TestLeadElectsOneAndHandsOver584=== PAUSE TestLeadElectsOneAndHandsOver585=== RUN TestLeadIncumbentWinsAfterRestart5862026/09/24 18:04:53 INFO lead: acquired remote=192.0.2.1:12345872026/09/24 18:04:54 INFO lead: released remote=192.0.2.1:12345882026/09/24 18:04:54 INFO lead: acquired remote=192.0.2.1:12345892026/09/24 18:04:55 INFO lead: released remote=192.0.2.1:1234590--- PASS: TestLeadIncumbentWinsAfterRestart (2.34s)591=== RUN TestLeadEndsOnShutdown592=== PAUSE TestLeadEndsOnShutdown593=== RUN TestLeadEndsWhenItsConnectionHangs5942026/09/24 18:04:55 INFO lead: acquired remote=192.0.2.1:12345952026-09-24 18:04:56.709 UTC [16784] FATAL: terminating connection due to administrator command5962026/09/24 18:04:56 INFO lead: acquired remote=192.0.2.1:12345972026/09/24 18:04:57 WARN lead: lock connection lost error="timeout: context deadline exceeded"5982026/09/24 18:04:57 INFO lead: released remote=192.0.2.1:12345992026/09/24 18:04:58 INFO lead: released remote=192.0.2.1:1234600--- PASS: TestLeadEndsWhenItsConnectionHangs (2.77s)601=== RUN TestGCAdvisoryLockBlocksConcurrentRun602=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun603=== RUN TestGCBugBareHashReferences604=== PAUSE TestGCBugBareHashReferences605=== RUN TestGCMetrics606=== PAUSE TestGCMetrics607=== RUN TestPushDedupSurvivesConcurrentGC608=== PAUSE TestPushDedupSurvivesConcurrentGC609=== RUN TestDeduplicatedObjectsRecordedAsPending610=== PAUSE TestDeduplicatedObjectsRecordedAsPending611=== RUN TestGCSweepSkipsPendingObjects612=== PAUSE TestGCSweepSkipsPendingObjects613=== RUN TestTombstonedObjectOfferedWithoutWaiting614=== PAUSE TestTombstonedObjectOfferedWithoutWaiting615=== RUN TestGCSweepDeliversEachKeyOnce616=== PAUSE TestGCSweepDeliversEachKeyOnce617=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection618=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection619=== RUN TestForceGCDuringPushOffersSweptObject620=== PAUSE TestForceGCDuringPushOffersSweptObject621=== RUN TestSweepRowDeleteSparesResurrectedObject622=== PAUSE TestSweepRowDeleteSparesResurrectedObject623=== RUN TestSweepSparesObjectReuploadedMidSweep624=== PAUSE TestSweepSparesObjectReuploadedMidSweep625=== RUN TestCommitRacingPendingCleanupKeepsObjects626=== PAUSE TestCommitRacingPendingCleanupKeepsObjects627=== RUN TestGCEndsOnShutdown628=== PAUSE TestGCEndsOnShutdown629=== RUN TestGCTaskStore_StartNew630=== PAUSE TestGCTaskStore_StartNew631=== RUN TestGCTaskStore_DeduplicateSameParams632=== PAUSE TestGCTaskStore_DeduplicateSameParams633=== RUN TestGCTaskStore_ConflictDifferentParams634=== PAUSE TestGCTaskStore_ConflictDifferentParams635=== RUN TestGCTaskStore_GetEmpty636=== PAUSE TestGCTaskStore_GetEmpty637=== RUN TestGCTaskStore_GetReturnsLatest638=== PAUSE TestGCTaskStore_GetReturnsLatest639=== RUN TestGCTaskStore_CompletedAllowsNewTask640=== PAUSE TestGCTaskStore_CompletedAllowsNewTask641=== RUN TestGCTaskStore_PhaseUpdates642=== PAUSE TestGCTaskStore_PhaseUpdates643=== RUN TestGCTaskStore_Fail644=== PAUSE TestGCTaskStore_Fail645=== RUN TestGracefulShutdownDrainsInflight646=== PAUSE TestGracefulShutdownDrainsInflight647=== RUN TestService_healthCheckHandler648=== PAUSE TestService_healthCheckHandler649=== RUN TestService_readinessHandler650=== PAUSE TestService_readinessHandler651=== RUN TestGenerateLandingPage652=== PAUSE TestGenerateLandingPage653=== RUN TestCacheConfigHandlerMaxNarSize654=== PAUSE TestCacheConfigHandlerMaxNarSize655=== RUN TestCreatePendingClosureRejectsOversizedNAR656=== PAUSE TestCreatePendingClosureRejectsOversizedNAR657=== RUN TestNARDeduplicationMetadataUploadBug658=== PAUSE TestNARDeduplicationMetadataUploadBug659=== RUN TestMetricsInventory660=== PAUSE TestMetricsInventory661=== RUN TestService_NativeMTLS662=== PAUSE TestService_NativeMTLS663=== RUN TestServerTLSConfig664=== PAUSE TestServerTLSConfig665=== RUN TestMultipartCleanup666=== PAUSE TestMultipartCleanup667=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded668=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded669=== RUN TestPendingCleanupUsesOneCutoff670=== PAUSE TestPendingCleanupUsesOneCutoff671=== RUN TestPendingClosureFailureTracksEveryUpload672=== PAUSE TestPendingClosureFailureTracksEveryUpload673=== RUN TestPendingClosureFailureAbortsItsUploads674=== PAUSE TestPendingClosureFailureAbortsItsUploads675=== RUN TestObjectStatsTrigger676=== PAUSE TestObjectStatsTrigger677=== RUN TestReconnectLeavesObjectsUnlocked678=== PAUSE TestReconnectLeavesObjectsUnlocked679=== RUN TestValidateS3Concurrency680=== PAUSE TestValidateS3Concurrency681=== RUN TestOrphanedObjectsGC682=== PAUSE TestOrphanedObjectsGC683=== RUN TestOrphanedObjectsGCStressTest684=== PAUSE TestOrphanedObjectsGCStressTest685=== RUN TestResurrectedObjectNotDeleted686=== PAUSE TestResurrectedObjectNotDeleted687=== RUN TestSweepKeepsTombstoneWhenDeleteOutcomeUnknown688=== PAUSE TestSweepKeepsTombstoneWhenDeleteOutcomeUnknown689=== RUN TestCreatePin_ReservedPins690=== PAUSE TestCreatePin_ReservedPins691=== RUN TestConcurrentPinUpdatesAgree692=== PAUSE TestConcurrentPinUpdatesAgree693=== RUN TestCreatePinRejectsBadInput694=== PAUSE TestCreatePinRejectsBadInput695=== RUN TestDeletePinKeepsRowWhenS3Fails696=== PAUSE TestDeletePinKeepsRowWhenS3Fails697=== RUN TestPresentReportsOnlyClosureRoots698=== PAUSE TestPresentReportsOnlyClosureRoots699=== RUN TestPresentNotReportedWhileGCDeletesClosure700=== PAUSE TestPresentNotReportedWhileGCDeletesClosure701=== RUN TestParseSingleRange702=== PAUSE TestParseSingleRange703=== RUN TestProxyHeadersOnlyTrustedOnSocket704=== PAUSE TestProxyHeadersOnlyTrustedOnSocket705=== RUN TestIsValidCachePath706=== PAUSE TestIsValidCachePath707=== RUN TestReadProxyNarinfo708=== PAUSE TestReadProxyNarinfo709=== RUN TestReadProxyNarinfoAlreadyDecompressed710=== PAUSE TestReadProxyNarinfoAlreadyDecompressed711=== RUN TestReadProxyNarStreaming712=== PAUSE TestReadProxyNarStreaming713=== RUN TestReadProxy404714=== PAUSE TestReadProxy404715=== RUN TestReadProxyInvalidPath716=== PAUSE TestReadProxyInvalidPath717=== RUN TestReadProxyHead718=== PAUSE TestReadProxyHead719=== RUN TestReadProxyOutlastsServerWriteTimeout720=== PAUSE TestReadProxyOutlastsServerWriteTimeout721=== RUN TestReadProxyConditionalGet722=== PAUSE TestReadProxyConditionalGet723=== RUN TestReadProxyRootRedirectsToIndexHTML724=== PAUSE TestReadProxyRootRedirectsToIndexHTML725=== RUN TestReadProxyDisabled726=== PAUSE TestReadProxyDisabled727=== RUN TestReadRedirectNar728=== PAUSE TestReadRedirectNar729=== RUN TestReadRedirectKeepsNarinfoProxied730=== PAUSE TestReadRedirectKeepsNarinfoProxied731=== RUN TestReadProxyRangeRequest732=== PAUSE TestReadProxyRangeRequest733=== RUN TestReadRedirectUsesPublicS3URL734=== PAUSE TestReadRedirectUsesPublicS3URL735=== RUN TestPush_OverlappingRootsStoreOneRowPerKey736=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey737=== RUN TestPush_CompleteCommitsEveryRoot738=== PAUSE TestPush_CompleteCommitsEveryRoot739=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit740=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit741=== RUN TestPush_RejectsBadRequests742=== PAUSE TestPush_RejectsBadRequests743=== RUN TestPush_SignsNarinfosOfItsPendingObjects744=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects745=== RUN TestRedundantMultipartUpload746=== PAUSE TestRedundantMultipartUpload747=== RUN TestCompleteMultipartUpload_ErrorButObjectExists748=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists749=== RUN TestCompletedNarNotReofferedAcrossClosures750=== PAUSE TestCompletedNarNotReofferedAcrossClosures751=== RUN TestPresignedUploadRegisteredBeforeCommit752=== PAUSE TestPresignedUploadRegisteredBeforeCommit753=== RUN TestService_Rustfstest754=== PAUSE TestService_Rustfstest755=== RUN TestParseSize756=== PAUSE TestParseSize757=== RUN TestSkippedUploadsHandler758=== PAUSE TestSkippedUploadsHandler759=== RUN TestSystemdListenerNotActivated760--- PASS: TestSystemdListenerNotActivated (0.00s)761=== RUN TestWatchdogBeatsWhenHealthy762--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)763=== RUN TestWatchdogSkipsWhenUnhealthy7642026/09/24 18:04:58 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7652026/09/24 18:04:58 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7662026/09/24 18:04:58 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7672026/09/24 18:04:58 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7682026/09/24 18:04:58 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7692026/09/24 18:04:58 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7702026/09/24 18:04:58 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7712026/09/24 18:04:58 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7722026/09/24 18:04:58 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7732026/09/24 18:04:58 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"774--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)775=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle776=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle777=== RUN TestProxyWriteTimeout778=== PAUSE TestProxyWriteTimeout779=== RUN TestPendingClosureWriteTimeout780=== PAUSE TestPendingClosureWriteTimeout781=== RUN TestIsValidUploadKey782=== PAUSE TestIsValidUploadKey783=== RUN TestUploadHandlersRejectInvalidKeys784=== PAUSE TestUploadHandlersRejectInvalidKeys785=== RUN TestUploadHandlersRejectOversizedBody786=== PAUSE TestUploadHandlersRejectOversizedBody787=== RUN TestService_cleanupPendingClosuresHandler788=== PAUSE TestService_cleanupPendingClosuresHandler789=== RUN TestService_createPendingClosureHandler790=== PAUSE TestService_createPendingClosureHandler791=== RUN TestService_verifyS3Integrity792=== PAUSE TestService_verifyS3Integrity793=== RUN TestCompleteMultipartUnregistered794=== PAUSE TestCompleteMultipartUnregistered795=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT796=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT797=== CONT TestObjectStatsTrigger798=== CONT TestReadRedirectNar799=== CONT TestService_AuthMiddleware_MTLSBoundSubjects800=== CONT TestTombstonedObjectOfferedWithoutWaiting801=== CONT TestGCSweepSkipsPendingObjects802=== CONT TestPendingClosureFailureAbortsItsUploads803=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection804=== CONT TestPendingClosureFailureTracksEveryUpload805=== CONT TestDeduplicatedObjectsRecordedAsPending806=== CONT TestPendingCleanupUsesOneCutoff8072026/09/24 18:04:58 INFO Received uploads request method=POST path=/api/pending_closures808=== CONT TestReconnectLeavesObjectsUnlocked809--- PASS: TestTombstonedObjectOfferedWithoutWaiting (0.45s)810--- PASS: TestObjectStatsTrigger (0.61s)811=== CONT TestGCAdvisoryLockBlocksConcurrentRun8122026/09/24 18:04:59 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"8132026/09/24 18:04:59 WARN mTLS auth: bound subjects configured but subject DN unavailable8142026/09/24 18:04:59 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"815--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.74s)816=== CONT TestGCBugBareHashReferences8172026/09/24 18:04:59 INFO Received uploads request method=POST path=/api/pending_closures8182026/09/24 18:04:59 INFO Aborted multipart uploads count=0 kept=08192026/09/24 18:04:59 WARN Force mode enabled - objects will be deleted immediately without grace period8202026/09/24 18:04:59 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=08212026/09/24 18:04:59 INFO Vacuumed table table=pending_closures8222026/09/24 18:04:59 INFO Vacuumed table table=pending_objects8232026/09/24 18:04:59 INFO Vacuumed table table=multipart_uploads8242026/09/24 18:04:59 INFO Vacuumed table table=closures8252026/09/24 18:04:59 INFO Vacuumed table table=objects826--- PASS: TestGCSweepSkipsPendingObjects (1.07s)827=== CONT TestGCMetrics828--- PASS: TestReadRedirectNar (1.13s)829=== CONT TestMultipartCleanup8302026/09/24 18:04:59 INFO Received uploads request method=POST path=/api/pending_closures8312026/09/24 18:04:59 INFO Received uploads request method=POST path=/api/pending_closures8322026/09/24 18:04:59 INFO Received uploads request method=POST path=/api/pending_closures833--- PASS: TestDeduplicatedObjectsRecordedAsPending (1.66s)834=== CONT TestLeadElectsOneAndHandsOver835--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (1.72s)836=== CONT TestCompleteMultipartUnregistered8372026/09/24 18:05:00 INFO Received uploads request method=POST path=/api/pending_closures838--- PASS: TestPendingClosureFailureTracksEveryUpload (1.83s)839=== CONT TestServerTLSConfig840=== RUN TestServerTLSConfig/no_client_CA841=== PAUSE TestServerTLSConfig/no_client_CA842=== RUN TestServerTLSConfig/missing_CA_file843=== PAUSE TestServerTLSConfig/missing_CA_file844=== RUN TestServerTLSConfig/not_a_PEM_file845=== PAUSE TestServerTLSConfig/not_a_PEM_file846=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded847--- PASS: TestPendingClosureFailureAbortsItsUploads (1.85s)848=== CONT TestService_Rustfstest8492026/09/24 18:05:00 INFO Received uploads request method=POST path=/api/pending_closures8502026/09/24 18:05:00 INFO Received uploads request method=POST path=/api/pending_closures8512026/09/24 18:05:00 INFO Received cleanup request method=DELETE path=/api/pending_closures852--- PASS: TestReconnectLeavesObjectsUnlocked (1.73s)853=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT8542026/09/24 18:05:01 INFO Aborted multipart uploads count=0 kept=08552026/09/24 18:05:01 WARN Force mode enabled - objects will be deleted immediately without grace period8562026/09/24 18:05: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=08572026/09/24 18:05:01 INFO Vacuumed table table=pending_closures8582026/09/24 18:05:01 INFO Vacuumed table table=pending_objects8592026/09/24 18:05:01 INFO Vacuumed table table=multipart_uploads8602026/09/24 18:05:01 INFO Vacuumed table table=closures8612026/09/24 18:05:01 INFO Vacuumed table table=objects862--- PASS: TestGCMetrics (1.62s)863=== CONT TestConnectSerialisesConcurrentMigrations864--- PASS: TestGCBugBareHashReferences (1.96s)865=== CONT TestResolveDBConnectionString866=== RUN TestResolveDBConnectionString/flag_wins867=== PAUSE TestResolveDBConnectionString/flag_wins868=== RUN TestResolveDBConnectionString/file_when_flag_empty869=== PAUSE TestResolveDBConnectionString/file_when_flag_empty870=== RUN TestResolveDBConnectionString/missing_file_is_an_error871=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error872=== RUN TestResolveDBConnectionString/PGHOST_allows_empty873=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty874=== RUN TestResolveDBConnectionString/nothing_configured875=== PAUSE TestResolveDBConnectionString/nothing_configured876=== CONT TestLeadEndsOnShutdown8772026/09/24 18:05:01 INFO Received uploads request method=POST path=/api/pending_closures8782026/09/24 18:05:01 INFO Received cleanup request method=DELETE path=/api/pending_closures8792026/09/24 18:05:01 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket17/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""8802026/09/24 18:05:01 INFO Aborted multipart uploads count=0 kept=18812026/09/24 18:05:01 INFO Received cleanup request method=DELETE path=/api/pending_closures8822026/09/24 18:05:01 INFO Aborted multipart uploads count=1 kept=0883--- PASS: TestMultipartCleanup (1.92s)884=== CONT TestService_verifyS3Integrity8852026/09/24 18:05:01 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8862026/09/24 18:05:01 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst887--- PASS: TestCompleteMultipartUnregistered (1.35s)888=== CONT TestService_createPendingClosureHandler8892026/09/24 18:05:01 INFO Received uploads request method=POST path=/api/pending_closures890--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (1.48s)891=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock892--- PASS: TestService_Rustfstest (1.58s)893=== CONT TestUploadHandlersRejectInvalidKeys894=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info895=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info896=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal897=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal898=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key899=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key900=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key901=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key902=== CONT TestIsValidUploadKey903=== RUN TestIsValidUploadKey/narinfo904=== PAUSE TestIsValidUploadKey/narinfo905=== RUN TestIsValidUploadKey/nar_zst906=== PAUSE TestIsValidUploadKey/nar_zst907=== RUN TestIsValidUploadKey/nar_xz908=== PAUSE TestIsValidUploadKey/nar_xz909=== RUN TestIsValidUploadKey/nar_plain910=== PAUSE TestIsValidUploadKey/nar_plain911=== RUN TestIsValidUploadKey/listing912=== PAUSE TestIsValidUploadKey/listing913=== RUN TestIsValidUploadKey/build_log914=== PAUSE TestIsValidUploadKey/build_log915=== RUN TestIsValidUploadKey/build_log_home-manager_file916=== PAUSE TestIsValidUploadKey/build_log_home-manager_file917=== RUN TestIsValidUploadKey/build_log_plus_in_name918=== PAUSE TestIsValidUploadKey/build_log_plus_in_name919=== RUN TestIsValidUploadKey/build_log_question_mark920=== PAUSE TestIsValidUploadKey/build_log_question_mark921=== RUN TestIsValidUploadKey/build_log_equals922=== PAUSE TestIsValidUploadKey/build_log_equals923=== RUN TestIsValidUploadKey/realisation924=== PAUSE TestIsValidUploadKey/realisation925=== RUN TestIsValidUploadKey/realisation_plus_in_output926=== PAUSE TestIsValidUploadKey/realisation_plus_in_output927=== RUN TestIsValidUploadKey/nix-cache-info928=== PAUSE TestIsValidUploadKey/nix-cache-info929=== RUN TestIsValidUploadKey/index.html930=== PAUSE TestIsValidUploadKey/index.html931=== RUN TestIsValidUploadKey/narinfo_key,_nar_type932=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type933=== RUN TestIsValidUploadKey/nar_key,_narinfo_type934=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type935=== RUN TestIsValidUploadKey/listing_key,_narinfo_type936=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type937=== RUN TestIsValidUploadKey/traversal938=== PAUSE TestIsValidUploadKey/traversal939=== RUN TestIsValidUploadKey/traversal_nar940=== PAUSE TestIsValidUploadKey/traversal_nar941=== RUN TestIsValidUploadKey/absolute942=== PAUSE TestIsValidUploadKey/absolute943=== RUN TestIsValidUploadKey/empty_key944=== PAUSE TestIsValidUploadKey/empty_key945=== RUN TestIsValidUploadKey/unknown_type946=== PAUSE TestIsValidUploadKey/unknown_type947=== CONT TestPendingClosureWriteTimeout948=== RUN TestPendingClosureWriteTimeout/empty949=== PAUSE TestPendingClosureWriteTimeout/empty950=== RUN TestPendingClosureWriteTimeout/negative951=== PAUSE TestPendingClosureWriteTimeout/negative952=== RUN TestPendingClosureWriteTimeout/400_objects953=== PAUSE TestPendingClosureWriteTimeout/400_objects954=== RUN TestPendingClosureWriteTimeout/670k_objects955=== PAUSE TestPendingClosureWriteTimeout/670k_objects956=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline957=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline958=== CONT TestService_cleanupPendingClosuresHandler9592026/09/24 18:05:01 INFO lead: acquired remote=192.0.2.1:12349602026-09-24 18:05:01.994 UTC [16886] ERROR: duplicate key value violates unique constraint "pg_class_relname_nsp_index"9612026-09-24 18:05:01.994 UTC [16886] DETAIL: Key (relname, relnamespace)=(goose_db_version_id_seq, 2200) already exists.9622026-09-24 18:05:01.994 UTC [16886] STATEMENT: CREATE TABLE goose_db_version (963 id integer PRIMARY KEY GENERATED BY DEFAULT AS IDENTITY,964 version_id bigint NOT NULL,965 is_applied boolean NOT NULL,966 tstamp timestamp NOT NULL DEFAULT now()967 )9682026/09/24 18:05:02 INFO Received uploads request method=POST path=/api/pending_closures969--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (1.66s)970=== CONT TestProxyWriteTimeout971=== RUN TestProxyWriteTimeout/narinfo972=== PAUSE TestProxyWriteTimeout/narinfo973=== RUN TestProxyWriteTimeout/1_GiB_nar974=== PAUSE TestProxyWriteTimeout/1_GiB_nar975=== RUN TestProxyWriteTimeout/10_GiB_nar976=== PAUSE TestProxyWriteTimeout/10_GiB_nar977=== RUN TestProxyWriteTimeout/unknown_size978=== PAUSE TestProxyWriteTimeout/unknown_size979=== CONT TestClientFallsBackToClosures9802026/09/24 18:05:02 ERROR failed to check GC advisory lock error="query pg_locks: failed to connect to `user=_nixbld1 database=niks3`: /nonexistent/.s.PGSQL.5432 (/nonexistent): dial error: dial unix /nonexistent/.s.PGSQL.5432: connect: no such file or directory"981--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (3.39s)982=== CONT TestSkippedUploadsHandler9832026/09/24 18:05:02 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000984--- PASS: TestSkippedUploadsHandler (0.00s)985=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle9862026/09/24 18:05:02 INFO lead: acquired remote=192.0.2.1:12349872026/09/24 18:05:02 INFO Received uploads request method=POST path=/api/pending_closures9882026/09/24 18:05:02 INFO Received uploads request method=POST path=/api/pending_closures9892026/09/24 18:05:02 INFO Received uploads request method=POST path=/api/pending_closures9902026/09/24 18:05:02 INFO Received uploads request method=POST path=/api/pending_closures991=== CONT TestParseSingleRange992=== RUN TestParseSingleRange/none993--- PASS: TestConnectSerialisesConcurrentMigrations (1.99s)994=== PAUSE TestParseSingleRange/none995=== RUN TestParseSingleRange/unknown_unit996=== PAUSE TestParseSingleRange/unknown_unit997=== RUN TestParseSingleRange/multi-range_ignored998=== PAUSE TestParseSingleRange/multi-range_ignored999=== RUN TestParseSingleRange/malformed_no_dash1000=== PAUSE TestParseSingleRange/malformed_no_dash1001=== RUN TestParseSingleRange/malformed_both_empty1002=== PAUSE TestParseSingleRange/malformed_both_empty1003=== RUN TestParseSingleRange/malformed_end_before_start1004=== PAUSE TestParseSingleRange/malformed_end_before_start1005=== RUN TestParseSingleRange/closed1006=== PAUSE TestParseSingleRange/closed1007=== RUN TestParseSingleRange/open-ended1008=== PAUSE TestParseSingleRange/open-ended1009=== RUN TestParseSingleRange/end_clamped_to_size1010=== PAUSE TestParseSingleRange/end_clamped_to_size1011=== RUN TestParseSingleRange/suffix1012=== PAUSE TestParseSingleRange/suffix1013=== RUN TestParseSingleRange/suffix_exceeds_size1014=== PAUSE TestParseSingleRange/suffix_exceeds_size1015=== RUN TestParseSingleRange/single_byte1016=== PAUSE TestParseSingleRange/single_byte1017=== RUN TestParseSingleRange/start_past_EOF1018=== PAUSE TestParseSingleRange/start_past_EOF1019=== RUN TestParseSingleRange/start_far_past_EOF1020=== PAUSE TestParseSingleRange/start_far_past_EOF1021=== CONT TestReadProxyRangeRequest10222026/09/24 18:05:03 INFO lead: released remote=192.0.2.1:123410232026/09/24 18:05:03 INFO lead: acquired remote=192.0.2.1:123410242026/09/24 18:05:03 INFO Received cleanup request method=DELETE path=/api/pending_closures10252026/09/24 18:05:03 INFO Aborted multipart uploads count=0 kept=010262026/09/24 18:05:03 INFO Received uploads request method=POST path=/api/pending_closures10272026/09/24 18:05:03 INFO Received cleanup request method=DELETE path=/api/pending_closures10282026/09/24 18:05:03 INFO Aborted multipart uploads count=1 kept=010292026/09/24 18:05:03 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10302026-09-24 18:05:03.525 UTC [16899] ERROR: Closure does not exist: id=110312026-09-24 18:05:03.525 UTC [16899] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 19 at RAISE10322026-09-24 18:05:03.525 UTC [16899] STATEMENT: -- name: CommitPendingClosure :exec1033 SELECT commit_pending_closure($1::bigint)1034 1035--- PASS: TestService_cleanupPendingClosuresHandler (1.74s)1036=== CONT TestConnectWaitsForAPeerMigration10372026/09/24 18:05:03 INFO lead: released remote=192.0.2.1:12341038--- PASS: TestLeadEndsOnShutdown (2.50s)1039=== CONT TestReadProxyRootRedirectsToIndexHTML10402026/09/24 18:05:03 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10412026/09/24 18:05:03 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=NDc3YzAzNzQtNDI2Yy00MTM0LTg2ZmEtYThmMDFjOTM4M2UxLjRkMjdlOWM4LTdmNzgtNDQxNS05MmYyLWRiNzk1NTU3YzU0MngxNzkwMjczMTAyNzY0ODM5MDAw parts=1010422026/09/24 18:05:03 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10432026/09/24 18:05:04 INFO Completed upload id=110442026/09/24 18:05:04 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000010452026/09/24 18:05:04 INFO Received uploads request method=POST path=/api/pending_closures10462026/09/24 18:05:04 INFO Starting cleanup of old closures method=DELETE path=/api/closures10472026/09/24 18:05:04 INFO Aborted multipart uploads count=0 kept=010482026/09/24 18:05:04 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=010492026/09/24 18:05:04 INFO Vacuumed table table=pending_closures10502026/09/24 18:05:04 INFO Vacuumed table table=pending_objects10512026/09/24 18:05:04 INFO Vacuumed table table=multipart_uploads10522026/09/24 18:05:04 INFO Vacuumed table table=closures10532026/09/24 18:05:04 INFO Received uploads request method=POST path=/api/pending_closures10542026/09/24 18:05:04 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10552026/09/24 18:05:04 INFO Vacuumed table table=objects10562026/09/24 18:05:04 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001057--- PASS: TestService_createPendingClosureHandler (2.74s)1058=== CONT TestReadProxyConditionalGet10592026/09/24 18:05:04 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=NDc3YzAzNzQtNDI2Yy00MTM0LTg2ZmEtYThmMDFjOTM4M2UxLjczYjhiMzRjLWI3ZmMtNDBlOS05MDhiLTZiMmNlNTRkNDgwY3gxNzkwMjczMTAyOTQxMzQ0MDAw parts=1010602026/09/24 18:05:04 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10612026/09/24 18:05:04 INFO Completed upload id=110622026/09/24 18:05:04 INFO Received uploads request method=POST path=/api/pending_closures10632026/09/24 18:05:04 INFO Received uploads request method=POST path=/api/pending_closures10642026/09/24 18:05:04 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo10652026/09/24 18:05:04 WARN Found objects in DB but missing from S3, will re-upload count=110662026/09/24 18:05:04 INFO Received complete upload request method=POST path=/api/pending_closures/3/complete10672026/09/24 18:05:04 INFO Completed upload id=31068--- PASS: TestService_verifyS3Integrity (2.82s)1069=== CONT TestService_NativeMTLS10702026/09/24 18:05:04 INFO lead: released remote=192.0.2.1:12341071--- PASS: TestLeadElectsOneAndHandsOver (4.25s)1072=== CONT TestReadProxyDisabled10732026/09/24 18:05:04 INFO Received uploads request method=POST path=/api/pending_closures10742026/09/24 18:05:04 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10752026/09/24 18:05:04 INFO Received uploads request method=POST path=/api/pending_closures10762026/09/24 18:05:04 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)10772026/09/24 18:05:04 INFO Uploading 5zy3zw6hs2mjx1y9sz3j82pd10wpkj17-shared-dep (136B)10782026/09/24 18:05:04 INFO Uploading 3b82353pchr1yn87l1wlb28mgij3wsrx-b (248B)10792026/09/24 18:05:04 WARN Failed to register uploaded object key=yayplgsk6lqca4d19hpxj1dhl3mlyyj2.ls error="server returned 404: 404 page not found\n"10802026/09/24 18:05:04 WARN Failed to register uploaded object key=5zy3zw6hs2mjx1y9sz3j82pd10wpkj17.ls error="server returned 404: 404 page not found\n"10812026/09/24 18:05:04 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"10822026/09/24 18:05:04 WARN Failed to register uploaded object key=nar/124g91fl5124kq9w7401x9zsxnvscg3xn6rak8k98g3fbx7shfs6.nar.zst error="server returned 404: 404 page not found\n"10832026/09/24 18:05:04 WARN Failed to register uploaded object key=3b82353pchr1yn87l1wlb28mgij3wsrx.ls error="server returned 404: 404 page not found\n"10842026/09/24 18:05:04 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign10852026/09/24 18:05:04 INFO Signed narinfos id=1 count=210862026/09/24 18:05:04 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign10872026/09/24 18:05:04 INFO Signed narinfos id=2 count=210882026/09/24 18:05:04 INFO Uploading 4 narinfos10892026/09/24 18:05:04 WARN Failed to register uploaded object key=3b82353pchr1yn87l1wlb28mgij3wsrx.narinfo error="server returned 404: 404 page not found\n"10902026/09/24 18:05:04 WARN Failed to register uploaded object key=5zy3zw6hs2mjx1y9sz3j82pd10wpkj17.narinfo error="server returned 404: 404 page not found\n"10912026/09/24 18:05:04 WARN Failed to register uploaded object key=yayplgsk6lqca4d19hpxj1dhl3mlyyj2.narinfo error="server returned 404: 404 page not found\n"10922026/09/24 18:05:04 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10932026/09/24 18:05:04 WARN Failed to register uploaded object key=5zy3zw6hs2mjx1y9sz3j82pd10wpkj17.narinfo error="server returned 404: 404 page not found\n"10942026/09/24 18:05:04 INFO Completed upload id=110952026/09/24 18:05:04 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete10962026/09/24 18:05:04 INFO Completed upload id=210972026/09/24 18:05:04 INFO Upload complete. (145ms)1098=== NAME TestClientFallsBackToClosures1099 client_pushes_test.go:112: Retrieved narinfo from S3:1100 StorePath: /nix/var/nix/builds/nix-16695-3377832867/TestClientFallsBackToClosures32720818/001/store/5zy3zw6hs2mjx1y9sz3j82pd10wpkj17-shared-dep1101 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1102 Compression: zstd1103 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821104 NarSize: 1361105 References: 1106 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1107 client_pushes_test.go:112: Retrieved narinfo from S3:1108 StorePath: /nix/var/nix/builds/nix-16695-3377832867/TestClientFallsBackToClosures32720818/001/store/yayplgsk6lqca4d19hpxj1dhl3mlyyj2-a1109 URL: nar/124g91fl5124kq9w7401x9zsxnvscg3xn6rak8k98g3fbx7shfs6.nar.zst1110 Compression: zstd1111 NarHash: sha256:124g91fl5124kq9w7401x9zsxnvscg3xn6rak8k98g3fbx7shfs61112 NarSize: 2481113 References: /nix/var/nix/builds/nix-16695-3377832867/TestClientFallsBackToClosures32720818/001/store/5zy3zw6hs2mjx1y9sz3j82pd10wpkj17-shared-dep1114 CA: text:sha256:07x834ykl37jcmv09lbiffkwvd0cm3gz92gwlv1xyz94scx99aqa1115 client_pushes_test.go:112: Retrieved narinfo from S3:1116 StorePath: /nix/var/nix/builds/nix-16695-3377832867/TestClientFallsBackToClosures32720818/001/store/3b82353pchr1yn87l1wlb28mgij3wsrx-b1117 URL: nar/124g91fl5124kq9w7401x9zsxnvscg3xn6rak8k98g3fbx7shfs6.nar.zst1118 Compression: zstd1119 NarHash: sha256:124g91fl5124kq9w7401x9zsxnvscg3xn6rak8k98g3fbx7shfs61120 NarSize: 2481121 References: /nix/var/nix/builds/nix-16695-3377832867/TestClientFallsBackToClosures32720818/001/store/5zy3zw6hs2mjx1y9sz3j82pd10wpkj17-shared-dep1122 CA: text:sha256:07x834ykl37jcmv09lbiffkwvd0cm3gz92gwlv1xyz94scx99aqa1123--- PASS: TestClientFallsBackToClosures (2.33s)1124=== CONT TestNARDeduplicationMetadataUploadBug1125--- PASS: TestReadProxyRangeRequest (1.92s)1126=== CONT TestReadProxy4041127--- PASS: TestReadProxyRootRedirectsToIndexHTML (1.83s)1128=== CONT TestCreatePendingClosureRejectsOversizedNAR11292026/09/24 18:05:05 INFO Received uploads request method=POST path=/api/pending_closures1130--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1131=== CONT TestReadProxyNarStreaming1132--- PASS: TestReadProxyConditionalGet (1.56s)1133=== CONT TestMetricsInventory1134--- PASS: TestReadProxyDisabled (1.71s)1135=== CONT TestReadProxyHead1136--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (4.41s)1137=== CONT TestCacheConfigHandlerMaxNarSize1138--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1139=== CONT TestReadProxyNarinfo11402026/09/24 18:05:06 INFO Aborted multipart uploads count=1 kept=011412026/09/24 18:05:06 INFO Received cleanup request method=DELETE path=/api/pending_closures11422026/09/24 18:05:06 INFO Aborted multipart uploads count=1 kept=01143--- PASS: TestPendingCleanupUsesOneCutoff (8.14s)1144=== CONT TestService_readinessHandler11452026/09/24 18:05:06 WARN mTLS auth: subject not in bound subjects subject="CN=reader"11462026/09/24 18:05:06 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1147=== NAME TestNARDeduplicationMetadataUploadBug1148 metadata_upload_test.go:48: First store path: /nix/var/nix/builds/nix-16695-3377832867/TestNARDeduplicationMetadataUploadBug3027340354/001/store/0krx3hi7pnrcnx1ilhbvmigg768cawr0-file1.txt1149--- PASS: TestService_NativeMTLS (2.32s)1150=== CONT TestIsValidCachePath1151=== RUN TestIsValidCachePath/narinfo1152=== PAUSE TestIsValidCachePath/narinfo1153=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1154=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1155=== RUN TestIsValidCachePath/nar_zst1156=== PAUSE TestIsValidCachePath/nar_zst1157=== RUN TestIsValidCachePath/nar_xz1158=== PAUSE TestIsValidCachePath/nar_xz1159=== RUN TestIsValidCachePath/nar_bz21160=== PAUSE TestIsValidCachePath/nar_bz21161=== RUN TestIsValidCachePath/nar_uncompressed1162=== PAUSE TestIsValidCachePath/nar_uncompressed1163=== RUN TestIsValidCachePath/ls1164=== PAUSE TestIsValidCachePath/ls1165=== RUN TestIsValidCachePath/log1166=== PAUSE TestIsValidCachePath/log1167=== RUN TestIsValidCachePath/realisation1168=== PAUSE TestIsValidCachePath/realisation1169=== RUN TestIsValidCachePath/nix-cache-info1170=== PAUSE TestIsValidCachePath/nix-cache-info1171=== RUN TestIsValidCachePath/index.html1172=== PAUSE TestIsValidCachePath/index.html1173=== RUN TestIsValidCachePath/traversal_parent1174=== PAUSE TestIsValidCachePath/traversal_parent1175=== RUN TestIsValidCachePath/traversal_in_middle1176=== PAUSE TestIsValidCachePath/traversal_in_middle1177=== RUN TestIsValidCachePath/invalid_char_e1178=== PAUSE TestIsValidCachePath/invalid_char_e1179=== RUN TestIsValidCachePath/invalid_char_u1180=== PAUSE TestIsValidCachePath/invalid_char_u1181=== RUN TestIsValidCachePath/random_path1182=== PAUSE TestIsValidCachePath/random_path1183=== RUN TestIsValidCachePath/empty1184=== PAUSE TestIsValidCachePath/empty1185=== RUN TestIsValidCachePath/leading_slash1186=== PAUSE TestIsValidCachePath/leading_slash1187=== RUN TestIsValidCachePath/wrong_extension1188=== PAUSE TestIsValidCachePath/wrong_extension1189=== RUN TestIsValidCachePath/short_hash1190=== PAUSE TestIsValidCachePath/short_hash1191=== CONT TestService_healthCheckHandler11922026/09/24 18:05:06 INFO Received push request method=POST path=/api/pushes11932026/09/24 18:05:06 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)11942026/09/24 18:05:06 INFO Uploading 0krx3hi7pnrcnx1ilhbvmigg768cawr0-file1.txt (160B)11952026/09/24 18:05:06 WARN Failed to register uploaded object key=0krx3hi7pnrcnx1ilhbvmigg768cawr0.ls error="server returned 404: 404 page not found\n"11962026/09/24 18:05:06 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"11972026/09/24 18:05:06 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11982026/09/24 18:05:06 INFO Signed narinfos id=1 count=111992026/09/24 18:05:06 INFO Uploading 1 narinfos12002026/09/24 18:05:06 INFO Received complete push request method=POST path=/api/pushes/1/complete12012026/09/24 18:05:06 WARN Failed to register uploaded object key=0krx3hi7pnrcnx1ilhbvmigg768cawr0.narinfo error="server returned 404: 404 page not found\n"12022026/09/24 18:05:06 INFO Upload complete. (124ms)1203=== NAME TestNARDeduplicationMetadataUploadBug1204 metadata_upload_test.go:54: Retrieved narinfo from S3:1205 StorePath: /nix/var/nix/builds/nix-16695-3377832867/TestNARDeduplicationMetadataUploadBug3027340354/001/store/0krx3hi7pnrcnx1ilhbvmigg768cawr0-file1.txt1206 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1207 Compression: zstd1208 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1209 NarSize: 1601210 References: 1211 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1212 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1213 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1214 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}1215 metadata_upload_test.go:64: Second store path (same content): /nix/var/nix/builds/nix-16695-3377832867/TestNARDeduplicationMetadataUploadBug3027340354/001/store/pc0z7nmf4kz4z7nnm2bxr0376d6p8x93-file2.txt12162026/09/24 18:05:06 INFO Received push request method=POST path=/api/pushes12172026/09/24 18:05:06 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)12182026/09/24 18:05:06 WARN Failed to register uploaded object key=pc0z7nmf4kz4z7nnm2bxr0376d6p8x93.ls error="server returned 404: 404 page not found\n"12192026/09/24 18:05:06 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign12202026/09/24 18:05:06 INFO Signed narinfos id=2 count=112212026/09/24 18:05:06 INFO Uploading 1 narinfos12222026/09/24 18:05:06 INFO Received complete push request method=POST path=/api/pushes/2/complete12232026/09/24 18:05:06 WARN Failed to register uploaded object key=pc0z7nmf4kz4z7nnm2bxr0376d6p8x93.narinfo error="server returned 404: 404 page not found\n"12242026/09/24 18:05:06 INFO Upload complete. (97ms)1225 metadata_upload_test.go:76: Retrieved narinfo from S3:1226 StorePath: /nix/var/nix/builds/nix-16695-3377832867/TestNARDeduplicationMetadataUploadBug3027340354/001/store/pc0z7nmf4kz4z7nnm2bxr0376d6p8x93-file2.txt1227 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1228 Compression: zstd1229 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1230 NarSize: 1601231 References: 1232 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1233 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1234 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1235 {"version":1,"root":{"type":"regular","size":44}}1236--- PASS: TestNARDeduplicationMetadataUploadBug (2.46s)1237=== CONT TestReadProxyNarinfoAlreadyDecompressed12382026/09/24 18:05:07 WARN Rate limiter enabled after throttle name=s3-test rate=512392026/09/24 18:05:07 WARN S3 rate limit hit during proxy key=4hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo error="Please reduce your request rate."1240--- PASS: TestReadProxyNarStreaming (1.86s)1241=== CONT TestGenerateLandingPage1242--- PASS: TestGenerateLandingPage (0.01s)1243=== CONT TestCreatePin_ReservedPins12442026/09/24 18:05:07 WARN Rate limiter backed off name=s3-test rate=512452026/09/24 18:05:07 WARN S3 rate limit hit during proxy key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhh.nar.zst error="Please reduce your request rate."1246--- PASS: TestReadProxy404 (2.38s)1247=== CONT TestGCTaskStore_Fail1248--- PASS: TestGCTaskStore_Fail (0.00s)1249=== CONT TestPresentNotReportedWhileGCDeletesClosure1250--- PASS: TestReadProxyHead (1.58s)1251=== CONT TestGracefulShutdownDrainsInflight12522026/09/24 18:05:07 INFO Starting HTTP server address=127.0.0.1:5254012532026/09/24 18:05:07 INFO Shutdown signal received, draining in-flight requests timeout=10s12542026/09/24 18:05:07 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52542/oidc1255--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1256=== CONT TestPresentReportsOnlyClosureRoots1257--- PASS: TestMetricsInventory (2.02s)1258=== CONT TestGCTaskStore_CompletedAllowsNewTask1259--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1260=== CONT TestProxyHeadersOnlyTrustedOnSocket12612026/09/24 18:05:08 ERROR Failed to decompress narinfo error="decompressed size exceeds configured limit"12622026/09/24 18:05:08 WARN readiness check failed error="closed pool"1263--- PASS: TestService_readinessHandler (1.56s)1264=== CONT TestCreatePinRejectsBadInput12652026/09/24 18:05:08 ERROR Refusing narinfo larger than the limit key=5hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=167772161266--- PASS: TestReadProxyNarinfo (2.21s)1267=== CONT TestDeletePinKeepsRowWhenS3Fails1268--- PASS: TestService_healthCheckHandler (1.74s)1269=== CONT TestClientPushesUseOnePush1270--- PASS: TestReadProxyNarinfoAlreadyDecompressed (1.46s)1271=== CONT TestGCTaskStore_ConflictDifferentParams1272--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1273=== CONT TestSweepRowDeleteSparesResurrectedObject12742026/09/24 18:05:08 WARN Rate limiter enabled after throttle name=s3-test rate=512752026/09/24 18:05:08 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1276=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1277 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101278 throttle_test.go:215: Rate limiter: enabled=true, rate=5.0012792026/09/24 18:05:08 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux12802026/09/24 18:05:08 WARN Refused reserved pin name=worker-x86_64-linux12812026/09/24 18:05:08 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux12822026/09/24 18:05:08 INFO Received create pin request method=POST path=/api/pins/my-app12832026/09/24 18:05:08 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1284--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (6.57s)1285=== CONT TestGCTaskStore_DeduplicateSameParams1286--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1287=== CONT TestGCTaskStore_GetEmpty1288=== CONT TestGCEndsOnShutdown1289=== RUN TestGCEndsOnShutdown/before_the_run1290--- PASS: TestGCTaskStore_GetEmpty (0.00s)1291=== PAUSE TestGCEndsOnShutdown/before_the_run1292=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1293=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1294=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1295=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1296=== CONT TestCommitRacingPendingCleanupKeepsObjects1297--- PASS: TestCreatePin_ReservedPins (1.67s)1298=== CONT TestCacheStatsHandler1299--- PASS: TestPresentReportsOnlyClosureRoots (1.54s)1300=== CONT TestGCTaskStore_StartNew1301--- PASS: TestGCTaskStore_StartNew (0.00s)1302=== CONT TestService_ReadAuthMiddleware1303--- PASS: TestPresentNotReportedWhileGCDeletesClosure (1.89s)1304=== CONT TestClientSharedPathCommittedMidPush13052026/09/24 18:05:09 INFO Starting HTTP server address=127.0.0.1:5256813062026/09/24 18:05:09 INFO Starting HTTP server address=/nix/var/nix/builds/nix-16695-3377832867/TestProxyHeadersOnlyTrustedOnSocket3300198140/001/proxy.sock13072026/09/24 18:05:09 WARN mTLS auth: subject not in bound subjects subject="CN=someone"13082026/09/24 18:05:09 INFO Shutdown signal received, draining in-flight requests timeout=10s1309--- PASS: TestProxyHeadersOnlyTrustedOnSocket (1.61s)1310=== CONT TestReadRedirectUsesPublicS3URL13112026/09/24 18:05:09 INFO Received create pin request method=POST path=/api/pins/deploy13122026/09/24 18:05:09 INFO Received create pin request method=POST path=/api/pins/deploy13132026/09/24 18:05:09 INFO Received create pin request method=POST path=/api/pins/deploy13142026/09/24 18:05:09 INFO Received create pin request method=POST path=/api/pins/deploy13152026/09/24 18:05:09 INFO Received create pin request method=POST path=/api/pins/deploy13162026/09/24 18:05:09 INFO Received create pin request method=POST path=/api/pins/deploy13172026/09/24 18:05:09 INFO Received create pin request method=POST path=/api/pins/deploy13182026/09/24 18:05:09 INFO Received create pin request method=POST path=/api/pins/deploy13192026/09/24 18:05:09 INFO Received create pin request method=POST path=/api/pins/deploy13202026/09/24 18:05:09 INFO Received create pin request method=POST path=/api/pins/app13212026/09/24 18:05:09 INFO Created/updated pin name=app store_path=/nix/store/cccccccccccccccccccccccccccccccc-app narinfo_key=cccccccccccccccccccccccccccccccc.narinfo13222026/09/24 18:05:09 INFO Received delete pin request method=DELETE path=/api/pins/app13232026/09/24 18:05:09 ERROR Failed to delete pin from S3 key=pins/app error="Get \"http://127.0.0.1:1/bucket50/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"13242026/09/24 18:05:09 INFO Received delete pin request method=DELETE path=/api/pins/app13252026/09/24 18:05:09 INFO Deleted pin name=app1326--- PASS: TestDeletePinKeepsRowWhenS3Fails (1.42s)1327=== CONT TestService_AuthMiddleware_OIDC13282026/09/24 18:05:09 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52575/oidc13292026/09/24 18:05:09 INFO Received create pin request method=POST path=/api/pins/deploy13302026/09/24 18:05:09 INFO Created/updated pin name=deploy store_path="/nix/store/dddddddddddddddddddddddddddddddd-app-1.0+git_x?y=z" narinfo_key=dddddddddddddddddddddddddddddddd.narinfo1331--- PASS: TestCreatePinRejectsBadInput (1.83s)1332=== CONT TestCacheConfigHandler1333=== RUN TestCacheConfigHandler/full_config,_no_issuer1334=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1335=== RUN TestCacheConfigHandler/no_cache_url_configured1336=== PAUSE TestCacheConfigHandler/no_cache_url_configured1337=== RUN TestCacheConfigHandler/no_signing_keys1338=== PAUSE TestCacheConfigHandler/no_signing_keys1339=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1340=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1341=== CONT TestPush_CompleteCommitsEveryRoot1342--- PASS: TestSweepRowDeleteSparesResurrectedObject (1.64s)1343=== CONT TestPinProtectsFromGC1344--- PASS: TestConnectWaitsForAPeerMigration (6.61s)1345=== CONT TestPush_OverlappingRootsStoreOneRowPerKey13462026/09/24 18:05:10 INFO Received push request method=POST path=/api/pushes13472026/09/24 18:05:10 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)13482026/09/24 18:05:10 INFO Uploading i1by3xy16hydk0b61ipfycvraqyzz57m-shared-dep (136B)13492026/09/24 18:05:10 INFO Uploading zq89jb16hvaqaw8ckr5s73gxq6gdjwar-b (248B)13502026/09/24 18:05:10 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"13512026/09/24 18:05:10 WARN Failed to register uploaded object key=nar/1qi50qpzp9rh6bg091dk3ppxjiffprfgaqlx7048v1yw4kl3lwx4.nar.zst error="server returned 404: 404 page not found\n"13522026/09/24 18:05:10 WARN Failed to register uploaded object key=jkiqjj95p10s8vvcqm0sfbj2drrcy812.ls error="server returned 404: 404 page not found\n"13532026/09/24 18:05:10 WARN Failed to register uploaded object key=zq89jb16hvaqaw8ckr5s73gxq6gdjwar.ls error="server returned 404: 404 page not found\n"13542026/09/24 18:05:10 WARN Failed to register uploaded object key=i1by3xy16hydk0b61ipfycvraqyzz57m.ls error="server returned 404: 404 page not found\n"13552026/09/24 18:05:10 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13562026/09/24 18:05:10 INFO Signed narinfos id=1 count=313572026/09/24 18:05:10 INFO Uploading 3 narinfos13582026/09/24 18:05:10 WARN Failed to register uploaded object key=i1by3xy16hydk0b61ipfycvraqyzz57m.narinfo error="server returned 404: 404 page not found\n"13592026/09/24 18:05:10 WARN Failed to register uploaded object key=jkiqjj95p10s8vvcqm0sfbj2drrcy812.narinfo error="server returned 404: 404 page not found\n"13602026/09/24 18:05:10 INFO Received complete push request method=POST path=/api/pushes/1/complete13612026/09/24 18:05:10 WARN Failed to register uploaded object key=zq89jb16hvaqaw8ckr5s73gxq6gdjwar.narinfo error="server returned 404: 404 page not found\n"13622026/09/24 18:05:10 INFO Upload complete. (129ms)1363=== NAME TestClientPushesUseOnePush1364 client_pushes_test.go:97: Retrieved narinfo from S3:1365 StorePath: /nix/var/nix/builds/nix-16695-3377832867/TestClientPushesUseOnePush2082090059/001/store/i1by3xy16hydk0b61ipfycvraqyzz57m-shared-dep1366 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1367 Compression: zstd1368 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821369 NarSize: 1361370 References: 1371 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1372 client_pushes_test.go:97: Retrieved narinfo from S3:1373 StorePath: /nix/var/nix/builds/nix-16695-3377832867/TestClientPushesUseOnePush2082090059/001/store/jkiqjj95p10s8vvcqm0sfbj2drrcy812-a1374 URL: nar/1qi50qpzp9rh6bg091dk3ppxjiffprfgaqlx7048v1yw4kl3lwx4.nar.zst1375 Compression: zstd1376 NarHash: sha256:1qi50qpzp9rh6bg091dk3ppxjiffprfgaqlx7048v1yw4kl3lwx41377 NarSize: 2481378 References: /nix/var/nix/builds/nix-16695-3377832867/TestClientPushesUseOnePush2082090059/001/store/i1by3xy16hydk0b61ipfycvraqyzz57m-shared-dep1379 CA: text:sha256:1x41j523a63pwn7ra91s88dz9mwx6ysq40d8jpr3ah2grpf51a591380 client_pushes_test.go:97: Retrieved narinfo from S3:1381 StorePath: /nix/var/nix/builds/nix-16695-3377832867/TestClientPushesUseOnePush2082090059/001/store/zq89jb16hvaqaw8ckr5s73gxq6gdjwar-b1382 URL: nar/1qi50qpzp9rh6bg091dk3ppxjiffprfgaqlx7048v1yw4kl3lwx4.nar.zst1383 Compression: zstd1384 NarHash: sha256:1qi50qpzp9rh6bg091dk3ppxjiffprfgaqlx7048v1yw4kl3lwx41385 NarSize: 2481386 References: /nix/var/nix/builds/nix-16695-3377832867/TestClientPushesUseOnePush2082090059/001/store/i1by3xy16hydk0b61ipfycvraqyzz57m-shared-dep1387 CA: text:sha256:1x41j523a63pwn7ra91s88dz9mwx6ysq40d8jpr3ah2grpf51a591388--- PASS: TestClientPushesUseOnePush (2.08s)1389=== CONT TestService_ReadScope_PublicByDefault1390--- PASS: TestCacheStatsHandler (1.47s)1391=== CONT TestGCTaskStore_GetReturnsLatest1392--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1393=== CONT TestClientCADerivations1394--- PASS: TestService_ReadAuthMiddleware (1.38s)1395=== CONT TestSweepSparesObjectReuploadedMidSweep13962026/09/24 18:05:10 INFO Aborted multipart uploads count=0 kept=013972026/09/24 18:05:10 WARN Force mode enabled - objects will be deleted immediately without grace period13982026/09/24 18:05:10 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=013992026/09/24 18:05:10 INFO Vacuumed table table=pending_closures14002026/09/24 18:05:10 INFO Vacuumed table table=pending_objects14012026/09/24 18:05:10 INFO Vacuumed table table=multipart_uploads14022026/09/24 18:05:10 INFO Vacuumed table table=closures14032026/09/24 18:05:10 INFO Vacuumed table table=objects1404--- PASS: TestCommitRacingPendingCleanupKeepsObjects (2.04s)1405=== CONT TestService_RequireScope_OIDC14062026/09/24 18:05:11 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52599/oidc1407--- PASS: TestReadRedirectUsesPublicS3URL (1.90s)1408=== CONT TestClientErrorHandling1409=== RUN TestClientErrorHandling/InvalidStorePath1410=== PAUSE TestClientErrorHandling/InvalidStorePath1411=== RUN TestClientErrorHandling/InvalidAuthToken1412=== PAUSE TestClientErrorHandling/InvalidAuthToken1413=== RUN TestClientErrorHandling/ServerNotAvailable1414=== PAUSE TestClientErrorHandling/ServerNotAvailable1415=== CONT TestGCSweepDeliversEachKeyOnce14162026/09/24 18:05:11 INFO Received push request method=POST path=/api/pushes14172026/09/24 18:05:11 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)14182026/09/24 18:05:11 INFO Uploading z4q88l7ia5x5hjmvxidm566d4vfhlb8y-top (256B)14192026/09/24 18:05:11 INFO Uploading 1xyanq0849m2lkywg5bpsv17m8kdd3lp-shared-dep (136B)14202026/09/24 18:05:11 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"14212026/09/24 18:05:11 WARN Failed to register uploaded object key=nar/13a26jrc87i5gif3mhj5maycfn5v2d3lsxpda9qank8753wl1n4a.nar.zst error="server returned 404: 404 page not found\n"14222026/09/24 18:05:11 WARN Failed to register uploaded object key=z4q88l7ia5x5hjmvxidm566d4vfhlb8y.ls error="server returned 404: 404 page not found\n"14232026/09/24 18:05:11 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14242026/09/24 18:05:11 WARN Failed to register uploaded object key=1xyanq0849m2lkywg5bpsv17m8kdd3lp.ls error="server returned 404: 404 page not found\n"14252026/09/24 18:05:11 INFO Signed narinfos id=1 count=214262026/09/24 18:05:11 INFO Uploading 2 narinfos14272026/09/24 18:05:11 WARN Failed to register uploaded object key=z4q88l7ia5x5hjmvxidm566d4vfhlb8y.narinfo error="server returned 404: 404 page not found\n"14282026/09/24 18:05:11 WARN Failed to register uploaded object key=1xyanq0849m2lkywg5bpsv17m8kdd3lp.narinfo error="server returned 404: 404 page not found\n"14292026/09/24 18:05:11 INFO Received complete push request method=POST path=/api/pushes/1/complete14302026/09/24 18:05:11 INFO Upload complete. (125ms)1431=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1432=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1433=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1434=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1435=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1436=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1437=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1438=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1439=== CONT TestResurrectedObjectNotDeleted1440=== NAME TestClientSharedPathCommittedMidPush1441 client_integration_test.go:816: Retrieved narinfo from S3:1442 StorePath: /nix/var/nix/builds/nix-16695-3377832867/TestClientSharedPathCommittedMidPush1583274684/001/store/1xyanq0849m2lkywg5bpsv17m8kdd3lp-shared-dep1443 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1444 Compression: zstd1445 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821446 NarSize: 1361447 References: 1448 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1449 client_integration_test.go:816: Retrieved narinfo from S3:1450 StorePath: /nix/var/nix/builds/nix-16695-3377832867/TestClientSharedPathCommittedMidPush1583274684/001/store/z4q88l7ia5x5hjmvxidm566d4vfhlb8y-top1451 URL: nar/13a26jrc87i5gif3mhj5maycfn5v2d3lsxpda9qank8753wl1n4a.nar.zst1452 Compression: zstd1453 NarHash: sha256:13a26jrc87i5gif3mhj5maycfn5v2d3lsxpda9qank8753wl1n4a1454 NarSize: 2561455 References: /nix/var/nix/builds/nix-16695-3377832867/TestClientSharedPathCommittedMidPush1583274684/001/store/1xyanq0849m2lkywg5bpsv17m8kdd3lp-shared-dep1456 CA: text:sha256:0084nrsiq62wcsf0hjsvqi6n75ad0dar5rh6hfp8kj01jsj85m371457--- PASS: TestClientSharedPathCommittedMidPush (2.24s)1458=== CONT TestClientMultipleUploads14592026/09/24 18:05:11 INFO Received push request method=POST path=/api/pushes14602026/09/24 18:05:12 INFO Received push request method=POST path=/api/pushes1461=== NAME TestPinProtectsFromGC1462 client_integration_test.go:867: Pinned store path: /nix/var/nix/builds/nix-16695-3377832867/TestPinProtectsFromGC625395639/001/store/ifgwynl26584va36c0pzmyw6fip73iqd-pinned-file.txt1463 client_integration_test.go:868: Unpinned store path: /nix/var/nix/builds/nix-16695-3377832867/TestPinProtectsFromGC625395639/001/store/9y8qnap3635gfihfiaabrmfnnccdf18h-unpinned-file.txt1464--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (2.05s)1465=== CONT TestPresignedUploadRegisteredBeforeCommit14662026/09/24 18:05:12 INFO Received push request method=POST path=/api/pushes14672026/09/24 18:05:12 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14682026/09/24 18:05:12 INFO Uploading ifgwynl26584va36c0pzmyw6fip73iqd-pinned-file.txt (128B)14692026/09/24 18:05:12 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"14702026/09/24 18:05:12 WARN Failed to register uploaded object key=ifgwynl26584va36c0pzmyw6fip73iqd.ls error="server returned 404: 404 page not found\n"14712026/09/24 18:05:12 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14722026/09/24 18:05:12 INFO Signed narinfos id=1 count=114732026/09/24 18:05:12 INFO Uploading 1 narinfos14742026/09/24 18:05:12 INFO Received complete push request method=POST path=/api/pushes/1/complete14752026/09/24 18:05:12 WARN Failed to register uploaded object key=ifgwynl26584va36c0pzmyw6fip73iqd.narinfo error="server returned 404: 404 page not found\n"14762026/09/24 18:05:12 INFO Upload complete. (118ms)1477--- PASS: TestService_ReadScope_PublicByDefault (1.97s)1478=== CONT TestUploadHandlersRejectOversizedBody1479=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure1480=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure1481=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart1482=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart1483=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts1484=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts1485=== CONT TestCompletedNarNotReofferedAcrossClosures14862026/09/24 18:05:12 INFO Received push request method=POST path=/api/pushes14872026/09/24 18:05:12 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14882026/09/24 18:05:12 INFO Uploading 9y8qnap3635gfihfiaabrmfnnccdf18h-unpinned-file.txt (128B)14892026/09/24 18:05:12 WARN Failed to register uploaded object key=9y8qnap3635gfihfiaabrmfnnccdf18h.ls error="server returned 404: 404 page not found\n"14902026/09/24 18:05:12 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign14912026/09/24 18:05:12 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"14922026/09/24 18:05:12 INFO Signed narinfos id=2 count=114932026/09/24 18:05:12 INFO Uploading 1 narinfos14942026/09/24 18:05:12 INFO Received complete push request method=POST path=/api/pushes/2/complete14952026/09/24 18:05:12 WARN Failed to register uploaded object key=9y8qnap3635gfihfiaabrmfnnccdf18h.narinfo error="server returned 404: 404 page not found\n"14962026/09/24 18:05:12 INFO Upload complete. (111ms)14972026/09/24 18:05:12 INFO Starting cleanup of old closures method=DELETE path=/api/closures14982026/09/24 18:05:12 INFO Garbage collection started14992026/09/24 18:05:12 INFO Aborted multipart uploads count=0 kept=015002026/09/24 18:05:12 WARN Force mode enabled - objects will be deleted immediately without grace period15012026/09/24 18:05:12 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=015022026/09/24 18:05:12 INFO Vacuumed table table=pending_closures15032026/09/24 18:05:12 INFO Vacuumed table table=pending_objects15042026/09/24 18:05:12 INFO Vacuumed table table=multipart_uploads15052026/09/24 18:05:12 INFO Vacuumed table table=closures15062026/09/24 18:05:12 INFO Vacuumed table table=objects15072026/09/24 18:05:12 INFO Received complete multipart upload request method=POST path=/api/multipart/complete15082026/09/24 18:05:12 INFO Aborted multipart uploads count=0 kept=015092026/09/24 18:05:12 INFO Received uploads request method=POST path=/api/pending_closures15102026/09/24 18:05:12 INFO Completed multipart upload object_key=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa00000000000000000000.nar.zst upload_id=NDc3YzAzNzQtNDI2Yy00MTM0LTg2ZmEtYThmMDFjOTM4M2UxLjE5YTY4MWE5LWEzMDMtNDcxZC1iMmI1LTc0NDMyODNlMzU4NXgxNzkwMjczMTExNjI4MDI5MDAw parts=101511=== NAME TestClientCADerivations1512 client_ca_test.go:136: Built CA derivation: /nix/var/nix/builds/nix-16695-3377832867/TestClientCADerivations4064621906/001/store/59gh9mv87sm2hi6vgj40460s2hh3r6yb-ca-test1513=== RUN TestService_RequireScope_OIDC/builder_may_write1514=== PAUSE TestService_RequireScope_OIDC/builder_may_write1515=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1516=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1517=== RUN TestService_RequireScope_OIDC/ops_may_admin1518=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1519=== RUN TestService_RequireScope_OIDC/ops_may_not_write1520=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1521=== RUN TestService_RequireScope_OIDC/reader_may_not_write1522=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1523=== RUN TestService_RequireScope_OIDC/static_token_may_admin1524=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1525=== RUN TestService_RequireScope_OIDC/static_token_may_write1526=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1527=== RUN TestService_RequireScope_OIDC/reader_may_read1528=== PAUSE TestService_RequireScope_OIDC/reader_may_read1529=== RUN TestService_RequireScope_OIDC/writer_implies_read1530=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1531=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1532=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1533=== CONT TestCompleteMultipartUpload_ErrorButObjectExists1534=== NAME TestClientCADerivations1535 client_ca_test.go:139: Found 1 dependencies (including self)15362026/09/24 18:05:13 INFO Received push request method=POST path=/api/pushes15372026/09/24 18:05:13 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15382026/09/24 18:05:13 INFO Uploading 59gh9mv87sm2hi6vgj40460s2hh3r6yb-ca-test (144B)15392026/09/24 18:05:13 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"15402026/09/24 18:05:13 WARN Failed to register uploaded object key=59gh9mv87sm2hi6vgj40460s2hh3r6yb.ls error="server returned 404: 404 page not found\n"15412026/09/24 18:05:13 WARN Failed to register uploaded object key=log/simfngv28vdd0cgyw7v65drh3ybpqx84-ca-test.drv error="server returned 404: 404 page not found\n"15422026/09/24 18:05:13 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15432026/09/24 18:05:13 INFO Signed narinfos id=1 count=115442026/09/24 18:05:13 INFO Uploading 1 narinfos15452026/09/24 18:05:13 INFO Received complete push request method=POST path=/api/pushes/1/complete15462026/09/24 18:05:13 WARN Failed to register uploaded object key=59gh9mv87sm2hi6vgj40460s2hh3r6yb.narinfo error="server returned 404: 404 page not found\n"15472026/09/24 18:05:13 INFO Upload complete. (208ms)1548 client_ca_test.go:180: Narinfo contains CA field: StorePath: /nix/var/nix/builds/nix-16695-3377832867/TestClientCADerivations4064621906/001/store/59gh9mv87sm2hi6vgj40460s2hh3r6yb-ca-test1549 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1550 Compression: zstd1551 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1552 NarSize: 1441553 References: 1554 Deriver: /nix/var/nix/builds/nix-16695-3377832867/TestClientCADerivations4064621906/001/store/simfngv28vdd0cgyw7v65drh3ybpqx84-ca-test.drv1555 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1556 client_ca_test.go:185: Checking for realisation files in S3...1557 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1558 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache15592026/09/24 18:05:13 INFO Aborted multipart uploads count=0 kept=015602026/09/24 18:05:13 WARN Force mode enabled - objects will be deleted immediately without grace period1561 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket63?endpoint=http://localhost:52391®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/nix/var/nix/builds/nix-16695-3377832867/TestClientCADerivations4064621906/001/store'1562 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 115632026/09/24 18:05:13 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=015642026/09/24 18:05:13 INFO Vacuumed table table=pending_closures15652026/09/24 18:05:13 INFO Vacuumed table table=pending_objects15662026/09/24 18:05:13 INFO Vacuumed table table=multipart_uploads15672026/09/24 18:05:13 INFO Vacuumed table table=closures15682026/09/24 18:05:13 INFO Vacuumed table table=objects1569--- PASS: TestGCSweepDeliversEachKeyOnce (2.19s)1570=== CONT TestSweepKeepsTombstoneWhenDeleteOutcomeUnknown1571--- PASS: TestClientCADerivations (3.08s)1572=== CONT TestPush_SignsNarinfosOfItsPendingObjects1573--- PASS: TestResurrectedObjectNotDeleted (2.29s)1574=== CONT TestOrphanedObjectsGC15752026/09/24 18:05:13 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=015762026/09/24 18:05:13 INFO Vacuumed table table=pending_closures15772026/09/24 18:05:13 INFO Vacuumed table table=pending_objects15782026/09/24 18:05:13 INFO Vacuumed table table=multipart_uploads15792026/09/24 18:05:13 INFO Vacuumed table table=closures1580=== NAME TestClientMultipleUploads1581 client_integration_test.go:480: Created store path 0: /nix/var/nix/builds/nix-16695-3377832867/TestClientMultipleUploads620688486/001/store/pc0s9dgln5mzfzkl9g5n0fxfzd7ndlk6-test-file-0.txt15822026/09/24 18:05:13 INFO Vacuumed table table=objects15832026/09/24 18:05:13 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1584--- PASS: TestSweepSparesObjectReuploadedMidSweep (3.46s)1585=== CONT TestPush_RejectsBadRequests15862026/09/24 18:05:14 INFO Completed multipart upload object_key=nar/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb00000000000000000000.nar.zst upload_id=NDc3YzAzNzQtNDI2Yy00MTM0LTg2ZmEtYThmMDFjOTM4M2UxLmQ2N2RjZmY1LTUyNWItNGZlOC1iMTVmLWU3MzQwNmU1ZDJhNXgxNzkwMjczMTExNjI4NDQyMDAw parts=101587=== NAME TestClientMultipleUploads1588 client_integration_test.go:480: Created store path 1: /nix/var/nix/builds/nix-16695-3377832867/TestClientMultipleUploads620688486/001/store/5xhlwjrq5546zfgm43nplsl88k0q1y86-test-file-1.txt1589 client_integration_test.go:480: Created store path 2: /nix/var/nix/builds/nix-16695-3377832867/TestClientMultipleUploads620688486/001/store/80c0a1xpdy2k9jgb476b3hs8qyz3li8x-test-file-2.txt15902026/09/24 18:05:14 INFO Received push request method=POST path=/api/pushes15912026/09/24 18:05:14 INFO Received uploads request method=POST path=/api/pending_closures15922026/09/24 18:05:14 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)15932026/09/24 18:05:14 INFO Uploading 5xhlwjrq5546zfgm43nplsl88k0q1y86-test-file-1.txt (160B)15942026/09/24 18:05:14 INFO Uploading 80c0a1xpdy2k9jgb476b3hs8qyz3li8x-test-file-2.txt (160B)15952026/09/24 18:05:14 INFO Uploading pc0s9dgln5mzfzkl9g5n0fxfzd7ndlk6-test-file-0.txt (160B)15962026/09/24 18:05:14 WARN Failed to register uploaded object key=80c0a1xpdy2k9jgb476b3hs8qyz3li8x.ls error="server returned 404: 404 page not found\n"15972026/09/24 18:05:14 WARN Failed to register uploaded object key=pc0s9dgln5mzfzkl9g5n0fxfzd7ndlk6.ls error="server returned 404: 404 page not found\n"15982026/09/24 18:05:14 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15992026/09/24 18:05:14 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"16002026/09/24 18:05:14 WARN Failed to register uploaded object key=5xhlwjrq5546zfgm43nplsl88k0q1y86.ls error="server returned 404: 404 page not found\n"16012026/09/24 18:05:14 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"16022026/09/24 18:05:14 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"16032026/09/24 18:05:14 INFO Signed narinfos id=1 count=316042026/09/24 18:05:14 INFO Uploading 3 narinfos16052026/09/24 18:05:14 WARN Failed to register uploaded object key=pc0s9dgln5mzfzkl9g5n0fxfzd7ndlk6.narinfo error="server returned 404: 404 page not found\n"16062026/09/24 18:05:14 INFO Received complete push request method=POST path=/api/pushes/1/complete16072026/09/24 18:05:14 WARN Failed to register uploaded object key=5xhlwjrq5546zfgm43nplsl88k0q1y86.narinfo error="server returned 404: 404 page not found\n"16082026/09/24 18:05:14 WARN Failed to register uploaded object key=80c0a1xpdy2k9jgb476b3hs8qyz3li8x.narinfo error="server returned 404: 404 page not found\n"16092026/09/24 18:05:14 INFO Upload complete. (136ms)1610 client_integration_test.go:491: Uploaded 3 paths in 172.035709ms16112026/09/24 18:05:14 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst16122026/09/24 18:05:14 INFO Received uploads request method=POST path=/api/pending_closures1613--- PASS: TestPresignedUploadRegisteredBeforeCommit (2.13s)1614=== CONT TestGCTaskStore_PhaseUpdates1615--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1616=== CONT TestClientWithDependencies1617--- PASS: TestClientMultipleUploads (2.95s)1618=== CONT TestReadProxyInvalidPath16192026/09/24 18:05:14 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=016202026/09/24 18:05:14 INFO Received create pin request method=POST path=/api/pins/myapp16212026/09/24 18:05:14 INFO Received uploads request method=POST path=/api/pending_closures16222026/09/24 18:05:14 INFO Created/updated pin name=myapp store_path=/nix/var/nix/builds/nix-16695-3377832867/TestPinProtectsFromGC625395639/001/store/ifgwynl26584va36c0pzmyw6fip73iqd-pinned-file.txt narinfo_key=ifgwynl26584va36c0pzmyw6fip73iqd.narinfo16232026/09/24 18:05:14 INFO Starting cleanup of old closures method=DELETE path=/api/closures16242026/09/24 18:05:14 INFO Garbage collection started16252026/09/24 18:05:14 INFO Aborted multipart uploads count=0 kept=016262026/09/24 18:05:14 WARN Force mode enabled - objects will be deleted immediately without grace period16272026/09/24 18:05:14 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=016282026/09/24 18:05:14 INFO Vacuumed table table=pending_closures16292026/09/24 18:05:14 INFO Vacuumed table table=pending_objects16302026/09/24 18:05:14 INFO Vacuumed table table=multipart_uploads16312026/09/24 18:05:14 INFO Vacuumed table table=closures16322026/09/24 18:05:14 INFO Vacuumed table table=objects16332026/09/24 18:05:15 INFO Received uploads request method=POST path=/api/pending_closures16342026/09/24 18:05:15 INFO Received complete multipart upload request method=POST path=/api/multipart/complete16352026/09/24 18:05:15 INFO Completed multipart upload object_key=nar/cccccccccccccccccccccccccccccccc00000000000000000000.nar.zst upload_id=NDc3YzAzNzQtNDI2Yy00MTM0LTg2ZmEtYThmMDFjOTM4M2UxLmJjMjdiMWY3LTEwYmItNGFmZS1iN2E2LWY3ODU1YzcwMGI1YngxNzkwMjczMTExNjI4NDEyMDAw parts=1016362026/09/24 18:05:15 INFO Received complete push request method=POST path=/api/pushes/1/complete1637--- PASS: TestPush_CompleteCommitsEveryRoot (5.39s)1638=== CONT TestClientIntegration16392026/09/24 18:05:15 INFO Received complete multipart upload request method=POST path=/api/multipart/complete16402026/09/24 18:05:15 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NDc3YzAzNzQtNDI2Yy00MTM0LTg2ZmEtYThmMDFjOTM4M2UxLjZiOTEwOTMyLWYyYjMtNGQ2ZS1iNGVlLWE1MWY2NTUwYTBlZXgxNzkwMjczMTE1MDM1OTA3MDAw16412026/09/24 18:05:15 INFO Aborted multipart uploads count=0 kept=016422026/09/24 18:05:15 WARN Force mode enabled - objects will be deleted immediately without grace period16432026/09/24 18:05:15 WARN Failed to abort multipart upload key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NDc3YzAzNzQtNDI2Yy00MTM0LTg2ZmEtYThmMDFjOTM4M2UxLjZiOTEwOTMyLWYyYjMtNGQ2ZS1iNGVlLWE1MWY2NTUwYTBlZXgxNzkwMjczMTE1MDM1OTA3MDAw error="Delete \"http://localhost:52391/bucket71/nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst?uploadId=NDc3YzAzNzQtNDI2Yy00MTM0LTg2ZmEtYThmMDFjOTM4M2UxLjZiOTEwOTMyLWYyYjMtNGQ2ZS1iNGVlLWE1MWY2NTUwYTBlZXgxNzkwMjczMTE1MDM1OTA3MDAw\": injected: abort refused"16442026/09/24 18:05:15 INFO Received complete multipart upload request method=POST path=/api/multipart/complete16452026/09/24 18:05:15 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NDc3YzAzNzQtNDI2Yy00MTM0LTg2ZmEtYThmMDFjOTM4M2UxLjZiOTEwOTMyLWYyYjMtNGQ2ZS1iNGVlLWE1MWY2NTUwYTBlZXgxNzkwMjczMTE1MDM1OTA3MDAw16462026/09/24 18:05:15 ERROR failed to remove object object=nar/nnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnn.nar.zst error="We encountered an internal error."16472026/09/24 18:05:15 INFO Received uploads request method=POST path=/api/pending_closures16482026/09/24 18:05:15 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NDc3YzAzNzQtNDI2Yy00MTM0LTg2ZmEtYThmMDFjOTM4M2UxLjZiOTEwOTMyLWYyYjMtNGQ2ZS1iNGVlLWE1MWY2NTUwYTBlZXgxNzkwMjczMTE1MDM1OTA3MDAw parts=116492026/09/24 18:05:15 INFO Aborted multipart uploads count=0 kept=01650--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (2.51s)1651=== CONT TestForceGCDuringPushOffersSweptObject1652=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows1653=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows1654=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check1655=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check1656=== CONT TestOrphanedObjectsGCStressTest16572026/09/24 18:05:15 WARN Force mode enabled - objects will be deleted immediately without grace period16582026/09/24 18:05:15 INFO Garbage collection completed failed-uploads-deleted=1 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=2 objects-failed-to-delete=016592026/09/24 18:05:15 INFO Vacuumed table table=pending_closures16602026/09/24 18:05:15 INFO Received push request method=POST path=/api/pushes16612026/09/24 18:05:15 INFO Vacuumed table table=pending_objects16622026/09/24 18:05:15 INFO Vacuumed table table=multipart_uploads16632026/09/24 18:05:15 INFO Vacuumed table table=closures16642026/09/24 18:05:15 INFO Vacuumed table table=objects1665--- PASS: TestSweepKeepsTombstoneWhenDeleteOutcomeUnknown (2.26s)1666=== CONT TestConcurrentPinUpdatesAgree16672026/09/24 18:05:15 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16682026/09/24 18:05:15 INFO Signed narinfos id=1 count=11669--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (2.24s)1670=== CONT TestReadProxyOutlastsServerWriteTimeout16712026/09/24 18:05:16 INFO Received complete multipart upload request method=POST path=/api/multipart/complete16722026/09/24 18:05:16 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=NDc3YzAzNzQtNDI2Yy00MTM0LTg2ZmEtYThmMDFjOTM4M2UxLmI4MWVhOTE5LWRlNDItNGFhMS1iOGUwLTMxNzRkYTRmMjNiMHgxNzkwMjczMTE0NTY1MTYyMDAw parts=1216732026/09/24 18:05:16 INFO Received uploads request method=POST path=/api/pending_closures1674--- PASS: TestCompletedNarNotReofferedAcrossClosures (3.76s)1675=== CONT TestParseSize1676--- PASS: TestParseSize (0.00s)1677=== CONT TestService_AuthMiddleware1678=== RUN TestPush_RejectsBadRequests/bad_root1679=== PAUSE TestPush_RejectsBadRequests/bad_root1680=== RUN TestPush_RejectsBadRequests/root_not_in_objects1681=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1682=== RUN TestPush_RejectsBadRequests/no_roots1683=== PAUSE TestPush_RejectsBadRequests/no_roots1684=== RUN TestPush_RejectsBadRequests/no_objects1685=== PAUSE TestPush_RejectsBadRequests/no_objects1686=== CONT TestValidateS3Concurrency1687=== CONT TestReadRedirectKeepsNarinfoProxied1688--- PASS: TestValidateS3Concurrency (0.00s)1689=== NAME TestPinProtectsFromGC1690 client_integration_test.go:981: Pin successfully protected closure from garbage collection1691--- PASS: TestPinProtectsFromGC (6.57s)1692=== CONT TestRedundantMultipartUpload1693--- PASS: TestReadProxyInvalidPath (2.53s)1694=== CONT TestPushDedupSurvivesConcurrentGC1695=== NAME TestOrphanedObjectsGC1696 orphaned_objects_gc_test.go:296: GC Test Summary:1697 orphaned_objects_gc_test.go:297: - Kept: 2 objects from closure A1698 orphaned_objects_gc_test.go:298: - Deleted: 2 objects from closure B1699 orphaned_objects_gc_test.go:299: - Deleted: 6 orphaned chain objects (X1->X2->X3)1700 orphaned_objects_gc_test.go:300: - Deleted: 2 orphaned single objects (Y)1701 orphaned_objects_gc_test.go:301: - Total deleted: 10 objects1702--- PASS: TestOrphanedObjectsGC (3.25s)1703=== CONT TestService_AuthMiddleware_MTLSProxyHeader1704=== NAME TestClientWithDependencies1705 client_integration_test.go:735: Built derivation: /nix/var/nix/builds/nix-16695-3377832867/TestClientWithDependencies3131240304/001/store/gdwkkj71hmhm1hjjxkv37mhxh25fwky8-test-script1706 client_integration_test.go:737: Found 1 dependencies (including self)17072026/09/24 18:05:17 INFO Received push request method=POST path=/api/pushes17082026/09/24 18:05:17 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17092026/09/24 18:05:17 INFO Uploading gdwkkj71hmhm1hjjxkv37mhxh25fwky8-test-script (136B)17102026/09/24 18:05:17 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"17112026/09/24 18:05:17 WARN Failed to register uploaded object key=gdwkkj71hmhm1hjjxkv37mhxh25fwky8.ls error="server returned 404: 404 page not found\n"17122026/09/24 18:05:17 WARN Failed to register uploaded object key=log/cghyqiv6jm13bk89qf0ria33baf59nv3-test-script.drv error="server returned 404: 404 page not found\n"17132026/09/24 18:05:17 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17142026/09/24 18:05:17 INFO Signed narinfos id=1 count=117152026/09/24 18:05:17 INFO Uploading 1 narinfos17162026/09/24 18:05:17 INFO Received complete push request method=POST path=/api/pushes/1/complete17172026/09/24 18:05:17 WARN Failed to register uploaded object key=gdwkkj71hmhm1hjjxkv37mhxh25fwky8.narinfo error="server returned 404: 404 page not found\n"17182026/09/24 18:05:17 INFO Upload complete. (170ms)17192026/09/24 18:05:17 INFO Aborted multipart uploads count=0 kept=017202026/09/24 18:05:17 WARN Force mode enabled - objects will be deleted immediately without grace period17212026/09/24 18:05:17 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=017222026/09/24 18:05:17 INFO Vacuumed table table=pending_closures17232026/09/24 18:05:17 INFO Vacuumed table table=pending_objects17242026/09/24 18:05:17 INFO Vacuumed table table=multipart_uploads17252026/09/24 18:05:17 INFO Vacuumed table table=closures17262026/09/24 18:05:17 INFO Vacuumed table table=objects1727 client_integration_test.go:753: Skipping nix copy test - isolated store (/nix/var/nix/builds/nix-16695-3377832867/TestClientWithDependencies3131240304/001/store) requires matching store prefix1728--- PASS: TestClientWithDependencies (3.40s)1729=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit1730=== NAME TestClientIntegration1731 client_integration_test.go:334: Created store path: /nix/var/nix/builds/nix-16695-3377832867/TestClientIntegration1775206333/002/store/jfs6lzbvl5y3cifp3r5chrlgrv0z0bz0-test-file.txt17322026/09/24 18:05:17 INFO Received push request method=POST path=/api/pushes17332026/09/24 18:05:17 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17342026/09/24 18:05:17 INFO Uploading jfs6lzbvl5y3cifp3r5chrlgrv0z0bz0-test-file.txt (152B)17352026/09/24 18:05:17 WARN Failed to register uploaded object key=jfs6lzbvl5y3cifp3r5chrlgrv0z0bz0.ls error="server returned 404: 404 page not found\n"17362026/09/24 18:05:18 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"17372026/09/24 18:05:18 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17382026/09/24 18:05:18 INFO Signed narinfos id=1 count=117392026/09/24 18:05:18 INFO Uploading 1 narinfos17402026/09/24 18:05:18 INFO Received complete push request method=POST path=/api/pushes/1/complete17412026/09/24 18:05:18 WARN Failed to register uploaded object key=jfs6lzbvl5y3cifp3r5chrlgrv0z0bz0.narinfo error="server returned 404: 404 page not found\n"17422026/09/24 18:05:18 INFO Upload complete. (171ms)17432026/09/24 18:05:18 INFO All 1 paths already cached1744 client_integration_test.go:360: Retrieved narinfo from S3:1745 StorePath: /nix/var/nix/builds/nix-16695-3377832867/TestClientIntegration1775206333/002/store/jfs6lzbvl5y3cifp3r5chrlgrv0z0bz0-test-file.txt1746 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1747 Compression: zstd1748 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11749 NarSize: 1521750 References: 1751 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11752 client_integration_test.go:361: Retrieved .ls file from S3 (compressed size: 77 bytes)1753 client_integration_test.go:361: Decompressed .ls content (64 bytes):1754 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}17552026/09/24 18:05:18 INFO Received create pin request method=POST path=/api/pins/app17562026/09/24 18:05:18 INFO Received create pin request method=POST path=/api/pins/app17572026/09/24 18:05:18 INFO Received push request method=POST path=/api/pushes17582026/09/24 18:05:18 INFO Object in database but missing from S3 key=jfs6lzbvl5y3cifp3r5chrlgrv0z0bz0.ls17592026/09/24 18:05:18 WARN Found objects in DB but missing from S3, will re-upload count=117602026/09/24 18:05:18 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)17612026/09/24 18:05:18 INFO Received complete push request method=POST path=/api/pushes/2/complete17622026/09/24 18:05:18 WARN Failed to register uploaded object key=jfs6lzbvl5y3cifp3r5chrlgrv0z0bz0.ls error="server returned 404: 404 page not found\n"17632026/09/24 18:05:18 INFO Upload complete. (98ms)1764 client_integration_test.go:389: Retrieved .ls file from S3 (compressed size: 62 bytes)1765 client_integration_test.go:389: Decompressed .ls content (49 bytes):1766 {"version":1,"root":{"type":"regular","size":39}}17672026/09/24 18:05:18 INFO Received push request method=POST path=/api/pushes17682026/09/24 18:05:18 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)17692026/09/24 18:05:18 INFO Received complete push request method=POST path=/api/pushes/3/complete17702026/09/24 18:05:18 WARN Failed to register uploaded object key=jfs6lzbvl5y3cifp3r5chrlgrv0z0bz0.ls error="server returned 404: 404 page not found\n"17712026/09/24 18:05:18 INFO Upload complete. (74ms)1772 client_integration_test.go:405: Retrieved .ls file from S3 (compressed size: 62 bytes)1773 client_integration_test.go:405: Decompressed .ls content (49 bytes):1774 {"version":1,"root":{"type":"regular","size":39}}17752026/09/24 18:05:18 INFO Received push request method=POST path=/api/pushes17762026/09/24 18:05:18 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17772026/09/24 18:05:18 INFO Uploading 120165pcx5n7ika92aq84c0p47swkiwy-lost-commit.txt (152B)17782026/09/24 18:05:18 WARN Failed to register uploaded object key=nar/04d5klw9iix884nk82y7nlkps8afh2bg119y7zkvcf1pc1x2y2jl.nar.zst error="server returned 404: 404 page not found\n"17792026/09/24 18:05:18 WARN Failed to register uploaded object key=120165pcx5n7ika92aq84c0p47swkiwy.ls error="server returned 404: 404 page not found\n"17802026/09/24 18:05:18 INFO Received sign narinfos request method=POST path=/api/pushes/4/sign17812026/09/24 18:05:18 INFO Signed narinfos id=4 count=117822026/09/24 18:05:18 INFO Uploading 1 narinfos17832026/09/24 18:05:18 INFO Received complete push request method=POST path=/api/pushes/4/complete17842026/09/24 18:05:18 WARN Failed to register uploaded object key=120165pcx5n7ika92aq84c0p47swkiwy.narinfo error="server returned 404: 404 page not found\n"17852026/09/24 18:05:18 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Post \"http://127.0.0.1:52705/api/pushes/4/complete\": EOF" url=http://127.0.0.1:52705/api/pushes/4/complete17862026/09/24 18:05:18 INFO Created/updated pin name=app store_path=/nix/store/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa-app narinfo_key=aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.narinfo17872026/09/24 18:05:18 INFO Received complete push request method=POST path=/api/pushes/4/complete17882026-09-24 18:05:18.722 UTC [17230] ERROR: Push does not exist: id=417892026-09-24 18:05:18.722 UTC [17230] CONTEXT: PL/pgSQL function commit_push(bigint) line 9 at RAISE17902026-09-24 18:05:18.722 UTC [17230] STATEMENT: -- name: CommitPush :exec1791 SELECT commit_push($1::bigint)1792 17932026/09/24 18:05:18 INFO Upload complete. (198ms)1794 client_integration_test.go:435: Retrieved narinfo from S3:1795 StorePath: /nix/var/nix/builds/nix-16695-3377832867/TestClientIntegration1775206333/002/store/120165pcx5n7ika92aq84c0p47swkiwy-lost-commit.txt1796 URL: nar/04d5klw9iix884nk82y7nlkps8afh2bg119y7zkvcf1pc1x2y2jl.nar.zst1797 Compression: zstd1798 NarHash: sha256:04d5klw9iix884nk82y7nlkps8afh2bg119y7zkvcf1pc1x2y2jl1799 NarSize: 1521800 References: 1801 CA: fixed:r:sha256:04d5klw9iix884nk82y7nlkps8afh2bg119y7zkvcf1pc1x2y2jl1802 client_integration_test.go:438: Testing garbage collection...18032026/09/24 18:05:18 INFO Created/updated pin name=app store_path=/nix/store/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb-app narinfo_key=bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb.narinfo1804--- PASS: TestConcurrentPinUpdatesAgree (3.03s)1805=== CONT TestServerTLSConfig/missing_CA_file1806=== CONT TestServerTLSConfig/not_a_PEM_file1807=== CONT TestServerTLSConfig/no_client_CA1808--- PASS: TestServerTLSConfig (0.00s)1809 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1810 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.02s)1811 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1812=== CONT TestResolveDBConnectionString/flag_wins1813=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1814=== CONT TestResolveDBConnectionString/missing_file_is_an_error1815=== CONT TestResolveDBConnectionString/file_when_flag_empty1816=== CONT TestResolveDBConnectionString/nothing_configured1817=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info18182026/09/24 18:05:18 INFO Received uploads request method=POST path=/1819=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal18202026/09/24 18:05:18 INFO Received uploads request method=POST path=/1821=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key18222026/09/24 18:05:18 INFO Received request for more parts method=POST path=/1823=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key18242026/09/24 18:05:18 INFO Received complete multipart upload request method=POST path=/1825=== CONT TestIsValidUploadKey/listing1826--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1827 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1828 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1829 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1830 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1831=== CONT TestIsValidUploadKey/realisation1832=== CONT TestIsValidUploadKey/unknown_type1833=== CONT TestIsValidUploadKey/empty_key1834=== CONT TestIsValidUploadKey/traversal_nar1835=== CONT TestIsValidUploadKey/absolute1836=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1837=== CONT TestIsValidUploadKey/traversal1838=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1839=== CONT TestIsValidUploadKey/index.html1840=== CONT TestIsValidUploadKey/nix-cache-info1841=== CONT TestIsValidUploadKey/realisation_plus_in_output1842=== CONT TestIsValidUploadKey/nar_xz1843=== CONT TestIsValidUploadKey/build_log1844=== CONT TestIsValidUploadKey/build_log_home-manager_file1845=== CONT TestIsValidUploadKey/nar_plain1846=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1847=== CONT TestIsValidUploadKey/build_log_equals1848=== CONT TestIsValidUploadKey/build_log_question_mark1849=== CONT TestIsValidUploadKey/build_log_plus_in_name1850=== CONT TestIsValidUploadKey/nar_zst1851=== CONT TestIsValidUploadKey/narinfo1852=== CONT TestPendingClosureWriteTimeout/empty1853--- PASS: TestIsValidUploadKey (0.00s)1854 --- PASS: TestIsValidUploadKey/listing (0.00s)1855 --- PASS: TestIsValidUploadKey/realisation (0.00s)1856 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1857 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1858 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1859 --- PASS: TestIsValidUploadKey/absolute (0.00s)1860 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1861 --- PASS: TestIsValidUploadKey/traversal (0.00s)1862 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1863 --- PASS: TestIsValidUploadKey/index.html (0.00s)1864 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1865 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1866 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1867 --- PASS: TestIsValidUploadKey/build_log (0.00s)1868 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1869 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1870 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1871 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1872 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1873 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1874 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1875 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1876=== CONT TestPendingClosureWriteTimeout/negative1877=== CONT TestPendingClosureWriteTimeout/670k_objects1878=== CONT TestPendingClosureWriteTimeout/400_objects1879=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline18802026/09/24 18:05:18 INFO Starting cleanup of old closures method=DELETE path=/api/closures18812026/09/24 18:05:18 INFO Garbage collection started18822026/09/24 18:05:18 INFO Aborted multipart uploads count=0 kept=018832026/09/24 18:05:18 WARN Force mode enabled - objects will be deleted immediately without grace period1884--- PASS: TestResolveDBConnectionString (0.01s)1885 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1886 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1887 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1888 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)1889 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)18902026/09/24 18:05:18 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=018912026/09/24 18:05:18 INFO Vacuumed table table=pending_closures18922026/09/24 18:05:18 INFO Vacuumed table table=pending_objects18932026/09/24 18:05:18 INFO Vacuumed table table=multipart_uploads18942026/09/24 18:05:18 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"1895--- PASS: TestService_AuthMiddleware (2.80s)1896=== CONT TestProxyWriteTimeout/narinfo1897=== CONT TestProxyWriteTimeout/1_GiB_nar1898=== CONT TestProxyWriteTimeout/unknown_size1899=== CONT TestProxyWriteTimeout/10_GiB_nar1900=== CONT TestParseSingleRange/malformed_end_before_start1901--- PASS: TestProxyWriteTimeout (0.00s)1902 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1903 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1904 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1905 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1906=== CONT TestParseSingleRange/start_far_past_EOF1907=== CONT TestParseSingleRange/closed1908=== CONT TestParseSingleRange/single_byte1909=== CONT TestParseSingleRange/suffix_exceeds_size1910=== CONT TestParseSingleRange/start_past_EOF1911=== CONT TestParseSingleRange/end_clamped_to_size1912=== CONT TestParseSingleRange/open-ended1913=== CONT TestParseSingleRange/malformed_no_dash1914=== CONT TestParseSingleRange/suffix1915=== CONT TestParseSingleRange/malformed_both_empty1916=== CONT TestParseSingleRange/unknown_unit1917=== CONT TestParseSingleRange/multi-range_ignored1918=== CONT TestParseSingleRange/none1919=== CONT TestIsValidCachePath/nar_zst1920--- PASS: TestParseSingleRange (0.00s)1921 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1922 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1923 --- PASS: TestParseSingleRange/closed (0.00s)1924 --- PASS: TestParseSingleRange/single_byte (0.00s)1925 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1926 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1927 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1928 --- PASS: TestParseSingleRange/open-ended (0.00s)1929 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1930 --- PASS: TestParseSingleRange/suffix (0.00s)1931 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1932 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1933 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1934 --- PASS: TestParseSingleRange/none (0.00s)1935=== CONT TestIsValidCachePath/short_hash1936=== CONT TestIsValidCachePath/wrong_extension1937=== CONT TestIsValidCachePath/realisation1938=== CONT TestIsValidCachePath/log1939=== CONT TestIsValidCachePath/ls1940=== CONT TestIsValidCachePath/nar_uncompressed1941=== CONT TestIsValidCachePath/nar_xz1942=== CONT TestIsValidCachePath/nix-cache-info1943=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1944=== CONT TestIsValidCachePath/nar_bz21945=== CONT TestIsValidCachePath/narinfo1946=== CONT TestIsValidCachePath/empty1947=== CONT TestIsValidCachePath/traversal_in_middle1948=== CONT TestIsValidCachePath/index.html1949=== CONT TestIsValidCachePath/random_path1950=== CONT TestIsValidCachePath/invalid_char_e1951=== CONT TestIsValidCachePath/leading_slash1952=== CONT TestIsValidCachePath/traversal_parent1953=== CONT TestIsValidCachePath/invalid_char_u1954=== CONT TestGCEndsOnShutdown/before_the_run1955--- PASS: TestIsValidCachePath (0.00s)1956 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1957 --- PASS: TestIsValidCachePath/short_hash (0.00s)1958 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1959 --- PASS: TestIsValidCachePath/realisation (0.00s)1960 --- PASS: TestIsValidCachePath/log (0.00s)1961 --- PASS: TestIsValidCachePath/ls (0.00s)1962 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1963 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1964 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1965 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1966 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1967 --- PASS: TestIsValidCachePath/narinfo (0.00s)1968 --- PASS: TestIsValidCachePath/empty (0.00s)1969 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1970 --- PASS: TestIsValidCachePath/index.html (0.00s)1971 --- PASS: TestIsValidCachePath/random_path (0.00s)1972 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1973 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1974 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1975 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)19762026/09/24 18:05:19 INFO Vacuumed table table=closures19772026/09/24 18:05:19 INFO Vacuumed table table=objects1978--- PASS: TestReadRedirectKeepsNarinfoProxied (3.03s)1979=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark19802026/09/24 18:05:19 INFO Received uploads request method=POST path=/api/pending_closures19812026/09/24 18:05:19 INFO Received uploads request method=POST path=/api/pending_closures1982--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (3.01s)1983=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete19842026/09/24 18:05:20 INFO Received uploads request method=POST path=/api/pending_closures19852026/09/24 18:05:20 INFO Aborted multipart uploads count=0 kept=019862026/09/24 18:05:20 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=019872026/09/24 18:05:20 INFO Vacuumed table table=pending_closures19882026/09/24 18:05:20 INFO Vacuumed table table=pending_objects19892026/09/24 18:05:20 INFO Vacuumed table table=multipart_uploads19902026/09/24 18:05:20 INFO Vacuumed table table=closures19912026/09/24 18:05:20 INFO Vacuumed table table=objects19922026/09/24 18:05:20 INFO Aborted multipart uploads count=0 kept=019932026/09/24 18:05:20 WARN Force mode enabled - objects will be deleted immediately without grace period19942026/09/24 18:05:20 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=019952026/09/24 18:05:20 INFO Vacuumed table table=pending_closures19962026/09/24 18:05:20 INFO Vacuumed table table=pending_objects19972026/09/24 18:05:20 INFO Vacuumed table table=multipart_uploads19982026/09/24 18:05:20 INFO Vacuumed table table=closures19992026/09/24 18:05:20 INFO Vacuumed table table=objects2000--- PASS: TestPushDedupSurvivesConcurrentGC (3.76s)2001=== CONT TestCacheConfigHandler/full_config,_no_issuer2002=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2003=== CONT TestCacheConfigHandler/no_signing_keys2004=== CONT TestCacheConfigHandler/no_cache_url_configured2005=== CONT TestClientErrorHandling/InvalidAuthToken2006--- PASS: TestCacheConfigHandler (0.00s)2007 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)2008 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)2009 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)2010 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)20112026/09/24 18:05:20 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=2 objects_marked=6 objects_deleted=6 objects_failed=02012=== NAME TestClientIntegration2013 client_integration_test.go:445: Objects in database after GC:2014 client_integration_test.go:445: Successfully deleted all objects with GC --force20152026/09/24 18:05:20 INFO Received push request method=POST path=/api/pushes2016--- PASS: TestClientIntegration (5.63s)2017=== CONT TestClientErrorHandling/InvalidStorePath20182026/09/24 18:05:21 INFO Received complete multipart upload request method=POST path=/api/multipart/complete20192026/09/24 18:05:21 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=NDc3YzAzNzQtNDI2Yy00MTM0LTg2ZmEtYThmMDFjOTM4M2UxLjQ3MDNjNWM2LThmY2YtNDgzNC1iYTUwLWIzMjAyYThjMjgxY3gxNzkwMjczMTE5NjM5OTg1MDAw parts=1220202026/09/24 18:05:21 INFO Received uploads request method=POST path=/api/pending_closures20212026/09/24 18:05:21 INFO Received uploads request method=POST path=/api/pending_closures20222026/09/24 18:05:22 INFO Received uploads request method=POST path=/api/pending_closures2023--- PASS: TestReadProxyOutlastsServerWriteTimeout (6.94s)2024=== CONT TestClientErrorHandling/ServerNotAvailable20252026/09/24 18:05:22 INFO Received complete multipart upload request method=POST path=/api/multipart/complete20262026/09/24 18:05:22 INFO Completed multipart upload object_key=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa00000000000000000000.nar.zst upload_id=NDc3YzAzNzQtNDI2Yy00MTM0LTg2ZmEtYThmMDFjOTM4M2UxLjE1NjNlNTJjLWM1YjMtNGE0NC1iY2QwLTBkNWEwMjRkYjM2OHgxNzkwMjczMTIwODU1NTYxMDAw parts=102027=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2028=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2029=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected20302026/09/24 18:05:22 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]2031=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected20322026/09/24 18:05:22 WARN Authentication failed token_preview=eyJhbGciOi...aA3OIrv3fw token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2033=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts20342026/09/24 18:05:22 INFO Received request for more parts method=POST path=/2035--- PASS: TestService_AuthMiddleware_OIDC (1.75s)2036 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2037 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2038 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2039 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)20402026/09/24 18:05:23 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2041=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart20422026/09/24 18:05:23 INFO Received complete multipart upload request method=POST path=/20432026/09/24 18:05:23 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=214.440889ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2044=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure2045--- PASS: TestPendingClosureWriteTimeout (0.00s)2046 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2047 --- PASS: TestPendingClosureWriteTimeout/negative (0.00s)2048 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2049 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2050 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (4.52s)20512026/09/24 18:05:23 INFO Received uploads request method=POST path=/20522026/09/24 18:05:23 INFO Aborted multipart uploads count=0 kept=020532026/09/24 18:05:23 WARN Force mode enabled - objects will be deleted immediately without grace period20542026-09-24 18:05:23.368 UTC [17310] ERROR: canceling statement due to user request20552026-09-24 18:05:23.368 UTC [17310] STATEMENT: -- name: MarkStaleObjects :execrows2056 WITH RECURSIVE ct AS (2057 SELECT timezone('UTC', now()) AS now2058 ),2059 closure_reach AS (2060 -- Start with all closure keys2061 SELECT o.key, o.refs2062 FROM objects o2063 INNER JOIN closures c ON o.key = c.key2064 UNION2065 -- Recursively add all referenced objects2066 SELECT o.key, o.refs2067 FROM objects o2068 INNER JOIN closure_reach cr ON o.key = ANY(cr.refs)2069 ),2070 reachable_objects AS (2071 SELECT DISTINCT key FROM closure_reach2072 ),2073 stale_objects AS (2074 SELECT o.key2075 FROM objects AS o, ct2076 WHERE2077 NOT EXISTS (2078 SELECT 12079 FROM reachable_objects ro2080 WHERE ro.key = o.key2081 )2082 AND NOT EXISTS (2083 SELECT 12084 FROM pending_objects AS po2085 WHERE po.key = o.key2086 )2087 AND o.deleted_at IS NULL -- Only mark fresh objects2088 ORDER BY o.key -- lock in key order, like commit_pending_closure2089 FOR UPDATE2090 )2091 UPDATE objects2092 SET2093 deleted_at = ct.now,2094 first_deleted_at = COALESCE(first_deleted_at, ct.now)2095 FROM stale_objects, ct2096 WHERE objects.key = stale_objects.key2097 2098=== CONT TestService_RequireScope_OIDC/ops_may_admin2099=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2100=== CONT TestService_RequireScope_OIDC/writer_implies_read2101=== CONT TestService_RequireScope_OIDC/reader_may_read2102=== CONT TestService_RequireScope_OIDC/static_token_may_admin2103=== CONT TestService_RequireScope_OIDC/static_token_may_write2104=== CONT TestService_RequireScope_OIDC/ops_may_not_write2105=== CONT TestService_RequireScope_OIDC/reader_may_not_write2106=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2107=== CONT TestService_RequireScope_OIDC/builder_may_write2108=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check2109--- PASS: TestService_RequireScope_OIDC (2.09s)2110 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2111 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2112 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2113 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2114 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2115 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2116 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2117 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2118 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2119 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)21202026/09/24 18:05:23 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=387.214588ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2121=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows21222026/09/24 18:05:23 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=799.751266ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present21232026/09/24 18:05:23 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21242026/09/24 18:05:23 INFO Aborted multipart uploads count=0 kept=021252026/09/24 18:05:23 WARN Force mode enabled - objects will be deleted immediately without grace period21262026/09/24 18:05:23 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=NDc3YzAzNzQtNDI2Yy00MTM0LTg2ZmEtYThmMDFjOTM4M2UxLjM5ZDExMjFlLWM2Y2EtNGJjOC04ZmY0LTAwYTAwZjJmZDY2YXgxNzkwMjczMTIxODg5Nzg1MDAw error="Get \"http://127.0.0.1:1/bucket84/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"21272026/09/24 18:05:23 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=NDc3YzAzNzQtNDI2Yy00MTM0LTg2ZmEtYThmMDFjOTM4M2UxLjRmNGE0ODI4LWYzOGItNDIxNC05NTg0LTQxM2ZjNmQyNzM1MXgxNzkwMjczMTIxODMwMDIxMDAw parts=1221282026/09/24 18:05:23 INFO Received cleanup request method=DELETE path=/api/pending_closures21292026/09/24 18:05:23 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:52391/bucket91/?delete=\": context canceled"21302026/09/24 18:05:23 INFO Aborted multipart uploads count=1 kept=02131=== CONT TestPush_RejectsBadRequests/bad_root2132--- PASS: TestGCEndsOnShutdown (0.00s)2133 --- PASS: TestGCEndsOnShutdown/before_the_run (3.92s)2134 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (4.03s)2135 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (3.94s)21362026/09/24 18:05:23 INFO Received push request method=POST path=/api/pushes2137=== CONT TestPush_RejectsBadRequests/no_objects21382026/09/24 18:05:23 INFO Received push request method=POST path=/api/pushes2139=== CONT TestPush_RejectsBadRequests/no_roots21402026/09/24 18:05:23 INFO Received push request method=POST path=/api/pushes2141=== CONT TestPush_RejectsBadRequests/root_not_in_objects21422026/09/24 18:05:23 INFO Received push request method=POST path=/api/pushes2143--- PASS: TestRedundantMultipartUpload (7.25s)2144--- PASS: TestPush_RejectsBadRequests (2.33s)2145 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)2146 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)2147 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)2148 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)2149=== NAME TestOrphanedObjectsGCStressTest2150 orphaned_objects_gc_test.go:431: Created 10 active closures, 5 to-delete closures, 20 orphaned chains21512026/09/24 18:05:24 INFO Received complete multipart upload request method=POST path=/api/multipart/complete2152 orphaned_objects_gc_test.go:452: Marked 210 objects for deletion21532026/09/24 18:05:24 INFO Completed multipart upload object_key=nar/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb00000000000000000000.nar.zst upload_id=NDc3YzAzNzQtNDI2Yy00MTM0LTg2ZmEtYThmMDFjOTM4M2UxLjZkMTE0ZmRmLTQ2ZDItNDZhZC04ZjM1LTVlYmYxMmZjZDkwNHgxNzkwMjczMTIwODU0ODk0MDAw parts=1021542026/09/24 18:05:24 INFO Received complete push request method=POST path=/api/pushes/1/complete21552026/09/24 18:05:24 INFO Received push request method=POST path=/api/pushes21562026/09/24 18:05:24 INFO Aborted multipart uploads count=0 kept=021572026/09/24 18:05:24 WARN Force mode enabled - objects will be deleted immediately without grace period21582026/09/24 18:05:24 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"21592026/09/24 18:05:24 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=021602026/09/24 18:05:24 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"21612026/09/24 18:05:24 INFO Vacuumed table table=pending_closures21622026/09/24 18:05:24 INFO Vacuumed table table=pending_objects21632026/09/24 18:05:24 INFO Vacuumed table table=multipart_uploads21642026/09/24 18:05:24 INFO Vacuumed table table=closures21652026/09/24 18:05:24 INFO Vacuumed table table=objects21662026/09/24 18:05:24 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.471348752s error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present21672026/09/24 18:05:24 INFO Received uploads request method=POST path=/api/pending_closures21682026/09/24 18:05:24 INFO Aborted multipart uploads count=0 kept=021692026/09/24 18:05:24 WARN Force mode enabled - objects will be deleted immediately without grace period21702026/09/24 18:05:24 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=021712026/09/24 18:05:24 INFO Vacuumed table table=pending_closures21722026/09/24 18:05:24 INFO Vacuumed table table=pending_objects21732026/09/24 18:05:24 INFO Vacuumed table table=multipart_uploads21742026/09/24 18:05:24 INFO Vacuumed table table=closures21752026/09/24 18:05:24 INFO Vacuumed table table=objects21762026/09/24 18:05:25 INFO Received uploads request method=POST path=/api/pending_closures21772026/09/24 18:05:25 INFO Aborted multipart uploads count=0 kept=021782026/09/24 18:05:25 WARN Force mode enabled - objects will be deleted immediately without grace period21792026/09/24 18:05:25 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=021802026/09/24 18:05:25 INFO Vacuumed table table=pending_closures21812026/09/24 18:05:25 INFO Vacuumed table table=pending_objects21822026/09/24 18:05:25 INFO Vacuumed table table=multipart_uploads21832026/09/24 18:05:25 INFO Vacuumed table table=closures21842026/09/24 18:05:25 INFO Vacuumed table table=objects2185--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2186 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (1.62s)2187 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (1.76s)21882026/09/24 18:05:25 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21892026/09/24 18:05:25 INFO Completed multipart upload object_key=nar/cccccccccccccccccccccccccccccccc00000000000000000000.nar.zst upload_id=NDc3YzAzNzQtNDI2Yy00MTM0LTg2ZmEtYThmMDFjOTM4M2UxLjc1N2YyMGUxLWM4MzUtNDA5Yi05N2ZmLTA3NTNhM2M4YTU0ZXgxNzkwMjczMTI0MzYxODM0MDAw parts=1021902026/09/24 18:05:25 INFO Received complete push request method=POST path=/api/pushes/2/complete2191--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (7.71s)2192=== NAME TestOrphanedObjectsGCStressTest2193 orphaned_objects_gc_test.go:515: Stress test completed successfully:2194 orphaned_objects_gc_test.go:516: - Active objects preserved: 202195 orphaned_objects_gc_test.go:517: - Objects deleted: 2102196 orphaned_objects_gc_test.go:518: - Total GC'd: 2102197--- PASS: TestOrphanedObjectsGCStressTest (9.93s)21982026/09/24 18:05:26 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21992026/09/24 18:05:26 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=197.440581ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22002026/09/24 18:05:26 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=386.696573ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22012026/09/24 18:05:26 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=866.799887ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2202--- PASS: TestUploadHandlersRejectOversizedBody (0.06s)2203 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.27s)2204 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.29s)2205 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (4.31s)22062026/09/24 18:05:27 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.4967416s error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22072026/09/24 18:05:29 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 127.0.0.1:19999: connect: connection refused"22082026/09/24 18:05:29 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22092026/09/24 18:05:29 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=197.864605ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22102026/09/24 18:05:29 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=363.12408ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22112026/09/24 18:05:29 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=735.938485ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22122026/09/24 18:05:30 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.656065969s error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22132026/09/24 18:05:32 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22142026/09/24 18:05:32 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=210.519147ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22152026/09/24 18:05:32 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=405.088539ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22162026/09/24 18:05:32 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=842.818401ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22172026/09/24 18:05:33 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.455794677s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2218--- PASS: TestClientErrorHandling (0.00s)2219 --- PASS: TestClientErrorHandling/InvalidStorePath (3.63s)2220 --- PASS: TestClientErrorHandling/InvalidAuthToken (3.89s)2221 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.62s)2222PASS2223{"timestamp":"2026-09-24T18:05:35.302108Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:52702","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2260,"threadName":"rustfs-worker","threadId":"ThreadId(10)"}2224{"timestamp":"2026-09-24T18:05:35.302108Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:52719","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2260,"threadName":"rustfs-worker","threadId":"ThreadId(9)"}22252026-09-24 18:05:35.448 UTC [16741] LOG: received smart shutdown request22262026-09-24 18:05:35.449 UTC [16741] LOG: background worker "logical replication launcher" (PID 16751) exited with exit code 122272026-09-24 18:05:35.458 UTC [16746] LOG: shutting down22282026-09-24 18:05:35.458 UTC [16746] LOG: checkpoint starting: shutdown immediate22292026-09-24 18:05:36.773 UTC [16746] LOG: checkpoint complete: wrote 12724 buffers (77.7%), wrote 4 SLRU buffers; 0 WAL file(s) added, 0 removed, 29 recycled; write=0.717 s, sync=0.559 s, total=1.315 s; sync files=32694, longest=0.001 s, average=0.001 s; distance=471208 kB, estimate=471208 kB; lsn=0/1E3B6FA8, redo lsn=0/1E3B6FA822302026-09-24 18:05:36.779 UTC [16741] LOG: database system is shut down2231Running OIDC tests...2232=== RUN TestAudienceForIssuer2233=== PAUSE TestAudienceForIssuer2234=== RUN TestHTTPClientForHasTimeouts2235=== PAUSE TestHTTPClientForHasTimeouts2236=== RUN TestGlobMatch2237=== PAUSE TestGlobMatch2238=== RUN TestValidateToken_ValidToken2239=== PAUSE TestValidateToken_ValidToken2240=== RUN TestValidateToken_WrongAudience2241=== PAUSE TestValidateToken_WrongAudience2242=== RUN TestValidateToken_Expired2243=== PAUSE TestValidateToken_Expired2244=== RUN TestValidateToken_BoundClaimsMismatch2245=== PAUSE TestValidateToken_BoundClaimsMismatch2246=== RUN TestValidateToken_BoundSubjectMismatch2247=== PAUSE TestValidateToken_BoundSubjectMismatch2248=== RUN TestValidateToken_MultipleProviders2249=== PAUSE TestValidateToken_MultipleProviders2250=== RUN TestValidateToken_NoMatchingProvider2251=== PAUSE TestValidateToken_NoMatchingProvider2252=== RUN TestValidateToken_KubernetesServiceAccount2253=== PAUSE TestValidateToken_KubernetesServiceAccount2254=== RUN TestNewValidator_KubernetesRequiresCA2255=== PAUSE TestNewValidator_KubernetesRequiresCA2256=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2257=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2258=== RUN TestPins_ReservedForMatchingRule2259=== PAUSE TestPins_ReservedForMatchingRule2260=== RUN TestPins_TopLevelShorthand2261=== PAUSE TestPins_TopLevelShorthand2262=== RUN TestPins_ConfigValidation2263=== PAUSE TestPins_ConfigValidation2264=== RUN TestScopes_LegacyProviderDefaultsToWrite2265=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2266=== RUN TestScopes_Rules2267=== PAUSE TestScopes_Rules2268=== RUN TestScopes_ConfigValidation2269=== PAUSE TestScopes_ConfigValidation2270=== CONT TestGlobMatch2271=== CONT TestNewValidator_KubernetesRequiresCA2272=== CONT TestValidateToken_WrongAudience2273=== CONT TestValidateToken_KubernetesServiceAccount2274=== CONT TestValidateToken_Expired2275=== CONT TestHTTPClientForHasTimeouts2276=== CONT TestValidateToken_ValidToken2277=== RUN TestGlobMatch/foo_foo2278=== PAUSE TestGlobMatch/foo_foo2279=== CONT TestAudienceForIssuer2280--- PASS: TestAudienceForIssuer (0.00s)2281=== CONT TestValidateToken_MultipleProviders2282=== RUN TestGlobMatch/foo_bar2283=== PAUSE TestGlobMatch/foo_bar2284=== RUN TestGlobMatch/*_2285=== PAUSE TestGlobMatch/*_2286=== RUN TestGlobMatch/*_anything2287=== PAUSE TestGlobMatch/*_anything2288=== RUN TestGlobMatch/foo*_foo2289=== PAUSE TestGlobMatch/foo*_foo2290=== RUN TestGlobMatch/foo*_foobar2291=== PAUSE TestGlobMatch/foo*_foobar2292=== RUN TestGlobMatch/foo*_bar2293=== PAUSE TestGlobMatch/foo*_bar2294=== RUN TestGlobMatch/*bar_bar2295=== PAUSE TestGlobMatch/*bar_bar2296=== RUN TestGlobMatch/*bar_foobar2297=== PAUSE TestGlobMatch/*bar_foobar2298=== RUN TestGlobMatch/*bar_foo2299=== PAUSE TestGlobMatch/*bar_foo2300=== RUN TestGlobMatch/foo*bar_foobar2301=== PAUSE TestGlobMatch/foo*bar_foobar2302=== RUN TestGlobMatch/foo*bar_foo123bar2303=== PAUSE TestGlobMatch/foo*bar_foo123bar2304=== RUN TestGlobMatch/foo*bar_foobarbaz2305=== PAUSE TestGlobMatch/foo*bar_foobarbaz2306=== RUN TestGlobMatch/*/*_foo/bar2307=== PAUSE TestGlobMatch/*/*_foo/bar2308=== RUN TestGlobMatch/*/*_foo2309=== PAUSE TestGlobMatch/*/*_foo2310=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2311=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2312=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02313=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02314=== CONT TestValidateToken_NoMatchingProvider2315=== CONT TestValidateToken_BoundClaimsMismatch2316=== RUN TestGlobMatch/refs/*/main_refs/heads/main2317=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2318=== RUN TestGlobMatch/fo?_foo2319=== PAUSE TestGlobMatch/fo?_foo2320=== RUN TestGlobMatch/fo?_fo2321=== PAUSE TestGlobMatch/fo?_fo2322=== RUN TestGlobMatch/fo?_fooo2323=== PAUSE TestGlobMatch/fo?_fooo2324=== RUN TestGlobMatch/?oo_foo2325=== PAUSE TestGlobMatch/?oo_foo2326=== RUN TestGlobMatch/?oo_boo2327=== PAUSE TestGlobMatch/?oo_boo2328=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2329=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2330=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2331=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2332=== CONT TestPins_TopLevelShorthand23332026/09/24 18:05:39 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52837/oidc2334--- PASS: TestPins_TopLevelShorthand (0.06s)2335=== CONT TestScopes_ConfigValidation2336--- PASS: TestScopes_ConfigValidation (0.00s)2337=== CONT TestScopes_Rules23382026/09/24 18:05:39 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52839/oidc2339--- PASS: TestValidateToken_BoundClaimsMismatch (0.07s)2340=== CONT TestScopes_LegacyProviderDefaultsToWrite23412026/09/24 18:05:39 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52841/oidc2342--- PASS: TestValidateToken_WrongAudience (0.09s)2343=== CONT TestPins_ReservedForMatchingRule23442026/09/24 18:05:39 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52846/oidc23452026/09/24 18:05:39 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:528442346--- PASS: TestValidateToken_Expired (0.12s)2347=== CONT TestPins_ConfigValidation2348=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2349--- PASS: TestPins_ConfigValidation (0.00s)2350--- PASS: TestValidateToken_KubernetesServiceAccount (0.12s)23512026/09/24 18:05:39 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52848/oidc2352=== CONT TestValidateToken_BoundSubjectMismatch2353=== CONT TestGlobMatch/foo_foo2354=== CONT TestGlobMatch/*/*_foo/bar2355=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2356=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2357--- PASS: TestValidateToken_ValidToken (0.13s)2358=== CONT TestGlobMatch/?oo_boo2359=== CONT TestGlobMatch/?oo_foo2360=== CONT TestGlobMatch/fo?_fo2361=== CONT TestGlobMatch/fo?_foo2362=== CONT TestGlobMatch/refs/*/main_refs/heads/main2363=== CONT TestGlobMatch/fo?_fooo2364=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2365=== CONT TestGlobMatch/*/*_foo2366=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02367=== CONT TestGlobMatch/*bar_foobar2368=== CONT TestGlobMatch/foo*bar_foobarbaz2369=== CONT TestGlobMatch/foo*bar_foo123bar2370=== CONT TestGlobMatch/*bar_foo2371=== CONT TestGlobMatch/foo*bar_foobar2372=== CONT TestGlobMatch/*bar_bar2373=== CONT TestGlobMatch/*_anything2374=== CONT TestGlobMatch/foo*_bar2375=== CONT TestGlobMatch/foo*_foobar2376=== CONT TestGlobMatch/foo_bar2377=== CONT TestGlobMatch/foo*_foo2378=== CONT TestGlobMatch/*_2379--- PASS: TestGlobMatch (0.01s)2380 --- PASS: TestGlobMatch/foo_foo (0.00s)2381 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2382 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2383 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2384 --- PASS: TestGlobMatch/?oo_boo (0.00s)2385 --- PASS: TestGlobMatch/?oo_foo (0.00s)2386 --- PASS: TestGlobMatch/fo?_fo (0.00s)2387 --- PASS: TestGlobMatch/fo?_foo (0.00s)2388 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2389 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2390 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2391 --- PASS: TestGlobMatch/*/*_foo (0.00s)2392 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2393 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2394 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2395 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2396 --- PASS: TestGlobMatch/*bar_foo (0.00s)2397 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2398 --- PASS: TestGlobMatch/*bar_bar (0.00s)2399 --- PASS: TestGlobMatch/*_anything (0.00s)2400 --- PASS: TestGlobMatch/foo*_bar (0.00s)2401 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2402 --- PASS: TestGlobMatch/foo_bar (0.00s)2403 --- PASS: TestGlobMatch/foo*_foo (0.00s)2404 --- PASS: TestGlobMatch/*_ (0.00s)24052026/09/24 18:05:39 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52850/oidc2406--- PASS: TestScopes_Rules (0.07s)24072026/09/24 18:05:39 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52852/oidc2408--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.07s)24092026/09/24 18:05:39 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52856/oidc24102026/09/24 18:05:39 http: TLS handshake error from 127.0.0.1:52855: remote error: tls: bad certificate2411--- PASS: TestNewValidator_KubernetesRequiresCA (0.16s)2412--- PASS: TestValidateToken_BoundSubjectMismatch (0.04s)24132026/09/24 18:05:39 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52859/oidc2414--- PASS: TestPins_ReservedForMatchingRule (0.08s)24152026/09/24 18:05:39 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:52858/oidc2416--- PASS: TestValidateToken_NoMatchingProvider (0.19s)24172026/09/24 18:05:39 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232418--- PASS: TestHTTPClientForHasTimeouts (0.20s)2419--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.09s)24202026/09/24 18:05:39 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:52865/oidc24212026/09/24 18:05:39 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:52843/oidc2422--- PASS: TestValidateToken_MultipleProviders (0.34s)2423PASS2424Running signing tests...2425=== RUN TestGenerateFingerprint2426=== PAUSE TestGenerateFingerprint2427=== RUN TestParseSigningKey2428=== PAUSE TestParseSigningKey2429=== RUN TestSignMessage2430=== PAUSE TestSignMessage2431=== RUN TestSignNarinfo2432=== PAUSE TestSignNarinfo2433=== CONT TestGenerateFingerprint2434=== CONT TestSignNarinfo2435=== CONT TestSignMessage2436=== RUN TestGenerateFingerprint/basic_with_references2437=== CONT TestParseSigningKey2438=== PAUSE TestGenerateFingerprint/basic_with_references2439=== RUN TestParseSigningKey/valid_32-byte_key2440=== RUN TestGenerateFingerprint/no_references2441=== PAUSE TestGenerateFingerprint/no_references2442=== PAUSE TestParseSigningKey/valid_32-byte_key2443=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2444=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2445=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2446=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2447=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2448=== RUN TestParseSigningKey/no_colon2449=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2450=== PAUSE TestParseSigningKey/no_colon2451=== RUN TestGenerateFingerprint/invalid_nar_hash_length2452=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2453=== RUN TestParseSigningKey/empty_name2454=== RUN TestGenerateFingerprint/invalid_store_path_prefix2455=== PAUSE TestParseSigningKey/empty_name2456=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2457=== RUN TestParseSigningKey/invalid_base642458=== RUN TestGenerateFingerprint/invalid_reference_prefix2459=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2460=== PAUSE TestParseSigningKey/invalid_base642461=== CONT TestGenerateFingerprint/basic_with_references2462=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2463=== RUN TestParseSigningKey/wrong_length2464=== CONT TestGenerateFingerprint/no_references2465=== PAUSE TestParseSigningKey/wrong_length2466=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2467=== CONT TestGenerateFingerprint/invalid_nar_hash_length2468=== CONT TestGenerateFingerprint/invalid_store_path_prefix2469=== CONT TestGenerateFingerprint/invalid_reference_prefix2470=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2471=== CONT TestParseSigningKey/no_colon2472=== CONT TestParseSigningKey/empty_name2473=== CONT TestParseSigningKey/invalid_base642474=== CONT TestParseSigningKey/wrong_length2475=== CONT TestParseSigningKey/valid_32-byte_key2476--- PASS: TestGenerateFingerprint (0.00s)2477 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2478 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2479 --- PASS: TestGenerateFingerprint/no_references (0.00s)2480 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2481 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2482 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2483 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2484--- PASS: TestParseSigningKey (0.00s)2485 --- PASS: TestParseSigningKey/no_colon (0.00s)2486 --- PASS: TestParseSigningKey/empty_name (0.00s)2487 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2488 --- PASS: TestParseSigningKey/wrong_length (0.00s)2489 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.01s)2490 --- PASS: TestParseSigningKey/valid_32-byte_key (0.01s)2491--- PASS: TestSignMessage (0.01s)2492--- PASS: TestSignNarinfo (0.01s)2493PASS2494Running hook tests...2495=== RUN TestSendPathsEmpty2496=== PAUSE TestSendPathsEmpty2497=== RUN TestQueueEnqueueAndFetch2498=== PAUSE TestQueueEnqueueAndFetch2499=== RUN TestQueueDeduplication2500=== PAUSE TestQueueDeduplication2501=== RUN TestQueueRemove2502=== PAUSE TestQueueRemove2503=== RUN TestQueueFetchBatchLimit2504=== PAUSE TestQueueFetchBatchLimit2505=== RUN TestQueueRetryMovesToBack2506=== PAUSE TestQueueRetryMovesToBack2507=== RUN TestQueueFetchRemoveLifecycle2508=== PAUSE TestQueueFetchRemoveLifecycle2509=== RUN TestQueueConcurrentWriters2510=== PAUSE TestQueueConcurrentWriters2511=== RUN TestQueueEnqueueWaitsOutSlowWriter2512=== PAUSE TestQueueEnqueueWaitsOutSlowWriter2513=== RUN TestQueueRemoveLargeClosure2514=== PAUSE TestQueueRemoveLargeClosure2515=== RUN TestServerClientIntegration2516=== PAUSE TestServerClientIntegration2517=== RUN TestServerQueueError2518=== PAUSE TestServerQueueError2519=== RUN TestServerRefusesOversizedAndNonStoreRequests2520=== PAUSE TestServerRefusesOversizedAndNonStoreRequests2521=== RUN TestGetListenerSocketActivation2522 server_test.go:317: === RUN TestGetListenerSocketActivation2523 --- PASS: TestGetListenerSocketActivation (0.00s)2524 PASS2525 2526--- PASS: TestGetListenerSocketActivation (1.03s)2527=== RUN TestServerStalledClientDoesNotBlockShutdown2528=== PAUSE TestServerStalledClientDoesNotBlockShutdown2529=== RUN TestServerBacksOffOnAcceptErrors2530=== PAUSE TestServerBacksOffOnAcceptErrors2531=== RUN TestDrainIsolatesPoisonPath2532=== PAUSE TestDrainIsolatesPoisonPath2533=== RUN TestRunNotBlockedByPoisonHead2534=== PAUSE TestRunNotBlockedByPoisonHead2535=== RUN TestDrainGivesUpWhenServerDown2536=== PAUSE TestDrainGivesUpWhenServerDown2537=== RUN TestFailedPathPrunedByLaterClosure2538=== PAUSE TestFailedPathPrunedByLaterClosure2539=== RUN TestWorkerUploadsAndRemoves2540=== PAUSE TestWorkerUploadsAndRemoves2541=== RUN TestWorkerSkipsGCdPaths2542=== PAUSE TestWorkerSkipsGCdPaths2543=== RUN TestWorkerPrunesClosureDeps2544=== PAUSE TestWorkerPrunesClosureDeps2545=== RUN TestWorkerRemovesCachedPathBatchedWithLargerClosure2546=== PAUSE TestWorkerRemovesCachedPathBatchedWithLargerClosure2547=== RUN TestDrainTimeout2548=== PAUSE TestDrainTimeout2549=== RUN TestDrainTimeoutDuringIsolation2550=== PAUSE TestDrainTimeoutDuringIsolation2551=== RUN TestShutdownFinishesInFlightPush2552=== PAUSE TestShutdownFinishesInFlightPush2553=== RUN TestWorkerRemoveFailureIsNotProgress2554=== PAUSE TestWorkerRemoveFailureIsNotProgress2555=== RUN TestWorkerKeepsPathItCannotStat2556=== PAUSE TestWorkerKeepsPathItCannotStat2557=== CONT TestDrainGivesUpWhenServerDown2558=== CONT TestDrainTimeout2559=== CONT TestWorkerSkipsGCdPaths2560=== CONT TestServerQueueError2561=== CONT TestSendPathsEmpty2562=== CONT TestDrainIsolatesPoisonPath2563=== CONT TestQueueRemoveLargeClosure2564=== CONT TestRunNotBlockedByPoisonHead2565=== CONT TestServerStalledClientDoesNotBlockShutdown2566=== CONT TestServerBacksOffOnAcceptErrors2567=== CONT TestServerClientIntegration2568--- PASS: TestSendPathsEmpty (0.00s)25692026/09/24 18:05:43 ERROR Accept failed error="too many open files"25702026/09/24 18:05:43 ERROR Failed to queue paths error="permission denied" count=12571--- PASS: TestServerQueueError (0.00s)2572=== CONT TestWorkerPrunesClosureDeps2573--- PASS: TestServerClientIntegration (0.00s)2574=== CONT TestShutdownFinishesInFlightPush2575=== RUN TestShutdownFinishesInFlightPush/completes2576=== PAUSE TestShutdownFinishesInFlightPush/completes2577=== RUN TestShutdownFinishesInFlightPush/hung_push_bounded_by_the_drain_timeout2578=== PAUSE TestShutdownFinishesInFlightPush/hung_push_bounded_by_the_drain_timeout2579=== CONT TestWorkerKeepsPathItCannotStat25802026/09/24 18:05:43 ERROR Accept failed error="too many open files"25812026/09/24 18:05:43 ERROR Accept failed error="too many open files"25822026/09/24 18:05:43 INFO Upload queue status pending=325832026/09/24 18:05:43 WARN Cannot stat store path, will retry later path=/nix/var/nix/builds/nix-16695-3377832867/TestWorkerKeepsPathItCannotStat37335225/002/locked/aaa error="lstat /nix/var/nix/builds/nix-16695-3377832867/TestWorkerKeepsPathItCannotStat37335225/002/locked/aaa: permission denied"25842026/09/24 18:05:43 INFO Upload queue status pending=325852026/09/24 18:05:43 INFO Upload queue status pending=225862026/09/24 18:05:43 INFO Uploading batch count=425872026/09/24 18:05:43 ERROR Upload failed error="upload failed" count=425882026/09/24 18:05:43 INFO Uploading batch count=125892026/09/24 18:05:43 ERROR Upload failed error="upload failed" count=125902026/09/24 18:05:43 INFO Uploading batch count=125912026/09/24 18:05:43 WARN Store path no longer exists (garbage collected?), removing from queue path=/nix/var/nix/builds/nix-16695-3377832867/TestWorkerSkipsGCdPaths739822539/002/nonexistent25922026/09/24 18:05:43 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-16695-3377832867/TestDrainIsolatesPoisonPath776931268/002/bbb25932026/09/24 18:05:43 INFO Uploading batch count=225942026/09/24 18:05:43 INFO Uploading batch count=225952026/09/24 18:05:43 INFO Uploading batch count=225962026/09/24 18:05:43 ERROR Upload failed error="upload failed" count=225972026/09/24 18:05:43 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-16695-3377832867/TestDrainGivesUpWhenServerDown3395163410/002/a25982026/09/24 18:05:43 WARN Cannot stat store path, will retry later path=/nix/var/nix/builds/nix-16695-3377832867/TestWorkerKeepsPathItCannotStat37335225/002/locked/aaa error="lstat /nix/var/nix/builds/nix-16695-3377832867/TestWorkerKeepsPathItCannotStat37335225/002/locked/aaa: permission denied"25992026/09/24 18:05:43 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-16695-3377832867/TestDrainGivesUpWhenServerDown3395163410/002/b26002026/09/24 18:05:43 WARN Cannot stat store path, will retry later path=/nix/var/nix/builds/nix-16695-3377832867/TestWorkerKeepsPathItCannotStat37335225/002/locked/aaa error="lstat /nix/var/nix/builds/nix-16695-3377832867/TestWorkerKeepsPathItCannotStat37335225/002/locked/aaa: permission denied"26012026/09/24 18:05:43 INFO Uploading batch count=126022026/09/24 18:05:43 ERROR Upload failed error="upload failed" count=126032026/09/24 18:05:43 INFO Uploading batch count=226042026/09/24 18:05:43 ERROR Upload failed error="upload failed" count=226052026/09/24 18:05:43 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-16695-3377832867/TestDrainGivesUpWhenServerDown3395163410/002/c26062026/09/24 18:05:43 ERROR Drain finished with paths left in queue remaining=126072026/09/24 18:05:43 INFO Uploading batch count=126082026/09/24 18:05:43 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-16695-3377832867/TestDrainGivesUpWhenServerDown3395163410/002/d26092026/09/24 18:05:43 ERROR Upload failed error="upload failed" count=12610--- PASS: TestWorkerKeepsPathItCannotStat (0.03s)2611=== CONT TestWorkerRemovesCachedPathBatchedWithLargerClosure26122026/09/24 18:05:43 INFO Uploading batch count=226132026/09/24 18:05:43 ERROR Upload failed error="upload failed" count=226142026/09/24 18:05:43 INFO Uploading batch count=126152026/09/24 18:05:43 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-16695-3377832867/TestDrainGivesUpWhenServerDown3395163410/002/e26162026/09/24 18:05:43 ERROR Upload failed error="upload failed" count=126172026/09/24 18:05:43 ERROR Accept failed error="too many open files"26182026/09/24 18:05:43 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-16695-3377832867/TestDrainGivesUpWhenServerDown3395163410/002/f26192026/09/24 18:05:43 ERROR Drain finished with paths left in queue remaining=126202026/09/24 18:05:43 ERROR Drain finished with paths left in queue remaining=102621--- PASS: TestDrainIsolatesPoisonPath (0.04s)2622=== CONT TestDrainTimeoutDuringIsolation2623=== RUN TestDrainTimeoutDuringIsolation/probe_cut_short2624=== PAUSE TestDrainTimeoutDuringIsolation/probe_cut_short2625=== RUN TestDrainTimeoutDuringIsolation/probe_outlasts_the_deadline2626=== PAUSE TestDrainTimeoutDuringIsolation/probe_outlasts_the_deadline2627=== CONT TestWorkerRemoveFailureIsNotProgress2628=== RUN TestWorkerRemoveFailureIsNotProgress/collected_path2629=== PAUSE TestWorkerRemoveFailureIsNotProgress/collected_path2630=== RUN TestWorkerRemoveFailureIsNotProgress/pushed_batch2631=== PAUSE TestWorkerRemoveFailureIsNotProgress/pushed_batch2632=== RUN TestWorkerRemoveFailureIsNotProgress/isolated_paths2633=== PAUSE TestWorkerRemoveFailureIsNotProgress/isolated_paths2634=== CONT TestWorkerUploadsAndRemoves2635--- PASS: TestDrainGivesUpWhenServerDown (0.04s)2636=== CONT TestFailedPathPrunedByLaterClosure26372026/09/24 18:05:43 INFO Upload queue status pending=226382026/09/24 18:05:43 INFO Uploading batch count=226392026/09/24 18:05:43 INFO Upload queue status pending=226402026/09/24 18:05:43 INFO Uploading batch count=226412026/09/24 18:05:43 INFO Uploading batch count=126422026/09/24 18:05:43 ERROR Upload failed error="upload failed" count=126432026/09/24 18:05:43 INFO Uploading batch count=126442026/09/24 18:05:43 INFO Uploading batch count=12645--- PASS: TestWorkerPrunesClosureDeps (0.05s)2646=== CONT TestQueueRetryMovesToBack2647--- PASS: TestWorkerSkipsGCdPaths (0.05s)2648=== CONT TestQueueFetchRemoveLifecycle2649--- PASS: TestFailedPathPrunedByLaterClosure (0.01s)2650=== CONT TestQueueConcurrentWriters2651--- PASS: TestQueueRetryMovesToBack (0.01s)2652=== CONT TestQueueDeduplication2653--- PASS: TestQueueFetchRemoveLifecycle (0.01s)2654=== CONT TestQueueFetchBatchLimit2655--- PASS: TestQueueDeduplication (0.01s)2656=== CONT TestQueueEnqueueWaitsOutSlowWriter2657=== CONT TestQueueRemove2658--- PASS: TestQueueFetchBatchLimit (0.01s)2659--- PASS: TestWorkerRemovesCachedPathBatchedWithLargerClosure (0.03s)2660=== CONT TestQueueEnqueueAndFetch2661--- PASS: TestWorkerUploadsAndRemoves (0.03s)2662=== CONT TestServerRefusesOversizedAndNonStoreRequests26632026/09/24 18:05:43 ERROR Refusing path outside the store path=/etc/shadow store=/nix/store26642026/09/24 18:05:43 ERROR Refusing path outside the store path=/nix/store store=/nix/store26652026/09/24 18:05:43 ERROR Refusing path outside the store path=/nix/store/ store=/nix/store26662026/09/24 18:05:43 ERROR Refusing path outside the store path=/nix/store/../../etc/shadow store=/nix/store26672026/09/24 18:05:43 ERROR Refusing path outside the store path=/nix/store/0123456789abcdfghijklmnpqrsvwxyz-hello/bin/sh store=/nix/store26682026/09/24 18:05:43 ERROR Refusing path outside the store path=nix/store/0123456789abcdfghijklmnpqrsvwxyz-hello store=/nix/store26692026/09/24 18:05:43 ERROR Refusing path outside the store path=/nix/storeX/0123456789abcdfghijklmnpqrsvwxyz-hello store=/nix/store26702026/09/24 18:05:43 ERROR Refusing path outside the store path=/nix/store/.links store=/nix/store26712026/09/24 18:05:43 ERROR Refusing path outside the store path=/nix/store/aaa-hello store=/nix/store2672--- PASS: TestQueueRemove (0.01s)2673=== CONT TestShutdownFinishesInFlightPush/completes26742026/09/24 18:05:43 ERROR Refusing path outside the store path=/nix/store/0123456789abcdfghijklmnpqrsvwxyz store=/nix/store26752026/09/24 18:05:43 ERROR Refusing path outside the store path=/nix/store/0123456789abcdfghijklmnpqrsvwxyz- store=/nix/store26762026/09/24 18:05:43 ERROR Refusing path outside the store path=/nix/store/0123456789ebcdfghijklmnpqrsvwxyz-hello store=/nix/store26772026/09/24 18:05:43 ERROR Refusing path outside the store path="/nix/store/0123456789abcdfghijklmnpqrsvwxyz-hel\x00lo" store=/nix/store26782026/09/24 18:05:43 ERROR Refusing path outside the store path=/nix/store/0123456789abcdfghijklmnpqrsvwxyz-hel/lo store=/nix/store2679--- PASS: TestQueueEnqueueAndFetch (0.01s)2680=== CONT TestShutdownFinishesInFlightPush/hung_push_bounded_by_the_drain_timeout26812026/09/24 18:05:43 ERROR Refusing path outside the store path=/nix/store/0123456789abcdfghijklmnpqrsvwxyz-xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx store=/nix/store26822026/09/24 18:05:43 ERROR Failed to decode request error="unexpected EOF"2683--- PASS: TestServerRefusesOversizedAndNonStoreRequests (0.00s)2684=== CONT TestDrainTimeoutDuringIsolation/probe_outlasts_the_deadline26852026/09/24 18:05:43 INFO Upload queue status pending=226862026/09/24 18:05:43 INFO Uploading batch count=226872026/09/24 18:05:43 INFO Upload queue status pending=226882026/09/24 18:05:43 INFO Uploading batch count=226892026/09/24 18:05:43 ERROR Accept failed error="too many open files"26902026/09/24 18:05:43 INFO Uploading batch count=426912026/09/24 18:05:43 ERROR Upload failed error="upload failed" count=426922026/09/24 18:05:43 ERROR Accept failed error="too many open files"2693=== CONT TestDrainTimeoutDuringIsolation/probe_cut_short26942026/09/24 18:05:44 INFO Uploading batch count=426952026/09/24 18:05:44 ERROR Upload failed error="upload failed" count=42696--- PASS: TestQueueConcurrentWriters (0.13s)2697=== CONT TestWorkerRemoveFailureIsNotProgress/isolated_paths26982026/09/24 18:05:44 INFO Uploading batch count=226992026/09/24 18:05:44 ERROR Upload failed error="upload failed" count=227002026/09/24 18:05:44 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=127012026/09/24 18:05:44 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=127022026/09/24 18:05:44 INFO Uploading batch count=227032026/09/24 18:05:44 ERROR Upload failed error="upload failed" count=227042026/09/24 18:05:44 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=127052026/09/24 18:05:44 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=127062026/09/24 18:05:44 INFO Uploading batch count=227072026/09/24 18:05:44 ERROR Upload failed error="upload failed" count=227082026/09/24 18:05:44 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=127092026/09/24 18:05:44 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=127102026/09/24 18:05:44 ERROR Drain finished with paths left in queue remaining=22711=== CONT TestWorkerRemoveFailureIsNotProgress/pushed_batch27122026/09/24 18:05:44 INFO Uploading batch count=227132026/09/24 18:05:44 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=227142026/09/24 18:05:44 INFO Uploading batch count=227152026/09/24 18:05:44 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=227162026/09/24 18:05:44 INFO Uploading batch count=227172026/09/24 18:05:44 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=227182026/09/24 18:05:44 ERROR Drain finished with paths left in queue remaining=22719=== CONT TestWorkerRemoveFailureIsNotProgress/collected_path27202026/09/24 18:05:44 ERROR Failed to decode request error="read unix /nix/var/nix/builds/nix-16695-3377832867/hook2924031282/test.sock->: i/o timeout"27212026/09/24 18:05:44 ERROR Failed to write response error="write unix /nix/var/nix/builds/nix-16695-3377832867/hook2924031282/test.sock->: i/o timeout"2722--- PASS: TestServerStalledClientDoesNotBlockShutdown (0.20s)27232026/09/24 18:05:44 WARN Store path no longer exists (garbage collected?), removing from queue path=/nix/var/nix/builds/nix-16695-3377832867/TestWorkerRemoveFailureIsNotProgresscollected_path2990590507/001/nonexistent27242026/09/24 18:05:44 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=127252026/09/24 18:05:44 WARN Store path no longer exists (garbage collected?), removing from queue path=/nix/var/nix/builds/nix-16695-3377832867/TestWorkerRemoveFailureIsNotProgresscollected_path2990590507/001/nonexistent27262026/09/24 18:05:44 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=127272026/09/24 18:05:44 WARN Store path no longer exists (garbage collected?), removing from queue path=/nix/var/nix/builds/nix-16695-3377832867/TestWorkerRemoveFailureIsNotProgresscollected_path2990590507/001/nonexistent27282026/09/24 18:05:44 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=127292026/09/24 18:05:44 ERROR Drain finished with paths left in queue remaining=12730--- PASS: TestWorkerRemoveFailureIsNotProgress (0.00s)2731 --- PASS: TestWorkerRemoveFailureIsNotProgress/isolated_paths (0.01s)2732 --- PASS: TestWorkerRemoveFailureIsNotProgress/pushed_batch (0.01s)2733 --- PASS: TestWorkerRemoveFailureIsNotProgress/collected_path (0.01s)27342026/09/24 18:05:44 ERROR Upload failed error="context canceled" count=227352026/09/24 18:05:44 ERROR Drain finished with paths left in queue remaining=42736--- PASS: TestDrainTimeout (0.23s)27372026/09/24 18:05:44 ERROR Upload failed error="context canceled" count=227382026/09/24 18:05:44 ERROR Drain finished with paths left in queue remaining=22739--- PASS: TestShutdownFinishesInFlightPush (0.00s)2740 --- PASS: TestShutdownFinishesInFlightPush/completes (0.11s)2741 --- PASS: TestShutdownFinishesInFlightPush/hung_push_bounded_by_the_drain_timeout (0.21s)27422026/09/24 18:05:44 ERROR Accept failed error="too many open files"27432026/09/24 18:05:44 ERROR Drain finished with paths left in queue remaining=327442026/09/24 18:05:44 ERROR Drain finished with paths left in queue remaining=42745--- PASS: TestDrainTimeoutDuringIsolation (0.00s)2746 --- PASS: TestDrainTimeoutDuringIsolation/probe_outlasts_the_deadline (0.31s)2747 --- PASS: TestDrainTimeoutDuringIsolation/probe_cut_short (0.21s)27482026/09/24 18:05:44 ERROR Accept failed error="too many open files"2749--- PASS: TestServerBacksOffOnAcceptErrors (0.64s)27502026/09/24 18:05:44 INFO Uploading batch count=127512026/09/24 18:05:44 INFO Uploading batch count=127522026/09/24 18:05:44 INFO Uploading batch count=127532026/09/24 18:05:44 ERROR Upload failed error="upload failed" count=127542026/09/24 18:05:44 INFO Uploading batch count=127552026/09/24 18:05:44 ERROR Upload failed error="upload failed" count=127562026/09/24 18:05:44 INFO Uploading batch count=127572026/09/24 18:05:44 ERROR Upload failed error="upload failed" count=127582026/09/24 18:05:44 INFO Uploading batch count=127592026/09/24 18:05:44 ERROR Upload failed error="upload failed" count=127602026/09/24 18:05:44 ERROR Drain finished with paths left in queue remaining=12761--- PASS: TestRunNotBlockedByPoisonHead (1.05s)2762--- PASS: TestQueueRemoveLargeClosure (1.17s)2763--- PASS: TestQueueEnqueueWaitsOutSlowWriter (6.01s)2764PASS2765Running niks3-hook command tests...2766=== RUN TestServeSecondSignalEndsDrain2767=== PAUSE TestServeSecondSignalEndsDrain2768=== RUN TestServeThenDrainPushesSendAcceptedBeforeShutdown2769=== PAUSE TestServeThenDrainPushesSendAcceptedBeforeShutdown2770=== CONT TestServeThenDrainPushesSendAcceptedBeforeShutdown2771=== CONT TestServeSecondSignalEndsDrain2772--- PASS: TestServeSecondSignalEndsDrain (0.07s)27732026/09/24 18:05:51 INFO Upload queue status pending=127742026/09/24 18:05:51 INFO Uploading batch count=12775--- PASS: TestServeThenDrainPushesSendAcceptedBeforeShutdown (0.12s)2776PASS2777Running rate limiter tests...2778=== RUN TestAdaptiveRateLimiter_ThreadSafety2779=== PAUSE TestAdaptiveRateLimiter_ThreadSafety2780=== CONT TestAdaptiveRateLimiter_ThreadSafety27812026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=7027822026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=4927832026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=34.327842026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=24.00999999999999827852026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=16.80727862026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=11.76489999999999927872026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=8.2354327882026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=5.76480099999999927892026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=527902026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=527912026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=527922026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=19.45971059722283827932026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=13.62179741805598527942026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=9.53525819263918927952026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=6.67468073484743227962026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=527972026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=527982026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=527992026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528002026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528012026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528022026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=5.63678500000000128032026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528042026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528052026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528062026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528072026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528082026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528092026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528102026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528112026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528122026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528132026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528142026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528152026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528162026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528172026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=5.12435000000000128182026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528192026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528202026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528212026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528222026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528232026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528242026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528252026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528262026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=8.25281691850000428272026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=5.77697184295000328282026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528292026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528302026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528312026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528322026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528332026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528342026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528352026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=6.82050985000000228362026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528372026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528382026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528392026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528402026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528412026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528422026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528432026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528442026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528452026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528462026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528472026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528482026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528492026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528502026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528512026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528522026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528532026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528542026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528552026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528562026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528572026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528582026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528592026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528602026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528612026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528622026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528632026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528642026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528652026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528662026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528672026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528682026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528692026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528702026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528712026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528722026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528732026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528742026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528752026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528762026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528772026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528782026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528792026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=528802026/09/24 18:05:52 WARN Rate limiter backed off name=test rate=52881--- PASS: TestAdaptiveRateLimiter_ThreadSafety (0.06s)2882PASS