niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #307
· 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.35s)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 TestRateLimiterFeedback_400DoesNotCountAsSuccess128=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry129=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer130=== CONT TestRateLimiterFeedback131=== RUN TestRateLimiterFeedback/429_enables_limiter132=== PAUSE TestRateLimiterFeedback/429_enables_limiter133=== RUN TestRateLimiterFeedback/503_enables_limiter134=== PAUSE TestRateLimiterFeedback/503_enables_limiter135=== CONT TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent136=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter137=== RUN TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/committed_earlier138=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter139=== CONT TestCompletePendingClosure_NotFoundWithoutKey140=== PAUSE TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/committed_earlier141=== CONT TestScriptTokenDoesNotWaitForItsChildren142=== RUN TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/cleaned_up143=== RUN TestScriptTokenDoesNotWaitForItsChildren/cancelled_while_a_child_runs144=== CONT TestParsePathInfoJSONMultiplePaths145=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths146=== CONT TestSetClientTLSDoesNotMutateDefaultTransport147=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths148=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter149=== CONT TestPathInfoCACompatibility150=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter151=== PAUSE TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/cleaned_up152=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths153=== RUN TestPathInfoCACompatibility/null_ca_field154=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths155=== PAUSE TestScriptTokenDoesNotWaitForItsChildren/cancelled_while_a_child_runs156=== CONT TestPathInfoHashCompatibility157=== RUN TestScriptTokenDoesNotWaitForItsChildren/child_left_holding_stdout158=== PAUSE TestScriptTokenDoesNotWaitForItsChildren/child_left_holding_stdout159=== CONT TestGetStorePathHash160=== PAUSE TestPathInfoCACompatibility/null_ca_field161=== CONT TestFileTokenEmpty162=== RUN TestGetStorePathHash/valid_store_path163=== RUN TestPathInfoCACompatibility/old_string_format_-_text164=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)165=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)166=== PAUSE TestGetStorePathHash/valid_store_path167=== RUN TestGetStorePathHash/basename_without_hyphen_should_error168=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon169=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text170=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error171=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive172=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon173=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error174=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive175=== RUN TestPathInfoCACompatibility/new_structured_format_-_text176=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI177=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error178=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI179=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512180--- PASS: TestFileTokenEmpty (0.00s)181=== CONT TestScriptTokenEmptyToken182=== CONT TestFileTokenMissing183=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text184=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512185=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error186=== CONT TestFileTokenReadsAndCaches187=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method188=== CONT TestDumpPathWriterError189--- PASS: TestCompletePendingClosure_NotFoundWithoutKey (0.00s)190=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method191=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error192=== CONT TestScriptTokenCachesUntilRefresh193=== CONT TestSetClientTLSErrors194--- PASS: TestFileTokenMissing (0.00s)195=== CONT TestScriptTokenNoExpiryRerunsEveryCall196--- PASS: TestFileTokenReadsAndCaches (0.00s)197=== CONT TestSetClientTLS198--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.01s)199--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.01s)200=== CONT TestUploadMultipart_SupersededByPeer201=== CONT TestEncodeNixBase32WithRealHash202=== RUN TestSetClientTLSErrors/missing_cert_file203=== PAUSE TestSetClientTLSErrors/missing_cert_file204--- PASS: TestEncodeNixBase32WithRealHash (0.00s)205=== CONT TestEncodeNixBase32206=== RUN TestEncodeNixBase32/test_string_hash207=== RUN TestSetClientTLSErrors/missing_key_file208=== RUN TestUploadMultipart_SupersededByPeer/exists209=== PAUSE TestSetClientTLSErrors/missing_key_file210=== PAUSE TestUploadMultipart_SupersededByPeer/exists211=== PAUSE TestEncodeNixBase32/test_string_hash212=== RUN TestSetClientTLSErrors/missing_ca_file213=== RUN TestEncodeNixBase32/empty_input214=== RUN TestUploadMultipart_SupersededByPeer/missing215=== PAUSE TestSetClientTLSErrors/missing_ca_file216=== PAUSE TestUploadMultipart_SupersededByPeer/missing217=== PAUSE TestEncodeNixBase32/empty_input218=== CONT TestScriptTokenEmptyCommand219=== CONT TestScriptTokenScriptFails220--- PASS: TestScriptTokenEmptyCommand (0.00s)221=== CONT TestConvertHashToNix32222=== RUN TestConvertHashToNix32/SRI_format_to_Nix32223=== RUN TestSetClientTLSErrors/invalid_ca_file224=== PAUSE TestSetClientTLSErrors/invalid_ca_file225=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32226=== RUN TestConvertHashToNix32/already_Nix32_format227=== CONT TestScriptTokenBadJSON228=== PAUSE TestConvertHashToNix32/already_Nix32_format229=== RUN TestConvertHashToNix32/invalid_format230=== PAUSE TestConvertHashToNix32/invalid_format231=== CONT TestDumpPathMatchesNix232--- PASS: TestScriptTokenEmptyToken (0.01s)233=== CONT TestTruncatedNARDumpIsNotCompleted234=== RUN TestSetClientTLS/rejects_connection_without_client_cert235=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert236=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA237=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA238=== RUN TestSetClientTLS/preserves_debug_logging_transport239=== PAUSE TestSetClientTLS/preserves_debug_logging_transport240=== CONT TestStaticToken241--- PASS: TestStaticToken (0.00s)242=== CONT TestSupersededNARStillUploadsListing243=== RUN TestSupersededNARStillUploadsListing/small_NAR244=== PAUSE TestSupersededNARStillUploadsListing/small_NAR245=== RUN TestSupersededNARStillUploadsListing/dump_cut_short246=== PAUSE TestSupersededNARStillUploadsListing/dump_cut_short247=== RUN TestSupersededNARStillUploadsListing/listing_upload_fails248=== PAUSE TestSupersededNARStillUploadsListing/listing_upload_fails249=== CONT TestCaseHackSuffix250--- PASS: TestScriptTokenScriptFails (0.01s)251=== CONT TestFilterOversizedClosures252=== RUN TestFilterOversizedClosures/no_limit_keeps_everything253=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything254=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped255=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped256=== RUN TestFilterOversizedClosures/all_closures_skipped257=== PAUSE TestFilterOversizedClosures/all_closures_skipped258=== CONT TestClientSignaturesByStorePath259--- PASS: TestClientSignaturesByStorePath (0.00s)260=== CONT TestStreamPushRequestLine261--- PASS: TestScriptTokenBadJSON (0.01s)262=== CONT TestDumpPathSingleFile263--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.03s)264=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica265--- PASS: TestScriptTokenCachesUntilRefresh (0.03s)266=== CONT TestUploadMultipart_FailedPartBufferNotReused267=== CONT TestStreamPushReportsSignatures268--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.00s)269=== CONT TestRegisterUploadedObjectReusesConnections270--- PASS: TestStreamPushReportsSignatures (0.00s)271--- PASS: TestDumpPathWriterError (0.07s)272=== CONT TestDoServerRequestAttachesToken273--- PASS: TestCaseHackSuffix (0.06s)274=== CONT TestParsePathInfoJSON275=== RUN TestParsePathInfoJSON/Nix_format276=== PAUSE TestParsePathInfoJSON/Nix_format277=== RUN TestParsePathInfoJSON/Lix_format278=== PAUSE TestParsePathInfoJSON/Lix_format279=== RUN TestParsePathInfoJSON/empty_input280=== PAUSE TestParsePathInfoJSON/empty_input281=== RUN TestParsePathInfoJSON/whitespace_only282=== PAUSE TestParsePathInfoJSON/whitespace_only283=== RUN TestParsePathInfoJSON/invalid_JSON284=== PAUSE TestParsePathInfoJSON/invalid_JSON285=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun286--- PASS: TestDoServerRequestAttachesToken (0.00s)287=== CONT TestPushPathsReportsOnlyUnuploadablePathsOfSkippedClosure288--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.00s)289=== CONT TestUploadMultipart_ProducerErrorIsNotEOF290=== RUN TestUploadMultipart_ProducerErrorIsNotEOF/short_read_inside_a_part291=== PAUSE TestUploadMultipart_ProducerErrorIsNotEOF/short_read_inside_a_part292=== RUN TestUploadMultipart_ProducerErrorIsNotEOF/empty_read_on_a_part_boundary293=== PAUSE TestUploadMultipart_ProducerErrorIsNotEOF/empty_read_on_a_part_boundary294=== CONT TestStreamPushReportsEveryPath295--- PASS: TestStreamPushReportsEveryPath (0.00s)296=== CONT TestStreamPushGivesUpOnDeadServer297--- PASS: TestDumpPathSingleFile (0.06s)298=== CONT TestResolveStorePath299--- PASS: TestStreamPushGivesUpOnDeadServer (0.01s)300=== CONT TestDoWithRetry_FinalResponseBodyReadable301--- PASS: TestResolveStorePath (0.00s)302=== CONT TestUploadMultipart_PartsInParallel303--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.01s)304=== CONT TestStreamPushStopsOnCancel305=== RUN TestStreamPushStopsOnCancel/waiting_for_input306=== PAUSE TestStreamPushStopsOnCancel/waiting_for_input307=== RUN TestStreamPushStopsOnCancel/partial_batch_waiting_for_a_slot308=== PAUSE TestStreamPushStopsOnCancel/partial_batch_waiting_for_a_slot309=== RUN TestStreamPushStopsOnCancel/input_closed,_last_batch_waiting_for_a_slot310=== PAUSE TestStreamPushStopsOnCancel/input_closed,_last_batch_waiting_for_a_slot311=== RUN TestStreamPushStopsOnCancel/full_batch_waiting_for_a_slot312=== PAUSE TestStreamPushStopsOnCancel/full_batch_waiting_for_a_slot313=== RUN TestStreamPushStopsOnCancel/request_line_waiting_for_a_slot314=== PAUSE TestStreamPushStopsOnCancel/request_line_waiting_for_a_slot315=== RUN TestStreamPushStopsOnCancel/lines_read_but_not_taken316=== PAUSE TestStreamPushStopsOnCancel/lines_read_but_not_taken317=== CONT TestDoWithRetry_BodyReplayedViaGetBody318--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.01s)319=== CONT TestPartSizeForNAR320=== RUN TestPartSizeForNAR/zero_stays_at_minimum321=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum322=== RUN TestPartSizeForNAR/small_stays_at_minimum323=== PAUSE TestPartSizeForNAR/small_stays_at_minimum324=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum325=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum326=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts327=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts328=== RUN TestPartSizeForNAR/1_TiB329=== PAUSE TestPartSizeForNAR/1_TiB330=== RUN TestPartSizeForNAR/5_TiB_S3_max_object331=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object332=== RUN TestPartSizeForNAR/capped_at_5_GiB333=== PAUSE TestPartSizeForNAR/capped_at_5_GiB334=== CONT TestStreamPushIsolatesFailures335--- PASS: TestStreamPushIsolatesFailures (0.00s)336=== CONT TestShellSplit337--- PASS: TestShellSplit (0.00s)338=== CONT TestShellSplitErrors339--- PASS: TestShellSplitErrors (0.00s)340=== CONT TestStreamPushBatchesUnderLoad341=== RUN TestStreamPushBatchesUnderLoad/together342=== PAUSE TestStreamPushBatchesUnderLoad/together343=== RUN TestStreamPushBatchesUnderLoad/one_at_a_time344=== PAUSE TestStreamPushBatchesUnderLoad/one_at_a_time345=== CONT TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/committed_earlier346=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths347=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths348--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)349 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)350 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)351=== CONT TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/cleaned_up352--- PASS: TestStreamPushRequestLine (0.09s)353=== CONT TestRateLimiterFeedback/429_enables_limiter354=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter355--- PASS: TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent (0.00s)356 --- PASS: TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/committed_earlier (0.00s)357 --- PASS: TestCompletePendingClosure_NotFoundIsSuccessWhenClosurePresent/cleaned_up (0.00s)358=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter359=== CONT TestRateLimiterFeedback/503_enables_limiter360=== CONT TestScriptTokenDoesNotWaitForItsChildren/cancelled_while_a_child_runs361=== CONT TestScriptTokenDoesNotWaitForItsChildren/child_left_holding_stdout362--- PASS: TestRateLimiterFeedback (0.00s)363 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)364 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)365 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)366 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)367--- PASS: TestDumpPathMatchesNix (0.14s)368=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)369=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512370=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI371=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon372=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive373--- PASS: TestPathInfoHashCompatibility (0.00s)374 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)375 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)376 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)377 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)378=== CONT TestPathInfoCACompatibility/new_structured_format_-_text379=== CONT TestPathInfoCACompatibility/old_string_format_-_text380=== CONT TestPathInfoCACompatibility/null_ca_field381=== CONT TestGetStorePathHash/basename_without_hyphen_should_error382=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error383=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error384=== CONT TestGetStorePathHash/valid_store_path385=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method386=== CONT TestUploadMultipart_SupersededByPeer/missing387--- PASS: TestGetStorePathHash (0.00s)388 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)389 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)390 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)391 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)392--- PASS: TestPathInfoCACompatibility (0.00s)393 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)394 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)395 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)396 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)397 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)398=== CONT TestUploadMultipart_SupersededByPeer/exists399=== CONT TestEncodeNixBase32/test_string_hash400--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)401 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)402 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)403=== CONT TestSetClientTLSErrors/missing_ca_file404=== CONT TestSetClientTLSErrors/missing_key_file405=== CONT TestSetClientTLSErrors/invalid_ca_file406=== CONT TestEncodeNixBase32/empty_input407=== CONT TestSetClientTLSErrors/missing_cert_file408--- PASS: TestEncodeNixBase32 (0.00s)409 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)410 --- PASS: TestEncodeNixBase32/empty_input (0.00s)411--- PASS: TestSetClientTLSErrors (0.01s)412 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)413 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)414 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)415 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)416=== CONT TestConvertHashToNix32/SRI_format_to_Nix32417=== CONT TestConvertHashToNix32/invalid_format418=== CONT TestConvertHashToNix32/already_Nix32_format419=== CONT TestSetClientTLS/rejects_connection_without_client_cert420--- PASS: TestConvertHashToNix32 (0.00s)421 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)422 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)423 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)424=== CONT TestSetClientTLS/preserves_debug_logging_transport425=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA426=== CONT TestSupersededNARStillUploadsListing/dump_cut_short427--- PASS: TestSetClientTLS (0.01s)428 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.01s)429 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.01s)430 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.01s)431--- PASS: TestPushPathsReportsOnlyUnuploadablePathsOfSkippedClosure (0.12s)432=== CONT TestSupersededNARStillUploadsListing/listing_upload_fails433=== CONT TestSupersededNARStillUploadsListing/small_NAR434=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped435=== CONT TestFilterOversizedClosures/all_closures_skipped436=== CONT TestFilterOversizedClosures/no_limit_keeps_everything437--- PASS: TestFilterOversizedClosures (0.00s)438 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)439 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)440 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)441=== CONT TestParsePathInfoJSON/invalid_JSON442=== CONT TestParsePathInfoJSON/Lix_format443=== CONT TestParsePathInfoJSON/whitespace_only444=== CONT TestParsePathInfoJSON/empty_input445=== CONT TestParsePathInfoJSON/Nix_format446=== CONT TestUploadMultipart_ProducerErrorIsNotEOF/empty_read_on_a_part_boundary447--- PASS: TestParsePathInfoJSON (0.00s)448 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)449 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)450 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)451 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)452 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)453--- PASS: TestRegisterUploadedObjectReusesConnections (0.18s)454=== CONT TestUploadMultipart_ProducerErrorIsNotEOF/short_read_inside_a_part455=== CONT TestStreamPushStopsOnCancel/partial_batch_waiting_for_a_slot456=== CONT TestStreamPushStopsOnCancel/lines_read_but_not_taken457--- PASS: TestUploadMultipart_ProducerErrorIsNotEOF (0.00s)458 --- PASS: TestUploadMultipart_ProducerErrorIsNotEOF/empty_read_on_a_part_boundary (0.03s)459 --- PASS: TestUploadMultipart_ProducerErrorIsNotEOF/short_read_inside_a_part (0.03s)460=== CONT TestStreamPushStopsOnCancel/full_batch_waiting_for_a_slot461=== CONT TestStreamPushStopsOnCancel/request_line_waiting_for_a_slot462=== CONT TestStreamPushStopsOnCancel/input_closed,_last_batch_waiting_for_a_slot463=== CONT TestStreamPushStopsOnCancel/waiting_for_input464=== CONT TestPartSizeForNAR/zero_stays_at_minimum465=== CONT TestPartSizeForNAR/capped_at_5_GiB466=== CONT TestPartSizeForNAR/5_TiB_S3_max_object467=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts468=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum469=== CONT TestPartSizeForNAR/1_TiB470=== CONT TestPartSizeForNAR/small_stays_at_minimum471=== CONT TestStreamPushBatchesUnderLoad/together472--- PASS: TestPartSizeForNAR (0.00s)473 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)474 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)475 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)476 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)477 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)478 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)479 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)480=== CONT TestStreamPushBatchesUnderLoad/one_at_a_time481--- PASS: TestStreamPushBatchesUnderLoad (0.00s)482 --- PASS: TestStreamPushBatchesUnderLoad/together (0.00s)483 --- PASS: TestStreamPushBatchesUnderLoad/one_at_a_time (0.00s)484--- PASS: TestStreamPushStopsOnCancel (0.00s)485 --- PASS: TestStreamPushStopsOnCancel/partial_batch_waiting_for_a_slot (0.05s)486 --- PASS: TestStreamPushStopsOnCancel/lines_read_but_not_taken (0.05s)487 --- PASS: TestStreamPushStopsOnCancel/full_batch_waiting_for_a_slot (0.05s)488 --- PASS: TestStreamPushStopsOnCancel/request_line_waiting_for_a_slot (0.05s)489 --- PASS: TestStreamPushStopsOnCancel/input_closed,_last_batch_waiting_for_a_slot (0.05s)490 --- PASS: TestStreamPushStopsOnCancel/waiting_for_input (0.05s)491--- PASS: TestTruncatedNARDumpIsNotCompleted (0.40s)492--- PASS: TestUploadMultipart_FailedPartBufferNotReused (0.64s)493--- PASS: TestUploadMultipart_PartsInParallel (0.67s)494--- PASS: TestSupersededNARStillUploadsListing (0.00s)495 --- PASS: TestSupersededNARStillUploadsListing/listing_upload_fails (0.01s)496 --- PASS: TestSupersededNARStillUploadsListing/small_NAR (0.00s)497 --- PASS: TestSupersededNARStillUploadsListing/dump_cut_short (0.59s)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-25758-1034586924/postgres4018739124/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-25758-1034586924/postgres4018739124/data -l logfile start531532/nix/var/nix/builds/nix-25758-1034586924/postgres4018739124:5432 - no response5332026-10-01 09:22:09.235 UTC [25803] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit5342026-10-01 09:22:09.235 UTC [25803] LOG: listening on Unix socket "/nix/var/nix/builds/nix-25758-1034586924/postgres4018739124/.s.PGSQL.5432"5352026-10-01 09:22:09.237 UTC [25810] LOG: database system was shut down at 2026-10-01 09:22:09 UTC5362026-10-01 09:22:09.238 UTC [25803] LOG: database system is ready to accept connections537/nix/var/nix/builds/nix-25758-1034586924/postgres4018739124:5432 - accepting connections538{"timestamp":"2026-10-01T09:22:09.455123Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"5a5356cd-ecf2-46e7-b3c6-7d69ecd9eb4a","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":501,"threadName":"rustfs-worker","threadId":"ThreadId(8)"}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/10/01 09:22:09 INFO lead: acquired remote=192.0.2.1:12345872026/10/01 09:22:10 INFO lead: released remote=192.0.2.1:12345882026/10/01 09:22:10 INFO lead: acquired remote=192.0.2.1:12345892026/10/01 09:22:11 INFO lead: released remote=192.0.2.1:1234590--- PASS: TestLeadIncumbentWinsAfterRestart (2.32s)591=== RUN TestLeadEndsOnShutdown592=== PAUSE TestLeadEndsOnShutdown593=== RUN TestLeadEndsWhenItsConnectionHangs5942026/10/01 09:22:12 INFO lead: acquired remote=192.0.2.1:12345952026-10-01 09:22:13.235 UTC [25847] FATAL: terminating connection due to administrator command5962026/10/01 09:22:13 INFO lead: acquired remote=192.0.2.1:12345972026/10/01 09:22:14 WARN lead: lock connection lost error="timeout: context deadline exceeded"5982026/10/01 09:22:14 INFO lead: released remote=192.0.2.1:12345992026/10/01 09:22:14 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 TestFailedS3DeleteKeepsTombstone622=== PAUSE TestFailedS3DeleteKeepsTombstone623=== RUN TestSweepSkipsRowsLockedByPush624=== PAUSE TestSweepSkipsRowsLockedByPush625=== RUN TestRegisterCompletedObjectNeedsPendingRow626=== PAUSE TestRegisterCompletedObjectNeedsPendingRow627=== RUN TestGetExistingObjectsLocksRows628=== PAUSE TestGetExistingObjectsLocksRows629=== RUN TestSweepRechecksPendingAfterLocking630=== PAUSE TestSweepRechecksPendingAfterLocking631=== RUN TestPushWaitsForSweepHoldingRow632=== PAUSE TestPushWaitsForSweepHoldingRow633=== RUN TestCommitRacingPendingCleanupKeepsObjects634=== PAUSE TestCommitRacingPendingCleanupKeepsObjects635=== RUN TestGCEndsOnShutdown636=== PAUSE TestGCEndsOnShutdown637=== RUN TestGCTaskStore_StartNew638=== PAUSE TestGCTaskStore_StartNew639=== RUN TestGCTaskStore_DeduplicateSameParams640=== PAUSE TestGCTaskStore_DeduplicateSameParams641=== RUN TestGCTaskStore_ConflictDifferentParams642=== PAUSE TestGCTaskStore_ConflictDifferentParams643=== RUN TestGCTaskStore_GetEmpty644=== PAUSE TestGCTaskStore_GetEmpty645=== RUN TestGCTaskStore_GetReturnsLatest646=== PAUSE TestGCTaskStore_GetReturnsLatest647=== RUN TestGCTaskStore_CompletedAllowsNewTask648=== PAUSE TestGCTaskStore_CompletedAllowsNewTask649=== RUN TestGCTaskStore_PhaseUpdates650=== PAUSE TestGCTaskStore_PhaseUpdates651=== RUN TestGCTaskStore_Fail652=== PAUSE TestGCTaskStore_Fail653=== RUN TestGracefulShutdownDrainsInflight654=== PAUSE TestGracefulShutdownDrainsInflight655=== RUN TestService_healthCheckHandler656=== PAUSE TestService_healthCheckHandler657=== RUN TestService_readinessHandler658=== PAUSE TestService_readinessHandler659=== RUN TestGenerateLandingPage660=== PAUSE TestGenerateLandingPage661=== RUN TestCacheConfigHandlerMaxNarSize662=== PAUSE TestCacheConfigHandlerMaxNarSize663=== RUN TestCreatePendingClosureRejectsOversizedNAR664=== PAUSE TestCreatePendingClosureRejectsOversizedNAR665=== RUN TestNARDeduplicationMetadataUploadBug666=== PAUSE TestNARDeduplicationMetadataUploadBug667=== RUN TestMetricsInventory668=== PAUSE TestMetricsInventory669=== RUN TestService_NativeMTLS670=== PAUSE TestService_NativeMTLS671=== RUN TestServerTLSConfig672=== PAUSE TestServerTLSConfig673=== RUN TestMultipartCleanup674=== PAUSE TestMultipartCleanup675=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded676=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded677=== RUN TestPendingCleanupUsesOneCutoff678=== PAUSE TestPendingCleanupUsesOneCutoff679=== RUN TestPendingClosureFailureTracksEveryUpload680=== PAUSE TestPendingClosureFailureTracksEveryUpload681=== RUN TestPendingClosureFailureAbortsItsUploads682=== PAUSE TestPendingClosureFailureAbortsItsUploads683=== RUN TestObjectStatsTrigger684=== PAUSE TestObjectStatsTrigger685=== RUN TestReconnectLeavesObjectsUnlocked686=== PAUSE TestReconnectLeavesObjectsUnlocked687=== RUN TestValidateS3Concurrency688=== PAUSE TestValidateS3Concurrency689=== RUN TestOrphanedObjectsGC690=== PAUSE TestOrphanedObjectsGC691=== RUN TestOrphanedObjectsGCStressTest692=== PAUSE TestOrphanedObjectsGCStressTest693=== RUN TestCreatePin_ReservedPins694=== PAUSE TestCreatePin_ReservedPins695=== RUN TestConcurrentPinUpdatesAgree696=== PAUSE TestConcurrentPinUpdatesAgree697=== RUN TestCreatePinRejectsBadInput698=== PAUSE TestCreatePinRejectsBadInput699=== RUN TestDeletePinKeepsRowWhenS3Fails700=== PAUSE TestDeletePinKeepsRowWhenS3Fails701=== RUN TestPresentReportsOnlyClosureRoots702=== PAUSE TestPresentReportsOnlyClosureRoots703=== RUN TestPresentNotReportedWhileGCDeletesClosure704=== PAUSE TestPresentNotReportedWhileGCDeletesClosure705=== RUN TestParseSingleRange706=== PAUSE TestParseSingleRange707=== RUN TestProxyHeadersOnlyTrustedOnSocket708=== PAUSE TestProxyHeadersOnlyTrustedOnSocket709=== RUN TestIsValidCachePath710=== PAUSE TestIsValidCachePath711=== RUN TestReadProxyNarinfo712=== PAUSE TestReadProxyNarinfo713=== RUN TestReadProxyNarinfoAlreadyDecompressed714=== PAUSE TestReadProxyNarinfoAlreadyDecompressed715=== RUN TestReadProxyNarStreaming716=== PAUSE TestReadProxyNarStreaming717=== RUN TestReadProxy404718=== PAUSE TestReadProxy404719=== RUN TestReadProxyInvalidPath720=== PAUSE TestReadProxyInvalidPath721=== RUN TestReadProxyHead722=== PAUSE TestReadProxyHead723=== RUN TestReadProxyOutlastsServerWriteTimeout724=== PAUSE TestReadProxyOutlastsServerWriteTimeout725=== RUN TestReadProxyConditionalGet726=== PAUSE TestReadProxyConditionalGet727=== RUN TestReadProxyRootRedirectsToIndexHTML728=== PAUSE TestReadProxyRootRedirectsToIndexHTML729=== RUN TestReadProxyDisabled730=== PAUSE TestReadProxyDisabled731=== RUN TestReadRedirectNar732=== PAUSE TestReadRedirectNar733=== RUN TestReadRedirectKeepsNarinfoProxied734=== PAUSE TestReadRedirectKeepsNarinfoProxied735=== RUN TestReadProxyRangeRequest736=== PAUSE TestReadProxyRangeRequest737=== RUN TestReadRedirectUsesPublicS3URL738=== PAUSE TestReadRedirectUsesPublicS3URL739=== RUN TestPush_OverlappingRootsStoreOneRowPerKey740=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey741=== RUN TestPush_CompleteCommitsEveryRoot742=== PAUSE TestPush_CompleteCommitsEveryRoot743=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit744=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit745=== RUN TestPush_RejectsBadRequests746=== PAUSE TestPush_RejectsBadRequests747=== RUN TestPush_SignsNarinfosOfItsPendingObjects748=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects749=== RUN TestRedundantMultipartUpload750=== PAUSE TestRedundantMultipartUpload751=== RUN TestCompleteMultipartUpload_ErrorButObjectExists752=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists753=== RUN TestCompletedNarNotReofferedAcrossClosures754=== PAUSE TestCompletedNarNotReofferedAcrossClosures755=== RUN TestPresignedUploadRegisteredBeforeCommit756=== PAUSE TestPresignedUploadRegisteredBeforeCommit757=== RUN TestService_Rustfstest758=== PAUSE TestService_Rustfstest759=== RUN TestParseSize760=== PAUSE TestParseSize761=== RUN TestSkippedUploadsHandler762=== PAUSE TestSkippedUploadsHandler763=== RUN TestSystemdListenerNotActivated764--- PASS: TestSystemdListenerNotActivated (0.00s)765=== RUN TestWatchdogBeatsWhenHealthy766--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)767=== RUN TestWatchdogSkipsWhenUnhealthy7682026/10/01 09:22:14 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7692026/10/01 09:22:14 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7702026/10/01 09:22:14 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7712026/10/01 09:22:14 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7722026/10/01 09:22:14 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7732026/10/01 09:22:14 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7742026/10/01 09:22:14 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7752026/10/01 09:22:14 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7762026/10/01 09:22:14 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7772026/10/01 09:22:14 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"778--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)779=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle780=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle781=== RUN TestProxyWriteTimeout782=== PAUSE TestProxyWriteTimeout783=== RUN TestPendingClosureWriteTimeout784=== PAUSE TestPendingClosureWriteTimeout785=== RUN TestIsValidUploadKey786=== PAUSE TestIsValidUploadKey787=== RUN TestUploadHandlersRejectInvalidKeys788=== PAUSE TestUploadHandlersRejectInvalidKeys789=== RUN TestUploadHandlersRejectOversizedBody790=== PAUSE TestUploadHandlersRejectOversizedBody791=== RUN TestService_cleanupPendingClosuresHandler792=== PAUSE TestService_cleanupPendingClosuresHandler793=== RUN TestService_createPendingClosureHandler794=== PAUSE TestService_createPendingClosureHandler795=== RUN TestService_verifyS3Integrity796=== PAUSE TestService_verifyS3Integrity797=== RUN TestCompleteMultipartUnregistered798=== PAUSE TestCompleteMultipartUnregistered799=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT800=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT801=== CONT TestReadProxyInvalidPath802=== CONT TestService_createPendingClosureHandler803=== CONT TestService_AuthMiddleware804=== CONT TestGCTaskStore_StartNew805=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT806--- PASS: TestGCTaskStore_StartNew (0.00s)807=== CONT TestMultipartCleanup808=== CONT TestService_verifyS3Integrity809=== CONT TestCompleteMultipartUnregistered810=== CONT TestReadProxy404811=== CONT TestOrphanedObjectsGC812=== CONT TestCompleteMultipartUpload_ErrorButObjectExists8132026/10/01 09:22:15 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"814--- PASS: TestService_AuthMiddleware (0.44s)815=== CONT TestServerTLSConfig816=== RUN TestServerTLSConfig/no_client_CA817=== PAUSE TestServerTLSConfig/no_client_CA818=== RUN TestServerTLSConfig/missing_CA_file819=== PAUSE TestServerTLSConfig/missing_CA_file820=== RUN TestServerTLSConfig/not_a_PEM_file821=== PAUSE TestServerTLSConfig/not_a_PEM_file822=== CONT TestMetricsInventory8232026/10/01 09:22:15 INFO Received uploads request method=POST path=/api/pending_closures824--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.64s)825=== CONT TestService_NativeMTLS8262026/10/01 09:22:15 INFO Received uploads request method=POST path=/api/pending_closures827--- PASS: TestReadProxyInvalidPath (1.12s)828=== CONT TestNARDeduplicationMetadataUploadBug8292026/10/01 09:22:16 INFO Received uploads request method=POST path=/api/pending_closures830=== NAME TestOrphanedObjectsGC831 orphaned_objects_gc_test.go:290: GC Test Summary:832 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A833 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B834 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)835 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)836 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects8372026/10/01 09:22:16 INFO Received cleanup request method=DELETE path=/api/pending_closures8382026/10/01 09:22:16 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket8/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""8392026/10/01 09:22:16 INFO Aborted multipart uploads count=0 kept=18402026/10/01 09:22:16 INFO Received cleanup request method=DELETE path=/api/pending_closures841--- PASS: TestOrphanedObjectsGC (1.53s)842=== CONT TestCreatePendingClosureRejectsOversizedNAR8432026/10/01 09:22:16 INFO Received uploads request method=POST path=/api/pending_closures844--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)845=== CONT TestGenerateLandingPage8462026/10/01 09:22:16 INFO Aborted multipart uploads count=1 kept=0847--- PASS: TestGenerateLandingPage (0.01s)848=== CONT TestService_readinessHandler849--- PASS: TestMultipartCleanup (1.56s)850=== CONT TestService_healthCheckHandler8512026/10/01 09:22:16 INFO Received uploads request method=POST path=/api/pending_closures8522026/10/01 09:22:16 INFO Received uploads request method=POST path=/api/pending_closures8532026/10/01 09:22:16 INFO Received uploads request method=POST path=/api/pending_closures8542026/10/01 09:22:16 INFO Received uploads request method=POST path=/api/pending_closures8552026/10/01 09:22:16 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8562026/10/01 09:22:16 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MjIyZjU3ZmItZjM0Zi00MzM3LWJiN2YtZDQ3MjhiODA4Yzg3LjlkNmJmMTdkLTk0ZjUtNGJiMS1hM2Q2LWQwOGRiNjEwNTNkNngxNzkwODQ2NTM2NDk1NzA4MDAw8572026/10/01 09:22:16 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8582026/10/01 09:22:16 WARN Failed to abort multipart upload key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MjIyZjU3ZmItZjM0Zi00MzM3LWJiN2YtZDQ3MjhiODA4Yzg3LjlkNmJmMTdkLTk0ZjUtNGJiMS1hM2Q2LWQwOGRiNjEwNTNkNngxNzkwODQ2NTM2NDk1NzA4MDAw error="Delete \"http://localhost:63354/bucket9/nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst?uploadId=MjIyZjU3ZmItZjM0Zi00MzM3LWJiN2YtZDQ3MjhiODA4Yzg3LjlkNmJmMTdkLTk0ZjUtNGJiMS1hM2Q2LWQwOGRiNjEwNTNkNngxNzkwODQ2NTM2NDk1NzA4MDAw\": injected: abort refused"8592026/10/01 09:22:16 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8602026/10/01 09:22:16 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MjIyZjU3ZmItZjM0Zi00MzM3LWJiN2YtZDQ3MjhiODA4Yzg3LjlkNmJmMTdkLTk0ZjUtNGJiMS1hM2Q2LWQwOGRiNjEwNTNkNngxNzkwODQ2NTM2NDk1NzA4MDAw8612026/10/01 09:22:16 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MjIyZjU3ZmItZjM0Zi00MzM3LWJiN2YtZDQ3MjhiODA4Yzg3LjlkNmJmMTdkLTk0ZjUtNGJiMS1hM2Q2LWQwOGRiNjEwNTNkNngxNzkwODQ2NTM2NDk1NzA4MDAw parts=1862--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (1.97s)863=== CONT TestGracefulShutdownDrainsInflight8642026/10/01 09:22:16 INFO Starting HTTP server address=127.0.0.1:634178652026/10/01 09:22:16 INFO Shutdown signal received, draining in-flight requests timeout=10s8662026/10/01 09:22:16 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=MjIyZjU3ZmItZjM0Zi00MzM3LWJiN2YtZDQ3MjhiODA4Yzg3LmU1OGVhOTMxLTgyYWUtNGQ0YS1hODcwLWJjNzQ2MzcwMmM3YngxNzkwODQ2NTM1Njc3OTQ1MDAw parts=108672026/10/01 09:22:16 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete8682026/10/01 09:22:16 INFO Completed upload id=18692026/10/01 09:22:16 INFO Received uploads request method=POST path=/api/pending_closures8702026/10/01 09:22:16 INFO Received uploads request method=POST path=/api/pending_closures8712026/10/01 09:22:16 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo8722026/10/01 09:22:16 WARN Found objects in DB but missing from S3, will re-upload count=18732026/10/01 09:22:16 INFO Received complete upload request method=POST path=/api/pending_closures/3/complete8742026/10/01 09:22:16 INFO Completed upload id=3875--- PASS: TestGracefulShutdownDrainsInflight (0.07s)876=== CONT TestGCTaskStore_Fail877--- PASS: TestGCTaskStore_Fail (0.00s)878=== CONT TestGCTaskStore_PhaseUpdates879=== CONT TestCacheConfigHandlerMaxNarSize880--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)881--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)882=== CONT TestGCTaskStore_GetReturnsLatest883--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)884=== CONT TestGCTaskStore_CompletedAllowsNewTask885--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)886=== CONT TestGCTaskStore_ConflictDifferentParams887--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)888=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded889--- PASS: TestService_verifyS3Integrity (2.05s)890=== CONT TestReadProxyNarinfoAlreadyDecompressed8912026/10/01 09:22:17 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8922026/10/01 09:22:17 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst893--- PASS: TestCompleteMultipartUnregistered (2.29s)894=== CONT TestReadProxyNarStreaming8952026/10/01 09:22:17 WARN Rate limiter enabled after throttle name=s3-test rate=58962026/10/01 09:22:17 WARN S3 rate limit hit during proxy key=4hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo error="Please reduce your request rate."8972026/10/01 09:22:17 WARN Rate limiter backed off name=s3-test rate=58982026/10/01 09:22:17 WARN S3 rate limit hit during proxy key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhh.nar.zst error="Please reduce your request rate."899--- PASS: TestReadProxy404 (2.43s)900=== CONT TestIsValidCachePath901=== RUN TestIsValidCachePath/narinfo902=== PAUSE TestIsValidCachePath/narinfo903=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars904=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars905=== RUN TestIsValidCachePath/nar_zst906=== PAUSE TestIsValidCachePath/nar_zst907=== RUN TestIsValidCachePath/nar_xz908=== PAUSE TestIsValidCachePath/nar_xz909=== RUN TestIsValidCachePath/nar_bz2910=== PAUSE TestIsValidCachePath/nar_bz2911=== RUN TestIsValidCachePath/nar_uncompressed912=== PAUSE TestIsValidCachePath/nar_uncompressed913=== RUN TestIsValidCachePath/ls914=== PAUSE TestIsValidCachePath/ls915=== RUN TestIsValidCachePath/log916=== PAUSE TestIsValidCachePath/log917=== RUN TestIsValidCachePath/realisation918=== PAUSE TestIsValidCachePath/realisation919=== RUN TestIsValidCachePath/nix-cache-info920=== PAUSE TestIsValidCachePath/nix-cache-info921=== RUN TestIsValidCachePath/index.html922=== PAUSE TestIsValidCachePath/index.html923=== RUN TestIsValidCachePath/traversal_parent924=== PAUSE TestIsValidCachePath/traversal_parent925=== RUN TestIsValidCachePath/traversal_in_middle926=== PAUSE TestIsValidCachePath/traversal_in_middle927=== RUN TestIsValidCachePath/invalid_char_e928=== PAUSE TestIsValidCachePath/invalid_char_e929=== RUN TestIsValidCachePath/invalid_char_u930=== PAUSE TestIsValidCachePath/invalid_char_u931=== RUN TestIsValidCachePath/random_path932=== PAUSE TestIsValidCachePath/random_path933=== RUN TestIsValidCachePath/empty934=== PAUSE TestIsValidCachePath/empty935=== RUN TestIsValidCachePath/leading_slash936=== PAUSE TestIsValidCachePath/leading_slash937=== RUN TestIsValidCachePath/wrong_extension938=== PAUSE TestIsValidCachePath/wrong_extension939=== RUN TestIsValidCachePath/short_hash940=== PAUSE TestIsValidCachePath/short_hash941=== CONT TestReadProxyNarinfo942--- PASS: TestMetricsInventory (2.10s)943=== CONT TestParseSingleRange944=== RUN TestParseSingleRange/none945=== PAUSE TestParseSingleRange/none946=== RUN TestParseSingleRange/unknown_unit947=== PAUSE TestParseSingleRange/unknown_unit948=== RUN TestParseSingleRange/multi-range_ignored949=== PAUSE TestParseSingleRange/multi-range_ignored950=== RUN TestParseSingleRange/malformed_no_dash951=== PAUSE TestParseSingleRange/malformed_no_dash952=== RUN TestParseSingleRange/malformed_both_empty953=== PAUSE TestParseSingleRange/malformed_both_empty954=== RUN TestParseSingleRange/malformed_end_before_start955=== PAUSE TestParseSingleRange/malformed_end_before_start956=== RUN TestParseSingleRange/closed957=== PAUSE TestParseSingleRange/closed958=== RUN TestParseSingleRange/open-ended959=== PAUSE TestParseSingleRange/open-ended960=== RUN TestParseSingleRange/end_clamped_to_size961=== PAUSE TestParseSingleRange/end_clamped_to_size962=== RUN TestParseSingleRange/suffix963=== PAUSE TestParseSingleRange/suffix964=== RUN TestParseSingleRange/suffix_exceeds_size965=== PAUSE TestParseSingleRange/suffix_exceeds_size966=== RUN TestParseSingleRange/single_byte967=== PAUSE TestParseSingleRange/single_byte968=== RUN TestParseSingleRange/start_past_EOF969=== PAUSE TestParseSingleRange/start_past_EOF970=== RUN TestParseSingleRange/start_far_past_EOF971=== PAUSE TestParseSingleRange/start_far_past_EOF972=== CONT TestProxyHeadersOnlyTrustedOnSocket9732026/10/01 09:22:17 WARN mTLS auth: subject not in bound subjects subject="CN=reader"9742026/10/01 09:22:17 WARN mTLS auth: subject not in bound subjects subject="CN=reader"975--- PASS: TestService_NativeMTLS (2.06s)976=== CONT TestPresentNotReportedWhileGCDeletesClosure9772026/10/01 09:22:17 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9782026/10/01 09:22:17 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=MjIyZjU3ZmItZjM0Zi00MzM3LWJiN2YtZDQ3MjhiODA4Yzg3LmQwMGUzZmZhLWVjMDctNDNlMC04Y2EwLWE1NzIyYjgwMTgyOXgxNzkwODQ2NTM2NzAxNzM1MDAw parts=109792026/10/01 09:22:17 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9802026/10/01 09:22:17 INFO Completed upload id=19812026/10/01 09:22:17 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000009822026/10/01 09:22:17 INFO Received uploads request method=POST path=/api/pending_closures9832026/10/01 09:22:17 INFO Starting cleanup of old closures method=DELETE path=/api/closures9842026/10/01 09:22:17 INFO Aborted multipart uploads count=0 kept=09852026/10/01 09:22:17 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=09862026/10/01 09:22:17 INFO Vacuumed table table=pending_closures9872026/10/01 09:22:17 INFO Vacuumed table table=pending_objects988=== NAME TestNARDeduplicationMetadataUploadBug989 metadata_upload_test.go:48: First store path: /nix/var/nix/builds/nix-25758-1034586924/TestNARDeduplicationMetadataUploadBug2608813672/001/store/vkrdbvljb0iarp7pnh7cvxz7k21qngj8-file1.txt9902026/10/01 09:22:17 INFO Vacuumed table table=multipart_uploads9912026/10/01 09:22:17 INFO Vacuumed table table=closures9922026/10/01 09:22:17 INFO Vacuumed table table=objects9932026/10/01 09:22:17 INFO Received get closure request method=GET path=/api/closures/00000000000000000000000000000000994--- PASS: TestService_createPendingClosureHandler (3.10s)995=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle9962026/10/01 09:22:18 INFO Received push request method=POST path=/api/pushes9972026/10/01 09:22:18 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)9982026/10/01 09:22:18 INFO Uploading vkrdbvljb0iarp7pnh7cvxz7k21qngj8-file1.txt (160B)9992026/10/01 09:22:18 WARN Failed to register uploaded object key=vkrdbvljb0iarp7pnh7cvxz7k21qngj8.ls error="server returned 404: 404 page not found\n"10002026/10/01 09:22:18 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"10012026/10/01 09:22:18 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10022026/10/01 09:22:18 INFO Signed narinfos id=1 count=110032026/10/01 09:22:18 INFO Uploading 1 narinfos10042026/10/01 09:22:18 INFO Received complete push request method=POST path=/api/pushes/1/complete10052026/10/01 09:22:18 WARN Failed to register uploaded object key=vkrdbvljb0iarp7pnh7cvxz7k21qngj8.narinfo error="server returned 404: 404 page not found\n"1006--- PASS: TestService_healthCheckHandler (1.65s)1007=== CONT TestCreatePinRejectsBadInput10082026/10/01 09:22:18 INFO Upload complete. (121ms)1009=== NAME TestNARDeduplicationMetadataUploadBug1010 metadata_upload_test.go:54: Retrieved narinfo from S3:1011 StorePath: /nix/var/nix/builds/nix-25758-1034586924/TestNARDeduplicationMetadataUploadBug2608813672/001/store/vkrdbvljb0iarp7pnh7cvxz7k21qngj8-file1.txt1012 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1013 Compression: zstd1014 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1015 NarSize: 1601016 References: 1017 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1018 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1019 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1020 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}1021 metadata_upload_test.go:64: Second store path (same content): /nix/var/nix/builds/nix-25758-1034586924/TestNARDeduplicationMetadataUploadBug2608813672/001/store/4zskg6x9i4bjy0bmnn9nsbmm392ss8g0-file2.txt10222026/10/01 09:22:18 INFO Received push request method=POST path=/api/pushes10232026/10/01 09:22:18 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)10242026/10/01 09:22:18 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign10252026/10/01 09:22:18 WARN Failed to register uploaded object key=4zskg6x9i4bjy0bmnn9nsbmm392ss8g0.ls error="server returned 404: 404 page not found\n"10262026/10/01 09:22:18 INFO Signed narinfos id=2 count=110272026/10/01 09:22:18 INFO Uploading 1 narinfos10282026/10/01 09:22:18 WARN readiness check failed error="closed pool"1029--- PASS: TestService_readinessHandler (1.85s)1030=== CONT TestDeletePinKeepsRowWhenS3Fails10312026/10/01 09:22:18 INFO Received complete push request method=POST path=/api/pushes/2/complete10322026/10/01 09:22:18 WARN Failed to register uploaded object key=4zskg6x9i4bjy0bmnn9nsbmm392ss8g0.narinfo error="server returned 404: 404 page not found\n"10332026/10/01 09:22:18 INFO Upload complete. (93ms)1034=== NAME TestNARDeduplicationMetadataUploadBug1035 metadata_upload_test.go:76: Retrieved narinfo from S3:1036 StorePath: /nix/var/nix/builds/nix-25758-1034586924/TestNARDeduplicationMetadataUploadBug2608813672/001/store/4zskg6x9i4bjy0bmnn9nsbmm392ss8g0-file2.txt1037 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1038 Compression: zstd1039 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1040 NarSize: 1601041 References: 1042 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1043 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1044 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1045 {"version":1,"root":{"type":"regular","size":44}}1046--- PASS: TestNARDeduplicationMetadataUploadBug (2.36s)1047=== CONT TestCreatePin_ReservedPins10482026/10/01 09:22:18 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:63473/oidc10492026/10/01 09:22:18 INFO Received uploads request method=POST path=/api/pending_closures1050--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (1.68s)1051=== CONT TestUploadHandlersRejectOversizedBody1052=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart1053=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart1054=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts1055=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts1056=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure1057=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure1058=== CONT TestOrphanedObjectsGCStressTest1059--- PASS: TestReadProxyNarinfoAlreadyDecompressed (1.81s)1060=== CONT TestUploadHandlersRejectInvalidKeys1061=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1062=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1063=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1064=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1065=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1066=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1067=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1068=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1069=== CONT TestConcurrentPinUpdatesAgree1070--- PASS: TestReadProxyNarStreaming (1.77s)1071=== CONT TestPendingClosureWriteTimeout1072=== RUN TestPendingClosureWriteTimeout/empty1073=== PAUSE TestPendingClosureWriteTimeout/empty1074=== RUN TestPendingClosureWriteTimeout/negative1075=== PAUSE TestPendingClosureWriteTimeout/negative1076=== RUN TestPendingClosureWriteTimeout/400_objects1077=== PAUSE TestPendingClosureWriteTimeout/400_objects1078=== RUN TestPendingClosureWriteTimeout/670k_objects1079=== PAUSE TestPendingClosureWriteTimeout/670k_objects1080=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1081=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1082=== CONT TestValidateS3Concurrency1083=== CONT TestIsValidUploadKey1084--- PASS: TestValidateS3Concurrency (0.00s)1085=== RUN TestIsValidUploadKey/narinfo1086=== PAUSE TestIsValidUploadKey/narinfo1087=== RUN TestIsValidUploadKey/nar_zst1088=== PAUSE TestIsValidUploadKey/nar_zst1089=== RUN TestIsValidUploadKey/nar_xz1090=== PAUSE TestIsValidUploadKey/nar_xz1091=== RUN TestIsValidUploadKey/nar_plain1092=== PAUSE TestIsValidUploadKey/nar_plain1093=== RUN TestIsValidUploadKey/listing1094=== PAUSE TestIsValidUploadKey/listing1095=== RUN TestIsValidUploadKey/build_log1096=== PAUSE TestIsValidUploadKey/build_log1097=== RUN TestIsValidUploadKey/build_log_home-manager_file1098=== PAUSE TestIsValidUploadKey/build_log_home-manager_file1099=== RUN TestIsValidUploadKey/build_log_plus_in_name1100=== PAUSE TestIsValidUploadKey/build_log_plus_in_name1101=== RUN TestIsValidUploadKey/build_log_question_mark1102=== PAUSE TestIsValidUploadKey/build_log_question_mark1103=== RUN TestIsValidUploadKey/build_log_equals1104=== PAUSE TestIsValidUploadKey/build_log_equals1105=== RUN TestIsValidUploadKey/realisation1106=== PAUSE TestIsValidUploadKey/realisation1107=== RUN TestIsValidUploadKey/realisation_plus_in_output1108=== PAUSE TestIsValidUploadKey/realisation_plus_in_output1109=== RUN TestIsValidUploadKey/nix-cache-info1110=== PAUSE TestIsValidUploadKey/nix-cache-info1111=== RUN TestIsValidUploadKey/index.html1112=== PAUSE TestIsValidUploadKey/index.html1113=== RUN TestIsValidUploadKey/narinfo_key,_nar_type1114=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type1115=== RUN TestIsValidUploadKey/nar_key,_narinfo_type1116=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type1117=== RUN TestIsValidUploadKey/listing_key,_narinfo_type1118=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type1119=== RUN TestIsValidUploadKey/traversal1120=== PAUSE TestIsValidUploadKey/traversal1121=== RUN TestIsValidUploadKey/traversal_nar1122=== PAUSE TestIsValidUploadKey/traversal_nar1123=== RUN TestIsValidUploadKey/absolute1124=== PAUSE TestIsValidUploadKey/absolute1125=== RUN TestIsValidUploadKey/empty_key1126=== PAUSE TestIsValidUploadKey/empty_key1127=== RUN TestIsValidUploadKey/unknown_type1128=== PAUSE TestIsValidUploadKey/unknown_type1129=== CONT TestGCTaskStore_GetEmpty1130--- PASS: TestGCTaskStore_GetEmpty (0.00s)1131=== CONT TestReconnectLeavesObjectsUnlocked11322026/10/01 09:22:19 ERROR Failed to decompress narinfo error="decompressed size exceeds configured limit"11332026/10/01 09:22:19 INFO Starting HTTP server address=127.0.0.1:6350311342026/10/01 09:22:19 INFO Starting HTTP server address=/nix/var/nix/builds/nix-25758-1034586924/TestProxyHeadersOnlyTrustedOnSocket1462974825/001/proxy.sock11352026/10/01 09:22:19 WARN mTLS auth: subject not in bound subjects subject="CN=someone"11362026/10/01 09:22:19 INFO Shutdown signal received, draining in-flight requests timeout=10s1137--- PASS: TestProxyHeadersOnlyTrustedOnSocket (1.92s)1138=== CONT TestObjectStatsTrigger11392026/10/01 09:22:19 ERROR Refusing narinfo larger than the limit key=5hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=167772161140--- PASS: TestReadProxyNarinfo (2.22s)1141=== CONT TestPendingClosureFailureAbortsItsUploads11422026/10/01 09:22:19 INFO Received uploads request method=POST path=/api/pending_closures11432026/10/01 09:22:19 INFO Received create pin request method=POST path=/api/pins/deploy11442026/10/01 09:22:19 INFO Received create pin request method=POST path=/api/pins/deploy11452026/10/01 09:22:19 INFO Received create pin request method=POST path=/api/pins/deploy11462026/10/01 09:22:19 INFO Received create pin request method=POST path=/api/pins/deploy11472026/10/01 09:22:19 INFO Received create pin request method=POST path=/api/pins/deploy11482026/10/01 09:22:19 INFO Received create pin request method=POST path=/api/pins/deploy11492026/10/01 09:22:19 INFO Received create pin request method=POST path=/api/pins/deploy11502026/10/01 09:22:19 INFO Received create pin request method=POST path=/api/pins/deploy11512026/10/01 09:22:19 INFO Received create pin request method=POST path=/api/pins/deploy11522026/10/01 09:22:20 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1153--- PASS: TestPresentNotReportedWhileGCDeletesClosure (2.49s)1154=== CONT TestProxyWriteTimeout1155=== RUN TestProxyWriteTimeout/narinfo1156=== PAUSE TestProxyWriteTimeout/narinfo1157=== RUN TestProxyWriteTimeout/1_GiB_nar1158=== PAUSE TestProxyWriteTimeout/1_GiB_nar1159=== RUN TestProxyWriteTimeout/10_GiB_nar1160=== PAUSE TestProxyWriteTimeout/10_GiB_nar1161=== RUN TestProxyWriteTimeout/unknown_size1162=== PAUSE TestProxyWriteTimeout/unknown_size1163=== CONT TestGCTaskStore_DeduplicateSameParams1164--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1165=== CONT TestParseSize1166--- PASS: TestParseSize (0.00s)1167=== CONT TestPresentReportsOnlyClosureRoots11682026/10/01 09:22:20 INFO Received create pin request method=POST path=/api/pins/app11692026/10/01 09:22:20 INFO Created/updated pin name=app store_path=/nix/store/cccccccccccccccccccccccccccccccc-app narinfo_key=cccccccccccccccccccccccccccccccc.narinfo11702026/10/01 09:22:20 INFO Received delete pin request method=DELETE path=/api/pins/app11712026/10/01 09:22:20 ERROR Failed to delete pin from S3 key=pins/app error="Get \"http://127.0.0.1:1/bucket26/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"11722026/10/01 09:22:20 INFO Received delete pin request method=DELETE path=/api/pins/app11732026/10/01 09:22:20 INFO Deleted pin name=app1174--- PASS: TestDeletePinKeepsRowWhenS3Fails (1.89s)1175=== CONT TestForceGCDuringPushOffersSweptObject1176=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows1177=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows1178=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check1179=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check1180=== CONT TestPendingClosureFailureTracksEveryUpload11812026/10/01 09:22:20 INFO Received create pin request method=POST path=/api/pins/deploy11822026/10/01 09:22:20 INFO Created/updated pin name=deploy store_path="/nix/store/dddddddddddddddddddddddddddddddd-app-1.0+git_x?y=z" narinfo_key=dddddddddddddddddddddddddddddddd.narinfo1183--- PASS: TestCreatePinRejectsBadInput (2.19s)1184=== CONT TestGCEndsOnShutdown1185=== RUN TestGCEndsOnShutdown/before_the_run1186=== PAUSE TestGCEndsOnShutdown/before_the_run1187=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1188=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1189=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1190=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1191=== CONT TestLeadElectsOneAndHandsOver11922026/10/01 09:22:20 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux11932026/10/01 09:22:20 WARN Refused reserved pin name=worker-x86_64-linux11942026/10/01 09:22:20 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux11952026/10/01 09:22:20 INFO Received create pin request method=POST path=/api/pins/my-app11962026/10/01 09:22:20 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1197--- PASS: TestCreatePin_ReservedPins (1.96s)1198=== CONT TestCommitRacingPendingCleanupKeepsObjects11992026/10/01 09:22:20 INFO Received create pin request method=POST path=/api/pins/app12002026/10/01 09:22:20 INFO Received create pin request method=POST path=/api/pins/app1201--- PASS: TestReconnectLeavesObjectsUnlocked (2.02s)1202=== CONT TestPendingCleanupUsesOneCutoff12032026/10/01 09:22:21 INFO Created/updated pin name=app store_path=/nix/store/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa-app narinfo_key=aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.narinfo12042026/10/01 09:22:21 INFO Created/updated pin name=app store_path=/nix/store/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb-app narinfo_key=bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb.narinfo1205--- PASS: TestObjectStatsTrigger (1.98s)1206--- PASS: TestConcurrentPinUpdatesAgree (2.57s)1207=== CONT TestGCSweepDeliversEachKeyOnce1208=== CONT TestSweepRechecksPendingAfterLocking12092026/10/01 09:22:21 INFO Received uploads request method=POST path=/api/pending_closures1210--- PASS: TestPendingClosureFailureAbortsItsUploads (2.12s)1211=== CONT TestTombstonedObjectOfferedWithoutWaiting1212--- PASS: TestPresentReportsOnlyClosureRoots (2.41s)1213=== CONT TestGCSweepSkipsPendingObjects12142026/10/01 09:22:22 INFO Received uploads request method=POST path=/api/pending_closures12152026/10/01 09:22:23 INFO Aborted multipart uploads count=0 kept=012162026/10/01 09:22:23 WARN Force mode enabled - objects will be deleted immediately without grace period12172026/10/01 09:22:23 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=012182026/10/01 09:22:23 INFO Vacuumed table table=pending_closures12192026/10/01 09:22:23 INFO Vacuumed table table=pending_objects12202026/10/01 09:22:23 INFO Vacuumed table table=multipart_uploads12212026/10/01 09:22:23 INFO Vacuumed table table=closures12222026/10/01 09:22:23 INFO Vacuumed table table=objects1223--- PASS: TestCommitRacingPendingCleanupKeepsObjects (2.89s)1224=== CONT TestPushDedupSurvivesConcurrentGC12252026/10/01 09:22:23 INFO lead: acquired remote=192.0.2.1:12341226--- PASS: TestPendingClosureFailureTracksEveryUpload (3.19s)1227=== CONT TestFailedS3DeleteKeepsTombstone12282026/10/01 09:22:23 INFO Received uploads request method=POST path=/api/pending_closures12292026/10/01 09:22:23 WARN Rate limiter enabled after throttle name=s3-test rate=512302026/10/01 09:22:23 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1231=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1232 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101233 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001234--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (5.87s)1235=== CONT TestDeduplicatedObjectsRecordedAsPending12362026/10/01 09:22:23 INFO Received uploads request method=POST path=/api/pending_closures12372026/10/01 09:22:23 INFO Received cleanup request method=DELETE path=/api/pending_closures12382026/10/01 09:22:24 INFO Aborted multipart uploads count=0 kept=012392026/10/01 09:22:24 WARN Force mode enabled - objects will be deleted immediately without grace period12402026/10/01 09:22: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=012412026/10/01 09:22:24 INFO Vacuumed table table=pending_closures12422026/10/01 09:22:24 INFO Vacuumed table table=pending_objects12432026/10/01 09:22:24 INFO Vacuumed table table=multipart_uploads12442026/10/01 09:22:24 INFO Vacuumed table table=closures12452026/10/01 09:22:24 INFO Vacuumed table table=objects1246--- PASS: TestSweepRechecksPendingAfterLocking (3.14s)1247=== CONT TestSkippedUploadsHandler12482026/10/01 09:22:24 INFO Client skipped oversized paths paths=3 nar_bytes=50000000001249--- PASS: TestSkippedUploadsHandler (0.00s)1250=== CONT TestGCBugBareHashReferences12512026/10/01 09:22:24 INFO lead: released remote=192.0.2.1:123412522026/10/01 09:22:24 INFO lead: acquired remote=192.0.2.1:123412532026/10/01 09:22:24 INFO Aborted multipart uploads count=0 kept=012542026/10/01 09:22:24 WARN Force mode enabled - objects will be deleted immediately without grace period12552026/10/01 09:22:24 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=012562026/10/01 09:22:24 INFO Vacuumed table table=pending_closures12572026/10/01 09:22:24 INFO Vacuumed table table=pending_objects12582026/10/01 09:22:24 INFO Vacuumed table table=multipart_uploads12592026/10/01 09:22:24 INFO Vacuumed table table=closures12602026/10/01 09:22:24 INFO Vacuumed table table=objects1261--- PASS: TestGCSweepDeliversEachKeyOnce (3.49s)1262=== CONT TestSweepSkipsRowsLockedByPush12632026/10/01 09:22:24 INFO Received uploads request method=POST path=/api/pending_closures1264--- PASS: TestTombstonedObjectOfferedWithoutWaiting (3.27s)1265=== CONT TestGCAdvisoryLockBlocksConcurrentRun12662026/10/01 09:22:25 INFO Received uploads request method=POST path=/api/pending_closures12672026/10/01 09:22:25 INFO Aborted multipart uploads count=0 kept=012682026/10/01 09:22:25 WARN Force mode enabled - objects will be deleted immediately without grace period12692026/10/01 09:22:25 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=012702026/10/01 09:22:25 INFO Vacuumed table table=pending_closures12712026/10/01 09:22:25 INFO Vacuumed table table=pending_objects12722026/10/01 09:22:25 INFO Vacuumed table table=multipart_uploads12732026/10/01 09:22:25 INFO lead: released remote=192.0.2.1:123412742026/10/01 09:22:25 INFO Vacuumed table table=closures12752026/10/01 09:22:25 INFO Vacuumed table table=objects1276--- PASS: TestLeadElectsOneAndHandsOver (5.35s)1277=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection1278--- PASS: TestGCSweepSkipsPendingObjects (3.18s)1279=== CONT TestGCMetrics12802026/10/01 09:22:26 INFO Received uploads request method=POST path=/api/pending_closures12812026/10/01 09:22:26 INFO Aborted multipart uploads count=0 kept=012822026/10/01 09:22:26 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=012832026/10/01 09:22:26 INFO Vacuumed table table=pending_closures12842026/10/01 09:22:26 INFO Received uploads request method=POST path=/api/pending_closures12852026/10/01 09:22:26 INFO Vacuumed table table=pending_objects12862026/10/01 09:22:26 INFO Vacuumed table table=multipart_uploads12872026/10/01 09:22:26 INFO Vacuumed table table=closures12882026/10/01 09:22:26 INFO Vacuumed table table=objects12892026/10/01 09:22:26 INFO Aborted multipart uploads count=0 kept=012902026/10/01 09:22:26 WARN Force mode enabled - objects will be deleted immediately without grace period12912026/10/01 09:22:26 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=012922026/10/01 09:22:26 INFO Vacuumed table table=pending_closures12932026/10/01 09:22:26 INFO Vacuumed table table=pending_objects12942026/10/01 09:22:26 INFO Vacuumed table table=multipart_uploads12952026/10/01 09:22:26 INFO Vacuumed table table=closures12962026/10/01 09:22:26 INFO Vacuumed table table=objects12972026/10/01 09:22:26 INFO Aborted multipart uploads count=0 kept=012982026/10/01 09:22:26 WARN Force mode enabled - objects will be deleted immediately without grace period1299=== CONT TestGetExistingObjectsLocksRows1300--- PASS: TestPushDedupSurvivesConcurrentGC (3.23s)13012026/10/01 09:22:26 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."13022026/10/01 09:22:26 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."1303--- PASS: TestFailedS3DeleteKeepsTombstone (3.10s)1304=== CONT TestRegisterCompletedObjectNeedsPendingRow1305=== NAME TestOrphanedObjectsGCStressTest1306 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains13072026/10/01 09:22:26 INFO Received uploads request method=POST path=/api/pending_closures1308--- PASS: TestDeduplicatedObjectsRecordedAsPending (2.78s)1309=== CONT TestReadProxyRangeRequest1310=== NAME TestOrphanedObjectsGCStressTest1311 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion13122026/10/01 09:22:27 INFO Aborted multipart uploads count=0 kept=013132026/10/01 09:22:27 WARN Force mode enabled - objects will be deleted immediately without grace period13142026/10/01 09:22:27 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=013152026/10/01 09:22:27 INFO Vacuumed table table=pending_closures13162026/10/01 09:22:27 INFO Vacuumed table table=pending_objects13172026/10/01 09:22:27 INFO Vacuumed table table=multipart_uploads13182026/10/01 09:22:27 INFO Vacuumed table table=closures1319--- PASS: TestGCBugBareHashReferences (2.60s)1320=== CONT TestLeadEndsOnShutdown13212026/10/01 09:22:27 INFO Vacuumed table table=objects13222026/10/01 09:22:27 INFO Aborted multipart uploads count=0 kept=013232026/10/01 09:22:27 WARN Force mode enabled - objects will be deleted immediately without grace period13242026/10/01 09:22:27 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=013252026/10/01 09:22:27 INFO Vacuumed table table=pending_closures13262026/10/01 09:22:27 INFO Vacuumed table table=pending_objects13272026/10/01 09:22:27 INFO Vacuumed table table=multipart_uploads13282026/10/01 09:22:27 INFO Vacuumed table table=closures13292026/10/01 09:22:27 INFO Vacuumed table table=objects1330--- PASS: TestSweepSkipsRowsLockedByPush (2.32s)1331=== CONT TestPush_SignsNarinfosOfItsPendingObjects13322026/10/01 09:22:27 INFO Aborted multipart uploads count=0 kept=013332026/10/01 09:22:27 WARN Force mode enabled - objects will be deleted immediately without grace period13342026/10/01 09:22:27 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=013352026/10/01 09:22:27 INFO Vacuumed table table=pending_closures13362026/10/01 09:22:27 INFO Vacuumed table table=pending_objects13372026/10/01 09:22:27 INFO Vacuumed table table=multipart_uploads13382026/10/01 09:22:27 INFO Vacuumed table table=closures13392026/10/01 09:22:27 INFO Vacuumed table table=objects1340--- PASS: TestGCMetrics (1.82s)1341=== CONT TestRedundantMultipartUpload13422026/10/01 09:22:27 INFO Received uploads request method=POST path=/api/pending_closures1343=== NAME TestOrphanedObjectsGCStressTest1344 orphaned_objects_gc_test.go:509: Stress test completed successfully:1345 orphaned_objects_gc_test.go:510: - Active objects preserved: 201346 orphaned_objects_gc_test.go:511: - Objects deleted: 2101347 orphaned_objects_gc_test.go:512: - Total GC'd: 2101348--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (2.24s)1349=== CONT TestPush_RejectsBadRequests1350--- PASS: TestOrphanedObjectsGCStressTest (9.23s)1351=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit1352--- PASS: TestRegisterCompletedObjectNeedsPendingRow (1.50s)1353=== CONT TestPush_CompleteCommitsEveryRoot1354--- PASS: TestGetExistingObjectsLocksRows (1.72s)1355=== CONT TestPush_OverlappingRootsStoreOneRowPerKey1356--- PASS: TestReadProxyRangeRequest (1.75s)1357=== CONT TestConnectSerialisesConcurrentMigrations13582026/10/01 09:22:28 INFO Received push request method=POST path=/api/pushes13592026/10/01 09:22:28 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13602026/10/01 09:22:28 INFO Signed narinfos id=1 count=11361--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (1.49s)1362=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock13632026/10/01 09:22:28 INFO lead: acquired remote=192.0.2.1:123413642026/10/01 09:22:28 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"1365--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (4.03s)1366=== CONT TestCompletedNarNotReofferedAcrossClosures13672026/10/01 09:22:29 INFO Received uploads request method=POST path=/api/pending_closures13682026/10/01 09:22:29 INFO Received uploads request method=POST path=/api/pending_closures13692026/10/01 09:22:29 INFO Received push request method=POST path=/api/pushes13702026-10-01 09:22:29.597 UTC [26123] ERROR: duplicate key value violates unique constraint "pg_type_typname_nsp_index"13712026-10-01 09:22:29.597 UTC [26123] DETAIL: Key (typname, typnamespace)=(goose_db_version, 2200) already exists.13722026-10-01 09:22:29.597 UTC [26123] STATEMENT: CREATE TABLE goose_db_version (1373 id integer PRIMARY KEY GENERATED BY DEFAULT AS IDENTITY,1374 version_id bigint NOT NULL,1375 is_applied boolean NOT NULL,1376 tstamp timestamp NOT NULL DEFAULT now()1377 )13782026/10/01 09:22:29 INFO lead: released remote=192.0.2.1:12341379=== RUN TestPush_RejectsBadRequests/no_objects1380=== PAUSE TestPush_RejectsBadRequests/no_objects1381=== RUN TestPush_RejectsBadRequests/bad_root1382=== PAUSE TestPush_RejectsBadRequests/bad_root1383=== RUN TestPush_RejectsBadRequests/root_not_in_objects1384=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1385=== RUN TestPush_RejectsBadRequests/no_roots1386=== PAUSE TestPush_RejectsBadRequests/no_roots1387=== CONT TestService_cleanupPendingClosuresHandler1388--- PASS: TestLeadEndsOnShutdown (2.70s)1389=== CONT TestClientWithDependencies13902026/10/01 09:22:29 INFO Aborted multipart uploads count=1 kept=013912026/10/01 09:22:29 INFO Received cleanup request method=DELETE path=/api/pending_closures13922026/10/01 09:22:29 INFO Aborted multipart uploads count=1 kept=01393--- PASS: TestPendingCleanupUsesOneCutoff (9.00s)1394=== CONT TestConnectWaitsForAPeerMigration13952026/10/01 09:22:30 INFO Received push request method=POST path=/api/pushes13962026/10/01 09:22:30 INFO Received push request method=POST path=/api/pushes1397--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (2.31s)1398=== CONT TestClientFallsBackToClosures1399=== CONT TestResolveDBConnectionString1400--- PASS: TestConnectSerialisesConcurrentMigrations (2.24s)1401=== RUN TestResolveDBConnectionString/flag_wins1402=== PAUSE TestResolveDBConnectionString/flag_wins1403=== RUN TestResolveDBConnectionString/file_when_flag_empty1404=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1405=== RUN TestResolveDBConnectionString/missing_file_is_an_error1406=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1407=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1408=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1409=== RUN TestResolveDBConnectionString/nothing_configured1410=== PAUSE TestResolveDBConnectionString/nothing_configured1411=== CONT TestClientMultipleUploads14122026/10/01 09:22:30 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14132026/10/01 09:22:30 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=MjIyZjU3ZmItZjM0Zi00MzM3LWJiN2YtZDQ3MjhiODA4Yzg3LmYzNjQ5ODkxLTYwMGUtNGQzMi05YzBmLTk2MTIzZjZhN2FjYngxNzkwODQ2NTQ5MTQ3OTgxMDAw parts=1214142026/10/01 09:22:30 INFO Received uploads request method=POST path=/api/pending_closures14152026/10/01 09:22:31 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14162026/10/01 09:22:31 INFO Received uploads request method=POST path=/api/pending_closures14172026/10/01 09:22:31 INFO Completed multipart upload object_key=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa00000000000000000000.nar.zst upload_id=MjIyZjU3ZmItZjM0Zi00MzM3LWJiN2YtZDQ3MjhiODA4Yzg3LmZhOTczYzUyLWFkOGEtNDIzYS1hZWMzLWI5M2ZhYTQ2YTk1OHgxNzkwODQ2NTQ5NTAzMTczMDAw parts=1014182026/10/01 09:22:31 INFO Received uploads request method=POST path=/api/pending_closures14192026/10/01 09:22:31 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14202026/10/01 09:22:31 INFO Completed multipart upload object_key=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa00000000000000000000.nar.zst upload_id=MjIyZjU3ZmItZjM0Zi00MzM3LWJiN2YtZDQ3MjhiODA4Yzg3LmE1OWM1ODU5LTQ4N2MtNDlhMi1iNzk2LTQzMzI0NGY4MjVjYXgxNzkwODQ2NTUwMDc1NzU3MDAw parts=1014212026/10/01 09:22:32 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14222026/10/01 09:22:32 INFO Completed multipart upload object_key=nar/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb00000000000000000000.nar.zst upload_id=MjIyZjU3ZmItZjM0Zi00MzM3LWJiN2YtZDQ3MjhiODA4Yzg3LmIxM2JiYmQxLWI5MGYtNDRjMS1iMmVjLTFiMDZiODAyOGMyM3gxNzkwODQ2NTQ5NTAyNTc2MDAw parts=1014232026/10/01 09:22:32 INFO Received complete push request method=POST path=/api/pushes/1/complete14242026/10/01 09:22:32 INFO Received push request method=POST path=/api/pushes14252026/10/01 09:22:32 INFO Aborted multipart uploads count=0 kept=014262026/10/01 09:22:32 WARN Force mode enabled - objects will be deleted immediately without grace period14272026/10/01 09:22:32 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=014282026/10/01 09:22:32 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14292026/10/01 09:22:32 INFO Vacuumed table table=pending_closures14302026/10/01 09:22:32 INFO Vacuumed table table=pending_objects14312026/10/01 09:22:32 INFO Vacuumed table table=multipart_uploads14322026/10/01 09:22:32 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=MjIyZjU3ZmItZjM0Zi00MzM3LWJiN2YtZDQ3MjhiODA4Yzg3LjY1NzBmOGJiLTVlMDYtNGY5My05OTE1LWUxYjQwMjQyZmU1ZHgxNzkwODQ2NTUxMDg0NDI3MDAw error="Get \"http://127.0.0.1:1/bucket56/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"14332026/10/01 09:22:32 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=MjIyZjU3ZmItZjM0Zi00MzM3LWJiN2YtZDQ3MjhiODA4Yzg3LjM1NDYyOThlLTU2NjgtNDE4YS04Mzc1LTk5MjU2OGI2YzhhN3gxNzkwODQ2NTUxMDAyMDU1MDAw parts=1214342026/10/01 09:22:32 INFO Received cleanup request method=DELETE path=/api/pending_closures14352026/10/01 09:22:33 INFO Aborted multipart uploads count=1 kept=014362026/10/01 09:22:33 INFO Vacuumed table table=closures1437--- PASS: TestRedundantMultipartUpload (5.55s)1438=== CONT TestClientSharedPathCommittedMidPush14392026/10/01 09:22:33 INFO Vacuumed table table=objects14402026/10/01 09:22:33 INFO Received cleanup request method=DELETE path=/api/pending_closures14412026/10/01 09:22:33 INFO Aborted multipart uploads count=0 kept=014422026/10/01 09:22:33 INFO Received uploads request method=POST path=/api/pending_closures14432026/10/01 09:22:33 INFO Received cleanup request method=DELETE path=/api/pending_closures14442026/10/01 09:22:33 INFO Aborted multipart uploads count=1 kept=014452026/10/01 09:22:33 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14462026-10-01 09:22:33.256 UTC [26142] ERROR: Closure does not exist: id=114472026-10-01 09:22:33.256 UTC [26142] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 12 at RAISE14482026-10-01 09:22:33.256 UTC [26142] STATEMENT: -- name: CommitPendingClosure :exec1449 SELECT commit_pending_closure($1::bigint)1450 1451--- PASS: TestService_cleanupPendingClosuresHandler (3.51s)1452=== CONT TestClientIntegration14532026/10/01 09:22:33 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14542026/10/01 09:22:33 INFO Completed multipart upload object_key=nar/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb00000000000000000000.nar.zst upload_id=MjIyZjU3ZmItZjM0Zi00MzM3LWJiN2YtZDQ3MjhiODA4Yzg3LjkwM2E3MDRiLWVkZTMtNDQwMi1iZDcxLWJiNGY0ZDRlZjM5ZXgxNzkwODQ2NTUwMDc1ODI3MDAw parts=1014552026/10/01 09:22:33 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14562026/10/01 09:22:33 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=MjIyZjU3ZmItZjM0Zi00MzM3LWJiN2YtZDQ3MjhiODA4Yzg3LmExNzg2YjA4LWEwMGItNGFiNC05YWFhLTVlYWE3MzM5YTg1YXgxNzkwODQ2NTUxNjg5NTI1MDAw parts=1214572026/10/01 09:22:33 INFO Received uploads request method=POST path=/api/pending_closures1458--- PASS: TestCompletedNarNotReofferedAcrossClosures (4.75s)1459=== CONT TestReadRedirectUsesPublicS3URL1460=== NAME TestClientWithDependencies1461 client_integration_test.go:735: Built derivation: /nix/var/nix/builds/nix-25758-1034586924/TestClientWithDependencies3552045708/001/store/7s6hh9s8nxlv4zgi461y8p90sv6ss7j5-test-script1462 client_integration_test.go:737: Found 1 dependencies (including self)14632026/10/01 09:22:34 INFO Received push request method=POST path=/api/pushes1464--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (5.56s)1465=== CONT TestClientPushesUseOnePush14662026/10/01 09:22:34 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14672026/10/01 09:22:34 INFO Uploading 7s6hh9s8nxlv4zgi461y8p90sv6ss7j5-test-script (136B)14682026/10/01 09:22:34 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"14692026/10/01 09:22:34 WARN Failed to register uploaded object key=7s6hh9s8nxlv4zgi461y8p90sv6ss7j5.ls error="server returned 404: 404 page not found\n"14702026/10/01 09:22:34 WARN Failed to register uploaded object key=log/fczfjr1nxi51yrd5fyfjxb7b9gjjkf03-test-script.drv error="server returned 404: 404 page not found\n"14712026/10/01 09:22:34 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14722026/10/01 09:22:34 INFO Signed narinfos id=1 count=114732026/10/01 09:22:34 INFO Uploading 1 narinfos14742026/10/01 09:22:34 INFO Received complete push request method=POST path=/api/pushes/1/complete14752026/10/01 09:22:34 WARN Failed to register uploaded object key=7s6hh9s8nxlv4zgi461y8p90sv6ss7j5.narinfo error="server returned 404: 404 page not found\n"14762026/10/01 09:22:34 INFO Upload complete. (187ms)14772026/10/01 09:22:34 INFO Aborted multipart uploads count=0 kept=014782026/10/01 09:22:34 WARN Force mode enabled - objects will be deleted immediately without grace period14792026/10/01 09:22:34 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=014802026/10/01 09:22:34 INFO Vacuumed table table=pending_closures14812026/10/01 09:22:34 INFO Vacuumed table table=pending_objects14822026/10/01 09:22:34 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14832026/10/01 09:22:34 INFO Vacuumed table table=multipart_uploads14842026/10/01 09:22:34 INFO Vacuumed table table=closures14852026/10/01 09:22:34 INFO Vacuumed table table=objects1486=== NAME TestClientWithDependencies1487 client_integration_test.go:753: Skipping nix copy test - isolated store (/nix/var/nix/builds/nix-25758-1034586924/TestClientWithDependencies3552045708/001/store) requires matching store prefix14882026/10/01 09:22:34 INFO Completed multipart upload object_key=nar/cccccccccccccccccccccccccccccccc00000000000000000000.nar.zst upload_id=MjIyZjU3ZmItZjM0Zi00MzM3LWJiN2YtZDQ3MjhiODA4Yzg3LjA2ZjYxNTYwLTQyNDYtNDAzZC1iNGNlLTNhYTIxNWM0MTBhMHgxNzkwODQ2NTUyNzE4Mjk1MDAw parts=1014892026/10/01 09:22:34 INFO Received complete push request method=POST path=/api/pushes/2/complete1490=== NAME TestClientMultipleUploads1491 client_integration_test.go:480: Created store path 0: /nix/var/nix/builds/nix-25758-1034586924/TestClientMultipleUploads2137170541/001/store/i6pk0g8qi2z9l59da2sn9c6wmgm5q3fk-test-file-0.txt1492--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (6.55s)1493=== CONT TestReadRedirectKeepsNarinfoProxied14942026/10/01 09:22:34 INFO Received uploads request method=POST path=/api/pending_closures14952026/10/01 09:22:34 INFO Received uploads request method=POST path=/api/pending_closures14962026/10/01 09:22:34 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)14972026/10/01 09:22:34 INFO Uploading y368kjjih4v34nd1slcdb4024bppsn3p-a (248B)14982026/10/01 09:22:34 INFO Uploading i5k70iv9mmy81w6lzjsii26p3s6qmm82-shared-dep (136B)1499--- PASS: TestClientWithDependencies (4.73s)1500=== CONT TestReadRedirectNar1501=== NAME TestClientMultipleUploads1502 client_integration_test.go:480: Created store path 1: /nix/var/nix/builds/nix-25758-1034586924/TestClientMultipleUploads2137170541/001/store/hlmgypafxlnp44sk5ggzac37l5j8jb7b-test-file-1.txt15032026/10/01 09:22:34 WARN Failed to register uploaded object key=i5k70iv9mmy81w6lzjsii26p3s6qmm82.ls error="server returned 404: 404 page not found\n"15042026/10/01 09:22:34 WARN Failed to register uploaded object key=nar/0j6zp733nlj2ngmarjjsc0p76iwskckw0kb3cyrpvi25p7acnmzj.nar.zst error="server returned 404: 404 page not found\n"15052026/10/01 09:22:34 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign15062026/10/01 09:22:34 WARN Failed to register uploaded object key=k7j6ycr78f7zqpw75r8slvk503ym9891.ls error="server returned 404: 404 page not found\n"15072026/10/01 09:22:34 WARN Failed to register uploaded object key=y368kjjih4v34nd1slcdb4024bppsn3p.ls error="server returned 404: 404 page not found\n"15082026/10/01 09:22:34 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"15092026/10/01 09:22:34 INFO Signed narinfos id=1 count=215102026/10/01 09:22:34 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign15112026/10/01 09:22:34 INFO Signed narinfos id=2 count=215122026/10/01 09:22:34 INFO Uploading 4 narinfos15132026/10/01 09:22:34 WARN Failed to register uploaded object key=i5k70iv9mmy81w6lzjsii26p3s6qmm82.narinfo error="server returned 404: 404 page not found\n"15142026/10/01 09:22:34 WARN Failed to register uploaded object key=y368kjjih4v34nd1slcdb4024bppsn3p.narinfo error="server returned 404: 404 page not found\n"15152026/10/01 09:22:34 WARN Failed to register uploaded object key=k7j6ycr78f7zqpw75r8slvk503ym9891.narinfo error="server returned 404: 404 page not found\n"15162026/10/01 09:22:34 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete15172026/10/01 09:22:34 WARN Failed to register uploaded object key=i5k70iv9mmy81w6lzjsii26p3s6qmm82.narinfo error="server returned 404: 404 page not found\n"15182026/10/01 09:22:34 INFO Completed upload id=115192026/10/01 09:22:34 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete15202026/10/01 09:22:34 INFO Completed upload id=215212026/10/01 09:22:34 INFO Upload complete. (144ms)1522=== NAME TestClientFallsBackToClosures1523 client_pushes_test.go:112: Retrieved narinfo from S3:1524 StorePath: /nix/var/nix/builds/nix-25758-1034586924/TestClientFallsBackToClosures2081634478/001/store/i5k70iv9mmy81w6lzjsii26p3s6qmm82-shared-dep1525 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1526 Compression: zstd1527 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821528 NarSize: 1361529 References: 1530 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1531 client_pushes_test.go:112: Retrieved narinfo from S3:1532 StorePath: /nix/var/nix/builds/nix-25758-1034586924/TestClientFallsBackToClosures2081634478/001/store/y368kjjih4v34nd1slcdb4024bppsn3p-a1533 URL: nar/0j6zp733nlj2ngmarjjsc0p76iwskckw0kb3cyrpvi25p7acnmzj.nar.zst1534 Compression: zstd1535 NarHash: sha256:0j6zp733nlj2ngmarjjsc0p76iwskckw0kb3cyrpvi25p7acnmzj1536 NarSize: 2481537 References: /nix/var/nix/builds/nix-25758-1034586924/TestClientFallsBackToClosures2081634478/001/store/i5k70iv9mmy81w6lzjsii26p3s6qmm82-shared-dep1538 CA: text:sha256:1ss95lzn7ra2c5xdbmq2004qzfrsk2h9ihj5f065y4rxdlll5c6a1539 client_pushes_test.go:112: Retrieved narinfo from S3:1540 StorePath: /nix/var/nix/builds/nix-25758-1034586924/TestClientFallsBackToClosures2081634478/001/store/k7j6ycr78f7zqpw75r8slvk503ym9891-b1541 URL: nar/0j6zp733nlj2ngmarjjsc0p76iwskckw0kb3cyrpvi25p7acnmzj.nar.zst1542 Compression: zstd1543 NarHash: sha256:0j6zp733nlj2ngmarjjsc0p76iwskckw0kb3cyrpvi25p7acnmzj1544 NarSize: 2481545 References: /nix/var/nix/builds/nix-25758-1034586924/TestClientFallsBackToClosures2081634478/001/store/i5k70iv9mmy81w6lzjsii26p3s6qmm82-shared-dep1546 CA: text:sha256:1ss95lzn7ra2c5xdbmq2004qzfrsk2h9ihj5f065y4rxdlll5c6a15472026/10/01 09:22:34 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1548=== NAME TestClientMultipleUploads1549 client_integration_test.go:480: Created store path 2: /nix/var/nix/builds/nix-25758-1034586924/TestClientMultipleUploads2137170541/001/store/xg7q07md6bz0kc3dvjckxqlg2lfxhlr5-test-file-2.txt15502026/10/01 09:22:34 INFO Completed multipart upload object_key=nar/cccccccccccccccccccccccccccccccc00000000000000000000.nar.zst upload_id=MjIyZjU3ZmItZjM0Zi00MzM3LWJiN2YtZDQ3MjhiODA4Yzg3Ljk5ZDZiZmVhLTc0OTMtNGI5MS04MDM0LTZlZTJhMmIxMjhhMngxNzkwODQ2NTUwMDc1MDgzMDAw parts=1015512026/10/01 09:22:34 INFO Received complete push request method=POST path=/api/pushes/1/complete1552--- PASS: TestClientFallsBackToClosures (4.15s)1553=== CONT TestReadProxyDisabled15542026/10/01 09:22:34 INFO Received push request method=POST path=/api/pushes1555--- PASS: TestPush_CompleteCommitsEveryRoot (6.71s)1556=== CONT TestPresignedUploadRegisteredBeforeCommit15572026/10/01 09:22:34 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)15582026/10/01 09:22:34 INFO Uploading i6pk0g8qi2z9l59da2sn9c6wmgm5q3fk-test-file-0.txt (160B)15592026/10/01 09:22:34 INFO Uploading hlmgypafxlnp44sk5ggzac37l5j8jb7b-test-file-1.txt (160B)15602026/10/01 09:22:34 INFO Uploading xg7q07md6bz0kc3dvjckxqlg2lfxhlr5-test-file-2.txt (160B)15612026/10/01 09:22:34 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"15622026/10/01 09:22:34 WARN Failed to register uploaded object key=xg7q07md6bz0kc3dvjckxqlg2lfxhlr5.ls error="server returned 404: 404 page not found\n"15632026/10/01 09:22:34 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"15642026/10/01 09:22:34 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"15652026/10/01 09:22:34 WARN Failed to register uploaded object key=hlmgypafxlnp44sk5ggzac37l5j8jb7b.ls error="server returned 404: 404 page not found\n"15662026/10/01 09:22:34 WARN Failed to register uploaded object key=i6pk0g8qi2z9l59da2sn9c6wmgm5q3fk.ls error="server returned 404: 404 page not found\n"15672026/10/01 09:22:34 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15682026/10/01 09:22:34 INFO Signed narinfos id=1 count=315692026/10/01 09:22:34 INFO Uploading 3 narinfos15702026/10/01 09:22:34 WARN Failed to register uploaded object key=hlmgypafxlnp44sk5ggzac37l5j8jb7b.narinfo error="server returned 404: 404 page not found\n"15712026/10/01 09:22:34 INFO Received complete push request method=POST path=/api/pushes/1/complete15722026/10/01 09:22:34 WARN Failed to register uploaded object key=xg7q07md6bz0kc3dvjckxqlg2lfxhlr5.narinfo error="server returned 404: 404 page not found\n"15732026/10/01 09:22:34 WARN Failed to register uploaded object key=i6pk0g8qi2z9l59da2sn9c6wmgm5q3fk.narinfo error="server returned 404: 404 page not found\n"15742026/10/01 09:22:34 INFO Upload complete. (104ms)1575=== NAME TestClientMultipleUploads1576 client_integration_test.go:491: Uploaded 3 paths in 138.072208ms1577--- PASS: TestClientMultipleUploads (4.12s)1578=== CONT TestPinProtectsFromGC1579=== NAME TestClientIntegration1580 client_integration_test.go:334: Created store path: /nix/var/nix/builds/nix-25758-1034586924/TestClientIntegration31329007/002/store/d2av26dv5j95l5fhdb9pfgfygy71r315-test-file.txt15812026/10/01 09:22:35 INFO Received push request method=POST path=/api/pushes15822026/10/01 09:22:35 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)15832026/10/01 09:22:35 INFO Uploading k6blaldz4s2wjvrlkx8vrqwqid24aydw-shared-dep (136B)15842026/10/01 09:22:35 INFO Uploading a10bbm0jia6hhy4g62w5r93kcx9lmjcv-top (256B)15852026/10/01 09:22:35 WARN Failed to register uploaded object key=nar/0pj3cw966zryr1m0a6vw7iflc8d2cc1j30y3v0d5nvjzj1nvlybg.nar.zst error="server returned 404: 404 page not found\n"15862026/10/01 09:22:35 WARN Failed to register uploaded object key=a10bbm0jia6hhy4g62w5r93kcx9lmjcv.ls error="server returned 404: 404 page not found\n"15872026/10/01 09:22:35 WARN Failed to register uploaded object key=k6blaldz4s2wjvrlkx8vrqwqid24aydw.ls error="server returned 404: 404 page not found\n"15882026/10/01 09:22:35 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15892026/10/01 09:22:35 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"15902026/10/01 09:22:35 INFO Signed narinfos id=1 count=215912026/10/01 09:22:35 INFO Uploading 2 narinfos15922026/10/01 09:22:35 INFO Received push request method=POST path=/api/pushes15932026/10/01 09:22:35 WARN Failed to register uploaded object key=k6blaldz4s2wjvrlkx8vrqwqid24aydw.narinfo error="server returned 404: 404 page not found\n"15942026/10/01 09:22:35 INFO Received complete push request method=POST path=/api/pushes/1/complete15952026/10/01 09:22:35 WARN Failed to register uploaded object key=a10bbm0jia6hhy4g62w5r93kcx9lmjcv.narinfo error="server returned 404: 404 page not found\n"15962026/10/01 09:22:35 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15972026/10/01 09:22:35 INFO Uploading d2av26dv5j95l5fhdb9pfgfygy71r315-test-file.txt (152B)15982026/10/01 09:22:35 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"15992026/10/01 09:22:35 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16002026/10/01 09:22:35 WARN Failed to register uploaded object key=d2av26dv5j95l5fhdb9pfgfygy71r315.ls error="server returned 404: 404 page not found\n"16012026/10/01 09:22:35 INFO Upload complete. (145ms)16022026/10/01 09:22:35 INFO Signed narinfos id=1 count=116032026/10/01 09:22:35 INFO Uploading 1 narinfos1604=== NAME TestClientSharedPathCommittedMidPush1605 client_integration_test.go:816: Retrieved narinfo from S3:1606 StorePath: /nix/var/nix/builds/nix-25758-1034586924/TestClientSharedPathCommittedMidPush1966525489/001/store/k6blaldz4s2wjvrlkx8vrqwqid24aydw-shared-dep1607 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1608 Compression: zstd1609 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821610 NarSize: 1361611 References: 1612 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1613 client_integration_test.go:816: Retrieved narinfo from S3:1614 StorePath: /nix/var/nix/builds/nix-25758-1034586924/TestClientSharedPathCommittedMidPush1966525489/001/store/a10bbm0jia6hhy4g62w5r93kcx9lmjcv-top1615 URL: nar/0pj3cw966zryr1m0a6vw7iflc8d2cc1j30y3v0d5nvjzj1nvlybg.nar.zst1616 Compression: zstd1617 NarHash: sha256:0pj3cw966zryr1m0a6vw7iflc8d2cc1j30y3v0d5nvjzj1nvlybg1618 NarSize: 2561619 References: /nix/var/nix/builds/nix-25758-1034586924/TestClientSharedPathCommittedMidPush1966525489/001/store/k6blaldz4s2wjvrlkx8vrqwqid24aydw-shared-dep1620 CA: text:sha256:1xy9yxzdhaifvps0qliil8bpfnz8ibx3b0y33wmsm0g53g6k6vgs1621--- PASS: TestReadRedirectUsesPublicS3URL (1.71s)1622=== CONT TestReadProxyRootRedirectsToIndexHTML16232026/10/01 09:22:35 INFO Received complete push request method=POST path=/api/pushes/1/complete16242026/10/01 09:22:35 WARN Failed to register uploaded object key=d2av26dv5j95l5fhdb9pfgfygy71r315.narinfo error="server returned 404: 404 page not found\n"16252026/10/01 09:22:35 INFO Upload complete. (172ms)1626--- PASS: TestClientSharedPathCommittedMidPush (2.47s)1627=== CONT TestReadProxyConditionalGet16282026/10/01 09:22:35 INFO All 1 paths already cached1629=== NAME TestClientIntegration1630 client_integration_test.go:360: Retrieved narinfo from S3:1631 StorePath: /nix/var/nix/builds/nix-25758-1034586924/TestClientIntegration31329007/002/store/d2av26dv5j95l5fhdb9pfgfygy71r315-test-file.txt1632 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1633 Compression: zstd1634 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11635 NarSize: 1521636 References: 1637 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11638 client_integration_test.go:361: Retrieved .ls file from S3 (compressed size: 77 bytes)1639 client_integration_test.go:361: Decompressed .ls content (64 bytes):1640 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}16412026/10/01 09:22:35 INFO Received push request method=POST path=/api/pushes16422026/10/01 09:22:35 INFO Object in database but missing from S3 key=d2av26dv5j95l5fhdb9pfgfygy71r315.ls16432026/10/01 09:22:35 WARN Found objects in DB but missing from S3, will re-upload count=116442026/10/01 09:22:35 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)16452026/10/01 09:22:35 WARN Failed to register uploaded object key=d2av26dv5j95l5fhdb9pfgfygy71r315.ls error="server returned 404: 404 page not found\n"16462026/10/01 09:22:35 INFO Received complete push request method=POST path=/api/pushes/2/complete16472026/10/01 09:22:35 INFO Upload complete. (59ms)1648 client_integration_test.go:389: Retrieved .ls file from S3 (compressed size: 62 bytes)1649 client_integration_test.go:389: Decompressed .ls content (49 bytes):1650 {"version":1,"root":{"type":"regular","size":39}}16512026/10/01 09:22:35 INFO Received push request method=POST path=/api/pushes16522026/10/01 09:22:35 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)16532026/10/01 09:22:35 INFO Received complete push request method=POST path=/api/pushes/3/complete16542026/10/01 09:22:35 WARN Failed to register uploaded object key=d2av26dv5j95l5fhdb9pfgfygy71r315.ls error="server returned 404: 404 page not found\n"16552026/10/01 09:22:35 INFO Upload complete. (85ms)1656 client_integration_test.go:405: Retrieved .ls file from S3 (compressed size: 62 bytes)1657 client_integration_test.go:405: Decompressed .ls content (49 bytes):1658 {"version":1,"root":{"type":"regular","size":39}}16592026/10/01 09:22:35 INFO Received push request method=POST path=/api/pushes16602026/10/01 09:22:35 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16612026/10/01 09:22:35 INFO Uploading rn3czbhcsp936343x297ksg2xk9bwkl0-lost-commit.txt (152B)16622026/10/01 09:22:35 WARN Failed to register uploaded object key=nar/04d5klw9iix884nk82y7nlkps8afh2bg119y7zkvcf1pc1x2y2jl.nar.zst error="server returned 404: 404 page not found\n"16632026/10/01 09:22:35 INFO Received sign narinfos request method=POST path=/api/pushes/4/sign16642026/10/01 09:22:35 WARN Failed to register uploaded object key=rn3czbhcsp936343x297ksg2xk9bwkl0.ls error="server returned 404: 404 page not found\n"16652026/10/01 09:22:35 INFO Signed narinfos id=4 count=116662026/10/01 09:22:35 INFO Uploading 1 narinfos16672026/10/01 09:22:35 INFO Received complete push request method=POST path=/api/pushes/4/complete16682026/10/01 09:22:35 WARN Failed to register uploaded object key=rn3czbhcsp936343x297ksg2xk9bwkl0.narinfo error="server returned 404: 404 page not found\n"16692026/10/01 09:22:35 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Post \"http://127.0.0.1:63781/api/pushes/4/complete\": EOF" url=http://127.0.0.1:63781/api/pushes/4/complete16702026/10/01 09:22:36 INFO Received complete push request method=POST path=/api/pushes/4/complete16712026-10-01 09:22:36.076 UTC [26207] ERROR: Push does not exist: id=416722026-10-01 09:22:36.076 UTC [26207] CONTEXT: PL/pgSQL function commit_push(bigint) line 9 at RAISE16732026-10-01 09:22:36.076 UTC [26207] STATEMENT: -- name: CommitPush :exec1674 SELECT commit_push($1::bigint)1675 16762026/10/01 09:22:36 INFO Upload complete. (181ms)1677 client_integration_test.go:435: Retrieved narinfo from S3:1678 StorePath: /nix/var/nix/builds/nix-25758-1034586924/TestClientIntegration31329007/002/store/rn3czbhcsp936343x297ksg2xk9bwkl0-lost-commit.txt1679 URL: nar/04d5klw9iix884nk82y7nlkps8afh2bg119y7zkvcf1pc1x2y2jl.nar.zst1680 Compression: zstd1681 NarHash: sha256:04d5klw9iix884nk82y7nlkps8afh2bg119y7zkvcf1pc1x2y2jl1682 NarSize: 1521683 References: 1684 CA: fixed:r:sha256:04d5klw9iix884nk82y7nlkps8afh2bg119y7zkvcf1pc1x2y2jl1685 client_integration_test.go:438: Testing garbage collection...16862026/10/01 09:22:36 INFO Starting cleanup of old closures method=DELETE path=/api/closures16872026/10/01 09:22:36 INFO Garbage collection started16882026/10/01 09:22:36 INFO Aborted multipart uploads count=0 kept=016892026/10/01 09:22:36 WARN Force mode enabled - objects will be deleted immediately without grace period16902026/10/01 09:22:36 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=016912026/10/01 09:22:36 INFO Vacuumed table table=pending_closures16922026/10/01 09:22:36 INFO Vacuumed table table=pending_objects16932026/10/01 09:22:36 INFO Vacuumed table table=multipart_uploads16942026/10/01 09:22:36 INFO Vacuumed table table=closures1695--- PASS: TestReadRedirectKeepsNarinfoProxied (1.93s)1696=== CONT TestReadProxyOutlastsServerWriteTimeout16972026/10/01 09:22:36 INFO Vacuumed table table=objects16982026/10/01 09:22:36 INFO Received push request method=POST path=/api/pushes16992026/10/01 09:22:36 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)17002026/10/01 09:22:36 INFO Uploading xzs9hzm6n5pf4jpxclyzlh0hs7gqpbws-a (248B)17012026/10/01 09:22:36 INFO Uploading 5g9dqdipr8pz5vg85biwm1759986kf7n-shared-dep (136B)17022026/10/01 09:22:36 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"17032026/10/01 09:22:36 WARN Failed to register uploaded object key=xzs9hzm6n5pf4jpxclyzlh0hs7gqpbws.ls error="server returned 404: 404 page not found\n"1704--- PASS: TestReadRedirectNar (2.13s)1705=== CONT TestService_AuthMiddleware_MTLSBoundSubjects17062026/10/01 09:22:36 WARN Failed to register uploaded object key=nar/1i2b9cj3401q3w9rmdd30j8z9wxm6ak0zmxy6xpm5gdm1qag8ri5.nar.zst error="server returned 404: 404 page not found\n"17072026/10/01 09:22:36 WARN Failed to register uploaded object key=r3hyrdiksrymjjqbzp4hfqbx9msbx5za.ls error="server returned 404: 404 page not found\n"17082026/10/01 09:22:36 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17092026/10/01 09:22:36 WARN Failed to register uploaded object key=5g9dqdipr8pz5vg85biwm1759986kf7n.ls error="server returned 404: 404 page not found\n"17102026/10/01 09:22:36 INFO Signed narinfos id=1 count=317112026/10/01 09:22:36 INFO Uploading 3 narinfos17122026/10/01 09:22:36 WARN Failed to register uploaded object key=5g9dqdipr8pz5vg85biwm1759986kf7n.narinfo error="server returned 404: 404 page not found\n"17132026/10/01 09:22:36 WARN Failed to register uploaded object key=xzs9hzm6n5pf4jpxclyzlh0hs7gqpbws.narinfo error="server returned 404: 404 page not found\n"17142026/10/01 09:22:36 INFO Received complete push request method=POST path=/api/pushes/1/complete17152026/10/01 09:22:36 WARN Failed to register uploaded object key=r3hyrdiksrymjjqbzp4hfqbx9msbx5za.narinfo error="server returned 404: 404 page not found\n"17162026/10/01 09:22:36 INFO Upload complete. (152ms)1717=== NAME TestClientPushesUseOnePush1718 client_pushes_test.go:97: Retrieved narinfo from S3:1719 StorePath: /nix/var/nix/builds/nix-25758-1034586924/TestClientPushesUseOnePush363646333/001/store/5g9dqdipr8pz5vg85biwm1759986kf7n-shared-dep1720 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1721 Compression: zstd1722 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821723 NarSize: 1361724 References: 1725 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1726 client_pushes_test.go:97: Retrieved narinfo from S3:1727 StorePath: /nix/var/nix/builds/nix-25758-1034586924/TestClientPushesUseOnePush363646333/001/store/xzs9hzm6n5pf4jpxclyzlh0hs7gqpbws-a1728 URL: nar/1i2b9cj3401q3w9rmdd30j8z9wxm6ak0zmxy6xpm5gdm1qag8ri5.nar.zst1729 Compression: zstd1730 NarHash: sha256:1i2b9cj3401q3w9rmdd30j8z9wxm6ak0zmxy6xpm5gdm1qag8ri51731 NarSize: 2481732 References: /nix/var/nix/builds/nix-25758-1034586924/TestClientPushesUseOnePush363646333/001/store/5g9dqdipr8pz5vg85biwm1759986kf7n-shared-dep1733 CA: text:sha256:0jwa99x4przp03n4wlarwb587nhqc90za592qxsiw3l08lg8325k1734 client_pushes_test.go:97: Retrieved narinfo from S3:1735 StorePath: /nix/var/nix/builds/nix-25758-1034586924/TestClientPushesUseOnePush363646333/001/store/r3hyrdiksrymjjqbzp4hfqbx9msbx5za-b1736 URL: nar/1i2b9cj3401q3w9rmdd30j8z9wxm6ak0zmxy6xpm5gdm1qag8ri5.nar.zst1737 Compression: zstd1738 NarHash: sha256:1i2b9cj3401q3w9rmdd30j8z9wxm6ak0zmxy6xpm5gdm1qag8ri51739 NarSize: 2481740 References: /nix/var/nix/builds/nix-25758-1034586924/TestClientPushesUseOnePush363646333/001/store/5g9dqdipr8pz5vg85biwm1759986kf7n-shared-dep1741 CA: text:sha256:0jwa99x4przp03n4wlarwb587nhqc90za592qxsiw3l08lg8325k1742--- PASS: TestClientPushesUseOnePush (2.58s)1743=== CONT TestService_AuthMiddleware_OIDC17442026/10/01 09:22:36 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:63865/oidc1745--- PASS: TestReadProxyDisabled (2.21s)1746=== CONT TestPushWaitsForSweepHoldingRow17472026/10/01 09:22:37 INFO Received uploads request method=POST path=/api/pending_closures17482026/10/01 09:22:37 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst17492026/10/01 09:22:37 INFO Received uploads request method=POST path=/api/pending_closures1750=== CONT TestClientErrorHandling1751--- PASS: TestPresignedUploadRegisteredBeforeCommit (2.58s)1752=== RUN TestClientErrorHandling/InvalidStorePath1753=== PAUSE TestClientErrorHandling/InvalidStorePath1754=== RUN TestClientErrorHandling/InvalidAuthToken1755=== PAUSE TestClientErrorHandling/InvalidAuthToken1756=== RUN TestClientErrorHandling/ServerNotAvailable1757=== PAUSE TestClientErrorHandling/ServerNotAvailable1758=== CONT TestService_RequireScope_OIDC17592026/10/01 09:22:37 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:63879/oidc1760=== NAME TestPinProtectsFromGC1761 client_integration_test.go:867: Pinned store path: /nix/var/nix/builds/nix-25758-1034586924/TestPinProtectsFromGC2740252931/001/store/f58j9m9sg8i9byyfd43f3w49gza9683v-pinned-file.txt1762 client_integration_test.go:868: Unpinned store path: /nix/var/nix/builds/nix-25758-1034586924/TestPinProtectsFromGC2740252931/001/store/z138s3jlqwwsn4pn3p4mlfbvp4b4d7s5-unpinned-file.txt17632026/10/01 09:22:37 INFO Received push request method=POST path=/api/pushes17642026/10/01 09:22:37 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17652026/10/01 09:22:37 INFO Uploading f58j9m9sg8i9byyfd43f3w49gza9683v-pinned-file.txt (128B)17662026/10/01 09:22:37 WARN Failed to register uploaded object key=f58j9m9sg8i9byyfd43f3w49gza9683v.ls error="server returned 404: 404 page not found\n"17672026/10/01 09:22:37 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17682026/10/01 09:22:37 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"17692026/10/01 09:22:37 INFO Signed narinfos id=1 count=117702026/10/01 09:22:37 INFO Uploading 1 narinfos17712026/10/01 09:22:37 INFO Received complete push request method=POST path=/api/pushes/1/complete17722026/10/01 09:22:37 WARN Failed to register uploaded object key=f58j9m9sg8i9byyfd43f3w49gza9683v.narinfo error="server returned 404: 404 page not found\n"1773--- PASS: TestReadProxyRootRedirectsToIndexHTML (2.34s)1774=== CONT TestCacheStatsHandler17752026/10/01 09:22:37 INFO Upload complete. (192ms)17762026/10/01 09:22:37 INFO Received push request method=POST path=/api/pushes17772026/10/01 09:22:37 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17782026/10/01 09:22:37 INFO Uploading z138s3jlqwwsn4pn3p4mlfbvp4b4d7s5-unpinned-file.txt (128B)17792026/10/01 09:22:37 WARN Failed to register uploaded object key=z138s3jlqwwsn4pn3p4mlfbvp4b4d7s5.ls error="server returned 404: 404 page not found\n"17802026/10/01 09:22:37 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"17812026/10/01 09:22:37 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign17822026/10/01 09:22:37 INFO Signed narinfos id=2 count=117832026/10/01 09:22:37 INFO Uploading 1 narinfos17842026/10/01 09:22:37 INFO Received complete push request method=POST path=/api/pushes/2/complete17852026/10/01 09:22:37 WARN Failed to register uploaded object key=z138s3jlqwwsn4pn3p4mlfbvp4b4d7s5.narinfo error="server returned 404: 404 page not found\n"17862026/10/01 09:22:37 INFO Upload complete. (109ms)17872026/10/01 09:22:38 INFO Starting cleanup of old closures method=DELETE path=/api/closures17882026/10/01 09:22:38 INFO Garbage collection started17892026/10/01 09:22:38 INFO Aborted multipart uploads count=0 kept=017902026/10/01 09:22:38 WARN Force mode enabled - objects will be deleted immediately without grace period1791--- PASS: TestReadProxyConditionalGet (2.56s)1792=== CONT TestService_ReadAuthMiddleware17932026/10/01 09:22:38 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=017942026/10/01 09:22:38 INFO Vacuumed table table=pending_closures17952026/10/01 09:22:38 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=2 objects_marked=6 objects_deleted=6 objects_failed=01796=== NAME TestClientIntegration1797 client_integration_test.go:445: Objects in database after GC:1798 client_integration_test.go:445: Successfully deleted all objects with GC --force17992026/10/01 09:22:38 INFO Vacuumed table table=pending_objects18002026/10/01 09:22:38 INFO Vacuumed table table=multipart_uploads18012026/10/01 09:22:38 INFO Vacuumed table table=closures18022026/10/01 09:22:38 INFO Vacuumed table table=objects1803--- PASS: TestClientIntegration (4.98s)1804=== CONT TestReadProxyHead1805--- PASS: TestConnectWaitsForAPeerMigration (8.36s)1806=== CONT TestService_ReadScope_PublicByDefault18072026/10/01 09:22:38 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"18082026/10/01 09:22:38 WARN mTLS auth: bound subjects configured but subject DN unavailable18092026/10/01 09:22:38 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1810--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (2.28s)1811=== CONT TestService_AuthMiddleware_MTLSProxyHeader1812=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1813=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1814=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1815=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1816=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1817=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1818=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1819=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1820=== CONT TestClientCADerivations18212026/10/01 09:22:39 INFO Received uploads request method=POST path=/api/pending_closures1822=== RUN TestService_RequireScope_OIDC/builder_may_write1823=== PAUSE TestService_RequireScope_OIDC/builder_may_write1824=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1825=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1826=== RUN TestService_RequireScope_OIDC/ops_may_admin1827=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1828=== RUN TestService_RequireScope_OIDC/ops_may_not_write1829=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1830=== RUN TestService_RequireScope_OIDC/reader_may_not_write1831=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1832=== RUN TestService_RequireScope_OIDC/static_token_may_admin1833=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1834=== RUN TestService_RequireScope_OIDC/static_token_may_write1835=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1836=== RUN TestService_RequireScope_OIDC/reader_may_read1837=== PAUSE TestService_RequireScope_OIDC/reader_may_read1838=== RUN TestService_RequireScope_OIDC/writer_implies_read1839=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1840=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1841=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1842=== CONT TestCacheConfigHandler1843=== RUN TestCacheConfigHandler/full_config,_no_issuer1844=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1845=== RUN TestCacheConfigHandler/no_cache_url_configured1846=== PAUSE TestCacheConfigHandler/no_cache_url_configured1847=== RUN TestCacheConfigHandler/no_signing_keys1848=== PAUSE TestCacheConfigHandler/no_signing_keys1849=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1850=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1851=== CONT TestService_Rustfstest18522026/10/01 09:22:40 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=018532026/10/01 09:22:40 INFO Received create pin request method=POST path=/api/pins/myapp18542026/10/01 09:22:40 INFO Created/updated pin name=myapp store_path=/nix/var/nix/builds/nix-25758-1034586924/TestPinProtectsFromGC2740252931/001/store/f58j9m9sg8i9byyfd43f3w49gza9683v-pinned-file.txt narinfo_key=f58j9m9sg8i9byyfd43f3w49gza9683v.narinfo18552026/10/01 09:22:40 INFO Starting cleanup of old closures method=DELETE path=/api/closures18562026/10/01 09:22:40 INFO Garbage collection started1857--- PASS: TestPushWaitsForSweepHoldingRow (3.19s)1858=== CONT TestServerTLSConfig/not_a_PEM_file18592026/10/01 09:22:40 INFO Aborted multipart uploads count=0 kept=018602026/10/01 09:22:40 WARN Force mode enabled - objects will be deleted immediately without grace period18612026/10/01 09:22:40 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=018622026/10/01 09:22:40 INFO Vacuumed table table=pending_closures18632026/10/01 09:22:40 INFO Vacuumed table table=pending_objects18642026/10/01 09:22:40 INFO Vacuumed table table=multipart_uploads18652026/10/01 09:22:40 INFO Vacuumed table table=closures18662026/10/01 09:22:40 INFO Vacuumed table table=objects1867=== CONT TestServerTLSConfig/missing_CA_file1868=== CONT TestServerTLSConfig/no_client_CA1869=== CONT TestIsValidCachePath/narinfo1870=== CONT TestIsValidCachePath/short_hash1871--- PASS: TestServerTLSConfig (0.00s)1872 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.02s)1873 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1874 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1875=== CONT TestIsValidCachePath/nix-cache-info1876=== CONT TestIsValidCachePath/leading_slash1877=== CONT TestIsValidCachePath/empty1878=== CONT TestIsValidCachePath/wrong_extension1879=== CONT TestIsValidCachePath/random_path1880=== CONT TestIsValidCachePath/invalid_char_e1881=== CONT TestIsValidCachePath/invalid_char_u1882=== CONT TestIsValidCachePath/traversal_parent1883=== CONT TestIsValidCachePath/traversal_in_middle1884=== CONT TestIsValidCachePath/nar_bz21885=== CONT TestIsValidCachePath/index.html1886=== CONT TestIsValidCachePath/realisation1887=== CONT TestIsValidCachePath/ls1888=== CONT TestIsValidCachePath/log1889=== CONT TestIsValidCachePath/nar_uncompressed1890=== CONT TestIsValidCachePath/nar_xz1891=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1892=== CONT TestIsValidCachePath/nar_zst1893=== CONT TestParseSingleRange/unknown_unit1894--- PASS: TestIsValidCachePath (0.00s)1895 --- PASS: TestIsValidCachePath/narinfo (0.00s)1896 --- PASS: TestIsValidCachePath/short_hash (0.00s)1897 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1898 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1899 --- PASS: TestIsValidCachePath/empty (0.00s)1900 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1901 --- PASS: TestIsValidCachePath/random_path (0.00s)1902 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1903 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1904 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1905 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1906 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1907 --- PASS: TestIsValidCachePath/index.html (0.00s)1908 --- PASS: TestIsValidCachePath/realisation (0.00s)1909 --- PASS: TestIsValidCachePath/ls (0.00s)1910 --- PASS: TestIsValidCachePath/log (0.00s)1911 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1912 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1913 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1914 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1915=== CONT TestParseSingleRange/closed1916=== CONT TestParseSingleRange/suffix_exceeds_size1917=== CONT TestParseSingleRange/suffix1918=== CONT TestParseSingleRange/end_clamped_to_size1919=== CONT TestParseSingleRange/start_past_EOF1920=== CONT TestParseSingleRange/open-ended1921=== CONT TestParseSingleRange/malformed_no_dash1922=== CONT TestParseSingleRange/malformed_both_empty1923=== CONT TestParseSingleRange/single_byte1924=== CONT TestParseSingleRange/start_far_past_EOF1925=== CONT TestParseSingleRange/multi-range_ignored1926=== CONT TestParseSingleRange/none1927=== CONT TestParseSingleRange/malformed_end_before_start1928=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart1929--- PASS: TestParseSingleRange (0.00s)1930 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1931 --- PASS: TestParseSingleRange/closed (0.00s)1932 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1933 --- PASS: TestParseSingleRange/suffix (0.00s)1934 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1935 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1936 --- PASS: TestParseSingleRange/open-ended (0.00s)1937 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1938 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1939 --- PASS: TestParseSingleRange/single_byte (0.00s)1940 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1941 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1942 --- PASS: TestParseSingleRange/none (0.00s)1943 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)19442026/10/01 09:22:40 INFO Received complete multipart upload request method=POST path=/1945=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts19462026/10/01 09:22:40 INFO Received request for more parts method=POST path=/1947--- PASS: TestCacheStatsHandler (2.69s)1948=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure19492026/10/01 09:22:40 INFO Received uploads request method=POST path=/1950--- PASS: TestService_ReadAuthMiddleware (2.54s)1951=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key19522026/10/01 09:22:40 INFO Received request for more parts method=POST path=/1953=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal19542026/10/01 09:22:40 INFO Received uploads request method=POST path=/1955=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key19562026/10/01 09:22:40 INFO Received complete multipart upload request method=POST path=/1957=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info19582026/10/01 09:22:40 INFO Received uploads request method=POST path=/1959--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1960 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1961 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1962 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1963 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1964=== CONT TestPendingClosureWriteTimeout/empty1965=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1966=== CONT TestPendingClosureWriteTimeout/670k_objects1967=== CONT TestPendingClosureWriteTimeout/negative1968=== CONT TestPendingClosureWriteTimeout/400_objects1969=== CONT TestIsValidUploadKey/narinfo1970=== CONT TestIsValidUploadKey/unknown_type1971=== CONT TestIsValidUploadKey/build_log_equals1972=== CONT TestIsValidUploadKey/realisation1973=== CONT TestIsValidUploadKey/build_log_question_mark1974=== CONT TestIsValidUploadKey/build_log_plus_in_name1975=== CONT TestIsValidUploadKey/build_log_home-manager_file1976=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1977=== CONT TestIsValidUploadKey/nar_plain1978=== CONT TestIsValidUploadKey/empty_key1979=== CONT TestIsValidUploadKey/build_log1980=== CONT TestIsValidUploadKey/nar_xz1981=== CONT TestIsValidUploadKey/nar_zst1982=== CONT TestIsValidUploadKey/listing1983=== CONT TestIsValidUploadKey/index.html1984=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1985=== CONT TestIsValidUploadKey/absolute1986=== CONT TestIsValidUploadKey/traversal_nar1987=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1988=== CONT TestIsValidUploadKey/nix-cache-info1989=== CONT TestIsValidUploadKey/traversal1990=== CONT TestIsValidUploadKey/realisation_plus_in_output1991=== CONT TestProxyWriteTimeout/1_GiB_nar1992=== CONT TestProxyWriteTimeout/unknown_size1993--- PASS: TestIsValidUploadKey (0.00s)1994 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1995 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1996 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1997 --- PASS: TestIsValidUploadKey/realisation (0.00s)1998 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1999 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)2000 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)2001 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)2002 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)2003 --- PASS: TestIsValidUploadKey/empty_key (0.00s)2004 --- PASS: TestIsValidUploadKey/build_log (0.00s)2005 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)2006 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)2007 --- PASS: TestIsValidUploadKey/listing (0.00s)2008 --- PASS: TestIsValidUploadKey/index.html (0.00s)2009 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)2010 --- PASS: TestIsValidUploadKey/absolute (0.00s)2011 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)2012 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)2013 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)2014 --- PASS: TestIsValidUploadKey/traversal (0.00s)2015 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)2016=== CONT TestProxyWriteTimeout/10_GiB_nar2017=== CONT TestProxyWriteTimeout/narinfo2018=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check2019--- PASS: TestProxyWriteTimeout (0.00s)2020 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)2021 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)2022 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)2023 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)2024--- PASS: TestService_ReadScope_PublicByDefault (2.51s)2025=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows2026--- PASS: TestReadProxyHead (2.79s)2027=== CONT TestGCEndsOnShutdown/before_the_run2028--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (2.25s)2029=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete2030--- PASS: TestService_Rustfstest (1.65s)2031=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark2032=== NAME TestClientCADerivations2033 client_ca_test.go:136: Built CA derivation: /nix/var/nix/builds/nix-25758-1034586924/TestClientCADerivations2275453093/001/store/3pl4by5g0kcnwv27wa8iw91qsckzamh6-ca-test2034 client_ca_test.go:139: Found 1 dependencies (including self)20352026/10/01 09:22:41 INFO Received push request method=POST path=/api/pushes20362026/10/01 09:22:41 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)20372026/10/01 09:22:41 INFO Uploading 3pl4by5g0kcnwv27wa8iw91qsckzamh6-ca-test (144B)20382026/10/01 09:22:41 WARN Failed to register uploaded object key=3pl4by5g0kcnwv27wa8iw91qsckzamh6.ls error="server returned 404: 404 page not found\n"20392026/10/01 09:22:41 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"20402026/10/01 09:22:41 INFO Received uploads request method=POST path=/api/pending_closures20412026/10/01 09:22:41 WARN Failed to register uploaded object key=log/35cl360b112kn7lf4a74q6wyxl82p5wm-ca-test.drv error="server returned 404: 404 page not found\n"20422026/10/01 09:22:41 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign20432026/10/01 09:22:41 INFO Signed narinfos id=1 count=120442026/10/01 09:22:41 INFO Uploading 1 narinfos20452026/10/01 09:22:41 INFO Received complete push request method=POST path=/api/pushes/1/complete20462026/10/01 09:22:41 WARN Failed to register uploaded object key=3pl4by5g0kcnwv27wa8iw91qsckzamh6.narinfo error="server returned 404: 404 page not found\n"20472026/10/01 09:22:41 INFO Upload complete. (195ms)2048 client_ca_test.go:180: Narinfo contains CA field: StorePath: /nix/var/nix/builds/nix-25758-1034586924/TestClientCADerivations2275453093/001/store/3pl4by5g0kcnwv27wa8iw91qsckzamh6-ca-test2049 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst2050 Compression: zstd2051 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2052 NarSize: 1442053 References: 2054 Deriver: /nix/var/nix/builds/nix-25758-1034586924/TestClientCADerivations2275453093/001/store/35cl360b112kn7lf4a74q6wyxl82p5wm-ca-test.drv2055 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2056 client_ca_test.go:185: Checking for realisation files in S3...2057 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations2058 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache2059 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket88?endpoint=http://localhost:63354®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/nix/var/nix/builds/nix-25758-1034586924/TestClientCADerivations2275453093/001/store'2060 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 12061=== NAME TestPinProtectsFromGC2062 client_integration_test.go:976: Pin successfully protected closure from garbage collection2063--- PASS: TestClientCADerivations (2.92s)2064=== CONT TestPush_RejectsBadRequests/no_objects20652026/10/01 09:22:42 INFO Received push request method=POST path=/api/pushes2066=== CONT TestPush_RejectsBadRequests/root_not_in_objects20672026/10/01 09:22:42 INFO Received push request method=POST path=/api/pushes2068=== CONT TestPush_RejectsBadRequests/bad_root20692026/10/01 09:22:42 INFO Received push request method=POST path=/api/pushes2070=== CONT TestPush_RejectsBadRequests/no_roots20712026/10/01 09:22:42 INFO Received push request method=POST path=/api/pushes2072=== CONT TestResolveDBConnectionString/missing_file_is_an_error2073=== CONT TestResolveDBConnectionString/nothing_configured2074=== CONT TestResolveDBConnectionString/file_when_flag_empty2075=== CONT TestResolveDBConnectionString/PGHOST_allows_empty2076=== CONT TestResolveDBConnectionString/flag_wins2077=== CONT TestClientErrorHandling/InvalidAuthToken2078--- PASS: TestResolveDBConnectionString (0.03s)2079 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)2080 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)2081 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)2082 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)2083 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)2084--- PASS: TestPinProtectsFromGC (7.33s)2085=== CONT TestClientErrorHandling/InvalidStorePath2086--- PASS: TestPush_RejectsBadRequests (1.91s)2087 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)2088 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)2089 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)2090 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)20912026/10/01 09:22:42 INFO Received uploads request method=POST path=/api/pending_closures20922026/10/01 09:22:42 INFO Aborted multipart uploads count=0 kept=020932026/10/01 09:22:42 WARN Force mode enabled - objects will be deleted immediately without grace period20942026/10/01 09:22:42 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=020952026/10/01 09:22:42 INFO Vacuumed table table=pending_closures20962026/10/01 09:22:42 INFO Vacuumed table table=pending_objects20972026/10/01 09:22:42 INFO Vacuumed table table=multipart_uploads20982026/10/01 09:22:42 INFO Vacuumed table table=closures20992026/10/01 09:22:42 INFO Vacuumed table table=objects2100=== CONT TestClientErrorHandling/ServerNotAvailable21012026/10/01 09:22:42 INFO Received uploads request method=POST path=/api/pending_closures21022026/10/01 09:22:42 INFO Aborted multipart uploads count=0 kept=021032026/10/01 09:22:42 WARN Force mode enabled - objects will be deleted immediately without grace period21042026/10/01 09:22:42 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=021052026/10/01 09:22:42 INFO Vacuumed table table=pending_closures21062026/10/01 09:22:42 INFO Vacuumed table table=pending_objects21072026/10/01 09:22:42 INFO Vacuumed table table=multipart_uploads21082026/10/01 09:22:42 INFO Vacuumed table table=closures21092026/10/01 09:22:42 INFO Vacuumed table table=objects21102026/10/01 09:22:42 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2111--- PASS: TestReadProxyOutlastsServerWriteTimeout (6.27s)2112=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2113=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected21142026/10/01 09:22:42 WARN Authentication failed token_preview=eyJhbGciOi...Uq9Wyehy0A token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2115=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected21162026/10/01 09:22:42 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]2117=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2118=== CONT TestService_RequireScope_OIDC/builder_may_write2119=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2120=== CONT TestService_RequireScope_OIDC/reader_may_read2121=== CONT TestService_RequireScope_OIDC/static_token_may_write2122=== CONT TestService_RequireScope_OIDC/writer_implies_read2123=== CONT TestService_RequireScope_OIDC/reader_may_not_write2124=== CONT TestService_RequireScope_OIDC/static_token_may_admin2125=== CONT TestService_RequireScope_OIDC/ops_may_admin2126=== CONT TestService_RequireScope_OIDC/ops_may_not_write2127=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2128=== CONT TestCacheConfigHandler/full_config,_no_issuer2129=== CONT TestCacheConfigHandler/no_cache_url_configured2130=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2131=== CONT TestCacheConfigHandler/no_signing_keys2132--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2133 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (1.66s)2134 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (1.80s)2135--- PASS: TestCacheConfigHandler (0.00s)2136 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)2137 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)2138 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)2139 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)2140--- PASS: TestService_RequireScope_OIDC (2.67s)2141 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2142 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2143 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2144 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2145 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2146 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2147 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2148 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2149 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2150 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)21512026/10/01 09:22:42 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=183.163199ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2152--- PASS: TestService_AuthMiddleware_OIDC (2.43s)2153 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2154 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)2155 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2156 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2157--- PASS: TestPendingClosureWriteTimeout (0.00s)2158 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2159 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2160 --- PASS: TestPendingClosureWriteTimeout/negative (0.00s)2161 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2162 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (2.13s)21632026/10/01 09:22:42 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=409.874925ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present21642026/10/01 09:22:42 INFO Aborted multipart uploads count=0 kept=021652026/10/01 09:22:42 WARN Force mode enabled - objects will be deleted immediately without grace period21662026/10/01 09:22:42 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:63354/bucket94/?delete=\": context canceled"21672026/10/01 09:22:43 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=810.313342ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present21682026/10/01 09:22:43 INFO Aborted multipart uploads count=0 kept=021692026/10/01 09:22:43 WARN Force mode enabled - objects will be deleted immediately without grace period21702026-10-01 09:22:43.362 UTC [26398] ERROR: canceling statement due to user request21712026-10-01 09:22:43.362 UTC [26398] STATEMENT: -- name: MarkStaleObjects :execrows2172 WITH RECURSIVE ct AS (2173 SELECT timezone('UTC', now()) AS now2174 ),2175 closure_reach AS (2176 -- Start with all closure keys2177 SELECT o.key, o.refs2178 FROM objects o2179 INNER JOIN closures c ON o.key = c.key2180 UNION2181 -- Recursively add all referenced objects2182 SELECT o.key, o.refs2183 FROM objects o2184 INNER JOIN closure_reach cr ON o.key = ANY(cr.refs)2185 ),2186 reachable_objects AS (2187 SELECT DISTINCT key FROM closure_reach2188 ),2189 stale_objects AS (2190 SELECT o.key2191 FROM objects AS o, ct2192 WHERE2193 NOT EXISTS (2194 SELECT 12195 FROM reachable_objects ro2196 WHERE ro.key = o.key2197 )2198 AND NOT EXISTS (2199 SELECT 12200 FROM pending_objects AS po2201 WHERE po.key = o.key2202 )2203 AND o.deleted_at IS NULL -- Only mark fresh objects2204 ORDER BY o.key COLLATE "C" -- lock in key order, like commit_pending_closure2205 FOR UPDATE2206 )2207 UPDATE objects2208 SET2209 deleted_at = ct.now,2210 first_deleted_at = COALESCE(first_deleted_at, ct.now)2211 FROM stale_objects, ct2212 WHERE objects.key = stale_objects.key2213 2214--- PASS: TestGCEndsOnShutdown (0.00s)2215 --- PASS: TestGCEndsOnShutdown/before_the_run (1.70s)2216 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (1.83s)2217 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (1.81s)22182026/10/01 09:22:43 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"22192026/10/01 09:22:43 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"22202026/10/01 09:22:44 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.672847911s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2221--- PASS: TestUploadHandlersRejectOversizedBody (0.05s)2222 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.29s)2223 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.27s)2224 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (4.39s)22252026/10/01 09:22:45 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22262026/10/01 09:22:45 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=213.334439ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22272026/10/01 09:22:46 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=383.170299ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22282026/10/01 09:22:46 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=872.838237ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22292026/10/01 09:22:47 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.522599568s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22302026/10/01 09:22:48 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: sending request: request failed after retries: Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused"22312026/10/01 09:22:48 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22322026/10/01 09:22:49 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=205.457459ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22332026/10/01 09:22:49 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=429.759128ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22342026/10/01 09:22:49 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=807.714165ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22352026/10/01 09:22:50 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.463889435s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22362026/10/01 09:22:51 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22372026/10/01 09:22:52 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=190.906603ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22382026/10/01 09:22:52 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=413.599186ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22392026/10/01 09:22:52 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=726.372847ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22402026/10/01 09:22:53 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.45488992s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2241--- PASS: TestClientErrorHandling (0.00s)2242 --- PASS: TestClientErrorHandling/InvalidStorePath (1.40s)2243 --- PASS: TestClientErrorHandling/InvalidAuthToken (1.58s)2244 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.62s)2245PASS2246{"timestamp":"2026-10-01T09:22:54.904321Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:63813","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2354,"threadName":"rustfs-worker","threadId":"ThreadId(3)"}22472026-10-01 09:22:55.048 UTC [25803] LOG: received smart shutdown request22482026-10-01 09:22:55.049 UTC [25803] LOG: background worker "logical replication launcher" (PID 25813) exited with exit code 122492026-10-01 09:22:55.057 UTC [25808] LOG: shutting down22502026-10-01 09:22:55.057 UTC [25808] LOG: checkpoint starting: shutdown immediate22512026-10-01 09:22:56.471 UTC [25808] LOG: checkpoint complete: wrote 12396 buffers (75.7%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 29 recycled; write=0.809 s, sync=0.567 s, total=1.414 s; sync files=33362, longest=0.001 s, average=0.001 s; distance=475059 kB, estimate=475059 kB; lsn=0/1E779DD0, redo lsn=0/1E779DD022522026-10-01 09:22:56.477 UTC [25803] LOG: database system is shut down2253Running OIDC tests...2254=== RUN TestAudienceForIssuer2255=== PAUSE TestAudienceForIssuer2256=== RUN TestHTTPClientForHasTimeouts2257=== PAUSE TestHTTPClientForHasTimeouts2258=== RUN TestGlobMatch2259=== PAUSE TestGlobMatch2260=== RUN TestValidateToken_ValidToken2261=== PAUSE TestValidateToken_ValidToken2262=== RUN TestValidateToken_WrongAudience2263=== PAUSE TestValidateToken_WrongAudience2264=== RUN TestValidateToken_Expired2265=== PAUSE TestValidateToken_Expired2266=== RUN TestValidateToken_BoundClaimsMismatch2267=== PAUSE TestValidateToken_BoundClaimsMismatch2268=== RUN TestValidateToken_BoundSubjectMismatch2269=== PAUSE TestValidateToken_BoundSubjectMismatch2270=== RUN TestValidateToken_MultipleProviders2271=== PAUSE TestValidateToken_MultipleProviders2272=== RUN TestValidateToken_NoMatchingProvider2273=== PAUSE TestValidateToken_NoMatchingProvider2274=== RUN TestValidateToken_KubernetesServiceAccount2275=== PAUSE TestValidateToken_KubernetesServiceAccount2276=== RUN TestNewValidator_KubernetesRequiresCA2277=== PAUSE TestNewValidator_KubernetesRequiresCA2278=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2279=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2280=== RUN TestPins_ReservedForMatchingRule2281=== PAUSE TestPins_ReservedForMatchingRule2282=== RUN TestPins_TopLevelShorthand2283=== PAUSE TestPins_TopLevelShorthand2284=== RUN TestPins_ConfigValidation2285=== PAUSE TestPins_ConfigValidation2286=== RUN TestScopes_LegacyProviderDefaultsToWrite2287=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2288=== RUN TestScopes_Rules2289=== PAUSE TestScopes_Rules2290=== RUN TestScopes_ConfigValidation2291=== PAUSE TestScopes_ConfigValidation2292=== CONT TestAudienceForIssuer2293=== CONT TestNewValidator_KubernetesRequiresCA2294--- PASS: TestAudienceForIssuer (0.00s)2295=== CONT TestValidateToken_BoundClaimsMismatch2296=== CONT TestValidateToken_NoMatchingProvider2297=== CONT TestScopes_ConfigValidation2298=== CONT TestValidateToken_WrongAudience2299=== CONT TestScopes_LegacyProviderDefaultsToWrite2300=== CONT TestScopes_Rules2301=== CONT TestPins_ReservedForMatchingRule2302=== CONT TestValidateToken_KubernetesServiceAccount2303=== CONT TestValidateToken_MultipleProviders2304--- PASS: TestScopes_ConfigValidation (0.01s)2305=== CONT TestValidateToken_BoundSubjectMismatch23062026/10/01 09:22:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:64067/oidc2307--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.05s)2308=== CONT TestPins_ConfigValidation2309--- PASS: TestPins_ConfigValidation (0.00s)2310=== CONT TestPins_TopLevelShorthand23112026/10/01 09:22:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:64069/oidc2312--- PASS: TestPins_ReservedForMatchingRule (0.07s)2313=== CONT TestValidateToken_Expired23142026/10/01 09:22:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:64072/oidc23152026/10/01 09:22:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:64074/oidc2316--- PASS: TestValidateToken_BoundSubjectMismatch (0.13s)2317=== CONT TestValidateToken_ValidToken2318--- PASS: TestScopes_Rules (0.14s)2319=== CONT TestHTTPClientForHasTimeouts23202026/10/01 09:22:59 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:64071/oidc23212026/10/01 09:22:59 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:64079/oidc2322--- PASS: TestValidateToken_MultipleProviders (0.16s)2323=== CONT TestGlobMatch2324=== RUN TestGlobMatch/foo_foo2325=== PAUSE TestGlobMatch/foo_foo2326=== RUN TestGlobMatch/foo_bar2327=== PAUSE TestGlobMatch/foo_bar2328=== RUN TestGlobMatch/*_2329=== PAUSE TestGlobMatch/*_2330=== RUN TestGlobMatch/*_anything2331=== PAUSE TestGlobMatch/*_anything2332=== RUN TestGlobMatch/foo*_foo2333=== PAUSE TestGlobMatch/foo*_foo2334=== RUN TestGlobMatch/foo*_foobar2335=== PAUSE TestGlobMatch/foo*_foobar2336=== RUN TestGlobMatch/foo*_bar2337=== PAUSE TestGlobMatch/foo*_bar2338=== RUN TestGlobMatch/*bar_bar2339=== PAUSE TestGlobMatch/*bar_bar2340=== RUN TestGlobMatch/*bar_foobar2341=== PAUSE TestGlobMatch/*bar_foobar2342=== RUN TestGlobMatch/*bar_foo2343=== PAUSE TestGlobMatch/*bar_foo2344=== RUN TestGlobMatch/foo*bar_foobar2345=== PAUSE TestGlobMatch/foo*bar_foobar2346=== RUN TestGlobMatch/foo*bar_foo123bar2347=== PAUSE TestGlobMatch/foo*bar_foo123bar2348=== RUN TestGlobMatch/foo*bar_foobarbaz2349=== PAUSE TestGlobMatch/foo*bar_foobarbaz2350=== RUN TestGlobMatch/*/*_foo/bar2351=== PAUSE TestGlobMatch/*/*_foo/bar2352=== RUN TestGlobMatch/*/*_foo2353=== PAUSE TestGlobMatch/*/*_foo2354=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2355=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2356=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02357=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02358=== RUN TestGlobMatch/refs/*/main_refs/heads/main2359=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2360=== RUN TestGlobMatch/fo?_foo2361=== PAUSE TestGlobMatch/fo?_foo2362=== RUN TestGlobMatch/fo?_fo2363=== PAUSE TestGlobMatch/fo?_fo2364=== RUN TestGlobMatch/fo?_fooo2365=== PAUSE TestGlobMatch/fo?_fooo2366=== RUN TestGlobMatch/?oo_foo2367=== PAUSE TestGlobMatch/?oo_foo2368=== RUN TestGlobMatch/?oo_boo2369=== PAUSE TestGlobMatch/?oo_boo2370=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2371=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2372=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2373=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2374=== CONT TestValidateToken_KubernetesIssuerFromOwnToken23752026/10/01 09:22:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:64084/oidc2376--- PASS: TestValidateToken_BoundClaimsMismatch (0.19s)2377=== CONT TestGlobMatch/foo_foo2378=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2379=== CONT TestGlobMatch/*/*_foo/bar2380=== CONT TestGlobMatch/?oo_boo2381=== CONT TestGlobMatch/?oo_foo2382=== CONT TestGlobMatch/fo?_fooo2383=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2384=== CONT TestGlobMatch/fo?_fo2385=== CONT TestGlobMatch/refs/*/main_refs/heads/main2386=== CONT TestGlobMatch/fo?_foo2387=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2388=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02389=== CONT TestGlobMatch/*/*_foo2390=== CONT TestGlobMatch/foo*bar_foobarbaz2391=== CONT TestGlobMatch/foo*_bar2392=== CONT TestGlobMatch/foo*bar_foo123bar2393=== CONT TestGlobMatch/foo*bar_foobar2394=== CONT TestGlobMatch/*bar_foo2395=== CONT TestGlobMatch/*bar_foobar2396=== CONT TestGlobMatch/*bar_bar2397=== CONT TestGlobMatch/*_anything2398=== CONT TestGlobMatch/foo*_foo2399=== CONT TestGlobMatch/foo*_foobar2400=== CONT TestGlobMatch/*_2401=== CONT TestGlobMatch/foo_bar2402--- PASS: TestGlobMatch (0.00s)2403 --- PASS: TestGlobMatch/foo_foo (0.00s)2404 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2405 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2406 --- PASS: TestGlobMatch/?oo_boo (0.00s)2407 --- PASS: TestGlobMatch/?oo_foo (0.00s)2408 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2409 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2410 --- PASS: TestGlobMatch/fo?_fo (0.00s)2411 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2412 --- PASS: TestGlobMatch/fo?_foo (0.00s)2413 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2414 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2415 --- PASS: TestGlobMatch/*/*_foo (0.00s)2416 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2417 --- PASS: TestGlobMatch/foo*_bar (0.00s)2418 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2419 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2420 --- PASS: TestGlobMatch/*bar_foo (0.00s)2421 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2422 --- PASS: TestGlobMatch/*bar_bar (0.00s)2423 --- PASS: TestGlobMatch/*_anything (0.00s)2424 --- PASS: TestGlobMatch/foo*_foo (0.00s)2425 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2426 --- PASS: TestGlobMatch/*_ (0.00s)2427 --- PASS: TestGlobMatch/foo_bar (0.00s)24282026/10/01 09:22:59 http: TLS handshake error from 127.0.0.1:64083: remote error: tls: bad certificate2429--- PASS: TestNewValidator_KubernetesRequiresCA (0.19s)24302026/10/01 09:22:59 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:64078/oidc2431--- PASS: TestValidateToken_NoMatchingProvider (0.19s)24322026/10/01 09:22:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:64088/oidc2433--- PASS: TestValidateToken_Expired (0.13s)24342026/10/01 09:22:59 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:640902435--- PASS: TestValidateToken_KubernetesServiceAccount (0.22s)24362026/10/01 09:22:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:64092/oidc2437--- PASS: TestValidateToken_ValidToken (0.10s)24382026/10/01 09:22:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:64094/oidc2439--- PASS: TestValidateToken_WrongAudience (0.24s)24402026/10/01 09:22:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:64096/oidc2441--- PASS: TestPins_TopLevelShorthand (0.20s)24422026/10/01 09:22:59 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232443--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.15s)2444--- PASS: TestHTTPClientForHasTimeouts (0.20s)2445PASS2446Running signing tests...2447=== RUN TestGenerateFingerprint2448=== PAUSE TestGenerateFingerprint2449=== RUN TestParseSigningKey2450=== PAUSE TestParseSigningKey2451=== RUN TestSignMessage2452=== PAUSE TestSignMessage2453=== RUN TestSignNarinfo2454=== PAUSE TestSignNarinfo2455=== CONT TestGenerateFingerprint2456=== CONT TestSignMessage2457=== CONT TestParseSigningKey2458=== CONT TestSignNarinfo2459=== RUN TestGenerateFingerprint/basic_with_references2460=== RUN TestParseSigningKey/valid_32-byte_key2461=== PAUSE TestGenerateFingerprint/basic_with_references2462=== PAUSE TestParseSigningKey/valid_32-byte_key2463=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2464=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2465=== RUN TestGenerateFingerprint/no_references2466=== RUN TestParseSigningKey/no_colon2467=== PAUSE TestGenerateFingerprint/no_references2468=== PAUSE TestParseSigningKey/no_colon2469=== RUN TestParseSigningKey/empty_name2470=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2471=== PAUSE TestParseSigningKey/empty_name2472=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2473=== RUN TestParseSigningKey/invalid_base642474=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2475=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2476=== PAUSE TestParseSigningKey/invalid_base642477=== RUN TestParseSigningKey/wrong_length2478=== PAUSE TestParseSigningKey/wrong_length2479=== RUN TestGenerateFingerprint/invalid_nar_hash_length2480=== CONT TestParseSigningKey/valid_32-byte_key2481=== CONT TestParseSigningKey/no_colon2482=== CONT TestParseSigningKey/invalid_base642483=== CONT TestParseSigningKey/wrong_length2484=== CONT TestParseSigningKey/empty_name2485=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2486=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2487=== RUN TestGenerateFingerprint/invalid_store_path_prefix2488=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2489=== RUN TestGenerateFingerprint/invalid_reference_prefix2490=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2491=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2492=== CONT TestGenerateFingerprint/no_references2493=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2494=== CONT TestGenerateFingerprint/invalid_store_path_prefix2495=== CONT TestGenerateFingerprint/basic_with_references2496=== CONT TestGenerateFingerprint/invalid_reference_prefix2497=== CONT TestGenerateFingerprint/invalid_nar_hash_length2498--- PASS: TestGenerateFingerprint (0.00s)2499 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2500 --- PASS: TestGenerateFingerprint/no_references (0.00s)2501 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2502 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2503 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2504 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2505 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2506--- PASS: TestParseSigningKey (0.00s)2507 --- PASS: TestParseSigningKey/no_colon (0.00s)2508 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2509 --- PASS: TestParseSigningKey/wrong_length (0.00s)2510 --- PASS: TestParseSigningKey/empty_name (0.00s)2511 --- PASS: TestParseSigningKey/valid_32-byte_key (0.01s)2512 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.01s)2513--- PASS: TestSignMessage (0.01s)2514--- PASS: TestSignNarinfo (0.01s)2515PASS2516Running hook tests...2517=== RUN TestSendPathsEmpty2518=== PAUSE TestSendPathsEmpty2519=== RUN TestQueueEnqueueAndFetch2520=== PAUSE TestQueueEnqueueAndFetch2521=== RUN TestQueueDeduplication2522=== PAUSE TestQueueDeduplication2523=== RUN TestQueueRemove2524=== PAUSE TestQueueRemove2525=== RUN TestQueueFetchBatchLimit2526=== PAUSE TestQueueFetchBatchLimit2527=== RUN TestQueueRetryMovesToBack2528=== PAUSE TestQueueRetryMovesToBack2529=== RUN TestQueueFetchRemoveLifecycle2530=== PAUSE TestQueueFetchRemoveLifecycle2531=== RUN TestQueueConcurrentWriters2532=== PAUSE TestQueueConcurrentWriters2533=== RUN TestQueueEnqueueWaitsOutSlowWriter2534=== PAUSE TestQueueEnqueueWaitsOutSlowWriter2535=== RUN TestQueueRemoveLargeClosure2536=== PAUSE TestQueueRemoveLargeClosure2537=== RUN TestServerClientIntegration2538=== PAUSE TestServerClientIntegration2539=== RUN TestServerQueueError2540=== PAUSE TestServerQueueError2541=== RUN TestServerRefusesOversizedAndNonStoreRequests2542=== PAUSE TestServerRefusesOversizedAndNonStoreRequests2543=== RUN TestGetListenerSocketActivation2544 server_test.go:317: === RUN TestGetListenerSocketActivation2545 --- PASS: TestGetListenerSocketActivation (0.00s)2546 PASS2547 2548--- PASS: TestGetListenerSocketActivation (1.18s)2549=== RUN TestServerStalledClientDoesNotBlockShutdown2550=== PAUSE TestServerStalledClientDoesNotBlockShutdown2551=== RUN TestServerBacksOffOnAcceptErrors2552=== PAUSE TestServerBacksOffOnAcceptErrors2553=== RUN TestDrainIsolatesPoisonPath2554=== PAUSE TestDrainIsolatesPoisonPath2555=== RUN TestRunNotBlockedByPoisonHead2556=== PAUSE TestRunNotBlockedByPoisonHead2557=== RUN TestDrainGivesUpWhenServerDown2558=== PAUSE TestDrainGivesUpWhenServerDown2559=== RUN TestFailedPathPrunedByLaterClosure2560=== PAUSE TestFailedPathPrunedByLaterClosure2561=== RUN TestWorkerUploadsAndRemoves2562=== PAUSE TestWorkerUploadsAndRemoves2563=== RUN TestWorkerSkipsGCdPaths2564=== PAUSE TestWorkerSkipsGCdPaths2565=== RUN TestWorkerPrunesClosureDeps2566=== PAUSE TestWorkerPrunesClosureDeps2567=== RUN TestWorkerRemovesCachedPathBatchedWithLargerClosure2568=== PAUSE TestWorkerRemovesCachedPathBatchedWithLargerClosure2569=== RUN TestDrainTimeout2570=== PAUSE TestDrainTimeout2571=== RUN TestDrainTimeoutDuringIsolation2572=== PAUSE TestDrainTimeoutDuringIsolation2573=== RUN TestShutdownFinishesInFlightPush2574=== PAUSE TestShutdownFinishesInFlightPush2575=== RUN TestWorkerRemoveFailureIsNotProgress2576=== PAUSE TestWorkerRemoveFailureIsNotProgress2577=== RUN TestWorkerKeepsPathItCannotStat2578=== PAUSE TestWorkerKeepsPathItCannotStat2579=== CONT TestServerBacksOffOnAcceptErrors2580=== CONT TestQueueEnqueueAndFetch2581=== CONT TestDrainTimeout2582=== CONT TestQueueFetchRemoveLifecycle2583=== CONT TestShutdownFinishesInFlightPush2584=== CONT TestServerQueueError2585=== CONT TestServerStalledClientDoesNotBlockShutdown25862026/10/01 09:23:03 ERROR Accept failed error="too many open files"2587=== CONT TestServerRefusesOversizedAndNonStoreRequests2588=== CONT TestWorkerKeepsPathItCannotStat2589=== CONT TestQueueRemoveLargeClosure2590=== RUN TestShutdownFinishesInFlightPush/completes2591=== PAUSE TestShutdownFinishesInFlightPush/completes2592=== RUN TestShutdownFinishesInFlightPush/hung_push_bounded_by_the_drain_timeout2593=== PAUSE TestShutdownFinishesInFlightPush/hung_push_bounded_by_the_drain_timeout2594=== CONT TestWorkerRemoveFailureIsNotProgress2595=== RUN TestWorkerRemoveFailureIsNotProgress/collected_path25962026/10/01 09:23:03 ERROR Refusing path outside the store path=/etc/shadow store=/nix/store25972026/10/01 09:23:03 ERROR Failed to queue paths error="permission denied" count=12598=== PAUSE TestWorkerRemoveFailureIsNotProgress/collected_path2599=== RUN TestWorkerRemoveFailureIsNotProgress/pushed_batch2600=== PAUSE TestWorkerRemoveFailureIsNotProgress/pushed_batch2601=== RUN TestWorkerRemoveFailureIsNotProgress/isolated_paths2602=== PAUSE TestWorkerRemoveFailureIsNotProgress/isolated_paths2603=== CONT TestDrainGivesUpWhenServerDown26042026/10/01 09:23:03 ERROR Refusing path outside the store path=/nix/store store=/nix/store2605--- PASS: TestServerQueueError (0.01s)2606=== CONT TestWorkerUploadsAndRemoves26072026/10/01 09:23:03 ERROR Accept failed error="too many open files"26082026/10/01 09:23:03 ERROR Refusing path outside the store path=/nix/store/ store=/nix/store26092026/10/01 09:23:03 ERROR Refusing path outside the store path=/nix/store/../../etc/shadow store=/nix/store26102026/10/01 09:23:03 ERROR Refusing path outside the store path=/nix/store/0123456789abcdfghijklmnpqrsvwxyz-hello/bin/sh store=/nix/store26112026/10/01 09:23:03 ERROR Refusing path outside the store path=nix/store/0123456789abcdfghijklmnpqrsvwxyz-hello store=/nix/store26122026/10/01 09:23:03 ERROR Refusing path outside the store path=/nix/storeX/0123456789abcdfghijklmnpqrsvwxyz-hello store=/nix/store26132026/10/01 09:23:03 ERROR Refusing path outside the store path=/nix/store/.links store=/nix/store26142026/10/01 09:23:03 ERROR Refusing path outside the store path=/nix/store/aaa-hello store=/nix/store26152026/10/01 09:23:03 ERROR Refusing path outside the store path=/nix/store/0123456789abcdfghijklmnpqrsvwxyz store=/nix/store26162026/10/01 09:23:03 ERROR Refusing path outside the store path=/nix/store/0123456789abcdfghijklmnpqrsvwxyz- store=/nix/store26172026/10/01 09:23:03 ERROR Refusing path outside the store path=/nix/store/0123456789ebcdfghijklmnpqrsvwxyz-hello store=/nix/store26182026/10/01 09:23:03 ERROR Refusing path outside the store path="/nix/store/0123456789abcdfghijklmnpqrsvwxyz-hel\x00lo" store=/nix/store26192026/10/01 09:23:03 ERROR Refusing path outside the store path=/nix/store/0123456789abcdfghijklmnpqrsvwxyz-hel/lo store=/nix/store26202026/10/01 09:23:03 ERROR Refusing path outside the store path=/nix/store/0123456789abcdfghijklmnpqrsvwxyz-xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx store=/nix/store26212026/10/01 09:23:03 ERROR Failed to decode request error="unexpected EOF"2622=== CONT TestWorkerSkipsGCdPaths2623--- PASS: TestServerRefusesOversizedAndNonStoreRequests (0.01s)26242026/10/01 09:23:03 ERROR Accept failed error="too many open files"26252026/10/01 09:23:03 INFO Upload queue status pending=226262026/10/01 09:23:03 INFO Uploading batch count=226272026/10/01 09:23:03 WARN Cannot stat store path, will retry later path=/nix/var/nix/builds/nix-25758-1034586924/TestWorkerKeepsPathItCannotStat3315556472/002/locked/aaa error="lstat /nix/var/nix/builds/nix-25758-1034586924/TestWorkerKeepsPathItCannotStat3315556472/002/locked/aaa: permission denied"26282026/10/01 09:23:03 INFO Uploading batch count=22629--- PASS: TestQueueEnqueueAndFetch (0.03s)2630=== CONT TestFailedPathPrunedByLaterClosure26312026/10/01 09:23:03 WARN Cannot stat store path, will retry later path=/nix/var/nix/builds/nix-25758-1034586924/TestWorkerKeepsPathItCannotStat3315556472/002/locked/aaa error="lstat /nix/var/nix/builds/nix-25758-1034586924/TestWorkerKeepsPathItCannotStat3315556472/002/locked/aaa: permission denied"26322026/10/01 09:23:03 INFO Uploading batch count=226332026/10/01 09:23:03 ERROR Upload failed error="upload failed" count=226342026/10/01 09:23:03 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-25758-1034586924/TestDrainGivesUpWhenServerDown299000399/002/a26352026/10/01 09:23:03 INFO Upload queue status pending=326362026/10/01 09:23:03 WARN Store path no longer exists (garbage collected?), removing from queue path=/nix/var/nix/builds/nix-25758-1034586924/TestWorkerSkipsGCdPaths1234844774/002/nonexistent2637--- PASS: TestQueueFetchRemoveLifecycle (0.03s)2638=== CONT TestQueueEnqueueWaitsOutSlowWriter26392026/10/01 09:23:03 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-25758-1034586924/TestDrainGivesUpWhenServerDown299000399/002/b26402026/10/01 09:23:03 WARN Cannot stat store path, will retry later path=/nix/var/nix/builds/nix-25758-1034586924/TestWorkerKeepsPathItCannotStat3315556472/002/locked/aaa error="lstat /nix/var/nix/builds/nix-25758-1034586924/TestWorkerKeepsPathItCannotStat3315556472/002/locked/aaa: permission denied"26412026/10/01 09:23:03 INFO Uploading batch count=226422026/10/01 09:23:03 ERROR Drain finished with paths left in queue remaining=126432026/10/01 09:23:03 INFO Uploading batch count=226442026/10/01 09:23:03 ERROR Upload failed error="upload failed" count=226452026/10/01 09:23:03 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-25758-1034586924/TestDrainGivesUpWhenServerDown299000399/002/c26462026/10/01 09:23:03 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-25758-1034586924/TestDrainGivesUpWhenServerDown299000399/002/d2647--- PASS: TestWorkerKeepsPathItCannotStat (0.03s)2648=== CONT TestQueueConcurrentWriters26492026/10/01 09:23:03 INFO Uploading batch count=226502026/10/01 09:23:03 ERROR Upload failed error="upload failed" count=226512026/10/01 09:23:03 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-25758-1034586924/TestDrainGivesUpWhenServerDown299000399/002/e26522026/10/01 09:23:03 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-25758-1034586924/TestDrainGivesUpWhenServerDown299000399/002/f26532026/10/01 09:23:03 INFO Uploading batch count=126542026/10/01 09:23:03 ERROR Upload failed error="upload failed" count=126552026/10/01 09:23:03 ERROR Drain finished with paths left in queue remaining=1026562026/10/01 09:23:03 INFO Uploading batch count=126572026/10/01 09:23:03 ERROR Accept failed error="too many open files"26582026/10/01 09:23:03 INFO Uploading batch count=12659--- PASS: TestDrainGivesUpWhenServerDown (0.03s)2660=== CONT TestQueueRetryMovesToBack2661--- PASS: TestFailedPathPrunedByLaterClosure (0.01s)2662=== CONT TestQueueFetchBatchLimit2663--- PASS: TestWorkerUploadsAndRemoves (0.04s)2664=== CONT TestQueueDeduplication2665=== CONT TestQueueRemove2666--- PASS: TestQueueRetryMovesToBack (0.01s)2667--- PASS: TestQueueFetchBatchLimit (0.01s)2668=== CONT TestWorkerPrunesClosureDeps2669--- PASS: TestWorkerSkipsGCdPaths (0.03s)2670=== CONT TestServerClientIntegration2671=== CONT TestDrainIsolatesPoisonPath2672--- PASS: TestServerClientIntegration (0.00s)2673--- PASS: TestQueueDeduplication (0.01s)2674=== CONT TestRunNotBlockedByPoisonHead26752026/10/01 09:23:03 INFO Upload queue status pending=22676--- PASS: TestQueueRemove (0.01s)2677=== CONT TestDrainTimeoutDuringIsolation2678=== RUN TestDrainTimeoutDuringIsolation/probe_cut_short2679=== PAUSE TestDrainTimeoutDuringIsolation/probe_cut_short2680=== RUN TestDrainTimeoutDuringIsolation/probe_outlasts_the_deadline2681=== PAUSE TestDrainTimeoutDuringIsolation/probe_outlasts_the_deadline2682=== CONT TestSendPathsEmpty2683--- PASS: TestSendPathsEmpty (0.00s)2684=== CONT TestWorkerRemovesCachedPathBatchedWithLargerClosure26852026/10/01 09:23:03 INFO Uploading batch count=126862026/10/01 09:23:03 INFO Uploading batch count=426872026/10/01 09:23:03 ERROR Upload failed error="upload failed" count=426882026/10/01 09:23:03 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-25758-1034586924/TestDrainIsolatesPoisonPath1687337464/002/bbb26892026/10/01 09:23:03 INFO Upload queue status pending=326902026/10/01 09:23:03 INFO Uploading batch count=126912026/10/01 09:23:03 ERROR Upload failed error="upload failed" count=126922026/10/01 09:23:03 INFO Uploading batch count=126932026/10/01 09:23:03 ERROR Upload failed error="upload failed" count=126942026/10/01 09:23:03 INFO Uploading batch count=126952026/10/01 09:23:03 ERROR Upload failed error="upload failed" count=126962026/10/01 09:23:03 INFO Upload queue status pending=226972026/10/01 09:23:03 INFO Uploading batch count=226982026/10/01 09:23:03 INFO Uploading batch count=126992026/10/01 09:23:03 ERROR Upload failed error="upload failed" count=127002026/10/01 09:23:03 ERROR Drain finished with paths left in queue remaining=12701--- PASS: TestDrainIsolatesPoisonPath (0.01s)2702=== CONT TestShutdownFinishesInFlightPush/hung_push_bounded_by_the_drain_timeout27032026/10/01 09:23:03 INFO Upload queue status pending=227042026/10/01 09:23:03 INFO Uploading batch count=227052026/10/01 09:23:03 ERROR Accept failed error="too many open files"2706--- PASS: TestWorkerPrunesClosureDeps (0.03s)2707=== CONT TestShutdownFinishesInFlightPush/completes27082026/10/01 09:23:03 INFO Upload queue status pending=227092026/10/01 09:23:03 INFO Uploading batch count=22710--- PASS: TestWorkerRemovesCachedPathBatchedWithLargerClosure (0.03s)2711=== CONT TestWorkerRemoveFailureIsNotProgress/collected_path27122026/10/01 09:23:03 WARN Store path no longer exists (garbage collected?), removing from queue path=/nix/var/nix/builds/nix-25758-1034586924/TestWorkerRemoveFailureIsNotProgresscollected_path2173724431/001/nonexistent27132026/10/01 09:23:03 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=127142026/10/01 09:23:03 WARN Store path no longer exists (garbage collected?), removing from queue path=/nix/var/nix/builds/nix-25758-1034586924/TestWorkerRemoveFailureIsNotProgresscollected_path2173724431/001/nonexistent27152026/10/01 09:23:03 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=127162026/10/01 09:23:03 WARN Store path no longer exists (garbage collected?), removing from queue path=/nix/var/nix/builds/nix-25758-1034586924/TestWorkerRemoveFailureIsNotProgresscollected_path2173724431/001/nonexistent27172026/10/01 09:23:03 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=127182026/10/01 09:23:03 ERROR Drain finished with paths left in queue remaining=12719=== CONT TestWorkerRemoveFailureIsNotProgress/isolated_paths27202026/10/01 09:23:03 INFO Uploading batch count=227212026/10/01 09:23:03 ERROR Upload failed error="upload failed" count=227222026/10/01 09:23:03 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=127232026/10/01 09:23:03 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=127242026/10/01 09:23:03 INFO Uploading batch count=227252026/10/01 09:23:03 ERROR Upload failed error="upload failed" count=227262026/10/01 09:23:03 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=127272026/10/01 09:23:03 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=127282026/10/01 09:23:03 INFO Uploading batch count=227292026/10/01 09:23:03 ERROR Upload failed error="upload failed" count=227302026/10/01 09:23:03 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=127312026/10/01 09:23:03 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=127322026/10/01 09:23:03 ERROR Drain finished with paths left in queue remaining=22733=== CONT TestWorkerRemoveFailureIsNotProgress/pushed_batch27342026/10/01 09:23:03 INFO Uploading batch count=227352026/10/01 09:23:03 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=227362026/10/01 09:23:03 INFO Uploading batch count=227372026/10/01 09:23:03 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=227382026/10/01 09:23:03 INFO Uploading batch count=227392026/10/01 09:23:03 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=227402026/10/01 09:23:03 ERROR Drain finished with paths left in queue remaining=22741=== CONT TestDrainTimeoutDuringIsolation/probe_outlasts_the_deadline2742--- PASS: TestWorkerRemoveFailureIsNotProgress (0.00s)2743 --- PASS: TestWorkerRemoveFailureIsNotProgress/collected_path (0.01s)2744 --- PASS: TestWorkerRemoveFailureIsNotProgress/isolated_paths (0.01s)2745 --- PASS: TestWorkerRemoveFailureIsNotProgress/pushed_batch (0.01s)27462026/10/01 09:23:03 INFO Uploading batch count=427472026/10/01 09:23:03 ERROR Upload failed error="upload failed" count=427482026/10/01 09:23:03 ERROR Accept failed error="too many open files"2749--- PASS: TestQueueConcurrentWriters (0.14s)2750=== CONT TestDrainTimeoutDuringIsolation/probe_cut_short27512026/10/01 09:23:03 INFO Uploading batch count=427522026/10/01 09:23:03 ERROR Upload failed error="upload failed" count=427532026/10/01 09:23:03 ERROR Failed to decode request error="read unix /nix/var/nix/builds/nix-25758-1034586924/hook1527569680/test.sock->: i/o timeout"27542026/10/01 09:23:03 ERROR Failed to write response error="write unix /nix/var/nix/builds/nix-25758-1034586924/hook1527569680/test.sock->: i/o timeout"2755--- PASS: TestServerStalledClientDoesNotBlockShutdown (0.20s)27562026/10/01 09:23:03 ERROR Upload failed error="context canceled" count=227572026/10/01 09:23:03 ERROR Drain finished with paths left in queue remaining=42758--- PASS: TestDrainTimeout (0.23s)27592026/10/01 09:23:03 ERROR Upload failed error="context canceled" count=227602026/10/01 09:23:03 ERROR Drain finished with paths left in queue remaining=22761--- PASS: TestShutdownFinishesInFlightPush (0.00s)2762 --- PASS: TestShutdownFinishesInFlightPush/completes (0.11s)2763 --- PASS: TestShutdownFinishesInFlightPush/hung_push_bounded_by_the_drain_timeout (0.21s)27642026/10/01 09:23:03 ERROR Accept failed error="too many open files"27652026/10/01 09:23:04 ERROR Drain finished with paths left in queue remaining=427662026/10/01 09:23:04 ERROR Drain finished with paths left in queue remaining=32767--- PASS: TestDrainTimeoutDuringIsolation (0.00s)2768 --- PASS: TestDrainTimeoutDuringIsolation/probe_cut_short (0.21s)2769 --- PASS: TestDrainTimeoutDuringIsolation/probe_outlasts_the_deadline (0.31s)27702026/10/01 09:23:04 ERROR Accept failed error="too many open files"2771--- PASS: TestServerBacksOffOnAcceptErrors (0.64s)27722026/10/01 09:23:04 INFO Uploading batch count=127732026/10/01 09:23:04 INFO Uploading batch count=127742026/10/01 09:23:04 INFO Uploading batch count=127752026/10/01 09:23:04 ERROR Upload failed error="upload failed" count=127762026/10/01 09:23:04 INFO Uploading batch count=127772026/10/01 09:23:04 ERROR Upload failed error="upload failed" count=127782026/10/01 09:23:04 INFO Uploading batch count=127792026/10/01 09:23:04 ERROR Upload failed error="upload failed" count=127802026/10/01 09:23:04 INFO Uploading batch count=127812026/10/01 09:23:04 ERROR Upload failed error="upload failed" count=127822026/10/01 09:23:04 ERROR Drain finished with paths left in queue remaining=12783--- PASS: TestRunNotBlockedByPoisonHead (1.04s)2784--- PASS: TestQueueRemoveLargeClosure (1.16s)2785--- PASS: TestQueueEnqueueWaitsOutSlowWriter (6.01s)2786PASS2787Running niks3-hook command tests...2788=== RUN TestServeSecondSignalEndsDrain2789=== PAUSE TestServeSecondSignalEndsDrain2790=== RUN TestServeThenDrainPushesSendAcceptedBeforeShutdown2791=== PAUSE TestServeThenDrainPushesSendAcceptedBeforeShutdown2792=== CONT TestServeSecondSignalEndsDrain2793=== CONT TestServeThenDrainPushesSendAcceptedBeforeShutdown2794--- PASS: TestServeSecondSignalEndsDrain (0.07s)27952026/10/01 09:23:11 INFO Upload queue status pending=127962026/10/01 09:23:11 INFO Uploading batch count=12797--- PASS: TestServeThenDrainPushesSendAcceptedBeforeShutdown (0.12s)2798PASS2799Running rate limiter tests...2800=== RUN TestAdaptiveRateLimiter_ThreadSafety2801=== PAUSE TestAdaptiveRateLimiter_ThreadSafety2802=== CONT TestAdaptiveRateLimiter_ThreadSafety28032026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=112.7357000000000728042026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=78.9149900000000528052026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=55.2404930000000328062026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=38.6683451000000228072026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=27.0678415700000128082026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=18.94748909900000628092026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=13.26324236930000428102026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=9.28426965851000228112026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=6.49898876095700128122026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528132026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528142026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528152026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528162026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528172026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528182026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528192026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528202026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528212026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528222026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528232026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528242026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528252026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528262026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528272026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528282026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528292026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528302026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528312026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528322026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528332026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528342026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528352026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528362026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528372026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528382026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528392026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528402026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528412026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528422026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528432026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528442026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528452026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=5.12435000000000128462026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528472026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528482026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528492026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528502026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528512026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528522026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528532026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528542026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528552026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528562026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528572026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528582026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528592026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528602026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528612026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528622026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528632026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528642026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528652026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528662026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528672026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528682026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528692026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528702026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528712026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528722026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528732026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528742026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528752026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528762026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528772026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528782026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528792026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528802026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528812026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528822026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528832026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528842026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=12.0829492503758628852026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=8.45806447526310228862026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=5.92064513268417128872026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528882026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=6.82050985000000228892026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528902026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528912026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528922026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528932026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528942026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=5.63678500000000128952026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528962026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528972026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528982026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=528992026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=529002026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=529012026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=529022026/10/01 09:23:12 WARN Rate limiter backed off name=test rate=52903--- PASS: TestAdaptiveRateLimiter_ThreadSafety (0.10s)2904PASS