niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #471
· raw
1tribuchet: building on mac022Running client tests...3=== RUN TestDoServerRequestAttachesToken4=== PAUSE TestDoServerRequestAttachesToken5=== RUN TestUploadBuildLog_FileBodyReplayedOnRetry6=== PAUSE TestUploadBuildLog_FileBodyReplayedOnRetry7=== RUN TestRegisterUploadedObjectReusesConnections8=== PAUSE TestRegisterUploadedObjectReusesConnections9=== RUN TestRunGarbageCollection_FinishedOnAnotherReplica10=== PAUSE TestRunGarbageCollection_FinishedOnAnotherReplica11=== RUN TestRunGarbageCollection_NotFoundAfterLocalRun12=== PAUSE TestRunGarbageCollection_NotFoundAfterLocalRun13=== RUN TestCaseHackSuffix14=== PAUSE TestCaseHackSuffix15=== RUN TestFilterOversizedClosures16=== PAUSE TestFilterOversizedClosures17=== RUN TestUploadMultipart_PartsInParallel18=== PAUSE TestUploadMultipart_PartsInParallel19=== RUN TestUploadMultipart_ReturnsAfterDroppedBody20=== PAUSE TestUploadMultipart_ReturnsAfterDroppedBody21=== RUN TestPartSizeForNAR22=== PAUSE TestPartSizeForNAR23=== RUN TestDumpPathCaseHackMatchesNix24--- PASS: TestDumpPathCaseHackMatchesNix (0.11s)25=== RUN TestDumpPathCaseHackCollision26--- PASS: TestDumpPathCaseHackCollision (0.00s)27=== RUN TestCaseHackPathIsRefusedWithoutStrip28--- PASS: TestCaseHackPathIsRefusedWithoutStrip (0.00s)29=== RUN TestDumpPathMatchesNix30=== PAUSE TestDumpPathMatchesNix31=== RUN TestDumpPathSingleFile32=== PAUSE TestDumpPathSingleFile33=== RUN TestDumpPathWriterError34=== PAUSE TestDumpPathWriterError35=== RUN TestEncodeNixBase3236=== PAUSE TestEncodeNixBase3237=== RUN TestEncodeNixBase32WithRealHash38=== PAUSE TestEncodeNixBase32WithRealHash39=== RUN TestConvertHashToNix3240=== PAUSE TestConvertHashToNix3241=== RUN TestGetStorePathHash42=== PAUSE TestGetStorePathHash43=== RUN TestPathInfoHashCompatibility44=== PAUSE TestPathInfoHashCompatibility45=== RUN TestParsePathInfoJSON46=== PAUSE TestParsePathInfoJSON47=== RUN TestParsePathInfoJSONMultiplePaths48=== PAUSE TestParsePathInfoJSONMultiplePaths49=== RUN TestPathInfoCACompatibility50=== PAUSE TestPathInfoCACompatibility51=== RUN TestRateLimiterFeedback52=== PAUSE TestRateLimiterFeedback53=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess54=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess55=== RUN TestRegisterUploadedObject_BoundedAgainstSilentServer56=== PAUSE TestRegisterUploadedObject_BoundedAgainstSilentServer57=== RUN TestRegisterUploadedObject_OutlivesPush58=== PAUSE TestRegisterUploadedObject_OutlivesPush59=== RUN TestResolveStorePath60=== PAUSE TestResolveStorePath61=== RUN TestDoWithRetry_BodyReplayedViaGetBody62=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody63=== RUN TestRetryTimeoutOutlastsMaxRetries64=== PAUSE TestRetryTimeoutOutlastsMaxRetries65=== RUN TestDoWithRetry_FinalResponseBodyReadable66=== PAUSE TestDoWithRetry_FinalResponseBodyReadable67=== RUN TestShellSplit68=== PAUSE TestShellSplit69=== RUN TestShellSplitErrors70=== PAUSE TestShellSplitErrors71=== RUN TestStreamPushReportsEveryPath72=== PAUSE TestStreamPushReportsEveryPath73=== RUN TestStreamPushBatchesUnderLoad74=== PAUSE TestStreamPushBatchesUnderLoad75=== RUN TestStreamPushIsolatesFailures76=== PAUSE TestStreamPushIsolatesFailures77=== RUN TestStreamPushGivesUpOnDeadServer78=== PAUSE TestStreamPushGivesUpOnDeadServer79=== RUN TestStreamPushRequestLine80=== PAUSE TestStreamPushRequestLine81=== RUN TestStreamPushReportsSignatures82=== PAUSE TestStreamPushReportsSignatures83=== RUN TestStreamPushReportsSkippedPaths84=== PAUSE TestStreamPushReportsSkippedPaths85=== RUN TestClientSignaturesByStorePath86=== PAUSE TestClientSignaturesByStorePath87=== RUN TestStreamPushStopsWhenCanceled88=== PAUSE TestStreamPushStopsWhenCanceled89=== RUN TestSetClientTLS90=== PAUSE TestSetClientTLS91=== RUN TestSetClientTLSDoesNotMutateDefaultTransport92=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport93=== RUN TestSetClientTLSErrors94=== PAUSE TestSetClientTLSErrors95=== RUN TestStaticToken96=== PAUSE TestStaticToken97=== RUN TestFileTokenReadsAndCaches98=== PAUSE TestFileTokenReadsAndCaches99=== RUN TestFileTokenMissing100=== PAUSE TestFileTokenMissing101=== RUN TestFileTokenEmpty102=== PAUSE TestFileTokenEmpty103=== RUN TestScriptTokenNoExpiryRerunsEveryCall104=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall105=== RUN TestScriptTokenCachesUntilRefresh106=== PAUSE TestScriptTokenCachesUntilRefresh107=== RUN TestScriptTokenEmptyToken108=== PAUSE TestScriptTokenEmptyToken109=== RUN TestScriptTokenBadJSON110=== PAUSE TestScriptTokenBadJSON111=== RUN TestScriptTokenScriptFails112=== PAUSE TestScriptTokenScriptFails113=== RUN TestScriptTokenEmptyCommand114=== PAUSE TestScriptTokenEmptyCommand115=== CONT TestDoServerRequestAttachesToken116=== CONT TestRetryTimeoutOutlastsMaxRetries117=== CONT TestScriptTokenEmptyCommand118--- PASS: TestScriptTokenEmptyCommand (0.00s)119=== CONT TestStreamPushReportsSkippedPaths120=== CONT TestSetClientTLS121=== CONT TestEncodeNixBase32WithRealHash122=== CONT TestParsePathInfoJSONMultiplePaths123=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths124=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths125=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths126=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths127=== CONT TestParsePathInfoJSON128=== RUN TestParsePathInfoJSON/Nix_format129=== PAUSE TestParsePathInfoJSON/Nix_format130=== RUN TestParsePathInfoJSON/Lix_format131=== PAUSE TestParsePathInfoJSON/Lix_format132=== RUN TestParsePathInfoJSON/empty_input133=== PAUSE TestParsePathInfoJSON/empty_input134=== CONT TestStreamPushRequestLine135=== RUN TestParsePathInfoJSON/whitespace_only136=== PAUSE TestParsePathInfoJSON/whitespace_only137=== CONT TestPathInfoHashCompatibility138=== CONT TestGetStorePathHash139=== RUN TestGetStorePathHash/valid_store_path140=== PAUSE TestGetStorePathHash/valid_store_path141=== CONT TestRegisterUploadedObject_OutlivesPush142=== CONT TestDoWithRetry_BodyReplayedViaGetBody143=== CONT TestResolveStorePath144=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer145=== CONT TestFileTokenEmpty146=== CONT TestScriptTokenScriptFails147=== CONT TestScriptTokenBadJSON148=== CONT TestScriptTokenEmptyToken1492026/11/09 11:53:14 WARN Rate limiter enabled after throttle name=server-test rate=51502026/11/09 11:53:14 ERROR Upload failed error=boom count=11512026/11/09 11:53:14 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:64683152=== CONT TestScriptTokenCachesUntilRefresh153=== CONT TestScriptTokenNoExpiryRerunsEveryCall154=== CONT TestStaticToken155=== CONT TestStreamPushGivesUpOnDeadServer156=== CONT TestStreamPushStopsWhenCanceled157=== CONT TestClientSignaturesByStorePath158=== CONT TestPathInfoCACompatibility159--- PASS: TestEncodeNixBase32WithRealHash (0.00s)160=== CONT TestStreamPushReportsSignatures161=== RUN TestParsePathInfoJSON/invalid_JSON162=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)163=== CONT TestConvertHashToNix32164=== RUN TestGetStorePathHash/basename_without_hyphen_should_error165=== CONT TestRateLimiterFeedback166=== RUN TestRateLimiterFeedback/429_enables_limiter167=== PAUSE TestRateLimiterFeedback/429_enables_limiter168=== RUN TestRateLimiterFeedback/503_enables_limiter169=== PAUSE TestRateLimiterFeedback/503_enables_limiter170=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter171=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter172=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter173=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter174--- PASS: TestStreamPushReportsSkippedPaths (0.00s)175--- PASS: TestResolveStorePath (0.00s)176--- PASS: TestFileTokenEmpty (0.00s)177=== CONT TestFileTokenMissing178=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)179=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon180=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon181=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI182=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI183=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512184--- PASS: TestRegisterUploadedObject_OutlivesPush (0.01s)185=== CONT TestFileTokenReadsAndCaches186--- PASS: TestFileTokenMissing (0.00s)187=== CONT TestStreamPushReportsEveryPath188=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess189=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512190--- PASS: TestClientSignaturesByStorePath (0.00s)191=== CONT TestStreamPushBatchesUnderLoad192=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=false193=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=false194=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=true195=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=true196=== CONT TestStreamPushIsolatesFailures197--- PASS: TestStaticToken (0.00s)198--- PASS: TestStreamPushReportsEveryPath (0.00s)199=== CONT TestShellSplitErrors200--- PASS: TestShellSplitErrors (0.00s)201=== CONT TestEncodeNixBase32202=== RUN TestPathInfoCACompatibility/null_ca_field203=== PAUSE TestPathInfoCACompatibility/null_ca_field204=== RUN TestPathInfoCACompatibility/old_string_format_-_text205=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text206=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive207=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error208=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error209=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error210=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error211=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error212=== RUN TestConvertHashToNix32/SRI_format_to_Nix32213=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32214=== RUN TestConvertHashToNix32/already_Nix32_format215=== PAUSE TestConvertHashToNix32/already_Nix32_format216=== RUN TestConvertHashToNix32/invalid_format217=== PAUSE TestConvertHashToNix32/invalid_format218=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive219=== RUN TestPathInfoCACompatibility/new_structured_format_-_text220=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text221--- PASS: TestStreamPushStopsWhenCanceled (0.00s)2222026/11/09 11:53:14 ERROR Upload failed error="bad path" count=32232026/11/09 11:53:14 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:64680224--- PASS: TestStreamPushIsolatesFailures (0.00s)225=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method226=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method2272026/11/09 11:53:14 WARN Rate limiter backed off name=server-test rate=52282026/11/09 11:53:14 WARN Request returned retryable status, retrying attempt=2 backoff=0s status=503 url=http://127.0.0.1:646832292026/11/09 11:53:14 ERROR Upload failed error=boom count=1230=== RUN TestEncodeNixBase32/test_string_hash231=== PAUSE TestEncodeNixBase32/test_string_hash232=== RUN TestEncodeNixBase32/empty_input233=== PAUSE TestEncodeNixBase32/empty_input234=== CONT TestDumpPathMatchesNix235=== CONT TestRegisterUploadedObjectReusesConnections2362026/11/09 11:53:14 ERROR Upload failed error="connection refused" count=202372026/11/09 11:53:14 ERROR Server seems unavailable, giving up on batch untried=172382026/11/09 11:53:14 WARN Rate limiter enabled after throttle name=server-test rate=5239=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica240=== CONT TestDumpPathSingleFile2412026/11/09 11:53:14 INFO Garbage collection started242=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun243=== CONT TestDumpPathWriterError244=== CONT TestDoWithRetry_FinalResponseBodyReadable245=== CONT TestShellSplit246=== CONT TestSetClientTLSErrors247=== RUN TestSetClientTLS/rejects_connection_without_client_cert248=== CONT TestUploadMultipart_PartsInParallel2492026/11/09 11:53:14 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:64680250=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths251=== PAUSE TestParsePathInfoJSON/invalid_JSON252--- PASS: TestDoServerRequestAttachesToken (0.01s)253=== CONT TestPartSizeForNAR254=== CONT TestSetClientTLSDoesNotMutateDefaultTransport255=== CONT TestUploadMultipart_ReturnsAfterDroppedBody256=== CONT TestCaseHackSuffix257=== CONT TestFilterOversizedClosures258=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert259=== CONT TestRateLimiterFeedback/429_enables_limiter260=== RUN TestPartSizeForNAR/zero_stays_at_minimum261=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA262=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths263--- PASS: TestStreamPushReportsSignatures (0.00s)264--- PASS: TestScriptTokenScriptFails (0.01s)265--- PASS: TestFileTokenReadsAndCaches (0.01s)266--- PASS: TestStreamPushGivesUpOnDeadServer (0.01s)267--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.01s)268--- PASS: TestScriptTokenBadJSON (0.01s)269--- PASS: TestScriptTokenEmptyToken (0.02s)270--- PASS: TestShellSplit (0.00s)271--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)272 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)273 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)274=== RUN TestSetClientTLSErrors/missing_cert_file275=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry276--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)277=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter278=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter279=== RUN TestFilterOversizedClosures/no_limit_keeps_everything280=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything281=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped282=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped283=== RUN TestFilterOversizedClosures/all_closures_skipped284=== PAUSE TestFilterOversizedClosures/all_closures_skipped285=== CONT TestRateLimiterFeedback/503_enables_limiter2862026/11/09 11:53:14 WARN Rate limiter enabled after throttle name=server-test rate=52872026/11/09 11:53:14 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:647632882026/11/09 11:53:14 WARN Rate limiter enabled after throttle name=server-test rate=52892026/11/09 11:53:14 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=429 url=http://127.0.0.1:647652902026/11/09 11:53:14 WARN Rate limiter enabled after throttle name=server-test rate=52912026/11/09 11:53:14 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:647692922026/11/09 11:53:14 WARN Rate limiter backed off name=server-test rate=5293=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)294=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=false2952026/11/09 11:53:14 WARN Rate limiter backed off name=server-test rate=5296=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512297=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI298=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon299--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.01s)300--- PASS: TestPathInfoHashCompatibility (0.01s)301 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)302 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)303 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)304 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)305=== CONT TestGetStorePathHash/valid_store_path306=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=true307=== CONT TestConvertHashToNix32/SRI_format_to_Nix32308=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error309=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error310=== CONT TestGetStorePathHash/basename_without_hyphen_should_error311--- PASS: TestGetStorePathHash (0.01s)312 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)313 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)314 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)315 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)316=== CONT TestConvertHashToNix32/invalid_format317=== CONT TestConvertHashToNix32/already_Nix32_format318--- PASS: TestConvertHashToNix32 (0.00s)319 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)320 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)321 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)322=== CONT TestPathInfoCACompatibility/null_ca_field323=== CONT TestPathInfoCACompatibility/new_structured_format_-_text324=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive325=== CONT TestPathInfoCACompatibility/old_string_format_-_text326=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method327--- PASS: TestPathInfoCACompatibility (0.00s)328 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)329 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)330 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)331 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)332 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)333--- PASS: TestStreamPushBatchesUnderLoad (0.00s)334 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=false (0.00s)335 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=true (0.00s)336=== CONT TestEncodeNixBase32/test_string_hash337=== CONT TestEncodeNixBase32/empty_input338--- PASS: TestEncodeNixBase32 (0.00s)339 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)340 --- PASS: TestEncodeNixBase32/empty_input (0.00s)341=== CONT TestParsePathInfoJSON/Nix_format342=== CONT TestParsePathInfoJSON/invalid_JSON343=== CONT TestParsePathInfoJSON/empty_input344=== CONT TestParsePathInfoJSON/Lix_format345=== CONT TestParsePathInfoJSON/whitespace_only346--- PASS: TestParsePathInfoJSON (0.02s)347 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)348 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)349 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)350 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)351 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)352=== CONT TestFilterOversizedClosures/no_limit_keeps_everything353=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped354=== CONT TestFilterOversizedClosures/all_closures_skipped3552026/11/09 11:53:14 WARN Rate limiter backed off name=server-test rate=53562026/11/09 11:53:14 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=20003572026/11/09 11:53:14 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=50358=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum359=== RUN TestPartSizeForNAR/small_stays_at_minimum360=== PAUSE TestPartSizeForNAR/small_stays_at_minimum361=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum362=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum363=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts364=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts365=== RUN TestPartSizeForNAR/1_TiB366=== PAUSE TestPartSizeForNAR/1_TiB367=== RUN TestPartSizeForNAR/5_TiB_S3_max_object368--- PASS: TestFilterOversizedClosures (0.00s)369 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)370 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)371 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)372=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA373=== RUN TestSetClientTLS/preserves_debug_logging_transport374=== PAUSE TestSetClientTLS/preserves_debug_logging_transport375=== CONT TestSetClientTLS/rejects_connection_without_client_cert376=== CONT TestSetClientTLS/preserves_debug_logging_transport377=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA3782026/11/09 11:53:14 INFO Garbage collection started3792026/11/09 11:53:14 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=0380=== PAUSE TestSetClientTLSErrors/missing_cert_file3812026/11/09 11:53:14 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:64680382=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object383=== RUN TestPartSizeForNAR/capped_at_5_GiB384=== PAUSE TestPartSizeForNAR/capped_at_5_GiB385=== CONT TestPartSizeForNAR/zero_stays_at_minimum386--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.01s)387=== CONT TestPartSizeForNAR/capped_at_5_GiB388=== CONT TestPartSizeForNAR/1_TiB389=== CONT TestPartSizeForNAR/5_TiB_S3_max_object390=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum391=== CONT TestPartSizeForNAR/small_stays_at_minimum392=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts393=== RUN TestSetClientTLSErrors/missing_key_file394=== PAUSE TestSetClientTLSErrors/missing_key_file395=== RUN TestSetClientTLSErrors/missing_ca_file396=== PAUSE TestSetClientTLSErrors/missing_ca_file397=== RUN TestSetClientTLSErrors/invalid_ca_file398=== PAUSE TestSetClientTLSErrors/invalid_ca_file399=== CONT TestSetClientTLSErrors/missing_cert_file400=== CONT TestSetClientTLSErrors/missing_ca_file401=== CONT TestSetClientTLSErrors/missing_key_file402=== CONT TestSetClientTLSErrors/invalid_ca_file4032026/11/09 11:53:14 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:64680404--- PASS: TestPartSizeForNAR (0.01s)405 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)406 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)407 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)408 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)409 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)410 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)411 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)4122026/11/09 11:53:14 WARN Garbage collection finished on another replica. Its statistics are not available here413--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.02s)414--- PASS: TestRateLimiterFeedback (0.00s)415 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)416 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)417 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)418 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.01s)419--- PASS: TestStreamPushRequestLine (0.03s)4202026/11/09 11:53:14 WARN Request returned retryable status, retrying attempt=3 backoff=1ms status=502 url=http://127.0.0.1:64680421--- PASS: TestSetClientTLSErrors (0.01s)422 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)423 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)424 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)425 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)4262026/11/09 11:53:14 WARN Rate limiter enabled after throttle name=s3-test rate=54272026/11/09 11:53:14 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:64779428--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.01s)4292026/11/09 11:53:14 WARN Request returned retryable status, retrying attempt=4 backoff=1ms status=502 url=http://127.0.0.1:64680430--- PASS: TestUploadMultipart_ReturnsAfterDroppedBody (0.01s)4312026/11/09 11:53:14 WARN Request returned retryable status, retrying attempt=5 backoff=1ms status=502 url=http://127.0.0.1:646804322026/11/09 11:53:14 WARN Request returned retryable status, retrying attempt=6 backoff=1ms status=502 url=http://127.0.0.1:646804332026/11/09 11:53:14 WARN Request returned retryable status, retrying attempt=7 backoff=1ms status=502 url=http://127.0.0.1:646804342026/11/09 11:53:14 WARN Request returned retryable status, retrying attempt=8 backoff=1ms status=502 url=http://127.0.0.1:646804352026/11/09 11:53:14 WARN Request returned retryable status, retrying attempt=9 backoff=1ms status=502 url=http://127.0.0.1:646804362026/11/09 11:53:14 WARN Request returned retryable status, retrying attempt=10 backoff=1ms status=502 url=http://127.0.0.1:646804372026/11/09 11:53:14 WARN Request returned retryable status, retrying attempt=11 backoff=1ms status=502 url=http://127.0.0.1:646804382026/11/09 11:53:14 WARN Request returned retryable status, retrying attempt=12 backoff=1ms status=502 url=http://127.0.0.1:64680439--- PASS: TestScriptTokenCachesUntilRefresh (0.06s)4402026/11/09 11:53:14 WARN Request returned retryable status, retrying attempt=13 backoff=1ms status=502 url=http://127.0.0.1:646804412026/11/09 11:53:14 WARN Request returned retryable status, retrying attempt=14 backoff=1ms status=502 url=http://127.0.0.1:64680442--- PASS: TestRegisterUploadedObjectReusesConnections (0.06s)4432026/11/09 11:53:14 WARN Request returned retryable status, retrying attempt=15 backoff=1ms status=502 url=http://127.0.0.1:646804442026/11/09 11:53:14 http: TLS handshake error from 127.0.0.1:64771: remote error: tls: bad certificate4452026/11/09 11:53:14 WARN Request returned retryable status, retrying attempt=16 backoff=1ms status=502 url=http://127.0.0.1:64680446--- PASS: TestSetClientTLS (0.03s)447 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.01s)448 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.01s)449 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.04s)4502026/11/09 11:53:14 WARN Request returned retryable status, retrying attempt=17 backoff=1ms status=502 url=http://127.0.0.1:64680451--- PASS: TestDumpPathWriterError (0.05s)452--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.07s)453--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.07s)454--- PASS: TestDumpPathSingleFile (0.07s)455--- PASS: TestCaseHackSuffix (0.05s)4562026/11/09 11:53:14 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:64686/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:64686/api/uploads/complete4572026/11/09 11:53:14 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:64686/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:64686/api/uploads/complete4582026/11/09 11:53:14 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4592026/11/09 11:53:14 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4602026/11/09 11:53:14 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:64686/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:64686/api/uploads/complete4612026/11/09 11:53:14 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"462--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (0.10s)463--- PASS: TestDumpPathMatchesNix (0.10s)464--- PASS: TestUploadMultipart_PartsInParallel (0.63s)465--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)466PASS467Running server tests...468The files belonging to this database system will be owned by user "_tribuchetbld8".469This user must also own the server process.470471The database cluster will be initialized with locale "C".472The default database encoding has accordingly been set to "SQL_ASCII".473The default text search configuration will be set to "english".474475Data page checksums are enabled.476477creating directory /private/var/tb/8/scratch/b4189290b5638e57/build/postgres3896471884/data ... ok478creating subdirectories ... ok479selecting dynamic shared memory implementation ... posix480selecting default "max_connections" ... 100481selecting default "shared_buffers" ... 128MB482selecting default time zone ... UTC483creating configuration files ... ok484running bootstrap script ... ok485performing post-bootstrap initialization ... ok486syncing data to disk ... ok487488initdb: warning: enabling "trust" authentication for local connections489initdb: 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.490491Success. You can now start the database server using:492493 pg_ctl -D /private/var/tb/8/scratch/b4189290b5638e57/build/postgres3896471884/data -l logfile start4944952026-11-09 11:53:17.267 UTC [24051] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit4962026-11-09 11:53:17.267 UTC [24051] LOG: listening on Unix socket "/private/var/tb/8/scratch/b4189290b5638e57/build/postgres3896471884/.s.PGSQL.5432"4972026-11-09 11:53:17.270 UTC [24058] LOG: database system was shut down at 2026-11-09 11:53:17 UTC4982026-11-09 11:53:17.271 UTC [24051] LOG: database system is ready to accept connections499/private/var/tb/8/scratch/b4189290b5638e57/build/postgres3896471884:5432 - accepting connections500{"timestamp":"2026-11-09T11:53:19.969487Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"bae37b66-c8bb-47f7-990d-936c7db0677f","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":0,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":502,"threadName":"rustfs-worker","threadId":"ThreadId(8)"}501=== RUN TestAbortSucceeded502=== PAUSE TestAbortSucceeded503=== RUN TestService_AuthMiddleware504=== PAUSE TestService_AuthMiddleware505=== RUN TestService_AuthMiddleware_MTLSProxyHeader506=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader507=== RUN TestService_AuthMiddleware_MTLSBoundSubjects508=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects509=== RUN TestService_ReadAuthMiddleware510=== PAUSE TestService_ReadAuthMiddleware511=== RUN TestService_AuthMiddleware_OIDC512=== PAUSE TestService_AuthMiddleware_OIDC513=== RUN TestService_RequireScope_OIDC514=== PAUSE TestService_RequireScope_OIDC515=== RUN TestService_ReadScope_PublicByDefault516=== PAUSE TestService_ReadScope_PublicByDefault517=== RUN TestCacheConfigHandler518=== PAUSE TestCacheConfigHandler519=== RUN TestCacheStatsHandler520=== PAUSE TestCacheStatsHandler521=== RUN TestClientCADerivations522=== PAUSE TestClientCADerivations523=== RUN TestClientErrorHandling524=== PAUSE TestClientErrorHandling525=== RUN TestClientIntegration526=== PAUSE TestClientIntegration527=== RUN TestClientMultipleUploads528=== PAUSE TestClientMultipleUploads529=== RUN TestClientWithDependencies530=== PAUSE TestClientWithDependencies531=== RUN TestClientSharedPathCommittedMidPush532=== PAUSE TestClientSharedPathCommittedMidPush533=== RUN TestPinProtectsFromGC534=== PAUSE TestPinProtectsFromGC535=== RUN TestClientPushesUseOnePush536=== PAUSE TestClientPushesUseOnePush537=== RUN TestClientFallsBackToClosures538=== PAUSE TestClientFallsBackToClosures539=== RUN TestDeleteClosuresRacingPins540=== PAUSE TestDeleteClosuresRacingPins541=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock542=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock543=== RUN TestRetryableCompletionError544=== PAUSE TestRetryableCompletionError545=== RUN TestCompleteMultipartUploadRetriesTransientFailure546=== PAUSE TestCompleteMultipartUploadRetriesTransientFailure547=== RUN TestResolveDBConnectionString548=== PAUSE TestResolveDBConnectionString549=== RUN TestConnectWaitsForAPeerMigration550=== PAUSE TestConnectWaitsForAPeerMigration551=== RUN TestLeadElectsOneAndHandsOver552=== PAUSE TestLeadElectsOneAndHandsOver553=== RUN TestLeadIncumbentWinsAfterRestart5542026/11/09 11:53:20 INFO lead: acquired remote=192.0.2.1:12345552026/11/09 11:53:21 INFO lead: released remote=192.0.2.1:12345562026/11/09 11:53:21 INFO lead: acquired remote=192.0.2.1:12345572026/11/09 11:53:22 INFO lead: released remote=192.0.2.1:1234558--- PASS: TestLeadIncumbentWinsAfterRestart (2.06s)559=== RUN TestLeadIncumbentAnnouncesAtOnce560=== PAUSE TestLeadIncumbentAnnouncesAtOnce561=== RUN TestLeadEndsOnShutdown562=== PAUSE TestLeadEndsOnShutdown563=== RUN TestLeadEndsWhenItsConnectionHangs5642026/11/09 11:53:22 INFO lead: acquired remote=192.0.2.1:12345652026-11-09 11:53:23.714 UTC [24115] FATAL: terminating connection due to administrator command5662026/11/09 11:53:23 INFO lead: acquired remote=192.0.2.1:12345672026/11/09 11:53:24 WARN lead: lock connection lost error="timeout: context deadline exceeded"5682026/11/09 11:53:24 INFO lead: released remote=192.0.2.1:12345692026/11/09 11:53:25 INFO lead: released remote=192.0.2.1:1234570--- PASS: TestLeadEndsWhenItsConnectionHangs (2.98s)571=== RUN TestGCAdvisoryLockBlocksConcurrentRun572=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun573=== RUN TestGCBugBareHashReferences574=== PAUSE TestGCBugBareHashReferences575=== RUN TestGCMetrics576=== PAUSE TestGCMetrics577=== RUN TestPushDedupSurvivesConcurrentGC578=== PAUSE TestPushDedupSurvivesConcurrentGC579=== RUN TestDeduplicatedObjectsRecordedAsPending580=== PAUSE TestDeduplicatedObjectsRecordedAsPending581=== RUN TestGCSweepSkipsPendingObjects582=== PAUSE TestGCSweepSkipsPendingObjects583=== RUN TestTombstonedObjectOfferedWithoutWaiting584=== PAUSE TestTombstonedObjectOfferedWithoutWaiting585=== RUN TestGCSweepDeliversEachKeyOnce586=== PAUSE TestGCSweepDeliversEachKeyOnce587=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection588=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection589=== RUN TestForceGCDuringPushOffersSweptObject590=== PAUSE TestForceGCDuringPushOffersSweptObject591=== RUN TestFailedS3DeleteKeepsTombstone592=== PAUSE TestFailedS3DeleteKeepsTombstone593=== RUN TestSweepSkipsRowsLockedByPush594=== PAUSE TestSweepSkipsRowsLockedByPush595=== RUN TestRegisterCompletedObjectNeedsPendingRow596=== PAUSE TestRegisterCompletedObjectNeedsPendingRow597=== RUN TestGetExistingObjectsLocksRows598=== PAUSE TestGetExistingObjectsLocksRows599=== RUN TestSweepRechecksPendingAfterLocking600=== PAUSE TestSweepRechecksPendingAfterLocking601=== RUN TestPushWaitsForSweepHoldingRow602=== PAUSE TestPushWaitsForSweepHoldingRow603=== RUN TestCommitRacingPendingCleanupKeepsObjects604=== PAUSE TestCommitRacingPendingCleanupKeepsObjects605=== RUN TestGCEndsOnShutdown606=== PAUSE TestGCEndsOnShutdown607=== RUN TestGCTaskStore_StartNew608=== PAUSE TestGCTaskStore_StartNew609=== RUN TestGCTaskStore_DeduplicateSameParams610=== PAUSE TestGCTaskStore_DeduplicateSameParams611=== RUN TestGCTaskStore_ConflictDifferentParams612=== PAUSE TestGCTaskStore_ConflictDifferentParams613=== RUN TestGCTaskStore_GetEmpty614=== PAUSE TestGCTaskStore_GetEmpty615=== RUN TestGCTaskStore_GetReturnsLatest616=== PAUSE TestGCTaskStore_GetReturnsLatest617=== RUN TestGCTaskStore_CompletedAllowsNewTask618=== PAUSE TestGCTaskStore_CompletedAllowsNewTask619=== RUN TestGCTaskStore_PhaseUpdates620=== PAUSE TestGCTaskStore_PhaseUpdates621=== RUN TestGCTaskStore_Fail622=== PAUSE TestGCTaskStore_Fail623=== RUN TestGracefulShutdownDrainsInflight624=== PAUSE TestGracefulShutdownDrainsInflight625=== RUN TestService_healthCheckHandler626=== PAUSE TestService_healthCheckHandler627=== RUN TestService_readinessHandler628=== PAUSE TestService_readinessHandler629=== RUN TestGenerateLandingPage630=== PAUSE TestGenerateLandingPage631=== RUN TestEnsureAbortUploadsRule632=== PAUSE TestEnsureAbortUploadsRule633=== RUN TestCacheConfigHandlerMaxNarSize634=== PAUSE TestCacheConfigHandlerMaxNarSize635=== RUN TestCreatePendingClosureRejectsOversizedNAR636=== PAUSE TestCreatePendingClosureRejectsOversizedNAR637=== RUN TestNARDeduplicationMetadataUploadBug638=== PAUSE TestNARDeduplicationMetadataUploadBug639=== RUN TestMetricsInventory640=== PAUSE TestMetricsInventory641=== RUN TestMetricsCommit642=== PAUSE TestMetricsCommit643=== RUN TestService_NativeMTLS644=== PAUSE TestService_NativeMTLS645=== RUN TestServerTLSConfig646=== PAUSE TestServerTLSConfig647=== RUN TestMultipartCleanup648=== PAUSE TestMultipartCleanup649=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded650=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded651=== RUN TestPendingCleanupUsesOneCutoff652=== PAUSE TestPendingCleanupUsesOneCutoff653=== RUN TestObjectStatsTrigger654=== PAUSE TestObjectStatsTrigger655=== RUN TestObjectStatsUpdatedOncePerCommit656=== PAUSE TestObjectStatsUpdatedOncePerCommit657=== RUN TestOrphanedObjectsGC658=== PAUSE TestOrphanedObjectsGC659=== RUN TestOrphanedObjectsGCStressTest660=== PAUSE TestOrphanedObjectsGCStressTest661=== RUN TestCreatePin_ReservedPins662=== PAUSE TestCreatePin_ReservedPins663=== RUN TestPresentReportsOnlyClosureRoots664=== PAUSE TestPresentReportsOnlyClosureRoots665=== RUN TestPresentRefreshesOnlyStaleClosures666=== PAUSE TestPresentRefreshesOnlyStaleClosures667=== RUN TestPresentNotReportedWhileGCDeletesClosure668=== PAUSE TestPresentNotReportedWhileGCDeletesClosure669=== RUN TestParseSingleRange670=== PAUSE TestParseSingleRange671=== RUN TestProxyHeadersOnlyTrustedOnSocket6722026/11/09 11:53:25 INFO Starting HTTP server address=127.0.0.1:648536732026/11/09 11:53:25 INFO Starting HTTP server address=proxy.sock6742026/11/09 11:53:25 WARN mTLS auth: subject not in bound subjects subject="CN=someone"6752026/11/09 11:53:25 INFO Shutdown signal received, draining in-flight requests timeout=10s676--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.17s)677=== RUN TestIsValidCachePath678=== PAUSE TestIsValidCachePath679=== RUN TestReadProxyNarinfo680=== PAUSE TestReadProxyNarinfo681=== RUN TestReadProxyNarinfoAlreadyDecompressed682=== PAUSE TestReadProxyNarinfoAlreadyDecompressed683=== RUN TestReadProxyContentNegotiation684=== PAUSE TestReadProxyContentNegotiation685=== RUN TestReadProxyNarStreaming686=== PAUSE TestReadProxyNarStreaming687=== RUN TestReadProxy404688=== PAUSE TestReadProxy404689=== RUN TestReadProxyInvalidPath690=== PAUSE TestReadProxyInvalidPath691=== RUN TestReadProxyHead692=== PAUSE TestReadProxyHead693=== RUN TestReadProxyOutlastsServerWriteTimeout694=== PAUSE TestReadProxyOutlastsServerWriteTimeout695=== RUN TestReadProxyConditionalGet696=== PAUSE TestReadProxyConditionalGet697=== RUN TestReadProxyRootRedirectsToIndexHTML698=== PAUSE TestReadProxyRootRedirectsToIndexHTML699=== RUN TestReadProxyDisabled700=== PAUSE TestReadProxyDisabled701=== RUN TestReadRedirectNar702=== PAUSE TestReadRedirectNar703=== RUN TestReadRedirectKeepsNarinfoProxied704=== PAUSE TestReadRedirectKeepsNarinfoProxied705=== RUN TestReadProxyRangeRequest706=== PAUSE TestReadProxyRangeRequest707=== RUN TestReadRedirectUsesPublicS3URL708=== PAUSE TestReadRedirectUsesPublicS3URL709=== RUN TestPush_OverlappingRootsStoreOneRowPerKey710=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey711=== RUN TestPush_CompleteCommitsEveryRoot712=== PAUSE TestPush_CompleteCommitsEveryRoot713=== RUN TestPush_RepeatedRootCommitsOnce714=== PAUSE TestPush_RepeatedRootCommitsOnce715=== RUN TestPush_CompleteWaitsForCleanupOfThePush716=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush717=== RUN TestPush_RootsAreLockedInByteOrder718=== PAUSE TestPush_RootsAreLockedInByteOrder719=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit720=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit721=== RUN TestPush_RejectsBadRequests722=== PAUSE TestPush_RejectsBadRequests723=== RUN TestPush_SignsNarinfosOfItsPendingObjects724=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects725=== RUN TestSharedNarBothUploadsComplete726=== PAUSE TestSharedNarBothUploadsComplete727=== RUN TestCompleteMultipartUpload_ErrorButObjectExists728=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists729=== RUN TestCompletedNarNotReofferedAcrossClosures730=== PAUSE TestCompletedNarNotReofferedAcrossClosures731=== RUN TestPresignedUploadRegisteredBeforeCommit732=== PAUSE TestPresignedUploadRegisteredBeforeCommit733=== RUN TestService_Rustfstest734=== PAUSE TestService_Rustfstest735=== RUN TestParseSize736=== PAUSE TestParseSize737=== RUN TestSkippedUploadsHandler738=== PAUSE TestSkippedUploadsHandler739=== RUN TestSystemdListenerNotActivated740--- PASS: TestSystemdListenerNotActivated (0.00s)741=== RUN TestWatchdogBeatsWhenHealthy742--- PASS: TestWatchdogBeatsWhenHealthy (0.03s)743=== RUN TestWatchdogSkipsWhenUnhealthy7442026/11/09 11:53:25 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7452026/11/09 11:53:25 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7462026/11/09 11:53:25 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7472026/11/09 11:53:25 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7482026/11/09 11:53:25 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7492026/11/09 11:53:25 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7502026/11/09 11:53:25 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7512026/11/09 11:53:25 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7522026/11/09 11:53:25 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"753--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)754=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle755=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle756=== RUN TestProxyWriteTimeout757=== PAUSE TestProxyWriteTimeout758=== RUN TestPendingClosureWriteTimeout759=== PAUSE TestPendingClosureWriteTimeout760=== RUN TestIsValidUploadKey761=== PAUSE TestIsValidUploadKey762=== RUN TestUploadHandlersRejectInvalidKeys763=== PAUSE TestUploadHandlersRejectInvalidKeys764=== RUN TestUploadHandlersRejectOversizedBody765=== PAUSE TestUploadHandlersRejectOversizedBody766=== RUN TestService_cleanupPendingClosuresHandler767=== PAUSE TestService_cleanupPendingClosuresHandler768=== RUN TestService_createPendingClosureHandler769=== PAUSE TestService_createPendingClosureHandler770=== RUN TestService_verifyS3Integrity771=== PAUSE TestService_verifyS3Integrity772=== RUN TestService_verifyS3ReuploadsStaleNarinfo773=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo774=== RUN TestCompleteMultipartUnregistered775=== PAUSE TestCompleteMultipartUnregistered776=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT777=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT778=== CONT TestPush_RejectsBadRequests779=== CONT TestGCTaskStore_GetReturnsLatest780=== CONT TestResolveDBConnectionString781=== CONT TestGCTaskStore_StartNew782=== CONT TestReadProxyOutlastsServerWriteTimeout783=== CONT TestGCTaskStore_DeduplicateSameParams784--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)785--- PASS: TestGCTaskStore_StartNew (0.00s)786--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)787=== CONT TestGCEndsOnShutdown788=== RUN TestGCEndsOnShutdown/before_the_run789=== PAUSE TestGCEndsOnShutdown/before_the_run790=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete791=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete792=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark793=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark794=== CONT TestGCEndsOnShutdown/before_the_run795=== CONT TestGCSweepSkipsPendingObjects796=== CONT TestPendingCleanupUsesOneCutoff797=== RUN TestResolveDBConnectionString/flag_wins798=== PAUSE TestResolveDBConnectionString/flag_wins799=== CONT TestConnectWaitsForAPeerMigration800=== RUN TestResolveDBConnectionString/file_when_flag_empty801=== PAUSE TestResolveDBConnectionString/file_when_flag_empty802=== RUN TestResolveDBConnectionString/missing_file_is_an_error803=== CONT TestParseSingleRange804=== RUN TestParseSingleRange/none805=== PAUSE TestParseSingleRange/none806=== RUN TestParseSingleRange/unknown_unit807=== PAUSE TestParseSingleRange/unknown_unit808=== RUN TestParseSingleRange/multi-range_ignored809=== PAUSE TestParseSingleRange/multi-range_ignored810=== RUN TestParseSingleRange/malformed_no_dash811=== PAUSE TestParseSingleRange/malformed_no_dash812=== CONT TestGCTaskStore_GetEmpty813=== CONT TestGCTaskStore_ConflictDifferentParams814=== CONT TestPush_RootsAreLockedInByteOrder815=== CONT TestPush_CompleteWaitsForCleanupOfThePush816=== CONT TestPush_RepeatedRootCommitsOnce817=== CONT TestPush_CompleteCommitsEveryRoot818=== CONT TestPush_OverlappingRootsStoreOneRowPerKey819=== CONT TestReadRedirectUsesPublicS3URL820=== CONT TestReadProxyRangeRequest821=== CONT TestReadRedirectKeepsNarinfoProxied822=== CONT TestReadRedirectNar823=== CONT TestReadProxyDisabled824=== CONT TestReadProxyRootRedirectsToIndexHTML825=== CONT TestReadProxyConditionalGet826=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit827=== CONT TestAbortSucceeded828=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error829=== CONT TestReadProxyInvalidPath830=== CONT TestReadProxyHead831=== RUN TestResolveDBConnectionString/PGHOST_allows_empty832=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty833--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)834--- PASS: TestGCTaskStore_GetEmpty (0.00s)835=== RUN TestResolveDBConnectionString/nothing_configured836=== PAUSE TestResolveDBConnectionString/nothing_configured837--- PASS: TestAbortSucceeded (0.00s)838=== RUN TestParseSingleRange/malformed_both_empty839=== PAUSE TestParseSingleRange/malformed_both_empty840=== RUN TestParseSingleRange/malformed_end_before_start841=== PAUSE TestParseSingleRange/malformed_end_before_start842=== RUN TestParseSingleRange/closed843=== PAUSE TestParseSingleRange/closed844=== RUN TestParseSingleRange/open-ended845=== PAUSE TestParseSingleRange/open-ended846=== RUN TestParseSingleRange/end_clamped_to_size847=== PAUSE TestParseSingleRange/end_clamped_to_size848=== RUN TestParseSingleRange/suffix849=== PAUSE TestParseSingleRange/suffix850=== CONT TestReadProxy404851=== CONT TestReadProxyNarStreaming852=== RUN TestParseSingleRange/suffix_exceeds_size853=== PAUSE TestParseSingleRange/suffix_exceeds_size854=== RUN TestParseSingleRange/single_byte855=== PAUSE TestParseSingleRange/single_byte856=== RUN TestParseSingleRange/start_past_EOF857=== PAUSE TestParseSingleRange/start_past_EOF858=== RUN TestParseSingleRange/start_far_past_EOF859=== PAUSE TestParseSingleRange/start_far_past_EOF860=== CONT TestReadProxyContentNegotiation8612026/11/09 11:53:26 INFO Received uploads request method=POST path=/api/pending_closures8622026/11/09 11:53:26 INFO Received uploads request method=POST path=/api/pending_closures8632026/11/09 11:53:26 INFO Received cleanup request method=DELETE path=/api/pending_closures864=== RUN TestPush_RejectsBadRequests/no_roots865=== PAUSE TestPush_RejectsBadRequests/no_roots866=== RUN TestPush_RejectsBadRequests/no_objects867=== PAUSE TestPush_RejectsBadRequests/no_objects868=== RUN TestPush_RejectsBadRequests/bad_root869=== PAUSE TestPush_RejectsBadRequests/bad_root870=== RUN TestPush_RejectsBadRequests/root_not_in_objects871=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects872=== CONT TestReadProxyNarinfoAlreadyDecompressed8732026/11/09 11:53:27 INFO Received uploads request method=POST path=/api/pending_closures8742026/11/09 11:53:27 INFO Aborted multipart uploads count=0 kept=08752026/11/09 11:53:27 WARN Force mode enabled - objects will be deleted immediately without grace period8762026/11/09 11:53:27 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=08772026/11/09 11:53:27 INFO Vacuumed table table=pending_closures8782026/11/09 11:53:27 INFO Vacuumed table table=pending_objects8792026/11/09 11:53:27 INFO Vacuumed table table=multipart_uploads8802026/11/09 11:53:27 INFO Vacuumed table table=closures8812026/11/09 11:53:27 INFO Vacuumed table table=objects882--- PASS: TestGCSweepSkipsPendingObjects (1.81s)883=== CONT TestReadProxyNarinfo884=== CONT TestIsValidCachePath885=== RUN TestIsValidCachePath/narinfo886=== PAUSE TestIsValidCachePath/narinfo887=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars888=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars889=== RUN TestIsValidCachePath/nar_zst890=== PAUSE TestIsValidCachePath/nar_zst891=== RUN TestIsValidCachePath/nar_xz892=== PAUSE TestIsValidCachePath/nar_xz893=== RUN TestIsValidCachePath/nar_bz2894=== PAUSE TestIsValidCachePath/nar_bz2895=== RUN TestIsValidCachePath/nar_uncompressed896=== PAUSE TestIsValidCachePath/nar_uncompressed897=== RUN TestIsValidCachePath/ls898=== PAUSE TestIsValidCachePath/ls899=== RUN TestIsValidCachePath/log900=== PAUSE TestIsValidCachePath/log901=== RUN TestIsValidCachePath/realisation902=== PAUSE TestIsValidCachePath/realisation903=== RUN TestIsValidCachePath/nix-cache-info904=== PAUSE TestIsValidCachePath/nix-cache-info905=== RUN TestIsValidCachePath/index.html906=== PAUSE TestIsValidCachePath/index.html907=== RUN TestIsValidCachePath/traversal_parent908=== PAUSE TestIsValidCachePath/traversal_parent909=== RUN TestIsValidCachePath/traversal_in_middle910=== PAUSE TestIsValidCachePath/traversal_in_middle911=== RUN TestIsValidCachePath/invalid_char_e912=== PAUSE TestIsValidCachePath/invalid_char_e913=== RUN TestIsValidCachePath/invalid_char_u914=== PAUSE TestIsValidCachePath/invalid_char_u915=== RUN TestIsValidCachePath/random_path916=== PAUSE TestIsValidCachePath/random_path917=== RUN TestIsValidCachePath/empty918=== PAUSE TestIsValidCachePath/empty919=== RUN TestIsValidCachePath/leading_slash920=== PAUSE TestIsValidCachePath/leading_slash921=== RUN TestIsValidCachePath/wrong_extension922=== PAUSE TestIsValidCachePath/wrong_extension923=== RUN TestIsValidCachePath/short_hash924=== PAUSE TestIsValidCachePath/short_hash925=== CONT TestCreatePin_ReservedPins9262026/11/09 11:53:27 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:64871/oidc927--- PASS: TestReadProxyConditionalGet (2.11s)928=== CONT TestPresentNotReportedWhileGCDeletesClosure929=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale930=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale931=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh932=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh933=== CONT TestPresentRefreshesOnlyStaleClosures934--- PASS: TestReadRedirectNar (2.26s)935=== CONT TestPresentReportsOnlyClosureRoots936--- PASS: TestReadProxyInvalidPath (2.38s)937=== CONT TestCacheConfigHandlerMaxNarSize938--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)939=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded940--- PASS: TestReadRedirectUsesPublicS3URL (2.60s)941=== CONT TestMultipartCleanup9422026/11/09 11:53:28 INFO Received push request method=POST path=/api/pushes943--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (2.80s)944=== CONT TestServerTLSConfig945=== RUN TestServerTLSConfig/no_client_CA946=== PAUSE TestServerTLSConfig/no_client_CA947=== RUN TestServerTLSConfig/missing_CA_file948=== PAUSE TestServerTLSConfig/missing_CA_file949=== RUN TestServerTLSConfig/not_a_PEM_file950=== PAUSE TestServerTLSConfig/not_a_PEM_file951=== CONT TestService_NativeMTLS952--- PASS: TestReadProxyDisabled (2.90s)953=== CONT TestMetricsCommit9542026/11/09 11:53:28 INFO Received push request method=POST path=/api/pushes9552026/11/09 11:53:28 INFO Received complete push request method=POST path=/api/pushes/1/complete9562026/11/09 11:53:28 INFO Completed push id=1 objects=4 duration=16.083917ms957--- PASS: TestPush_RepeatedRootCommitsOnce (3.20s)958=== CONT TestMetricsInventory9592026/11/09 11:53:28 INFO Received push request method=POST path=/api/pushes9602026/11/09 11:53:28 INFO Received complete push request method=POST path=/api/pushes/1/complete9612026/11/09 11:53:28 INFO Completed push id=1 objects=6 duration=24.440416ms962--- PASS: TestPush_CompleteCommitsEveryRoot (3.39s)963=== CONT TestNARDeduplicationMetadataUploadBug9642026/11/09 11:53:29 INFO Received push request method=POST path=/api/pushes9652026-11-09 11:53:29.156 UTC [24228] ERROR: could not obtain lock on row in relation "closures"9662026-11-09 11:53:29.156 UTC [24228] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT9672026-11-09 11:53:29.158 UTC [24228] ERROR: could not obtain lock on row in relation "closures"9682026-11-09 11:53:29.158 UTC [24228] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT9692026-11-09 11:53:29.159 UTC [24228] ERROR: could not obtain lock on row in relation "closures"9702026-11-09 11:53:29.159 UTC [24228] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT9712026-11-09 11:53:29.159 UTC [24228] ERROR: could not obtain lock on row in relation "closures"9722026-11-09 11:53:29.159 UTC [24228] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT9732026-11-09 11:53:29.161 UTC [24228] ERROR: could not obtain lock on row in relation "closures"9742026-11-09 11:53:29.161 UTC [24228] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT975--- PASS: TestPush_RootsAreLockedInByteOrder (3.65s)976=== CONT TestCreatePendingClosureRejectsOversizedNAR9772026/11/09 11:53:29 INFO Received uploads request method=POST path=/api/pending_closures978--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)979=== CONT TestSweepSkipsRowsLockedByPush980--- PASS: TestReadRedirectKeepsNarinfoProxied (3.79s)981=== CONT TestCommitRacingPendingCleanupKeepsObjects9822026/11/09 11:53:29 INFO Received push request method=POST path=/api/pushes983--- PASS: TestReadProxyRootRedirectsToIndexHTML (4.15s)984=== CONT TestPushWaitsForSweepHoldingRow9852026/11/09 11:53:29 INFO Received push request method=POST path=/api/pushes9862026-11-09 11:53:29.811 UTC [24237] ERROR: Push does not exist: id=19872026-11-09 11:53:29.811 UTC [24237] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE9882026-11-09 11:53:29.811 UTC [24237] STATEMENT: SELECT commit_push($1)989--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (4.28s)990=== CONT TestSweepRechecksPendingAfterLocking9912026/11/09 11:53:29 INFO Received complete push request method=POST path=/api/pushes/1/complete9922026/11/09 11:53:29 INFO Completed push id=1 objects=4 duration=13.717541ms9932026/11/09 11:53:29 INFO Received push request method=POST path=/api/pushes9942026/11/09 11:53:30 INFO Aborted multipart uploads count=0 kept=09952026/11/09 11:53:30 WARN Force mode enabled - objects will be deleted immediately without grace period9962026/11/09 11:53:30 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=09972026/11/09 11:53:30 INFO Vacuumed table table=pending_closures9982026/11/09 11:53:30 INFO Vacuumed table table=pending_objects9992026/11/09 11:53:30 INFO Vacuumed table table=multipart_uploads10002026/11/09 11:53:30 INFO Vacuumed table table=closures10012026/11/09 11:53:30 INFO Vacuumed table table=objects10022026/11/09 11:53:30 INFO Received complete push request method=POST path=/api/pushes/2/complete10032026/11/09 11:53:30 INFO Completed push id=2 objects=4 duration=6.21ms1004--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (4.68s)1005=== CONT TestGetExistingObjectsLocksRows1006--- PASS: TestReadProxyHead (4.79s)1007=== CONT TestRegisterCompletedObjectNeedsPendingRow1008--- PASS: TestReadProxy404 (4.89s)1009=== CONT TestOrphanedObjectsGC1010--- PASS: TestReadProxyContentNegotiation (5.06s)1011=== CONT TestOrphanedObjectsGCStressTest1012--- PASS: TestReadProxyRangeRequest (5.18s)1013=== CONT TestObjectStatsUpdatedOncePerCommit1014--- PASS: TestReadProxyNarStreaming (5.36s)1015=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection1016--- PASS: TestReadProxyOutlastsServerWriteTimeout (5.38s)1017=== CONT TestFailedS3DeleteKeepsTombstone1018--- PASS: TestReadProxyNarinfoAlreadyDecompressed (4.72s)1019=== CONT TestForceGCDuringPushOffersSweptObject1020=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows1021=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows1022=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check1023=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check1024=== CONT TestGCSweepDeliversEachKeyOnce1025--- PASS: TestConnectWaitsForAPeerMigration (5.69s)1026=== CONT TestLeadEndsOnShutdown10272026/11/09 11:53:31 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>1028--- PASS: TestReadProxyNarinfo (4.03s)1029=== CONT TestDeduplicatedObjectsRecordedAsPending10302026/11/09 11:53:31 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux10312026/11/09 11:53:31 WARN Refused reserved pin name=worker-x86_64-linux10322026/11/09 11:53:31 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux10332026/11/09 11:53:31 INFO Received create pin request method=POST path=/api/pins/my-app10342026/11/09 11:53:31 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1035--- PASS: TestCreatePin_ReservedPins (3.99s)1036=== CONT TestPushDedupSurvivesConcurrentGC1037--- PASS: TestPresentRefreshesOnlyStaleClosures (4.05s)1038=== CONT TestGCMetrics1039--- PASS: TestPresentReportsOnlyClosureRoots (4.09s)1040=== CONT TestGCBugBareHashReferences10412026/11/09 11:53:32 INFO Received uploads request method=POST path=/api/pending_closures1042--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (4.26s)1043=== CONT TestGCAdvisoryLockBlocksConcurrentRun10442026/11/09 11:53:32 INFO Received uploads request method=POST path=/api/pending_closures10452026/11/09 11:53:32 INFO Aborted multipart uploads count=1 kept=010462026/11/09 11:53:32 INFO Received cleanup request method=DELETE path=/api/pending_closures10472026/11/09 11:53:32 INFO Aborted multipart uploads count=1 kept=01048--- PASS: TestPendingCleanupUsesOneCutoff (6.95s)1049=== CONT TestTombstonedObjectOfferedWithoutWaiting10502026/11/09 11:53:32 INFO Received cleanup request method=DELETE path=/api/pending_closures10512026/11/09 11:53:32 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket33/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""10522026/11/09 11:53:32 INFO Aborted multipart uploads count=0 kept=110532026/11/09 11:53:32 INFO Received cleanup request method=DELETE path=/api/pending_closures10542026/11/09 11:53:32 INFO Aborted multipart uploads count=1 kept=010552026/11/09 11:53:32 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1056--- PASS: TestMultipartCleanup (4.53s)1057=== CONT TestService_healthCheckHandler10582026/11/09 11:53:32 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1059--- PASS: TestService_NativeMTLS (4.34s)1060=== CONT TestEnsureAbortUploadsRule10612026/11/09 11:53:32 INFO Received push request method=POST path=/api/pushes10622026/11/09 11:53:32 INFO Received complete push request method=POST path=/api/pushes/1/complete10632026/11/09 11:53:33 INFO Completed push id=1 objects=4 duration=58.023375ms10642026/11/09 11:53:33 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete10652026/11/09 11:53:33 INFO Completed upload id=2 objects=2 duration=5.791208ms1066--- PASS: TestMetricsCommit (4.65s)1067=== CONT TestGenerateLandingPage1068--- PASS: TestGenerateLandingPage (0.00s)1069=== CONT TestService_readinessHandler1070--- PASS: TestMetricsInventory (4.54s)1071=== CONT TestLeadIncumbentAnnouncesAtOnce1072=== NAME TestNARDeduplicationMetadataUploadBug1073 metadata_upload_test.go:48: First store path: /private/var/tb/8/scratch/b4189290b5638e57/build/TestNARDeduplicationMetadataUploadBug3889530055/001/store/8qwyb9haygcfj29ijlclr0pf3pnfd54y-file1.txt10742026/11/09 11:53:33 INFO Aborted multipart uploads count=0 kept=010752026/11/09 11:53:33 WARN Force mode enabled - objects will be deleted immediately without grace period10762026/11/09 11:53:33 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=010772026/11/09 11:53:33 INFO Vacuumed table table=pending_closures10782026/11/09 11:53:33 INFO Vacuumed table table=pending_objects10792026/11/09 11:53:33 INFO Vacuumed table table=multipart_uploads10802026/11/09 11:53:33 INFO Vacuumed table table=closures10812026/11/09 11:53:33 INFO Vacuumed table table=objects10822026/11/09 11:53:33 INFO Aborted multipart uploads count=0 kept=010832026/11/09 11:53:33 WARN Force mode enabled - objects will be deleted immediately without grace period10842026/11/09 11:53:33 INFO Received push request method=POST path=/api/pushes10852026/11/09 11:53:33 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)10862026/11/09 11:53:33 INFO Uploading 8qwyb9haygcfj29ijlclr0pf3pnfd54y-file1.txt (160B)10872026/11/09 11:53:34 WARN Failed to register uploaded object key=8qwyb9haygcfj29ijlclr0pf3pnfd54y.ls error="server returned 404: 404 page not found\n"10882026/11/09 11:53:34 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"10892026/11/09 11:53:34 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10902026/11/09 11:53:34 INFO Signed narinfos id=1 count=110912026/11/09 11:53:34 INFO Uploading 1 narinfos10922026/11/09 11:53:34 INFO Received complete push request method=POST path=/api/pushes/1/complete10932026/11/09 11:53:34 WARN Failed to register uploaded object key=8qwyb9haygcfj29ijlclr0pf3pnfd54y.narinfo error="server returned 404: 404 page not found\n"10942026/11/09 11:53:34 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=010952026/11/09 11:53:34 INFO Vacuumed table table=pending_closures10962026/11/09 11:53:34 INFO Completed push id=1 objects=3 duration=34.332792ms10972026/11/09 11:53:34 INFO Upload complete. (290ms)10982026/11/09 11:53:34 INFO Vacuumed table table=pending_objects1099 metadata_upload_test.go:54: Retrieved narinfo from S3:1100 StorePath: /private/var/tb/8/scratch/b4189290b5638e57/build/TestNARDeduplicationMetadataUploadBug3889530055/001/store/8qwyb9haygcfj29ijlclr0pf3pnfd54y-file1.txt1101 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1102 Compression: zstd1103 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1104 NarSize: 1601105 References: 1106 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf11072026/11/09 11:53:34 INFO Vacuumed table table=multipart_uploads1108 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1109 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1110 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}11112026/11/09 11:53:34 INFO Vacuumed table table=closures11122026/11/09 11:53:34 INFO Vacuumed table table=objects1113--- PASS: TestSweepSkipsRowsLockedByPush (4.99s)1114=== CONT TestLeadElectsOneAndHandsOver11152026/11/09 11:53:34 INFO Aborted multipart uploads count=0 kept=011162026/11/09 11:53:34 WARN Force mode enabled - objects will be deleted immediately without grace period1117=== NAME TestNARDeduplicationMetadataUploadBug1118 metadata_upload_test.go:64: Second store path (same content): /private/var/tb/8/scratch/b4189290b5638e57/build/TestNARDeduplicationMetadataUploadBug3889530055/001/store/76hslrx2yk5rxwm4lvciqxiw3pvpdd5q-file2.txt11192026/11/09 11:53: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=011202026/11/09 11:53:34 INFO Vacuumed table table=pending_closures11212026/11/09 11:53:34 INFO Vacuumed table table=pending_objects11222026/11/09 11:53:34 INFO Vacuumed table table=multipart_uploads11232026/11/09 11:53:34 INFO Vacuumed table table=closures11242026/11/09 11:53:34 INFO Vacuumed table table=objects11252026/11/09 11:53:34 INFO Received uploads request method=POST path=/api/pending_closures1126--- PASS: TestCommitRacingPendingCleanupKeepsObjects (4.96s)1127=== CONT TestClientIntegration11282026/11/09 11:53:34 INFO Received push request method=POST path=/api/pushes11292026/11/09 11:53:34 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)11302026/11/09 11:53:34 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign11312026/11/09 11:53:34 INFO Signed narinfos id=2 count=111322026/11/09 11:53:34 WARN Failed to register uploaded object key=76hslrx2yk5rxwm4lvciqxiw3pvpdd5q.ls error="server returned 404: 404 page not found\n"11332026/11/09 11:53:34 INFO Uploading 1 narinfos11342026/11/09 11:53:34 INFO Received complete push request method=POST path=/api/pushes/2/complete11352026/11/09 11:53:34 WARN Failed to register uploaded object key=76hslrx2yk5rxwm4lvciqxiw3pvpdd5q.narinfo error="server returned 404: 404 page not found\n"11362026/11/09 11:53:34 INFO Completed push id=2 objects=3 duration=1.087334ms11372026/11/09 11:53:34 INFO Upload complete. (136ms)1138=== NAME TestNARDeduplicationMetadataUploadBug1139 metadata_upload_test.go:76: Retrieved narinfo from S3:1140 StorePath: /private/var/tb/8/scratch/b4189290b5638e57/build/TestNARDeduplicationMetadataUploadBug3889530055/001/store/76hslrx2yk5rxwm4lvciqxiw3pvpdd5q-file2.txt1141 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1142 Compression: zstd1143 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1144 NarSize: 1601145 References: 1146 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1147 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1148 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1149 {"version":1,"root":{"type":"regular","size":44}}1150--- PASS: TestNARDeduplicationMetadataUploadBug (5.54s)1151=== CONT TestCompleteMultipartUploadRetriesTransientFailure11522026/11/09 11:53:34 INFO Aborted multipart uploads count=0 kept=011532026/11/09 11:53:34 WARN Force mode enabled - objects will be deleted immediately without grace period11542026/11/09 11:53: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=011552026/11/09 11:53:34 INFO Vacuumed table table=pending_closures11562026/11/09 11:53:34 INFO Vacuumed table table=pending_objects11572026/11/09 11:53:34 INFO Vacuumed table table=multipart_uploads11582026/11/09 11:53:34 INFO Vacuumed table table=closures11592026/11/09 11:53:34 INFO Vacuumed table table=objects1160--- PASS: TestSweepRechecksPendingAfterLocking (4.91s)1161=== CONT TestRetryableCompletionError1162=== RUN TestRetryableCompletionError/context_canceled1163=== PAUSE TestRetryableCompletionError/context_canceled1164=== RUN TestRetryableCompletionError/degraded_quorum1165=== PAUSE TestRetryableCompletionError/degraded_quorum1166=== RUN TestRetryableCompletionError/transport_failure1167=== PAUSE TestRetryableCompletionError/transport_failure1168=== RUN TestRetryableCompletionError/no_such_upload1169=== PAUSE TestRetryableCompletionError/no_such_upload1170=== RUN TestRetryableCompletionError/invalid_part1171=== PAUSE TestRetryableCompletionError/invalid_part1172=== RUN TestRetryableCompletionError/throttled1173=== PAUSE TestRetryableCompletionError/throttled1174=== RUN TestRetryableCompletionError/deadline_exceeded1175=== PAUSE TestRetryableCompletionError/deadline_exceeded1176=== RUN TestRetryableCompletionError/nil1177=== PAUSE TestRetryableCompletionError/nil1178=== RUN TestRetryableCompletionError/bad_gateway1179=== PAUSE TestRetryableCompletionError/bad_gateway1180=== RUN TestRetryableCompletionError/access_denied1181=== PAUSE TestRetryableCompletionError/access_denied1182=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock1183--- PASS: TestGetExistingObjectsLocksRows (4.56s)1184=== CONT TestDeleteClosuresRacingPins1185--- PASS: TestPushWaitsForSweepHoldingRow (5.11s)1186=== CONT TestClientFallsBackToClosures1187--- PASS: TestRegisterCompletedObjectNeedsPendingRow (4.67s)1188=== CONT TestClientPushesUseOnePush1189--- PASS: TestObjectStatsUpdatedOncePerCommit (5.60s)1190=== CONT TestPinProtectsFromGC11912026/11/09 11:53:36 INFO Received uploads request method=POST path=/api/pending_closures11922026/11/09 11:53:36 INFO Aborted multipart uploads count=0 kept=011932026/11/09 11:53:36 WARN Force mode enabled - objects will be deleted immediately without grace period11942026/11/09 11:53:36 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."11952026/11/09 11:53:36 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."1196--- PASS: TestFailedS3DeleteKeepsTombstone (5.88s)1197=== CONT TestClientSharedPathCommittedMidPush11982026/11/09 11:53:36 INFO Received uploads request method=POST path=/api/pending_closures1199--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (6.15s)1200=== CONT TestClientWithDependencies12012026/11/09 11:53:37 INFO Aborted multipart uploads count=0 kept=012022026/11/09 11:53:37 WARN Force mode enabled - objects will be deleted immediately without grace period1203=== NAME TestOrphanedObjectsGC1204 orphaned_objects_gc_test.go:287: GC Test Summary:1205 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A1206 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B1207 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)1208 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)1209 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects1210--- PASS: TestOrphanedObjectsGC (7.34s)1211=== CONT TestClientMultipleUploads12122026/11/09 11:53:37 INFO lead: acquired remote=192.0.2.1:123412132026/11/09 11:53:38 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=012142026/11/09 11:53:38 INFO Vacuumed table table=pending_closures12152026/11/09 11:53:38 INFO Vacuumed table table=pending_objects12162026/11/09 11:53:38 INFO Vacuumed table table=multipart_uploads12172026/11/09 11:53:38 INFO Vacuumed table table=closures12182026/11/09 11:53:38 INFO Vacuumed table table=objects12192026/11/09 11:53:38 INFO Received uploads request method=POST path=/api/pending_closures1220--- PASS: TestGCSweepDeliversEachKeyOnce (7.19s)1221=== CONT TestPendingClosureWriteTimeout1222=== RUN TestPendingClosureWriteTimeout/empty1223=== PAUSE TestPendingClosureWriteTimeout/empty1224=== RUN TestPendingClosureWriteTimeout/400_objects1225=== PAUSE TestPendingClosureWriteTimeout/400_objects1226=== RUN TestPendingClosureWriteTimeout/670k_objects1227=== PAUSE TestPendingClosureWriteTimeout/670k_objects1228=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1229=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1230=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT1231--- PASS: TestDeduplicatedObjectsRecordedAsPending (6.95s)1232=== CONT TestCompleteMultipartUnregistered12332026/11/09 11:53:38 INFO Received uploads request method=POST path=/api/pending_closures12342026/11/09 11:53:38 INFO Aborted multipart uploads count=0 kept=012352026/11/09 11:53:38 INFO Aborted multipart uploads count=0 kept=012362026/11/09 11:53:38 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=012372026/11/09 11:53:38 WARN Force mode enabled - objects will be deleted immediately without grace period12382026/11/09 11:53:38 INFO Vacuumed table table=pending_closures12392026/11/09 11:53:38 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=012402026/11/09 11:53:38 INFO Vacuumed table table=pending_closures12412026/11/09 11:53:38 INFO Vacuumed table table=pending_objects12422026/11/09 11:53:38 INFO Vacuumed table table=multipart_uploads12432026/11/09 11:53:38 INFO Vacuumed table table=closures12442026/11/09 11:53:38 INFO Vacuumed table table=pending_objects12452026/11/09 11:53:38 INFO Vacuumed table table=objects12462026/11/09 11:53:38 INFO lead: released remote=192.0.2.1:12341247--- PASS: TestLeadEndsOnShutdown (7.76s)1248=== CONT TestService_verifyS3ReuploadsStaleNarinfo1249=== RUN TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed1250=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed1251=== RUN TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed1252=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed1253=== RUN TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost1254=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost1255=== RUN TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed1256=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed1257=== RUN TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed1258=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed1259=== CONT TestService_verifyS3Integrity12602026/11/09 11:53:38 INFO Vacuumed table table=multipart_uploads1261--- PASS: TestGCMetrics (7.29s)1262=== CONT TestService_createPendingClosureHandler12632026/11/09 11:53:38 INFO Vacuumed table table=closures12642026/11/09 11:53:39 INFO Vacuumed table table=objects12652026/11/09 11:53:39 INFO Aborted multipart uploads count=0 kept=012662026/11/09 11:53:39 WARN Force mode enabled - objects will be deleted immediately without grace period12672026/11/09 11:53:39 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=012682026/11/09 11:53:39 INFO Vacuumed table table=pending_closures12692026/11/09 11:53:39 INFO Vacuumed table table=pending_objects12702026/11/09 11:53:39 INFO Vacuumed table table=multipart_uploads12712026/11/09 11:53:39 INFO Vacuumed table table=closures12722026/11/09 11:53:39 INFO Vacuumed table table=objects1273--- PASS: TestPushDedupSurvivesConcurrentGC (7.67s)1274=== CONT TestService_cleanupPendingClosuresHandler1275--- PASS: TestGCBugBareHashReferences (7.60s)1276=== CONT TestUploadHandlersRejectOversizedBody12772026/11/09 11:53:39 ERROR failed to check GC advisory lock error="query pg_locks: failed to connect to `user=_tribuchetbld8 database=niks3`: /nonexistent/.s.PGSQL.5432 (/nonexistent): dial error: dial unix /nonexistent/.s.PGSQL.5432: connect: no such file or directory"1278--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (7.40s)1279=== CONT TestUploadHandlersRejectInvalidKeys1280=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1281=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1282=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1283=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1284=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1285=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1286=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1287=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1288=== CONT TestIsValidUploadKey1289=== RUN TestIsValidUploadKey/narinfo1290=== PAUSE TestIsValidUploadKey/narinfo1291=== RUN TestIsValidUploadKey/nar_zst1292=== PAUSE TestIsValidUploadKey/nar_zst1293=== RUN TestIsValidUploadKey/nar_xz1294=== PAUSE TestIsValidUploadKey/nar_xz1295=== RUN TestIsValidUploadKey/nar_plain1296=== PAUSE TestIsValidUploadKey/nar_plain1297=== RUN TestIsValidUploadKey/listing1298=== PAUSE TestIsValidUploadKey/listing1299=== RUN TestIsValidUploadKey/build_log1300=== PAUSE TestIsValidUploadKey/build_log1301=== RUN TestIsValidUploadKey/build_log_home-manager_file1302=== PAUSE TestIsValidUploadKey/build_log_home-manager_file1303=== RUN TestIsValidUploadKey/build_log_plus_in_name1304=== PAUSE TestIsValidUploadKey/build_log_plus_in_name1305=== RUN TestIsValidUploadKey/build_log_question_mark1306=== PAUSE TestIsValidUploadKey/build_log_question_mark1307=== RUN TestIsValidUploadKey/build_log_equals1308=== PAUSE TestIsValidUploadKey/build_log_equals1309=== RUN TestIsValidUploadKey/realisation1310=== PAUSE TestIsValidUploadKey/realisation1311=== RUN TestIsValidUploadKey/realisation_plus_in_output1312=== PAUSE TestIsValidUploadKey/realisation_plus_in_output1313=== RUN TestIsValidUploadKey/nix-cache-info1314=== PAUSE TestIsValidUploadKey/nix-cache-info1315=== RUN TestIsValidUploadKey/index.html1316=== PAUSE TestIsValidUploadKey/index.html1317=== RUN TestIsValidUploadKey/narinfo_key,_nar_type1318=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type1319=== RUN TestIsValidUploadKey/nar_key,_narinfo_type1320=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type1321=== RUN TestIsValidUploadKey/listing_key,_narinfo_type1322=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type1323=== RUN TestIsValidUploadKey/traversal1324=== PAUSE TestIsValidUploadKey/traversal1325=== RUN TestIsValidUploadKey/traversal_nar1326=== PAUSE TestIsValidUploadKey/traversal_nar1327=== RUN TestIsValidUploadKey/absolute1328=== PAUSE TestIsValidUploadKey/absolute1329=== RUN TestIsValidUploadKey/empty_key1330=== PAUSE TestIsValidUploadKey/empty_key1331=== RUN TestIsValidUploadKey/unknown_type1332=== PAUSE TestIsValidUploadKey/unknown_type1333=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark13342026/11/09 11:53:40 INFO Received uploads request method=POST path=/api/pending_closures1335--- PASS: TestTombstonedObjectOfferedWithoutWaiting (7.80s)1336=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1337=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure1338=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure1339=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart1340=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart1341=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts1342=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts13432026/11/09 11:53:40 INFO Installed lifecycle rule aborting incomplete NAR uploads bucket=bucket57 days=21344=== CONT TestService_RequireScope_OIDC1345--- PASS: TestEnsureAbortUploadsRule (7.65s)1346=== CONT TestClientErrorHandling1347=== RUN TestClientErrorHandling/InvalidStorePath1348=== PAUSE TestClientErrorHandling/InvalidStorePath1349=== RUN TestClientErrorHandling/InvalidAuthToken1350=== PAUSE TestClientErrorHandling/InvalidAuthToken1351=== RUN TestClientErrorHandling/ServerNotAvailable1352=== PAUSE TestClientErrorHandling/ServerNotAvailable1353=== CONT TestClientCADerivations13542026/11/09 11:53:40 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:65053/oidc1355--- PASS: TestService_healthCheckHandler (7.79s)1356=== CONT TestCacheStatsHandler13572026/11/09 11:53:40 WARN readiness check failed error="closed pool"1358--- PASS: TestService_readinessHandler (7.64s)1359=== CONT TestCacheConfigHandler1360=== RUN TestCacheConfigHandler/full_config,_no_issuer1361=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1362=== RUN TestCacheConfigHandler/no_cache_url_configured1363=== PAUSE TestCacheConfigHandler/no_cache_url_configured1364=== RUN TestCacheConfigHandler/no_signing_keys1365=== PAUSE TestCacheConfigHandler/no_signing_keys1366=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1367=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1368=== CONT TestService_ReadScope_PublicByDefault13692026/11/09 11:53:41 INFO lead: acquired remote=192.0.2.1:123413702026/11/09 11:53:41 INFO lead: released remote=192.0.2.1:12341371--- PASS: TestLeadIncumbentAnnouncesAtOnce (7.74s)1372=== CONT TestGCTaskStore_Fail1373--- PASS: TestGCTaskStore_Fail (0.00s)1374=== CONT TestGracefulShutdownDrainsInflight13752026/11/09 11:53:41 INFO Starting HTTP server address=127.0.0.1:6506113762026/11/09 11:53:41 INFO Shutdown signal received, draining in-flight requests timeout=10s1377--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1378=== CONT TestObjectStatsTrigger13792026/11/09 11:53:41 INFO lead: acquired remote=192.0.2.1:12341380=== NAME TestClientIntegration1381 client_integration_test.go:291: Created store path: /private/var/tb/8/scratch/b4189290b5638e57/build/TestClientIntegration2203933958/002/store/i4i91bk0wgvqga7wwhy7vlvl3sypag7a-test-file.txt13822026/11/09 11:53:41 INFO Received uploads request method=POST path=/api/pending_closures13832026/11/09 11:53:42 INFO Received push request method=POST path=/api/pushes13842026/11/09 11:53:42 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)13852026/11/09 11:53:42 INFO Uploading i4i91bk0wgvqga7wwhy7vlvl3sypag7a-test-file.txt (152B)13862026/11/09 11:53:42 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13872026/11/09 11:53:42 WARN Failed to register uploaded object key=i4i91bk0wgvqga7wwhy7vlvl3sypag7a.ls error="server returned 404: 404 page not found\n"13882026/11/09 11:53:42 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"13892026/11/09 11:53:42 INFO Signed narinfos id=1 count=113902026/11/09 11:53:42 INFO Uploading 1 narinfos13912026/11/09 11:53:42 INFO Received complete push request method=POST path=/api/pushes/1/complete13922026/11/09 11:53:42 WARN Failed to register uploaded object key=i4i91bk0wgvqga7wwhy7vlvl3sypag7a.narinfo error="server returned 404: 404 page not found\n"13932026/11/09 11:53:42 INFO Completed push id=1 objects=3 duration=32.434375ms13942026/11/09 11:53:42 INFO Upload complete. (286ms)13952026/11/09 11:53:42 INFO All 1 paths already cached13962026/11/09 11:53:42 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1397 client_integration_test.go:317: Retrieved narinfo from S3:1398 StorePath: /private/var/tb/8/scratch/b4189290b5638e57/build/TestClientIntegration2203933958/002/store/i4i91bk0wgvqga7wwhy7vlvl3sypag7a-test-file.txt1399 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1400 Compression: zstd1401 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11402 NarSize: 1521403 References: 1404 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11405 client_integration_test.go:318: Retrieved .ls file from S3 (compressed size: 77 bytes)1406 client_integration_test.go:318: Decompressed .ls content (64 bytes):1407 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}14082026/11/09 11:53:42 INFO lead: released remote=192.0.2.1:123414092026/11/09 11:53:42 INFO lead: acquired remote=192.0.2.1:123414102026/11/09 11:53:42 INFO Completed multipart upload object_key=nar/cccccccccccccccccccccccccccccc0100000000000000000000.nar.zst upload_id=OTgzNTgyZmUtODRjZC00ZDk3LWE4YmYtYjIyNDA0N2QwZTM0LjA3ZTA5MmM2LTE3M2EtNDRmMi1hYjgzLWIyZWMzMjg1MDJhNXgxNzk0MjI1MjIxOTk5NzUwMDAw parts=21411--- PASS: TestCompleteMultipartUploadRetriesTransientFailure (8.14s)1412=== CONT TestService_AuthMiddleware_MTLSBoundSubjects14132026/11/09 11:53:42 INFO Received push request method=POST path=/api/pushes14142026/11/09 11:53:42 INFO Object in database but missing from S3 key=i4i91bk0wgvqga7wwhy7vlvl3sypag7a.ls14152026/11/09 11:53:42 WARN Found objects in DB but missing from S3, will re-upload count=114162026/11/09 11:53:42 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)14172026/11/09 11:53:42 INFO Received complete push request method=POST path=/api/pushes/2/complete14182026/11/09 11:53:42 WARN Failed to register uploaded object key=i4i91bk0wgvqga7wwhy7vlvl3sypag7a.ls error="server returned 404: 404 page not found\n"14192026/11/09 11:53:42 INFO Completed push id=2 objects=3 duration=652.167µs14202026/11/09 11:53:42 INFO Upload complete. (113ms)1421=== NAME TestClientIntegration1422 client_integration_test.go:335: Retrieved .ls file from S3 (compressed size: 62 bytes)1423 client_integration_test.go:335: Decompressed .ls content (49 bytes):1424 {"version":1,"root":{"type":"regular","size":39}}14252026/11/09 11:53:43 INFO Received push request method=POST path=/api/pushes14262026/11/09 11:53:43 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)14272026/11/09 11:53:43 INFO Received complete push request method=POST path=/api/pushes/3/complete14282026/11/09 11:53:43 WARN Failed to register uploaded object key=i4i91bk0wgvqga7wwhy7vlvl3sypag7a.ls error="server returned 404: 404 page not found\n"14292026/11/09 11:53:43 INFO Completed push id=3 objects=3 duration=1.152292ms14302026/11/09 11:53:43 INFO Upload complete. (114ms)1431 client_integration_test.go:352: Retrieved .ls file from S3 (compressed size: 62 bytes)1432 client_integration_test.go:352: Decompressed .ls content (49 bytes):1433 {"version":1,"root":{"type":"regular","size":39}}1434 client_integration_test.go:363: Testing garbage collection...14352026/11/09 11:53:43 INFO Starting cleanup of old closures method=DELETE path=/api/closures14362026/11/09 11:53:43 INFO Garbage collection started14372026/11/09 11:53:43 INFO Aborted multipart uploads count=0 kept=014382026/11/09 11:53:43 WARN Force mode enabled - objects will be deleted immediately without grace period1439--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (8.59s)1440=== CONT TestService_AuthMiddleware_OIDC14412026/11/09 11:53:43 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:65105/oidc14422026/11/09 11:53:43 INFO Received uploads request method=POST path=/api/pending_closures14432026/11/09 11:53:43 INFO Received uploads request method=POST path=/api/pending_closures14442026/11/09 11:53:43 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)14452026/11/09 11:53:43 INFO Uploading hwdmdsx9h7m4wbdv4dirwqj6s64372kc-shared-dep (136B)14462026/11/09 11:53:43 INFO Uploading k7jpxpb76p9kkxi5wgqkzvpw459l026b-a (256B)14472026/11/09 11:53:43 WARN Failed to register uploaded object key=b04ni2warnyaazib6xnwgyj1zvb68sr1.ls error="server returned 404: 404 page not found\n"14482026/11/09 11:53:43 WARN Failed to register uploaded object key=hwdmdsx9h7m4wbdv4dirwqj6s64372kc.ls error="server returned 404: 404 page not found\n"14492026/11/09 11:53:43 WARN Failed to register uploaded object key=k7jpxpb76p9kkxi5wgqkzvpw459l026b.ls error="server returned 404: 404 page not found\n"14502026/11/09 11:53:43 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"14512026/11/09 11:53:43 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign14522026/11/09 11:53:43 WARN Failed to register uploaded object key=nar/08xbflf7srqvmn8wcdzkd3xz6qydaw7a5sln3sdzcc8gqq2qn0vr.nar.zst error="server returned 404: 404 page not found\n"14532026/11/09 11:53:43 INFO Signed narinfos id=1 count=214542026/11/09 11:53:43 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign14552026/11/09 11:53:43 INFO Signed narinfos id=2 count=214562026/11/09 11:53:43 INFO Uploading 4 narinfos14572026/11/09 11:53:43 WARN Failed to register uploaded object key=b04ni2warnyaazib6xnwgyj1zvb68sr1.narinfo error="server returned 404: 404 page not found\n"14582026/11/09 11:53:43 WARN Failed to register uploaded object key=k7jpxpb76p9kkxi5wgqkzvpw459l026b.narinfo error="server returned 404: 404 page not found\n"14592026/11/09 11:53:43 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=014602026/11/09 11:53:43 WARN Failed to register uploaded object key=hwdmdsx9h7m4wbdv4dirwqj6s64372kc.narinfo error="server returned 404: 404 page not found\n"14612026/11/09 11:53:43 INFO Vacuumed table table=pending_closures14622026/11/09 11:53:43 INFO lead: released remote=192.0.2.1:12341463--- PASS: TestLeadElectsOneAndHandsOver (9.52s)1464=== CONT TestService_ReadAuthMiddleware14652026/11/09 11:53:43 INFO Vacuumed table table=pending_objects14662026/11/09 11:53:43 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14672026/11/09 11:53:43 WARN Failed to register uploaded object key=hwdmdsx9h7m4wbdv4dirwqj6s64372kc.narinfo error="server returned 404: 404 page not found\n"14682026/11/09 11:53:43 INFO Vacuumed table table=multipart_uploads14692026/11/09 11:53:43 INFO Vacuumed table table=closures14702026/11/09 11:53:43 INFO Completed upload id=1 objects=6 duration=19.381833ms14712026/11/09 11:53:43 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete14722026/11/09 11:53:43 INFO Completed upload id=2 objects=6 duration=402.583µs14732026/11/09 11:53:43 INFO Upload complete. (433ms)1474=== NAME TestClientFallsBackToClosures1475 client_pushes_test.go:112: Retrieved narinfo from S3:1476 StorePath: /private/var/tb/8/scratch/b4189290b5638e57/build/TestClientFallsBackToClosures934565825/001/store/hwdmdsx9h7m4wbdv4dirwqj6s64372kc-shared-dep1477 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1478 Compression: zstd1479 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821480 NarSize: 1361481 References: 1482 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1483 client_pushes_test.go:112: Retrieved narinfo from S3:1484 StorePath: /private/var/tb/8/scratch/b4189290b5638e57/build/TestClientFallsBackToClosures934565825/001/store/k7jpxpb76p9kkxi5wgqkzvpw459l026b-a1485 URL: nar/08xbflf7srqvmn8wcdzkd3xz6qydaw7a5sln3sdzcc8gqq2qn0vr.nar.zst1486 Compression: zstd1487 NarHash: sha256:08xbflf7srqvmn8wcdzkd3xz6qydaw7a5sln3sdzcc8gqq2qn0vr1488 NarSize: 25614892026/11/09 11:53:43 INFO Vacuumed table table=objects1490 References: /private/var/tb/8/scratch/b4189290b5638e57/build/TestClientFallsBackToClosures934565825/001/store/hwdmdsx9h7m4wbdv4dirwqj6s64372kc-shared-dep1491 CA: text:sha256:1dqmknhksvxmrhrgiadh5l5jwlvvfc1198kqdh93y76wn17ryhy71492 client_pushes_test.go:112: Retrieved narinfo from S3:1493 StorePath: /private/var/tb/8/scratch/b4189290b5638e57/build/TestClientFallsBackToClosures934565825/001/store/b04ni2warnyaazib6xnwgyj1zvb68sr1-b1494 URL: nar/08xbflf7srqvmn8wcdzkd3xz6qydaw7a5sln3sdzcc8gqq2qn0vr.nar.zst1495 Compression: zstd1496 NarHash: sha256:08xbflf7srqvmn8wcdzkd3xz6qydaw7a5sln3sdzcc8gqq2qn0vr1497 NarSize: 2561498 References: /private/var/tb/8/scratch/b4189290b5638e57/build/TestClientFallsBackToClosures934565825/001/store/hwdmdsx9h7m4wbdv4dirwqj6s64372kc-shared-dep1499 CA: text:sha256:1dqmknhksvxmrhrgiadh5l5jwlvvfc1198kqdh93y76wn17ryhy71500--- PASS: TestClientFallsBackToClosures (9.04s)1501=== CONT TestService_AuthMiddleware_MTLSProxyHeader1502=== NAME TestPinProtectsFromGC1503 client_integration_test.go:778: Pinned store path: /private/var/tb/8/scratch/b4189290b5638e57/build/TestPinProtectsFromGC934937887/001/store/sb42df16fqa7vsvdvgi47a4dqw72p9gh-pinned-file.txt1504 client_integration_test.go:779: Unpinned store path: /private/var/tb/8/scratch/b4189290b5638e57/build/TestPinProtectsFromGC934937887/001/store/9mvzyrwg61va8xahpz8xak73fhwzx1rc-unpinned-file.txt15052026/11/09 11:53:43 INFO Received push request method=POST path=/api/pushes15062026/11/09 11:53:43 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)15072026/11/09 11:53:43 INFO Uploading n204dlm3g2856q64zpl6xzkb4a9s5kx8-shared-dep (136B)15082026/11/09 11:53:43 INFO Uploading k3iflqpyd79qp24bqjx2b8h054rvlksc-b (256B)15092026/11/09 11:53:43 WARN Failed to register uploaded object key=38vxm5vv5j9g9i8a221q6s6r443c5xfl.ls error="server returned 404: 404 page not found\n"15102026/11/09 11:53:43 WARN Failed to register uploaded object key=k3iflqpyd79qp24bqjx2b8h054rvlksc.ls error="server returned 404: 404 page not found\n"15112026/11/09 11:53:44 WARN Failed to register uploaded object key=n204dlm3g2856q64zpl6xzkb4a9s5kx8.ls error="server returned 404: 404 page not found\n"15122026/11/09 11:53:44 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"15132026/11/09 11:53:44 WARN Failed to register uploaded object key=nar/1aqqbzxavk8waxkcn0bcq2f2imirj20bjzn2zx48g0vxp5fyyask.nar.zst error="server returned 404: 404 page not found\n"15142026/11/09 11:53:44 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15152026/11/09 11:53:44 INFO Signed narinfos id=1 count=315162026/11/09 11:53:44 INFO Received push request method=POST path=/api/pushes15172026/11/09 11:53:44 INFO Uploading 3 narinfos15182026/11/09 11:53:44 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15192026/11/09 11:53:44 INFO Uploading sb42df16fqa7vsvdvgi47a4dqw72p9gh-pinned-file.txt (128B)15202026/11/09 11:53:44 WARN Failed to register uploaded object key=n204dlm3g2856q64zpl6xzkb4a9s5kx8.narinfo error="server returned 404: 404 page not found\n"15212026/11/09 11:53:44 WARN Failed to register uploaded object key=k3iflqpyd79qp24bqjx2b8h054rvlksc.narinfo error="server returned 404: 404 page not found\n"15222026/11/09 11:53:44 INFO Received complete push request method=POST path=/api/pushes/1/complete15232026/11/09 11:53:44 WARN Failed to register uploaded object key=38vxm5vv5j9g9i8a221q6s6r443c5xfl.narinfo error="server returned 404: 404 page not found\n"15242026/11/09 11:53:44 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"15252026/11/09 11:53:44 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15262026/11/09 11:53:44 WARN Failed to register uploaded object key=sb42df16fqa7vsvdvgi47a4dqw72p9gh.ls error="server returned 404: 404 page not found\n"15272026/11/09 11:53:44 INFO Signed narinfos id=1 count=115282026/11/09 11:53:44 INFO Completed push id=1 objects=8 duration=19.770709ms15292026/11/09 11:53:44 INFO Upload complete. (293ms)15302026/11/09 11:53:44 INFO Uploading 1 narinfos1531=== NAME TestClientPushesUseOnePush1532 client_pushes_test.go:97: Retrieved narinfo from S3:1533 StorePath: /private/var/tb/8/scratch/b4189290b5638e57/build/TestClientPushesUseOnePush212491800/001/store/n204dlm3g2856q64zpl6xzkb4a9s5kx8-shared-dep1534 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1535 Compression: zstd1536 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821537 NarSize: 1361538 References: 1539 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1540 client_pushes_test.go:97: Retrieved narinfo from S3:1541 StorePath: /private/var/tb/8/scratch/b4189290b5638e57/build/TestClientPushesUseOnePush212491800/001/store/38vxm5vv5j9g9i8a221q6s6r443c5xfl-a1542 URL: nar/1aqqbzxavk8waxkcn0bcq2f2imirj20bjzn2zx48g0vxp5fyyask.nar.zst1543 Compression: zstd1544 NarHash: sha256:1aqqbzxavk8waxkcn0bcq2f2imirj20bjzn2zx48g0vxp5fyyask1545 NarSize: 2561546 References: /private/var/tb/8/scratch/b4189290b5638e57/build/TestClientPushesUseOnePush212491800/001/store/n204dlm3g2856q64zpl6xzkb4a9s5kx8-shared-dep1547 CA: text:sha256:1ai1lbpirq47ai9gx2ckfadndcq8j1c3ix4hsy11kfh1z3zss9kl1548 client_pushes_test.go:97: Retrieved narinfo from S3:1549 StorePath: /private/var/tb/8/scratch/b4189290b5638e57/build/TestClientPushesUseOnePush212491800/001/store/k3iflqpyd79qp24bqjx2b8h054rvlksc-b1550 URL: nar/1aqqbzxavk8waxkcn0bcq2f2imirj20bjzn2zx48g0vxp5fyyask.nar.zst1551 Compression: zstd1552 NarHash: sha256:1aqqbzxavk8waxkcn0bcq2f2imirj20bjzn2zx48g0vxp5fyyask1553 NarSize: 2561554 References: /private/var/tb/8/scratch/b4189290b5638e57/build/TestClientPushesUseOnePush212491800/001/store/n204dlm3g2856q64zpl6xzkb4a9s5kx8-shared-dep1555 CA: text:sha256:1ai1lbpirq47ai9gx2ckfadndcq8j1c3ix4hsy11kfh1z3zss9kl15562026/11/09 11:53:44 INFO Received complete push request method=POST path=/api/pushes/1/complete15572026/11/09 11:53:44 WARN Failed to register uploaded object key=sb42df16fqa7vsvdvgi47a4dqw72p9gh.narinfo error="server returned 404: 404 page not found\n"15582026/11/09 11:53:44 INFO Completed push id=1 objects=3 duration=32.502708ms15592026/11/09 11:53:44 INFO Upload complete. (276ms)1560--- PASS: TestClientPushesUseOnePush (9.24s)1561=== CONT TestService_AuthMiddleware15622026/11/09 11:53:44 INFO Received push request method=POST path=/api/pushes15632026/11/09 11:53:44 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15642026/11/09 11:53:44 INFO Uploading 9mvzyrwg61va8xahpz8xak73fhwzx1rc-unpinned-file.txt (128B)1565=== NAME TestClientWithDependencies1566 client_integration_test.go:660: Built derivation: /private/var/tb/8/scratch/b4189290b5638e57/build/TestClientWithDependencies3170840306/001/store/6vli00jksyrmamzzxzvgz2dji0y3xxpd-test-script15672026/11/09 11:53:44 WARN Failed to register uploaded object key=9mvzyrwg61va8xahpz8xak73fhwzx1rc.ls error="server returned 404: 404 page not found\n"15682026/11/09 11:53:44 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign15692026/11/09 11:53:44 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"15702026/11/09 11:53:44 INFO Signed narinfos id=2 count=11571 client_integration_test.go:662: Found 1 dependencies (including self)15722026/11/09 11:53:44 INFO Uploading 1 narinfos15732026/11/09 11:53:44 INFO Received complete push request method=POST path=/api/pushes/2/complete15742026/11/09 11:53:44 WARN Failed to register uploaded object key=9mvzyrwg61va8xahpz8xak73fhwzx1rc.narinfo error="server returned 404: 404 page not found\n"15752026/11/09 11:53:44 INFO Completed push id=2 objects=3 duration=830.291µs15762026/11/09 11:53:44 INFO Upload complete. (203ms)15772026/11/09 11:53:44 INFO Received push request method=POST path=/api/pushes15782026/11/09 11:53:44 INFO Starting cleanup of old closures method=DELETE path=/api/closures15792026/11/09 11:53:44 INFO Garbage collection started15802026/11/09 11:53:44 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15812026/11/09 11:53:44 INFO Uploading 6vli00jksyrmamzzxzvgz2dji0y3xxpd-test-script (136B)15822026/11/09 11:53:44 INFO Aborted multipart uploads count=0 kept=015832026/11/09 11:53:44 WARN Force mode enabled - objects will be deleted immediately without grace period15842026/11/09 11:53:44 INFO Received push request method=POST path=/api/pushes15852026/11/09 11:53:44 WARN Failed to register uploaded object key=6vli00jksyrmamzzxzvgz2dji0y3xxpd.ls error="server returned 404: 404 page not found\n"15862026/11/09 11:53:44 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"15872026/11/09 11:53:44 WARN Failed to register uploaded object key=log/hppijyw2jh3ngkr566msp7wl3k4pb4mk-test-script.drv error="server returned 404: 404 page not found\n"15882026/11/09 11:53:44 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15892026/11/09 11:53:44 INFO Signed narinfos id=1 count=115902026/11/09 11:53:44 INFO Uploading 1 narinfos15912026/11/09 11:53:44 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)15922026/11/09 11:53:44 INFO Uploading fb7ljdx0cmi006jxr405h3a48xl64glp-shared-dep (136B)15932026/11/09 11:53:44 INFO Uploading f25bdh72q7r5ia6pzd0zymyxyjqsli7a-top (264B)15942026/11/09 11:53:44 INFO Received complete push request method=POST path=/api/pushes/1/complete15952026/11/09 11:53:44 WARN Failed to register uploaded object key=6vli00jksyrmamzzxzvgz2dji0y3xxpd.narinfo error="server returned 404: 404 page not found\n"15962026/11/09 11:53:44 WARN Failed to register uploaded object key=fb7ljdx0cmi006jxr405h3a48xl64glp.ls error="server returned 404: 404 page not found\n"15972026/11/09 11:53:44 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"15982026/11/09 11:53:44 INFO Completed push id=1 objects=4 duration=33.279084ms15992026/11/09 11:53:44 INFO Upload complete. (272ms)16002026/11/09 11:53:44 WARN Failed to register uploaded object key=f25bdh72q7r5ia6pzd0zymyxyjqsli7a.ls error="server returned 404: 404 page not found\n"16012026/11/09 11:53:44 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16022026/11/09 11:53:44 WARN Failed to register uploaded object key=nar/11v0v454a9ivxb9f7acgh18wwdwr07a58xp0as4mslh2pahpfsrb.nar.zst error="server returned 404: 404 page not found\n"16032026/11/09 11:53:44 INFO Signed narinfos id=1 count=216042026/11/09 11:53:44 INFO Uploading 2 narinfos1605 client_integration_test.go:664: Skipping nix copy test - isolated store (/private/var/tb/8/scratch/b4189290b5638e57/build/TestClientWithDependencies3170840306/001/store) requires matching store prefix1606=== NAME TestClientMultipleUploads1607 client_integration_test.go:405: Created store path 0: /private/var/tb/8/scratch/b4189290b5638e57/build/TestClientMultipleUploads2942124026/001/store/w0pmlls5h3zkdj9hyh0j8v6jbifd9i00-test-file-0.txt16082026/11/09 11:53:44 INFO Received uploads request method=POST path=/api/pending_closures16092026/11/09 11:53:44 WARN Failed to register uploaded object key=f25bdh72q7r5ia6pzd0zymyxyjqsli7a.narinfo error="server returned 404: 404 page not found\n"16102026/11/09 11:53:44 INFO Received complete push request method=POST path=/api/pushes/1/complete16112026/11/09 11:53:44 WARN Failed to register uploaded object key=fb7ljdx0cmi006jxr405h3a48xl64glp.narinfo error="server returned 404: 404 page not found\n"16122026/11/09 11:53:44 INFO Completed push id=1 objects=6 duration=26.200584ms16132026/11/09 11:53:44 INFO Upload complete. (348ms)1614=== NAME TestClientSharedPathCommittedMidPush1615 client_integration_test.go:727: Retrieved narinfo from S3:1616 StorePath: /private/var/tb/8/scratch/b4189290b5638e57/build/TestClientSharedPathCommittedMidPush597423620/001/store/fb7ljdx0cmi006jxr405h3a48xl64glp-shared-dep1617 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1618 Compression: zstd1619 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821620 NarSize: 1361621 References: 1622 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1623 client_integration_test.go:727: Retrieved narinfo from S3:1624 StorePath: /private/var/tb/8/scratch/b4189290b5638e57/build/TestClientSharedPathCommittedMidPush597423620/001/store/f25bdh72q7r5ia6pzd0zymyxyjqsli7a-top1625 URL: nar/11v0v454a9ivxb9f7acgh18wwdwr07a58xp0as4mslh2pahpfsrb.nar.zst1626 Compression: zstd1627 NarHash: sha256:11v0v454a9ivxb9f7acgh18wwdwr07a58xp0as4mslh2pahpfsrb1628 NarSize: 2641629 References: /private/var/tb/8/scratch/b4189290b5638e57/build/TestClientSharedPathCommittedMidPush597423620/001/store/fb7ljdx0cmi006jxr405h3a48xl64glp-shared-dep1630 CA: text:sha256:0vwjjg173cpssrdi4rjs9lcfcn4w0hd8w2rqkszrb1fqqswj82fj1631--- PASS: TestClientWithDependencies (7.84s)1632=== CONT TestGCTaskStore_PhaseUpdates1633--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1634=== CONT TestService_Rustfstest1635=== NAME TestClientMultipleUploads1636 client_integration_test.go:405: Created store path 1: /private/var/tb/8/scratch/b4189290b5638e57/build/TestClientMultipleUploads2942124026/001/store/a58jqsf5snh082wn5asrdkyrnklsskp5-test-file-1.txt1637--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (6.63s)1638=== CONT TestProxyWriteTimeout1639=== RUN TestProxyWriteTimeout/narinfo1640=== PAUSE TestProxyWriteTimeout/narinfo1641=== RUN TestProxyWriteTimeout/1_GiB_nar1642=== PAUSE TestProxyWriteTimeout/1_GiB_nar1643=== RUN TestProxyWriteTimeout/10_GiB_nar1644=== PAUSE TestProxyWriteTimeout/10_GiB_nar1645=== RUN TestProxyWriteTimeout/unknown_size1646=== PAUSE TestProxyWriteTimeout/unknown_size1647=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1648--- PASS: TestClientSharedPathCommittedMidPush (8.21s)1649=== CONT TestSkippedUploadsHandler16502026/11/09 11:53:45 INFO Client skipped oversized paths paths=3 nar_bytes=50000000001651--- PASS: TestSkippedUploadsHandler (0.01s)1652=== CONT TestParseSize1653--- PASS: TestParseSize (0.00s)1654=== CONT TestCompleteMultipartUpload_ErrorButObjectExists16552026/11/09 11:53:45 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=01656=== NAME TestClientMultipleUploads1657 client_integration_test.go:405: Created store path 2: /private/var/tb/8/scratch/b4189290b5638e57/build/TestClientMultipleUploads2942124026/001/store/shrdwhiqb9bhyjnbin8k9plgwy3pwg2z-test-file-2.txt16582026/11/09 11:53:45 INFO Vacuumed table table=pending_closures16592026/11/09 11:53:45 INFO Vacuumed table table=pending_objects16602026/11/09 11:53:45 INFO Vacuumed table table=multipart_uploads16612026/11/09 11:53:45 INFO Vacuumed table table=closures16622026/11/09 11:53:45 INFO Vacuumed table table=objects16632026/11/09 11:53:45 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=016642026/11/09 11:53:45 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1665=== NAME TestClientIntegration1666 client_integration_test.go:370: Objects in database after GC:1667 client_integration_test.go:370: Successfully deleted all objects with GC --force16682026/11/09 11:53:45 INFO Received push request method=POST path=/api/pushes16692026/11/09 11:53:45 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst1670--- PASS: TestCompleteMultipartUnregistered (6.86s)1671=== CONT TestPresignedUploadRegisteredBeforeCommit16722026/11/09 11:53:45 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)16732026/11/09 11:53:45 INFO Uploading shrdwhiqb9bhyjnbin8k9plgwy3pwg2z-test-file-2.txt (160B)16742026/11/09 11:53:45 INFO Uploading a58jqsf5snh082wn5asrdkyrnklsskp5-test-file-1.txt (160B)16752026/11/09 11:53:45 INFO Uploading w0pmlls5h3zkdj9hyh0j8v6jbifd9i00-test-file-0.txt (160B)16762026/11/09 11:53:45 WARN Failed to register uploaded object key=shrdwhiqb9bhyjnbin8k9plgwy3pwg2z.ls error="server returned 404: 404 page not found\n"16772026/11/09 11:53:45 WARN Failed to register uploaded object key=a58jqsf5snh082wn5asrdkyrnklsskp5.ls error="server returned 404: 404 page not found\n"16782026/11/09 11:53:45 WARN Failed to register uploaded object key=w0pmlls5h3zkdj9hyh0j8v6jbifd9i00.ls error="server returned 404: 404 page not found\n"16792026/11/09 11:53:45 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"16802026/11/09 11:53:45 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"16812026/11/09 11:53:45 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16822026/11/09 11:53:45 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"16832026/11/09 11:53:45 INFO Signed narinfos id=1 count=316842026/11/09 11:53:45 INFO Uploading 3 narinfos1685--- PASS: TestClientIntegration (11.02s)1686=== CONT TestCompletedNarNotReofferedAcrossClosures16872026/11/09 11:53:45 WARN Failed to register uploaded object key=shrdwhiqb9bhyjnbin8k9plgwy3pwg2z.narinfo error="server returned 404: 404 page not found\n"16882026/11/09 11:53:45 INFO Received complete push request method=POST path=/api/pushes/1/complete16892026/11/09 11:53:45 WARN Failed to register uploaded object key=w0pmlls5h3zkdj9hyh0j8v6jbifd9i00.narinfo error="server returned 404: 404 page not found\n"16902026/11/09 11:53:45 WARN Failed to register uploaded object key=a58jqsf5snh082wn5asrdkyrnklsskp5.narinfo error="server returned 404: 404 page not found\n"16912026/11/09 11:53:45 INFO Completed push id=1 objects=9 duration=23.948833ms16922026/11/09 11:53:45 INFO Upload complete. (294ms)1693=== NAME TestClientMultipleUploads1694 client_integration_test.go:416: Uploaded 3 paths in 330.927833ms1695--- PASS: TestClientMultipleUploads (7.71s)1696=== CONT TestSharedNarBothUploadsComplete16972026/11/09 11:53:45 INFO Received uploads request method=POST path=/api/pending_closures16982026/11/09 11:53:45 INFO Received uploads request method=POST path=/api/pending_closures16992026/11/09 11:53:45 INFO Received uploads request method=POST path=/api/pending_closures17002026/11/09 11:53:45 INFO Received cleanup request method=DELETE path=/api/pending_closures17012026/11/09 11:53:45 INFO Aborted multipart uploads count=0 kept=017022026/11/09 11:53:45 INFO Received uploads request method=POST path=/api/pending_closures17032026/11/09 11:53:46 INFO Received cleanup request method=DELETE path=/api/pending_closures17042026/11/09 11:53:46 INFO Aborted multipart uploads count=1 kept=017052026/11/09 11:53:46 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete17062026-11-09 11:53:46.088 UTC [24384] ERROR: Closure does not exist: id=117072026-11-09 11:53:46.088 UTC [24384] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE17082026-11-09 11:53:46.088 UTC [24384] STATEMENT: -- name: CommitPendingClosure :one1709 SELECT commit_pending_closure($1::bigint)::bigint1710 1711--- PASS: TestService_cleanupPendingClosuresHandler (6.95s)1712=== CONT TestGCTaskStore_CompletedAllowsNewTask1713--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1714=== CONT TestPush_SignsNarinfosOfItsPendingObjects17152026/11/09 11:53:46 INFO Received uploads request method=POST path=/api/pending_closures17162026/11/09 11:53:46 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=017172026/11/09 11:53:46 INFO Received create pin request method=POST path=/api/pins/myapp17182026/11/09 11:53:46 INFO Created/updated pin name=myapp store_path=/private/var/tb/8/scratch/b4189290b5638e57/build/TestPinProtectsFromGC934937887/001/store/sb42df16fqa7vsvdvgi47a4dqw72p9gh-pinned-file.txt narinfo_key=sb42df16fqa7vsvdvgi47a4dqw72p9gh.narinfo17192026/11/09 11:53:46 INFO Starting cleanup of old closures method=DELETE path=/api/closures17202026/11/09 11:53:46 INFO Garbage collection started17212026/11/09 11:53:46 INFO Aborted multipart uploads count=0 kept=017222026/11/09 11:53:46 WARN Force mode enabled - objects will be deleted immediately without grace period17232026/11/09 11:53:46 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=017242026/11/09 11:53:46 INFO Vacuumed table table=pending_closures17252026/11/09 11:53:46 INFO Vacuumed table table=pending_objects17262026/11/09 11:53:46 INFO Vacuumed table table=multipart_uploads17272026/11/09 11:53:46 INFO Vacuumed table table=closures17282026/11/09 11:53:46 INFO Vacuumed table table=objects17292026/11/09 11:53:46 INFO Aborted multipart uploads count=0 kept=017302026/11/09 11:53:46 WARN Force mode enabled - objects will be deleted immediately without grace period17312026-11-09 11:53:46.729 UTC [24488] ERROR: canceling statement due to user request17322026-11-09 11:53:46.729 UTC [24488] CONTEXT: while locking tuple (0,1) in relation "objects"17332026-11-09 11:53:46.729 UTC [24488] STATEMENT: -- name: MarkStaleObjects :execrows1734 WITH RECURSIVE ct AS (1735 SELECT timezone('UTC', now()) AS now1736 ),1737 closure_reach AS (1738 -- Start with all closure keys1739 SELECT o.key, o.refs1740 FROM objects o1741 INNER JOIN closures c ON o.key = c.key1742 UNION1743 -- Recursively add all referenced objects1744 SELECT o.key, o.refs1745 FROM objects o1746 INNER JOIN closure_reach cr ON o.key = ANY(cr.refs)1747 ),1748 reachable_objects AS (1749 SELECT DISTINCT key FROM closure_reach1750 ),1751 stale_objects AS (1752 SELECT o.key1753 FROM objects AS o, ct1754 WHERE1755 NOT EXISTS (1756 SELECT 11757 FROM reachable_objects ro1758 WHERE ro.key = o.key1759 )1760 AND NOT EXISTS (1761 SELECT 11762 FROM pending_objects AS po1763 WHERE po.key = o.key1764 )1765 AND o.deleted_at IS NULL -- Only mark fresh objects1766 ORDER BY o.key COLLATE "C" -- lock in key order, like commit_pending_closure1767 FOR UPDATE1768 )1769 UPDATE objects1770 SET1771 deleted_at = ct.now,1772 first_deleted_at = COALESCE(first_deleted_at, ct.now)1773 FROM stale_objects, ct1774 WHERE objects.key = stale_objects.key1775 1776=== CONT TestResolveDBConnectionString/flag_wins1777=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1778=== CONT TestResolveDBConnectionString/missing_file_is_an_error1779=== CONT TestResolveDBConnectionString/file_when_flag_empty1780=== CONT TestResolveDBConnectionString/nothing_configured1781=== CONT TestParseSingleRange/none1782=== CONT TestParseSingleRange/open-ended1783=== CONT TestParseSingleRange/start_far_past_EOF1784=== CONT TestParseSingleRange/start_past_EOF1785=== CONT TestParseSingleRange/single_byte1786=== CONT TestParseSingleRange/suffix_exceeds_size1787=== CONT TestParseSingleRange/suffix1788=== CONT TestParseSingleRange/end_clamped_to_size1789=== CONT TestParseSingleRange/malformed_both_empty1790=== CONT TestParseSingleRange/closed1791=== CONT TestParseSingleRange/malformed_end_before_start1792=== CONT TestParseSingleRange/multi-range_ignored1793=== CONT TestParseSingleRange/malformed_no_dash1794=== CONT TestParseSingleRange/unknown_unit1795--- PASS: TestParseSingleRange (0.00s)1796 --- PASS: TestParseSingleRange/none (0.00s)1797 --- PASS: TestParseSingleRange/open-ended (0.00s)1798 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1799 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1800 --- PASS: TestParseSingleRange/single_byte (0.00s)1801 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1802 --- PASS: TestParseSingleRange/suffix (0.00s)1803 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1804 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1805 --- PASS: TestParseSingleRange/closed (0.00s)1806 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1807 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1808 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1809 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1810=== CONT TestPush_RejectsBadRequests/no_roots18112026/11/09 11:53:46 INFO Received push request method=POST path=/api/pushes1812=== CONT TestPush_RejectsBadRequests/bad_root18132026/11/09 11:53:46 INFO Received push request method=POST path=/api/pushes1814=== CONT TestPush_RejectsBadRequests/root_not_in_objects18152026/11/09 11:53:46 INFO Received push request method=POST path=/api/pushes1816=== CONT TestPush_RejectsBadRequests/no_objects18172026/11/09 11:53:46 INFO Received push request method=POST path=/api/pushes1818=== CONT TestIsValidCachePath/narinfo1819=== CONT TestIsValidCachePath/index.html1820=== CONT TestIsValidCachePath/short_hash1821=== CONT TestIsValidCachePath/wrong_extension1822=== CONT TestIsValidCachePath/leading_slash1823=== CONT TestIsValidCachePath/empty1824=== CONT TestIsValidCachePath/random_path1825=== CONT TestIsValidCachePath/invalid_char_u1826--- PASS: TestPush_RejectsBadRequests (0.83s)1827 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)1828 --- PASS: TestPush_RejectsBadRequests/bad_root (0.01s)1829 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)1830 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)1831=== CONT TestIsValidCachePath/invalid_char_e1832=== CONT TestIsValidCachePath/traversal_in_middle1833=== CONT TestIsValidCachePath/traversal_parent1834=== CONT TestIsValidCachePath/nar_uncompressed1835=== CONT TestIsValidCachePath/nix-cache-info1836=== CONT TestIsValidCachePath/realisation1837=== CONT TestIsValidCachePath/log1838=== CONT TestIsValidCachePath/ls1839=== CONT TestIsValidCachePath/nar_xz1840=== CONT TestIsValidCachePath/nar_bz21841=== CONT TestIsValidCachePath/nar_zst1842=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1843--- PASS: TestIsValidCachePath (0.00s)1844 --- PASS: TestIsValidCachePath/narinfo (0.00s)1845 --- PASS: TestIsValidCachePath/index.html (0.00s)1846 --- PASS: TestIsValidCachePath/short_hash (0.00s)1847 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1848 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1849 --- PASS: TestIsValidCachePath/empty (0.00s)1850 --- PASS: TestIsValidCachePath/random_path (0.00s)1851 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1852 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1853 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1854 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1855 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1856 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1857 --- PASS: TestIsValidCachePath/realisation (0.00s)1858 --- PASS: TestIsValidCachePath/log (0.00s)1859 --- PASS: TestIsValidCachePath/ls (0.00s)1860 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1861 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1862 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1863 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1864=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale1865--- PASS: TestResolveDBConnectionString (0.02s)1866 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1867 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1868 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1869 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)1870 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)18712026/11/09 11:53:47 INFO Received complete multipart upload request method=POST path=/api/multipart/complete18722026/11/09 11:53:47 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=OTgzNTgyZmUtODRjZC00ZDk3LWE4YmYtYjIyNDA0N2QwZTM0LmI4Y2EzYTk1LTNhYzMtNDc3MS04ZTQzLWIxNWVhMzE4ZWRhZXgxNzk0MjI1MjI1NTg3Njk0MDAw parts=1018732026/11/09 11:53:47 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete18742026/11/09 11:53:47 INFO Completed upload id=1 objects=2 duration=39.221ms18752026/11/09 11:53:47 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000018762026/11/09 11:53:47 INFO Received uploads request method=POST path=/api/pending_closures18772026/11/09 11:53:47 INFO Starting cleanup of old closures method=DELETE path=/api/closures18782026/11/09 11:53:47 INFO Aborted multipart uploads count=0 kept=018792026/11/09 11:53:47 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=018802026/11/09 11:53:47 INFO Aborted multipart uploads count=0 kept=018812026/11/09 11:53:47 INFO Vacuumed table table=pending_closures18822026/11/09 11:53:47 WARN Force mode enabled - objects will be deleted immediately without grace period18832026/11/09 11:53:47 INFO Vacuumed table table=pending_objects1884--- PASS: TestDeleteClosuresRacingPins (12.93s)1885=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh18862026/11/09 11:53:47 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:64787/bucket79/?delete=\": context canceled"1887--- PASS: TestGCEndsOnShutdown (0.00s)1888 --- PASS: TestGCEndsOnShutdown/before_the_run (1.95s)1889 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (7.02s)1890 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (7.45s)1891=== CONT TestServerTLSConfig/no_client_CA1892=== CONT TestServerTLSConfig/not_a_PEM_file1893=== CONT TestServerTLSConfig/missing_CA_file1894--- PASS: TestServerTLSConfig (0.00s)1895 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1896 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.01s)1897 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1898=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows18992026/11/09 11:53:47 INFO Vacuumed table table=multipart_uploads19002026/11/09 11:53:47 INFO Vacuumed table table=closures19012026/11/09 11:53:47 INFO Vacuumed table table=objects19022026/11/09 11:53:47 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001903--- PASS: TestService_createPendingClosureHandler (8.85s)1904=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check1905=== NAME TestClientCADerivations1906 client_ca_test.go:136: Built CA derivation: /private/var/tb/8/scratch/b4189290b5638e57/build/TestClientCADerivations2134709223/001/store/kar925x5jav7q665k98nm6cs9s7q5l33-ca-test1907 client_ca_test.go:139: Found 1 dependencies (including self)1908--- PASS: TestCacheStatsHandler (7.55s)1909=== CONT TestRetryableCompletionError/context_canceled1910=== CONT TestRetryableCompletionError/throttled1911=== CONT TestRetryableCompletionError/access_denied1912=== CONT TestRetryableCompletionError/bad_gateway1913=== CONT TestRetryableCompletionError/nil1914=== CONT TestRetryableCompletionError/deadline_exceeded1915=== CONT TestRetryableCompletionError/no_such_upload1916=== CONT TestRetryableCompletionError/invalid_part1917=== CONT TestRetryableCompletionError/transport_failure1918=== CONT TestRetryableCompletionError/degraded_quorum1919--- PASS: TestRetryableCompletionError (0.02s)1920 --- PASS: TestRetryableCompletionError/context_canceled (0.00s)1921 --- PASS: TestRetryableCompletionError/throttled (0.00s)1922 --- PASS: TestRetryableCompletionError/access_denied (0.00s)1923 --- PASS: TestRetryableCompletionError/bad_gateway (0.00s)1924 --- PASS: TestRetryableCompletionError/nil (0.00s)1925 --- PASS: TestRetryableCompletionError/deadline_exceeded (0.00s)1926 --- PASS: TestRetryableCompletionError/no_such_upload (0.00s)1927 --- PASS: TestRetryableCompletionError/invalid_part (0.00s)1928 --- PASS: TestRetryableCompletionError/transport_failure (0.00s)1929 --- PASS: TestRetryableCompletionError/degraded_quorum (0.00s)1930=== CONT TestPendingClosureWriteTimeout/empty1931=== CONT TestPendingClosureWriteTimeout/670k_objects1932=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline19332026/11/09 11:53:48 INFO Received push request method=POST path=/api/pushes19342026/11/09 11:53:48 INFO Received complete multipart upload request method=POST path=/api/multipart/complete19352026/11/09 11:53:48 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)19362026/11/09 11:53:48 INFO Uploading kar925x5jav7q665k98nm6cs9s7q5l33-ca-test (144B)19372026/11/09 11:53:48 WARN Failed to register uploaded object key=kar925x5jav7q665k98nm6cs9s7q5l33.ls error="server returned 404: 404 page not found\n"19382026/11/09 11:53:48 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=OTgzNTgyZmUtODRjZC00ZDk3LWE4YmYtYjIyNDA0N2QwZTM0Ljg2YmIyYmQ3LTEwY2ItNGQzYi1hMWNlLWViNzZhODA3ODNiN3gxNzk0MjI1MjI2MjcyMzMzMDAw parts=1019392026/11/09 11:53:48 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete19402026/11/09 11:53:48 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"19412026/11/09 11:53:48 WARN Failed to register uploaded object key=log/w52n2k1yyrm569aqdq9akxygid13wxx2-ca-test.drv error="server returned 404: 404 page not found\n"19422026/11/09 11:53:48 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19432026/11/09 11:53:48 INFO Completed upload id=1 objects=2 duration=23.863375ms19442026/11/09 11:53:48 INFO Signed narinfos id=1 count=11945=== RUN TestService_RequireScope_OIDC/builder_may_write19462026/11/09 11:53:48 INFO Received uploads request method=POST path=/api/pending_closures1947=== PAUSE TestService_RequireScope_OIDC/builder_may_write1948=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1949=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1950=== RUN TestService_RequireScope_OIDC/ops_may_admin1951=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1952=== RUN TestService_RequireScope_OIDC/ops_may_not_write1953=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1954=== RUN TestService_RequireScope_OIDC/reader_may_not_write1955=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1956=== RUN TestService_RequireScope_OIDC/static_token_may_admin1957=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1958=== RUN TestService_RequireScope_OIDC/static_token_may_write1959=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1960=== RUN TestService_RequireScope_OIDC/reader_may_read19612026/11/09 11:53:48 INFO Uploading 1 narinfos1962=== PAUSE TestService_RequireScope_OIDC/reader_may_read1963=== RUN TestService_RequireScope_OIDC/writer_implies_read1964=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1965=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1966=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1967=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1968=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc1969=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1970=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1971=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1972=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1973=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1974=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1975=== CONT TestPendingClosureWriteTimeout/400_objects1976=== CONT TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed19772026/11/09 11:53:48 INFO Received uploads request method=POST path=/api/pending_closures19782026/11/09 11:53:48 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo19792026/11/09 11:53:48 WARN Found objects in DB but missing from S3, will re-upload count=11980--- PASS: TestService_verifyS3Integrity (9.37s)1981=== CONT TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed19822026/11/09 11:53:48 INFO Received complete push request method=POST path=/api/pushes/1/complete19832026/11/09 11:53:48 WARN Failed to register uploaded object key=kar925x5jav7q665k98nm6cs9s7q5l33.narinfo error="server returned 404: 404 page not found\n"19842026/11/09 11:53:48 INFO Completed push id=1 objects=4 duration=28.364209ms19852026/11/09 11:53:48 INFO Upload complete. (487ms)1986=== NAME TestClientCADerivations1987 client_ca_test.go:180: Narinfo contains CA field: StorePath: /private/var/tb/8/scratch/b4189290b5638e57/build/TestClientCADerivations2134709223/001/store/kar925x5jav7q665k98nm6cs9s7q5l33-ca-test1988 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1989 Compression: zstd1990 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1991 NarSize: 1441992 References: 1993 Deriver: /private/var/tb/8/scratch/b4189290b5638e57/build/TestClientCADerivations2134709223/001/store/w52n2k1yyrm569aqdq9akxygid13wxx2-ca-test.drv1994 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1995 client_ca_test.go:185: Checking for realisation files in S3...1996 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1997 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache1998 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket78?endpoint=http://localhost:64787®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/private/var/tb/8/scratch/b4189290b5638e57/build/TestClientCADerivations2134709223/001/store'1999 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 12000--- PASS: TestService_ReadScope_PublicByDefault (7.80s)2001=== CONT TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed2002=== NAME TestPinProtectsFromGC2003 client_integration_test.go:887: Pin successfully protected closure from garbage collection2004--- PASS: TestClientCADerivations (8.27s)2005=== CONT TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost2006--- PASS: TestPinProtectsFromGC (12.31s)2007=== CONT TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed2008=== NAME TestOrphanedObjectsGCStressTest2009 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains2010 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion2011--- PASS: TestObjectStatsTrigger (7.85s)2012=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info20132026/11/09 11:53:48 INFO Received uploads request method=POST path=/2014=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key20152026/11/09 11:53:48 INFO Received request for more parts method=POST path=/2016=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key20172026/11/09 11:53:48 INFO Received complete multipart upload request method=POST path=/2018=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal20192026/11/09 11:53:48 INFO Received uploads request method=POST path=/2020--- PASS: TestUploadHandlersRejectInvalidKeys (0.01s)2021 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)2022 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)2023 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)2024 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)2025=== CONT TestIsValidUploadKey/narinfo2026=== CONT TestIsValidUploadKey/realisation_plus_in_output2027=== CONT TestIsValidUploadKey/unknown_type2028=== CONT TestIsValidUploadKey/empty_key2029=== CONT TestIsValidUploadKey/absolute2030=== CONT TestIsValidUploadKey/traversal_nar2031=== CONT TestIsValidUploadKey/traversal2032=== CONT TestIsValidUploadKey/listing_key,_narinfo_type2033=== CONT TestIsValidUploadKey/nar_key,_narinfo_type2034=== CONT TestIsValidUploadKey/narinfo_key,_nar_type2035=== CONT TestIsValidUploadKey/index.html2036=== CONT TestIsValidUploadKey/nix-cache-info2037=== CONT TestIsValidUploadKey/build_log_home-manager_file2038=== CONT TestIsValidUploadKey/realisation2039=== CONT TestIsValidUploadKey/build_log_equals2040=== CONT TestIsValidUploadKey/build_log_question_mark2041=== CONT TestIsValidUploadKey/build_log_plus_in_name2042=== CONT TestIsValidUploadKey/nar_plain2043=== CONT TestIsValidUploadKey/build_log2044=== CONT TestIsValidUploadKey/listing2045=== CONT TestIsValidUploadKey/nar_xz2046=== CONT TestIsValidUploadKey/nar_zst2047=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure2048--- PASS: TestIsValidUploadKey (0.11s)2049 --- PASS: TestIsValidUploadKey/narinfo (0.00s)2050 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)2051 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)2052 --- PASS: TestIsValidUploadKey/empty_key (0.00s)2053 --- PASS: TestIsValidUploadKey/absolute (0.00s)2054 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)2055 --- PASS: TestIsValidUploadKey/traversal (0.00s)2056 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)2057 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)2058 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)2059 --- PASS: TestIsValidUploadKey/index.html (0.00s)2060 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)2061 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)2062 --- PASS: TestIsValidUploadKey/realisation (0.00s)2063 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)2064 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)2065 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)2066 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)2067 --- PASS: TestIsValidUploadKey/build_log (0.00s)2068 --- PASS: TestIsValidUploadKey/listing (0.00s)2069 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)2070 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)20712026/11/09 11:53:48 INFO Received uploads request method=POST path=/20722026/11/09 11:53:49 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"20732026/11/09 11:53:49 WARN mTLS auth: bound subjects configured but subject DN unavailable20742026/11/09 11:53:49 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"2075--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (6.45s)2076=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts20772026/11/09 11:53:49 INFO Received request for more parts method=POST path=/2078=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart20792026/11/09 11:53:49 INFO Received complete multipart upload request method=POST path=/2080=== CONT TestClientErrorHandling/InvalidStorePath2081=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token2082=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token2083=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2084=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2085=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected2086=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected2087=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2088=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2089=== CONT TestClientErrorHandling/ServerNotAvailable2090=== CONT TestClientErrorHandling/InvalidAuthToken2091--- PASS: TestUploadHandlersRejectOversizedBody (0.82s)2092 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.04s)2093 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.08s)2094 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.53s)20952026/11/09 11:53:49 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/present2096--- PASS: TestService_ReadAuthMiddleware (5.90s)2097=== CONT TestCacheConfigHandler/full_config,_no_issuer2098=== CONT TestCacheConfigHandler/no_signing_keys2099=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2100=== CONT TestCacheConfigHandler/no_cache_url_configured2101--- PASS: TestCacheConfigHandler (0.01s)2102 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)2103 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)2104 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)2105 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)2106=== CONT TestProxyWriteTimeout/narinfo2107=== CONT TestProxyWriteTimeout/10_GiB_nar2108=== CONT TestProxyWriteTimeout/1_GiB_nar2109=== CONT TestProxyWriteTimeout/unknown_size2110--- PASS: TestProxyWriteTimeout (0.00s)2111 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)2112 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)2113 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)2114 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)2115=== CONT TestService_RequireScope_OIDC/builder_may_write2116=== CONT TestService_RequireScope_OIDC/reader_may_read2117=== CONT TestService_RequireScope_OIDC/static_token_may_write2118=== CONT TestService_RequireScope_OIDC/static_token_may_admin2119=== CONT TestService_RequireScope_OIDC/writer_implies_read2120=== CONT TestService_RequireScope_OIDC/reader_may_not_write2121=== CONT TestService_RequireScope_OIDC/ops_may_not_write2122=== CONT TestService_RequireScope_OIDC/ops_may_admin2123=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2124=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc2125=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read2126=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read21272026/11/09 11:53:49 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]2128=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc2129=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2130=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2131=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected21322026/11/09 11:53:49 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]2133=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2134=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2135--- PASS: TestService_RequireScope_OIDC (8.02s)2136 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2137 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2138 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2139 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2140 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2141 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2142 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2143 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2144 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2145 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)2146 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)2147 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)2148 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)2149 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)21502026/11/09 11:53:49 WARN Authentication failed token_preview=eyJhbGciOi...9lD0cLIowA token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2151--- PASS: TestService_AuthMiddleware_OIDC (5.96s)2152 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2153 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2154 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2155 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.01s)21562026/11/09 11:53:49 WARN Request failed, retrying attempt=2 backoff=193.277166ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present21572026/11/09 11:53:49 WARN Request failed, retrying attempt=3 backoff=436.198605ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2158--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (6.10s)21592026/11/09 11:53:50 WARN Request failed, retrying attempt=4 backoff=725.965181ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present21602026/11/09 11:53:50 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"2161--- PASS: TestService_AuthMiddleware (6.09s)2162--- PASS: TestService_Rustfstest (5.83s)21632026/11/09 11:53:51 WARN Request failed, retrying attempt=5 backoff=1.525155886s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present21642026/11/09 11:53:51 INFO Received uploads request method=POST path=/api/pending_closures21652026-11-09 11:53:51.445 UTC [24056] LOG: checkpoint starting: wal21662026/11/09 11:53:51 INFO Received uploads request method=POST path=/api/pending_closures21672026/11/09 11:53:51 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21682026/11/09 11:53:51 INFO Received uploads request method=POST path=/api/pending_closures21692026/11/09 11:53:52 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21702026/11/09 11:53:52 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=OTgzNTgyZmUtODRjZC00ZDk3LWE4YmYtYjIyNDA0N2QwZTM0LjVjZDI2OGVlLTg2NTktNDNmOS05NTg4LWRkNDQ2NzY1OGE4MXgxNzk0MjI1MjMxNjI1MDE4MDAw21712026/11/09 11:53:52 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=OTgzNTgyZmUtODRjZC00ZDk3LWE4YmYtYjIyNDA0N2QwZTM0LjVjZDI2OGVlLTg2NTktNDNmOS05NTg4LWRkNDQ2NzY1OGE4MXgxNzk0MjI1MjMxNjI1MDE4MDAw parts=12172--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (7.05s)21732026/11/09 11:53:52 INFO Received uploads request method=POST path=/api/pending_closures21742026/11/09 11:53:52 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst21752026/11/09 11:53:52 INFO Received uploads request method=POST path=/api/pending_closures2176--- PASS: TestPresignedUploadRegisteredBeforeCommit (7.35s)21772026/11/09 11:53:52 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-config21782026/11/09 11:53:52 INFO Received uploads request method=POST path=/api/pending_closures21792026/11/09 11:53:52 WARN Request failed, retrying attempt=2 backoff=202.905979ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21802026/11/09 11:53:52 INFO Received uploads request method=POST path=/api/pending_closures21812026/11/09 11:53:53 WARN Request failed, retrying attempt=3 backoff=402.524186ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21822026/11/09 11:53:53 INFO Received push request method=POST path=/api/pushes21832026/11/09 11:53:53 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign21842026/11/09 11:53:53 INFO Signed narinfos id=1 count=121852026/11/09 11:53:53 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign21862026/11/09 11:53:53 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign21872026/11/09 11:53:53 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"21882026/11/09 11:53:53 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign21892026/11/09 11:53:53 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"21902026/11/09 11:53:53 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign21912026/11/09 11:53:53 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=121922026/11/09 11:53:53 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign21932026/11/09 11:53:53 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo2194--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (7.15s)21952026/11/09 11:53:53 WARN Request failed, retrying attempt=4 backoff=825.575872ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21962026/11/09 11:53:54 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21972026/11/09 11:53:54 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=OTgzNTgyZmUtODRjZC00ZDk3LWE4YmYtYjIyNDA0N2QwZTM0LmRlYzA5OWRjLTNiNTItNGU1OS1hZDIyLWQ2NjE2ZGI0M2FiOHgxNzk0MjI1MjMyMDMwNTIzMDAw parts=1221982026/11/09 11:53:54 INFO Received uploads request method=POST path=/api/pending_closures2199--- PASS: TestCompletedNarNotReofferedAcrossClosures (8.90s)22002026/11/09 11:53:54 INFO Received uploads request method=POST path=/api/pending_closures22012026/11/09 11:53:54 WARN Request failed, retrying attempt=5 backoff=1.673724699s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22022026/11/09 11:53:54 INFO Aborted multipart uploads count=0 kept=022032026/11/09 11:53:54 WARN Force mode enabled - objects will be deleted immediately without grace period2204--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2205 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (7.24s)2206 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (6.63s)22072026/11/09 11:53:54 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=022082026/11/09 11:53:54 INFO Vacuumed table table=pending_closures22092026/11/09 11:53:54 INFO Vacuumed table table=pending_objects22102026/11/09 11:53:54 INFO Vacuumed table table=multipart_uploads22112026/11/09 11:53:54 INFO Vacuumed table table=closures22122026/11/09 11:53:54 INFO Vacuumed table table=objects22132026/11/09 11:53:54 INFO Received uploads request method=POST path=/api/pending_closures22142026/11/09 11:53:54 INFO Aborted multipart uploads count=0 kept=022152026/11/09 11:53:54 WARN Force mode enabled - objects will be deleted immediately without grace period22162026/11/09 11:53:54 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=022172026/11/09 11:53:54 INFO Vacuumed table table=pending_closures22182026/11/09 11:53:54 INFO Vacuumed table table=pending_objects22192026/11/09 11:53:54 INFO Vacuumed table table=multipart_uploads22202026/11/09 11:53:54 INFO Vacuumed table table=closures22212026/11/09 11:53:54 INFO Vacuumed table table=objects22222026/11/09 11:53:54 INFO Received complete multipart upload request method=POST path=/api/multipart/complete2223--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2224 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (6.98s)2225 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (6.99s)22262026/11/09 11:53:54 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=OTgzNTgyZmUtODRjZC00ZDk3LWE4YmYtYjIyNDA0N2QwZTM0Ljc0NzMyNjY1LTFkN2MtNDE2Ny05OGMyLTgyZTgzM2UzMTZhY3gxNzk0MjI1MjMyNzcwOTQ2MDAw parts=1222272026/11/09 11:53:54 INFO Received uploads request method=POST path=/api/pending_closures22282026/11/09 11:53:55 INFO Received uploads request method=POST path=/api/pending_closures22292026/11/09 11:53:55 INFO Received uploads request method=POST path=/api/pending_closures2230--- PASS: TestPendingClosureWriteTimeout (0.00s)2231 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2232 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2233 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2234 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (7.70s)22352026/11/09 11:53:55 WARN Rate limiter enabled after throttle name=s3-test rate=522362026/11/09 11:53:55 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."2237=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle2238 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=102239 throttle_test.go:215: Rate limiter: enabled=true, rate=5.002240--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (10.89s)22412026/11/09 11:53:55 INFO Received uploads request method=POST path=/api/pending_closures22422026/11/09 11:53:55 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"22432026/11/09 11:53:55 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-config22442026/11/09 11:53:56 WARN Request failed, retrying attempt=2 backoff=213.614736ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22452026/11/09 11:53:56 WARN Request failed, retrying attempt=3 backoff=428.463392ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22462026/11/09 11:53:56 INFO Received uploads request method=POST path=/api/pending_closures22472026/11/09 11:53:56 INFO Received uploads request method=POST path=/api/pending_closures22482026/11/09 11:53:56 WARN Request failed, retrying attempt=4 backoff=836.310817ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22492026/11/09 11:53:56 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22502026/11/09 11:53:57 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=OTgzNTgyZmUtODRjZC00ZDk3LWE4YmYtYjIyNDA0N2QwZTM0LmRlYjZhM2NjLTM3ODQtNGZlNy05ZjBiLWNjNDNmMjJlODQ1NHgxNzk0MjI1MjMyODIxMzc3MDAw parts=122251--- PASS: TestSharedNarBothUploadsComplete (11.55s)22522026/11/09 11:53:57 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22532026/11/09 11:53:57 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000400000000000000000000.nar.zst upload_id=OTgzNTgyZmUtODRjZC00ZDk3LWE4YmYtYjIyNDA0N2QwZTM0Ljc0NTFhNjYyLTYwOTAtNGMyYS1iYWFlLTVkMjU2OWEzZTVmNXgxNzk0MjI1MjM1MTgxMDcxMDAw parts=1022542026/11/09 11:53:57 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22552026/11/09 11:53:57 INFO Completed upload id=1 objects=3 duration=16.183458ms22562026/11/09 11:53:57 INFO Received uploads request method=POST path=/api/pending_closures22572026/11/09 11:53:57 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22582026/11/09 11:53:57 WARN Request failed, retrying attempt=5 backoff=1.736813251s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22592026/11/09 11:53:57 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000100000000000000000000.nar.zst upload_id=OTgzNTgyZmUtODRjZC00ZDk3LWE4YmYtYjIyNDA0N2QwZTM0LjExZWY4MjlhLWQ5MmQtNDZkMS1iZmE3LTk5OGZkZjg4NjY5YXgxNzk0MjI1MjM1NTQ5OTc3MDAw parts=1022602026/11/09 11:53:57 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22612026/11/09 11:53:57 INFO Completed upload id=1 objects=3 duration=12.655ms22622026/11/09 11:53:57 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22632026/11/09 11:53:57 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"22642026/11/09 11:53:57 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"22652026/11/09 11:53:57 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000200000000000000000000.nar.zst upload_id=OTgzNTgyZmUtODRjZC00ZDk3LWE4YmYtYjIyNDA0N2QwZTM0LjlhMjc3MmM0LWE3YWEtNDZhNC1hOWUxLTFlZjJkNzhlNWFmM3gxNzk0MjI1MjM1OTU0NjY3MDAw parts=1022662026/11/09 11:53:58 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22672026/11/09 11:53:58 INFO Received uploads request method=POST path=/api/pending_closures22682026/11/09 11:53:58 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000100000000000000000000.nar.zst22692026/11/09 11:53:58 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0001.narinfo22702026/11/09 11:53:58 INFO Completed upload id=1 objects=3 duration=10.237166ms22712026/11/09 11:53:58 INFO Received uploads request method=POST path=/api/pending_closures22722026/11/09 11:53:58 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22732026/11/09 11:53:58 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000500000000000000000000.nar.zst upload_id=OTgzNTgyZmUtODRjZC00ZDk3LWE4YmYtYjIyNDA0N2QwZTM0LjQ2Mjc0N2E4LTA1NmYtNDg4ZS04NzE5LWM2NjY1ZDY0ZWNjYXgxNzk0MjI1MjM2MzA5OTk3MDAw parts=1022742026/11/09 11:53:58 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22752026/11/09 11:53:58 INFO Completed upload id=1 objects=3 duration=6.118333ms22762026/11/09 11:53:58 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22772026/11/09 11:53:58 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000300000000000000000000.nar.zst upload_id=OTgzNTgyZmUtODRjZC00ZDk3LWE4YmYtYjIyNDA0N2QwZTM0LjZlODhiYmI3LWIyZTktNGE0Zi1hMGQ4LWVlODc1ZDhhM2E1YngxNzk0MjI1MjM2Njg0Mzc0MDAw parts=1022782026/11/09 11:53:58 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22792026/11/09 11:53:58 INFO Completed upload id=1 objects=3 duration=13.510167ms22802026/11/09 11:53:58 INFO Received uploads request method=POST path=/api/pending_closures22812026/11/09 11:53:58 INFO Received uploads request method=POST path=/api/pending_closures22822026/11/09 11:53:58 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000500000000000000000000.nar.zst22832026/11/09 11:53:58 WARN Found objects in DB but missing from S3, will re-upload count=122842026/11/09 11:53:58 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22852026/11/09 11:53:58 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f100400000000000000000000.nar.zst upload_id=OTgzNTgyZmUtODRjZC00ZDk3LWE4YmYtYjIyNDA0N2QwZTM0LjAyOTU3ZTNiLTIwN2QtNGI4Yi1hMmYwLTI4MmU4MzNmY2RlZXgxNzk0MjI1MjM3MjgwOTgxMDAw parts=1022862026/11/09 11:53:58 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete22872026/11/09 11:53:58 INFO Completed upload id=2 objects=3 duration=1.239875ms22882026/11/09 11:53:59 INFO Received uploads request method=POST path=/api/pending_closures22892026/11/09 11:53:59 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000400000000000000000000.nar.zst22902026/11/09 11:53:59 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0004.narinfo22912026/11/09 11:53:59 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_closures22922026/11/09 11:53:59 WARN Request failed, retrying attempt=2 backoff=199.035661ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22932026/11/09 11:53:59 WARN Request failed, retrying attempt=3 backoff=424.921853ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22942026/11/09 11:53:59 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22952026/11/09 11:53:59 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f100300000000000000000000.nar.zst upload_id=OTgzNTgyZmUtODRjZC00ZDk3LWE4YmYtYjIyNDA0N2QwZTM0Ljk2YWNkNzMzLTQxNjgtNGVmOC1iOWUzLWQ4NTExODU3NzVkYXgxNzk0MjI1MjM4NjI4Nzg0MDAw parts=1022962026/11/09 11:53:59 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete22972026/11/09 11:53:59 INFO Completed upload id=2 objects=3 duration=1.08525ms22982026/11/09 11:53:59 INFO Received uploads request method=POST path=/api/pending_closures22992026/11/09 11:53:59 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000300000000000000000000.nar.zst23002026/11/09 11:53:59 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0003.narinfo2301--- PASS: TestService_verifyS3ReuploadsStaleNarinfo (0.00s)2302 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed (9.73s)2303 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed (9.46s)2304 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed (10.15s)2305 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed (10.83s)2306 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost (11.39s)23072026/11/09 11:54:00 WARN Request failed, retrying attempt=4 backoff=759.335467ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures23082026/11/09 11:54:00 WARN Request failed, retrying attempt=5 backoff=1.547051042s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2309--- PASS: TestClientErrorHandling (0.01s)2310 --- PASS: TestClientErrorHandling/InvalidStorePath (7.95s)2311 --- PASS: TestClientErrorHandling/InvalidAuthToken (8.54s)2312 --- PASS: TestClientErrorHandling/ServerNotAvailable (13.27s)2313=== NAME TestOrphanedObjectsGCStressTest2314 orphaned_objects_gc_test.go:503: Stress test completed successfully:2315 orphaned_objects_gc_test.go:504: - Active objects preserved: 202316 orphaned_objects_gc_test.go:505: - Objects deleted: 2102317 orphaned_objects_gc_test.go:506: - Total GC'd: 2102318--- PASS: TestOrphanedObjectsGCStressTest (35.02s)2319PASS2320{"timestamp":"2026-11-09T11:54:05.623856Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:65348","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(5)"}2321{"timestamp":"2026-11-09T11:54:05.621951Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:65351","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(2)"}2322{"timestamp":"2026-11-09T11:54:05.625513Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:65346","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(11)"}2323{"timestamp":"2026-11-09T11:54:05.623988Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:65225","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(10)"}2324{"timestamp":"2026-11-09T11:54:05.63135Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:65089","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(2)"}23252026-11-09 11:54:05.738 UTC [24051] LOG: received smart shutdown request23262026-11-09 11:54:05.739 UTC [24051] LOG: background worker "logical replication launcher" (PID 24061) exited with exit code 123272026-11-09 11:54:07.419 UTC [24056] LOG: checkpoint complete: wrote 11783 buffers (71.9%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 33 recycled; write=15.068 s, sync=0.712 s, total=15.975 s; sync files=36397, longest=0.001 s, average=0.001 s; distance=532946 kB, estimate=532946 kB; lsn=0/223D2E38, redo lsn=0/2200197023282026-11-09 11:54:07.420 UTC [24056] LOG: shutting down23292026-11-09 11:54:07.420 UTC [24056] LOG: checkpoint starting: shutdown immediate23302026-11-09 11:54:07.447 UTC [24056] LOG: checkpoint complete: wrote 459 buffers (2.8%), wrote 1 SLRU buffers; 0 WAL file(s) added, 0 removed, 0 recycled; write=0.019 s, sync=0.008 s, total=0.028 s; sync files=295, longest=0.001 s, average=0.001 s; distance=3909 kB, estimate=480042 kB; lsn=0/223D2EB0, redo lsn=0/223D2EB023312026-11-09 11:54:07.462 UTC [24051] LOG: database system is shut down2332Running OIDC tests...2333=== RUN TestAudienceForIssuer2334=== PAUSE TestAudienceForIssuer2335=== RUN TestGlobMatch2336=== PAUSE TestGlobMatch2337=== RUN TestValidateToken_ValidToken2338=== PAUSE TestValidateToken_ValidToken2339=== RUN TestValidateToken_WrongAudience2340=== PAUSE TestValidateToken_WrongAudience2341=== RUN TestValidateToken_Expired2342=== PAUSE TestValidateToken_Expired2343=== RUN TestValidateToken_BoundClaimsMismatch2344=== PAUSE TestValidateToken_BoundClaimsMismatch2345=== RUN TestValidateToken_BoundSubjectMismatch2346=== PAUSE TestValidateToken_BoundSubjectMismatch2347=== RUN TestValidateToken_MultipleProviders2348=== PAUSE TestValidateToken_MultipleProviders2349=== RUN TestValidateToken_NoMatchingProvider2350=== PAUSE TestValidateToken_NoMatchingProvider2351=== RUN TestValidateToken_KubernetesServiceAccount2352=== PAUSE TestValidateToken_KubernetesServiceAccount2353=== RUN TestNewValidator_KubernetesRequiresCA2354=== PAUSE TestNewValidator_KubernetesRequiresCA2355=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2356=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2357=== RUN TestPins_ReservedForMatchingRule2358=== PAUSE TestPins_ReservedForMatchingRule2359=== RUN TestPins_TopLevelShorthand2360=== PAUSE TestPins_TopLevelShorthand2361=== RUN TestPins_ConfigValidation2362=== PAUSE TestPins_ConfigValidation2363=== RUN TestScopes_LegacyProviderDefaultsToWrite2364=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2365=== RUN TestScopes_Rules2366=== PAUSE TestScopes_Rules2367=== RUN TestScopes_ConfigValidation2368=== PAUSE TestScopes_ConfigValidation2369=== CONT TestAudienceForIssuer2370--- PASS: TestAudienceForIssuer (0.00s)2371=== CONT TestValidateToken_Expired2372=== CONT TestValidateToken_BoundClaimsMismatch2373=== CONT TestValidateToken_KubernetesServiceAccount2374=== CONT TestPins_ConfigValidation2375=== CONT TestPins_ReservedForMatchingRule2376=== CONT TestValidateToken_ValidToken2377=== CONT TestValidateToken_WrongAudience2378=== CONT TestScopes_Rules2379--- PASS: TestPins_ConfigValidation (0.01s)2380=== CONT TestPins_TopLevelShorthand2381=== CONT TestValidateToken_MultipleProviders2382=== CONT TestValidateToken_NoMatchingProvider2383=== CONT TestValidateToken_BoundSubjectMismatch2384=== CONT TestGlobMatch2385=== RUN TestGlobMatch/foo_foo2386=== PAUSE TestGlobMatch/foo_foo2387=== RUN TestGlobMatch/foo_bar2388=== PAUSE TestGlobMatch/foo_bar2389=== RUN TestGlobMatch/*_2390=== PAUSE TestGlobMatch/*_2391=== RUN TestGlobMatch/*_anything2392=== PAUSE TestGlobMatch/*_anything2393=== RUN TestGlobMatch/foo*_foo2394=== PAUSE TestGlobMatch/foo*_foo2395=== RUN TestGlobMatch/foo*_foobar2396=== PAUSE TestGlobMatch/foo*_foobar2397=== RUN TestGlobMatch/foo*_bar2398=== PAUSE TestGlobMatch/foo*_bar2399=== RUN TestGlobMatch/*bar_bar2400=== PAUSE TestGlobMatch/*bar_bar2401=== RUN TestGlobMatch/*bar_foobar2402=== PAUSE TestGlobMatch/*bar_foobar2403=== RUN TestGlobMatch/*bar_foo2404=== PAUSE TestGlobMatch/*bar_foo2405=== RUN TestGlobMatch/foo*bar_foobar2406=== PAUSE TestGlobMatch/foo*bar_foobar2407=== RUN TestGlobMatch/foo*bar_foo123bar2408=== PAUSE TestGlobMatch/foo*bar_foo123bar2409=== RUN TestGlobMatch/foo*bar_foobarbaz2410=== PAUSE TestGlobMatch/foo*bar_foobarbaz2411=== RUN TestGlobMatch/*/*_foo/bar2412=== PAUSE TestGlobMatch/*/*_foo/bar2413=== RUN TestGlobMatch/*/*_foo2414=== PAUSE TestGlobMatch/*/*_foo2415=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2416=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2417=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02418=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02419=== RUN TestGlobMatch/refs/*/main_refs/heads/main2420=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2421=== RUN TestGlobMatch/fo?_foo2422=== PAUSE TestGlobMatch/fo?_foo2423=== RUN TestGlobMatch/fo?_fo2424=== PAUSE TestGlobMatch/fo?_fo2425=== RUN TestGlobMatch/fo?_fooo2426=== PAUSE TestGlobMatch/fo?_fooo2427=== RUN TestGlobMatch/?oo_foo2428=== PAUSE TestGlobMatch/?oo_foo2429=== RUN TestGlobMatch/?oo_boo2430=== PAUSE TestGlobMatch/?oo_boo2431=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2432=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2433=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2434=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2435=== CONT TestGlobMatch/foo_foo2436=== CONT TestScopes_LegacyProviderDefaultsToWrite2437=== CONT TestGlobMatch/*/*_foo/bar2438=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2439=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2440=== CONT TestGlobMatch/?oo_boo2441=== CONT TestGlobMatch/?oo_foo2442=== CONT TestGlobMatch/fo?_fooo2443=== CONT TestGlobMatch/fo?_fo2444=== CONT TestGlobMatch/fo?_foo2445=== CONT TestGlobMatch/refs/*/main_refs/heads/main2446=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02447=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2448=== CONT TestGlobMatch/*/*_foo2449=== CONT TestGlobMatch/*bar_bar2450=== CONT TestGlobMatch/foo*bar_foobarbaz2451=== CONT TestGlobMatch/foo*bar_foo123bar2452=== CONT TestGlobMatch/foo*bar_foobar2453=== CONT TestGlobMatch/*bar_foo2454=== CONT TestGlobMatch/*bar_foobar2455=== CONT TestGlobMatch/foo*_foo2456=== CONT TestGlobMatch/foo*_bar2457=== CONT TestGlobMatch/foo*_foobar2458=== CONT TestGlobMatch/*_2459=== CONT TestGlobMatch/*_anything2460=== CONT TestGlobMatch/foo_bar2461--- PASS: TestGlobMatch (0.00s)2462 --- PASS: TestGlobMatch/foo_foo (0.00s)2463 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2464 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2465 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2466 --- PASS: TestGlobMatch/?oo_boo (0.00s)2467 --- PASS: TestGlobMatch/?oo_foo (0.00s)2468 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2469 --- PASS: TestGlobMatch/fo?_fo (0.00s)2470 --- PASS: TestGlobMatch/fo?_foo (0.00s)2471 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2472 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2473 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2474 --- PASS: TestGlobMatch/*/*_foo (0.00s)2475 --- PASS: TestGlobMatch/*bar_bar (0.00s)2476 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2477 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2478 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2479 --- PASS: TestGlobMatch/*bar_foo (0.00s)2480 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2481 --- PASS: TestGlobMatch/foo*_foo (0.00s)2482 --- PASS: TestGlobMatch/foo*_bar (0.00s)2483 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2484 --- PASS: TestGlobMatch/*_ (0.00s)2485 --- PASS: TestGlobMatch/*_anything (0.00s)2486 --- PASS: TestGlobMatch/foo_bar (0.00s)2487=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2488=== CONT TestScopes_ConfigValidation2489--- PASS: TestScopes_ConfigValidation (0.00s)2490=== CONT TestNewValidator_KubernetesRequiresCA24912026/11/09 11:54:09 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:6537324922026/11/09 11:54:09 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC12324932026/11/09 11:54:09 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:65378/oidc24942026/11/09 11:54:09 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:65376/oidc24952026/11/09 11:54:09 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:65381/oidc24962026/11/09 11:54:09 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:65384/oidc2497--- PASS: TestValidateToken_Expired (0.07s)2498--- PASS: TestValidateToken_BoundClaimsMismatch (0.07s)2499--- PASS: TestValidateToken_WrongAudience (0.07s)25002026/11/09 11:54:09 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:65386/oidc2501--- PASS: TestValidateToken_KubernetesServiceAccount (0.07s)2502--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.05s)25032026/11/09 11:54:09 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:65388/oidc2504--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.05s)2505--- PASS: TestPins_TopLevelShorthand (0.07s)2506--- PASS: TestPins_ReservedForMatchingRule (0.08s)25072026/11/09 11:54:09 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:65392/oidc25082026/11/09 11:54:09 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:65394/oidc2509--- PASS: TestScopes_Rules (0.09s)2510--- PASS: TestValidateToken_ValidToken (0.09s)25112026/11/09 11:54:09 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:65396/oidc2512--- PASS: TestValidateToken_BoundSubjectMismatch (0.08s)25132026/11/09 11:54:09 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:65398/oidc2514--- PASS: TestValidateToken_NoMatchingProvider (0.13s)25152026/11/09 11:54:09 http: TLS handshake error from 127.0.0.1:65402: read tcp 127.0.0.1:65401->127.0.0.1:65402: use of closed network connection2516--- PASS: TestNewValidator_KubernetesRequiresCA (0.12s)25172026/11/09 11:54:09 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:65374/oidc25182026/11/09 11:54:09 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:65403/oidc2519--- PASS: TestValidateToken_MultipleProviders (0.15s)2520PASS2521Running hook tests...2522=== RUN TestSendPathsEmpty2523=== PAUSE TestSendPathsEmpty2524=== RUN TestQueueEnqueueAndFetch2525=== PAUSE TestQueueEnqueueAndFetch2526=== RUN TestQueueDeduplication2527=== PAUSE TestQueueDeduplication2528=== RUN TestQueueRemove2529=== PAUSE TestQueueRemove2530=== RUN TestQueueFetchBatchLimit2531=== PAUSE TestQueueFetchBatchLimit2532=== RUN TestQueueRetryMovesToBack2533=== PAUSE TestQueueRetryMovesToBack2534=== RUN TestQueueFetchRemoveLifecycle2535=== PAUSE TestQueueFetchRemoveLifecycle2536=== RUN TestQueueConcurrentWriters2537=== PAUSE TestQueueConcurrentWriters2538=== RUN TestQueueRemoveLargeClosure2539=== PAUSE TestQueueRemoveLargeClosure2540=== RUN TestServerClientIntegration2541--- PASS: TestServerClientIntegration (0.00s)2542=== RUN TestServerQueueError25432026/11/09 11:54:09 ERROR Failed to queue paths error="permission denied" count=12544--- PASS: TestServerQueueError (0.00s)2545=== RUN TestGetListenerSocketActivation2546 server_test.go:145: systemd socket activation does not exist on darwin2547--- SKIP: TestGetListenerSocketActivation (0.00s)2548=== RUN TestServerStalledClientDoesNotBlockShutdown2549=== PAUSE TestServerStalledClientDoesNotBlockShutdown2550=== RUN TestServerBacksOffOnAcceptErrors2551=== PAUSE TestServerBacksOffOnAcceptErrors2552=== RUN TestDrainIsolatesPoisonPath2553=== PAUSE TestDrainIsolatesPoisonPath2554=== RUN TestRunNotBlockedByPoisonHead2555=== PAUSE TestRunNotBlockedByPoisonHead2556=== RUN TestDrainGivesUpWhenServerDown2557=== PAUSE TestDrainGivesUpWhenServerDown2558=== RUN TestFailedPathPrunedByLaterClosure2559=== PAUSE TestFailedPathPrunedByLaterClosure2560=== RUN TestWorkerUploadsAndRemoves2561=== PAUSE TestWorkerUploadsAndRemoves2562=== RUN TestWorkerSkipsGCdPaths2563=== PAUSE TestWorkerSkipsGCdPaths2564=== RUN TestWorkerPrunesClosureDeps2565=== PAUSE TestWorkerPrunesClosureDeps2566=== RUN TestDrainTimeout2567=== PAUSE TestDrainTimeout2568=== RUN TestWorkerRemoveFailureIsNotProgress2569=== PAUSE TestWorkerRemoveFailureIsNotProgress2570=== RUN TestWorkerKeepsPathItCannotStat2571=== PAUSE TestWorkerKeepsPathItCannotStat2572=== CONT TestSendPathsEmpty2573=== CONT TestDrainGivesUpWhenServerDown2574--- PASS: TestSendPathsEmpty (0.00s)2575=== CONT TestWorkerKeepsPathItCannotStat2576=== CONT TestWorkerRemoveFailureIsNotProgress2577=== CONT TestDrainTimeout2578=== CONT TestServerStalledClientDoesNotBlockShutdown2579=== CONT TestWorkerSkipsGCdPaths2580=== CONT TestWorkerUploadsAndRemoves2581=== CONT TestFailedPathPrunedByLaterClosure2582=== CONT TestWorkerPrunesClosureDeps2583=== CONT TestQueueFetchBatchLimit2584=== CONT TestQueueRemove2585=== CONT TestQueueRetryMovesToBack2586=== CONT TestQueueDeduplication2587=== CONT TestQueueEnqueueAndFetch2588=== CONT TestQueueRemoveLargeClosure2589=== CONT TestQueueConcurrentWriters2590=== CONT TestDrainIsolatesPoisonPath2591=== CONT TestQueueFetchRemoveLifecycle2592=== CONT TestRunNotBlockedByPoisonHead2593=== CONT TestServerBacksOffOnAcceptErrors25942026/11/09 11:54:09 ERROR Accept failed error="too many open files"25952026/11/09 11:54:09 INFO Upload queue status pending=225962026/11/09 11:54:09 INFO Uploading batch count=125972026/11/09 11:54:09 ERROR Accept failed error="too many open files"25982026/11/09 11:54:09 WARN Cannot stat store path, will retry later path=/private/var/tb/8/scratch/b4189290b5638e57/build/TestWorkerKeepsPathItCannotStat3329971368/002/locked/aaa error="stat /private/var/tb/8/scratch/b4189290b5638e57/build/TestWorkerKeepsPathItCannotStat3329971368/002/locked/aaa: permission denied"25992026/11/09 11:54:09 INFO Upload queue status pending=226002026/11/09 11:54:09 WARN Cannot stat store path, will retry later path=/private/var/tb/8/scratch/b4189290b5638e57/build/TestWorkerKeepsPathItCannotStat3329971368/002/locked/aaa error="stat /private/var/tb/8/scratch/b4189290b5638e57/build/TestWorkerKeepsPathItCannotStat3329971368/002/locked/aaa: permission denied"26012026/11/09 11:54:09 INFO Uploading batch count=226022026/11/09 11:54:09 WARN Cannot stat store path, will retry later path=/private/var/tb/8/scratch/b4189290b5638e57/build/TestWorkerKeepsPathItCannotStat3329971368/002/locked/aaa error="stat /private/var/tb/8/scratch/b4189290b5638e57/build/TestWorkerKeepsPathItCannotStat3329971368/002/locked/aaa: permission denied"26032026/11/09 11:54:09 INFO Uploading batch count=126042026/11/09 11:54:09 ERROR Upload failed error="upload failed" count=126052026/11/09 11:54:09 INFO Uploading batch count=126062026/11/09 11:54:09 INFO Upload queue status pending=326072026/11/09 11:54:09 INFO Uploading batch count=126082026/11/09 11:54:09 ERROR Upload failed error="upload failed" count=126092026/11/09 11:54:09 ERROR Drain finished with paths left in queue remaining=126102026/11/09 11:54:09 INFO Upload queue status pending=226112026/11/09 11:54:09 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/8/scratch/b4189290b5638e57/build/TestWorkerSkipsGCdPaths256998860/002/nonexistent2612--- PASS: TestQueueEnqueueAndFetch (0.01s)26132026/11/09 11:54:09 INFO Uploading batch count=226142026/11/09 11:54:09 ERROR Upload failed error="upload failed" count=226152026/11/09 11:54:09 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/8/scratch/b4189290b5638e57/build/TestDrainGivesUpWhenServerDown3491637593/002/a26162026/11/09 11:54:09 INFO Uploading batch count=426172026/11/09 11:54:09 ERROR Upload failed error="upload failed" count=42618--- PASS: TestQueueDeduplication (0.01s)26192026/11/09 11:54:09 INFO Uploading batch count=12620--- PASS: TestQueueRetryMovesToBack (0.02s)2621--- PASS: TestQueueRemove (0.02s)26222026/11/09 11:54:09 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/8/scratch/b4189290b5638e57/build/TestDrainGivesUpWhenServerDown3491637593/002/b26232026/11/09 11:54:09 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/8/scratch/b4189290b5638e57/build/TestDrainIsolatesPoisonPath3636484612/002/bbb26242026/11/09 11:54:09 INFO Uploading batch count=126252026/11/09 11:54:09 INFO Uploading batch count=226262026/11/09 11:54:09 ERROR Upload failed error="upload failed" count=226272026/11/09 11:54:09 INFO Uploading batch count=226282026/11/09 11:54:09 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/8/scratch/b4189290b5638e57/build/TestDrainGivesUpWhenServerDown3491637593/002/c2629--- PASS: TestWorkerKeepsPathItCannotStat (0.02s)26302026/11/09 11:54:09 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/8/scratch/b4189290b5638e57/build/TestDrainGivesUpWhenServerDown3491637593/002/d2631--- PASS: TestQueueFetchRemoveLifecycle (0.01s)26322026/11/09 11:54:09 INFO Uploading batch count=226332026/11/09 11:54:09 ERROR Upload failed error="upload failed" count=226342026/11/09 11:54:09 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/8/scratch/b4189290b5638e57/build/TestDrainGivesUpWhenServerDown3491637593/002/e2635--- PASS: TestQueueFetchBatchLimit (0.02s)26362026/11/09 11:54:09 INFO Uploading batch count=126372026/11/09 11:54:09 ERROR Upload failed error="upload failed" count=126382026/11/09 11:54:09 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/8/scratch/b4189290b5638e57/build/TestWorkerRemoveFailureIsNotProgress2138384806/002/nonexistent26392026/11/09 11:54:09 INFO Uploading batch count=126402026/11/09 11:54:09 ERROR Upload failed error="upload failed" count=126412026/11/09 11:54:09 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=126422026/11/09 11:54:09 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/8/scratch/b4189290b5638e57/build/TestWorkerRemoveFailureIsNotProgress2138384806/002/nonexistent26432026/11/09 11:54:09 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/8/scratch/b4189290b5638e57/build/TestDrainGivesUpWhenServerDown3491637593/002/f26442026/11/09 11:54:09 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=126452026/11/09 11:54:09 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/8/scratch/b4189290b5638e57/build/TestWorkerRemoveFailureIsNotProgress2138384806/002/nonexistent26462026/11/09 11:54:09 INFO Uploading batch count=126472026/11/09 11:54:09 ERROR Upload failed error="upload failed" count=126482026/11/09 11:54:09 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=126492026/11/09 11:54:09 ERROR Drain finished with paths left in queue remaining=1026502026/11/09 11:54:09 ERROR Drain finished with paths left in queue remaining=126512026/11/09 11:54:09 ERROR Drain finished with paths left in queue remaining=12652--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)2653--- PASS: TestWorkerRemoveFailureIsNotProgress (0.02s)2654--- PASS: TestDrainIsolatesPoisonPath (0.01s)2655--- PASS: TestDrainGivesUpWhenServerDown (0.02s)26562026/11/09 11:54:09 ERROR Accept failed error="too many open files"26572026/11/09 11:54:09 ERROR Accept failed error="too many open files"2658--- PASS: TestWorkerSkipsGCdPaths (0.07s)2659--- PASS: TestWorkerPrunesClosureDeps (0.07s)2660--- PASS: TestWorkerUploadsAndRemoves (0.07s)2661--- PASS: TestQueueRemoveLargeClosure (0.09s)26622026/11/09 11:54:09 ERROR Accept failed error="too many open files"2663--- PASS: TestQueueConcurrentWriters (0.11s)26642026/11/09 11:54:09 ERROR Accept failed error="too many open files"26652026/11/09 11:54:09 ERROR Failed to decode request error="read unix /private/var/tb/8/scratch/b4189290b5638e57/build/hook1955762892/test.sock->: i/o timeout"26662026/11/09 11:54:09 ERROR Failed to write response error="write unix /private/var/tb/8/scratch/b4189290b5638e57/build/hook1955762892/test.sock->: i/o timeout"2667--- PASS: TestServerStalledClientDoesNotBlockShutdown (0.20s)26682026/11/09 11:54:09 ERROR Upload failed error="context deadline exceeded" count=226692026/11/09 11:54:09 ERROR Drain finished with paths left in queue remaining=42670--- PASS: TestDrainTimeout (0.22s)26712026/11/09 11:54:10 ERROR Accept failed error="too many open files"26722026/11/09 11:54:10 ERROR Accept failed error="too many open files"2673--- PASS: TestServerBacksOffOnAcceptErrors (0.67s)26742026/11/09 11:54:10 INFO Uploading batch count=126752026/11/09 11:54:10 INFO Uploading batch count=126762026/11/09 11:54:10 INFO Uploading batch count=126772026/11/09 11:54:10 ERROR Upload failed error="upload failed" count=126782026/11/09 11:54:10 INFO Uploading batch count=126792026/11/09 11:54:10 ERROR Upload failed error="upload failed" count=126802026/11/09 11:54:10 INFO Uploading batch count=126812026/11/09 11:54:10 ERROR Upload failed error="upload failed" count=126822026/11/09 11:54:10 INFO Uploading batch count=126832026/11/09 11:54:10 ERROR Upload failed error="upload failed" count=126842026/11/09 11:54:10 ERROR Drain finished with paths left in queue remaining=12685--- PASS: TestRunNotBlockedByPoisonHead (1.02s)2686PASS2687Running signing tests...2688=== RUN TestExternalSigner2689=== PAUSE TestExternalSigner2690=== RUN TestExternalSignerWrongPublicKey2691=== PAUSE TestExternalSignerWrongPublicKey2692=== RUN TestExternalSignerErrors2693=== PAUSE TestExternalSignerErrors2694=== RUN TestExternalSignerRestartsAfterCrash2695=== PAUSE TestExternalSignerRestartsAfterCrash2696=== RUN TestExternalSignerProgramErrorKeepsProcess2697=== PAUSE TestExternalSignerProgramErrorKeepsProcess2698=== RUN TestExternalSignerClose2699=== PAUSE TestExternalSignerClose2700=== RUN TestExternalSignerRejectsInvalidPublicKey2701=== PAUSE TestExternalSignerRejectsInvalidPublicKey2702=== RUN TestExternalSignerCancellation2703=== PAUSE TestExternalSignerCancellation2704=== RUN TestGenerateFingerprint2705=== PAUSE TestGenerateFingerprint2706=== RUN TestParseSigningKey2707=== PAUSE TestParseSigningKey2708=== RUN TestSign2709=== PAUSE TestSign2710=== RUN TestSignBatch2711=== PAUSE TestSignBatch2712=== RUN TestNilKeyPublicKey2713=== PAUSE TestNilKeyPublicKey2714=== RUN TestSignErrors2715=== PAUSE TestSignErrors2716=== CONT TestExternalSigner2717=== CONT TestExternalSignerCancellation2718=== CONT TestSignBatch2719=== CONT TestSignErrors2720=== CONT TestParseSigningKey2721=== RUN TestParseSigningKey/valid_32-byte_key2722=== CONT TestExternalSignerWrongPublicKey2723=== PAUSE TestParseSigningKey/valid_32-byte_key2724=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2725=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2726=== RUN TestParseSigningKey/no_colon2727=== PAUSE TestParseSigningKey/no_colon2728=== RUN TestParseSigningKey/empty_name2729=== PAUSE TestParseSigningKey/empty_name2730=== RUN TestParseSigningKey/invalid_base642731=== PAUSE TestParseSigningKey/invalid_base642732=== RUN TestParseSigningKey/wrong_length2733=== CONT TestGenerateFingerprint2734=== RUN TestGenerateFingerprint/basic_with_references2735=== PAUSE TestGenerateFingerprint/basic_with_references2736=== RUN TestGenerateFingerprint/no_references2737=== PAUSE TestGenerateFingerprint/no_references2738=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2739=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2740=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2741=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2742=== RUN TestGenerateFingerprint/invalid_nar_hash_length2743=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2744=== RUN TestGenerateFingerprint/invalid_store_path_prefix2745=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2746=== RUN TestGenerateFingerprint/invalid_reference_prefix2747=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2748=== CONT TestGenerateFingerprint/basic_with_references2749=== PAUSE TestParseSigningKey/wrong_length2750=== CONT TestParseSigningKey/valid_32-byte_key2751=== CONT TestGenerateFingerprint/invalid_reference_prefix2752=== CONT TestGenerateFingerprint/invalid_store_path_prefix2753=== CONT TestGenerateFingerprint/invalid_nar_hash_length2754=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2755=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2756=== CONT TestGenerateFingerprint/no_references2757--- PASS: TestGenerateFingerprint (0.00s)2758 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2759 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2760 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2761 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2762 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2763 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2764 --- PASS: TestGenerateFingerprint/no_references (0.00s)2765=== CONT TestExternalSignerRejectsInvalidPublicKey2766=== RUN TestExternalSignerRejectsInvalidPublicKey/#002767=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002768=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2769=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2770=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2771=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2772=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2773=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2774=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2775=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2776=== CONT TestExternalSignerRejectsInvalidPublicKey/#002777=== CONT TestParseSigningKey/wrong_length2778=== CONT TestParseSigningKey/invalid_base642779=== CONT TestParseSigningKey/empty_name2780=== CONT TestParseSigningKey/no_colon2781=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2782=== CONT TestExternalSignerClose2783=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2784=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2785=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2786=== CONT TestExternalSignerRestartsAfterCrash2787=== CONT TestSign2788=== CONT TestExternalSignerProgramErrorKeepsProcess2789=== CONT TestNilKeyPublicKey2790--- PASS: TestNilKeyPublicKey (0.00s)2791=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2792=== CONT TestExternalSignerErrors2793--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2794 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2795 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2796 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2797 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2798 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2799=== RUN TestExternalSignerErrors/invalid_JSON2800=== PAUSE TestExternalSignerErrors/invalid_JSON2801=== RUN TestExternalSignerErrors/too_few_signatures2802=== PAUSE TestExternalSignerErrors/too_few_signatures2803=== RUN TestExternalSignerErrors/missing_signature_name2804=== PAUSE TestExternalSignerErrors/missing_signature_name2805=== RUN TestExternalSignerErrors/wrong_signature_name2806=== PAUSE TestExternalSignerErrors/wrong_signature_name2807=== RUN TestExternalSignerErrors/wrong_id2808=== PAUSE TestExternalSignerErrors/wrong_id2809=== RUN TestExternalSignerErrors/unrequested_key2810=== PAUSE TestExternalSignerErrors/unrequested_key2811=== RUN TestExternalSignerErrors/invalid_signature_base642812=== PAUSE TestExternalSignerErrors/invalid_signature_base642813=== RUN TestExternalSignerErrors/program_error2814=== PAUSE TestExternalSignerErrors/program_error2815=== RUN TestExternalSignerErrors/exit_at_startup2816=== PAUSE TestExternalSignerErrors/exit_at_startup2817=== RUN TestExternalSignerErrors/exit_on_request2818=== PAUSE TestExternalSignerErrors/exit_on_request2819=== RUN TestExternalSignerErrors/null2820=== PAUSE TestExternalSignerErrors/null2821=== RUN TestExternalSignerErrors/missing_signatures2822=== PAUSE TestExternalSignerErrors/missing_signatures2823=== RUN TestExternalSignerErrors/wrong_signature_length2824=== PAUSE TestExternalSignerErrors/wrong_signature_length2825=== RUN TestExternalSignerErrors/wrong_shape2826=== PAUSE TestExternalSignerErrors/wrong_shape2827=== RUN TestExternalSignerErrors/null_signatures2828=== PAUSE TestExternalSignerErrors/null_signatures2829=== RUN TestExternalSignerErrors/wrong_signatures_shape2830=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2831=== CONT TestExternalSignerErrors/invalid_JSON2832=== CONT TestExternalSignerErrors/exit_at_startup2833=== CONT TestExternalSignerErrors/wrong_signatures_shape2834=== CONT TestExternalSignerErrors/null2835=== CONT TestExternalSignerErrors/wrong_signature_length2836=== CONT TestExternalSignerErrors/exit_on_request2837--- PASS: TestSignBatch (0.00s)2838=== CONT TestExternalSignerErrors/null_signatures2839=== CONT TestExternalSignerErrors/missing_signature_name2840=== CONT TestExternalSignerErrors/too_few_signatures2841=== CONT TestExternalSignerErrors/wrong_shape2842=== RUN TestSignErrors/nil_key2843=== PAUSE TestSignErrors/nil_key2844=== RUN TestSignErrors/nil_narinfo2845=== PAUSE TestSignErrors/nil_narinfo2846=== RUN TestSignErrors/invalid_narinfo2847=== CONT TestExternalSignerErrors/wrong_id2848=== CONT TestExternalSignerErrors/wrong_signature_name2849--- PASS: TestParseSigningKey (0.00s)2850 --- PASS: TestParseSigningKey/wrong_length (0.00s)2851 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2852 --- PASS: TestParseSigningKey/empty_name (0.00s)2853 --- PASS: TestParseSigningKey/no_colon (0.00s)2854 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2855 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2856--- PASS: TestSign (0.00s)2857=== CONT TestExternalSignerErrors/missing_signatures2858=== CONT TestExternalSignerErrors/program_error2859=== CONT TestExternalSignerErrors/invalid_signature_base642860=== CONT TestExternalSignerErrors/unrequested_key2861=== PAUSE TestSignErrors/invalid_narinfo2862=== RUN TestSignErrors/canceled2863=== PAUSE TestSignErrors/canceled2864=== CONT TestSignErrors/nil_key2865=== CONT TestSignErrors/canceled2866=== CONT TestSignErrors/invalid_narinfo2867=== CONT TestSignErrors/nil_narinfo2868--- PASS: TestSignErrors (0.00s)2869 --- PASS: TestSignErrors/nil_key (0.00s)2870 --- PASS: TestSignErrors/canceled (0.00s)2871 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2872 --- PASS: TestSignErrors/nil_narinfo (0.00s)2873--- PASS: TestExternalSignerCancellation (0.23s)2874--- PASS: TestExternalSignerRestartsAfterCrash (0.42s)2875/private/var/tb/8/scratch/b4189290b5638e57/build/TestExternalSignerRestartsAfterCrash2804212173/001/sign program: line 7: /private/var/tb/8/scratch/b4189290b5638e57/build/TestExternalSignerRestartsAfterCrash2804212173/001/sign program.starts: No such file or directory2876--- PASS: TestExternalSigner (0.63s)2877--- PASS: TestExternalSignerWrongPublicKey (0.80s)2878--- PASS: TestExternalSignerClose (1.76s)2879--- PASS: TestExternalSignerProgramErrorKeepsProcess (3.50s)2880--- PASS: TestExternalSignerErrors (0.00s)2881 --- PASS: TestExternalSignerErrors/missing_signatures (0.99s)2882 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (1.18s)2883 --- PASS: TestExternalSignerErrors/invalid_JSON (1.37s)2884 --- PASS: TestExternalSignerErrors/program_error (1.56s)2885 --- PASS: TestExternalSignerErrors/null (1.95s)2886 --- PASS: TestExternalSignerErrors/exit_on_request (2.15s)2887 --- PASS: TestExternalSignerErrors/exit_at_startup (2.34s)2888 --- PASS: TestExternalSignerErrors/too_few_signatures (2.53s)2889 --- PASS: TestExternalSignerErrors/wrong_signature_length (2.72s)2890 --- PASS: TestExternalSignerErrors/unrequested_key (2.91s)2891 --- PASS: TestExternalSignerErrors/wrong_shape (3.11s)2892 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (3.31s)2893 --- PASS: TestExternalSignerErrors/wrong_id (3.69s)2894 --- PASS: TestExternalSignerErrors/wrong_signature_name (3.91s)2895 --- PASS: TestExternalSignerErrors/missing_signature_name (4.10s)2896 --- PASS: TestExternalSignerErrors/null_signatures (4.29s)2897PASS2898Running OpenBao signer tests...2899=== RUN TestSign2900=== PAUSE TestSign2901=== RUN TestSignErrors2902=== PAUSE TestSignErrors2903=== RUN TestServe2904=== PAUSE TestServe2905=== RUN TestServeRejectsGarbage2906=== PAUSE TestServeRejectsGarbage2907=== CONT TestSign2908=== CONT TestSignErrors2909=== CONT TestServe2910=== RUN TestSignErrors/http_error2911=== PAUSE TestSignErrors/http_error2912=== RUN TestSignErrors/invalid_json2913=== PAUSE TestSignErrors/invalid_json2914=== RUN TestSignErrors/no_prefix2915=== PAUSE TestSignErrors/no_prefix2916=== RUN TestSignErrors/invalid_base642917=== PAUSE TestSignErrors/invalid_base642918=== CONT TestSignErrors/http_error2919=== CONT TestServeRejectsGarbage2920--- PASS: TestServeRejectsGarbage (0.00s)2921=== CONT TestSignErrors/invalid_json2922=== CONT TestSignErrors/no_prefix2923=== CONT TestSignErrors/invalid_base642924--- PASS: TestServe (0.00s)2925--- PASS: TestSign (0.00s)2926--- PASS: TestSignErrors (0.00s)2927 --- PASS: TestSignErrors/http_error (0.00s)2928 --- PASS: TestSignErrors/no_prefix (0.00s)2929 --- PASS: TestSignErrors/invalid_base64 (0.00s)2930 --- PASS: TestSignErrors/invalid_json (0.00s)2931PASS