niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #398
· raw
1tribuchet: building on mac022Running client tests...3=== RUN TestDoServerRequestAttachesToken4=== PAUSE TestDoServerRequestAttachesToken5=== RUN TestRegisterUploadedObjectReusesConnections6=== PAUSE TestRegisterUploadedObjectReusesConnections7=== RUN TestRunGarbageCollection_FinishedOnAnotherReplica8=== PAUSE TestRunGarbageCollection_FinishedOnAnotherReplica9=== RUN TestRunGarbageCollection_NotFoundAfterLocalRun10=== PAUSE TestRunGarbageCollection_NotFoundAfterLocalRun11=== RUN TestCaseHackSuffix12=== PAUSE TestCaseHackSuffix13=== RUN TestFilterOversizedClosures14=== PAUSE TestFilterOversizedClosures15=== RUN TestUploadMultipart_PartsInParallel16=== PAUSE TestUploadMultipart_PartsInParallel17=== RUN TestPartSizeForNAR18=== PAUSE TestPartSizeForNAR19=== RUN TestUploadMultipart_SupersededByPeer20=== PAUSE TestUploadMultipart_SupersededByPeer21=== RUN TestDumpPathCaseHackMatchesNix22--- PASS: TestDumpPathCaseHackMatchesNix (0.44s)23=== RUN TestDumpPathCaseHackCollision24--- PASS: TestDumpPathCaseHackCollision (0.00s)25=== RUN TestDumpPathMatchesNix26=== PAUSE TestDumpPathMatchesNix27=== RUN TestDumpPathSingleFile28=== PAUSE TestDumpPathSingleFile29=== RUN TestDumpPathWriterError30=== PAUSE TestDumpPathWriterError31=== RUN TestEncodeNixBase3232=== PAUSE TestEncodeNixBase3233=== RUN TestEncodeNixBase32WithRealHash34=== PAUSE TestEncodeNixBase32WithRealHash35=== RUN TestConvertHashToNix3236=== PAUSE TestConvertHashToNix3237=== RUN TestGetStorePathHash38=== PAUSE TestGetStorePathHash39=== RUN TestPathInfoHashCompatibility40=== PAUSE TestPathInfoHashCompatibility41=== RUN TestParsePathInfoJSON42=== PAUSE TestParsePathInfoJSON43=== RUN TestParsePathInfoJSONMultiplePaths44=== PAUSE TestParsePathInfoJSONMultiplePaths45=== RUN TestPathInfoCACompatibility46=== PAUSE TestPathInfoCACompatibility47=== RUN TestRateLimiterFeedback48=== PAUSE TestRateLimiterFeedback49=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess50=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess51=== RUN TestResolveStorePath52=== PAUSE TestResolveStorePath53=== RUN TestDoWithRetry_BodyReplayedViaGetBody54=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody55=== RUN TestRetryTimeoutOutlastsMaxRetries56=== PAUSE TestRetryTimeoutOutlastsMaxRetries57=== RUN TestShellSplit58=== PAUSE TestShellSplit59=== RUN TestShellSplitErrors60=== PAUSE TestShellSplitErrors61=== RUN TestStreamPushReportsEveryPath62=== PAUSE TestStreamPushReportsEveryPath63=== RUN TestStreamPushBatchesUnderLoad64=== PAUSE TestStreamPushBatchesUnderLoad65=== RUN TestStreamPushIsolatesFailures66=== PAUSE TestStreamPushIsolatesFailures67=== RUN TestStreamPushGivesUpOnDeadServer68=== PAUSE TestStreamPushGivesUpOnDeadServer69=== RUN TestStreamPushRequestLine70=== PAUSE TestStreamPushRequestLine71=== RUN TestStreamPushReportsSignatures72=== PAUSE TestStreamPushReportsSignatures73=== RUN TestClientSignaturesByStorePath74=== PAUSE TestClientSignaturesByStorePath75=== RUN TestStreamPushStopsWhenCanceled76=== PAUSE TestStreamPushStopsWhenCanceled77=== RUN TestSetClientTLS78=== PAUSE TestSetClientTLS79=== RUN TestSetClientTLSDoesNotMutateDefaultTransport80=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport81=== RUN TestSetClientTLSErrors82=== PAUSE TestSetClientTLSErrors83=== RUN TestStaticToken84=== PAUSE TestStaticToken85=== RUN TestFileTokenReadsAndCaches86=== PAUSE TestFileTokenReadsAndCaches87=== RUN TestFileTokenMissing88=== PAUSE TestFileTokenMissing89=== RUN TestFileTokenEmpty90=== PAUSE TestFileTokenEmpty91=== RUN TestScriptTokenNoExpiryRerunsEveryCall92=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall93=== RUN TestScriptTokenCachesUntilRefresh94=== PAUSE TestScriptTokenCachesUntilRefresh95=== RUN TestScriptTokenEmptyToken96=== PAUSE TestScriptTokenEmptyToken97=== RUN TestScriptTokenBadJSON98=== PAUSE TestScriptTokenBadJSON99=== RUN TestScriptTokenScriptFails100=== PAUSE TestScriptTokenScriptFails101=== RUN TestScriptTokenEmptyCommand102=== PAUSE TestScriptTokenEmptyCommand103=== CONT TestDoServerRequestAttachesToken104=== CONT TestScriptTokenScriptFails105=== CONT TestPathInfoHashCompatibility106=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)107=== CONT TestDoWithRetry_BodyReplayedViaGetBody108=== CONT TestEncodeNixBase32109=== RUN TestEncodeNixBase32/test_string_hash110=== PAUSE TestEncodeNixBase32/test_string_hash111=== RUN TestEncodeNixBase32/empty_input112=== CONT TestResolveStorePath113=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess114=== CONT TestRateLimiterFeedback115=== RUN TestRateLimiterFeedback/429_enables_limiter116=== PAUSE TestRateLimiterFeedback/429_enables_limiter117=== RUN TestRateLimiterFeedback/503_enables_limiter118=== PAUSE TestRateLimiterFeedback/503_enables_limiter119=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter120=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter121=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter122=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter123=== CONT TestClientSignaturesByStorePath124--- PASS: TestClientSignaturesByStorePath (0.00s)125=== CONT TestStreamPushReportsSignatures126=== CONT TestPathInfoCACompatibility127=== RUN TestPathInfoCACompatibility/null_ca_field128=== PAUSE TestPathInfoCACompatibility/null_ca_field129=== RUN TestPathInfoCACompatibility/old_string_format_-_text130=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text131=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive132=== CONT TestParsePathInfoJSONMultiplePaths133=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive134=== RUN TestPathInfoCACompatibility/new_structured_format_-_text135=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text136=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method137=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths1382026/10/08 17:03:09 WARN Rate limiter enabled after throttle name=server-test rate=5139=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method140=== CONT TestScriptTokenBadJSON141=== CONT TestScriptTokenEmptyToken142--- PASS: TestResolveStorePath (0.00s)143=== CONT TestScriptTokenCachesUntilRefresh144=== CONT TestScriptTokenNoExpiryRerunsEveryCall145=== CONT TestFileTokenEmpty146=== CONT TestFileTokenMissing147=== CONT TestFileTokenReadsAndCaches148=== CONT TestStaticToken149=== CONT TestSetClientTLSErrors150=== CONT TestSetClientTLSDoesNotMutateDefaultTransport151=== CONT TestSetClientTLS152=== CONT TestStreamPushStopsWhenCanceled1532026/10/08 17:03:09 ERROR Upload failed error=boom count=1154=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)155=== CONT TestScriptTokenEmptyCommand156=== PAUSE TestEncodeNixBase32/empty_input157=== CONT TestParsePathInfoJSON158=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths159=== CONT TestStreamPushRequestLine160=== CONT TestStreamPushGivesUpOnDeadServer161=== CONT TestStreamPushReportsEveryPath162=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon163=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon164=== CONT TestShellSplitErrors165=== CONT TestShellSplit1662026/10/08 17:03:09 ERROR Upload failed error="connection refused" count=20167=== CONT TestRetryTimeoutOutlastsMaxRetries168=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths169=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths170=== RUN TestParsePathInfoJSON/Nix_format171=== PAUSE TestParsePathInfoJSON/Nix_format172=== RUN TestParsePathInfoJSON/Lix_format173=== PAUSE TestParsePathInfoJSON/Lix_format174=== RUN TestParsePathInfoJSON/empty_input175=== CONT TestDumpPathMatchesNix176=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI1772026/10/08 17:03:09 ERROR Server seems unavailable, giving up on batch untried=17178=== CONT TestStreamPushBatchesUnderLoad179--- PASS: TestStreamPushReportsSignatures (0.00s)180--- PASS: TestStaticToken (0.00s)181--- PASS: TestStreamPushReportsEveryPath (0.00s)182--- PASS: TestStreamPushStopsWhenCanceled (0.00s)183--- PASS: TestScriptTokenEmptyCommand (0.00s)184--- PASS: TestShellSplitErrors (0.00s)185--- PASS: TestShellSplit (0.00s)186=== PAUSE TestParsePathInfoJSON/empty_input187=== CONT TestDumpPathWriterError188=== CONT TestStreamPushIsolatesFailures1892026/10/08 17:03:09 ERROR Upload failed error=boom count=1190=== CONT TestDumpPathSingleFile191--- PASS: TestFileTokenMissing (0.00s)192=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun193--- PASS: TestFileTokenEmpty (0.00s)194=== CONT TestFilterOversizedClosures195--- PASS: TestScriptTokenScriptFails (0.01s)196=== CONT TestCaseHackSuffix197--- PASS: TestFileTokenReadsAndCaches (0.01s)198=== CONT TestUploadMultipart_PartsInParallel199--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.01s)200=== RUN TestParsePathInfoJSON/whitespace_only201=== RUN TestFilterOversizedClosures/no_limit_keeps_everything202=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything203=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI204=== RUN TestSetClientTLSErrors/missing_cert_file205=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512206=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped207=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped208=== RUN TestFilterOversizedClosures/all_closures_skipped209--- PASS: TestStreamPushGivesUpOnDeadServer (0.01s)210=== CONT TestGetStorePathHash211=== RUN TestGetStorePathHash/valid_store_path212=== PAUSE TestGetStorePathHash/valid_store_path213=== RUN TestGetStorePathHash/basename_without_hyphen_should_error214=== PAUSE TestParsePathInfoJSON/whitespace_only215=== RUN TestParsePathInfoJSON/invalid_JSON216=== CONT TestUploadMultipart_SupersededByPeer217=== RUN TestUploadMultipart_SupersededByPeer/exists2182026/10/08 17:03:09 ERROR Upload failed error="bad path" count=3219=== PAUSE TestUploadMultipart_SupersededByPeer/exists220=== RUN TestUploadMultipart_SupersededByPeer/missing221=== PAUSE TestUploadMultipart_SupersededByPeer/missing222=== PAUSE TestSetClientTLSErrors/missing_cert_file223=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512224=== RUN TestSetClientTLSErrors/missing_key_file225=== PAUSE TestSetClientTLSErrors/missing_key_file226=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error227=== PAUSE TestFilterOversizedClosures/all_closures_skipped228=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica229=== RUN TestSetClientTLSErrors/missing_ca_file230=== CONT TestEncodeNixBase32WithRealHash231=== CONT TestRateLimiterFeedback/429_enables_limiter232=== PAUSE TestParsePathInfoJSON/invalid_JSON233=== PAUSE TestSetClientTLSErrors/missing_ca_file234=== CONT TestPartSizeForNAR235=== CONT TestRateLimiterFeedback/503_enables_limiter236=== RUN TestPartSizeForNAR/zero_stays_at_minimum2372026/10/08 17:03:09 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:54070238--- PASS: TestDoServerRequestAttachesToken (0.02s)239=== CONT TestRegisterUploadedObjectReusesConnections240=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum241=== RUN TestPartSizeForNAR/small_stays_at_minimum242=== PAUSE TestPartSizeForNAR/small_stays_at_minimum243=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum244=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum245=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts246=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts247=== RUN TestPartSizeForNAR/1_TiB248=== PAUSE TestPartSizeForNAR/1_TiB249=== RUN TestPartSizeForNAR/5_TiB_S3_max_object250=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object251=== RUN TestPartSizeForNAR/capped_at_5_GiB252=== PAUSE TestPartSizeForNAR/capped_at_5_GiB253=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter254--- PASS: TestStreamPushIsolatesFailures (0.00s)255--- PASS: TestEncodeNixBase32WithRealHash (0.00s)2562026/10/08 17:03:09 WARN Rate limiter enabled after throttle name=server-test rate=52572026/10/08 17:03:09 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:540672582026/10/08 17:03:09 WARN Rate limiter backed off name=server-test rate=52592026/10/08 17:03:09 WARN Request returned retryable status, retrying attempt=2 backoff=0s status=503 url=http://127.0.0.1:54067260=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error261=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error262=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error263=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error264=== CONT TestConvertHashToNix32265=== RUN TestConvertHashToNix32/SRI_format_to_Nix32266=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32267=== RUN TestConvertHashToNix32/already_Nix32_format268=== PAUSE TestConvertHashToNix32/already_Nix32_format269=== RUN TestConvertHashToNix32/invalid_format270=== PAUSE TestConvertHashToNix32/invalid_format271=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter272=== RUN TestSetClientTLSErrors/invalid_ca_file273=== PAUSE TestSetClientTLSErrors/invalid_ca_file274=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method2752026/10/08 17:03:09 INFO Garbage collection started276=== CONT TestPathInfoCACompatibility/new_structured_format_-_text277=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive278=== CONT TestPathInfoCACompatibility/old_string_format_-_text279=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths280=== CONT TestPathInfoCACompatibility/null_ca_field281--- PASS: TestPathInfoCACompatibility (0.00s)282 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)283 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)284 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)285 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)286 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)287=== CONT TestEncodeNixBase32/test_string_hash288=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths289--- PASS: TestParsePathInfoJSONMultiplePaths (0.01s)290 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)291 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)292=== CONT TestEncodeNixBase32/empty_input293--- PASS: TestEncodeNixBase32 (0.01s)294 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)295 --- PASS: TestEncodeNixBase32/empty_input (0.00s)296=== CONT TestUploadMultipart_SupersededByPeer/exists297=== CONT TestUploadMultipart_SupersededByPeer/missing2982026/10/08 17:03:09 WARN Rate limiter enabled after throttle name=server-test rate=52992026/10/08 17:03:09 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=429 url=http://127.0.0.1:540773002026/10/08 17:03:09 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:54070301--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.02s)302=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)303=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha5123042026/10/08 17:03:09 INFO Garbage collection started305--- PASS: TestScriptTokenBadJSON (0.02s)306=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI307=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon308=== CONT TestFilterOversizedClosures/no_limit_keeps_everything309=== CONT TestFilterOversizedClosures/all_closures_skipped3102026/10/08 17:03:09 WARN Skipping closure: path exceeds server max NAR size top_level_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper oversized_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper nar_size=100 max_nar_size=50311=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3122026/10/08 17:03:09 WARN Skipping closure: path exceeds server max NAR size top_level_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper oversized_path=/nix/store/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb-vm-image nar_size=5000 max_nar_size=2000313--- PASS: TestFilterOversizedClosures (0.01s)314 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)315 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)316 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)317=== CONT TestParsePathInfoJSON/Nix_format318=== CONT TestParsePathInfoJSON/whitespace_only319=== CONT TestParsePathInfoJSON/invalid_JSON320=== CONT TestParsePathInfoJSON/empty_input321=== CONT TestParsePathInfoJSON/Lix_format322--- PASS: TestParsePathInfoJSON (0.01s)323 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)324 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)325 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)326 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)327 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)328=== CONT TestPartSizeForNAR/zero_stays_at_minimum329=== CONT TestPartSizeForNAR/1_TiB330=== CONT TestPartSizeForNAR/capped_at_5_GiB331=== CONT TestPartSizeForNAR/5_TiB_S3_max_object332=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum333=== CONT TestPartSizeForNAR/small_stays_at_minimum334--- PASS: TestPathInfoHashCompatibility (0.02s)335 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)336 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)337 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)338 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)339=== CONT TestGetStorePathHash/valid_store_path340=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts341--- PASS: TestPartSizeForNAR (0.00s)342 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)343 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)344 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)345 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)346 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)347 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)348 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)349=== CONT TestConvertHashToNix32/SRI_format_to_Nix32350=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error351=== CONT TestGetStorePathHash/basename_without_hyphen_should_error352=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error353--- PASS: TestGetStorePathHash (0.00s)354 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)355 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)356 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)357 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)358=== CONT TestSetClientTLSErrors/missing_cert_file359=== CONT TestConvertHashToNix32/invalid_format360=== CONT TestSetClientTLSErrors/invalid_ca_file361=== CONT TestConvertHashToNix32/already_Nix32_format362--- PASS: TestConvertHashToNix32 (0.00s)363 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)364 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)365 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)366=== CONT TestSetClientTLSErrors/missing_ca_file3672026/10/08 17:03:09 WARN Rate limiter backed off name=server-test rate=5368=== CONT TestSetClientTLSErrors/missing_key_file3692026/10/08 17:03:09 WARN Rate limiter enabled after throttle name=server-test rate=53702026/10/08 17:03:09 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:541363712026/10/08 17:03:09 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:540703722026/10/08 17:03:09 WARN Rate limiter backed off name=server-test rate=5373--- PASS: TestRateLimiterFeedback (0.00s)374 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)375 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)376 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.01s)377 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.01s)378--- PASS: TestSetClientTLSErrors (0.01s)379 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)380 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)381 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)382 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)383--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.02s)3842026/10/08 17:03:09 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:54070385=== RUN TestSetClientTLS/rejects_connection_without_client_cert386=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert387=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA388=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA389=== RUN TestSetClientTLS/preserves_debug_logging_transport390=== PAUSE TestSetClientTLS/preserves_debug_logging_transport391=== CONT TestSetClientTLS/rejects_connection_without_client_cert392--- PASS: TestScriptTokenEmptyToken (0.03s)393=== CONT TestSetClientTLS/preserves_debug_logging_transport394=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA3952026/10/08 17:03:09 INFO Garbage collection progress phase=running_on_another_replica failed_uploads_deleted=0 old_closures_deleted=0 objects_marked=0 objects_deleted=0 objects_failed=03962026/10/08 17:03:09 WARN Request returned retryable status, retrying attempt=3 backoff=1ms status=502 url=http://127.0.0.1:54070397--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)398 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.01s)399 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.01s)4002026/10/08 17:03:09 WARN Garbage collection finished on another replica. Its statistics are not available here401--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.02s)4022026/10/08 17:03:09 WARN Request returned retryable status, retrying attempt=4 backoff=1ms status=502 url=http://127.0.0.1:540704032026/10/08 17:03:09 WARN Request returned retryable status, retrying attempt=5 backoff=1ms status=502 url=http://127.0.0.1:54070404--- PASS: TestStreamPushRequestLine (0.03s)4052026/10/08 17:03:09 WARN Request returned retryable status, retrying attempt=6 backoff=1ms status=502 url=http://127.0.0.1:540704062026/10/08 17:03:09 WARN Request returned retryable status, retrying attempt=7 backoff=1ms status=502 url=http://127.0.0.1:540704072026/10/08 17:03:09 WARN Request returned retryable status, retrying attempt=8 backoff=1ms status=502 url=http://127.0.0.1:540704082026/10/08 17:03:09 WARN Request returned retryable status, retrying attempt=9 backoff=1ms status=502 url=http://127.0.0.1:540704092026/10/08 17:03:09 WARN Request returned retryable status, retrying attempt=10 backoff=1ms status=502 url=http://127.0.0.1:540704102026/10/08 17:03:09 WARN Request returned retryable status, retrying attempt=11 backoff=1ms status=502 url=http://127.0.0.1:540704112026/10/08 17:03:09 WARN Request returned retryable status, retrying attempt=12 backoff=1ms status=502 url=http://127.0.0.1:540704122026/10/08 17:03:09 WARN Request returned retryable status, retrying attempt=13 backoff=1ms status=502 url=http://127.0.0.1:540704132026/10/08 17:03:09 WARN Request returned retryable status, retrying attempt=14 backoff=1ms status=502 url=http://127.0.0.1:540704142026/10/08 17:03:09 WARN Request returned retryable status, retrying attempt=15 backoff=1ms status=502 url=http://127.0.0.1:540704152026/10/08 17:03:09 WARN Request returned retryable status, retrying attempt=16 backoff=1ms status=502 url=http://127.0.0.1:54070416--- PASS: TestScriptTokenCachesUntilRefresh (0.05s)4172026/10/08 17:03:09 http: TLS handshake error from 127.0.0.1:54160: read tcp 127.0.0.1:54145->127.0.0.1:54160: use of closed network connection418--- PASS: TestSetClientTLS (0.03s)419 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)420 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.01s)421 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.03s)4222026/10/08 17:03:09 WARN Request returned retryable status, retrying attempt=17 backoff=1ms status=502 url=http://127.0.0.1:54070423--- PASS: TestRegisterUploadedObjectReusesConnections (0.04s)424--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.06s)425--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.06s)426--- PASS: TestDumpPathWriterError (0.05s)427--- PASS: TestDumpPathSingleFile (0.07s)428--- PASS: TestCaseHackSuffix (0.08s)429--- PASS: TestDumpPathMatchesNix (0.09s)430--- PASS: TestStreamPushBatchesUnderLoad (0.10s)431--- PASS: TestUploadMultipart_PartsInParallel (0.62s)432--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.01s)433PASS434Running server tests...435The files belonging to this database system will be owned by user "_tribuchetbld3".436This user must also own the server process.437438The database cluster will be initialized with locale "C".439The default database encoding has accordingly been set to "SQL_ASCII".440The default text search configuration will be set to "english".441442Data page checksums are enabled.443444creating directory /private/var/tb/3/scratch/ec71b307c420129e/build/postgres2819432535/data ... ok445creating subdirectories ... ok446selecting dynamic shared memory implementation ... posix447selecting default "max_connections" ... 100448selecting default "shared_buffers" ... 128MB449selecting default time zone ... UTC450creating configuration files ... ok451running bootstrap script ... ok452performing post-bootstrap initialization ... ok453syncing data to disk ... ok454455initdb: warning: enabling "trust" authentication for local connections456initdb: 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.457458Success. You can now start the database server using:459460 pg_ctl -D /private/var/tb/3/scratch/ec71b307c420129e/build/postgres2819432535/data -l logfile start4614622026-10-08 17:03:11.576 UTC [67677] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit4632026-10-08 17:03:11.577 UTC [67677] LOG: listening on Unix socket "/private/var/tb/3/scratch/ec71b307c420129e/build/postgres2819432535/.s.PGSQL.5432"4642026-10-08 17:03:11.579 UTC [67684] LOG: database system was shut down at 2026-10-08 17:03:11 UTC4652026-10-08 17:03:11.579 UTC [67685] FATAL: the database system is starting up466/private/var/tb/3/scratch/ec71b307c420129e/build/postgres2819432535:5432 - rejecting connections4672026-10-08 17:03:11.579 UTC [67677] LOG: database system is ready to accept connections468/private/var/tb/3/scratch/ec71b307c420129e/build/postgres2819432535:5432 - accepting connections469{"timestamp":"2026-10-08T17:03:11.838188Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"95ecd863-72fc-45aa-8068-b416faef08f8","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":9,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":501,"threadName":"rustfs-worker","threadId":"ThreadId(4)"}470{"timestamp":"2026-10-08T17:03:11.950931Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"3ae8b835-3b07-4b37-ac0f-3ffe11371fc6","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(4)"}471=== RUN TestService_AuthMiddleware472=== PAUSE TestService_AuthMiddleware473=== RUN TestService_AuthMiddleware_MTLSProxyHeader474=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader475=== RUN TestService_AuthMiddleware_MTLSBoundSubjects476=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects477=== RUN TestService_ReadAuthMiddleware478=== PAUSE TestService_ReadAuthMiddleware479=== RUN TestService_AuthMiddleware_OIDC480=== PAUSE TestService_AuthMiddleware_OIDC481=== RUN TestService_RequireScope_OIDC482=== PAUSE TestService_RequireScope_OIDC483=== RUN TestService_ReadScope_PublicByDefault484=== PAUSE TestService_ReadScope_PublicByDefault485=== RUN TestCacheConfigHandler486=== PAUSE TestCacheConfigHandler487=== RUN TestCacheStatsHandler488=== PAUSE TestCacheStatsHandler489=== RUN TestClientCADerivations490=== PAUSE TestClientCADerivations491=== RUN TestClientErrorHandling492=== PAUSE TestClientErrorHandling493=== RUN TestClientIntegration494=== PAUSE TestClientIntegration495=== RUN TestClientMultipleUploads496=== PAUSE TestClientMultipleUploads497=== RUN TestClientWithDependencies498=== PAUSE TestClientWithDependencies499=== RUN TestClientSharedPathCommittedMidPush500=== PAUSE TestClientSharedPathCommittedMidPush501=== RUN TestPinProtectsFromGC502=== PAUSE TestPinProtectsFromGC503=== RUN TestClientPushesUseOnePush504=== PAUSE TestClientPushesUseOnePush505=== RUN TestClientFallsBackToClosures506=== PAUSE TestClientFallsBackToClosures507=== RUN TestDeleteClosuresRacingPins508=== PAUSE TestDeleteClosuresRacingPins509=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock510=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock511=== RUN TestResolveDBConnectionString512=== PAUSE TestResolveDBConnectionString513=== RUN TestConnectWaitsForAPeerMigration514=== PAUSE TestConnectWaitsForAPeerMigration515=== RUN TestLeadElectsOneAndHandsOver516=== PAUSE TestLeadElectsOneAndHandsOver517=== RUN TestLeadIncumbentWinsAfterRestart5182026/10/08 17:03:12 INFO lead: acquired remote=192.0.2.1:12345192026/10/08 17:03:13 INFO lead: released remote=192.0.2.1:12345202026/10/08 17:03:13 INFO lead: acquired remote=192.0.2.1:12345212026/10/08 17:03:14 INFO lead: released remote=192.0.2.1:1234522--- PASS: TestLeadIncumbentWinsAfterRestart (2.10s)523=== RUN TestLeadIncumbentAnnouncesAtOnce524=== PAUSE TestLeadIncumbentAnnouncesAtOnce525=== RUN TestLeadEndsOnShutdown526=== PAUSE TestLeadEndsOnShutdown527=== RUN TestLeadEndsWhenItsConnectionHangs5282026/10/08 17:03:14 INFO lead: acquired remote=192.0.2.1:12345292026-10-08 17:03:15.728 UTC [67720] FATAL: terminating connection due to administrator command5302026/10/08 17:03:15 INFO lead: acquired remote=192.0.2.1:12345312026/10/08 17:03:16 WARN lead: lock connection lost error="timeout: context deadline exceeded"5322026/10/08 17:03:16 INFO lead: released remote=192.0.2.1:12345332026/10/08 17:03:17 INFO lead: released remote=192.0.2.1:1234534--- PASS: TestLeadEndsWhenItsConnectionHangs (2.97s)535=== RUN TestGCAdvisoryLockBlocksConcurrentRun536=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun537=== RUN TestGCBugBareHashReferences538=== PAUSE TestGCBugBareHashReferences539=== RUN TestGCMetrics540=== PAUSE TestGCMetrics541=== RUN TestPushDedupSurvivesConcurrentGC542=== PAUSE TestPushDedupSurvivesConcurrentGC543=== RUN TestDeduplicatedObjectsRecordedAsPending544=== PAUSE TestDeduplicatedObjectsRecordedAsPending545=== RUN TestGCSweepSkipsPendingObjects546=== PAUSE TestGCSweepSkipsPendingObjects547=== RUN TestTombstonedObjectOfferedWithoutWaiting548=== PAUSE TestTombstonedObjectOfferedWithoutWaiting549=== RUN TestGCSweepDeliversEachKeyOnce550=== PAUSE TestGCSweepDeliversEachKeyOnce551=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection552=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection553=== RUN TestForceGCDuringPushOffersSweptObject554=== PAUSE TestForceGCDuringPushOffersSweptObject555=== RUN TestFailedS3DeleteKeepsTombstone556=== PAUSE TestFailedS3DeleteKeepsTombstone557=== RUN TestSweepSkipsRowsLockedByPush558=== PAUSE TestSweepSkipsRowsLockedByPush559=== RUN TestRegisterCompletedObjectNeedsPendingRow560=== PAUSE TestRegisterCompletedObjectNeedsPendingRow561=== RUN TestGetExistingObjectsLocksRows562=== PAUSE TestGetExistingObjectsLocksRows563=== RUN TestSweepRechecksPendingAfterLocking564=== PAUSE TestSweepRechecksPendingAfterLocking565=== RUN TestPushWaitsForSweepHoldingRow566=== PAUSE TestPushWaitsForSweepHoldingRow567=== RUN TestCommitRacingPendingCleanupKeepsObjects568=== PAUSE TestCommitRacingPendingCleanupKeepsObjects569=== RUN TestGCEndsOnShutdown570=== PAUSE TestGCEndsOnShutdown571=== RUN TestGCTaskStore_StartNew572=== PAUSE TestGCTaskStore_StartNew573=== RUN TestGCTaskStore_DeduplicateSameParams574=== PAUSE TestGCTaskStore_DeduplicateSameParams575=== RUN TestGCTaskStore_ConflictDifferentParams576=== PAUSE TestGCTaskStore_ConflictDifferentParams577=== RUN TestGCTaskStore_GetEmpty578=== PAUSE TestGCTaskStore_GetEmpty579=== RUN TestGCTaskStore_GetReturnsLatest580=== PAUSE TestGCTaskStore_GetReturnsLatest581=== RUN TestGCTaskStore_CompletedAllowsNewTask582=== PAUSE TestGCTaskStore_CompletedAllowsNewTask583=== RUN TestGCTaskStore_PhaseUpdates584=== PAUSE TestGCTaskStore_PhaseUpdates585=== RUN TestGCTaskStore_Fail586=== PAUSE TestGCTaskStore_Fail587=== RUN TestGracefulShutdownDrainsInflight588=== PAUSE TestGracefulShutdownDrainsInflight589=== RUN TestService_healthCheckHandler590=== PAUSE TestService_healthCheckHandler591=== RUN TestService_readinessHandler592=== PAUSE TestService_readinessHandler593=== RUN TestGenerateLandingPage594=== PAUSE TestGenerateLandingPage595=== RUN TestCacheConfigHandlerMaxNarSize596=== PAUSE TestCacheConfigHandlerMaxNarSize597=== RUN TestCreatePendingClosureRejectsOversizedNAR598=== PAUSE TestCreatePendingClosureRejectsOversizedNAR599=== RUN TestNARDeduplicationMetadataUploadBug600=== PAUSE TestNARDeduplicationMetadataUploadBug601=== RUN TestMetricsInventory602=== PAUSE TestMetricsInventory603=== RUN TestMetricsCommit604=== PAUSE TestMetricsCommit605=== RUN TestService_NativeMTLS606=== PAUSE TestService_NativeMTLS607=== RUN TestServerTLSConfig608=== PAUSE TestServerTLSConfig609=== RUN TestMultipartCleanup610=== PAUSE TestMultipartCleanup611=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded612=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded613=== RUN TestPendingCleanupUsesOneCutoff614=== PAUSE TestPendingCleanupUsesOneCutoff615=== RUN TestObjectStatsTrigger616=== PAUSE TestObjectStatsTrigger617=== RUN TestObjectStatsLargeCommit618=== PAUSE TestObjectStatsLargeCommit619=== RUN TestOrphanedObjectsGC620=== PAUSE TestOrphanedObjectsGC621=== RUN TestOrphanedObjectsGCStressTest622=== PAUSE TestOrphanedObjectsGCStressTest623=== RUN TestCreatePin_ReservedPins624=== PAUSE TestCreatePin_ReservedPins625=== RUN TestPresentReportsOnlyClosureRoots626=== PAUSE TestPresentReportsOnlyClosureRoots627=== RUN TestPresentRefreshesOnlyStaleClosures628=== PAUSE TestPresentRefreshesOnlyStaleClosures629=== RUN TestPresentNotReportedWhileGCDeletesClosure630=== PAUSE TestPresentNotReportedWhileGCDeletesClosure631=== RUN TestParseSingleRange632=== PAUSE TestParseSingleRange633=== RUN TestProxyHeadersOnlyTrustedOnSocket6342026/10/08 17:03:17 INFO Starting HTTP server address=proxy.sock6352026/10/08 17:03:17 INFO Starting HTTP server address=127.0.0.1:541866362026/10/08 17:03:17 WARN mTLS auth: subject not in bound subjects subject="CN=someone"6372026/10/08 17:03:17 INFO Shutdown signal received, draining in-flight requests timeout=10s638--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.17s)639=== RUN TestIsValidCachePath640=== PAUSE TestIsValidCachePath641=== RUN TestReadProxyNarinfo642=== PAUSE TestReadProxyNarinfo643=== RUN TestReadProxyNarinfoAlreadyDecompressed644=== PAUSE TestReadProxyNarinfoAlreadyDecompressed645=== RUN TestReadProxyContentNegotiation646=== PAUSE TestReadProxyContentNegotiation647=== RUN TestReadProxyNarStreaming648=== PAUSE TestReadProxyNarStreaming649=== RUN TestReadProxy404650=== PAUSE TestReadProxy404651=== RUN TestReadProxyInvalidPath652=== PAUSE TestReadProxyInvalidPath653=== RUN TestReadProxyHead654=== PAUSE TestReadProxyHead655=== RUN TestReadProxyOutlastsServerWriteTimeout656=== PAUSE TestReadProxyOutlastsServerWriteTimeout657=== RUN TestReadProxyConditionalGet658=== PAUSE TestReadProxyConditionalGet659=== RUN TestReadProxyRootRedirectsToIndexHTML660=== PAUSE TestReadProxyRootRedirectsToIndexHTML661=== RUN TestReadProxyDisabled662=== PAUSE TestReadProxyDisabled663=== RUN TestReadRedirectNar664=== PAUSE TestReadRedirectNar665=== RUN TestReadRedirectKeepsNarinfoProxied666=== PAUSE TestReadRedirectKeepsNarinfoProxied667=== RUN TestReadProxyRangeRequest668=== PAUSE TestReadProxyRangeRequest669=== RUN TestReadRedirectUsesPublicS3URL670=== PAUSE TestReadRedirectUsesPublicS3URL671=== RUN TestPush_OverlappingRootsStoreOneRowPerKey672=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey673=== RUN TestPush_CompleteCommitsEveryRoot674=== PAUSE TestPush_CompleteCommitsEveryRoot675=== RUN TestPush_RepeatedRootCommitsOnce676=== PAUSE TestPush_RepeatedRootCommitsOnce677=== RUN TestPush_CompleteWaitsForCleanupOfThePush678=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush679=== RUN TestPush_RootsAreLockedInByteOrder680=== PAUSE TestPush_RootsAreLockedInByteOrder681=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit682=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit683=== RUN TestPush_RejectsBadRequests684=== PAUSE TestPush_RejectsBadRequests685=== RUN TestPush_SignsNarinfosOfItsPendingObjects686=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects687=== RUN TestRedundantMultipartUpload688=== PAUSE TestRedundantMultipartUpload689=== RUN TestCompleteMultipartUpload_ErrorButObjectExists690=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists691=== RUN TestCompletedNarNotReofferedAcrossClosures692=== PAUSE TestCompletedNarNotReofferedAcrossClosures693=== RUN TestPresignedUploadRegisteredBeforeCommit694=== PAUSE TestPresignedUploadRegisteredBeforeCommit695=== RUN TestService_Rustfstest696=== PAUSE TestService_Rustfstest697=== RUN TestParseSize698=== PAUSE TestParseSize699=== RUN TestSkippedUploadsHandler700=== PAUSE TestSkippedUploadsHandler701=== RUN TestSystemdListenerNotActivated702--- PASS: TestSystemdListenerNotActivated (0.00s)703=== RUN TestWatchdogBeatsWhenHealthy704--- PASS: TestWatchdogBeatsWhenHealthy (0.03s)705=== RUN TestWatchdogSkipsWhenUnhealthy7062026/10/08 17:03:17 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7072026/10/08 17:03:17 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7082026/10/08 17:03:17 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7092026/10/08 17:03:17 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7102026/10/08 17:03:17 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7112026/10/08 17:03:17 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7122026/10/08 17:03:17 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7132026/10/08 17:03:17 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7142026/10/08 17:03:17 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7152026/10/08 17:03:17 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"716--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)717=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle718=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle719=== RUN TestProxyWriteTimeout720=== PAUSE TestProxyWriteTimeout721=== RUN TestPendingClosureWriteTimeout722=== PAUSE TestPendingClosureWriteTimeout723=== RUN TestIsValidUploadKey724=== PAUSE TestIsValidUploadKey725=== RUN TestUploadHandlersRejectInvalidKeys726=== PAUSE TestUploadHandlersRejectInvalidKeys727=== RUN TestUploadHandlersRejectOversizedBody728=== PAUSE TestUploadHandlersRejectOversizedBody729=== RUN TestService_cleanupPendingClosuresHandler730=== PAUSE TestService_cleanupPendingClosuresHandler731=== RUN TestService_createPendingClosureHandler732=== PAUSE TestService_createPendingClosureHandler733=== RUN TestService_verifyS3Integrity734=== PAUSE TestService_verifyS3Integrity735=== RUN TestCompleteMultipartUnregistered736=== PAUSE TestCompleteMultipartUnregistered737=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT738=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT739=== CONT TestReadProxyHead740=== CONT TestRegisterCompletedObjectNeedsPendingRow741=== CONT TestPresentNotReportedWhileGCDeletesClosure742=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock743=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale744=== CONT TestGCSweepSkipsPendingObjects745=== CONT TestCompleteMultipartUpload_ErrorButObjectExists746=== CONT TestGetExistingObjectsLocksRows747=== CONT TestPushDedupSurvivesConcurrentGC748=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale749=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh750=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh751=== CONT TestReadProxyNarStreaming752=== CONT TestReadProxyInvalidPath753=== CONT TestPresentReportsOnlyClosureRoots754=== CONT TestService_AuthMiddleware755=== CONT TestReadProxyNarinfo756=== CONT TestIsValidCachePath757=== CONT TestParseSingleRange758=== CONT TestSweepSkipsRowsLockedByPush759=== RUN TestParseSingleRange/none760=== CONT TestFailedS3DeleteKeepsTombstone761=== CONT TestForceGCDuringPushOffersSweptObject762=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection763=== CONT TestGCSweepDeliversEachKeyOnce764=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows765=== CONT TestTombstonedObjectOfferedWithoutWaiting766=== CONT TestPresentRefreshesOnlyStaleClosures767=== CONT TestReadProxyContentNegotiation768=== CONT TestReadProxyNarinfoAlreadyDecompressed769=== CONT TestReadProxy404770=== RUN TestIsValidCachePath/narinfo771=== PAUSE TestParseSingleRange/none772=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows773=== PAUSE TestIsValidCachePath/narinfo774=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check775=== RUN TestParseSingleRange/unknown_unit776=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars777=== PAUSE TestParseSingleRange/unknown_unit778=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars779=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check780=== RUN TestParseSingleRange/multi-range_ignored781=== RUN TestIsValidCachePath/nar_zst782=== PAUSE TestParseSingleRange/multi-range_ignored783=== CONT TestCreatePin_ReservedPins784=== RUN TestParseSingleRange/malformed_no_dash785=== PAUSE TestParseSingleRange/malformed_no_dash786=== RUN TestParseSingleRange/malformed_both_empty787=== PAUSE TestParseSingleRange/malformed_both_empty788=== RUN TestParseSingleRange/malformed_end_before_start789=== PAUSE TestParseSingleRange/malformed_end_before_start790=== RUN TestParseSingleRange/closed791=== PAUSE TestParseSingleRange/closed792=== RUN TestParseSingleRange/open-ended793=== PAUSE TestParseSingleRange/open-ended794=== RUN TestParseSingleRange/end_clamped_to_size795=== PAUSE TestParseSingleRange/end_clamped_to_size796=== RUN TestParseSingleRange/suffix797=== PAUSE TestParseSingleRange/suffix798=== PAUSE TestIsValidCachePath/nar_zst799=== RUN TestParseSingleRange/suffix_exceeds_size800=== PAUSE TestParseSingleRange/suffix_exceeds_size801=== RUN TestParseSingleRange/single_byte802=== RUN TestIsValidCachePath/nar_xz803=== PAUSE TestParseSingleRange/single_byte804=== PAUSE TestIsValidCachePath/nar_xz805=== RUN TestIsValidCachePath/nar_bz2806=== PAUSE TestIsValidCachePath/nar_bz2807=== RUN TestIsValidCachePath/nar_uncompressed808=== PAUSE TestIsValidCachePath/nar_uncompressed809=== RUN TestIsValidCachePath/ls810=== PAUSE TestIsValidCachePath/ls811=== RUN TestIsValidCachePath/log812=== PAUSE TestIsValidCachePath/log813=== RUN TestIsValidCachePath/realisation814=== PAUSE TestIsValidCachePath/realisation815=== RUN TestIsValidCachePath/nix-cache-info816=== RUN TestParseSingleRange/start_past_EOF817=== PAUSE TestParseSingleRange/start_past_EOF818=== PAUSE TestIsValidCachePath/nix-cache-info819=== RUN TestParseSingleRange/start_far_past_EOF820=== PAUSE TestParseSingleRange/start_far_past_EOF821=== RUN TestIsValidCachePath/index.html822=== PAUSE TestIsValidCachePath/index.html823=== RUN TestIsValidCachePath/traversal_parent824=== PAUSE TestIsValidCachePath/traversal_parent825=== RUN TestIsValidCachePath/traversal_in_middle826=== PAUSE TestIsValidCachePath/traversal_in_middle827=== RUN TestIsValidCachePath/invalid_char_e828=== PAUSE TestIsValidCachePath/invalid_char_e829=== RUN TestIsValidCachePath/invalid_char_u830=== PAUSE TestIsValidCachePath/invalid_char_u831=== RUN TestIsValidCachePath/random_path832=== PAUSE TestIsValidCachePath/random_path833=== RUN TestIsValidCachePath/empty834=== PAUSE TestIsValidCachePath/empty835=== RUN TestIsValidCachePath/leading_slash836=== PAUSE TestIsValidCachePath/leading_slash837=== RUN TestIsValidCachePath/wrong_extension838=== PAUSE TestIsValidCachePath/wrong_extension839=== RUN TestIsValidCachePath/short_hash840=== PAUSE TestIsValidCachePath/short_hash841=== CONT TestOrphanedObjectsGCStressTest842=== CONT TestOrphanedObjectsGC8432026/10/08 17:03:17 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54188/oidc8442026/10/08 17:03:19 INFO Received uploads request method=POST path=/api/pending_closures8452026/10/08 17:03:19 INFO Aborted multipart uploads count=0 kept=08462026/10/08 17:03:19 WARN Force mode enabled - objects will be deleted immediately without grace period8472026/10/08 17:03:19 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=08482026/10/08 17:03:19 INFO Vacuumed table table=pending_closures8492026/10/08 17:03:19 INFO Vacuumed table table=pending_objects8502026/10/08 17:03:19 INFO Vacuumed table table=multipart_uploads8512026/10/08 17:03:19 INFO Vacuumed table table=closures8522026/10/08 17:03:19 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"853--- PASS: TestService_AuthMiddleware (1.85s)854=== CONT TestObjectStatsLargeCommit8552026/10/08 17:03:19 INFO Vacuumed table table=objects856--- PASS: TestGCSweepSkipsPendingObjects (1.96s)857=== CONT TestObjectStatsTrigger858--- PASS: TestRegisterCompletedObjectNeedsPendingRow (2.21s)859=== CONT TestPendingCleanupUsesOneCutoff8602026/10/08 17:03:20 INFO Received uploads request method=POST path=/api/pending_closures8612026/10/08 17:03:20 INFO Aborted multipart uploads count=0 kept=08622026/10/08 17:03:20 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=08632026/10/08 17:03:20 INFO Vacuumed table table=pending_closures8642026/10/08 17:03:20 INFO Vacuumed table table=pending_objects8652026/10/08 17:03:20 INFO Vacuumed table table=multipart_uploads8662026/10/08 17:03:20 INFO Vacuumed table table=closures867--- PASS: TestReadProxyHead (2.75s)868=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded8692026/10/08 17:03:20 INFO Vacuumed table table=objects8702026/10/08 17:03:20 INFO Aborted multipart uploads count=0 kept=08712026/10/08 17:03:20 WARN Force mode enabled - objects will be deleted immediately without grace period8722026/10/08 17:03:20 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=08732026/10/08 17:03:20 INFO Vacuumed table table=pending_closures8742026/10/08 17:03:20 INFO Vacuumed table table=pending_objects8752026/10/08 17:03:20 INFO Vacuumed table table=multipart_uploads8762026/10/08 17:03:20 INFO Vacuumed table table=closures8772026/10/08 17:03:20 INFO Vacuumed table table=objects878--- PASS: TestPushDedupSurvivesConcurrentGC (2.81s)879=== CONT TestMultipartCleanup8802026/10/08 17:03:20 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>881--- PASS: TestReadProxyNarinfo (2.98s)882=== CONT TestServerTLSConfig883=== RUN TestServerTLSConfig/no_client_CA884=== PAUSE TestServerTLSConfig/no_client_CA885=== RUN TestServerTLSConfig/missing_CA_file886=== PAUSE TestServerTLSConfig/missing_CA_file887=== RUN TestServerTLSConfig/not_a_PEM_file888=== PAUSE TestServerTLSConfig/not_a_PEM_file889=== CONT TestService_NativeMTLS890--- PASS: TestReadProxyInvalidPath (3.15s)891=== CONT TestMetricsCommit8922026/10/08 17:03:21 INFO Aborted multipart uploads count=0 kept=08932026/10/08 17:03:21 WARN Force mode enabled - objects will be deleted immediately without grace period8942026/10/08 17:03:21 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=08952026/10/08 17:03:21 INFO Vacuumed table table=pending_closures8962026/10/08 17:03:21 INFO Vacuumed table table=pending_objects8972026/10/08 17:03:21 INFO Vacuumed table table=multipart_uploads8982026/10/08 17:03:21 INFO Vacuumed table table=closures8992026/10/08 17:03:21 INFO Vacuumed table table=objects900--- PASS: TestGCSweepDeliversEachKeyOnce (3.96s)901=== CONT TestMetricsInventory902--- PASS: TestReadProxyContentNegotiation (4.04s)903=== CONT TestNARDeduplicationMetadataUploadBug904--- PASS: TestPresentRefreshesOnlyStaleClosures (4.27s)905=== CONT TestCreatePendingClosureRejectsOversizedNAR9062026/10/08 17:03:21 INFO Received uploads request method=POST path=/api/pending_closures907--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)908=== CONT TestCacheConfigHandlerMaxNarSize909--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)910=== CONT TestGenerateLandingPage911--- PASS: TestGenerateLandingPage (0.00s)912=== CONT TestService_readinessHandler913--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (4.42s)914=== CONT TestService_healthCheckHandler915--- PASS: TestPresentReportsOnlyClosureRoots (4.51s)916=== CONT TestGracefulShutdownDrainsInflight9172026/10/08 17:03:22 INFO Starting HTTP server address=127.0.0.1:542249182026/10/08 17:03:22 INFO Shutdown signal received, draining in-flight requests timeout=10s919--- PASS: TestGracefulShutdownDrainsInflight (0.08s)920=== CONT TestGCTaskStore_Fail921--- PASS: TestGCTaskStore_Fail (0.00s)922=== CONT TestGCTaskStore_PhaseUpdates923--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)924=== CONT TestGCTaskStore_CompletedAllowsNewTask925--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)926=== CONT TestGCTaskStore_GetReturnsLatest927--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)928=== CONT TestGCTaskStore_GetEmpty929--- PASS: TestGCTaskStore_GetEmpty (0.00s)930=== CONT TestGCTaskStore_ConflictDifferentParams931--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)932=== CONT TestGCTaskStore_DeduplicateSameParams933--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)934=== CONT TestGCTaskStore_StartNew935--- PASS: TestGCTaskStore_StartNew (0.00s)936=== CONT TestGCEndsOnShutdown937=== RUN TestGCEndsOnShutdown/before_the_run938=== PAUSE TestGCEndsOnShutdown/before_the_run939=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete940=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete941=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark942=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark943=== CONT TestCommitRacingPendingCleanupKeepsObjects9442026/10/08 17:03:22 INFO Received uploads request method=POST path=/api/pending_closures9452026/10/08 17:03:22 INFO Aborted multipart uploads count=0 kept=09462026/10/08 17:03:22 WARN Force mode enabled - objects will be deleted immediately without grace period9472026/10/08 17:03:22 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."9482026/10/08 17:03:22 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."949--- PASS: TestFailedS3DeleteKeepsTombstone (5.23s)950=== CONT TestPushWaitsForSweepHoldingRow9512026/10/08 17:03:22 INFO Received uploads request method=POST path=/api/pending_closures952--- PASS: TestTombstonedObjectOfferedWithoutWaiting (5.41s)953=== CONT TestSweepRechecksPendingAfterLocking954=== NAME TestOrphanedObjectsGC955 orphaned_objects_gc_test.go:287: GC Test Summary:956 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A957 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B958 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)959 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)960 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects961--- PASS: TestOrphanedObjectsGC (5.48s)962=== CONT TestClientErrorHandling963=== RUN TestClientErrorHandling/InvalidStorePath964=== PAUSE TestClientErrorHandling/InvalidStorePath965=== RUN TestClientErrorHandling/InvalidAuthToken966=== PAUSE TestClientErrorHandling/InvalidAuthToken967=== RUN TestClientErrorHandling/ServerNotAvailable968=== PAUSE TestClientErrorHandling/ServerNotAvailable969=== CONT TestDeleteClosuresRacingPins9702026/10/08 17:03:23 INFO Received uploads request method=POST path=/api/pending_closures971--- PASS: TestGetExistingObjectsLocksRows (5.94s)972=== CONT TestClientFallsBackToClosures9732026/10/08 17:03:23 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9742026/10/08 17:03:23 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MzQ2Njc2OWUtOTMxYy00YjBjLTg5ZjEtOTQ3OGM5ODJjNzNjLjIxZjVjMzA0LWU5ZTUtNDdhMS05MGZmLWQ2ZWY2Y2VlNDU1MHgxNzkxNDc5MDAzMjIxMjM0MDAw9752026/10/08 17:03:23 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MzQ2Njc2OWUtOTMxYy00YjBjLTg5ZjEtOTQ3OGM5ODJjNzNjLjIxZjVjMzA0LWU5ZTUtNDdhMS05MGZmLWQ2ZWY2Y2VlNDU1MHgxNzkxNDc5MDAzMjIxMjM0MDAw parts=1976--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (6.00s)977=== CONT TestClientPushesUseOnePush978--- PASS: TestReadProxyNarinfoAlreadyDecompressed (6.18s)979=== CONT TestPinProtectsFromGC9802026/10/08 17:03:23 INFO Received uploads request method=POST path=/api/pending_closures981--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (6.68s)982=== CONT TestClientSharedPathCommittedMidPush9832026/10/08 17:03:24 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux9842026/10/08 17:03:24 WARN Refused reserved pin name=worker-x86_64-linux9852026/10/08 17:03:24 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux9862026/10/08 17:03:24 INFO Received create pin request method=POST path=/api/pins/my-app9872026/10/08 17:03:24 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux988--- PASS: TestCreatePin_ReservedPins (7.07s)989=== CONT TestClientWithDependencies9902026/10/08 17:03:24 INFO Aborted multipart uploads count=0 kept=09912026/10/08 17:03:25 WARN Force mode enabled - objects will be deleted immediately without grace period9922026/10/08 17:03: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=09932026/10/08 17:03:25 INFO Vacuumed table table=pending_closures9942026/10/08 17:03:25 INFO Vacuumed table table=pending_objects9952026/10/08 17:03:25 INFO Vacuumed table table=multipart_uploads9962026/10/08 17:03:25 INFO Vacuumed table table=closures9972026/10/08 17:03:25 INFO Vacuumed table table=objects9982026/10/08 17:03:25 INFO Aborted multipart uploads count=0 kept=09992026/10/08 17:03:25 WARN Force mode enabled - objects will be deleted immediately without grace period10002026/10/08 17:03:25 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=010012026/10/08 17:03:25 INFO Vacuumed table table=pending_closures10022026/10/08 17:03:25 INFO Vacuumed table table=pending_objects10032026/10/08 17:03:25 INFO Vacuumed table table=multipart_uploads10042026/10/08 17:03:25 INFO Vacuumed table table=closures10052026/10/08 17:03:25 INFO Vacuumed table table=objects1006--- PASS: TestSweepSkipsRowsLockedByPush (7.67s)1007=== CONT TestClientMultipleUploads1008--- PASS: TestReadProxyNarStreaming (7.78s)1009=== CONT TestClientIntegration1010--- PASS: TestReadProxy404 (8.31s)1011=== CONT TestIsValidUploadKey1012=== RUN TestIsValidUploadKey/narinfo1013=== PAUSE TestIsValidUploadKey/narinfo1014=== RUN TestIsValidUploadKey/nar_zst1015=== PAUSE TestIsValidUploadKey/nar_zst1016=== RUN TestIsValidUploadKey/nar_xz1017=== PAUSE TestIsValidUploadKey/nar_xz1018=== RUN TestIsValidUploadKey/nar_plain1019=== PAUSE TestIsValidUploadKey/nar_plain1020=== RUN TestIsValidUploadKey/listing1021=== PAUSE TestIsValidUploadKey/listing1022=== RUN TestIsValidUploadKey/build_log1023=== PAUSE TestIsValidUploadKey/build_log1024=== RUN TestIsValidUploadKey/build_log_home-manager_file1025=== PAUSE TestIsValidUploadKey/build_log_home-manager_file1026=== RUN TestIsValidUploadKey/build_log_plus_in_name1027=== PAUSE TestIsValidUploadKey/build_log_plus_in_name1028=== RUN TestIsValidUploadKey/build_log_question_mark1029=== PAUSE TestIsValidUploadKey/build_log_question_mark1030=== RUN TestIsValidUploadKey/build_log_equals1031=== PAUSE TestIsValidUploadKey/build_log_equals1032=== RUN TestIsValidUploadKey/realisation1033=== PAUSE TestIsValidUploadKey/realisation1034=== RUN TestIsValidUploadKey/realisation_plus_in_output1035=== PAUSE TestIsValidUploadKey/realisation_plus_in_output1036=== RUN TestIsValidUploadKey/nix-cache-info1037=== PAUSE TestIsValidUploadKey/nix-cache-info1038=== RUN TestIsValidUploadKey/index.html1039=== PAUSE TestIsValidUploadKey/index.html1040=== RUN TestIsValidUploadKey/narinfo_key,_nar_type1041=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type1042=== RUN TestIsValidUploadKey/nar_key,_narinfo_type1043=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type1044=== RUN TestIsValidUploadKey/listing_key,_narinfo_type1045=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type1046=== RUN TestIsValidUploadKey/traversal1047=== PAUSE TestIsValidUploadKey/traversal1048=== RUN TestIsValidUploadKey/traversal_nar1049=== PAUSE TestIsValidUploadKey/traversal_nar1050=== RUN TestIsValidUploadKey/absolute1051=== PAUSE TestIsValidUploadKey/absolute1052=== RUN TestIsValidUploadKey/empty_key1053=== PAUSE TestIsValidUploadKey/empty_key1054=== RUN TestIsValidUploadKey/unknown_type1055=== PAUSE TestIsValidUploadKey/unknown_type1056=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT10572026/10/08 17:03:26 INFO Received uploads request method=POST path=/api/pending_closures10582026/10/08 17:03:26 INFO Received uploads request method=POST path=/api/pending_closures10592026/10/08 17:03:26 INFO Received cleanup request method=DELETE path=/api/pending_closures1060--- PASS: TestObjectStatsTrigger (7.14s)1061=== CONT TestCompleteMultipartUnregistered10622026/10/08 17:03:27 INFO Received uploads request method=POST path=/api/pending_closures1063--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (7.24s)1064=== CONT TestService_verifyS3Integrity10652026/10/08 17:03:27 INFO Received uploads request method=POST path=/api/pending_closures10662026/10/08 17:03:28 INFO Received cleanup request method=DELETE path=/api/pending_closures10672026/10/08 17:03:28 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket32/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""10682026/10/08 17:03:28 INFO Aborted multipart uploads count=0 kept=110692026/10/08 17:03:28 WARN mTLS auth: subject not in bound subjects subject="CN=reader"10702026/10/08 17:03:28 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1071--- PASS: TestService_NativeMTLS (7.69s)1072=== CONT TestService_createPendingClosureHandler10732026/10/08 17:03:28 INFO Received cleanup request method=DELETE path=/api/pending_closures10742026/10/08 17:03:28 INFO Aborted multipart uploads count=1 kept=01075--- PASS: TestMultipartCleanup (7.88s)1076=== CONT TestService_cleanupPendingClosuresHandler10772026/10/08 17:03:28 INFO Received push request method=POST path=/api/pushes10782026/10/08 17:03:28 INFO Received complete push request method=POST path=/api/pushes/1/complete10792026/10/08 17:03:28 INFO Completed push id=1 objects=4 duration=38.6155ms10802026/10/08 17:03:28 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete10812026/10/08 17:03:28 INFO Completed upload id=2 objects=2 duration=2.32ms1082--- PASS: TestMetricsCommit (8.03s)1083=== CONT TestUploadHandlersRejectOversizedBody1084=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart1085=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart1086=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts1087=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts1088=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure1089=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure1090=== CONT TestUploadHandlersRejectInvalidKeys1091=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1092=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1093=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1094=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1095=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1096=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1097=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1098=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1099=== CONT TestService_RequireScope_OIDC11002026/10/08 17:03:28 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54285/oidc1101--- PASS: TestMetricsInventory (7.51s)1102=== CONT TestClientCADerivations11032026/10/08 17:03:29 WARN readiness check failed error="closed pool"1104--- PASS: TestService_readinessHandler (7.73s)1105=== CONT TestCacheStatsHandler1106=== NAME TestNARDeduplicationMetadataUploadBug1107 metadata_upload_test.go:48: First store path: /private/var/tb/3/scratch/ec71b307c420129e/build/TestNARDeduplicationMetadataUploadBug469171868/001/store/4871zh11rs3x683j5q64qhs3my1avqik-file1.txt11082026/10/08 17:03:29 INFO Received push request method=POST path=/api/pushes11092026/10/08 17:03:29 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)11102026/10/08 17:03:29 INFO Uploading 4871zh11rs3x683j5q64qhs3my1avqik-file1.txt (160B)11112026/10/08 17:03:29 WARN Failed to register uploaded object key=4871zh11rs3x683j5q64qhs3my1avqik.ls error="server returned 404: 404 page not found\n"11122026/10/08 17:03:29 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"11132026/10/08 17:03:29 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11142026/10/08 17:03:29 INFO Signed narinfos id=1 count=111152026/10/08 17:03:29 INFO Uploading 1 narinfos11162026/10/08 17:03:29 INFO Received complete push request method=POST path=/api/pushes/1/complete11172026/10/08 17:03:29 WARN Failed to register uploaded object key=4871zh11rs3x683j5q64qhs3my1avqik.narinfo error="server returned 404: 404 page not found\n"1118--- PASS: TestService_healthCheckHandler (7.92s)1119=== CONT TestCacheConfigHandler1120=== RUN TestCacheConfigHandler/full_config,_no_issuer1121=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1122=== RUN TestCacheConfigHandler/no_cache_url_configured1123=== PAUSE TestCacheConfigHandler/no_cache_url_configured1124=== RUN TestCacheConfigHandler/no_signing_keys1125=== PAUSE TestCacheConfigHandler/no_signing_keys1126=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1127=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1128=== CONT TestService_ReadScope_PublicByDefault11292026/10/08 17:03:29 INFO Completed push id=1 objects=3 duration=32.399208ms11302026/10/08 17:03:29 INFO Upload complete. (194ms)1131=== NAME TestNARDeduplicationMetadataUploadBug1132 metadata_upload_test.go:54: Retrieved narinfo from S3:1133 StorePath: /private/var/tb/3/scratch/ec71b307c420129e/build/TestNARDeduplicationMetadataUploadBug469171868/001/store/4871zh11rs3x683j5q64qhs3my1avqik-file1.txt1134 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1135 Compression: zstd1136 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1137 NarSize: 1601138 References: 1139 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1140 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1141 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1142 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}1143 metadata_upload_test.go:64: Second store path (same content): /private/var/tb/3/scratch/ec71b307c420129e/build/TestNARDeduplicationMetadataUploadBug469171868/001/store/3223amgiipzkwfm2s93sjnk55gvz404g-file2.txt11442026/10/08 17:03:30 INFO Received push request method=POST path=/api/pushes11452026/10/08 17:03:30 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)11462026/10/08 17:03:30 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign11472026/10/08 17:03:30 WARN Failed to register uploaded object key=3223amgiipzkwfm2s93sjnk55gvz404g.ls error="server returned 404: 404 page not found\n"11482026/10/08 17:03:30 INFO Signed narinfos id=2 count=111492026/10/08 17:03:30 INFO Uploading 1 narinfos11502026/10/08 17:03:30 INFO Received complete push request method=POST path=/api/pushes/2/complete11512026/10/08 17:03:30 WARN Failed to register uploaded object key=3223amgiipzkwfm2s93sjnk55gvz404g.narinfo error="server returned 404: 404 page not found\n"11522026/10/08 17:03:30 INFO Completed push id=2 objects=3 duration=1.159292ms11532026/10/08 17:03:30 INFO Upload complete. (141ms)1154 metadata_upload_test.go:76: Retrieved narinfo from S3:1155 StorePath: /private/var/tb/3/scratch/ec71b307c420129e/build/TestNARDeduplicationMetadataUploadBug469171868/001/store/3223amgiipzkwfm2s93sjnk55gvz404g-file2.txt1156 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1157 Compression: zstd1158 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1159 NarSize: 1601160 References: 1161 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1162 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1163 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1164 {"version":1,"root":{"type":"regular","size":44}}11652026/10/08 17:03:30 INFO Aborted multipart uploads count=0 kept=01166--- PASS: TestNARDeduplicationMetadataUploadBug (8.71s)1167=== CONT TestPush_OverlappingRootsStoreOneRowPerKey11682026/10/08 17:03:30 WARN Force mode enabled - objects will be deleted immediately without grace period11692026/10/08 17:03:30 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=011702026/10/08 17:03:30 INFO Vacuumed table table=pending_closures11712026/10/08 17:03:30 INFO Vacuumed table table=pending_objects11722026/10/08 17:03:30 INFO Vacuumed table table=multipart_uploads11732026/10/08 17:03:30 INFO Vacuumed table table=closures11742026/10/08 17:03:30 INFO Vacuumed table table=objects1175--- PASS: TestCommitRacingPendingCleanupKeepsObjects (8.32s)1176=== CONT TestRedundantMultipartUpload11772026/10/08 17:03:30 INFO Aborted multipart uploads count=0 kept=011782026/10/08 17:03:30 WARN Force mode enabled - objects will be deleted immediately without grace period11792026/10/08 17:03:30 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=011802026/10/08 17:03:30 INFO Vacuumed table table=pending_closures11812026/10/08 17:03:30 INFO Vacuumed table table=pending_objects11822026/10/08 17:03:30 INFO Vacuumed table table=multipart_uploads11832026/10/08 17:03:30 INFO Vacuumed table table=closures11842026/10/08 17:03:30 INFO Vacuumed table table=objects1185--- PASS: TestSweepRechecksPendingAfterLocking (7.80s)1186=== CONT TestPush_SignsNarinfosOfItsPendingObjects11872026/10/08 17:03:30 INFO Received uploads request method=POST path=/api/pending_closures1188--- PASS: TestPushWaitsForSweepHoldingRow (8.66s)1189=== CONT TestPush_RejectsBadRequests11902026/10/08 17:03:32 INFO Received uploads request method=POST path=/api/pending_closures11912026/10/08 17:03:32 INFO Received uploads request method=POST path=/api/pending_closures11922026/10/08 17:03:32 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)11932026/10/08 17:03:32 INFO Uploading g0c6cibi3ldrx617pfk21aw695a3h5ya-shared-dep (136B)11942026/10/08 17:03:32 INFO Uploading h9yqga2hc2s8nc0rly4pcgqkz9rblj68-b (256B)11952026/10/08 17:03:32 WARN Failed to register uploaded object key=br8bsv3d26gp334fjjzxmb2ix65knx6x.ls error="server returned 404: 404 page not found\n"11962026/10/08 17:03:32 WARN Failed to register uploaded object key=g0c6cibi3ldrx617pfk21aw695a3h5ya.ls error="server returned 404: 404 page not found\n"11972026/10/08 17:03:32 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"11982026/10/08 17:03:32 WARN Failed to register uploaded object key=nar/0h3pcwlg2vld797l9pcj6hih8pkfkkq73rsyl5q6al1hbp57v2j0.nar.zst error="server returned 404: 404 page not found\n"11992026/10/08 17:03:32 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign12002026/10/08 17:03:32 WARN Failed to register uploaded object key=h9yqga2hc2s8nc0rly4pcgqkz9rblj68.ls error="server returned 404: 404 page not found\n"12012026/10/08 17:03:32 INFO Signed narinfos id=1 count=212022026/10/08 17:03:32 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign12032026/10/08 17:03:32 INFO Signed narinfos id=2 count=212042026/10/08 17:03:32 INFO Uploading 4 narinfos12052026/10/08 17:03:32 WARN Failed to register uploaded object key=h9yqga2hc2s8nc0rly4pcgqkz9rblj68.narinfo error="server returned 404: 404 page not found\n"12062026/10/08 17:03:32 WARN Failed to register uploaded object key=br8bsv3d26gp334fjjzxmb2ix65knx6x.narinfo error="server returned 404: 404 page not found\n"12072026/10/08 17:03:32 WARN Failed to register uploaded object key=g0c6cibi3ldrx617pfk21aw695a3h5ya.narinfo error="server returned 404: 404 page not found\n"1208=== NAME TestOrphanedObjectsGCStressTest1209 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains12102026/10/08 17:03:32 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12112026/10/08 17:03:32 WARN Failed to register uploaded object key=g0c6cibi3ldrx617pfk21aw695a3h5ya.narinfo error="server returned 404: 404 page not found\n"12122026/10/08 17:03:32 INFO Completed upload id=1 objects=6 duration=21.593125ms12132026/10/08 17:03:32 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete12142026/10/08 17:03:32 INFO Completed upload id=2 objects=6 duration=1.385167ms12152026/10/08 17:03:32 INFO Upload complete. (232ms)1216 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion1217=== NAME TestClientFallsBackToClosures1218 client_pushes_test.go:112: Retrieved narinfo from S3:1219 StorePath: /private/var/tb/3/scratch/ec71b307c420129e/build/TestClientFallsBackToClosures2997995738/001/store/g0c6cibi3ldrx617pfk21aw695a3h5ya-shared-dep1220 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1221 Compression: zstd1222 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821223 NarSize: 1361224 References: 1225 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1226 client_pushes_test.go:112: Retrieved narinfo from S3:1227 StorePath: /private/var/tb/3/scratch/ec71b307c420129e/build/TestClientFallsBackToClosures2997995738/001/store/br8bsv3d26gp334fjjzxmb2ix65knx6x-a1228 URL: nar/0h3pcwlg2vld797l9pcj6hih8pkfkkq73rsyl5q6al1hbp57v2j0.nar.zst1229 Compression: zstd1230 NarHash: sha256:0h3pcwlg2vld797l9pcj6hih8pkfkkq73rsyl5q6al1hbp57v2j01231 NarSize: 2561232 References: /private/var/tb/3/scratch/ec71b307c420129e/build/TestClientFallsBackToClosures2997995738/001/store/g0c6cibi3ldrx617pfk21aw695a3h5ya-shared-dep1233 CA: text:sha256:0hzwc2z4c7i0v8kqlyqi07kf8xnm29827c7r3gi8qkg6kin608hz1234 client_pushes_test.go:112: Retrieved narinfo from S3:1235 StorePath: /private/var/tb/3/scratch/ec71b307c420129e/build/TestClientFallsBackToClosures2997995738/001/store/h9yqga2hc2s8nc0rly4pcgqkz9rblj68-b1236 URL: nar/0h3pcwlg2vld797l9pcj6hih8pkfkkq73rsyl5q6al1hbp57v2j0.nar.zst1237 Compression: zstd1238 NarHash: sha256:0h3pcwlg2vld797l9pcj6hih8pkfkkq73rsyl5q6al1hbp57v2j01239 NarSize: 2561240 References: /private/var/tb/3/scratch/ec71b307c420129e/build/TestClientFallsBackToClosures2997995738/001/store/g0c6cibi3ldrx617pfk21aw695a3h5ya-shared-dep1241 CA: text:sha256:0hzwc2z4c7i0v8kqlyqi07kf8xnm29827c7r3gi8qkg6kin608hz1242--- PASS: TestClientFallsBackToClosures (8.87s)1243=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit12442026/10/08 17:03:32 INFO Aborted multipart uploads count=1 kept=012452026/10/08 17:03:32 INFO Received push request method=POST path=/api/pushes12462026/10/08 17:03:32 INFO Received cleanup request method=DELETE path=/api/pending_closures12472026/10/08 17:03:32 INFO Aborted multipart uploads count=1 kept=01248--- PASS: TestPendingCleanupUsesOneCutoff (12.67s)1249=== CONT TestPush_RootsAreLockedInByteOrder12502026/10/08 17:03:32 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)12512026/10/08 17:03:32 INFO Uploading lidnsvabrr3s5zdlspnnvk6h5k6npfbg-a (256B)12522026/10/08 17:03:32 INFO Uploading vbcambxab3m7xcv6imzvibskhbybkyz2-shared-dep (136B)12532026/10/08 17:03:32 WARN Failed to register uploaded object key=vbcambxab3m7xcv6imzvibskhbybkyz2.ls error="server returned 404: 404 page not found\n"1254=== NAME TestPinProtectsFromGC1255 client_integration_test.go:731: Pinned store path: /private/var/tb/3/scratch/ec71b307c420129e/build/TestPinProtectsFromGC3221096886/001/store/5wj96lnx5p0wfr6j55spgcm04n9fbsz6-pinned-file.txt1256 client_integration_test.go:732: Unpinned store path: /private/var/tb/3/scratch/ec71b307c420129e/build/TestPinProtectsFromGC3221096886/001/store/isfxq5kjardbiyz1l9adadmc9z3xqamy-unpinned-file.txt12572026/10/08 17:03:32 WARN Failed to register uploaded object key=5h29g0f1sjnph3vf0nxcnwg1p8k5b6np.ls error="server returned 404: 404 page not found\n"12582026/10/08 17:03:32 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"12592026/10/08 17:03:32 WARN Failed to register uploaded object key=nar/04izaqcyx3jpxp59i7xq034s23mm24hmg11gwmish1kmsh6ggzpv.nar.zst error="server returned 404: 404 page not found\n"12602026/10/08 17:03:32 WARN Failed to register uploaded object key=lidnsvabrr3s5zdlspnnvk6h5k6npfbg.ls error="server returned 404: 404 page not found\n"12612026/10/08 17:03:32 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12622026/10/08 17:03:32 INFO Signed narinfos id=1 count=312632026/10/08 17:03:32 INFO Uploading 3 narinfos12642026/10/08 17:03:32 WARN Failed to register uploaded object key=5h29g0f1sjnph3vf0nxcnwg1p8k5b6np.narinfo error="server returned 404: 404 page not found\n"12652026/10/08 17:03:32 WARN Failed to register uploaded object key=vbcambxab3m7xcv6imzvibskhbybkyz2.narinfo error="server returned 404: 404 page not found\n"12662026/10/08 17:03:32 INFO Received complete push request method=POST path=/api/pushes/1/complete12672026/10/08 17:03:32 WARN Failed to register uploaded object key=lidnsvabrr3s5zdlspnnvk6h5k6npfbg.narinfo error="server returned 404: 404 page not found\n"12682026/10/08 17:03:32 INFO Received push request method=POST path=/api/pushes12692026/10/08 17:03:32 INFO Completed push id=1 objects=8 duration=55.4135ms12702026/10/08 17:03:32 INFO Upload complete. (247ms)1271=== NAME TestClientPushesUseOnePush1272 client_pushes_test.go:97: Retrieved narinfo from S3:1273 StorePath: /private/var/tb/3/scratch/ec71b307c420129e/build/TestClientPushesUseOnePush3235103727/001/store/vbcambxab3m7xcv6imzvibskhbybkyz2-shared-dep1274 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1275 Compression: zstd1276 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821277 NarSize: 1361278 References: 1279 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1280 client_pushes_test.go:97: Retrieved narinfo from S3:1281 StorePath: /private/var/tb/3/scratch/ec71b307c420129e/build/TestClientPushesUseOnePush3235103727/001/store/lidnsvabrr3s5zdlspnnvk6h5k6npfbg-a1282 URL: nar/04izaqcyx3jpxp59i7xq034s23mm24hmg11gwmish1kmsh6ggzpv.nar.zst1283 Compression: zstd1284 NarHash: sha256:04izaqcyx3jpxp59i7xq034s23mm24hmg11gwmish1kmsh6ggzpv1285 NarSize: 2561286 References: /private/var/tb/3/scratch/ec71b307c420129e/build/TestClientPushesUseOnePush3235103727/001/store/vbcambxab3m7xcv6imzvibskhbybkyz2-shared-dep1287 CA: text:sha256:0a03bdca2g4gv5faljfb5jnx1n6v1kjqwjz93p1anyp785g51crs1288 client_pushes_test.go:97: Retrieved narinfo from S3:1289 StorePath: /private/var/tb/3/scratch/ec71b307c420129e/build/TestClientPushesUseOnePush3235103727/001/store/5h29g0f1sjnph3vf0nxcnwg1p8k5b6np-b1290 URL: nar/04izaqcyx3jpxp59i7xq034s23mm24hmg11gwmish1kmsh6ggzpv.nar.zst1291 Compression: zstd1292 NarHash: sha256:04izaqcyx3jpxp59i7xq034s23mm24hmg11gwmish1kmsh6ggzpv1293 NarSize: 2561294 References: /private/var/tb/3/scratch/ec71b307c420129e/build/TestClientPushesUseOnePush3235103727/001/store/vbcambxab3m7xcv6imzvibskhbybkyz2-shared-dep1295 CA: text:sha256:0a03bdca2g4gv5faljfb5jnx1n6v1kjqwjz93p1anyp785g51crs12962026/10/08 17:03:32 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12972026/10/08 17:03:32 INFO Uploading 5wj96lnx5p0wfr6j55spgcm04n9fbsz6-pinned-file.txt (128B)12982026/10/08 17:03:32 WARN Failed to register uploaded object key=5wj96lnx5p0wfr6j55spgcm04n9fbsz6.ls error="server returned 404: 404 page not found\n"1299--- PASS: TestClientPushesUseOnePush (9.07s)1300=== CONT TestPush_CompleteWaitsForCleanupOfThePush13012026/10/08 17:03:32 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13022026/10/08 17:03:32 INFO Signed narinfos id=1 count=113032026/10/08 17:03:32 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"13042026/10/08 17:03:32 INFO Uploading 1 narinfos13052026/10/08 17:03:32 INFO Received complete push request method=POST path=/api/pushes/1/complete13062026/10/08 17:03:32 WARN Failed to register uploaded object key=5wj96lnx5p0wfr6j55spgcm04n9fbsz6.narinfo error="server returned 404: 404 page not found\n"13072026/10/08 17:03:32 INFO Completed push id=1 objects=3 duration=18.187583ms13082026/10/08 17:03:32 INFO Upload complete. (179ms)13092026/10/08 17:03:32 INFO Received push request method=POST path=/api/pushes13102026/10/08 17:03:32 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)13112026/10/08 17:03:32 INFO Uploading isfxq5kjardbiyz1l9adadmc9z3xqamy-unpinned-file.txt (128B)13122026/10/08 17:03:32 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"13132026/10/08 17:03:32 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign13142026/10/08 17:03:32 WARN Failed to register uploaded object key=isfxq5kjardbiyz1l9adadmc9z3xqamy.ls error="server returned 404: 404 page not found\n"13152026/10/08 17:03:32 INFO Signed narinfos id=2 count=113162026/10/08 17:03:32 INFO Uploading 1 narinfos13172026/10/08 17:03:32 INFO Received complete push request method=POST path=/api/pushes/2/complete13182026/10/08 17:03:32 WARN Failed to register uploaded object key=isfxq5kjardbiyz1l9adadmc9z3xqamy.narinfo error="server returned 404: 404 page not found\n"13192026/10/08 17:03:32 INFO Completed push id=2 objects=3 duration=1.29575ms13202026/10/08 17:03:32 INFO Upload complete. (103ms)13212026/10/08 17:03:32 INFO Starting cleanup of old closures method=DELETE path=/api/closures13222026/10/08 17:03:32 INFO Garbage collection started13232026/10/08 17:03:32 INFO Received push request method=POST path=/api/pushes13242026/10/08 17:03:32 INFO Aborted multipart uploads count=0 kept=013252026/10/08 17:03:32 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)13262026/10/08 17:03:32 INFO Uploading fybv6l3miwyv2dr257midza00if80v5w-top (264B)13272026/10/08 17:03:32 INFO Uploading 97pir810q7l503bnn2zwqa1byasinp5v-shared-dep (136B)13282026/10/08 17:03:32 WARN Force mode enabled - objects will be deleted immediately without grace period13292026/10/08 17:03:32 WARN Failed to register uploaded object key=97pir810q7l503bnn2zwqa1byasinp5v.ls error="server returned 404: 404 page not found\n"13302026/10/08 17:03:32 WARN Failed to register uploaded object key=fybv6l3miwyv2dr257midza00if80v5w.ls error="server returned 404: 404 page not found\n"13312026/10/08 17:03:32 WARN Failed to register uploaded object key=nar/0kiwx3k6rl56y0m9lh4rv7khbaif4xykkmaq0xqrfdby3rhs722b.nar.zst error="server returned 404: 404 page not found\n"13322026/10/08 17:03:32 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13332026/10/08 17:03:32 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"13342026/10/08 17:03:32 INFO Signed narinfos id=1 count=213352026/10/08 17:03:32 INFO Uploading 2 narinfos13362026/10/08 17:03:32 WARN Failed to register uploaded object key=97pir810q7l503bnn2zwqa1byasinp5v.narinfo error="server returned 404: 404 page not found\n"13372026/10/08 17:03:32 INFO Received complete push request method=POST path=/api/pushes/1/complete13382026/10/08 17:03:32 WARN Failed to register uploaded object key=fybv6l3miwyv2dr257midza00if80v5w.narinfo error="server returned 404: 404 page not found\n"13392026/10/08 17:03:32 INFO Completed push id=1 objects=6 duration=22.7835ms13402026/10/08 17:03:33 INFO Upload complete. (184ms)1341=== NAME TestClientSharedPathCommittedMidPush1342 client_integration_test.go:680: Retrieved narinfo from S3:1343 StorePath: /private/var/tb/3/scratch/ec71b307c420129e/build/TestClientSharedPathCommittedMidPush1166644602/001/store/97pir810q7l503bnn2zwqa1byasinp5v-shared-dep1344 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1345 Compression: zstd1346 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821347 NarSize: 1361348 References: 1349 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1350 client_integration_test.go:680: Retrieved narinfo from S3:1351 StorePath: /private/var/tb/3/scratch/ec71b307c420129e/build/TestClientSharedPathCommittedMidPush1166644602/001/store/fybv6l3miwyv2dr257midza00if80v5w-top1352 URL: nar/0kiwx3k6rl56y0m9lh4rv7khbaif4xykkmaq0xqrfdby3rhs722b.nar.zst1353 Compression: zstd1354 NarHash: sha256:0kiwx3k6rl56y0m9lh4rv7khbaif4xykkmaq0xqrfdby3rhs722b1355 NarSize: 2641356 References: /private/var/tb/3/scratch/ec71b307c420129e/build/TestClientSharedPathCommittedMidPush1166644602/001/store/97pir810q7l503bnn2zwqa1byasinp5v-shared-dep1357 CA: text:sha256:03drhlblv910kcwd17s3i8ih890isjpb8gx81kdv1n9dwichhan413582026/10/08 17:03:33 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=013592026/10/08 17:03:33 INFO Vacuumed table table=pending_closures1360--- PASS: TestClientSharedPathCommittedMidPush (8.83s)13612026/10/08 17:03:33 INFO Vacuumed table table=pending_objects1362=== CONT TestPush_RepeatedRootCommitsOnce13632026/10/08 17:03:33 INFO Vacuumed table table=multipart_uploads13642026/10/08 17:03:33 INFO Vacuumed table table=closures13652026/10/08 17:03:33 INFO Vacuumed table table=objects1366=== NAME TestClientWithDependencies1367 client_integration_test.go:613: Built derivation: /private/var/tb/3/scratch/ec71b307c420129e/build/TestClientWithDependencies2365099125/001/store/xqv3z98yzfcz89k2nwji71fzydnq6ap9-test-script1368 client_integration_test.go:615: Found 1 dependencies (including self)1369=== NAME TestClientMultipleUploads1370 client_integration_test.go:358: Created store path 0: /private/var/tb/3/scratch/ec71b307c420129e/build/TestClientMultipleUploads3109041811/001/store/8hrndaapswhq7fm021982ysjqv6xiqcr-test-file-0.txt13712026/10/08 17:03:33 INFO Received push request method=POST path=/api/pushes1372 client_integration_test.go:358: Created store path 1: /private/var/tb/3/scratch/ec71b307c420129e/build/TestClientMultipleUploads3109041811/001/store/nkl9s3ra7gdcn3pbk7kj84cw49c142pn-test-file-1.txt13732026/10/08 17:03:33 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)13742026/10/08 17:03:33 INFO Uploading xqv3z98yzfcz89k2nwji71fzydnq6ap9-test-script (136B)13752026/10/08 17:03:33 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"13762026/10/08 17:03:33 WARN Failed to register uploaded object key=xqv3z98yzfcz89k2nwji71fzydnq6ap9.ls error="server returned 404: 404 page not found\n"13772026/10/08 17:03:33 WARN Failed to register uploaded object key=log/fgrhwrpnawlayl026n4x2dv9w54mjs0y-test-script.drv error="server returned 404: 404 page not found\n"13782026/10/08 17:03:33 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign1379 client_integration_test.go:358: Created store path 2: /private/var/tb/3/scratch/ec71b307c420129e/build/TestClientMultipleUploads3109041811/001/store/kj5hm0rjxnjrdbpwh3hj2vqjwh0dj9ig-test-file-2.txt13802026/10/08 17:03:33 INFO Signed narinfos id=1 count=113812026/10/08 17:03:33 INFO Uploading 1 narinfos13822026/10/08 17:03:33 INFO Received complete push request method=POST path=/api/pushes/1/complete13832026/10/08 17:03:33 WARN Failed to register uploaded object key=xqv3z98yzfcz89k2nwji71fzydnq6ap9.narinfo error="server returned 404: 404 page not found\n"13842026/10/08 17:03:33 INFO Completed push id=1 objects=4 duration=28.962583ms13852026/10/08 17:03:33 INFO Upload complete. (212ms)1386=== NAME TestClientWithDependencies1387 client_integration_test.go:617: Skipping nix copy test - isolated store (/private/var/tb/3/scratch/ec71b307c420129e/build/TestClientWithDependencies2365099125/001/store) requires matching store prefix13882026/10/08 17:03:33 INFO Received push request method=POST path=/api/pushes13892026/10/08 17:03:33 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)13902026/10/08 17:03:33 INFO Uploading nkl9s3ra7gdcn3pbk7kj84cw49c142pn-test-file-1.txt (160B)13912026/10/08 17:03:33 INFO Uploading 8hrndaapswhq7fm021982ysjqv6xiqcr-test-file-0.txt (160B)13922026/10/08 17:03:33 INFO Uploading kj5hm0rjxnjrdbpwh3hj2vqjwh0dj9ig-test-file-2.txt (160B)13932026/10/08 17:03:33 WARN Failed to register uploaded object key=8hrndaapswhq7fm021982ysjqv6xiqcr.ls error="server returned 404: 404 page not found\n"13942026/10/08 17:03:33 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"13952026/10/08 17:03:33 WARN Failed to register uploaded object key=nkl9s3ra7gdcn3pbk7kj84cw49c142pn.ls error="server returned 404: 404 page not found\n"13962026/10/08 17:03:33 WARN Failed to register uploaded object key=kj5hm0rjxnjrdbpwh3hj2vqjwh0dj9ig.ls error="server returned 404: 404 page not found\n"13972026/10/08 17:03:33 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"1398=== NAME TestClientIntegration1399 client_integration_test.go:286: Created store path: /private/var/tb/3/scratch/ec71b307c420129e/build/TestClientIntegration1864514543/002/store/4292cgj8mrf2xbbd2lgbj3b4fj4smg3z-test-file.txt14002026/10/08 17:03:33 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14012026/10/08 17:03:33 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"14022026/10/08 17:03:33 INFO Signed narinfos id=1 count=314032026/10/08 17:03:33 INFO Uploading 3 narinfos1404--- PASS: TestClientWithDependencies (8.96s)1405=== CONT TestPush_CompleteCommitsEveryRoot14062026/10/08 17:03:33 WARN Failed to register uploaded object key=8hrndaapswhq7fm021982ysjqv6xiqcr.narinfo error="server returned 404: 404 page not found\n"14072026/10/08 17:03:33 WARN Failed to register uploaded object key=nkl9s3ra7gdcn3pbk7kj84cw49c142pn.narinfo error="server returned 404: 404 page not found\n"14082026/10/08 17:03:33 INFO Received complete push request method=POST path=/api/pushes/1/complete14092026/10/08 17:03:33 WARN Failed to register uploaded object key=kj5hm0rjxnjrdbpwh3hj2vqjwh0dj9ig.narinfo error="server returned 404: 404 page not found\n"14102026/10/08 17:03:33 INFO Completed push id=1 objects=9 duration=35.772709ms14112026/10/08 17:03:33 INFO Upload complete. (180ms)1412=== NAME TestClientMultipleUploads1413 client_integration_test.go:369: Uploaded 3 paths in 211.425042ms14142026/10/08 17:03:33 INFO Received uploads request method=POST path=/api/pending_closures14152026/10/08 17:03:33 INFO Received push request method=POST path=/api/pushes14162026/10/08 17:03:33 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14172026/10/08 17:03:33 INFO Uploading 4292cgj8mrf2xbbd2lgbj3b4fj4smg3z-test-file.txt (152B)1418--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (7.82s)1419=== CONT TestDeduplicatedObjectsRecordedAsPending14202026/10/08 17:03:33 WARN Failed to register uploaded object key=4292cgj8mrf2xbbd2lgbj3b4fj4smg3z.ls error="server returned 404: 404 page not found\n"14212026/10/08 17:03:33 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14222026/10/08 17:03:33 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"14232026/10/08 17:03:33 INFO Signed narinfos id=1 count=114242026/10/08 17:03:33 INFO Uploading 1 narinfos1425--- PASS: TestClientMultipleUploads (8.54s)1426=== CONT TestSkippedUploadsHandler14272026/10/08 17:03:33 INFO Client skipped oversized paths paths=3 nar_bytes=50000000001428--- PASS: TestSkippedUploadsHandler (0.01s)1429=== CONT TestPendingClosureWriteTimeout1430=== RUN TestPendingClosureWriteTimeout/empty1431=== PAUSE TestPendingClosureWriteTimeout/empty1432=== RUN TestPendingClosureWriteTimeout/400_objects1433=== PAUSE TestPendingClosureWriteTimeout/400_objects1434=== RUN TestPendingClosureWriteTimeout/670k_objects1435=== PAUSE TestPendingClosureWriteTimeout/670k_objects1436=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1437=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1438=== CONT TestProxyWriteTimeout1439=== RUN TestProxyWriteTimeout/narinfo1440=== PAUSE TestProxyWriteTimeout/narinfo1441=== RUN TestProxyWriteTimeout/1_GiB_nar1442=== PAUSE TestProxyWriteTimeout/1_GiB_nar1443=== RUN TestProxyWriteTimeout/10_GiB_nar1444=== PAUSE TestProxyWriteTimeout/10_GiB_nar1445=== RUN TestProxyWriteTimeout/unknown_size1446=== PAUSE TestProxyWriteTimeout/unknown_size1447=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle14482026/10/08 17:03:33 INFO Received complete push request method=POST path=/api/pushes/1/complete14492026/10/08 17:03:33 WARN Failed to register uploaded object key=4292cgj8mrf2xbbd2lgbj3b4fj4smg3z.narinfo error="server returned 404: 404 page not found\n"14502026/10/08 17:03:33 INFO Completed push id=1 objects=3 duration=21.168541ms14512026/10/08 17:03:33 INFO Upload complete. (209ms)14522026/10/08 17:03:33 INFO All 1 paths already cached1453=== NAME TestClientIntegration1454 client_integration_test.go:312: Retrieved narinfo from S3:1455 StorePath: /private/var/tb/3/scratch/ec71b307c420129e/build/TestClientIntegration1864514543/002/store/4292cgj8mrf2xbbd2lgbj3b4fj4smg3z-test-file.txt1456 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1457 Compression: zstd1458 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11459 NarSize: 1521460 References: 1461 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11462 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)1463 client_integration_test.go:313: Decompressed .ls content (64 bytes):1464 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1465 client_integration_test.go:316: Testing garbage collection...14662026/10/08 17:03:33 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14672026/10/08 17:03:33 INFO Starting cleanup of old closures method=DELETE path=/api/closures14682026/10/08 17:03:33 INFO Garbage collection started14692026/10/08 17:03:33 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst1470--- PASS: TestCompleteMultipartUnregistered (7.31s)1471=== CONT TestLeadEndsOnShutdown14722026/10/08 17:03:33 INFO Aborted multipart uploads count=0 kept=014732026/10/08 17:03:33 WARN Force mode enabled - objects will be deleted immediately without grace period14742026/10/08 17:03:34 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=014752026/10/08 17:03:34 INFO Vacuumed table table=pending_closures14762026/10/08 17:03:34 INFO Vacuumed table table=pending_objects14772026/10/08 17:03:34 INFO Vacuumed table table=multipart_uploads14782026/10/08 17:03:34 INFO Vacuumed table table=closures14792026/10/08 17:03:34 INFO Vacuumed table table=objects14802026/10/08 17:03:34 INFO Received uploads request method=POST path=/api/pending_closures14812026/10/08 17:03:34 INFO Received uploads request method=POST path=/api/pending_closures14822026/10/08 17:03:34 INFO Received uploads request method=POST path=/api/pending_closures14832026/10/08 17:03:34 INFO Received uploads request method=POST path=/api/pending_closures14842026/10/08 17:03:34 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=014852026/10/08 17:03:34 INFO Received create pin request method=POST path=/api/pins/myapp14862026/10/08 17:03:34 INFO Created/updated pin name=myapp store_path=/private/var/tb/3/scratch/ec71b307c420129e/build/TestPinProtectsFromGC3221096886/001/store/5wj96lnx5p0wfr6j55spgcm04n9fbsz6-pinned-file.txt narinfo_key=5wj96lnx5p0wfr6j55spgcm04n9fbsz6.narinfo14872026/10/08 17:03:34 INFO Starting cleanup of old closures method=DELETE path=/api/closures14882026/10/08 17:03:34 INFO Garbage collection started14892026/10/08 17:03:34 INFO Aborted multipart uploads count=0 kept=014902026/10/08 17:03:34 WARN Force mode enabled - objects will be deleted immediately without grace period14912026/10/08 17:03:34 INFO Received cleanup request method=DELETE path=/api/pending_closures14922026/10/08 17:03: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=014932026/10/08 17:03:35 INFO Vacuumed table table=pending_closures14942026/10/08 17:03:35 INFO Vacuumed table table=pending_objects14952026/10/08 17:03:35 INFO Aborted multipart uploads count=0 kept=014962026/10/08 17:03:35 INFO Vacuumed table table=multipart_uploads14972026/10/08 17:03:35 INFO Vacuumed table table=closures14982026/10/08 17:03:35 INFO Vacuumed table table=objects14992026/10/08 17:03:35 INFO Received uploads request method=POST path=/api/pending_closures15002026/10/08 17:03:35 INFO Received cleanup request method=DELETE path=/api/pending_closures15012026/10/08 17:03:35 INFO Aborted multipart uploads count=1 kept=015022026/10/08 17:03:35 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete15032026-10-08 17:03:35.286 UTC [67920] ERROR: Closure does not exist: id=115042026-10-08 17:03:35.286 UTC [67920] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE15052026-10-08 17:03:35.286 UTC [67920] STATEMENT: -- name: CommitPendingClosure :one1506 SELECT commit_pending_closure($1::bigint)::bigint1507 1508--- PASS: TestService_cleanupPendingClosuresHandler (7.03s)1509=== CONT TestGCMetrics1510=== RUN TestService_RequireScope_OIDC/builder_may_write1511=== PAUSE TestService_RequireScope_OIDC/builder_may_write1512=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1513=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1514=== RUN TestService_RequireScope_OIDC/ops_may_admin1515=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1516=== RUN TestService_RequireScope_OIDC/ops_may_not_write1517=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1518=== RUN TestService_RequireScope_OIDC/reader_may_not_write1519=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1520=== RUN TestService_RequireScope_OIDC/static_token_may_admin1521=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1522=== RUN TestService_RequireScope_OIDC/static_token_may_write1523=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1524=== RUN TestService_RequireScope_OIDC/reader_may_read1525=== PAUSE TestService_RequireScope_OIDC/reader_may_read1526=== RUN TestService_RequireScope_OIDC/writer_implies_read1527=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1528=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1529=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1530=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1531=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc1532=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1533=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1534=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1535=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1536=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1537=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1538=== CONT TestGCBugBareHashReferences1539{"timestamp":"2026-10-08T17:03:35.624761Z","level":"ERROR","duration":"130.6485ms","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"<?xml version=\\\"1.0\\\" encoding=\\\"UTF-8\\\"?><Error><Code>InternalError</Code><Message>We encountered an internal error, please try again.</Message></Error>\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(8)"}1540{"timestamp":"2026-10-08T17:03:35.627086Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"f1b4a1b9-6c78-44ea-b956-912d93df8d8e","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"PUT","uri":"/bucket56/","status_code":500,"suppressed_errors":0,"duration_ms":132,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":501,"threadName":"rustfs-worker","threadId":"ThreadId(8)"}1541{"timestamp":"2026-10-08T17:03:35.631559Z","level":"ERROR","message":"Heal object operation failed","event":"heal_object_result","component":"heal","subsystem":"object","task_id":"b5ef46b5-2e60-450d-bf4e-7a1bc447762a","bucket":".rustfs.sys","object":"buckets/.usage.v2.json.bkp","result":"failed","error":"Storage error: Io error: Too many open files (os error 24)","target":"rustfs::heal::task","filename":"crates/heal/src/heal/task/heal_object.rs","line_number":261,"threadName":"rustfs-worker","threadId":"ThreadId(9)"}1542{"timestamp":"2026-10-08T17:03:35.631839Z","level":"ERROR","message":"Heal scheduler task failed","event":"heal_scheduler_state","component":"heal","subsystem":"manager","task_id":"b5ef46b5-2e60-450d-bf4e-7a1bc447762a","heal_type":"object","set":"pool_0_set_0","state":"task_failed","error":"Storage error: Io error: Too many open files (os error 24)","target":"rustfs::heal::manager","filename":"crates/heal/src/heal/manager/scheduler.rs","line_number":269,"threadName":"rustfs-worker","threadId":"ThreadId(9)"}1543--- PASS: TestDeleteClosuresRacingPins (12.63s)1544=== CONT TestGCAdvisoryLockBlocksConcurrentRun1545{"timestamp":"2026-10-08T17:03:35.707653Z","level":"ERROR","duration":"186.131875ms","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"<?xml version=\\\"1.0\\\" encoding=\\\"UTF-8\\\"?><Error><Code>InternalError</Code><Message>We encountered an internal error, please try again.</Message></Error>\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(4)"}1546=== NAME TestService_verifyS3Integrity1547 uploads_test.go:403: expected http status 200 for part 7, got 5001548 uploads_test.go:403: no ETag in response for part 71549=== NAME TestService_createPendingClosureHandler1550 uploads_test.go:307: expected http status 200 for part 5, got 5001551 uploads_test.go:307: no ETag in response for part 51552{"timestamp":"2026-10-08T17:03:35.728611Z","level":"ERROR","duration":"124.584ms","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"<?xml version=\\\"1.0\\\" encoding=\\\"UTF-8\\\"?><Error><Code>InternalError</Code><Message>We encountered an internal error, please try again.</Message></Error>\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(11)"}1553=== NAME TestOrphanedObjectsGCStressTest1554 orphaned_objects_gc_test.go:503: Stress test completed successfully:1555 orphaned_objects_gc_test.go:504: - Active objects preserved: 201556 orphaned_objects_gc_test.go:505: - Objects deleted: 2101557 orphaned_objects_gc_test.go:506: - Total GC'd: 2101558--- PASS: TestOrphanedObjectsGCStressTest (18.23s)1559=== CONT TestReadRedirectNar15602026/10/08 17:03:35 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=01561=== NAME TestClientIntegration1562 client_integration_test.go:323: Objects in database after GC:1563 client_integration_test.go:323: Successfully deleted all objects with GC --force1564--- PASS: TestClientIntegration (10.78s)1565=== CONT TestReadRedirectUsesPublicS3URL15662026/10/08 17:03:36 INFO Received complete multipart upload request method=POST path=/api/multipart/complete15672026/10/08 17:03:36 ERROR Failed to complete multipart upload error="One or more of the specified parts could not be found. The part may not have been uploaded, or the specified entity tag may not match the part's entity tag." object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=MzQ2Njc2OWUtOTMxYy00YjBjLTg5ZjEtOTQ3OGM5ODJjNzNjLjlhNjlkYmIxLWU1OGEtNGQ1Ni04MzQ0LTE5MGY3YmU4MzNlMngxNzkxNDc5MDE0Mjc2ODk2MDAw1568=== NAME TestService_verifyS3Integrity1569 uploads_test.go:403: unexpected http status=500 body=failed to complete multipart upload: One or more of the specified parts could not be found. The part may not have been uploaded, or the specified entity tag may not match the part's entity tag.1570 1571 1572--- FAIL: TestService_verifyS3Integrity (8.78s)1573=== CONT TestReadProxyRangeRequest1574--- PASS: TestObjectStatsLargeCommit (17.21s)1575=== CONT TestReadRedirectKeepsNarinfoProxied15762026/10/08 17:03:36 INFO Received complete multipart upload request method=POST path=/api/multipart/complete15772026/10/08 17:03:36 ERROR Failed to complete multipart upload error="One or more of the specified parts could not be found. The part may not have been uploaded, or the specified entity tag may not match the part's entity tag." object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=MzQ2Njc2OWUtOTMxYy00YjBjLTg5ZjEtOTQ3OGM5ODJjNzNjLmVkMDgzODQ2LWMzMDktNDU2NC1hMWNkLWQ3YjY2MDNiMWNlZHgxNzkxNDc5MDE0NjkwOTgxMDAw1578=== NAME TestService_createPendingClosureHandler1579 uploads_test.go:307: unexpected http status=500 body=failed to complete multipart upload: One or more of the specified parts could not be found. The part may not have been uploaded, or the specified entity tag may not match the part's entity tag.1580 1581 1582--- FAIL: TestService_createPendingClosureHandler (8.51s)1583=== CONT TestService_ReadAuthMiddleware1584--- PASS: TestCacheStatsHandler (7.19s)1585=== CONT TestService_AuthMiddleware_OIDC15862026/10/08 17:03:36 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54444/oidc1587=== NAME TestClientCADerivations1588 client_ca_test.go:136: Built CA derivation: /private/var/tb/3/scratch/ec71b307c420129e/build/TestClientCADerivations2321397227/001/store/s6lwpkwv38nn4nk43fqgd2diwj7wrwih-ca-test1589--- PASS: TestService_ReadScope_PublicByDefault (7.06s)1590=== CONT TestService_AuthMiddleware_MTLSBoundSubjects1591=== NAME TestPinProtectsFromGC1592 client_integration_test.go:840: Pin successfully protected closure from garbage collection1593=== NAME TestClientCADerivations1594 client_ca_test.go:139: Found 1 dependencies (including self)1595=== CONT TestService_Rustfstest1596--- PASS: TestPinProtectsFromGC (13.34s)15972026/10/08 17:03:37 INFO Received push request method=POST path=/api/pushes15982026/10/08 17:03:37 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15992026/10/08 17:03:37 INFO Uploading s6lwpkwv38nn4nk43fqgd2diwj7wrwih-ca-test (144B)16002026/10/08 17:03:37 WARN Failed to register uploaded object key=s6lwpkwv38nn4nk43fqgd2diwj7wrwih.ls error="server returned 404: 404 page not found\n"16012026/10/08 17:03:37 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"16022026/10/08 17:03:37 WARN Failed to register uploaded object key=log/2l2009r81wvmmvqcrb6v3v4l592yqxwi-ca-test.drv error="server returned 404: 404 page not found\n"16032026/10/08 17:03:37 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16042026/10/08 17:03:37 INFO Signed narinfos id=1 count=116052026/10/08 17:03:37 INFO Uploading 1 narinfos16062026/10/08 17:03:37 INFO Received push request method=POST path=/api/pushes16072026/10/08 17:03:37 INFO Received complete push request method=POST path=/api/pushes/1/complete16082026/10/08 17:03:37 WARN Failed to register uploaded object key=s6lwpkwv38nn4nk43fqgd2diwj7wrwih.narinfo error="server returned 404: 404 page not found\n"16092026/10/08 17:03:37 INFO Completed push id=1 objects=4 duration=36.520417ms16102026/10/08 17:03:37 INFO Upload complete. (320ms)1611=== NAME TestClientCADerivations1612 client_ca_test.go:180: Narinfo contains CA field: StorePath: /private/var/tb/3/scratch/ec71b307c420129e/build/TestClientCADerivations2321397227/001/store/s6lwpkwv38nn4nk43fqgd2diwj7wrwih-ca-test1613 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1614 Compression: zstd1615 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1616 NarSize: 1441617 References: 1618 Deriver: /private/var/tb/3/scratch/ec71b307c420129e/build/TestClientCADerivations2321397227/001/store/2l2009r81wvmmvqcrb6v3v4l592yqxwi-ca-test.drv1619 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1620 client_ca_test.go:185: Checking for realisation files in S3...1621 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1622 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache1623--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (7.20s)1624=== CONT TestParseSize1625--- PASS: TestParseSize (0.00s)1626=== CONT TestLeadElectsOneAndHandsOver1627=== NAME TestClientCADerivations1628 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket56?endpoint=http://localhost:54165®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/private/var/tb/3/scratch/ec71b307c420129e/build/TestClientCADerivations2321397227/001/store'1629 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 11630--- PASS: TestClientCADerivations (8.67s)1631=== CONT TestLeadIncumbentAnnouncesAtOnce16322026/10/08 17:03:37 INFO Received uploads request method=POST path=/api/pending_closures16332026/10/08 17:03:37 INFO Received uploads request method=POST path=/api/pending_closures16342026/10/08 17:03:38 INFO Received push request method=POST path=/api/pushes16352026/10/08 17:03:38 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16362026/10/08 17:03:38 INFO Signed narinfos id=1 count=116372026/10/08 17:03:38 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16382026/10/08 17:03:38 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16392026/10/08 17:03:38 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"16402026/10/08 17:03:38 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16412026/10/08 17:03:38 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"16422026/10/08 17:03:38 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16432026/10/08 17:03:38 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=116442026/10/08 17:03:38 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16452026/10/08 17:03:38 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo1646--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (7.44s)1647=== CONT TestReadProxyRootRedirectsToIndexHTML1648=== RUN TestPush_RejectsBadRequests/no_roots1649=== PAUSE TestPush_RejectsBadRequests/no_roots1650=== RUN TestPush_RejectsBadRequests/no_objects1651=== PAUSE TestPush_RejectsBadRequests/no_objects1652=== RUN TestPush_RejectsBadRequests/bad_root1653=== PAUSE TestPush_RejectsBadRequests/bad_root1654=== RUN TestPush_RejectsBadRequests/root_not_in_objects1655=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1656=== CONT TestReadProxyDisabled16572026/10/08 17:03:38 INFO Received push request method=POST path=/api/pushes16582026/10/08 17:03:39 INFO Received complete push request method=POST path=/api/pushes/1/complete16592026/10/08 17:03:39 INFO Completed push id=1 objects=4 duration=49.974958ms16602026/10/08 17:03:39 INFO Received push request method=POST path=/api/pushes16612026/10/08 17:03:39 INFO Aborted multipart uploads count=0 kept=016622026/10/08 17:03:39 WARN Force mode enabled - objects will be deleted immediately without grace period16632026/10/08 17:03:39 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=2 objects-deleted-after-grace-period=2 objects-failed-to-delete=016642026/10/08 17:03:39 INFO Received push request method=POST path=/api/pushes16652026/10/08 17:03:39 INFO Vacuumed table table=pending_closures16662026/10/08 17:03:39 INFO Vacuumed table table=pending_objects16672026/10/08 17:03:39 INFO Vacuumed table table=multipart_uploads16682026/10/08 17:03:39 INFO Vacuumed table table=closures16692026/10/08 17:03:39 INFO Vacuumed table table=objects16702026-10-08 17:03:39.474 UTC [68094] ERROR: could not obtain lock on row in relation "closures"16712026-10-08 17:03:39.474 UTC [68094] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT16722026-10-08 17:03:39.477 UTC [68094] ERROR: could not obtain lock on row in relation "closures"16732026-10-08 17:03:39.477 UTC [68094] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT16742026/10/08 17:03:39 INFO Received complete push request method=POST path=/api/pushes/2/complete16752026-10-08 17:03:39.486 UTC [68094] ERROR: could not obtain lock on row in relation "closures"16762026-10-08 17:03:39.486 UTC [68094] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT16772026-10-08 17:03:39.494 UTC [68094] ERROR: could not obtain lock on row in relation "closures"16782026-10-08 17:03:39.494 UTC [68094] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT16792026-10-08 17:03:39.500 UTC [68094] ERROR: could not obtain lock on row in relation "closures"16802026-10-08 17:03:39.500 UTC [68094] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT16812026/10/08 17:03:39 INFO Completed push id=2 objects=4 duration=66.702542ms1682--- PASS: TestPush_RootsAreLockedInByteOrder (7.12s)1683=== CONT TestConnectWaitsForAPeerMigration1684--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (7.20s)1685=== CONT TestReadProxyConditionalGet16862026/10/08 17:03:39 INFO Received push request method=POST path=/api/pushes16872026/10/08 17:03:40 INFO Received complete multipart upload request method=POST path=/api/multipart/complete16882026/10/08 17:03:40 INFO Received push request method=POST path=/api/pushes16892026-10-08 17:03:40.123 UTC [68102] ERROR: Push does not exist: id=116902026-10-08 17:03:40.123 UTC [68102] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE16912026-10-08 17:03:40.123 UTC [68102] STATEMENT: SELECT commit_push($1)1692--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (7.52s)1693=== CONT TestResolveDBConnectionString1694=== RUN TestResolveDBConnectionString/flag_wins1695=== PAUSE TestResolveDBConnectionString/flag_wins1696=== RUN TestResolveDBConnectionString/file_when_flag_empty1697=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1698=== RUN TestResolveDBConnectionString/missing_file_is_an_error1699=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1700=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1701=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1702=== RUN TestResolveDBConnectionString/nothing_configured1703=== PAUSE TestResolveDBConnectionString/nothing_configured1704=== CONT TestService_AuthMiddleware_MTLSProxyHeader17052026/10/08 17:03:40 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=MzQ2Njc2OWUtOTMxYy00YjBjLTg5ZjEtOTQ3OGM5ODJjNzNjLmNiNjBlMjkwLTJiNjQtNGVmNy1iYzk2LTQwZDgyYzRiOGNlOXgxNzkxNDc5MDE3Nzg1MTU3MDAw parts=1217062026/10/08 17:03:40 INFO Received uploads request method=POST path=/api/pending_closures17072026/10/08 17:03:40 INFO Received complete push request method=POST path=/api/pushes/1/complete17082026/10/08 17:03:40 INFO Received uploads request method=POST path=/api/pending_closures17092026/10/08 17:03:40 INFO Completed push id=1 objects=4 duration=53.313417ms1710--- PASS: TestPush_RepeatedRootCommitsOnce (7.30s)1711=== CONT TestReadProxyOutlastsServerWriteTimeout17122026/10/08 17:03:40 INFO Received push request method=POST path=/api/pushes17132026/10/08 17:03:40 INFO Received complete push request method=POST path=/api/pushes/1/complete17142026/10/08 17:03:40 INFO Completed push id=1 objects=6 duration=70.995459ms1715--- PASS: TestPush_CompleteCommitsEveryRoot (7.29s)1716=== CONT TestPresignedUploadRegisteredBeforeCommit17172026/10/08 17:03:41 INFO Received uploads request method=POST path=/api/pending_closures1718--- PASS: TestDeduplicatedObjectsRecordedAsPending (7.42s)1719=== CONT TestCompletedNarNotReofferedAcrossClosures17202026/10/08 17:03:41 INFO Received uploads request method=POST path=/api/pending_closures17212026/10/08 17:03:42 INFO lead: acquired remote=192.0.2.1:123417222026/10/08 17:03:42 INFO Received complete multipart upload request method=POST path=/api/multipart/complete17232026/10/08 17:03:42 INFO Aborted multipart uploads count=0 kept=017242026/10/08 17:03:42 WARN Force mode enabled - objects will be deleted immediately without grace period17252026/10/08 17:03:42 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=017262026/10/08 17:03:42 INFO Vacuumed table table=pending_closures17272026/10/08 17:03:42 INFO Vacuumed table table=pending_objects17282026/10/08 17:03:42 INFO Vacuumed table table=multipart_uploads17292026/10/08 17:03:42 INFO Vacuumed table table=closures17302026/10/08 17:03:42 INFO Vacuumed table table=objects1731--- PASS: TestGCMetrics (7.25s)1732=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale17332026/10/08 17:03:42 ERROR failed to check GC advisory lock error="query pg_locks: failed to connect to `user=_tribuchetbld3 database=niks3`: /nonexistent/.s.PGSQL.5432 (/nonexistent): dial error: dial unix /nonexistent/.s.PGSQL.5432: connect: no such file or directory"1734--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (7.17s)1735=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh17362026/10/08 17:03:42 INFO Received complete multipart upload request method=POST path=/api/multipart/complete17372026/10/08 17:03:42 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=MzQ2Njc2OWUtOTMxYy00YjBjLTg5ZjEtOTQ3OGM5ODJjNzNjLjI3NDJkNWMxLWZiNjMtNDRhOS1iZjIyLTBiZDUwNjRhNjA5NXgxNzkxNDc5MDIwMzQ2ODcwMDAw error="Get \"http://127.0.0.1:1/bucket60/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"17382026/10/08 17:03:42 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=MzQ2Njc2OWUtOTMxYy00YjBjLTg5ZjEtOTQ3OGM5ODJjNzNjLmJiNjk2NGM5LTE0NWYtNDQ1Yi1hZjNlLTA1NWQwN2Y3OTNkY3gxNzkxNDc5MDIwMjkyMzAwMDAw parts=1217392026/10/08 17:03:42 INFO Received cleanup request method=DELETE path=/api/pending_closures17402026/10/08 17:03:42 INFO Aborted multipart uploads count=1 kept=01741--- PASS: TestRedundantMultipartUpload (12.54s)1742=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows17432026/10/08 17:03:43 INFO lead: released remote=192.0.2.1:12341744--- PASS: TestLeadEndsOnShutdown (9.11s)1745=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check1746--- PASS: TestGCBugBareHashReferences (8.03s)1747=== CONT TestParseSingleRange/none1748=== CONT TestParseSingleRange/end_clamped_to_size1749=== CONT TestParseSingleRange/start_far_past_EOF1750=== CONT TestParseSingleRange/start_past_EOF1751=== CONT TestParseSingleRange/single_byte1752=== CONT TestParseSingleRange/suffix_exceeds_size1753=== CONT TestParseSingleRange/suffix1754=== CONT TestParseSingleRange/multi-range_ignored1755=== CONT TestParseSingleRange/malformed_no_dash1756=== CONT TestParseSingleRange/closed1757=== CONT TestParseSingleRange/open-ended1758=== CONT TestParseSingleRange/malformed_end_before_start1759=== CONT TestParseSingleRange/unknown_unit1760=== CONT TestIsValidCachePath/narinfo1761=== CONT TestIsValidCachePath/traversal_parent1762=== CONT TestIsValidCachePath/index.html1763=== CONT TestIsValidCachePath/nix-cache-info1764=== CONT TestIsValidCachePath/realisation1765=== CONT TestIsValidCachePath/log1766=== CONT TestIsValidCachePath/ls1767=== CONT TestIsValidCachePath/nar_uncompressed1768=== CONT TestIsValidCachePath/nar_bz21769=== CONT TestIsValidCachePath/nar_xz1770=== CONT TestIsValidCachePath/nar_zst1771=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1772=== CONT TestIsValidCachePath/empty1773=== CONT TestIsValidCachePath/short_hash1774=== CONT TestIsValidCachePath/wrong_extension1775=== CONT TestIsValidCachePath/leading_slash1776=== CONT TestIsValidCachePath/invalid_char_u1777=== CONT TestIsValidCachePath/random_path1778=== CONT TestIsValidCachePath/invalid_char_e1779=== CONT TestIsValidCachePath/traversal_in_middle1780--- PASS: TestIsValidCachePath (0.01s)1781 --- PASS: TestIsValidCachePath/narinfo (0.00s)1782 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1783 --- PASS: TestIsValidCachePath/index.html (0.00s)1784 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1785 --- PASS: TestIsValidCachePath/realisation (0.00s)1786 --- PASS: TestIsValidCachePath/log (0.00s)1787 --- PASS: TestIsValidCachePath/ls (0.00s)1788 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1789 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1790 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1791 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1792 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1793 --- PASS: TestIsValidCachePath/empty (0.00s)1794 --- PASS: TestIsValidCachePath/short_hash (0.00s)1795 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1796 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1797 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1798 --- PASS: TestIsValidCachePath/random_path (0.00s)1799 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1800 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1801=== CONT TestParseSingleRange/malformed_both_empty1802--- PASS: TestParseSingleRange (0.01s)1803 --- PASS: TestParseSingleRange/none (0.00s)1804 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1805 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1806 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1807 --- PASS: TestParseSingleRange/single_byte (0.00s)1808 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1809 --- PASS: TestParseSingleRange/suffix (0.00s)1810 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1811 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1812 --- PASS: TestParseSingleRange/closed (0.00s)1813 --- PASS: TestParseSingleRange/open-ended (0.00s)1814 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1815 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1816 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1817=== CONT TestServerTLSConfig/no_client_CA1818=== CONT TestServerTLSConfig/not_a_PEM_file1819=== CONT TestServerTLSConfig/missing_CA_file1820--- PASS: TestServerTLSConfig (0.00s)1821 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1822 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.02s)1823 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1824=== CONT TestGCEndsOnShutdown/before_the_run1825--- PASS: TestReadRedirectNar (7.84s)1826=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1827--- PASS: TestReadProxyRangeRequest (7.71s)1828=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1829--- PASS: TestReadRedirectUsesPublicS3URL (8.37s)1830=== CONT TestClientErrorHandling/InvalidStorePath1831--- PASS: TestService_ReadAuthMiddleware (8.11s)1832=== CONT TestClientErrorHandling/ServerNotAvailable1833=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1834=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1835=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1836=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1837=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1838=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected18392026/10/08 17:03:45 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present1840=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1841=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1842=== CONT TestClientErrorHandling/InvalidAuthToken18432026/10/08 17:03:45 WARN Request failed, retrying attempt=2 backoff=200.069117ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present18442026/10/08 17:03:45 WARN Request failed, retrying attempt=3 backoff=430.678717ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present1845--- PASS: TestReadRedirectKeepsNarinfoProxied (8.85s)1846=== CONT TestIsValidUploadKey/narinfo1847=== CONT TestIsValidUploadKey/realisation_plus_in_output1848=== CONT TestIsValidUploadKey/unknown_type1849=== CONT TestIsValidUploadKey/empty_key1850=== CONT TestIsValidUploadKey/absolute1851=== CONT TestIsValidUploadKey/traversal_nar1852=== CONT TestIsValidUploadKey/traversal1853=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1854=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1855=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1856=== CONT TestIsValidUploadKey/index.html1857=== CONT TestIsValidUploadKey/nix-cache-info1858=== CONT TestIsValidUploadKey/build_log_home-manager_file1859=== CONT TestIsValidUploadKey/realisation1860=== CONT TestIsValidUploadKey/build_log_equals1861=== CONT TestIsValidUploadKey/build_log_question_mark1862=== CONT TestIsValidUploadKey/build_log_plus_in_name1863=== CONT TestIsValidUploadKey/nar_xz1864=== CONT TestIsValidUploadKey/nar_plain1865=== CONT TestIsValidUploadKey/nar_zst1866=== CONT TestIsValidUploadKey/build_log1867=== CONT TestIsValidUploadKey/listing1868--- PASS: TestIsValidUploadKey (0.06s)1869 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1870 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1871 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1872 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1873 --- PASS: TestIsValidUploadKey/absolute (0.00s)1874 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1875 --- PASS: TestIsValidUploadKey/traversal (0.00s)1876 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1877 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1878 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1879 --- PASS: TestIsValidUploadKey/index.html (0.00s)1880 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1881 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1882 --- PASS: TestIsValidUploadKey/realisation (0.00s)1883 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1884 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1885 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1886 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1887 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1888 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1889 --- PASS: TestIsValidUploadKey/build_log (0.00s)1890 --- PASS: TestIsValidUploadKey/listing (0.00s)1891=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart18922026/10/08 17:03:45 INFO Received complete multipart upload request method=POST path=/1893=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info18942026/10/08 17:03:45 INFO Received uploads request method=POST path=/1895=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure18962026/10/08 17:03:45 INFO Received uploads request method=POST path=/18972026/10/08 17:03:45 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"18982026/10/08 17:03:45 WARN mTLS auth: bound subjects configured but subject DN unavailable18992026/10/08 17:03:45 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1900--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (8.79s)1901=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts19022026/10/08 17:03:45 INFO Received request for more parts method=POST path=/1903=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key19042026/10/08 17:03:45 INFO Received complete multipart upload request method=POST path=/1905=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key19062026/10/08 17:03:45 INFO Received request for more parts method=POST path=/1907=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal19082026/10/08 17:03:45 INFO Received uploads request method=POST path=/1909--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1910 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1911 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.01s)1912 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1913 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1914=== CONT TestCacheConfigHandler/full_config,_no_issuer1915=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1916=== CONT TestCacheConfigHandler/no_signing_keys1917=== CONT TestCacheConfigHandler/no_cache_url_configured1918--- PASS: TestCacheConfigHandler (0.00s)1919 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1920 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1921 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1922 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1923=== CONT TestPendingClosureWriteTimeout/empty1924=== CONT TestProxyWriteTimeout/narinfo1925=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1926--- PASS: TestUploadHandlersRejectOversizedBody (0.04s)1927 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.04s)1928 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.02s)1929 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.29s)1930=== CONT TestPendingClosureWriteTimeout/670k_objects1931=== CONT TestPendingClosureWriteTimeout/400_objects1932=== CONT TestProxyWriteTimeout/10_GiB_nar1933=== CONT TestProxyWriteTimeout/unknown_size1934=== CONT TestProxyWriteTimeout/1_GiB_nar1935--- PASS: TestProxyWriteTimeout (0.00s)1936 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1937 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1938 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1939 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1940=== CONT TestService_RequireScope_OIDC/builder_may_write1941=== CONT TestService_RequireScope_OIDC/reader_may_read1942=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1943=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read19442026/10/08 17:03:45 WARN Authentication failed token_preview=wrong token_length=5 oidc_error="no provider could verify the token (signature or issuer mismatch)" oidc_provider="" tried_providers=[test]1945=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1946=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc1947=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read1948=== CONT TestService_RequireScope_OIDC/writer_implies_read1949=== CONT TestService_RequireScope_OIDC/reader_may_not_write1950=== CONT TestService_RequireScope_OIDC/static_token_may_write1951=== CONT TestService_RequireScope_OIDC/static_token_may_admin1952=== CONT TestService_RequireScope_OIDC/ops_may_admin1953=== CONT TestService_RequireScope_OIDC/ops_may_not_write1954=== CONT TestService_RequireScope_OIDC/builder_may_not_admin1955=== CONT TestPush_RejectsBadRequests/no_roots19562026/10/08 17:03:45 INFO Received push request method=POST path=/api/pushes1957=== CONT TestPush_RejectsBadRequests/bad_root19582026/10/08 17:03:45 INFO Received push request method=POST path=/api/pushes1959=== CONT TestPush_RejectsBadRequests/root_not_in_objects19602026/10/08 17:03:45 INFO Received push request method=POST path=/api/pushes1961=== CONT TestPush_RejectsBadRequests/no_objects19622026/10/08 17:03:45 INFO Received push request method=POST path=/api/pushes1963--- PASS: TestPush_RejectsBadRequests (7.04s)1964 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)1965 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)1966 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)1967 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)1968=== CONT TestResolveDBConnectionString/flag_wins1969--- PASS: TestService_RequireScope_OIDC (6.75s)1970 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)1971 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)1972 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)1973 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)1974 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)1975 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)1976 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)1977 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)1978 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)1979 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)1980 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)1981 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)1982 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)1983 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)1984=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1985=== CONT TestResolveDBConnectionString/nothing_configured1986=== CONT TestResolveDBConnectionString/missing_file_is_an_error1987=== CONT TestResolveDBConnectionString/file_when_flag_empty1988=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token1989=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected1990--- PASS: TestResolveDBConnectionString (0.05s)1991 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1992 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1993 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1994 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1995 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)19962026/10/08 17:03:45 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]1997=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1998=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected19992026/10/08 17:03:45 WARN Authentication failed token_preview=eyJhbGciOi...BxHOuqVH3A token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2000--- PASS: TestService_AuthMiddleware_OIDC (8.40s)2001 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2002 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2003 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2004 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)20052026/10/08 17:03:45 WARN Request failed, retrying attempt=4 backoff=878.524578ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2006--- PASS: TestService_Rustfstest (8.94s)20072026/10/08 17:03:46 INFO lead: acquired remote=192.0.2.1:12342008{"timestamp":"2026-10-08T17:03:46.402663Z","level":"ERROR","message":"Scanner cycle completed without a durable data usage snapshot","event":"scanner_persist_state","component":"scanner","subsystem":"runtime","cycle":5,"outcome":"NoUpdate","state":"usage_not_durable","target":"rustfs::scanner","filename":"crates/scanner/src/scanner.rs","line_number":2350,"threadName":"rustfs-worker","threadId":"ThreadId(3)"}20092026-10-08 17:03:46.430 UTC [67682] LOG: checkpoint starting: wal20102026/10/08 17:03:46 INFO lead: acquired remote=192.0.2.1:123420112026/10/08 17:03:46 INFO lead: released remote=192.0.2.1:12342012--- PASS: TestLeadIncumbentAnnouncesAtOnce (8.94s)20132026/10/08 17:03:46 WARN Request failed, retrying attempt=5 backoff=1.577963498s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2014--- PASS: TestReadProxyRootRedirectsToIndexHTML (8.78s)2015--- PASS: TestReadProxyDisabled (8.79s)20162026/10/08 17:03:47 INFO lead: released remote=192.0.2.1:123420172026/10/08 17:03:47 INFO lead: acquired remote=192.0.2.1:12342018--- PASS: TestReadProxyConditionalGet (8.06s)20192026/10/08 17:03:48 WARN Rate limiter enabled after throttle name=s3-test rate=520202026/10/08 17:03:48 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."2021=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle2022 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=102023 throttle_test.go:215: Rate limiter: enabled=true, rate=5.002024--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (14.30s)2025--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (7.96s)20262026/10/08 17:03:48 INFO Received uploads request method=POST path=/api/pending_closures20272026/10/08 17:03:48 WARN Request failed, retrying attempt=1 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2028--- PASS: TestConnectWaitsForAPeerMigration (8.98s)20292026/10/08 17:03:48 WARN Request failed, retrying attempt=2 backoff=212.705974ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20302026/10/08 17:03:48 INFO Received uploads request method=POST path=/api/pending_closures20312026/10/08 17:03:48 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst20322026/10/08 17:03:48 INFO Received uploads request method=POST path=/api/pending_closures2033--- PASS: TestPresignedUploadRegisteredBeforeCommit (7.75s)20342026/10/08 17:03:48 INFO lead: released remote=192.0.2.1:12342035--- PASS: TestLeadElectsOneAndHandsOver (11.14s)20362026/10/08 17:03:48 WARN Request failed, retrying attempt=3 backoff=363.663519ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20372026/10/08 17:03:49 INFO Received uploads request method=POST path=/api/pending_closures20382026/10/08 17:03:49 INFO Aborted multipart uploads count=0 kept=020392026/10/08 17:03:49 WARN Force mode enabled - objects will be deleted immediately without grace period20402026/10/08 17:03:49 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=020412026/10/08 17:03:49 INFO Vacuumed table table=pending_closures20422026/10/08 17:03:49 INFO Vacuumed table table=pending_objects20432026/10/08 17:03:49 INFO Vacuumed table table=multipart_uploads20442026/10/08 17:03:49 INFO Vacuumed table table=closures20452026/10/08 17:03:49 INFO Vacuumed table table=objects20462026/10/08 17:03:49 WARN Request failed, retrying attempt=4 backoff=832.162756ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20472026/10/08 17:03:49 INFO Received uploads request method=POST path=/api/pending_closures20482026/10/08 17:03:49 INFO Aborted multipart uploads count=0 kept=020492026/10/08 17:03:49 WARN Force mode enabled - objects will be deleted immediately without grace period20502026/10/08 17:03:49 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=020512026/10/08 17:03:49 INFO Vacuumed table table=pending_closures20522026/10/08 17:03:49 INFO Vacuumed table table=pending_objects20532026/10/08 17:03:49 INFO Vacuumed table table=multipart_uploads20542026/10/08 17:03:49 INFO Vacuumed table table=closures20552026/10/08 17:03:49 INFO Vacuumed table table=objects2056--- PASS: TestForceGCDuringPushOffersSweptObject (0.01s)2057 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (6.17s)2058 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (6.53s)20592026/10/08 17:03:49 INFO Received complete multipart upload request method=POST path=/api/multipart/complete2060--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2061 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (6.73s)2062 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (6.94s)20632026/10/08 17:03:49 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=MzQ2Njc2OWUtOTMxYy00YjBjLTg5ZjEtOTQ3OGM5ODJjNzNjLjg0YzgzMDM0LTM5NTgtNDg5Mi1hNWFmLTRhZjBkYTQ2ZDA5NHgxNzkxNDc5MDI4NDE2NjUwMDAw parts=1220642026/10/08 17:03:49 INFO Received uploads request method=POST path=/api/pending_closures2065--- PASS: TestCompletedNarNotReofferedAcrossClosures (8.63s)20662026/10/08 17:03:49 INFO Aborted multipart uploads count=0 kept=020672026/10/08 17:03:49 WARN Force mode enabled - objects will be deleted immediately without grace period20682026/10/08 17:03:49 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:54165/bucket96/?delete=\": context canceled"20692026/10/08 17:03:49 WARN Request failed, retrying attempt=5 backoff=1.662363124s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20702026/10/08 17:03:50 INFO Aborted multipart uploads count=0 kept=020712026/10/08 17:03:50 WARN Force mode enabled - objects will be deleted immediately without grace period2072--- PASS: TestGCEndsOnShutdown (0.00s)2073 --- PASS: TestGCEndsOnShutdown/before_the_run (6.14s)2074 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (6.30s)2075 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (6.03s)20762026/10/08 17:03:50 INFO Received uploads request method=POST path=/api/pending_closures20772026/10/08 17:03:50 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"20782026/10/08 17:03:50 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"2079--- PASS: TestPendingClosureWriteTimeout (0.00s)2080 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2081 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2082 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2083 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (5.53s)20842026/10/08 17:03:51 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"20852026/10/08 17:03:51 WARN Request failed, retrying attempt=1 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20862026/10/08 17:03:51 WARN Request failed, retrying attempt=2 backoff=187.894738ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20872026/10/08 17:03:51 WARN Request failed, retrying attempt=3 backoff=399.211916ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2088--- PASS: TestReadProxyOutlastsServerWriteTimeout (11.75s)20892026/10/08 17:03:52 WARN Request failed, retrying attempt=4 backoff=728.744142ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20902026/10/08 17:03:53 WARN Request failed, retrying attempt=5 backoff=1.508108162s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2091{"timestamp":"2026-10-08T17:03:53.990404Z","level":"ERROR","message":"Scanner cycle completed without a durable data usage snapshot","event":"scanner_persist_state","component":"scanner","subsystem":"runtime","cycle":5,"outcome":"NoUpdate","state":"usage_not_durable","target":"rustfs::scanner","filename":"crates/scanner/src/scanner.rs","line_number":2350,"threadName":"rustfs-worker","threadId":"ThreadId(8)"}20922026/10/08 17:03:54 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures20932026/10/08 17:03:54 WARN Request failed, retrying attempt=2 backoff=219.710269ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures20942026/10/08 17:03:54 WARN Request failed, retrying attempt=3 backoff=400.369528ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures20952026/10/08 17:03:55 WARN Request failed, retrying attempt=4 backoff=864.608284ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures20962026/10/08 17:03:56 WARN Request failed, retrying attempt=5 backoff=1.446734662s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2097--- PASS: TestClientErrorHandling (0.00s)2098 --- PASS: TestClientErrorHandling/InvalidStorePath (5.73s)2099 --- PASS: TestClientErrorHandling/InvalidAuthToken (5.39s)2100 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.82s)2101FAIL2102{"timestamp":"2026-10-08T17:03:57.656606Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:54329","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(5)"}21032026-10-08 17:03:57.812 UTC [67677] LOG: received smart shutdown request21042026-10-08 17:03:57.813 UTC [67677] LOG: background worker "logical replication launcher" (PID 67688) exited with exit code 121052026-10-08 17:03:59.140 UTC [67682] LOG: checkpoint complete: wrote 10889 buffers (66.5%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 33 recycled; write=11.966 s, sync=0.655 s, total=12.711 s; sync files=34035, longest=0.001 s, average=0.001 s; distance=533305 kB, estimate=533305 kB; lsn=0/228079C8, redo lsn=0/2205B5F821062026-10-08 17:03:59.141 UTC [67682] LOG: shutting down21072026-10-08 17:03:59.141 UTC [67682] LOG: checkpoint starting: shutdown immediate21082026-10-08 17:03:59.197 UTC [67682] LOG: checkpoint complete: wrote 1277 buffers (7.8%), wrote 1 SLRU buffers; 0 WAL file(s) added, 0 removed, 0 recycled; write=0.046 s, sync=0.010 s, total=0.057 s; sync files=456, longest=0.001 s, average=0.001 s; distance=7857 kB, estimate=480760 kB; lsn=0/22807A40, redo lsn=0/22807A4021092026-10-08 17:03:59.203 UTC [67677] LOG: database system is shut down