niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #405
· raw
1tribuchet: building on mac022Running client tests...3=== RUN TestDoServerRequestAttachesToken4=== PAUSE TestDoServerRequestAttachesToken5=== RUN TestRegisterUploadedObjectReusesConnections6=== PAUSE TestRegisterUploadedObjectReusesConnections7=== RUN TestRunGarbageCollection_FinishedOnAnotherReplica8=== PAUSE TestRunGarbageCollection_FinishedOnAnotherReplica9=== RUN TestRunGarbageCollection_NotFoundAfterLocalRun10=== PAUSE TestRunGarbageCollection_NotFoundAfterLocalRun11=== RUN TestCaseHackSuffix12=== PAUSE TestCaseHackSuffix13=== RUN TestFilterOversizedClosures14=== PAUSE TestFilterOversizedClosures15=== RUN TestUploadMultipart_PartsInParallel16=== PAUSE TestUploadMultipart_PartsInParallel17=== RUN TestPartSizeForNAR18=== PAUSE TestPartSizeForNAR19=== RUN TestUploadMultipart_SupersededByPeer20=== PAUSE TestUploadMultipart_SupersededByPeer21=== RUN TestDumpPathCaseHackMatchesNix22--- PASS: TestDumpPathCaseHackMatchesNix (0.05s)23=== RUN TestDumpPathCaseHackCollision24--- PASS: TestDumpPathCaseHackCollision (0.00s)25=== RUN TestSupersededNARStillUploadsListing26=== PAUSE TestSupersededNARStillUploadsListing27=== RUN TestDumpPathMatchesNix28=== PAUSE TestDumpPathMatchesNix29=== RUN TestDumpPathSingleFile30=== PAUSE TestDumpPathSingleFile31=== RUN TestDumpPathWriterError32=== PAUSE TestDumpPathWriterError33=== RUN TestEncodeNixBase3234=== PAUSE TestEncodeNixBase3235=== RUN TestEncodeNixBase32WithRealHash36=== PAUSE TestEncodeNixBase32WithRealHash37=== RUN TestConvertHashToNix3238=== PAUSE TestConvertHashToNix3239=== RUN TestGetStorePathHash40=== PAUSE TestGetStorePathHash41=== RUN TestPathInfoHashCompatibility42=== PAUSE TestPathInfoHashCompatibility43=== RUN TestParsePathInfoJSON44=== PAUSE TestParsePathInfoJSON45=== RUN TestParsePathInfoJSONMultiplePaths46=== PAUSE TestParsePathInfoJSONMultiplePaths47=== RUN TestPathInfoCACompatibility48=== PAUSE TestPathInfoCACompatibility49=== RUN TestRateLimiterFeedback50=== PAUSE TestRateLimiterFeedback51=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess52=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess53=== RUN TestResolveStorePath54=== PAUSE TestResolveStorePath55=== RUN TestDoWithRetry_BodyReplayedViaGetBody56=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody57=== RUN TestRetryTimeoutOutlastsMaxRetries58=== PAUSE TestRetryTimeoutOutlastsMaxRetries59=== RUN TestShellSplit60=== PAUSE TestShellSplit61=== RUN TestShellSplitErrors62=== PAUSE TestShellSplitErrors63=== RUN TestStreamPushReportsEveryPath64=== PAUSE TestStreamPushReportsEveryPath65=== RUN TestStreamPushBatchesUnderLoad66=== PAUSE TestStreamPushBatchesUnderLoad67=== RUN TestStreamPushIsolatesFailures68=== PAUSE TestStreamPushIsolatesFailures69=== RUN TestStreamPushGivesUpOnDeadServer70=== PAUSE TestStreamPushGivesUpOnDeadServer71=== RUN TestStreamPushRequestLine72=== PAUSE TestStreamPushRequestLine73=== RUN TestStreamPushReportsSignatures74=== PAUSE TestStreamPushReportsSignatures75=== RUN TestStreamPushReportsSkippedPaths76=== PAUSE TestStreamPushReportsSkippedPaths77=== RUN TestClientSignaturesByStorePath78=== PAUSE TestClientSignaturesByStorePath79=== RUN TestStreamPushStopsWhenCanceled80=== PAUSE TestStreamPushStopsWhenCanceled81=== RUN TestSetClientTLS82=== PAUSE TestSetClientTLS83=== RUN TestSetClientTLSDoesNotMutateDefaultTransport84=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport85=== RUN TestSetClientTLSErrors86=== PAUSE TestSetClientTLSErrors87=== RUN TestStaticToken88=== PAUSE TestStaticToken89=== RUN TestFileTokenReadsAndCaches90=== PAUSE TestFileTokenReadsAndCaches91=== RUN TestFileTokenMissing92=== PAUSE TestFileTokenMissing93=== RUN TestFileTokenEmpty94=== PAUSE TestFileTokenEmpty95=== RUN TestScriptTokenNoExpiryRerunsEveryCall96=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall97=== RUN TestScriptTokenCachesUntilRefresh98=== PAUSE TestScriptTokenCachesUntilRefresh99=== RUN TestScriptTokenEmptyToken100=== PAUSE TestScriptTokenEmptyToken101=== RUN TestScriptTokenBadJSON102=== PAUSE TestScriptTokenBadJSON103=== RUN TestScriptTokenScriptFails104=== PAUSE TestScriptTokenScriptFails105=== RUN TestScriptTokenEmptyCommand106=== PAUSE TestScriptTokenEmptyCommand107=== CONT TestDoServerRequestAttachesToken108=== CONT TestRetryTimeoutOutlastsMaxRetries109=== CONT TestScriptTokenEmptyCommand110=== CONT TestPartSizeForNAR111=== CONT TestEncodeNixBase32112=== CONT TestDoWithRetry_BodyReplayedViaGetBody113=== RUN TestPartSizeForNAR/zero_stays_at_minimum114=== CONT TestStreamPushRequestLine115=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum116=== RUN TestPartSizeForNAR/small_stays_at_minimum117=== CONT TestResolveStorePath118=== RUN TestEncodeNixBase32/test_string_hash119=== PAUSE TestEncodeNixBase32/test_string_hash120=== RUN TestEncodeNixBase32/empty_input121=== PAUSE TestEncodeNixBase32/empty_input122=== CONT TestStreamPushIsolatesFailures123=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess1242026/10/10 19:00:37 ERROR Upload failed error="bad path" count=3125=== CONT TestRateLimiterFeedback126=== CONT TestPathInfoCACompatibility127=== CONT TestParsePathInfoJSONMultiplePaths128=== CONT TestParsePathInfoJSON129=== CONT TestPathInfoHashCompatibility130=== CONT TestGetStorePathHash131=== CONT TestConvertHashToNix32132=== CONT TestEncodeNixBase32WithRealHash133=== CONT TestSetClientTLSDoesNotMutateDefaultTransport134=== CONT TestSetClientTLS135=== CONT TestStreamPushStopsWhenCanceled136=== CONT TestClientSignaturesByStorePath137=== CONT TestStreamPushReportsSkippedPaths138=== CONT TestStreamPushReportsSignatures139=== CONT TestStreamPushBatchesUnderLoad140--- PASS: TestScriptTokenEmptyCommand (0.00s)141=== CONT TestStreamPushGivesUpOnDeadServer142=== PAUSE TestPartSizeForNAR/small_stays_at_minimum143=== RUN TestRateLimiterFeedback/429_enables_limiter144=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths145=== RUN TestPathInfoCACompatibility/null_ca_field146=== RUN TestParsePathInfoJSON/Nix_format147=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum148=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum149=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts150=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)151=== RUN TestGetStorePathHash/valid_store_path152=== PAUSE TestGetStorePathHash/valid_store_path153=== RUN TestGetStorePathHash/basename_without_hyphen_should_error154=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error155=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error156=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error157=== RUN TestConvertHashToNix32/SRI_format_to_Nix32158=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix321592026/10/10 19:00:37 WARN Rate limiter enabled after throttle name=server-test rate=5160=== RUN TestConvertHashToNix32/already_Nix32_format161=== PAUSE TestConvertHashToNix32/already_Nix32_format162=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun163=== CONT TestDumpPathSingleFile1642026/10/10 19:00:37 ERROR Upload failed error=boom count=1165=== CONT TestShellSplitErrors166=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica1672026/10/10 19:00:37 INFO Garbage collection started1682026/10/10 19:00:37 ERROR Upload failed error=boom count=11692026/10/10 19:00:37 ERROR Upload failed error="connection refused" count=201702026/10/10 19:00:37 ERROR Server seems unavailable, giving up on batch untried=17171--- PASS: TestResolveStorePath (0.00s)172--- PASS: TestEncodeNixBase32WithRealHash (0.00s)173--- PASS: TestStreamPushIsolatesFailures (0.00s)174--- PASS: TestClientSignaturesByStorePath (0.00s)175=== CONT TestDumpPathMatchesNix176=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error177=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error178=== RUN TestConvertHashToNix32/invalid_format179=== PAUSE TestConvertHashToNix32/invalid_format180=== CONT TestRegisterUploadedObjectReusesConnections181=== CONT TestDumpPathWriterError1822026/10/10 19:00:37 WARN Rate limiter enabled after throttle name=server-test rate=51832026/10/10 19:00:37 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:63026184=== CONT TestStreamPushReportsEveryPath185=== PAUSE TestRateLimiterFeedback/429_enables_limiter186=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths187=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts188=== PAUSE TestPathInfoCACompatibility/null_ca_field189=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)190=== CONT TestSupersededNARStillUploadsListing191=== CONT TestShellSplit192=== PAUSE TestParsePathInfoJSON/Nix_format193--- PASS: TestStreamPushStopsWhenCanceled (0.00s)194--- PASS: TestStreamPushReportsSkippedPaths (0.00s)195--- PASS: TestShellSplitErrors (0.00s)196--- PASS: TestStreamPushReportsSignatures (0.00s)197--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)198=== CONT TestScriptTokenNoExpiryRerunsEveryCall1992026/10/10 19:00:37 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:63027200--- PASS: TestDoServerRequestAttachesToken (0.00s)201=== CONT TestScriptTokenScriptFails202--- PASS: TestStreamPushReportsEveryPath (0.00s)203=== CONT TestScriptTokenBadJSON2042026/10/10 19:00:37 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:63027205--- PASS: TestShellSplit (0.00s)206=== CONT TestScriptTokenEmptyToken207--- PASS: TestScriptTokenScriptFails (0.01s)208=== CONT TestScriptTokenCachesUntilRefresh209--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.01s)210=== CONT TestFileTokenReadsAndCaches211--- PASS: TestFileTokenReadsAndCaches (0.00s)212=== CONT TestFileTokenEmpty2132026/10/10 19:00:37 WARN Rate limiter backed off name=server-test rate=52142026/10/10 19:00:37 WARN Request returned retryable status, retrying attempt=2 backoff=0s status=503 url=http://127.0.0.1:630262152026/10/10 19:00:37 INFO Garbage collection started216--- PASS: TestFileTokenEmpty (0.00s)217=== CONT TestFileTokenMissing218--- PASS: TestFileTokenMissing (0.00s)219=== CONT TestUploadMultipart_SupersededByPeer220=== RUN TestRateLimiterFeedback/503_enables_limiter221=== PAUSE TestRateLimiterFeedback/503_enables_limiter222=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths223=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths224--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.01s)225=== CONT TestUploadMultipart_PartsInParallel226--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.01s)227=== CONT TestCaseHackSuffix228=== RUN TestPartSizeForNAR/1_TiB229=== PAUSE TestPartSizeForNAR/1_TiB230=== RUN TestPartSizeForNAR/5_TiB_S3_max_object231=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object232=== RUN TestPartSizeForNAR/capped_at_5_GiB233=== PAUSE TestPartSizeForNAR/capped_at_5_GiB234=== CONT TestStaticToken235--- PASS: TestStaticToken (0.00s)236=== CONT TestSetClientTLSErrors237=== CONT TestFilterOversizedClosures238=== RUN TestFilterOversizedClosures/no_limit_keeps_everything239=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything240=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped241=== RUN TestPathInfoCACompatibility/old_string_format_-_text242=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text243=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive244=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive245=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon246=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped247=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon248=== RUN TestFilterOversizedClosures/all_closures_skipped249=== RUN TestParsePathInfoJSON/Lix_format250=== PAUSE TestFilterOversizedClosures/all_closures_skipped251=== RUN TestSupersededNARStillUploadsListing/small_NAR252=== RUN TestPathInfoCACompatibility/new_structured_format_-_text253=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text254=== RUN TestSetClientTLS/rejects_connection_without_client_cert255=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method256=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method257=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert258=== CONT TestEncodeNixBase32/empty_input259=== PAUSE TestSupersededNARStillUploadsListing/small_NAR260=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA261=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA262=== RUN TestSetClientTLS/preserves_debug_logging_transport263=== PAUSE TestSetClientTLS/preserves_debug_logging_transport264=== CONT TestGetStorePathHash/valid_store_path265=== CONT TestEncodeNixBase32/test_string_hash266=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI267=== RUN TestUploadMultipart_SupersededByPeer/exists2682026/10/10 19:00:37 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:630272692026/10/10 19:00:37 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=0270=== CONT TestConvertHashToNix32/SRI_format_to_Nix32271=== CONT TestGetStorePathHash/basename_without_hyphen_should_error272=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths273=== CONT TestPartSizeForNAR/zero_stays_at_minimum274=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths275=== CONT TestPartSizeForNAR/5_TiB_S3_max_object276=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts277=== CONT TestPartSizeForNAR/1_TiB278=== CONT TestPartSizeForNAR/capped_at_5_GiB279=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum280=== CONT TestPartSizeForNAR/small_stays_at_minimum281=== CONT TestFilterOversizedClosures/no_limit_keeps_everything282=== CONT TestFilterOversizedClosures/all_closures_skipped2832026/10/10 19:00:37 WARN Skipping closure: path exceeds server max NAR size top_level_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper oversized_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper nar_size=100 max_nar_size=50284=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped2852026/10/10 19:00:37 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=2000286=== CONT TestPathInfoCACompatibility/null_ca_field287=== CONT TestPathInfoCACompatibility/new_structured_format_-_text288=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive289=== CONT TestPathInfoCACompatibility/old_string_format_-_text290=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method291=== CONT TestSetClientTLS/rejects_connection_without_client_cert292=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error293=== CONT TestSetClientTLS/preserves_debug_logging_transport294=== RUN TestSupersededNARStillUploadsListing/dump_cut_short295=== PAUSE TestSupersededNARStillUploadsListing/dump_cut_short296=== RUN TestSupersededNARStillUploadsListing/listing_upload_fails297=== PAUSE TestSupersededNARStillUploadsListing/listing_upload_fails298=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI299=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512300=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512301=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA302=== PAUSE TestUploadMultipart_SupersededByPeer/exists303=== RUN TestUploadMultipart_SupersededByPeer/missing304=== PAUSE TestUploadMultipart_SupersededByPeer/missing305=== CONT TestSupersededNARStillUploadsListing/small_NAR3062026/10/10 19:00:37 INFO Uploading abc-hello (1.0GB)307=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter308=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter309=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter310=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter311=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)312=== CONT TestSupersededNARStillUploadsListing/dump_cut_short313--- PASS: TestScriptTokenBadJSON (0.02s)314--- PASS: TestScriptTokenEmptyToken (0.02s)315=== CONT TestConvertHashToNix32/invalid_format316=== CONT TestConvertHashToNix32/already_Nix32_format3172026/10/10 19:00:37 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:63027318=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error319--- PASS: TestGetStorePathHash (0.00s)320 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)321 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)322 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)323 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)324=== CONT TestUploadMultipart_SupersededByPeer/exists325=== PAUSE TestParsePathInfoJSON/Lix_format326=== RUN TestParsePathInfoJSON/empty_input327=== PAUSE TestParsePathInfoJSON/empty_input328=== RUN TestParsePathInfoJSON/whitespace_only329=== PAUSE TestParsePathInfoJSON/whitespace_only330=== RUN TestParsePathInfoJSON/invalid_JSON331=== PAUSE TestParsePathInfoJSON/invalid_JSON332=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512333=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI334=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon335--- PASS: TestPathInfoHashCompatibility (0.02s)336 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)337 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)338 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)339 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)340--- PASS: TestEncodeNixBase32 (0.00s)341 --- PASS: TestEncodeNixBase32/empty_input (0.00s)342 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)343=== CONT TestRateLimiterFeedback/429_enables_limiter344=== CONT TestUploadMultipart_SupersededByPeer/missing345=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter346=== CONT TestSupersededNARStillUploadsListing/listing_upload_fails347=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter348--- PASS: TestConvertHashToNix32 (0.00s)349 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)350 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)351 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)352--- PASS: TestParsePathInfoJSONMultiplePaths (0.02s)353 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)354 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)355--- PASS: TestPartSizeForNAR (0.02s)356 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)357 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)358 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)359 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)360 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)361 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)362 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)363--- PASS: TestFilterOversizedClosures (0.00s)364 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)365 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)366 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)367--- PASS: TestPathInfoCACompatibility (0.02s)368 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)369 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)370 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)371 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)372 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)3732026/10/10 19:00:37 WARN Request returned retryable status, retrying attempt=3 backoff=1ms status=502 url=http://127.0.0.1:630273742026/10/10 19:00:37 INFO Uploading abc-hello (1.0GB)375=== CONT TestRateLimiterFeedback/503_enables_limiter376=== CONT TestParsePathInfoJSON/Nix_format377=== CONT TestParsePathInfoJSON/whitespace_only378=== CONT TestParsePathInfoJSON/invalid_JSON379=== CONT TestParsePathInfoJSON/empty_input380=== CONT TestParsePathInfoJSON/Lix_format381--- PASS: TestParsePathInfoJSON (0.03s)382 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)383 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)384 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)385 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)386 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)387=== RUN TestSetClientTLSErrors/missing_cert_file388=== PAUSE TestSetClientTLSErrors/missing_cert_file389=== RUN TestSetClientTLSErrors/missing_key_file390=== PAUSE TestSetClientTLSErrors/missing_key_file391=== RUN TestSetClientTLSErrors/missing_ca_file392=== PAUSE TestSetClientTLSErrors/missing_ca_file393=== RUN TestSetClientTLSErrors/invalid_ca_file394=== PAUSE TestSetClientTLSErrors/invalid_ca_file395=== CONT TestSetClientTLSErrors/missing_cert_file396=== CONT TestSetClientTLSErrors/invalid_ca_file397=== CONT TestSetClientTLSErrors/missing_ca_file398=== CONT TestSetClientTLSErrors/missing_key_file3992026/10/10 19:00:37 WARN Rate limiter enabled after throttle name=server-test rate=54002026/10/10 19:00:37 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=429 url=http://127.0.0.1:631134012026/10/10 19:00:37 WARN Request returned retryable status, retrying attempt=4 backoff=1ms status=502 url=http://127.0.0.1:630274022026/10/10 19:00:37 WARN Rate limiter enabled after throttle name=server-test rate=54032026/10/10 19:00:37 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:631214042026/10/10 19:00:37 WARN Garbage collection finished on another replica. Its statistics are not available here405--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.03s)406--- PASS: TestSetClientTLSErrors (0.02s)407 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)408 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)409 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)410 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)4112026/10/10 19:00:37 WARN Rate limiter backed off name=server-test rate=5412--- PASS: TestUploadMultipart_SupersededByPeer (0.01s)413 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)414 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.01s)4152026/10/10 19:00:37 WARN Rate limiter backed off name=server-test rate=5416--- PASS: TestRateLimiterFeedback (0.03s)417 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)418 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.01s)419 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)420 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.01s)421--- PASS: TestStreamPushRequestLine (0.04s)4222026/10/10 19:00:37 WARN Request returned retryable status, retrying attempt=5 backoff=1ms status=502 url=http://127.0.0.1:630274232026/10/10 19:00:37 WARN Request returned retryable status, retrying attempt=6 backoff=1ms status=502 url=http://127.0.0.1:630274242026/10/10 19:00:37 WARN Request returned retryable status, retrying attempt=7 backoff=1ms status=502 url=http://127.0.0.1:630274252026/10/10 19:00:37 WARN Request returned retryable status, retrying attempt=8 backoff=1ms status=502 url=http://127.0.0.1:630274262026/10/10 19:00:37 WARN Request returned retryable status, retrying attempt=9 backoff=1ms status=502 url=http://127.0.0.1:630274272026/10/10 19:00:37 WARN Request returned retryable status, retrying attempt=10 backoff=1ms status=502 url=http://127.0.0.1:630274282026/10/10 19:00:37 WARN Request returned retryable status, retrying attempt=11 backoff=1ms status=502 url=http://127.0.0.1:63027429--- PASS: TestRegisterUploadedObjectReusesConnections (0.05s)4302026/10/10 19:00:37 WARN Request returned retryable status, retrying attempt=12 backoff=1ms status=502 url=http://127.0.0.1:630274312026/10/10 19:00:37 WARN Request returned retryable status, retrying attempt=13 backoff=1ms status=502 url=http://127.0.0.1:630274322026/10/10 19:00:37 http: TLS handshake error from 127.0.0.1:63104: remote error: tls: bad certificate4332026/10/10 19:00:37 WARN Request returned retryable status, retrying attempt=14 backoff=1ms status=502 url=http://127.0.0.1:63027434--- PASS: TestSetClientTLS (0.02s)435 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.02s)436 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.02s)437 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.03s)4382026/10/10 19:00:37 WARN Request returned retryable status, retrying attempt=15 backoff=1ms status=502 url=http://127.0.0.1:630274392026/10/10 19:00:37 WARN Request returned retryable status, retrying attempt=16 backoff=1ms status=502 url=http://127.0.0.1:630274402026/10/10 19:00:37 WARN Request returned retryable status, retrying attempt=17 backoff=1ms status=502 url=http://127.0.0.1:63027441--- PASS: TestScriptTokenCachesUntilRefresh (0.05s)442--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.06s)443--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.05s)444--- PASS: TestDumpPathSingleFile (0.06s)4452026/10/10 19:00:37 INFO Uploading abc-hello (1.0GB)446--- PASS: TestCaseHackSuffix (0.07s)447--- PASS: TestDumpPathWriterError (0.08s)4482026/10/10 19:00:37 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:63109/part/2\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:63109/part/24492026/10/10 19:00:37 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:63109/part/3\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:63109/part/34502026/10/10 19:00:37 ERROR Failed to close zstd encoder error="io: read/write on closed pipe"451--- PASS: TestStreamPushBatchesUnderLoad (0.10s)452--- PASS: TestDumpPathMatchesNix (0.11s)453--- PASS: TestSupersededNARStillUploadsListing (0.02s)454 --- PASS: TestSupersededNARStillUploadsListing/small_NAR (0.01s)455 --- PASS: TestSupersededNARStillUploadsListing/listing_upload_fails (0.01s)456 --- PASS: TestSupersededNARStillUploadsListing/dump_cut_short (0.56s)457--- PASS: TestUploadMultipart_PartsInParallel (0.62s)458--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)459PASS460Running server tests...461The files belonging to this database system will be owned by user "_tribuchetbld5".462This user must also own the server process.463464The database cluster will be initialized with locale "C".465The default database encoding has accordingly been set to "SQL_ASCII".466The default text search configuration will be set to "english".467468Data page checksums are enabled.469470creating directory /private/var/tb/5/scratch/1572a97443ce2c80/build/postgres4013063381/data ... ok471creating subdirectories ... ok472selecting dynamic shared memory implementation ... posix473selecting default "max_connections" ... 100474selecting default "shared_buffers" ... 128MB475selecting default time zone ... UTC476creating configuration files ... ok477running bootstrap script ... ok478performing post-bootstrap initialization ... ok479syncing data to disk ... ok480481initdb: warning: enabling "trust" authentication for local connections482initdb: 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.483484Success. You can now start the database server using:485486 pg_ctl -D /private/var/tb/5/scratch/1572a97443ce2c80/build/postgres4013063381/data -l logfile start4874882026-10-10 19:00:40.887 UTC [95013] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit4892026-10-10 19:00:40.887 UTC [95013] LOG: listening on Unix socket "/private/var/tb/5/scratch/1572a97443ce2c80/build/postgres4013063381/.s.PGSQL.5432"4902026-10-10 19:00:40.889 UTC [95020] LOG: database system was shut down at 2026-10-10 19:00:40 UTC4912026-10-10 19:00:40.890 UTC [95013] LOG: database system is ready to accept connections492/private/var/tb/5/scratch/1572a97443ce2c80/build/postgres4013063381:5432 - accepting connections493{"timestamp":"2026-10-10T19:00:43.097685Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"13875a11-6594-4922-aa55-1cc89bb5ef02","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":1,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":501,"threadName":"rustfs-worker","threadId":"ThreadId(2)"}494=== RUN TestService_AuthMiddleware495=== PAUSE TestService_AuthMiddleware496=== RUN TestService_AuthMiddleware_MTLSProxyHeader497=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader498=== RUN TestService_AuthMiddleware_MTLSBoundSubjects499=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects500=== RUN TestService_ReadAuthMiddleware501=== PAUSE TestService_ReadAuthMiddleware502=== RUN TestService_AuthMiddleware_OIDC503=== PAUSE TestService_AuthMiddleware_OIDC504=== RUN TestService_RequireScope_OIDC505=== PAUSE TestService_RequireScope_OIDC506=== RUN TestService_ReadScope_PublicByDefault507=== PAUSE TestService_ReadScope_PublicByDefault508=== RUN TestCacheConfigHandler509=== PAUSE TestCacheConfigHandler510=== RUN TestCacheStatsHandler511=== PAUSE TestCacheStatsHandler512=== RUN TestClientCADerivations513=== PAUSE TestClientCADerivations514=== RUN TestClientErrorHandling515=== PAUSE TestClientErrorHandling516=== RUN TestClientIntegration517=== PAUSE TestClientIntegration518=== RUN TestClientMultipleUploads519=== PAUSE TestClientMultipleUploads520=== RUN TestClientWithDependencies521=== PAUSE TestClientWithDependencies522=== RUN TestClientSharedPathCommittedMidPush523=== PAUSE TestClientSharedPathCommittedMidPush524=== RUN TestPinProtectsFromGC525=== PAUSE TestPinProtectsFromGC526=== RUN TestClientPushesUseOnePush527=== PAUSE TestClientPushesUseOnePush528=== RUN TestClientFallsBackToClosures529=== PAUSE TestClientFallsBackToClosures530=== RUN TestDeleteClosuresRacingPins531=== PAUSE TestDeleteClosuresRacingPins532=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock533=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock534=== RUN TestResolveDBConnectionString535=== PAUSE TestResolveDBConnectionString536=== RUN TestConnectWaitsForAPeerMigration537=== PAUSE TestConnectWaitsForAPeerMigration538=== RUN TestLeadElectsOneAndHandsOver539=== PAUSE TestLeadElectsOneAndHandsOver540=== RUN TestLeadIncumbentWinsAfterRestart5412026/10/10 19:00:43 INFO lead: acquired remote=192.0.2.1:12345422026/10/10 19:00:44 INFO lead: released remote=192.0.2.1:12345432026/10/10 19:00:44 INFO lead: acquired remote=192.0.2.1:12345442026/10/10 19:00:45 INFO lead: released remote=192.0.2.1:1234545--- PASS: TestLeadIncumbentWinsAfterRestart (2.10s)546=== RUN TestLeadIncumbentAnnouncesAtOnce547=== PAUSE TestLeadIncumbentAnnouncesAtOnce548=== RUN TestLeadEndsOnShutdown549=== PAUSE TestLeadEndsOnShutdown550=== RUN TestLeadEndsWhenItsConnectionHangs5512026/10/10 19:00:45 INFO lead: acquired remote=192.0.2.1:12345522026-10-10 19:00:46.865 UTC [95085] FATAL: terminating connection due to administrator command5532026/10/10 19:00:47 INFO lead: acquired remote=192.0.2.1:12345542026/10/10 19:00:48 WARN lead: lock connection lost error="timeout: context deadline exceeded"5552026/10/10 19:00:48 INFO lead: released remote=192.0.2.1:12345562026/10/10 19:00:48 INFO lead: released remote=192.0.2.1:1234557--- PASS: TestLeadEndsWhenItsConnectionHangs (2.96s)558=== RUN TestGCAdvisoryLockBlocksConcurrentRun559=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun560=== RUN TestGCBugBareHashReferences561=== PAUSE TestGCBugBareHashReferences562=== RUN TestGCMetrics563=== PAUSE TestGCMetrics564=== RUN TestPushDedupSurvivesConcurrentGC565=== PAUSE TestPushDedupSurvivesConcurrentGC566=== RUN TestDeduplicatedObjectsRecordedAsPending567=== PAUSE TestDeduplicatedObjectsRecordedAsPending568=== RUN TestGCSweepSkipsPendingObjects569=== PAUSE TestGCSweepSkipsPendingObjects570=== RUN TestTombstonedObjectOfferedWithoutWaiting571=== PAUSE TestTombstonedObjectOfferedWithoutWaiting572=== RUN TestGCSweepDeliversEachKeyOnce573=== PAUSE TestGCSweepDeliversEachKeyOnce574=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection575=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection576=== RUN TestForceGCDuringPushOffersSweptObject577=== PAUSE TestForceGCDuringPushOffersSweptObject578=== RUN TestFailedS3DeleteKeepsTombstone579=== PAUSE TestFailedS3DeleteKeepsTombstone580=== RUN TestSweepSkipsRowsLockedByPush581=== PAUSE TestSweepSkipsRowsLockedByPush582=== RUN TestRegisterCompletedObjectNeedsPendingRow583=== PAUSE TestRegisterCompletedObjectNeedsPendingRow584=== RUN TestGetExistingObjectsLocksRows585=== PAUSE TestGetExistingObjectsLocksRows586=== RUN TestSweepRechecksPendingAfterLocking587=== PAUSE TestSweepRechecksPendingAfterLocking588=== RUN TestPushWaitsForSweepHoldingRow589=== PAUSE TestPushWaitsForSweepHoldingRow590=== RUN TestCommitRacingPendingCleanupKeepsObjects591=== PAUSE TestCommitRacingPendingCleanupKeepsObjects592=== RUN TestGCEndsOnShutdown593=== PAUSE TestGCEndsOnShutdown594=== RUN TestGCTaskStore_StartNew595=== PAUSE TestGCTaskStore_StartNew596=== RUN TestGCTaskStore_DeduplicateSameParams597=== PAUSE TestGCTaskStore_DeduplicateSameParams598=== RUN TestGCTaskStore_ConflictDifferentParams599=== PAUSE TestGCTaskStore_ConflictDifferentParams600=== RUN TestGCTaskStore_GetEmpty601=== PAUSE TestGCTaskStore_GetEmpty602=== RUN TestGCTaskStore_GetReturnsLatest603=== PAUSE TestGCTaskStore_GetReturnsLatest604=== RUN TestGCTaskStore_CompletedAllowsNewTask605=== PAUSE TestGCTaskStore_CompletedAllowsNewTask606=== RUN TestGCTaskStore_PhaseUpdates607=== PAUSE TestGCTaskStore_PhaseUpdates608=== RUN TestGCTaskStore_Fail609=== PAUSE TestGCTaskStore_Fail610=== RUN TestGracefulShutdownDrainsInflight611=== PAUSE TestGracefulShutdownDrainsInflight612=== RUN TestService_healthCheckHandler613=== PAUSE TestService_healthCheckHandler614=== RUN TestService_readinessHandler615=== PAUSE TestService_readinessHandler616=== RUN TestGenerateLandingPage617=== PAUSE TestGenerateLandingPage618=== RUN TestCacheConfigHandlerMaxNarSize619=== PAUSE TestCacheConfigHandlerMaxNarSize620=== RUN TestCreatePendingClosureRejectsOversizedNAR621=== PAUSE TestCreatePendingClosureRejectsOversizedNAR622=== RUN TestNARDeduplicationMetadataUploadBug623=== PAUSE TestNARDeduplicationMetadataUploadBug624=== RUN TestMetricsInventory625=== PAUSE TestMetricsInventory626=== RUN TestMetricsCommit627=== PAUSE TestMetricsCommit628=== RUN TestService_NativeMTLS629=== PAUSE TestService_NativeMTLS630=== RUN TestServerTLSConfig631=== PAUSE TestServerTLSConfig632=== RUN TestMultipartCleanup633=== PAUSE TestMultipartCleanup634=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded635=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded636=== RUN TestPendingCleanupUsesOneCutoff637=== PAUSE TestPendingCleanupUsesOneCutoff638=== RUN TestObjectStatsTrigger639=== PAUSE TestObjectStatsTrigger640=== RUN TestObjectStatsLargeCommit641=== PAUSE TestObjectStatsLargeCommit642=== RUN TestOrphanedObjectsGC643=== PAUSE TestOrphanedObjectsGC644=== RUN TestOrphanedObjectsGCStressTest645=== PAUSE TestOrphanedObjectsGCStressTest646=== RUN TestCreatePin_ReservedPins647=== PAUSE TestCreatePin_ReservedPins648=== RUN TestPresentReportsOnlyClosureRoots649=== PAUSE TestPresentReportsOnlyClosureRoots650=== RUN TestPresentRefreshesOnlyStaleClosures651=== PAUSE TestPresentRefreshesOnlyStaleClosures652=== RUN TestPresentNotReportedWhileGCDeletesClosure653=== PAUSE TestPresentNotReportedWhileGCDeletesClosure654=== RUN TestParseSingleRange655=== PAUSE TestParseSingleRange656=== RUN TestProxyHeadersOnlyTrustedOnSocket6572026/10/10 19:00:48 INFO Starting HTTP server address=proxy.sock6582026/10/10 19:00:48 INFO Starting HTTP server address=127.0.0.1:631856592026/10/10 19:00:48 WARN mTLS auth: subject not in bound subjects subject="CN=someone"6602026/10/10 19:00:48 INFO Shutdown signal received, draining in-flight requests timeout=10s661--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.17s)662=== RUN TestIsValidCachePath663=== PAUSE TestIsValidCachePath664=== RUN TestReadProxyNarinfo665=== PAUSE TestReadProxyNarinfo666=== RUN TestReadProxyNarinfoAlreadyDecompressed667=== PAUSE TestReadProxyNarinfoAlreadyDecompressed668=== RUN TestReadProxyContentNegotiation669=== PAUSE TestReadProxyContentNegotiation670=== RUN TestReadProxyNarStreaming671=== PAUSE TestReadProxyNarStreaming672=== RUN TestReadProxy404673=== PAUSE TestReadProxy404674=== RUN TestReadProxyInvalidPath675=== PAUSE TestReadProxyInvalidPath676=== RUN TestReadProxyHead677=== PAUSE TestReadProxyHead678=== RUN TestReadProxyOutlastsServerWriteTimeout679=== PAUSE TestReadProxyOutlastsServerWriteTimeout680=== RUN TestReadProxyConditionalGet681=== PAUSE TestReadProxyConditionalGet682=== RUN TestReadProxyRootRedirectsToIndexHTML683=== PAUSE TestReadProxyRootRedirectsToIndexHTML684=== RUN TestReadProxyDisabled685=== PAUSE TestReadProxyDisabled686=== RUN TestReadRedirectNar687=== PAUSE TestReadRedirectNar688=== RUN TestReadRedirectKeepsNarinfoProxied689=== PAUSE TestReadRedirectKeepsNarinfoProxied690=== RUN TestReadProxyRangeRequest691=== PAUSE TestReadProxyRangeRequest692=== RUN TestReadRedirectUsesPublicS3URL693=== PAUSE TestReadRedirectUsesPublicS3URL694=== RUN TestPush_OverlappingRootsStoreOneRowPerKey695=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey696=== RUN TestPush_CompleteCommitsEveryRoot697=== PAUSE TestPush_CompleteCommitsEveryRoot698=== RUN TestPush_RepeatedRootCommitsOnce699=== PAUSE TestPush_RepeatedRootCommitsOnce700=== RUN TestPush_CompleteWaitsForCleanupOfThePush701=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush702=== RUN TestPush_RootsAreLockedInByteOrder703=== PAUSE TestPush_RootsAreLockedInByteOrder704=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit705=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit706=== RUN TestPush_RejectsBadRequests707=== PAUSE TestPush_RejectsBadRequests708=== RUN TestPush_SignsNarinfosOfItsPendingObjects709=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects710=== RUN TestRedundantMultipartUpload711=== PAUSE TestRedundantMultipartUpload712=== RUN TestCompleteMultipartUpload_ErrorButObjectExists713=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists714=== RUN TestCompletedNarNotReofferedAcrossClosures715=== PAUSE TestCompletedNarNotReofferedAcrossClosures716=== RUN TestPresignedUploadRegisteredBeforeCommit717=== PAUSE TestPresignedUploadRegisteredBeforeCommit718=== RUN TestService_Rustfstest719=== PAUSE TestService_Rustfstest720=== RUN TestParseSize721=== PAUSE TestParseSize722=== RUN TestSkippedUploadsHandler723=== PAUSE TestSkippedUploadsHandler724=== RUN TestSystemdListenerNotActivated725--- PASS: TestSystemdListenerNotActivated (0.00s)726=== RUN TestWatchdogBeatsWhenHealthy727--- PASS: TestWatchdogBeatsWhenHealthy (0.03s)728=== RUN TestWatchdogSkipsWhenUnhealthy7292026/10/10 19:00:48 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7302026/10/10 19:00:48 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7312026/10/10 19:00:48 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7322026/10/10 19:00:48 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7332026/10/10 19:00:48 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7342026/10/10 19:00:48 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7352026/10/10 19:00:48 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7362026/10/10 19:00:48 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7372026/10/10 19:00:48 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7382026/10/10 19:00:48 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"739--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)740=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle741=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle742=== RUN TestProxyWriteTimeout743=== PAUSE TestProxyWriteTimeout744=== RUN TestPendingClosureWriteTimeout745=== PAUSE TestPendingClosureWriteTimeout746=== RUN TestIsValidUploadKey747=== PAUSE TestIsValidUploadKey748=== RUN TestUploadHandlersRejectInvalidKeys749=== PAUSE TestUploadHandlersRejectInvalidKeys750=== RUN TestUploadHandlersRejectOversizedBody751=== PAUSE TestUploadHandlersRejectOversizedBody752=== RUN TestService_cleanupPendingClosuresHandler753=== PAUSE TestService_cleanupPendingClosuresHandler754=== RUN TestService_createPendingClosureHandler755=== PAUSE TestService_createPendingClosureHandler756=== RUN TestService_verifyS3Integrity757=== PAUSE TestService_verifyS3Integrity758=== RUN TestCompleteMultipartUnregistered759=== PAUSE TestCompleteMultipartUnregistered760=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT761=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT762=== CONT TestReadRedirectKeepsNarinfoProxied763=== CONT TestReadRedirectNar764=== CONT TestService_Rustfstest765=== CONT TestService_cleanupPendingClosuresHandler766=== CONT TestGCTaskStore_StartNew767--- PASS: TestGCTaskStore_StartNew (0.00s)768=== CONT TestReadProxyDisabled769=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit770=== CONT TestLeadElectsOneAndHandsOver771=== CONT TestService_AuthMiddleware772=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock773=== CONT TestUploadHandlersRejectInvalidKeys774=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info775=== CONT TestCompleteMultipartUnregistered776=== CONT TestReadProxyRootRedirectsToIndexHTML777=== CONT TestService_verifyS3Integrity778=== CONT TestService_createPendingClosureHandler779=== CONT TestConnectWaitsForAPeerMigration780=== CONT TestResolveDBConnectionString781=== CONT TestReadProxyConditionalGet782=== CONT TestReadProxyOutlastsServerWriteTimeout783=== CONT TestReadProxyHead784=== CONT TestReadProxyInvalidPath785=== CONT TestReadProxy404786=== CONT TestReadProxyNarStreaming787=== CONT TestReadProxyContentNegotiation788=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT789=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info790=== RUN TestResolveDBConnectionString/flag_wins791=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal792=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal793=== PAUSE TestResolveDBConnectionString/flag_wins794=== RUN TestResolveDBConnectionString/file_when_flag_empty795=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key796=== PAUSE TestResolveDBConnectionString/file_when_flag_empty797=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key798=== RUN TestResolveDBConnectionString/missing_file_is_an_error799=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key800=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error801=== RUN TestResolveDBConnectionString/PGHOST_allows_empty802=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty803=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key804=== RUN TestResolveDBConnectionString/nothing_configured805=== CONT TestReadProxyNarinfoAlreadyDecompressed806=== PAUSE TestResolveDBConnectionString/nothing_configured807=== CONT TestReadProxyNarinfo8082026/10/10 19:00:50 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8092026/10/10 19:00:50 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst810--- PASS: TestCompleteMultipartUnregistered (1.44s)811=== CONT TestIsValidCachePath812=== RUN TestIsValidCachePath/narinfo813=== PAUSE TestIsValidCachePath/narinfo814=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars815=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars816=== RUN TestIsValidCachePath/nar_zst817=== PAUSE TestIsValidCachePath/nar_zst818=== RUN TestIsValidCachePath/nar_xz819=== PAUSE TestIsValidCachePath/nar_xz820=== RUN TestIsValidCachePath/nar_bz2821=== PAUSE TestIsValidCachePath/nar_bz2822=== RUN TestIsValidCachePath/nar_uncompressed823=== PAUSE TestIsValidCachePath/nar_uncompressed824=== RUN TestIsValidCachePath/ls825=== PAUSE TestIsValidCachePath/ls826=== RUN TestIsValidCachePath/log827=== PAUSE TestIsValidCachePath/log828=== RUN TestIsValidCachePath/realisation829=== PAUSE TestIsValidCachePath/realisation830=== RUN TestIsValidCachePath/nix-cache-info831=== PAUSE TestIsValidCachePath/nix-cache-info832=== RUN TestIsValidCachePath/index.html833=== PAUSE TestIsValidCachePath/index.html834=== RUN TestIsValidCachePath/traversal_parent835=== PAUSE TestIsValidCachePath/traversal_parent836=== RUN TestIsValidCachePath/traversal_in_middle837=== PAUSE TestIsValidCachePath/traversal_in_middle838=== RUN TestIsValidCachePath/invalid_char_e839=== PAUSE TestIsValidCachePath/invalid_char_e840=== RUN TestIsValidCachePath/invalid_char_u841=== PAUSE TestIsValidCachePath/invalid_char_u842=== RUN TestIsValidCachePath/random_path843=== PAUSE TestIsValidCachePath/random_path844=== RUN TestIsValidCachePath/empty845=== PAUSE TestIsValidCachePath/empty846=== RUN TestIsValidCachePath/leading_slash847=== PAUSE TestIsValidCachePath/leading_slash848=== RUN TestIsValidCachePath/wrong_extension849=== PAUSE TestIsValidCachePath/wrong_extension850=== RUN TestIsValidCachePath/short_hash851=== PAUSE TestIsValidCachePath/short_hash852=== CONT TestParseSingleRange853=== RUN TestParseSingleRange/none854=== PAUSE TestParseSingleRange/none855=== RUN TestParseSingleRange/unknown_unit856=== PAUSE TestParseSingleRange/unknown_unit857=== RUN TestParseSingleRange/multi-range_ignored858=== PAUSE TestParseSingleRange/multi-range_ignored859=== RUN TestParseSingleRange/malformed_no_dash860=== PAUSE TestParseSingleRange/malformed_no_dash861=== RUN TestParseSingleRange/malformed_both_empty862=== PAUSE TestParseSingleRange/malformed_both_empty863=== RUN TestParseSingleRange/malformed_end_before_start864=== PAUSE TestParseSingleRange/malformed_end_before_start865=== RUN TestParseSingleRange/closed866=== PAUSE TestParseSingleRange/closed867=== RUN TestParseSingleRange/open-ended868=== PAUSE TestParseSingleRange/open-ended869=== RUN TestParseSingleRange/end_clamped_to_size870=== PAUSE TestParseSingleRange/end_clamped_to_size871=== RUN TestParseSingleRange/suffix872=== PAUSE TestParseSingleRange/suffix873=== RUN TestParseSingleRange/suffix_exceeds_size874=== PAUSE TestParseSingleRange/suffix_exceeds_size875=== RUN TestParseSingleRange/single_byte876=== PAUSE TestParseSingleRange/single_byte877=== RUN TestParseSingleRange/start_past_EOF878=== PAUSE TestParseSingleRange/start_past_EOF879=== RUN TestParseSingleRange/start_far_past_EOF880=== PAUSE TestParseSingleRange/start_far_past_EOF881=== CONT TestPresentNotReportedWhileGCDeletesClosure882=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale883=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale884=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh885=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh886=== CONT TestPresentRefreshesOnlyStaleClosures8872026/10/10 19:00:50 INFO Received push request method=POST path=/api/pushes8882026/10/10 19:00:50 INFO Received complete push request method=POST path=/api/pushes/1/complete8892026/10/10 19:00:50 INFO Completed push id=1 objects=4 duration=31.055458ms8902026/10/10 19:00:50 INFO Received push request method=POST path=/api/pushes8912026/10/10 19:00:50 INFO Aborted multipart uploads count=0 kept=08922026/10/10 19:00:50 WARN Force mode enabled - objects will be deleted immediately without grace period8932026/10/10 19:00:50 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=0894--- PASS: TestReadProxyDisabled (2.05s)895=== CONT TestPresentReportsOnlyClosureRoots8962026/10/10 19:00:50 INFO Vacuumed table table=pending_closures8972026/10/10 19:00:50 INFO Vacuumed table table=pending_objects8982026/10/10 19:00:50 INFO Vacuumed table table=multipart_uploads8992026/10/10 19:00:50 INFO Vacuumed table table=closures9002026/10/10 19:00:50 INFO Vacuumed table table=objects9012026/10/10 19:00:50 INFO Received complete push request method=POST path=/api/pushes/2/complete9022026/10/10 19:00:50 INFO Completed push id=2 objects=4 duration=7.285917ms903--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (2.24s)904=== CONT TestCreatePin_ReservedPins9052026/10/10 19:00:50 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:63194/oidc9062026/10/10 19:00:51 INFO Received cleanup request method=DELETE path=/api/pending_closures9072026/10/10 19:00:51 INFO Aborted multipart uploads count=0 kept=09082026/10/10 19:00:51 INFO Received uploads request method=POST path=/api/pending_closures9092026/10/10 19:00:51 INFO Received cleanup request method=DELETE path=/api/pending_closures9102026/10/10 19:00:51 INFO Aborted multipart uploads count=1 kept=09112026/10/10 19:00:51 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9122026-10-10 19:00:51.128 UTC [95150] ERROR: Closure does not exist: id=19132026-10-10 19:00:51.128 UTC [95150] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE9142026-10-10 19:00:51.128 UTC [95150] STATEMENT: -- name: CommitPendingClosure :one915 SELECT commit_pending_closure($1::bigint)::bigint916 917--- PASS: TestService_cleanupPendingClosuresHandler (2.45s)918=== CONT TestOrphanedObjectsGCStressTest919--- PASS: TestReadProxyNarStreaming (2.59s)920=== CONT TestOrphanedObjectsGC9212026/10/10 19:00:51 INFO Received uploads request method=POST path=/api/pending_closures922--- PASS: TestReadRedirectKeepsNarinfoProxied (3.09s)923=== CONT TestObjectStatsLargeCommit9242026/10/10 19:00:52 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>925--- PASS: TestReadProxyNarinfo (3.45s)926=== CONT TestObjectStatsTrigger9272026/10/10 19:00:52 INFO Received uploads request method=POST path=/api/pending_closures928--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (3.80s)929=== CONT TestPendingCleanupUsesOneCutoff9302026/10/10 19:00:52 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"931--- PASS: TestService_AuthMiddleware (4.00s)932=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded933--- PASS: TestService_Rustfstest (4.30s)934=== CONT TestMultipartCleanup9352026/10/10 19:00:53 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9362026/10/10 19:00:53 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=OWUyNjU5MDktZTExOC00OTFmLWE1M2MtOTU1YTA4M2ZkOGIwLjIyZGQ2MzcwLTI2NzUtNGI1My04ZjNmLTFmY2NmY2ZmMTI0ZXgxNzkxNjU4ODUxNDc5MzI3MDAw parts=109372026/10/10 19:00:53 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9382026/10/10 19:00:53 INFO Completed upload id=1 objects=2 duration=23.449791ms9392026/10/10 19:00:53 INFO Received uploads request method=POST path=/api/pending_closures9402026/10/10 19:00:53 INFO Received uploads request method=POST path=/api/pending_closures9412026/10/10 19:00:53 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo9422026/10/10 19:00:53 WARN Found objects in DB but missing from S3, will re-upload count=1943--- PASS: TestService_verifyS3Integrity (4.52s)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: TestReadProxyInvalidPath (4.60s)953=== CONT TestMetricsCommit954--- PASS: TestReadProxy404 (5.20s)955=== CONT TestMetricsInventory956--- PASS: TestReadProxyConditionalGet (5.37s)957=== CONT TestNARDeduplicationMetadataUploadBug9582026/10/10 19:00:54 INFO lead: acquired remote=192.0.2.1:1234959--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (5.79s)960=== CONT TestCreatePendingClosureRejectsOversizedNAR9612026/10/10 19:00:54 INFO Received uploads request method=POST path=/api/pending_closures962--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)963=== CONT TestCacheConfigHandlerMaxNarSize964--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)965=== CONT TestGenerateLandingPage966--- PASS: TestGenerateLandingPage (0.00s)967=== CONT TestService_readinessHandler968--- PASS: TestReadProxyHead (5.88s)969=== CONT TestService_healthCheckHandler970--- PASS: TestReadRedirectNar (6.35s)971=== CONT TestGracefulShutdownDrainsInflight9722026/10/10 19:00:55 INFO Starting HTTP server address=127.0.0.1:632369732026/10/10 19:00:55 INFO Shutdown signal received, draining in-flight requests timeout=10s974--- PASS: TestGracefulShutdownDrainsInflight (0.08s)975=== CONT TestGCTaskStore_Fail976--- PASS: TestGCTaskStore_Fail (0.00s)977=== CONT TestGCTaskStore_PhaseUpdates978--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)979=== CONT TestGCTaskStore_CompletedAllowsNewTask980--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)981=== CONT TestGCTaskStore_GetReturnsLatest982--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)983=== CONT TestGCTaskStore_GetEmpty984--- PASS: TestGCTaskStore_GetEmpty (0.00s)985=== CONT TestGCTaskStore_ConflictDifferentParams986--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)987=== CONT TestGCTaskStore_DeduplicateSameParams988--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)989=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection990--- PASS: TestConnectWaitsForAPeerMigration (6.47s)991=== CONT TestGCEndsOnShutdown992=== RUN TestGCEndsOnShutdown/before_the_run993=== PAUSE TestGCEndsOnShutdown/before_the_run994=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete995=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete996=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark997=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark998=== CONT TestCommitRacingPendingCleanupKeepsObjects999--- PASS: TestReadProxyContentNegotiation (6.65s)1000=== CONT TestPushWaitsForSweepHoldingRow1001--- PASS: TestReadProxyRootRedirectsToIndexHTML (6.82s)1002=== CONT TestSweepRechecksPendingAfterLocking10032026/10/10 19:00:55 INFO lead: released remote=192.0.2.1:123410042026/10/10 19:00:55 INFO lead: acquired remote=192.0.2.1:123410052026/10/10 19:00:55 INFO Received uploads request method=POST path=/api/pending_closures10062026/10/10 19:00:55 INFO Received uploads request method=POST path=/api/pending_closures10072026/10/10 19:00:55 INFO Received uploads request method=POST path=/api/pending_closures1008--- PASS: TestReadProxyNarinfoAlreadyDecompressed (7.39s)1009=== CONT TestGetExistingObjectsLocksRows1010--- PASS: TestPresentReportsOnlyClosureRoots (5.77s)1011=== CONT TestRegisterCompletedObjectNeedsPendingRow10122026/10/10 19:00:56 INFO lead: released remote=192.0.2.1:12341013--- PASS: TestLeadElectsOneAndHandsOver (7.98s)1014=== CONT TestSweepSkipsRowsLockedByPush1015--- PASS: TestPresentRefreshesOnlyStaleClosures (6.73s)1016=== CONT TestFailedS3DeleteKeepsTombstone10172026/10/10 19:00:57 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux10182026/10/10 19:00:57 WARN Refused reserved pin name=worker-x86_64-linux10192026/10/10 19:00:57 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux10202026/10/10 19:00:57 INFO Received create pin request method=POST path=/api/pins/my-app10212026/10/10 19:00:57 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1022--- PASS: TestCreatePin_ReservedPins (6.16s)1023=== CONT TestForceGCDuringPushOffersSweptObject1024=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows1025=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows1026=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check1027=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check1028=== CONT TestProxyWriteTimeout1029=== RUN TestProxyWriteTimeout/narinfo1030=== PAUSE TestProxyWriteTimeout/narinfo1031=== RUN TestProxyWriteTimeout/1_GiB_nar1032=== PAUSE TestProxyWriteTimeout/1_GiB_nar1033=== RUN TestProxyWriteTimeout/10_GiB_nar1034=== PAUSE TestProxyWriteTimeout/10_GiB_nar1035=== RUN TestProxyWriteTimeout/unknown_size1036=== PAUSE TestProxyWriteTimeout/unknown_size1037=== CONT TestUploadHandlersRejectOversizedBody1038=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure1039=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure1040=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart1041=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart1042=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts1043=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts1044=== CONT TestIsValidUploadKey1045=== RUN TestIsValidUploadKey/narinfo1046=== PAUSE TestIsValidUploadKey/narinfo1047=== RUN TestIsValidUploadKey/nar_zst1048=== PAUSE TestIsValidUploadKey/nar_zst1049=== RUN TestIsValidUploadKey/nar_xz1050=== PAUSE TestIsValidUploadKey/nar_xz1051=== RUN TestIsValidUploadKey/nar_plain1052=== PAUSE TestIsValidUploadKey/nar_plain1053=== RUN TestIsValidUploadKey/listing1054=== PAUSE TestIsValidUploadKey/listing1055=== RUN TestIsValidUploadKey/build_log1056=== PAUSE TestIsValidUploadKey/build_log1057=== RUN TestIsValidUploadKey/build_log_home-manager_file1058=== PAUSE TestIsValidUploadKey/build_log_home-manager_file1059=== RUN TestIsValidUploadKey/build_log_plus_in_name1060=== PAUSE TestIsValidUploadKey/build_log_plus_in_name1061=== RUN TestIsValidUploadKey/build_log_question_mark1062=== PAUSE TestIsValidUploadKey/build_log_question_mark1063=== RUN TestIsValidUploadKey/build_log_equals1064=== PAUSE TestIsValidUploadKey/build_log_equals1065=== RUN TestIsValidUploadKey/realisation1066=== PAUSE TestIsValidUploadKey/realisation1067=== RUN TestIsValidUploadKey/realisation_plus_in_output1068=== PAUSE TestIsValidUploadKey/realisation_plus_in_output1069=== RUN TestIsValidUploadKey/nix-cache-info1070=== PAUSE TestIsValidUploadKey/nix-cache-info1071=== RUN TestIsValidUploadKey/index.html1072=== PAUSE TestIsValidUploadKey/index.html1073=== RUN TestIsValidUploadKey/narinfo_key,_nar_type1074=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type1075=== RUN TestIsValidUploadKey/nar_key,_narinfo_type1076=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type1077=== RUN TestIsValidUploadKey/listing_key,_narinfo_type1078=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type1079=== RUN TestIsValidUploadKey/traversal1080=== PAUSE TestIsValidUploadKey/traversal1081=== RUN TestIsValidUploadKey/traversal_nar1082=== PAUSE TestIsValidUploadKey/traversal_nar1083=== RUN TestIsValidUploadKey/absolute1084=== PAUSE TestIsValidUploadKey/absolute1085=== RUN TestIsValidUploadKey/empty_key1086=== PAUSE TestIsValidUploadKey/empty_key1087=== RUN TestIsValidUploadKey/unknown_type1088=== PAUSE TestIsValidUploadKey/unknown_type1089=== CONT TestPendingClosureWriteTimeout1090=== RUN TestPendingClosureWriteTimeout/empty1091=== PAUSE TestPendingClosureWriteTimeout/empty1092=== RUN TestPendingClosureWriteTimeout/400_objects1093=== PAUSE TestPendingClosureWriteTimeout/400_objects1094=== RUN TestPendingClosureWriteTimeout/670k_objects1095=== PAUSE TestPendingClosureWriteTimeout/670k_objects1096=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1097=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1098=== CONT TestPushDedupSurvivesConcurrentGC10992026/10/10 19:00:57 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11002026/10/10 19:00:57 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=OWUyNjU5MDktZTExOC00OTFmLWE1M2MtOTU1YTA4M2ZkOGIwLjMwYjdhY2Q4LWYwM2QtNDA2ZS1iODUyLTExYzA5YjQ5YTEzNHgxNzkxNjU4ODU1NzcxNjIyMDAw parts=1011012026/10/10 19:00:57 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11022026/10/10 19:00:57 INFO Completed upload id=1 objects=2 duration=50.220792ms11032026/10/10 19:00:57 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000011042026/10/10 19:00:57 INFO Received uploads request method=POST path=/api/pending_closures11052026/10/10 19:00:57 INFO Starting cleanup of old closures method=DELETE path=/api/closures11062026/10/10 19:00:57 INFO Aborted multipart uploads count=0 kept=011072026/10/10 19:00:57 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=011082026/10/10 19:00:57 INFO Vacuumed table table=pending_closures11092026/10/10 19:00:57 INFO Vacuumed table table=pending_objects11102026/10/10 19:00:57 INFO Vacuumed table table=multipart_uploads11112026/10/10 19:00:57 INFO Vacuumed table table=closures11122026/10/10 19:00:57 INFO Vacuumed table table=objects11132026/10/10 19:00:57 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001114--- PASS: TestService_createPendingClosureHandler (9.28s)1115=== CONT TestGCSweepDeliversEachKeyOnce1116--- PASS: TestObjectStatsTrigger (6.82s)1117=== CONT TestGCSweepSkipsPendingObjects1118--- PASS: TestReadProxyOutlastsServerWriteTimeout (10.33s)1119=== CONT TestDeduplicatedObjectsRecordedAsPending1120=== NAME TestOrphanedObjectsGC1121 orphaned_objects_gc_test.go:287: GC Test Summary:1122 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A1123 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B1124 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)1125 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)1126 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects1127--- PASS: TestOrphanedObjectsGC (7.84s)1128=== CONT TestTombstonedObjectOfferedWithoutWaiting11292026/10/10 19:00:59 INFO Received uploads request method=POST path=/api/pending_closures11302026/10/10 19:00:59 INFO Received uploads request method=POST path=/api/pending_closures11312026/10/10 19:00:59 INFO Received cleanup request method=DELETE path=/api/pending_closures11322026/10/10 19:00:59 INFO Received uploads request method=POST path=/api/pending_closures1133--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (7.33s)1134=== CONT TestClientErrorHandling1135=== RUN TestClientErrorHandling/InvalidStorePath1136=== PAUSE TestClientErrorHandling/InvalidStorePath1137=== RUN TestClientErrorHandling/InvalidAuthToken1138=== PAUSE TestClientErrorHandling/InvalidAuthToken1139=== RUN TestClientErrorHandling/ServerNotAvailable1140=== PAUSE TestClientErrorHandling/ServerNotAvailable1141=== CONT TestGCAdvisoryLockBlocksConcurrentRun11422026/10/10 19:01:00 INFO Received uploads request method=POST path=/api/pending_closures11432026/10/10 19:01:00 INFO Received cleanup request method=DELETE path=/api/pending_closures11442026/10/10 19:01:00 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket36/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""11452026/10/10 19:01:00 INFO Aborted multipart uploads count=0 kept=111462026/10/10 19:01:00 INFO Received cleanup request method=DELETE path=/api/pending_closures11472026/10/10 19:01:00 INFO Aborted multipart uploads count=1 kept=01148--- PASS: TestMultipartCleanup (7.57s)1149=== CONT TestDeleteClosuresRacingPins11502026/10/10 19:01:00 WARN mTLS auth: subject not in bound subjects subject="CN=reader"11512026/10/10 19:01:00 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1152--- PASS: TestService_NativeMTLS (7.47s)1153=== CONT TestGCMetrics11542026/10/10 19:01:01 INFO Received push request method=POST path=/api/pushes11552026/10/10 19:01:01 INFO Received complete push request method=POST path=/api/pushes/1/complete11562026/10/10 19:01:01 INFO Completed push id=1 objects=4 duration=41.886458ms11572026/10/10 19:01:01 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete11582026/10/10 19:01:01 INFO Completed upload id=2 objects=2 duration=1.882875ms1159--- PASS: TestMetricsCommit (8.01s)1160=== CONT TestClientFallsBackToClosures1161--- PASS: TestMetricsInventory (7.71s)1162=== CONT TestGCBugBareHashReferences1163--- PASS: TestService_healthCheckHandler (7.78s)1164=== CONT TestClientPushesUseOnePush1165=== NAME TestNARDeduplicationMetadataUploadBug1166 metadata_upload_test.go:48: First store path: /private/var/tb/5/scratch/1572a97443ce2c80/build/TestNARDeduplicationMetadataUploadBug108651078/001/store/4l1g414dx1lzr55s6gc117pp7abh9iai-file1.txt11672026/10/10 19:01:02 INFO Received push request method=POST path=/api/pushes11682026/10/10 19:01:02 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)11692026/10/10 19:01:02 INFO Uploading 4l1g414dx1lzr55s6gc117pp7abh9iai-file1.txt (160B)11702026/10/10 19:01:02 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"11712026/10/10 19:01:02 WARN Failed to register uploaded object key=4l1g414dx1lzr55s6gc117pp7abh9iai.ls error="server returned 404: 404 page not found\n"11722026/10/10 19:01:02 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11732026/10/10 19:01:02 INFO Signed narinfos id=1 count=111742026/10/10 19:01:02 INFO Uploading 1 narinfos11752026/10/10 19:01:02 INFO Received complete push request method=POST path=/api/pushes/1/complete11762026/10/10 19:01:02 WARN Failed to register uploaded object key=4l1g414dx1lzr55s6gc117pp7abh9iai.narinfo error="server returned 404: 404 page not found\n"11772026/10/10 19:01:02 INFO Completed push id=1 objects=3 duration=25.458ms11782026/10/10 19:01:02 INFO Upload complete. (200ms)1179 metadata_upload_test.go:54: Retrieved narinfo from S3:1180 StorePath: /private/var/tb/5/scratch/1572a97443ce2c80/build/TestNARDeduplicationMetadataUploadBug108651078/001/store/4l1g414dx1lzr55s6gc117pp7abh9iai-file1.txt1181 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1182 Compression: zstd1183 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1184 NarSize: 1601185 References: 1186 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1187 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1188 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1189 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}11902026/10/10 19:01:02 WARN readiness check failed error="closed pool"1191--- PASS: TestService_readinessHandler (8.22s)1192=== CONT TestClientWithDependencies1193=== NAME TestNARDeduplicationMetadataUploadBug1194 metadata_upload_test.go:64: Second store path (same content): /private/var/tb/5/scratch/1572a97443ce2c80/build/TestNARDeduplicationMetadataUploadBug108651078/001/store/dbzipg4hvs038pwc63y5s86aq4g3khc3-file2.txt11952026/10/10 19:01:02 INFO Received push request method=POST path=/api/pushes11962026/10/10 19:01:02 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)11972026/10/10 19:01:02 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign11982026/10/10 19:01:02 WARN Failed to register uploaded object key=dbzipg4hvs038pwc63y5s86aq4g3khc3.ls error="server returned 404: 404 page not found\n"11992026/10/10 19:01:02 INFO Signed narinfos id=2 count=112002026/10/10 19:01:02 INFO Uploading 1 narinfos12012026/10/10 19:01:02 INFO Received complete push request method=POST path=/api/pushes/2/complete12022026/10/10 19:01:02 WARN Failed to register uploaded object key=dbzipg4hvs038pwc63y5s86aq4g3khc3.narinfo error="server returned 404: 404 page not found\n"12032026/10/10 19:01:02 INFO Completed push id=2 objects=3 duration=978.334µs12042026/10/10 19:01:02 INFO Upload complete. (139ms)1205 metadata_upload_test.go:76: Retrieved narinfo from S3:1206 StorePath: /private/var/tb/5/scratch/1572a97443ce2c80/build/TestNARDeduplicationMetadataUploadBug108651078/001/store/dbzipg4hvs038pwc63y5s86aq4g3khc3-file2.txt1207 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1208 Compression: zstd1209 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1210 NarSize: 1601211 References: 1212 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1213 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1214 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1215 {"version":1,"root":{"type":"regular","size":44}}1216--- PASS: TestNARDeduplicationMetadataUploadBug (8.92s)1217=== CONT TestClientMultipleUploads12182026/10/10 19:01:03 INFO Aborted multipart uploads count=0 kept=012192026/10/10 19:01:03 WARN Force mode enabled - objects will be deleted immediately without grace period12202026/10/10 19:01:03 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=012212026/10/10 19:01:03 INFO Vacuumed table table=pending_closures12222026/10/10 19:01:03 INFO Vacuumed table table=pending_objects12232026/10/10 19:01:03 INFO Vacuumed table table=multipart_uploads12242026/10/10 19:01:03 INFO Vacuumed table table=closures12252026/10/10 19:01:03 INFO Received uploads request method=POST path=/api/pending_closures12262026/10/10 19:01:03 INFO Vacuumed table table=objects1227--- PASS: TestCommitRacingPendingCleanupKeepsObjects (8.30s)1228=== CONT TestClientIntegration1229--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (8.55s)1230=== CONT TestPinProtectsFromGC12312026/10/10 19:01:03 INFO Received uploads request method=POST path=/api/pending_closures12322026/10/10 19:01:04 INFO Aborted multipart uploads count=0 kept=012332026/10/10 19:01:04 WARN Force mode enabled - objects will be deleted immediately without grace period12342026/10/10 19:01:04 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=012352026/10/10 19:01:04 INFO Vacuumed table table=pending_closures1236--- PASS: TestPushWaitsForSweepHoldingRow (8.92s)1237=== CONT TestClientSharedPathCommittedMidPush12382026/10/10 19:01:04 INFO Vacuumed table table=pending_objects12392026/10/10 19:01:04 INFO Vacuumed table table=multipart_uploads12402026/10/10 19:01:04 INFO Vacuumed table table=closures12412026/10/10 19:01:04 INFO Vacuumed table table=objects1242--- PASS: TestSweepRechecksPendingAfterLocking (8.91s)1243=== CONT TestPush_CompleteCommitsEveryRoot1244--- PASS: TestGetExistingObjectsLocksRows (8.36s)1245=== CONT TestPush_RootsAreLockedInByteOrder1246--- PASS: TestRegisterCompletedObjectNeedsPendingRow (8.33s)1247=== CONT TestPush_CompleteWaitsForCleanupOfThePush12482026/10/10 19:01:05 INFO Aborted multipart uploads count=0 kept=012492026/10/10 19:01:05 WARN Force mode enabled - objects will be deleted immediately without grace period12502026/10/10 19:01:05 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=012512026/10/10 19:01:05 INFO Vacuumed table table=pending_closures12522026/10/10 19:01:05 INFO Vacuumed table table=pending_objects12532026/10/10 19:01:05 INFO Vacuumed table table=multipart_uploads12542026/10/10 19:01:05 INFO Vacuumed table table=closures12552026/10/10 19:01:05 INFO Vacuumed table table=objects12562026/10/10 19:01:05 INFO Aborted multipart uploads count=0 kept=012572026/10/10 19:01:05 WARN Force mode enabled - objects will be deleted immediately without grace period12582026/10/10 19:01:05 INFO Aborted multipart uploads count=1 kept=012592026/10/10 19:01:05 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=012602026/10/10 19:01:05 INFO Vacuumed table table=pending_closures12612026/10/10 19:01:05 INFO Vacuumed table table=pending_objects12622026/10/10 19:01:05 INFO Vacuumed table table=multipart_uploads12632026/10/10 19:01:05 INFO Vacuumed table table=closures12642026/10/10 19:01:05 INFO Vacuumed table table=objects1265--- PASS: TestSweepSkipsRowsLockedByPush (8.86s)1266=== CONT TestPush_RepeatedRootCommitsOnce12672026/10/10 19:01:05 INFO Received cleanup request method=DELETE path=/api/pending_closures12682026/10/10 19:01:05 INFO Aborted multipart uploads count=1 kept=01269--- PASS: TestPendingCleanupUsesOneCutoff (13.07s)1270=== CONT TestCacheStatsHandler12712026/10/10 19:01:05 INFO Received uploads request method=POST path=/api/pending_closures12722026/10/10 19:01:05 INFO Aborted multipart uploads count=0 kept=012732026/10/10 19:01:05 WARN Force mode enabled - objects will be deleted immediately without grace period12742026/10/10 19:01:05 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."12752026/10/10 19:01:05 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."1276--- PASS: TestFailedS3DeleteKeepsTombstone (8.95s)1277=== CONT TestClientCADerivations12782026/10/10 19:01:06 INFO Received uploads request method=POST path=/api/pending_closures1279=== NAME TestOrphanedObjectsGCStressTest1280 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains12812026/10/10 19:01:06 INFO Aborted multipart uploads count=0 kept=012822026/10/10 19:01:06 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=01283 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion12842026/10/10 19:01:06 INFO Vacuumed table table=pending_closures12852026/10/10 19:01:06 INFO Vacuumed table table=pending_objects12862026/10/10 19:01:06 INFO Vacuumed table table=multipart_uploads12872026/10/10 19:01:06 INFO Vacuumed table table=closures12882026/10/10 19:01:06 INFO Aborted multipart uploads count=0 kept=012892026/10/10 19:01:06 INFO Vacuumed table table=objects12902026/10/10 19:01:06 WARN Force mode enabled - objects will be deleted immediately without grace period12912026/10/10 19:01:06 INFO Aborted multipart uploads count=0 kept=012922026/10/10 19:01:06 WARN Force mode enabled - objects will be deleted immediately without grace period12932026/10/10 19:01:06 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=012942026/10/10 19:01:06 INFO Vacuumed table table=pending_closures12952026/10/10 19:01:06 INFO Vacuumed table table=pending_objects12962026/10/10 19:01:06 INFO Vacuumed table table=multipart_uploads12972026/10/10 19:01:06 INFO Vacuumed table table=closures12982026/10/10 19:01:06 INFO Vacuumed table table=objects1299--- PASS: TestPushDedupSurvivesConcurrentGC (9.64s)1300=== CONT TestSkippedUploadsHandler13012026/10/10 19:01:06 INFO Client skipped oversized paths paths=3 nar_bytes=500000000013022026/10/10 19:01:06 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=01303--- PASS: TestSkippedUploadsHandler (0.00s)1304=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle13052026/10/10 19:01:06 INFO Vacuumed table table=pending_closures13062026/10/10 19:01:06 INFO Vacuumed table table=pending_objects13072026/10/10 19:01:06 INFO Vacuumed table table=multipart_uploads13082026/10/10 19:01:06 INFO Vacuumed table table=closures13092026/10/10 19:01:06 INFO Received uploads request method=POST path=/api/pending_closures13102026/10/10 19:01:06 INFO Vacuumed table table=objects1311--- PASS: TestGCSweepDeliversEachKeyOnce (8.98s)1312=== CONT TestCompleteMultipartUpload_ErrorButObjectExists1313--- PASS: TestDeduplicatedObjectsRecordedAsPending (7.96s)1314=== CONT TestPresignedUploadRegisteredBeforeCommit13152026/10/10 19:01:07 INFO Received uploads request method=POST path=/api/pending_closures13162026/10/10 19:01:07 INFO Aborted multipart uploads count=0 kept=013172026/10/10 19:01:07 WARN Force mode enabled - objects will be deleted immediately without grace period13182026/10/10 19:01:07 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=013192026/10/10 19:01:07 INFO Vacuumed table table=pending_closures13202026/10/10 19:01:07 INFO Vacuumed table table=pending_objects13212026/10/10 19:01:07 INFO Vacuumed table table=multipart_uploads13222026/10/10 19:01:07 INFO Vacuumed table table=closures13232026/10/10 19:01:07 INFO Vacuumed table table=objects13242026/10/10 19:01:07 INFO Received uploads request method=POST path=/api/pending_closures1325--- PASS: TestTombstonedObjectOfferedWithoutWaiting (8.82s)1326=== CONT TestCompletedNarNotReofferedAcrossClosures1327--- PASS: TestGCSweepSkipsPendingObjects (8.99s)1328=== CONT TestLeadEndsOnShutdown13292026/10/10 19:01:08 ERROR failed to check GC advisory lock error="query pg_locks: failed to connect to `user=_tribuchetbld5 database=niks3`: /nonexistent/.s.PGSQL.5432 (/nonexistent): dial error: dial unix /nonexistent/.s.PGSQL.5432: connect: no such file or directory"1330--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (8.37s)1331=== CONT TestPush_SignsNarinfosOfItsPendingObjects13322026/10/10 19:01:08 INFO Aborted multipart uploads count=0 kept=013332026/10/10 19:01:08 WARN Force mode enabled - objects will be deleted immediately without grace period13342026/10/10 19:01:08 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=013352026/10/10 19:01:08 INFO Vacuumed table table=pending_closures13362026/10/10 19:01:08 INFO Vacuumed table table=pending_objects13372026/10/10 19:01:08 INFO Vacuumed table table=multipart_uploads13382026/10/10 19:01:08 INFO Vacuumed table table=closures13392026/10/10 19:01:08 INFO Vacuumed table table=objects1340--- PASS: TestGCMetrics (8.19s)1341=== CONT TestRedundantMultipartUpload1342--- PASS: TestObjectStatsLargeCommit (18.37s)1343=== CONT TestReadRedirectUsesPublicS3URL1344--- PASS: TestGCBugBareHashReferences (8.65s)1345=== CONT TestPush_OverlappingRootsStoreOneRowPerKey13462026/10/10 19:01:10 INFO Received uploads request method=POST path=/api/pending_closures13472026/10/10 19:01:10 INFO Received uploads request method=POST path=/api/pending_closures13482026/10/10 19:01:10 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)13492026/10/10 19:01:10 INFO Uploading ccfrlr9z2gwq4m79a0vv8bjb9z0yvrci-b (256B)13502026/10/10 19:01:10 INFO Uploading bf260x288y4m70zj1r7pqjbr4ix08hcd-shared-dep (136B)13512026/10/10 19:01:10 WARN Failed to register uploaded object key=bf260x288y4m70zj1r7pqjbr4ix08hcd.ls error="server returned 404: 404 page not found\n"13522026/10/10 19:01:10 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"13532026/10/10 19:01:10 WARN Failed to register uploaded object key=ccfrlr9z2gwq4m79a0vv8bjb9z0yvrci.ls error="server returned 404: 404 page not found\n"13542026/10/10 19:01:10 WARN Failed to register uploaded object key=c7ynxyhw7vgldmjzg4qzyk158dbzw8b0.ls error="server returned 404: 404 page not found\n"13552026/10/10 19:01:10 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign13562026/10/10 19:01:10 WARN Failed to register uploaded object key=nar/0lzg42f8i0psc57r5bzs9ax1kl9jcn60wxg80fjfhzi54lvxlkyl.nar.zst error="server returned 404: 404 page not found\n"13572026/10/10 19:01:10 INFO Signed narinfos id=2 count=213582026/10/10 19:01:10 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign13592026/10/10 19:01:10 INFO Signed narinfos id=1 count=213602026/10/10 19:01:10 INFO Uploading 4 narinfos13612026/10/10 19:01:10 WARN Failed to register uploaded object key=ccfrlr9z2gwq4m79a0vv8bjb9z0yvrci.narinfo error="server returned 404: 404 page not found\n"13622026/10/10 19:01:10 WARN Failed to register uploaded object key=bf260x288y4m70zj1r7pqjbr4ix08hcd.narinfo error="server returned 404: 404 page not found\n"13632026/10/10 19:01:10 WARN Failed to register uploaded object key=c7ynxyhw7vgldmjzg4qzyk158dbzw8b0.narinfo error="server returned 404: 404 page not found\n"13642026/10/10 19:01:10 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13652026/10/10 19:01:10 WARN Failed to register uploaded object key=bf260x288y4m70zj1r7pqjbr4ix08hcd.narinfo error="server returned 404: 404 page not found\n"13662026/10/10 19:01:10 INFO Completed upload id=1 objects=6 duration=12.386792ms13672026/10/10 19:01:10 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete13682026/10/10 19:01:10 INFO Completed upload id=2 objects=6 duration=730.792µs13692026/10/10 19:01:10 INFO Upload complete. (272ms)1370=== NAME TestClientFallsBackToClosures1371 client_pushes_test.go:112: Retrieved narinfo from S3:1372 StorePath: /private/var/tb/5/scratch/1572a97443ce2c80/build/TestClientFallsBackToClosures171394135/001/store/bf260x288y4m70zj1r7pqjbr4ix08hcd-shared-dep1373 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1374 Compression: zstd1375 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821376 NarSize: 1361377 References: 1378 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1379 client_pushes_test.go:112: Retrieved narinfo from S3:1380 StorePath: /private/var/tb/5/scratch/1572a97443ce2c80/build/TestClientFallsBackToClosures171394135/001/store/c7ynxyhw7vgldmjzg4qzyk158dbzw8b0-a1381 URL: nar/0lzg42f8i0psc57r5bzs9ax1kl9jcn60wxg80fjfhzi54lvxlkyl.nar.zst1382 Compression: zstd1383 NarHash: sha256:0lzg42f8i0psc57r5bzs9ax1kl9jcn60wxg80fjfhzi54lvxlkyl1384 NarSize: 2561385 References: /private/var/tb/5/scratch/1572a97443ce2c80/build/TestClientFallsBackToClosures171394135/001/store/bf260x288y4m70zj1r7pqjbr4ix08hcd-shared-dep1386 CA: text:sha256:01mr205xbqqpaa1qmbr2di1snq8c5n6q7p6bjs0sq5a3i6hqagph1387 client_pushes_test.go:112: Retrieved narinfo from S3:1388 StorePath: /private/var/tb/5/scratch/1572a97443ce2c80/build/TestClientFallsBackToClosures171394135/001/store/ccfrlr9z2gwq4m79a0vv8bjb9z0yvrci-b1389 URL: nar/0lzg42f8i0psc57r5bzs9ax1kl9jcn60wxg80fjfhzi54lvxlkyl.nar.zst1390 Compression: zstd1391 NarHash: sha256:0lzg42f8i0psc57r5bzs9ax1kl9jcn60wxg80fjfhzi54lvxlkyl1392 NarSize: 2561393 References: /private/var/tb/5/scratch/1572a97443ce2c80/build/TestClientFallsBackToClosures171394135/001/store/bf260x288y4m70zj1r7pqjbr4ix08hcd-shared-dep1394 CA: text:sha256:01mr205xbqqpaa1qmbr2di1snq8c5n6q7p6bjs0sq5a3i6hqagph1395--- PASS: TestClientFallsBackToClosures (9.29s)1396=== CONT TestReadProxyRangeRequest13972026/10/10 19:01:10 INFO Received push request method=POST path=/api/pushes13982026/10/10 19:01:10 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)13992026/10/10 19:01:10 INFO Uploading z839wxq1wlwzn34arm5q79pjh7p111fd-a (256B)14002026/10/10 19:01:10 INFO Uploading 5ccz1ni8lz6wm8krr18fvn4xlh83fi56-shared-dep (136B)14012026/10/10 19:01:10 WARN Failed to register uploaded object key=nar/0g1d0lyi7cm59ffqpbkfmabgvh7v7nhidijdkrqhz4294mf60jaf.nar.zst error="server returned 404: 404 page not found\n"14022026/10/10 19:01:10 WARN Failed to register uploaded object key=2szdkvh21gav1545qq3qqd6i7v636wqv.ls error="server returned 404: 404 page not found\n"14032026/10/10 19:01:10 WARN Failed to register uploaded object key=z839wxq1wlwzn34arm5q79pjh7p111fd.ls error="server returned 404: 404 page not found\n"14042026/10/10 19:01:10 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14052026/10/10 19:01:10 WARN Failed to register uploaded object key=5ccz1ni8lz6wm8krr18fvn4xlh83fi56.ls error="server returned 404: 404 page not found\n"14062026/10/10 19:01:10 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"14072026/10/10 19:01:10 INFO Signed narinfos id=1 count=314082026/10/10 19:01:10 INFO Uploading 3 narinfos14092026/10/10 19:01:10 WARN Failed to register uploaded object key=2szdkvh21gav1545qq3qqd6i7v636wqv.narinfo error="server returned 404: 404 page not found\n"14102026/10/10 19:01:10 WARN Failed to register uploaded object key=5ccz1ni8lz6wm8krr18fvn4xlh83fi56.narinfo error="server returned 404: 404 page not found\n"14112026/10/10 19:01:10 INFO Received complete push request method=POST path=/api/pushes/1/complete14122026/10/10 19:01:10 WARN Failed to register uploaded object key=z839wxq1wlwzn34arm5q79pjh7p111fd.narinfo error="server returned 404: 404 page not found\n"1413{"timestamp":"2026-10-10T19:01:10.927333Z","level":"ERROR","message":"save_config_with_opts: err: Io(Custom { kind: TooManyOpenFiles, error: \"Too many open files (os error 24)\" }), file: scanner/durable-dirty-producer-replay.json","target":"rustfs_ecstore::config::com","filename":"crates/ecstore/src/config/com.rs","line_number":813,"threadName":"rustfs-worker","threadId":"ThreadId(2)"}14142026/10/10 19:01:10 INFO Completed push id=1 objects=8 duration=36.606ms14152026/10/10 19:01:10 INFO Upload complete. (202ms)1416=== NAME TestClientPushesUseOnePush1417 client_pushes_test.go:97: Retrieved narinfo from S3:1418 StorePath: /private/var/tb/5/scratch/1572a97443ce2c80/build/TestClientPushesUseOnePush4001979315/001/store/5ccz1ni8lz6wm8krr18fvn4xlh83fi56-shared-dep1419 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1420 Compression: zstd1421 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821422 NarSize: 1361423 References: 1424 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1425 client_pushes_test.go:97: Retrieved narinfo from S3:1426 StorePath: /private/var/tb/5/scratch/1572a97443ce2c80/build/TestClientPushesUseOnePush4001979315/001/store/z839wxq1wlwzn34arm5q79pjh7p111fd-a1427 URL: nar/0g1d0lyi7cm59ffqpbkfmabgvh7v7nhidijdkrqhz4294mf60jaf.nar.zst1428 Compression: zstd1429 NarHash: sha256:0g1d0lyi7cm59ffqpbkfmabgvh7v7nhidijdkrqhz4294mf60jaf1430 NarSize: 2561431 References: /private/var/tb/5/scratch/1572a97443ce2c80/build/TestClientPushesUseOnePush4001979315/001/store/5ccz1ni8lz6wm8krr18fvn4xlh83fi56-shared-dep1432 CA: text:sha256:1nr6bqhfk0d4b296fabcaz63k33wbi33q0s3bzbrn2jrrhydy5dy1433 client_pushes_test.go:97: Retrieved narinfo from S3:1434 StorePath: /private/var/tb/5/scratch/1572a97443ce2c80/build/TestClientPushesUseOnePush4001979315/001/store/2szdkvh21gav1545qq3qqd6i7v636wqv-b1435 URL: nar/0g1d0lyi7cm59ffqpbkfmabgvh7v7nhidijdkrqhz4294mf60jaf.nar.zst1436 Compression: zstd1437 NarHash: sha256:0g1d0lyi7cm59ffqpbkfmabgvh7v7nhidijdkrqhz4294mf60jaf1438 NarSize: 2561439 References: /private/var/tb/5/scratch/1572a97443ce2c80/build/TestClientPushesUseOnePush4001979315/001/store/5ccz1ni8lz6wm8krr18fvn4xlh83fi56-shared-dep1440 CA: text:sha256:1nr6bqhfk0d4b296fabcaz63k33wbi33q0s3bzbrn2jrrhydy5dy1441--- PASS: TestClientPushesUseOnePush (8.74s)1442=== CONT TestService_RequireScope_OIDC1443=== NAME TestClientWithDependencies1444 client_integration_test.go:613: Built derivation: /private/var/tb/5/scratch/1572a97443ce2c80/build/TestClientWithDependencies634974056/001/store/x5r184jhwgslyvmy4nkk03pmmw1c82h4-test-script1445 client_integration_test.go:615: Found 1 dependencies (including self)14462026/10/10 19:01:11 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:63329/oidc1447=== NAME TestClientMultipleUploads1448 client_integration_test.go:358: Created store path 0: /private/var/tb/5/scratch/1572a97443ce2c80/build/TestClientMultipleUploads3456979323/001/store/614gxpkx9c1wypfl9d66sdd1d0yfpms2-test-file-0.txt1449=== NAME TestOrphanedObjectsGCStressTest1450 orphaned_objects_gc_test.go:503: Stress test completed successfully:1451 orphaned_objects_gc_test.go:504: - Active objects preserved: 201452 orphaned_objects_gc_test.go:505: - Objects deleted: 2101453 orphaned_objects_gc_test.go:506: - Total GC'd: 2101454=== CONT TestService_ReadAuthMiddleware1455--- PASS: TestOrphanedObjectsGCStressTest (20.05s)1456=== NAME TestClientMultipleUploads1457 client_integration_test.go:358: Created store path 1: /private/var/tb/5/scratch/1572a97443ce2c80/build/TestClientMultipleUploads3456979323/001/store/1yphpaxl5zkf9vg40n6hlmai16fz12ks-test-file-1.txt14582026/10/10 19:01:11 INFO Received push request method=POST path=/api/pushes14592026/10/10 19:01:11 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14602026/10/10 19:01:11 INFO Uploading x5r184jhwgslyvmy4nkk03pmmw1c82h4-test-script (136B)1461 client_integration_test.go:358: Created store path 2: /private/var/tb/5/scratch/1572a97443ce2c80/build/TestClientMultipleUploads3456979323/001/store/b31gkm748fq0795bamlaydw3b6x7b6pn-test-file-2.txt14622026/10/10 19:01:11 WARN Failed to register uploaded object key=x5r184jhwgslyvmy4nkk03pmmw1c82h4.ls error="server returned 404: 404 page not found\n"14632026/10/10 19:01:11 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"14642026/10/10 19:01:11 WARN Failed to register uploaded object key=log/lh2rfpc7iq6s8xibk7p0mv47rkay4rs3-test-script.drv error="server returned 404: 404 page not found\n"14652026/10/10 19:01:11 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14662026/10/10 19:01:11 INFO Signed narinfos id=1 count=114672026/10/10 19:01:11 INFO Uploading 1 narinfos14682026/10/10 19:01:11 INFO Received complete push request method=POST path=/api/pushes/1/complete14692026/10/10 19:01:11 WARN Failed to register uploaded object key=x5r184jhwgslyvmy4nkk03pmmw1c82h4.narinfo error="server returned 404: 404 page not found\n"1470=== NAME TestClientIntegration1471 client_integration_test.go:286: Created store path: /private/var/tb/5/scratch/1572a97443ce2c80/build/TestClientIntegration2798216790/002/store/nclc6z3pb6cad9nrydsas20bqm7qfp9d-test-file.txt14722026/10/10 19:01:11 INFO Completed push id=1 objects=4 duration=15.190292ms14732026/10/10 19:01:11 INFO Upload complete. (203ms)1474=== NAME TestClientWithDependencies1475 client_integration_test.go:617: Skipping nix copy test - isolated store (/private/var/tb/5/scratch/1572a97443ce2c80/build/TestClientWithDependencies634974056/001/store) requires matching store prefix14762026/10/10 19:01:11 INFO Received push request method=POST path=/api/pushes14772026/10/10 19:01:11 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)14782026/10/10 19:01:11 INFO Uploading b31gkm748fq0795bamlaydw3b6x7b6pn-test-file-2.txt (160B)14792026/10/10 19:01:11 INFO Uploading 1yphpaxl5zkf9vg40n6hlmai16fz12ks-test-file-1.txt (160B)14802026/10/10 19:01:11 INFO Uploading 614gxpkx9c1wypfl9d66sdd1d0yfpms2-test-file-0.txt (160B)1481--- PASS: TestClientWithDependencies (8.77s)1482=== CONT TestService_AuthMiddleware_OIDC14832026/10/10 19:01:11 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14842026/10/10 19:01:11 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"14852026/10/10 19:01:11 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"14862026/10/10 19:01:11 WARN Failed to register uploaded object key=1yphpaxl5zkf9vg40n6hlmai16fz12ks.ls error="server returned 404: 404 page not found\n"14872026/10/10 19:01:11 WARN Failed to register uploaded object key=b31gkm748fq0795bamlaydw3b6x7b6pn.ls error="server returned 404: 404 page not found\n"14882026/10/10 19:01:11 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"14892026/10/10 19:01:11 WARN Failed to register uploaded object key=614gxpkx9c1wypfl9d66sdd1d0yfpms2.ls error="server returned 404: 404 page not found\n"14902026/10/10 19:01:11 INFO Received push request method=POST path=/api/pushes14912026/10/10 19:01:11 INFO Signed narinfos id=1 count=314922026/10/10 19:01:11 INFO Uploading 3 narinfos14932026/10/10 19:01:11 WARN Failed to register uploaded object key=614gxpkx9c1wypfl9d66sdd1d0yfpms2.narinfo error="server returned 404: 404 page not found\n"14942026/10/10 19:01:11 INFO Received complete push request method=POST path=/api/pushes/1/complete14952026/10/10 19:01:11 WARN Failed to register uploaded object key=b31gkm748fq0795bamlaydw3b6x7b6pn.narinfo error="server returned 404: 404 page not found\n"14962026/10/10 19:01:11 WARN Failed to register uploaded object key=1yphpaxl5zkf9vg40n6hlmai16fz12ks.narinfo error="server returned 404: 404 page not found\n"14972026/10/10 19:01:11 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14982026/10/10 19:01:11 INFO Uploading nclc6z3pb6cad9nrydsas20bqm7qfp9d-test-file.txt (152B)14992026/10/10 19:01:11 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:63352/oidc15002026/10/10 19:01:11 INFO Completed push id=1 objects=9 duration=17.309417ms15012026/10/10 19:01:11 INFO Upload complete. (171ms)1502=== NAME TestClientMultipleUploads1503 client_integration_test.go:369: Uploaded 3 paths in 207.5475ms15042026/10/10 19:01:11 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15052026/10/10 19:01:11 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"15062026/10/10 19:01:11 WARN Failed to register uploaded object key=nclc6z3pb6cad9nrydsas20bqm7qfp9d.ls error="server returned 404: 404 page not found\n"15072026/10/10 19:01:11 INFO Signed narinfos id=1 count=115082026/10/10 19:01:11 INFO Uploading 1 narinfos15092026/10/10 19:01:11 INFO Received complete push request method=POST path=/api/pushes/1/complete15102026/10/10 19:01:11 WARN Failed to register uploaded object key=nclc6z3pb6cad9nrydsas20bqm7qfp9d.narinfo error="server returned 404: 404 page not found\n"15112026/10/10 19:01:11 INFO Completed push id=1 objects=3 duration=18.012375ms15122026/10/10 19:01:11 INFO Upload complete. (181ms)1513--- PASS: TestClientMultipleUploads (8.66s)1514=== CONT TestCacheConfigHandler15152026/10/10 19:01:11 INFO All 1 paths already cached1516=== RUN TestCacheConfigHandler/full_config,_no_issuer1517=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1518=== RUN TestCacheConfigHandler/no_cache_url_configured1519=== NAME TestClientIntegration1520 client_integration_test.go:312: Retrieved narinfo from S3:1521 StorePath: /private/var/tb/5/scratch/1572a97443ce2c80/build/TestClientIntegration2798216790/002/store/nclc6z3pb6cad9nrydsas20bqm7qfp9d-test-file.txt1522 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1523 Compression: zstd1524 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11525 NarSize: 1521526 References: 1527 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11528=== PAUSE TestCacheConfigHandler/no_cache_url_configured1529=== RUN TestCacheConfigHandler/no_signing_keys1530=== PAUSE TestCacheConfigHandler/no_signing_keys1531=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1532=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1533=== CONT TestLeadIncumbentAnnouncesAtOnce1534=== NAME TestClientIntegration1535 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)1536 client_integration_test.go:313: Decompressed .ls content (64 bytes):1537 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1538 client_integration_test.go:316: Testing garbage collection...15392026/10/10 19:01:11 INFO Starting cleanup of old closures method=DELETE path=/api/closures15402026/10/10 19:01:11 INFO Garbage collection started15412026/10/10 19:01:11 INFO Aborted multipart uploads count=0 kept=015422026/10/10 19:01:11 WARN Force mode enabled - objects will be deleted immediately without grace period15432026/10/10 19:01:11 INFO Received push request method=POST path=/api/pushes1544=== NAME TestPinProtectsFromGC1545 client_integration_test.go:731: Pinned store path: /private/var/tb/5/scratch/1572a97443ce2c80/build/TestPinProtectsFromGC1222136920/001/store/93376bjf4xlgsmcayh1g2l5fq8md349c-pinned-file.txt1546 client_integration_test.go:732: Unpinned store path: /private/var/tb/5/scratch/1572a97443ce2c80/build/TestPinProtectsFromGC1222136920/001/store/x9i77j5c9h46ix1zh7ciyhiydkpcfycf-unpinned-file.txt15472026/10/10 19:01:11 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=015482026/10/10 19:01:11 INFO Received push request method=POST path=/api/pushes15492026/10/10 19:01:11 INFO Vacuumed table table=pending_closures15502026/10/10 19:01:11 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15512026/10/10 19:01:11 INFO Uploading 93376bjf4xlgsmcayh1g2l5fq8md349c-pinned-file.txt (128B)15522026-10-10 19:01:11.937 UTC [95630] ERROR: could not obtain lock on row in relation "closures"15532026-10-10 19:01:11.937 UTC [95630] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT15542026/10/10 19:01:11 INFO Vacuumed table table=pending_objects15552026-10-10 19:01:11.942 UTC [95630] ERROR: could not obtain lock on row in relation "closures"15562026-10-10 19:01:11.942 UTC [95630] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT15572026-10-10 19:01:11.944 UTC [95630] ERROR: could not obtain lock on row in relation "closures"15582026-10-10 19:01:11.944 UTC [95630] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT15592026/10/10 19:01:11 INFO Vacuumed table table=multipart_uploads15602026-10-10 19:01:11.952 UTC [95630] ERROR: could not obtain lock on row in relation "closures"15612026-10-10 19:01:11.952 UTC [95630] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT15622026-10-10 19:01:11.958 UTC [95630] ERROR: could not obtain lock on row in relation "closures"15632026-10-10 19:01:11.958 UTC [95630] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT15642026/10/10 19:01:11 WARN Failed to register uploaded object key=93376bjf4xlgsmcayh1g2l5fq8md349c.ls error="server returned 404: 404 page not found\n"15652026/10/10 19:01:11 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15662026/10/10 19:01:11 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"15672026/10/10 19:01:11 INFO Signed narinfos id=1 count=115682026/10/10 19:01:11 INFO Uploading 1 narinfos15692026/10/10 19:01:11 INFO Received complete push request method=POST path=/api/pushes/1/complete15702026/10/10 19:01:11 WARN Failed to register uploaded object key=93376bjf4xlgsmcayh1g2l5fq8md349c.narinfo error="server returned 404: 404 page not found\n"1571--- PASS: TestPush_RootsAreLockedInByteOrder (7.58s)1572=== CONT TestService_ReadScope_PublicByDefault15732026/10/10 19:01:12 INFO Vacuumed table table=closures15742026/10/10 19:01:12 INFO Completed push id=1 objects=3 duration=28.76375ms15752026/10/10 19:01:12 INFO Upload complete. (232ms)15762026/10/10 19:01:12 INFO Vacuumed table table=objects15772026/10/10 19:01:12 INFO Received push request method=POST path=/api/pushes15782026/10/10 19:01:12 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15792026/10/10 19:01:12 INFO Uploading x9i77j5c9h46ix1zh7ciyhiydkpcfycf-unpinned-file.txt (128B)15802026/10/10 19:01:12 WARN Failed to register uploaded object key=x9i77j5c9h46ix1zh7ciyhiydkpcfycf.ls error="server returned 404: 404 page not found\n"15812026/10/10 19:01:12 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign15822026/10/10 19:01:12 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"15832026/10/10 19:01:12 INFO Signed narinfos id=2 count=115842026/10/10 19:01:12 INFO Uploading 1 narinfos15852026/10/10 19:01:12 INFO Received complete push request method=POST path=/api/pushes/2/complete15862026/10/10 19:01:12 WARN Failed to register uploaded object key=x9i77j5c9h46ix1zh7ciyhiydkpcfycf.narinfo error="server returned 404: 404 page not found\n"15872026/10/10 19:01:12 INFO Completed push id=2 objects=3 duration=1.642083ms15882026/10/10 19:01:12 INFO Upload complete. (157ms)15892026/10/10 19:01:12 INFO Starting cleanup of old closures method=DELETE path=/api/closures15902026/10/10 19:01:12 INFO Garbage collection started15912026/10/10 19:01:12 INFO Aborted multipart uploads count=0 kept=015922026/10/10 19:01:12 WARN Force mode enabled - objects will be deleted immediately without grace period15932026/10/10 19:01:12 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=3 objects-failed-to-delete=015942026/10/10 19:01:12 INFO Vacuumed table table=pending_closures15952026/10/10 19:01:12 INFO Received push request method=POST path=/api/pushes15962026/10/10 19:01:12 INFO Vacuumed table table=pending_objects15972026/10/10 19:01:12 INFO Vacuumed table table=multipart_uploads15982026/10/10 19:01:12 INFO Vacuumed table table=closures15992026/10/10 19:01:12 INFO Vacuumed table table=objects16002026/10/10 19:01:12 INFO Received complete push request method=POST path=/api/pushes/1/complete16012026/10/10 19:01:12 INFO Completed push id=1 objects=6 duration=30.413958ms1602--- PASS: TestPush_CompleteCommitsEveryRoot (8.27s)1603=== CONT TestService_AuthMiddleware_MTLSBoundSubjects16042026/10/10 19:01:12 INFO Received push request method=POST path=/api/pushes16052026/10/10 19:01:12 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)16062026/10/10 19:01:12 INFO Uploading vlizkhkhzbr66jrbkzpm7jqzvfz5n12c-shared-dep (136B)16072026/10/10 19:01:12 INFO Uploading s5xmjj32flvabqsyh5v2jgk9lmqnjyrf-top (264B)16082026/10/10 19:01:12 WARN Failed to register uploaded object key=vlizkhkhzbr66jrbkzpm7jqzvfz5n12c.ls error="server returned 404: 404 page not found\n"16092026/10/10 19:01:12 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"16102026/10/10 19:01:12 WARN Failed to register uploaded object key=nar/1gkz101dr43iya6lmxdxrm3n8l6203rh4aj3f5qznf8553k1h94h.nar.zst error="server returned 404: 404 page not found\n"16112026/10/10 19:01:12 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16122026/10/10 19:01:12 WARN Failed to register uploaded object key=s5xmjj32flvabqsyh5v2jgk9lmqnjyrf.ls error="server returned 404: 404 page not found\n"16132026/10/10 19:01:12 INFO Signed narinfos id=1 count=216142026/10/10 19:01:12 INFO Uploading 2 narinfos16152026/10/10 19:01:12 INFO Received push request method=POST path=/api/pushes16162026/10/10 19:01:12 INFO Received complete push request method=POST path=/api/pushes/1/complete16172026/10/10 19:01:12 WARN Failed to register uploaded object key=vlizkhkhzbr66jrbkzpm7jqzvfz5n12c.narinfo error="server returned 404: 404 page not found\n"16182026/10/10 19:01:12 WARN Failed to register uploaded object key=s5xmjj32flvabqsyh5v2jgk9lmqnjyrf.narinfo error="server returned 404: 404 page not found\n"16192026/10/10 19:01:12 INFO Completed push id=1 objects=6 duration=31.663875ms16202026/10/10 19:01:12 INFO Upload complete. (229ms)1621=== NAME TestClientSharedPathCommittedMidPush1622 client_integration_test.go:680: Retrieved narinfo from S3:1623 StorePath: /private/var/tb/5/scratch/1572a97443ce2c80/build/TestClientSharedPathCommittedMidPush3105995638/001/store/vlizkhkhzbr66jrbkzpm7jqzvfz5n12c-shared-dep1624 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1625 Compression: zstd1626 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821627 NarSize: 1361628 References: 1629 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1630 client_integration_test.go:680: Retrieved narinfo from S3:1631 StorePath: /private/var/tb/5/scratch/1572a97443ce2c80/build/TestClientSharedPathCommittedMidPush3105995638/001/store/s5xmjj32flvabqsyh5v2jgk9lmqnjyrf-top1632 URL: nar/1gkz101dr43iya6lmxdxrm3n8l6203rh4aj3f5qznf8553k1h94h.nar.zst1633 Compression: zstd1634 NarHash: sha256:1gkz101dr43iya6lmxdxrm3n8l6203rh4aj3f5qznf8553k1h94h1635 NarSize: 2641636 References: /private/var/tb/5/scratch/1572a97443ce2c80/build/TestClientSharedPathCommittedMidPush3105995638/001/store/vlizkhkhzbr66jrbkzpm7jqzvfz5n12c-shared-dep1637 CA: text:sha256:0fjv2xdqg9xfzchh0mp8iq7hrdbfc6ni4nnp9siixfxh797lqxy21638--- PASS: TestClientSharedPathCommittedMidPush (8.80s)1639=== CONT TestParseSize1640--- PASS: TestParseSize (0.00s)1641=== CONT TestService_AuthMiddleware_MTLSProxyHeader16422026-10-10 19:01:13.280 UTC [95656] ERROR: Push does not exist: id=116432026-10-10 19:01:13.280 UTC [95656] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE16442026-10-10 19:01:13.280 UTC [95656] STATEMENT: SELECT commit_push($1)1645--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (8.45s)1646=== CONT TestPush_RejectsBadRequests1647--- PASS: TestCacheStatsHandler (7.77s)1648=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info16492026/10/10 19:01:13 INFO Received uploads request method=POST path=/1650=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key16512026/10/10 19:01:13 INFO Received complete multipart upload request method=POST path=/1652=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key16532026/10/10 19:01:13 INFO Received request for more parts method=POST path=/1654=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal16552026/10/10 19:01:13 INFO Received uploads request method=POST path=/1656--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1657 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1658 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.01s)1659 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1660 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1661=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1662=== CONT TestResolveDBConnectionString/flag_wins1663=== CONT TestResolveDBConnectionString/missing_file_is_an_error1664=== CONT TestResolveDBConnectionString/file_when_flag_empty1665=== CONT TestResolveDBConnectionString/nothing_configured1666=== CONT TestIsValidCachePath/narinfo1667=== CONT TestIsValidCachePath/leading_slash1668=== CONT TestIsValidCachePath/empty1669=== CONT TestIsValidCachePath/random_path1670--- PASS: TestResolveDBConnectionString (0.01s)1671 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1672 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1673 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1674 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)1675 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1676=== CONT TestIsValidCachePath/invalid_char_u1677=== CONT TestIsValidCachePath/invalid_char_e1678=== CONT TestIsValidCachePath/traversal_in_middle1679=== CONT TestIsValidCachePath/wrong_extension1680=== CONT TestIsValidCachePath/traversal_parent1681=== CONT TestIsValidCachePath/index.html1682=== CONT TestIsValidCachePath/nix-cache-info1683=== CONT TestIsValidCachePath/realisation1684=== CONT TestIsValidCachePath/log1685=== CONT TestIsValidCachePath/ls1686=== CONT TestIsValidCachePath/nar_uncompressed1687=== CONT TestIsValidCachePath/nar_bz21688=== CONT TestIsValidCachePath/nar_xz1689=== CONT TestIsValidCachePath/nar_zst1690=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1691=== CONT TestIsValidCachePath/short_hash1692--- PASS: TestIsValidCachePath (0.03s)1693 --- PASS: TestIsValidCachePath/narinfo (0.00s)1694 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1695 --- PASS: TestIsValidCachePath/empty (0.00s)1696 --- PASS: TestIsValidCachePath/random_path (0.00s)1697 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1698 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1699 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1700 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1701 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1702 --- PASS: TestIsValidCachePath/index.html (0.00s)1703 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1704 --- PASS: TestIsValidCachePath/realisation (0.00s)1705 --- PASS: TestIsValidCachePath/log (0.00s)1706 --- PASS: TestIsValidCachePath/ls (0.00s)1707 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1708 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1709 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1710 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1711 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1712 --- PASS: TestIsValidCachePath/short_hash (0.00s)1713=== CONT TestParseSingleRange/none1714=== CONT TestParseSingleRange/start_far_past_EOF1715=== CONT TestParseSingleRange/start_past_EOF1716=== CONT TestParseSingleRange/single_byte1717=== CONT TestParseSingleRange/suffix_exceeds_size1718=== CONT TestParseSingleRange/suffix1719=== CONT TestParseSingleRange/end_clamped_to_size1720=== CONT TestParseSingleRange/open-ended1721=== CONT TestParseSingleRange/closed1722=== CONT TestParseSingleRange/malformed_end_before_start1723=== CONT TestParseSingleRange/malformed_both_empty1724=== CONT TestParseSingleRange/malformed_no_dash1725=== CONT TestParseSingleRange/multi-range_ignored1726=== CONT TestParseSingleRange/unknown_unit1727--- PASS: TestParseSingleRange (0.00s)1728 --- PASS: TestParseSingleRange/none (0.00s)1729 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1730 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1731 --- PASS: TestParseSingleRange/single_byte (0.00s)1732 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1733 --- PASS: TestParseSingleRange/suffix (0.00s)1734 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1735 --- PASS: TestParseSingleRange/open-ended (0.00s)1736 --- PASS: TestParseSingleRange/closed (0.00s)1737 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1738 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1739 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1740 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1741 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1742=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale17432026/10/10 19:01:13 INFO Received push request method=POST path=/api/pushes17442026/10/10 19:01:13 INFO Received complete push request method=POST path=/api/pushes/1/complete17452026/10/10 19:01:13 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=01746=== NAME TestClientIntegration1747 client_integration_test.go:323: Objects in database after GC:1748 client_integration_test.go:323: Successfully deleted all objects with GC --force17492026/10/10 19:01:13 INFO Completed push id=1 objects=4 duration=30.389875ms1750--- PASS: TestPush_RepeatedRootCommitsOnce (8.21s)1751=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh1752--- PASS: TestDeleteClosuresRacingPins (13.19s)1753=== CONT TestServerTLSConfig/no_client_CA1754=== CONT TestServerTLSConfig/not_a_PEM_file1755=== CONT TestServerTLSConfig/missing_CA_file1756--- PASS: TestServerTLSConfig (0.00s)1757 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1758 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.01s)1759 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1760=== CONT TestGCEndsOnShutdown/before_the_run1761--- PASS: TestClientIntegration (10.32s)1762=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark17632026/10/10 19:01:14 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=017642026/10/10 19:01:14 INFO Received create pin request method=POST path=/api/pins/myapp17652026/10/10 19:01:14 INFO Received uploads request method=POST path=/api/pending_closures17662026/10/10 19:01:14 INFO Created/updated pin name=myapp store_path=/private/var/tb/5/scratch/1572a97443ce2c80/build/TestPinProtectsFromGC1222136920/001/store/93376bjf4xlgsmcayh1g2l5fq8md349c-pinned-file.txt narinfo_key=93376bjf4xlgsmcayh1g2l5fq8md349c.narinfo17672026/10/10 19:01:14 INFO Starting cleanup of old closures method=DELETE path=/api/closures17682026/10/10 19:01:14 INFO Garbage collection started17692026/10/10 19:01:14 INFO Aborted multipart uploads count=0 kept=017702026/10/10 19:01:14 WARN Force mode enabled - objects will be deleted immediately without grace period17712026/10/10 19:01:14 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=017722026/10/10 19:01:14 INFO Vacuumed table table=pending_closures17732026/10/10 19:01:14 INFO Vacuumed table table=pending_objects17742026/10/10 19:01:14 INFO Vacuumed table table=multipart_uploads17752026/10/10 19:01:14 INFO Vacuumed table table=closures17762026/10/10 19:01:14 INFO Vacuumed table table=objects1777=== NAME TestClientCADerivations1778 client_ca_test.go:136: Built CA derivation: /private/var/tb/5/scratch/1572a97443ce2c80/build/TestClientCADerivations3012764249/001/store/m1nxjlb1g9d65v4zwcma7s4g059i9sf6-ca-test17792026/10/10 19:01:14 INFO Received uploads request method=POST path=/api/pending_closures1780 client_ca_test.go:139: Found 1 dependencies (including self)17812026/10/10 19:01:14 INFO Received complete multipart upload request method=POST path=/api/multipart/complete17822026/10/10 19:01:14 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=OWUyNjU5MDktZTExOC00OTFmLWE1M2MtOTU1YTA4M2ZkOGIwLmRhZmEzMzljLTkzYmYtNDE2MC1hMTE4LWYxNmUwYWZiMDBmZngxNzkxNjU4ODc0NDAzMjY3MDAw17832026/10/10 19:01:14 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=OWUyNjU5MDktZTExOC00OTFmLWE1M2MtOTU1YTA4M2ZkOGIwLmRhZmEzMzljLTkzYmYtNDE2MC1hMTE4LWYxNmUwYWZiMDBmZngxNzkxNjU4ODc0NDAzMjY3MDAw parts=11784--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (7.82s)1785=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete17862026/10/10 19:01:14 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst17872026/10/10 19:01:14 INFO Received uploads request method=POST path=/api/pending_closures1788--- PASS: TestPresignedUploadRegisteredBeforeCommit (7.87s)1789=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows17902026/10/10 19:01:14 INFO Received push request method=POST path=/api/pushes17912026/10/10 19:01:15 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17922026/10/10 19:01:15 INFO Uploading m1nxjlb1g9d65v4zwcma7s4g059i9sf6-ca-test (144B)17932026/10/10 19:01:15 WARN Failed to register uploaded object key=m1nxjlb1g9d65v4zwcma7s4g059i9sf6.ls error="server returned 404: 404 page not found\n"17942026/10/10 19:01:15 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"17952026/10/10 19:01:15 WARN Failed to register uploaded object key=log/zrnn4c85sn7p8dvx4j9ly43hp5rh7hj5-ca-test.drv error="server returned 404: 404 page not found\n"17962026/10/10 19:01:15 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17972026/10/10 19:01:15 INFO Signed narinfos id=1 count=117982026/10/10 19:01:15 INFO Uploading 1 narinfos17992026/10/10 19:01:15 INFO Received complete push request method=POST path=/api/pushes/1/complete18002026/10/10 19:01:15 WARN Failed to register uploaded object key=m1nxjlb1g9d65v4zwcma7s4g059i9sf6.narinfo error="server returned 404: 404 page not found\n"18012026/10/10 19:01:15 INFO Received uploads request method=POST path=/api/pending_closures18022026/10/10 19:01:15 INFO Completed push id=1 objects=4 duration=36.670416ms18032026/10/10 19:01:15 INFO Upload complete. (376ms)1804=== NAME TestClientCADerivations1805 client_ca_test.go:180: Narinfo contains CA field: StorePath: /private/var/tb/5/scratch/1572a97443ce2c80/build/TestClientCADerivations3012764249/001/store/m1nxjlb1g9d65v4zwcma7s4g059i9sf6-ca-test1806 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1807 Compression: zstd1808 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1809 NarSize: 1441810 References: 1811 Deriver: /private/var/tb/5/scratch/1572a97443ce2c80/build/TestClientCADerivations3012764249/001/store/zrnn4c85sn7p8dvx4j9ly43hp5rh7hj5-ca-test.drv1812 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1813 client_ca_test.go:185: Checking for realisation files in S3...1814 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1815 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache1816 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket72?endpoint=http://localhost:63134®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/private/var/tb/5/scratch/1572a97443ce2c80/build/TestClientCADerivations3012764249/001/store'1817 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 11818--- PASS: TestClientCADerivations (9.61s)1819=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check18202026/10/10 19:01:15 INFO lead: acquired remote=192.0.2.1:123418212026/10/10 19:01:15 INFO Received complete multipart upload request method=POST path=/api/multipart/complete18222026/10/10 19:01:15 INFO Received uploads request method=POST path=/api/pending_closures1823{"timestamp":"2026-10-10T19:01:15.998355Z","level":"ERROR","message":"Scanner cycle completed without a durable data usage snapshot","event":"scanner_persist_state","component":"scanner","subsystem":"runtime","cycle":5,"outcome":"NoUpdate","state":"usage_not_durable","target":"rustfs::scanner","filename":"crates/scanner/src/scanner.rs","line_number":2350,"threadName":"rustfs-worker","threadId":"ThreadId(11)"}18242026/10/10 19:01:16 INFO Received push request method=POST path=/api/pushes1825=== NAME TestPinProtectsFromGC1826 client_integration_test.go:840: Pin successfully protected closure from garbage collection1827--- PASS: TestPinProtectsFromGC (12.78s)1828=== CONT TestProxyWriteTimeout/narinfo1829=== CONT TestProxyWriteTimeout/10_GiB_nar1830=== CONT TestProxyWriteTimeout/unknown_size1831=== CONT TestProxyWriteTimeout/1_GiB_nar1832--- PASS: TestProxyWriteTimeout (0.00s)1833 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1834 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1835 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1836 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1837=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure18382026/10/10 19:01:16 INFO Received uploads request method=POST path=/18392026/10/10 19:01:16 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18402026/10/10 19:01:16 INFO lead: released remote=192.0.2.1:12341841--- PASS: TestLeadEndsOnShutdown (8.62s)1842=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts18432026/10/10 19:01:16 INFO Signed narinfos id=1 count=118442026/10/10 19:01:16 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18452026/10/10 19:01:16 INFO Received request for more parts method=POST path=/18462026/10/10 19:01:16 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18472026/10/10 19:01:16 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"1848=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart18492026/10/10 19:01:16 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18502026/10/10 19:01:16 INFO Received complete multipart upload request method=POST path=/18512026/10/10 19:01:16 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"18522026/10/10 19:01:16 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18532026/10/10 19:01:16 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=118542026/10/10 19:01:16 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18552026/10/10 19:01:16 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo1856--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (8.23s)1857=== CONT TestIsValidUploadKey/narinfo1858=== CONT TestIsValidUploadKey/realisation_plus_in_output1859=== CONT TestIsValidUploadKey/unknown_type1860=== CONT TestIsValidUploadKey/empty_key1861=== CONT TestIsValidUploadKey/absolute1862=== CONT TestIsValidUploadKey/traversal_nar1863=== CONT TestIsValidUploadKey/traversal1864=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1865=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1866=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1867=== CONT TestIsValidUploadKey/nix-cache-info1868=== CONT TestIsValidUploadKey/build_log_home-manager_file1869=== CONT TestIsValidUploadKey/index.html1870=== CONT TestIsValidUploadKey/realisation1871=== CONT TestIsValidUploadKey/build_log_equals1872=== CONT TestIsValidUploadKey/build_log_question_mark1873=== CONT TestIsValidUploadKey/build_log_plus_in_name1874=== CONT TestIsValidUploadKey/nar_plain1875=== CONT TestIsValidUploadKey/build_log1876=== CONT TestIsValidUploadKey/listing1877=== CONT TestIsValidUploadKey/nar_xz1878=== CONT TestIsValidUploadKey/nar_zst1879--- PASS: TestIsValidUploadKey (0.02s)1880 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1881 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1882 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1883 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1884 --- PASS: TestIsValidUploadKey/absolute (0.00s)1885 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1886 --- PASS: TestIsValidUploadKey/traversal (0.00s)1887 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1888 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1889 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1890 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1891 --- PASS: TestIsValidUploadKey/index.html (0.00s)1892 --- PASS: TestIsValidUploadKey/realisation (0.00s)1893 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1894 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1895 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1896 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1897 --- PASS: TestIsValidUploadKey/build_log (0.00s)1898 --- PASS: TestIsValidUploadKey/listing (0.00s)1899 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1900 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1901 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1902=== CONT TestPendingClosureWriteTimeout/empty1903=== CONT TestPendingClosureWriteTimeout/670k_objects1904=== CONT TestPendingClosureWriteTimeout/400_objects1905=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1906=== CONT TestClientErrorHandling/InvalidStorePath1907--- PASS: TestUploadHandlersRejectOversizedBody (0.05s)1908 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.03s)1909 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.02s)1910 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.30s)1911=== CONT TestClientErrorHandling/ServerNotAvailable19122026/10/10 19:01:16 INFO Received uploads request method=POST path=/api/pending_closures19132026/10/10 19:01:17 INFO Received uploads request method=POST path=/api/pending_closures1914--- PASS: TestReadRedirectUsesPublicS3URL (7.10s)1915=== CONT TestClientErrorHandling/InvalidAuthToken19162026/10/10 19:01:17 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present19172026/10/10 19:01:17 WARN Request failed, retrying attempt=2 backoff=213.506309ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present19182026/10/10 19:01:17 WARN Request failed, retrying attempt=3 backoff=372.219978ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present19192026/10/10 19:01:17 INFO Received push request method=POST path=/api/pushes1920--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (7.70s)1921=== CONT TestCacheConfigHandler/full_config,_no_issuer1922=== CONT TestCacheConfigHandler/no_signing_keys1923=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1924=== CONT TestCacheConfigHandler/no_cache_url_configured1925--- PASS: TestCacheConfigHandler (0.01s)1926 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1927 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1928 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1929 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)19302026/10/10 19:01:17 WARN Request failed, retrying attempt=4 backoff=856.465286ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present1931--- PASS: TestReadProxyRangeRequest (7.73s)19322026/10/10 19:01:18 INFO Received complete multipart upload request method=POST path=/api/multipart/complete19332026/10/10 19:01:18 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=OWUyNjU5MDktZTExOC00OTFmLWE1M2MtOTU1YTA4M2ZkOGIwLjFmYjU0ZmQ2LWM0YzEtNDYzNi05YzAxLWUzYzI1NzM3Y2U0Y3gxNzkxNjU4ODc1OTg1OTgzMDAw parts=1219342026/10/10 19:01:18 INFO Received uploads request method=POST path=/api/pending_closures1935--- PASS: TestCompletedNarNotReofferedAcrossClosures (10.86s)1936=== RUN TestService_RequireScope_OIDC/builder_may_write1937=== PAUSE TestService_RequireScope_OIDC/builder_may_write1938=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1939=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1940=== RUN TestService_RequireScope_OIDC/ops_may_admin1941=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1942=== RUN TestService_RequireScope_OIDC/ops_may_not_write1943=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1944=== RUN TestService_RequireScope_OIDC/reader_may_not_write1945=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1946=== RUN TestService_RequireScope_OIDC/static_token_may_admin1947=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1948=== RUN TestService_RequireScope_OIDC/static_token_may_write1949=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1950=== RUN TestService_RequireScope_OIDC/reader_may_read1951=== PAUSE TestService_RequireScope_OIDC/reader_may_read1952=== RUN TestService_RequireScope_OIDC/writer_implies_read1953=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1954=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1955=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read19562026/10/10 19:01:18 WARN Request failed, retrying attempt=5 backoff=1.621834879s error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present1957=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1958=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc1959=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1960=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1961=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1962=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1963=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1964=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1965=== CONT TestService_RequireScope_OIDC/builder_may_write1966=== CONT TestService_RequireScope_OIDC/reader_may_read1967=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1968=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1969=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc1970=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read19712026/10/10 19:01:18 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]1972=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read1973=== CONT TestService_RequireScope_OIDC/writer_implies_read1974=== CONT TestService_RequireScope_OIDC/reader_may_not_write1975=== CONT TestService_RequireScope_OIDC/static_token_may_write1976=== CONT TestService_RequireScope_OIDC/static_token_may_admin1977=== CONT TestService_RequireScope_OIDC/ops_may_admin1978=== CONT TestService_RequireScope_OIDC/builder_may_not_admin1979=== CONT TestService_RequireScope_OIDC/ops_may_not_write1980--- PASS: TestService_RequireScope_OIDC (7.82s)1981 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)1982 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)1983 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)1984 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)1985 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)1986 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)1987 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)1988 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)1989 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)1990 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)1991 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)1992 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)1993 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)1994 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)1995--- PASS: TestService_ReadAuthMiddleware (8.05s)19962026-10-10 19:01:19.490 UTC [95018] LOG: checkpoint starting: wal19972026/10/10 19:01:19 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1998=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1999=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token2000=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2001=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2002=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected2003=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected2004=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2005=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2006=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2007=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2008=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected20092026/10/10 19:01:19 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]2010=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected20112026/10/10 19:01:19 WARN Authentication failed token_preview=eyJhbGciOi...fbGgSIW-mw token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2012--- PASS: TestService_AuthMiddleware_OIDC (8.24s)2013 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2014 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2015 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2016 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.01s)20172026/10/10 19:01:19 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=OWUyNjU5MDktZTExOC00OTFmLWE1M2MtOTU1YTA4M2ZkOGIwLjcxMDY0ZWFlLTlkMDItNGNhYy1hNzA0LTI0YmMyMzc0NmQyZngxNzkxNjU4ODc2OTYyMzA5MDAw parts=1220182026/10/10 19:01:19 INFO Received uploads request method=POST path=/api/pending_closures20192026/10/10 19:01:19 WARN Rate limiter enabled after throttle name=s3-test rate=520202026/10/10 19:01:19 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."2021=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle2022 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=102023 throttle_test.go:215: Rate limiter: enabled=true, rate=5.002024--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (13.02s)20252026/10/10 19:01:19 INFO Received uploads request method=POST path=/api/pending_closures20262026/10/10 19:01:20 INFO lead: acquired remote=192.0.2.1:123420272026/10/10 19:01:20 INFO lead: released remote=192.0.2.1:12342028--- PASS: TestLeadIncumbentAnnouncesAtOnce (8.46s)2029--- PASS: TestService_ReadScope_PublicByDefault (8.41s)20302026/10/10 19:01:20 WARN Request failed, retrying attempt=1 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20312026/10/10 19:01:20 WARN Request failed, retrying attempt=2 backoff=189.220414ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20322026/10/10 19:01:20 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"20332026/10/10 19:01:20 WARN mTLS auth: bound subjects configured but subject DN unavailable20342026/10/10 19:01:20 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"2035--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (8.04s)20362026/10/10 19:01:20 WARN Request failed, retrying attempt=3 backoff=414.609861ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2037--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (7.87s)2038=== RUN TestPush_RejectsBadRequests/no_roots2039=== PAUSE TestPush_RejectsBadRequests/no_roots2040=== RUN TestPush_RejectsBadRequests/no_objects2041=== PAUSE TestPush_RejectsBadRequests/no_objects2042=== RUN TestPush_RejectsBadRequests/bad_root2043=== PAUSE TestPush_RejectsBadRequests/bad_root2044=== RUN TestPush_RejectsBadRequests/root_not_in_objects2045=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects2046=== CONT TestPush_RejectsBadRequests/no_roots2047=== CONT TestPush_RejectsBadRequests/bad_root2048=== CONT TestPush_RejectsBadRequests/no_objects2049=== CONT TestPush_RejectsBadRequests/root_not_in_objects20502026/10/10 19:01:21 INFO Received push request method=POST path=/api/pushes20512026/10/10 19:01:21 INFO Received push request method=POST path=/api/pushes20522026/10/10 19:01:21 INFO Received push request method=POST path=/api/pushes20532026/10/10 19:01:21 INFO Received push request method=POST path=/api/pushes2054--- PASS: TestPush_RejectsBadRequests (7.87s)2055 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)2056 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)2057 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)2058 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)20592026/10/10 19:01:21 WARN Request failed, retrying attempt=4 backoff=790.503481ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20602026/10/10 19:01:21 INFO Received complete multipart upload request method=POST path=/api/multipart/complete20612026/10/10 19:01:21 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=OWUyNjU5MDktZTExOC00OTFmLWE1M2MtOTU1YTA4M2ZkOGIwLjZkZjJhODVjLWI5MWEtNDIxYy1iNWZlLWVjMGE4MGI4MjUxZXgxNzkxNjU4ODc5ODkwNTEzMDAw error="Get \"http://127.0.0.1:1/bucket79/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"20622026/10/10 19:01:21 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=OWUyNjU5MDktZTExOC00OTFmLWE1M2MtOTU1YTA4M2ZkOGIwLjQwMzNhYjU3LTljNjgtNDlmMC04NzE1LTRlZDA3ZmQ5YmM5MngxNzkxNjU4ODc5ODM1NDg3MDAw parts=1220632026/10/10 19:01:21 INFO Received cleanup request method=DELETE path=/api/pending_closures20642026/10/10 19:01:21 INFO Aborted multipart uploads count=1 kept=02065--- PASS: TestRedundantMultipartUpload (12.63s)20662026/10/10 19:01:21 INFO Aborted multipart uploads count=0 kept=020672026/10/10 19:01:21 WARN Force mode enabled - objects will be deleted immediately without grace period20682026-10-10 19:01:21.644 UTC [95972] ERROR: canceling statement due to user request20692026-10-10 19:01:21.644 UTC [95972] STATEMENT: -- name: MarkStaleObjects :execrows2070 WITH RECURSIVE ct AS (2071 SELECT timezone('UTC', now()) AS now2072 ),2073 closure_reach AS (2074 -- Start with all closure keys2075 SELECT o.key, o.refs2076 FROM objects o2077 INNER JOIN closures c ON o.key = c.key2078 UNION2079 -- Recursively add all referenced objects2080 SELECT o.key, o.refs2081 FROM objects o2082 INNER JOIN closure_reach cr ON o.key = ANY(cr.refs)2083 ),2084 reachable_objects AS (2085 SELECT DISTINCT key FROM closure_reach2086 ),2087 stale_objects AS (2088 SELECT o.key2089 FROM objects AS o, ct2090 WHERE2091 NOT EXISTS (2092 SELECT 12093 FROM reachable_objects ro2094 WHERE ro.key = o.key2095 )2096 AND NOT EXISTS (2097 SELECT 12098 FROM pending_objects AS po2099 WHERE po.key = o.key2100 )2101 AND o.deleted_at IS NULL -- Only mark fresh objects2102 ORDER BY o.key COLLATE "C" -- lock in key order, like commit_pending_closure2103 FOR UPDATE2104 )2105 UPDATE objects2106 SET2107 deleted_at = ct.now,2108 first_deleted_at = COALESCE(first_deleted_at, ct.now)2109 FROM stale_objects, ct2110 WHERE objects.key = stale_objects.key2111 21122026/10/10 19:01:22 WARN Request failed, retrying attempt=5 backoff=1.586403303s error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21132026/10/10 19:01:22 INFO Aborted multipart uploads count=0 kept=021142026/10/10 19:01:22 WARN Force mode enabled - objects will be deleted immediately without grace period21152026/10/10 19:01:22 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:63134/bucket95/?delete=\": context canceled"2116--- PASS: TestGCEndsOnShutdown (0.00s)2117 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (7.88s)2118 --- PASS: TestGCEndsOnShutdown/before_the_run (8.15s)2119 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (7.34s)2120--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2121 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (8.49s)2122 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (8.51s)21232026/10/10 19:01:22 INFO Received uploads request method=POST path=/api/pending_closures21242026/10/10 19:01:22 INFO Aborted multipart uploads count=0 kept=021252026/10/10 19:01:22 WARN Force mode enabled - objects will be deleted immediately without grace period21262026/10/10 19:01:22 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=021272026/10/10 19:01:22 INFO Vacuumed table table=pending_closures21282026/10/10 19:01:22 INFO Vacuumed table table=pending_objects21292026/10/10 19:01:22 INFO Vacuumed table table=multipart_uploads21302026/10/10 19:01:22 INFO Vacuumed table table=closures21312026/10/10 19:01:22 INFO Vacuumed table table=objects21322026/10/10 19:01:22 INFO Received uploads request method=POST path=/api/pending_closures21332026/10/10 19:01:22 INFO Aborted multipart uploads count=0 kept=021342026/10/10 19:01:22 WARN Force mode enabled - objects will be deleted immediately without grace period21352026/10/10 19:01:22 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=021362026/10/10 19:01:22 INFO Vacuumed table table=pending_closures21372026/10/10 19:01:22 INFO Vacuumed table table=pending_objects21382026/10/10 19:01:22 INFO Vacuumed table table=multipart_uploads21392026/10/10 19:01:22 INFO Vacuumed table table=closures21402026/10/10 19:01:22 INFO Vacuumed table table=objects2141--- PASS: TestForceGCDuringPushOffersSweptObject (0.01s)2142 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (7.60s)2143 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (7.27s)21442026/10/10 19:01:22 INFO Received uploads request method=POST path=/api/pending_closures21452026/10/10 19:01:23 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"21462026/10/10 19:01:23 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"2147--- PASS: TestPendingClosureWriteTimeout (0.00s)2148 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2149 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2150 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2151 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (6.93s)21522026/10/10 19:01:23 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: sending request: request failed after retries: Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused"21532026/10/10 19:01:23 WARN Request failed, retrying attempt=1 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21542026/10/10 19:01:23 WARN Request failed, retrying attempt=2 backoff=206.991358ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21552026/10/10 19:01:23 WARN Request failed, retrying attempt=3 backoff=364.174479ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21562026/10/10 19:01:24 WARN Request failed, retrying attempt=4 backoff=791.3898ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21572026/10/10 19:01:25 WARN Request failed, retrying attempt=5 backoff=1.73339242s error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2158{"timestamp":"2026-10-10T19:01:26.449931Z","level":"ERROR","message":"Scanner cycle completed without a durable data usage snapshot","event":"scanner_persist_state","component":"scanner","subsystem":"runtime","cycle":5,"outcome":"NoUpdate","state":"usage_not_durable","target":"rustfs::scanner","filename":"crates/scanner/src/scanner.rs","line_number":2350,"threadName":"rustfs-worker","threadId":"ThreadId(4)"}21592026/10/10 19:01:26 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21602026/10/10 19:01:26 WARN Request failed, retrying attempt=2 backoff=201.715314ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21612026/10/10 19:01:27 WARN Request failed, retrying attempt=3 backoff=430.445104ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21622026/10/10 19:01:27 WARN Request failed, retrying attempt=4 backoff=866.577808ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21632026/10/10 19:01:28 WARN Request failed, retrying attempt=5 backoff=1.704745742s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2164--- PASS: TestClientErrorHandling (0.00s)2165 --- PASS: TestClientErrorHandling/InvalidStorePath (6.39s)2166 --- PASS: TestClientErrorHandling/InvalidAuthToken (6.16s)2167 --- PASS: TestClientErrorHandling/ServerNotAvailable (13.45s)2168PASS21692026-10-10 19:01:30.361 UTC [95013] LOG: received smart shutdown request21702026-10-10 19:01:30.363 UTC [95013] LOG: background worker "logical replication launcher" (PID 95023) exited with exit code 121712026-10-10 19:01:31.968 UTC [95018] LOG: checkpoint complete: wrote 10454 buffers (63.8%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 33 recycled; write=11.489 s, sync=0.887 s, total=12.479 s; sync files=34045, longest=0.012 s, average=0.001 s; distance=532989 kB, estimate=532989 kB; lsn=0/227EF000, redo lsn=0/2200C63021722026-10-10 19:01:31.968 UTC [95018] LOG: shutting down21732026-10-10 19:01:31.969 UTC [95018] LOG: checkpoint starting: shutdown immediate21742026-10-10 19:01:32.028 UTC [95018] LOG: checkpoint complete: wrote 1241 buffers (7.6%), wrote 1 SLRU buffers; 0 WAL file(s) added, 0 removed, 0 recycled; write=0.050 s, sync=0.009 s, total=0.060 s; sync files=440, longest=0.001 s, average=0.001 s; distance=8074 kB, estimate=480498 kB; lsn=0/227EF078, redo lsn=0/227EF07821752026-10-10 19:01:32.039 UTC [95013] LOG: database system is shut down2176Running OIDC tests...2177=== RUN TestAudienceForIssuer2178=== PAUSE TestAudienceForIssuer2179=== RUN TestGlobMatch2180=== PAUSE TestGlobMatch2181=== RUN TestValidateToken_ValidToken2182=== PAUSE TestValidateToken_ValidToken2183=== RUN TestValidateToken_WrongAudience2184=== PAUSE TestValidateToken_WrongAudience2185=== RUN TestValidateToken_Expired2186=== PAUSE TestValidateToken_Expired2187=== RUN TestValidateToken_BoundClaimsMismatch2188=== PAUSE TestValidateToken_BoundClaimsMismatch2189=== RUN TestValidateToken_BoundSubjectMismatch2190=== PAUSE TestValidateToken_BoundSubjectMismatch2191=== RUN TestValidateToken_MultipleProviders2192=== PAUSE TestValidateToken_MultipleProviders2193=== RUN TestValidateToken_NoMatchingProvider2194=== PAUSE TestValidateToken_NoMatchingProvider2195=== RUN TestValidateToken_KubernetesServiceAccount2196=== PAUSE TestValidateToken_KubernetesServiceAccount2197=== RUN TestNewValidator_KubernetesRequiresCA2198=== PAUSE TestNewValidator_KubernetesRequiresCA2199=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2200=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2201=== RUN TestPins_ReservedForMatchingRule2202=== PAUSE TestPins_ReservedForMatchingRule2203=== RUN TestPins_TopLevelShorthand2204=== PAUSE TestPins_TopLevelShorthand2205=== RUN TestPins_ConfigValidation2206=== PAUSE TestPins_ConfigValidation2207=== RUN TestScopes_LegacyProviderDefaultsToWrite2208=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2209=== RUN TestScopes_Rules2210=== PAUSE TestScopes_Rules2211=== RUN TestScopes_ConfigValidation2212=== PAUSE TestScopes_ConfigValidation2213=== CONT TestAudienceForIssuer2214--- PASS: TestAudienceForIssuer (0.00s)2215=== CONT TestPins_ConfigValidation2216=== CONT TestScopes_Rules2217=== CONT TestValidateToken_NoMatchingProvider2218=== CONT TestValidateToken_MultipleProviders2219=== CONT TestValidateToken_BoundSubjectMismatch2220=== CONT TestValidateToken_BoundClaimsMismatch2221=== CONT TestValidateToken_Expired2222=== CONT TestValidateToken_WrongAudience2223=== CONT TestValidateToken_ValidToken2224--- PASS: TestPins_ConfigValidation (0.01s)2225=== CONT TestGlobMatch2226=== RUN TestGlobMatch/foo_foo2227=== PAUSE TestGlobMatch/foo_foo2228=== RUN TestGlobMatch/foo_bar2229=== PAUSE TestGlobMatch/foo_bar2230=== RUN TestGlobMatch/*_2231=== PAUSE TestGlobMatch/*_2232=== RUN TestGlobMatch/*_anything2233=== PAUSE TestGlobMatch/*_anything2234=== RUN TestGlobMatch/foo*_foo2235=== PAUSE TestGlobMatch/foo*_foo2236=== RUN TestGlobMatch/foo*_foobar2237=== PAUSE TestGlobMatch/foo*_foobar2238=== RUN TestGlobMatch/foo*_bar2239=== PAUSE TestGlobMatch/foo*_bar2240=== RUN TestGlobMatch/*bar_bar2241=== PAUSE TestGlobMatch/*bar_bar2242=== RUN TestGlobMatch/*bar_foobar2243=== PAUSE TestGlobMatch/*bar_foobar2244=== RUN TestGlobMatch/*bar_foo2245=== PAUSE TestGlobMatch/*bar_foo2246=== RUN TestGlobMatch/foo*bar_foobar2247=== PAUSE TestGlobMatch/foo*bar_foobar2248=== RUN TestGlobMatch/foo*bar_foo123bar2249=== PAUSE TestGlobMatch/foo*bar_foo123bar2250=== RUN TestGlobMatch/foo*bar_foobarbaz2251=== PAUSE TestGlobMatch/foo*bar_foobarbaz2252=== RUN TestGlobMatch/*/*_foo/bar2253=== PAUSE TestGlobMatch/*/*_foo/bar2254=== RUN TestGlobMatch/*/*_foo2255=== PAUSE TestGlobMatch/*/*_foo2256=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2257=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2258=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02259=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02260=== RUN TestGlobMatch/refs/*/main_refs/heads/main2261=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2262=== RUN TestGlobMatch/fo?_foo2263=== PAUSE TestGlobMatch/fo?_foo2264=== RUN TestGlobMatch/fo?_fo2265=== PAUSE TestGlobMatch/fo?_fo2266=== RUN TestGlobMatch/fo?_fooo2267=== PAUSE TestGlobMatch/fo?_fooo2268=== RUN TestGlobMatch/?oo_foo2269=== PAUSE TestGlobMatch/?oo_foo2270=== RUN TestGlobMatch/?oo_boo2271=== PAUSE TestGlobMatch/?oo_boo2272=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2273=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2274=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2275=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2276=== CONT TestGlobMatch/foo_foo2277=== CONT TestScopes_LegacyProviderDefaultsToWrite2278=== CONT TestGlobMatch/*/*_foo/bar2279=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2280=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2281=== CONT TestGlobMatch/?oo_boo2282=== CONT TestGlobMatch/?oo_foo2283=== CONT TestGlobMatch/fo?_fooo2284=== CONT TestGlobMatch/fo?_fo2285=== CONT TestGlobMatch/fo?_foo2286=== CONT TestGlobMatch/refs/*/main_refs/heads/main2287=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02288=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2289=== CONT TestGlobMatch/*/*_foo2290=== CONT TestGlobMatch/*bar_bar2291=== CONT TestGlobMatch/foo*bar_foobarbaz2292=== CONT TestGlobMatch/foo*bar_foo123bar2293=== CONT TestGlobMatch/foo*bar_foobar2294=== CONT TestGlobMatch/*bar_foo2295=== CONT TestGlobMatch/*bar_foobar2296=== CONT TestGlobMatch/foo*_foo2297=== CONT TestGlobMatch/foo*_bar2298=== CONT TestGlobMatch/foo*_foobar2299=== CONT TestGlobMatch/*_2300=== CONT TestGlobMatch/*_anything2301=== CONT TestGlobMatch/foo_bar2302--- PASS: TestGlobMatch (0.00s)2303 --- PASS: TestGlobMatch/foo_foo (0.00s)2304 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2305 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2306 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2307 --- PASS: TestGlobMatch/?oo_boo (0.00s)2308 --- PASS: TestGlobMatch/?oo_foo (0.00s)2309 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2310 --- PASS: TestGlobMatch/fo?_fo (0.00s)2311 --- PASS: TestGlobMatch/fo?_foo (0.00s)2312 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2313 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2314 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2315 --- PASS: TestGlobMatch/*/*_foo (0.00s)2316 --- PASS: TestGlobMatch/*bar_bar (0.00s)2317 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2318 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2319 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2320 --- PASS: TestGlobMatch/*bar_foo (0.00s)2321 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2322 --- PASS: TestGlobMatch/foo*_foo (0.00s)2323 --- PASS: TestGlobMatch/foo*_bar (0.00s)2324 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2325 --- PASS: TestGlobMatch/*_ (0.00s)2326 --- PASS: TestGlobMatch/*_anything (0.00s)2327 --- PASS: TestGlobMatch/foo_bar (0.00s)2328=== CONT TestPins_ReservedForMatchingRule2329=== CONT TestPins_TopLevelShorthand2330=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2331=== CONT TestNewValidator_KubernetesRequiresCA2332=== CONT TestScopes_ConfigValidation2333=== CONT TestValidateToken_KubernetesServiceAccount2334--- PASS: TestScopes_ConfigValidation (0.00s)23352026/10/10 19:01:34 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:63499/oidc23362026/10/10 19:01:34 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:63501/oidc2337--- PASS: TestPins_TopLevelShorthand (0.03s)2338--- PASS: TestValidateToken_BoundClaimsMismatch (0.06s)23392026/10/10 19:01:34 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:63503/oidc2340--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.12s)23412026/10/10 19:01:34 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:63508/oidc23422026/10/10 19:01:34 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:63506/oidc2343--- PASS: TestValidateToken_Expired (0.14s)23442026/10/10 19:01:34 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:63505/oidc2345--- PASS: TestScopes_Rules (0.18s)23462026/10/10 19:01:34 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:63511/oidc23472026/10/10 19:01:34 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:63514/oidc2348--- PASS: TestValidateToken_MultipleProviders (0.20s)2349--- PASS: TestPins_ReservedForMatchingRule (0.19s)23502026/10/10 19:01:34 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC12323512026/10/10 19:01:34 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:6351623522026/10/10 19:01:34 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:63520/oidc2353--- PASS: TestValidateToken_KubernetesServiceAccount (0.26s)2354--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.27s)2355--- PASS: TestValidateToken_ValidToken (0.29s)23562026/10/10 19:01:34 http: TLS handshake error from 127.0.0.1:63523: read tcp 127.0.0.1:63521->127.0.0.1:63523: use of closed network connection2357--- PASS: TestNewValidator_KubernetesRequiresCA (0.28s)23582026/10/10 19:01:34 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:63525/oidc2359--- PASS: TestValidateToken_WrongAudience (0.32s)23602026/10/10 19:01:34 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:63528/oidc2361--- PASS: TestValidateToken_BoundSubjectMismatch (0.32s)23622026/10/10 19:01:34 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:63510/oidc2363--- PASS: TestValidateToken_NoMatchingProvider (0.43s)2364PASS2365Running hook tests...2366=== RUN TestSendPathsEmpty2367=== PAUSE TestSendPathsEmpty2368=== RUN TestQueueEnqueueAndFetch2369=== PAUSE TestQueueEnqueueAndFetch2370=== RUN TestQueueDeduplication2371=== PAUSE TestQueueDeduplication2372=== RUN TestQueueRemove2373=== PAUSE TestQueueRemove2374=== RUN TestQueueFetchBatchLimit2375=== PAUSE TestQueueFetchBatchLimit2376=== RUN TestQueueRetryMovesToBack2377=== PAUSE TestQueueRetryMovesToBack2378=== RUN TestQueueFetchRemoveLifecycle2379=== PAUSE TestQueueFetchRemoveLifecycle2380=== RUN TestQueueConcurrentWriters2381=== PAUSE TestQueueConcurrentWriters2382=== RUN TestQueueRemoveLargeClosure2383=== PAUSE TestQueueRemoveLargeClosure2384=== RUN TestServerClientIntegration2385--- PASS: TestServerClientIntegration (0.00s)2386=== RUN TestServerQueueError23872026/10/10 19:01:34 ERROR Failed to queue paths error="permission denied" count=12388--- PASS: TestServerQueueError (0.00s)2389=== RUN TestGetListenerSocketActivation2390 server_test.go:146: systemd socket activation does not exist on darwin2391--- SKIP: TestGetListenerSocketActivation (0.00s)2392=== RUN TestDrainIsolatesPoisonPath2393=== PAUSE TestDrainIsolatesPoisonPath2394=== RUN TestRunNotBlockedByPoisonHead2395=== PAUSE TestRunNotBlockedByPoisonHead2396=== RUN TestDrainGivesUpWhenServerDown2397=== PAUSE TestDrainGivesUpWhenServerDown2398=== RUN TestFailedPathPrunedByLaterClosure2399=== PAUSE TestFailedPathPrunedByLaterClosure2400=== RUN TestWorkerUploadsAndRemoves2401=== PAUSE TestWorkerUploadsAndRemoves2402=== RUN TestWorkerSkipsGCdPaths2403=== PAUSE TestWorkerSkipsGCdPaths2404=== RUN TestWorkerPrunesClosureDeps2405=== PAUSE TestWorkerPrunesClosureDeps2406=== RUN TestDrainTimeout2407=== PAUSE TestDrainTimeout2408=== CONT TestSendPathsEmpty2409=== CONT TestDrainIsolatesPoisonPath2410--- PASS: TestSendPathsEmpty (0.00s)2411=== CONT TestQueueRemoveLargeClosure2412=== CONT TestQueueConcurrentWriters2413=== CONT TestQueueFetchRemoveLifecycle2414=== CONT TestQueueRetryMovesToBack2415=== CONT TestQueueFetchBatchLimit2416=== CONT TestQueueRemove2417=== CONT TestQueueDeduplication2418=== CONT TestQueueEnqueueAndFetch2419=== CONT TestWorkerUploadsAndRemoves2420=== CONT TestDrainTimeout2421=== CONT TestWorkerPrunesClosureDeps2422=== CONT TestWorkerSkipsGCdPaths2423=== CONT TestRunNotBlockedByPoisonHead2424=== CONT TestFailedPathPrunedByLaterClosure2425=== CONT TestDrainGivesUpWhenServerDown24262026/10/10 19:01:34 INFO Uploading batch count=224272026/10/10 19:01:34 INFO Upload queue status pending=224282026/10/10 19:01:34 INFO Uploading batch count=22429--- PASS: TestQueueRemove (0.01s)24302026/10/10 19:01:34 INFO Uploading batch count=124312026/10/10 19:01:34 ERROR Upload failed error="upload failed" count=124322026/10/10 19:01:34 INFO Upload queue status pending=324332026/10/10 19:01:34 INFO Uploading batch count=124342026/10/10 19:01:34 ERROR Upload failed error="upload failed" count=124352026/10/10 19:01:34 INFO Upload queue status pending=224362026/10/10 19:01:34 INFO Uploading batch count=12437--- PASS: TestQueueRetryMovesToBack (0.01s)24382026/10/10 19:01:34 INFO Uploading batch count=124392026/10/10 19:01:34 INFO Uploading batch count=424402026/10/10 19:01:34 ERROR Upload failed error="upload failed" count=42441--- PASS: TestQueueDeduplication (0.01s)24422026/10/10 19:01:34 INFO Upload queue status pending=224432026/10/10 19:01:34 INFO Uploading batch count=124442026/10/10 19:01:34 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/5/scratch/1572a97443ce2c80/build/TestWorkerSkipsGCdPaths3178352017/002/nonexistent24452026/10/10 19:01:34 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/5/scratch/1572a97443ce2c80/build/TestDrainIsolatesPoisonPath3657544051/002/bbb24462026/10/10 19:01:34 INFO Uploading batch count=124472026/10/10 19:01:34 INFO Uploading batch count=224482026/10/10 19:01:34 ERROR Upload failed error="upload failed" count=22449--- PASS: TestQueueFetchRemoveLifecycle (0.01s)24502026/10/10 19:01:34 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/5/scratch/1572a97443ce2c80/build/TestDrainGivesUpWhenServerDown3378914288/002/a2451--- PASS: TestQueueEnqueueAndFetch (0.01s)24522026/10/10 19:01:34 INFO Uploading batch count=124532026/10/10 19:01:34 ERROR Upload failed error="upload failed" count=124542026/10/10 19:01:34 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/5/scratch/1572a97443ce2c80/build/TestDrainGivesUpWhenServerDown3378914288/002/b2455--- PASS: TestQueueFetchBatchLimit (0.01s)24562026/10/10 19:01:34 INFO Uploading batch count=124572026/10/10 19:01:34 ERROR Upload failed error="upload failed" count=124582026/10/10 19:01:34 INFO Uploading batch count=224592026/10/10 19:01:34 ERROR Upload failed error="upload failed" count=224602026/10/10 19:01:34 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/5/scratch/1572a97443ce2c80/build/TestDrainGivesUpWhenServerDown3378914288/002/c24612026/10/10 19:01:34 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/5/scratch/1572a97443ce2c80/build/TestDrainGivesUpWhenServerDown3378914288/002/d24622026/10/10 19:01:34 INFO Uploading batch count=124632026/10/10 19:01:34 ERROR Upload failed error="upload failed" count=124642026/10/10 19:01:34 INFO Uploading batch count=224652026/10/10 19:01:34 ERROR Upload failed error="upload failed" count=224662026/10/10 19:01:34 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/5/scratch/1572a97443ce2c80/build/TestDrainGivesUpWhenServerDown3378914288/002/e24672026/10/10 19:01:34 ERROR Drain finished with paths left in queue remaining=124682026/10/10 19:01:34 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/5/scratch/1572a97443ce2c80/build/TestDrainGivesUpWhenServerDown3378914288/002/f2469--- PASS: TestFailedPathPrunedByLaterClosure (0.01s)24702026/10/10 19:01:34 ERROR Drain finished with paths left in queue remaining=102471--- PASS: TestDrainIsolatesPoisonPath (0.02s)2472--- PASS: TestDrainGivesUpWhenServerDown (0.02s)2473--- PASS: TestWorkerUploadsAndRemoves (0.03s)2474--- PASS: TestWorkerPrunesClosureDeps (0.03s)2475--- PASS: TestWorkerSkipsGCdPaths (0.03s)2476--- PASS: TestQueueRemoveLargeClosure (0.04s)2477--- PASS: TestQueueConcurrentWriters (0.13s)24782026/10/10 19:01:34 ERROR Upload failed error="context deadline exceeded" count=224792026/10/10 19:01:34 ERROR Drain finished with paths left in queue remaining=42480--- PASS: TestDrainTimeout (0.21s)24812026/10/10 19:01:35 INFO Uploading batch count=124822026/10/10 19:01:35 INFO Uploading batch count=124832026/10/10 19:01:35 INFO Uploading batch count=124842026/10/10 19:01:35 ERROR Upload failed error="upload failed" count=124852026/10/10 19:01:35 INFO Uploading batch count=124862026/10/10 19:01:35 ERROR Upload failed error="upload failed" count=124872026/10/10 19:01:35 INFO Uploading batch count=124882026/10/10 19:01:35 ERROR Upload failed error="upload failed" count=124892026/10/10 19:01:35 INFO Uploading batch count=124902026/10/10 19:01:35 ERROR Upload failed error="upload failed" count=124912026/10/10 19:01:35 ERROR Drain finished with paths left in queue remaining=12492--- PASS: TestRunNotBlockedByPoisonHead (1.02s)2493PASS2494Running signing tests...2495=== RUN TestExternalSigner2496=== PAUSE TestExternalSigner2497=== RUN TestExternalSignerWrongPublicKey2498=== PAUSE TestExternalSignerWrongPublicKey2499=== RUN TestExternalSignerErrors2500=== PAUSE TestExternalSignerErrors2501=== RUN TestExternalSignerRestartsAfterCrash2502=== PAUSE TestExternalSignerRestartsAfterCrash2503=== RUN TestExternalSignerProgramErrorKeepsProcess2504=== PAUSE TestExternalSignerProgramErrorKeepsProcess2505=== RUN TestExternalSignerClose2506=== PAUSE TestExternalSignerClose2507=== RUN TestExternalSignerRejectsInvalidPublicKey2508=== PAUSE TestExternalSignerRejectsInvalidPublicKey2509=== RUN TestExternalSignerCancellation2510=== PAUSE TestExternalSignerCancellation2511=== RUN TestGenerateFingerprint2512=== PAUSE TestGenerateFingerprint2513=== RUN TestParseSigningKey2514=== PAUSE TestParseSigningKey2515=== RUN TestSign2516=== PAUSE TestSign2517=== RUN TestSignBatch2518=== PAUSE TestSignBatch2519=== RUN TestNilKeyPublicKey2520=== PAUSE TestNilKeyPublicKey2521=== RUN TestSignErrors2522=== PAUSE TestSignErrors2523=== CONT TestExternalSigner2524=== CONT TestSignBatch2525=== CONT TestExternalSignerErrors2526=== RUN TestExternalSignerErrors/invalid_JSON2527=== CONT TestNilKeyPublicKey2528=== PAUSE TestExternalSignerErrors/invalid_JSON2529--- PASS: TestNilKeyPublicKey (0.00s)2530=== CONT TestParseSigningKey2531=== RUN TestParseSigningKey/valid_32-byte_key2532=== RUN TestExternalSignerErrors/unrequested_key2533=== PAUSE TestExternalSignerErrors/unrequested_key2534=== RUN TestExternalSignerErrors/missing_signature_name2535=== PAUSE TestExternalSignerErrors/missing_signature_name2536=== RUN TestExternalSignerErrors/exit_at_startup2537=== PAUSE TestExternalSignerErrors/exit_at_startup2538=== RUN TestExternalSignerErrors/missing_signatures2539=== PAUSE TestExternalSignerErrors/missing_signatures2540=== RUN TestExternalSignerErrors/too_few_signatures2541=== PAUSE TestExternalSignerErrors/too_few_signatures2542=== RUN TestExternalSignerErrors/invalid_signature_base642543=== PAUSE TestExternalSignerErrors/invalid_signature_base642544=== RUN TestExternalSignerErrors/wrong_signature_length2545=== PAUSE TestExternalSignerErrors/wrong_signature_length2546=== RUN TestExternalSignerErrors/null2547=== PAUSE TestExternalSignerErrors/null2548=== RUN TestExternalSignerErrors/wrong_signature_name2549=== PAUSE TestExternalSignerErrors/wrong_signature_name2550=== RUN TestExternalSignerErrors/program_error2551=== CONT TestExternalSignerCancellation2552=== CONT TestSign2553=== CONT TestExternalSignerProgramErrorKeepsProcess2554=== CONT TestExternalSignerRejectsInvalidPublicKey2555=== RUN TestExternalSignerRejectsInvalidPublicKey/#002556=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002557=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2558=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2559=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2560=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2561=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2562=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2563=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2564=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2565=== CONT TestExternalSignerClose2566=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2567=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2568=== CONT TestExternalSignerRestartsAfterCrash2569=== CONT TestExternalSignerWrongPublicKey2570=== CONT TestGenerateFingerprint2571=== RUN TestGenerateFingerprint/basic_with_references2572=== PAUSE TestParseSigningKey/valid_32-byte_key2573=== CONT TestSignErrors2574=== CONT TestExternalSignerRejectsInvalidPublicKey/#002575=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2576=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2577--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2578 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2579 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2580 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2581 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2582 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2583=== PAUSE TestGenerateFingerprint/basic_with_references2584=== RUN TestGenerateFingerprint/no_references2585=== PAUSE TestGenerateFingerprint/no_references2586=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2587=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2588=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2589=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2590=== RUN TestGenerateFingerprint/invalid_nar_hash_length2591=== PAUSE TestExternalSignerErrors/program_error2592=== RUN TestExternalSignerErrors/exit_on_request2593=== PAUSE TestExternalSignerErrors/exit_on_request2594=== RUN TestExternalSignerErrors/wrong_shape2595=== PAUSE TestExternalSignerErrors/wrong_shape2596=== RUN TestExternalSignerErrors/wrong_id2597=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2598=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2599=== RUN TestParseSigningKey/no_colon2600=== PAUSE TestParseSigningKey/no_colon2601=== RUN TestParseSigningKey/empty_name2602=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2603=== PAUSE TestExternalSignerErrors/wrong_id2604=== RUN TestExternalSignerErrors/null_signatures2605=== PAUSE TestParseSigningKey/empty_name2606=== RUN TestParseSigningKey/invalid_base642607=== PAUSE TestParseSigningKey/invalid_base642608=== RUN TestParseSigningKey/wrong_length2609=== PAUSE TestParseSigningKey/wrong_length2610=== CONT TestParseSigningKey/valid_32-byte_key2611=== RUN TestGenerateFingerprint/invalid_store_path_prefix2612=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2613=== RUN TestGenerateFingerprint/invalid_reference_prefix2614=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2615=== CONT TestGenerateFingerprint/basic_with_references2616=== CONT TestParseSigningKey/wrong_length2617=== CONT TestParseSigningKey/invalid_base642618=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2619=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2620=== CONT TestGenerateFingerprint/invalid_reference_prefix2621=== CONT TestParseSigningKey/empty_name2622=== CONT TestParseSigningKey/no_colon2623=== CONT TestGenerateFingerprint/invalid_store_path_prefix2624=== CONT TestGenerateFingerprint/invalid_nar_hash_length2625=== PAUSE TestExternalSignerErrors/null_signatures2626=== RUN TestExternalSignerErrors/wrong_signatures_shape2627=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2628=== CONT TestExternalSignerErrors/invalid_JSON2629=== CONT TestExternalSignerErrors/wrong_signature_name2630=== CONT TestExternalSignerErrors/too_few_signatures2631=== CONT TestExternalSignerErrors/exit_at_startup2632=== CONT TestGenerateFingerprint/no_references2633=== CONT TestExternalSignerErrors/missing_signatures2634=== CONT TestExternalSignerErrors/unrequested_key2635=== CONT TestExternalSignerErrors/wrong_id2636--- PASS: TestSign (0.00s)2637=== CONT TestExternalSignerErrors/wrong_signature_length2638--- PASS: TestSignBatch (0.00s)2639=== CONT TestExternalSignerErrors/wrong_signatures_shape2640=== RUN TestSignErrors/nil_key2641=== PAUSE TestSignErrors/nil_key2642=== RUN TestSignErrors/nil_narinfo2643=== PAUSE TestSignErrors/nil_narinfo2644=== RUN TestSignErrors/invalid_narinfo2645=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2646=== CONT TestExternalSignerErrors/missing_signature_name2647=== CONT TestExternalSignerErrors/exit_on_request2648=== CONT TestExternalSignerErrors/wrong_shape2649=== CONT TestExternalSignerErrors/null2650=== CONT TestExternalSignerErrors/program_error2651=== CONT TestExternalSignerErrors/null_signatures2652=== PAUSE TestSignErrors/invalid_narinfo2653=== RUN TestSignErrors/canceled2654=== PAUSE TestSignErrors/canceled2655=== CONT TestSignErrors/nil_key2656=== CONT TestSignErrors/canceled2657=== CONT TestSignErrors/invalid_narinfo2658=== CONT TestSignErrors/nil_narinfo2659--- PASS: TestParseSigningKey (0.00s)2660 --- PASS: TestParseSigningKey/wrong_length (0.00s)2661 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2662 --- PASS: TestParseSigningKey/empty_name (0.00s)2663 --- PASS: TestParseSigningKey/no_colon (0.00s)2664 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2665 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2666=== CONT TestExternalSignerErrors/invalid_signature_base642667--- PASS: TestGenerateFingerprint (0.00s)2668 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2669 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2670 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2671 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2672 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2673 --- PASS: TestGenerateFingerprint/no_references (0.00s)2674 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2675--- PASS: TestSignErrors (0.00s)2676 --- PASS: TestSignErrors/nil_key (0.00s)2677 --- PASS: TestSignErrors/canceled (0.00s)2678 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2679 --- PASS: TestSignErrors/nil_narinfo (0.00s)2680--- PASS: TestExternalSigner (0.22s)2681--- PASS: TestExternalSignerProgramErrorKeepsProcess (0.59s)2682--- PASS: TestExternalSignerCancellation (1.38s)2683--- PASS: TestExternalSignerWrongPublicKey (1.54s)2684--- PASS: TestExternalSignerRestartsAfterCrash (1.75s)2685/private/var/tb/5/scratch/1572a97443ce2c80/build/TestExternalSignerRestartsAfterCrash1602966066/001/sign program: line 7: /private/var/tb/5/scratch/1572a97443ce2c80/build/TestExternalSignerRestartsAfterCrash1602966066/001/sign program.starts: No such file or directory2686--- PASS: TestExternalSignerClose (2.29s)2687--- PASS: TestExternalSignerErrors (0.00s)2688 --- PASS: TestExternalSignerErrors/too_few_signatures (0.39s)2689 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (0.78s)2690 --- PASS: TestExternalSignerErrors/wrong_signature_length (0.97s)2691 --- PASS: TestExternalSignerErrors/invalid_JSON (1.16s)2692 --- PASS: TestExternalSignerErrors/exit_at_startup (1.92s)2693 --- PASS: TestExternalSignerErrors/missing_signatures (2.10s)2694 --- PASS: TestExternalSignerErrors/wrong_signature_name (2.49s)2695 --- PASS: TestExternalSignerErrors/program_error (2.68s)2696 --- PASS: TestExternalSignerErrors/unrequested_key (2.87s)2697 --- PASS: TestExternalSignerErrors/wrong_shape (3.06s)2698 --- PASS: TestExternalSignerErrors/null_signatures (3.27s)2699 --- PASS: TestExternalSignerErrors/exit_on_request (3.46s)2700 --- PASS: TestExternalSignerErrors/missing_signature_name (3.67s)2701 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (3.86s)2702 --- PASS: TestExternalSignerErrors/wrong_id (4.05s)2703 --- PASS: TestExternalSignerErrors/null (4.24s)2704PASS2705Running OpenBao signer tests...2706=== RUN TestSign2707=== PAUSE TestSign2708=== RUN TestSignErrors2709=== PAUSE TestSignErrors2710=== RUN TestServe2711=== PAUSE TestServe2712=== RUN TestServeRejectsGarbage2713=== PAUSE TestServeRejectsGarbage2714=== CONT TestSign2715=== CONT TestServeRejectsGarbage2716=== CONT TestSignErrors2717=== CONT TestServe2718=== RUN TestSignErrors/invalid_json2719--- PASS: TestServeRejectsGarbage (0.00s)2720=== PAUSE TestSignErrors/invalid_json2721=== RUN TestSignErrors/no_prefix2722=== PAUSE TestSignErrors/no_prefix2723=== RUN TestSignErrors/invalid_base642724=== PAUSE TestSignErrors/invalid_base642725=== RUN TestSignErrors/http_error2726=== PAUSE TestSignErrors/http_error2727=== CONT TestSignErrors/invalid_json2728=== CONT TestSignErrors/invalid_base642729=== CONT TestSignErrors/no_prefix2730--- PASS: TestServe (0.00s)2731=== CONT TestSignErrors/http_error2732--- PASS: TestSignErrors (0.00s)2733 --- PASS: TestSignErrors/invalid_json (0.00s)2734 --- PASS: TestSignErrors/invalid_base64 (0.00s)2735 --- PASS: TestSignErrors/http_error (0.00s)2736 --- PASS: TestSignErrors/no_prefix (0.00s)2737--- PASS: TestSign (0.00s)2738PASS