niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #472
· raw
1tribuchet: building on mac022Running client tests...3=== RUN TestDoServerRequestAttachesToken4=== PAUSE TestDoServerRequestAttachesToken5=== RUN TestUploadBuildLog_FileBodyReplayedOnRetry6=== PAUSE TestUploadBuildLog_FileBodyReplayedOnRetry7=== RUN TestRegisterUploadedObjectReusesConnections8=== PAUSE TestRegisterUploadedObjectReusesConnections9=== RUN TestRunGarbageCollection_FinishedOnAnotherReplica10=== PAUSE TestRunGarbageCollection_FinishedOnAnotherReplica11=== RUN TestRunGarbageCollection_NotFoundAfterLocalRun12=== PAUSE TestRunGarbageCollection_NotFoundAfterLocalRun13=== RUN TestCaseHackSuffix14=== PAUSE TestCaseHackSuffix15=== RUN TestFilterOversizedClosures16=== PAUSE TestFilterOversizedClosures17=== RUN TestUploadMultipart_PartsInParallel18=== PAUSE TestUploadMultipart_PartsInParallel19=== RUN TestUploadMultipart_ReturnsAfterDroppedBody20=== PAUSE TestUploadMultipart_ReturnsAfterDroppedBody21=== RUN TestPartSizeForNAR22=== PAUSE TestPartSizeForNAR23=== RUN TestDumpPathCaseHackMatchesNix24--- PASS: TestDumpPathCaseHackMatchesNix (0.09s)25=== RUN TestDumpPathCaseHackCollision26--- PASS: TestDumpPathCaseHackCollision (0.00s)27=== 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 TestRegisterUploadedObject_BoundedAgainstSilentServer54=== PAUSE TestRegisterUploadedObject_BoundedAgainstSilentServer55=== RUN TestRegisterUploadedObject_OutlivesPush56=== PAUSE TestRegisterUploadedObject_OutlivesPush57=== RUN TestResolveStorePath58=== PAUSE TestResolveStorePath59=== RUN TestDoWithRetry_BodyReplayedViaGetBody60=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody61=== RUN TestRetryTimeoutOutlastsMaxRetries62=== PAUSE TestRetryTimeoutOutlastsMaxRetries63=== RUN TestDoWithRetry_FinalResponseBodyReadable64=== PAUSE TestDoWithRetry_FinalResponseBodyReadable65=== RUN TestShellSplit66=== PAUSE TestShellSplit67=== RUN TestShellSplitErrors68=== PAUSE TestShellSplitErrors69=== RUN TestStreamPushReportsEveryPath70=== PAUSE TestStreamPushReportsEveryPath71=== RUN TestStreamPushBatchesUnderLoad72=== PAUSE TestStreamPushBatchesUnderLoad73=== RUN TestStreamPushIsolatesFailures74=== PAUSE TestStreamPushIsolatesFailures75=== RUN TestStreamPushGivesUpOnDeadServer76=== PAUSE TestStreamPushGivesUpOnDeadServer77=== RUN TestStreamPushRequestLine78=== PAUSE TestStreamPushRequestLine79=== RUN TestStreamPushReportsSignatures80=== PAUSE TestStreamPushReportsSignatures81=== RUN TestStreamPushReportsSkippedPaths82=== PAUSE TestStreamPushReportsSkippedPaths83=== RUN TestClientSignaturesByStorePath84=== PAUSE TestClientSignaturesByStorePath85=== RUN TestStreamPushStopsWhenCanceled86=== PAUSE TestStreamPushStopsWhenCanceled87=== RUN TestSetClientTLS88=== PAUSE TestSetClientTLS89=== RUN TestSetClientTLSDoesNotMutateDefaultTransport90=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport91=== RUN TestSetClientTLSErrors92=== PAUSE TestSetClientTLSErrors93=== RUN TestStaticToken94=== PAUSE TestStaticToken95=== RUN TestFileTokenReadsAndCaches96=== PAUSE TestFileTokenReadsAndCaches97=== RUN TestFileTokenMissing98=== PAUSE TestFileTokenMissing99=== RUN TestFileTokenEmpty100=== PAUSE TestFileTokenEmpty101=== RUN TestScriptTokenNoExpiryRerunsEveryCall102=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall103=== RUN TestScriptTokenCachesUntilRefresh104=== PAUSE TestScriptTokenCachesUntilRefresh105=== RUN TestScriptTokenEmptyToken106=== PAUSE TestScriptTokenEmptyToken107=== RUN TestScriptTokenBadJSON108=== PAUSE TestScriptTokenBadJSON109=== RUN TestScriptTokenScriptFails110=== PAUSE TestScriptTokenScriptFails111=== RUN TestScriptTokenEmptyCommand112=== PAUSE TestScriptTokenEmptyCommand113=== CONT TestDoServerRequestAttachesToken114=== CONT TestRetryTimeoutOutlastsMaxRetries115=== CONT TestEncodeNixBase32116=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun117=== CONT TestEncodeNixBase32WithRealHash118=== RUN TestEncodeNixBase32/test_string_hash119--- PASS: TestEncodeNixBase32WithRealHash (0.00s)120=== PAUSE TestEncodeNixBase32/test_string_hash121=== CONT TestResolveStorePath122=== RUN TestEncodeNixBase32/empty_input123=== PAUSE TestEncodeNixBase32/empty_input124=== CONT TestFilterOversizedClosures125=== RUN TestFilterOversizedClosures/no_limit_keeps_everything126=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything127=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped128=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped129=== RUN TestFilterOversizedClosures/all_closures_skipped130=== PAUSE TestFilterOversizedClosures/all_closures_skipped131=== CONT TestCaseHackSuffix132=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica133=== CONT TestRegisterUploadedObject_OutlivesPush134=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer135=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess136=== CONT TestRateLimiterFeedback137=== CONT TestPathInfoCACompatibility138=== CONT TestParsePathInfoJSONMultiplePaths139=== CONT TestParsePathInfoJSON140=== CONT TestPathInfoHashCompatibility141=== CONT TestGetStorePathHash142=== CONT TestConvertHashToNix32143=== CONT TestUploadMultipart_PartsInParallel144=== CONT TestDumpPathWriterError145=== CONT TestDumpPathSingleFile146=== CONT TestDumpPathMatchesNix147=== CONT TestPartSizeForNAR148=== CONT TestUploadMultipart_ReturnsAfterDroppedBody149=== CONT TestRegisterUploadedObjectReusesConnections150=== CONT TestDoWithRetry_BodyReplayedViaGetBody151=== RUN TestRateLimiterFeedback/429_enables_limiter1522026/11/09 12:01:10 WARN Rate limiter enabled after throttle name=server-test rate=5153=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)154=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)155=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon156=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon157=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI158=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI159=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512160=== RUN TestPartSizeForNAR/zero_stays_at_minimum161=== CONT TestStreamPushGivesUpOnDeadServer162=== PAUSE TestRateLimiterFeedback/429_enables_limiter1632026/11/09 12:01:10 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:65428/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:65428/api/uploads/complete1642026/11/09 12:01:10 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"1652026/11/09 12:01:10 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:65428/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:65428/api/uploads/complete1662026/11/09 12:01:10 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"167=== RUN TestRateLimiterFeedback/503_enables_limiter168=== PAUSE TestRateLimiterFeedback/503_enables_limiter169=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter170=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter171=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter172=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter173=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512174=== RUN TestPathInfoCACompatibility/null_ca_field175=== PAUSE TestPathInfoCACompatibility/null_ca_field176=== RUN TestPathInfoCACompatibility/old_string_format_-_text177=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text178=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive179=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive180=== RUN TestPathInfoCACompatibility/new_structured_format_-_text181=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text182=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method183=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method184=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum185=== RUN TestPartSizeForNAR/small_stays_at_minimum186=== PAUSE TestPartSizeForNAR/small_stays_at_minimum187=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum188=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum189=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts190=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts191=== RUN TestPartSizeForNAR/1_TiB192=== PAUSE TestPartSizeForNAR/1_TiB193=== RUN TestPartSizeForNAR/5_TiB_S3_max_object194=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object195=== RUN TestPartSizeForNAR/capped_at_5_GiB196=== PAUSE TestPartSizeForNAR/capped_at_5_GiB197=== CONT TestStreamPushStopsWhenCanceled198--- PASS: TestStreamPushStopsWhenCanceled (0.00s)199=== CONT TestStreamPushRequestLine200=== CONT TestClientSignaturesByStorePath201--- PASS: TestClientSignaturesByStorePath (0.00s)202=== CONT TestStreamPushReportsEveryPath2032026/11/09 12:01:10 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:65428/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:65428/api/uploads/complete2042026/11/09 12:01:10 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"2052026/11/09 12:01:10 ERROR Upload failed error="connection refused" count=202062026/11/09 12:01:10 ERROR Server seems unavailable, giving up on batch untried=172072026/11/09 12:01:10 ERROR Upload failed error=boom count=1208--- PASS: TestResolveStorePath (0.00s)209--- PASS: TestStreamPushGivesUpOnDeadServer (0.15s)210=== RUN TestGetStorePathHash/valid_store_path211=== RUN TestConvertHashToNix32/SRI_format_to_Nix32212=== RUN TestParsePathInfoJSON/Nix_format213=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths214=== CONT TestStreamPushReportsSkippedPaths215=== CONT TestStreamPushReportsSignatures216=== CONT TestStreamPushIsolatesFailures217=== CONT TestStreamPushBatchesUnderLoad218=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=false219=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=false220=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=true221=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=true222--- PASS: TestStreamPushReportsEveryPath (0.00s)223=== PAUSE TestGetStorePathHash/valid_store_path224=== RUN TestGetStorePathHash/basename_without_hyphen_should_error225=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error226=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error227=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error228=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error229=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error230=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32231=== RUN TestConvertHashToNix32/already_Nix32_format232=== PAUSE TestConvertHashToNix32/already_Nix32_format233=== RUN TestConvertHashToNix32/invalid_format234=== PAUSE TestConvertHashToNix32/invalid_format235=== PAUSE TestParsePathInfoJSON/Nix_format236=== RUN TestParsePathInfoJSON/Lix_format237=== PAUSE TestParsePathInfoJSON/Lix_format238=== RUN TestParsePathInfoJSON/empty_input239=== PAUSE TestParsePathInfoJSON/empty_input240=== RUN TestParsePathInfoJSON/whitespace_only241=== PAUSE TestParsePathInfoJSON/whitespace_only242=== RUN TestParsePathInfoJSON/invalid_JSON243=== PAUSE TestParsePathInfoJSON/invalid_JSON244=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths245=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths246=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths247--- PASS: TestStreamPushReportsSkippedPaths (0.00s)248=== CONT TestScriptTokenEmptyCommand249--- PASS: TestScriptTokenEmptyCommand (0.00s)250=== CONT TestScriptTokenScriptFails251=== CONT TestDoWithRetry_FinalResponseBodyReadable2522026/11/09 12:01:10 ERROR Upload failed error="bad path" count=32532026/11/09 12:01:10 ERROR Upload failed error=boom count=1254=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry255=== CONT TestScriptTokenEmptyToken256=== CONT TestScriptTokenNoExpiryRerunsEveryCall257=== CONT TestShellSplit258=== CONT TestScriptTokenCachesUntilRefresh259=== CONT TestShellSplitErrors260--- PASS: TestStreamPushIsolatesFailures (0.00s)261=== CONT TestScriptTokenBadJSON262--- PASS: TestShellSplitErrors (0.00s)263=== CONT TestFileTokenReadsAndCaches264--- PASS: TestStreamPushReportsSignatures (0.01s)265--- PASS: TestShellSplit (0.00s)266--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (0.22s)267=== CONT TestFileTokenEmpty2682026/11/09 12:01:10 INFO Garbage collection started269--- PASS: TestFileTokenEmpty (0.00s)2702026/11/09 12:01:10 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:654252712026/11/09 12:01:10 INFO Garbage collection started2722026/11/09 12:01:10 WARN Rate limiter enabled after throttle name=server-test rate=52732026/11/09 12:01:10 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:65435274--- PASS: TestDoServerRequestAttachesToken (0.23s)275=== CONT TestSetClientTLSErrors276=== CONT TestStaticToken277=== CONT TestFileTokenMissing278--- PASS: TestRegisterUploadedObject_OutlivesPush (0.22s)279=== CONT TestSetClientTLSDoesNotMutateDefaultTransport2802026/11/09 12:01:10 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:65425281--- PASS: TestStaticToken (0.00s)282--- PASS: TestScriptTokenEmptyToken (0.10s)283--- PASS: TestFileTokenMissing (0.01s)284--- PASS: TestFileTokenReadsAndCaches (0.09s)285--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.28s)286=== CONT TestEncodeNixBase32/empty_input287=== CONT TestFilterOversizedClosures/all_closures_skipped2882026/11/09 12:01:10 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=50289=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped290=== CONT TestFilterOversizedClosures/no_limit_keeps_everything2912026/11/09 12:01:10 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=2000292=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)2932026/11/09 12:01:10 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=0294--- PASS: TestScriptTokenScriptFails (0.19s)295=== CONT TestPathInfoCACompatibility/null_ca_field296--- PASS: TestFilterOversizedClosures (0.00s)297 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.01s)298 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)299 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)300=== CONT TestSetClientTLS301=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter3022026/11/09 12:01:10 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:65425303=== CONT TestPartSizeForNAR/zero_stays_at_minimum304=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter305--- PASS: TestUploadMultipart_ReturnsAfterDroppedBody (0.37s)306=== CONT TestRateLimiterFeedback/429_enables_limiter307=== CONT TestEncodeNixBase32/test_string_hash308--- PASS: TestEncodeNixBase32 (0.00s)309 --- PASS: TestEncodeNixBase32/empty_input (0.00s)310 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)3112026/11/09 12:01:10 WARN Rate limiter enabled after throttle name=server-test rate=53122026/11/09 12:01:10 WARN Rate limiter backed off name=server-test rate=53132026/11/09 12:01:10 WARN Request returned retryable status, retrying attempt=2 backoff=0s status=503 url=http://127.0.0.1:654353142026/11/09 12:01:10 WARN Rate limiter enabled after throttle name=s3-test rate=53152026/11/09 12:01:10 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:654993162026/11/09 12:01:10 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:65505317=== CONT TestRateLimiterFeedback/503_enables_limiter318=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512319--- PASS: TestStreamPushRequestLine (0.25s)320=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI321=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon322=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method323=== CONT TestPathInfoCACompatibility/new_structured_format_-_text324=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive325=== CONT TestPathInfoCACompatibility/old_string_format_-_text3262026/11/09 12:01:10 WARN Rate limiter backed off name=server-test rate=5327--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.24s)328=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts329=== RUN TestSetClientTLSErrors/missing_cert_file330=== CONT TestPartSizeForNAR/capped_at_5_GiB331--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.40s)332=== CONT TestPartSizeForNAR/5_TiB_S3_max_object3332026/11/09 12:01:10 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:65425334=== CONT TestPartSizeForNAR/1_TiB335=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum336=== CONT TestPartSizeForNAR/small_stays_at_minimum337=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=false338--- PASS: TestPartSizeForNAR (0.15s)339 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)340 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)341 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)342 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)343 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)344 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)345 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)346=== PAUSE TestSetClientTLSErrors/missing_cert_file347=== RUN TestSetClientTLSErrors/missing_key_file348=== PAUSE TestSetClientTLSErrors/missing_key_file349=== RUN TestSetClientTLSErrors/missing_ca_file350=== PAUSE TestSetClientTLSErrors/missing_ca_file351=== RUN TestSetClientTLSErrors/invalid_ca_file352=== PAUSE TestSetClientTLSErrors/invalid_ca_file353=== CONT TestGetStorePathHash/valid_store_path354=== CONT TestConvertHashToNix32/SRI_format_to_Nix32355=== CONT TestParsePathInfoJSON/Nix_format3562026/11/09 12:01:10 WARN Rate limiter enabled after throttle name=server-test rate=53572026/11/09 12:01:10 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=429 url=http://127.0.0.1:65517358=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths359=== CONT TestConvertHashToNix32/already_Nix32_format360=== CONT TestParsePathInfoJSON/whitespace_only361=== CONT TestParsePathInfoJSON/Lix_format362=== CONT TestConvertHashToNix32/invalid_format363=== CONT TestParsePathInfoJSON/empty_input364=== CONT TestParsePathInfoJSON/invalid_JSON365=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths366=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error367=== CONT TestGetStorePathHash/basename_without_hyphen_should_error368=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error369--- PASS: TestGetStorePathHash (0.15s)370 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)371 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)372 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)373 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)374=== CONT TestSetClientTLSErrors/missing_cert_file375=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=true3762026/11/09 12:01:10 WARN Rate limiter enabled after throttle name=server-test rate=53772026/11/09 12:01:10 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:65520378=== CONT TestSetClientTLSErrors/invalid_ca_file3792026/11/09 12:01:10 WARN Rate limiter backed off name=server-test rate=53802026/11/09 12:01:10 WARN Rate limiter backed off name=server-test rate=5381=== CONT TestSetClientTLSErrors/missing_key_file382=== CONT TestSetClientTLSErrors/missing_ca_file383--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.13s)384--- PASS: TestPathInfoHashCompatibility (0.14s)385 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.03s)386 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.01s)387 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)388 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.01s)389--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.23s)390--- PASS: TestParsePathInfoJSON (0.15s)391 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)392 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)393 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)394 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)395 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)396--- PASS: TestPathInfoCACompatibility (0.14s)397 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)398 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)399 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)400 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)401 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.02s)402--- PASS: TestStreamPushBatchesUnderLoad (0.00s)403 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=false (0.00s)404 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=true (0.01s)4052026/11/09 12:01:10 WARN Request returned retryable status, retrying attempt=3 backoff=1ms status=502 url=http://127.0.0.1:65425406--- PASS: TestConvertHashToNix32 (0.15s)407 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)408 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)409 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)410--- PASS: TestParsePathInfoJSONMultiplePaths (0.15s)411 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)412 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.01s)4132026/11/09 12:01:10 WARN Garbage collection finished on another replica. Its statistics are not available here414--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.42s)415--- PASS: TestRateLimiterFeedback (0.11s)416 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.03s)417 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.03s)418 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.02s)419 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.03s)420=== RUN TestSetClientTLS/rejects_connection_without_client_cert421=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert422=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA423=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA424=== RUN TestSetClientTLS/preserves_debug_logging_transport425=== PAUSE TestSetClientTLS/preserves_debug_logging_transport426=== CONT TestSetClientTLS/rejects_connection_without_client_cert427=== CONT TestSetClientTLS/preserves_debug_logging_transport428=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA429--- PASS: TestSetClientTLSErrors (0.14s)430 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)431 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.01s)432 --- PASS: TestSetClientTLSErrors/missing_key_file (0.01s)433 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.03s)4342026/11/09 12:01:10 WARN Request returned retryable status, retrying attempt=4 backoff=1ms status=502 url=http://127.0.0.1:654254352026/11/09 12:01:10 WARN Request returned retryable status, retrying attempt=5 backoff=1ms status=502 url=http://127.0.0.1:654254362026/11/09 12:01:10 WARN Request returned retryable status, retrying attempt=6 backoff=1ms status=502 url=http://127.0.0.1:654254372026/11/09 12:01:10 WARN Request returned retryable status, retrying attempt=7 backoff=1ms status=502 url=http://127.0.0.1:65425438--- PASS: TestScriptTokenBadJSON (0.29s)4392026/11/09 12:01:10 WARN Request returned retryable status, retrying attempt=8 backoff=1ms status=502 url=http://127.0.0.1:654254402026/11/09 12:01:10 WARN Request returned retryable status, retrying attempt=9 backoff=1ms status=502 url=http://127.0.0.1:654254412026/11/09 12:01:10 WARN Request returned retryable status, retrying attempt=10 backoff=1ms status=502 url=http://127.0.0.1:654254422026/11/09 12:01:10 http: TLS handshake error from 127.0.0.1:65526: read tcp 127.0.0.1:65525->127.0.0.1:65526: use of closed network connection443--- PASS: TestSetClientTLS (0.06s)444 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.02s)445 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.04s)446 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.08s)4472026/11/09 12:01:10 WARN Request returned retryable status, retrying attempt=11 backoff=1ms status=502 url=http://127.0.0.1:65425448--- PASS: TestCaseHackSuffix (0.51s)4492026/11/09 12:01:10 WARN Request returned retryable status, retrying attempt=12 backoff=1ms status=502 url=http://127.0.0.1:654254502026/11/09 12:01:10 WARN Request returned retryable status, retrying attempt=13 backoff=1ms status=502 url=http://127.0.0.1:65425451--- PASS: TestDumpPathSingleFile (0.51s)4522026/11/09 12:01:10 WARN Request returned retryable status, retrying attempt=14 backoff=1ms status=502 url=http://127.0.0.1:65425453--- PASS: TestRegisterUploadedObjectReusesConnections (0.51s)4542026/11/09 12:01:10 WARN Request returned retryable status, retrying attempt=15 backoff=1ms status=502 url=http://127.0.0.1:654254552026/11/09 12:01:10 WARN Request returned retryable status, retrying attempt=16 backoff=1ms status=502 url=http://127.0.0.1:654254562026/11/09 12:01:10 WARN Request returned retryable status, retrying attempt=17 backoff=1ms status=502 url=http://127.0.0.1:65425457--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.52s)458--- PASS: TestDumpPathWriterError (0.52s)459--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.34s)460--- PASS: TestScriptTokenCachesUntilRefresh (0.35s)461--- PASS: TestDumpPathMatchesNix (0.55s)462--- PASS: TestUploadMultipart_PartsInParallel (0.99s)463--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.07s)464PASS465Running server tests...466The files belonging to this database system will be owned by user "_tribuchetbld8".467This user must also own the server process.468469The database cluster will be initialized with locale "C".470The default database encoding has accordingly been set to "SQL_ASCII".471The default text search configuration will be set to "english".472473Data page checksums are enabled.474475creating directory /private/var/tb/8/scratch/cde53c32ef764c64/build/postgres243623995/data ... ok476creating subdirectories ... ok477selecting dynamic shared memory implementation ... posix478selecting default "max_connections" ... 100479selecting default "shared_buffers" ... 128MB480selecting default time zone ... UTC481creating configuration files ... ok482running bootstrap script ... ok483performing post-bootstrap initialization ... ok484syncing data to disk ... ok485486initdb: warning: enabling "trust" authentication for local connections487initdb: 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.488489Success. You can now start the database server using:490491 pg_ctl -D /private/var/tb/8/scratch/cde53c32ef764c64/build/postgres243623995/data -l logfile start492493/private/var/tb/8/scratch/cde53c32ef764c64/build/postgres243623995:5432 - no response4942026-11-09 12:01:12.298 UTC [27360] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit4952026-11-09 12:01:12.298 UTC [27360] LOG: listening on Unix socket "/private/var/tb/8/scratch/cde53c32ef764c64/build/postgres243623995/.s.PGSQL.5432"4962026-11-09 12:01:12.303 UTC [27367] LOG: database system was shut down at 2026-11-09 12:01:12 UTC4972026-11-09 12:01:12.305 UTC [27360] LOG: database system is ready to accept connections498/private/var/tb/8/scratch/cde53c32ef764c64/build/postgres243623995:5432 - accepting connections499{"timestamp":"2026-11-09T12:01:12.539068Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"0274dcc7-422b-4ca2-838f-5fa6c4b89b0c","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":12,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":502,"threadName":"rustfs-worker","threadId":"ThreadId(10)"}500{"timestamp":"2026-11-09T12:01:12.653326Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"21362d5a-7294-42c6-869e-af866e201cae","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":0,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":502,"threadName":"rustfs-worker","threadId":"ThreadId(11)"}501{"timestamp":"2026-11-09T12:01:12.756802Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"226bae1f-26c7-438f-994a-5e2fb1aea682","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":0,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":502,"threadName":"rustfs-worker","threadId":"ThreadId(10)"}502=== RUN TestAbortSucceeded503=== PAUSE TestAbortSucceeded504=== RUN TestService_AuthMiddleware505=== PAUSE TestService_AuthMiddleware506=== RUN TestService_AuthMiddleware_MTLSProxyHeader507=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader508=== RUN TestService_AuthMiddleware_MTLSBoundSubjects509=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects510=== RUN TestService_ReadAuthMiddleware511=== PAUSE TestService_ReadAuthMiddleware512=== RUN TestService_AuthMiddleware_OIDC513=== PAUSE TestService_AuthMiddleware_OIDC514=== RUN TestService_RequireScope_OIDC515=== PAUSE TestService_RequireScope_OIDC516=== RUN TestService_ReadScope_PublicByDefault517=== PAUSE TestService_ReadScope_PublicByDefault518=== RUN TestCacheConfigHandler519=== PAUSE TestCacheConfigHandler520=== RUN TestCacheStatsHandler521=== PAUSE TestCacheStatsHandler522=== RUN TestClientCADerivations523=== PAUSE TestClientCADerivations524=== RUN TestClientErrorHandling525=== PAUSE TestClientErrorHandling526=== RUN TestClientIntegration527=== PAUSE TestClientIntegration528=== RUN TestClientMultipleUploads529=== PAUSE TestClientMultipleUploads530=== RUN TestClientWithDependencies531=== PAUSE TestClientWithDependencies532=== RUN TestClientSharedPathCommittedMidPush533=== PAUSE TestClientSharedPathCommittedMidPush534=== RUN TestPinProtectsFromGC535=== PAUSE TestPinProtectsFromGC536=== RUN TestClientPushesUseOnePush537=== PAUSE TestClientPushesUseOnePush538=== RUN TestClientFallsBackToClosures539=== PAUSE TestClientFallsBackToClosures540=== RUN TestDeleteClosuresRacingPins541=== PAUSE TestDeleteClosuresRacingPins542=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock543=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock544=== RUN TestRetryableCompletionError545=== PAUSE TestRetryableCompletionError546=== RUN TestCompleteMultipartUploadRetriesTransientFailure547=== PAUSE TestCompleteMultipartUploadRetriesTransientFailure548=== RUN TestResolveDBConnectionString549=== PAUSE TestResolveDBConnectionString550=== RUN TestConnectWaitsForAPeerMigration551=== PAUSE TestConnectWaitsForAPeerMigration552=== RUN TestLeadElectsOneAndHandsOver553=== PAUSE TestLeadElectsOneAndHandsOver554=== RUN TestLeadIncumbentWinsAfterRestart5552026/11/09 12:01:13 INFO lead: acquired remote=192.0.2.1:12345562026/11/09 12:01:13 INFO lead: released remote=192.0.2.1:12345572026/11/09 12:01:13 INFO lead: acquired remote=192.0.2.1:12345582026/11/09 12:01:14 INFO lead: released remote=192.0.2.1:1234559--- PASS: TestLeadIncumbentWinsAfterRestart (1.98s)560=== RUN TestLeadIncumbentAnnouncesAtOnce561=== PAUSE TestLeadIncumbentAnnouncesAtOnce562=== RUN TestLeadEndsOnShutdown563=== PAUSE TestLeadEndsOnShutdown564=== RUN TestLeadEndsWhenItsConnectionHangs5652026/11/09 12:01:14 INFO lead: acquired remote=192.0.2.1:12345662026-11-09 12:01:16.399 UTC [27404] FATAL: terminating connection due to administrator command5672026/11/09 12:01:16 INFO lead: acquired remote=192.0.2.1:12345682026/11/09 12:01:17 WARN lead: lock connection lost error="timeout: context deadline exceeded"5692026/11/09 12:01:17 INFO lead: released remote=192.0.2.1:12345702026/11/09 12:01:17 INFO lead: released remote=192.0.2.1:1234571--- PASS: TestLeadEndsWhenItsConnectionHangs (2.95s)572=== RUN TestGCAdvisoryLockBlocksConcurrentRun573=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun574=== RUN TestGCBugBareHashReferences575=== PAUSE TestGCBugBareHashReferences576=== RUN TestGCMetrics577=== PAUSE TestGCMetrics578=== RUN TestPushDedupSurvivesConcurrentGC579=== PAUSE TestPushDedupSurvivesConcurrentGC580=== RUN TestDeduplicatedObjectsRecordedAsPending581=== PAUSE TestDeduplicatedObjectsRecordedAsPending582=== RUN TestGCSweepSkipsPendingObjects583=== PAUSE TestGCSweepSkipsPendingObjects584=== RUN TestTombstonedObjectOfferedWithoutWaiting585=== PAUSE TestTombstonedObjectOfferedWithoutWaiting586=== RUN TestGCSweepDeliversEachKeyOnce587=== PAUSE TestGCSweepDeliversEachKeyOnce588=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection589=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection590=== RUN TestForceGCDuringPushOffersSweptObject591=== PAUSE TestForceGCDuringPushOffersSweptObject592=== RUN TestFailedS3DeleteKeepsTombstone593=== PAUSE TestFailedS3DeleteKeepsTombstone594=== RUN TestSweepSkipsRowsLockedByPush595=== PAUSE TestSweepSkipsRowsLockedByPush596=== RUN TestRegisterCompletedObjectNeedsPendingRow597=== PAUSE TestRegisterCompletedObjectNeedsPendingRow598=== RUN TestGetExistingObjectsLocksRows599=== PAUSE TestGetExistingObjectsLocksRows600=== RUN TestSweepRechecksPendingAfterLocking601=== PAUSE TestSweepRechecksPendingAfterLocking602=== RUN TestPushWaitsForSweepHoldingRow603=== PAUSE TestPushWaitsForSweepHoldingRow604=== RUN TestCommitRacingPendingCleanupKeepsObjects605=== PAUSE TestCommitRacingPendingCleanupKeepsObjects606=== RUN TestGCEndsOnShutdown607=== PAUSE TestGCEndsOnShutdown608=== RUN TestGCTaskStore_StartNew609=== PAUSE TestGCTaskStore_StartNew610=== RUN TestGCTaskStore_DeduplicateSameParams611=== PAUSE TestGCTaskStore_DeduplicateSameParams612=== RUN TestGCTaskStore_ConflictDifferentParams613=== PAUSE TestGCTaskStore_ConflictDifferentParams614=== RUN TestGCTaskStore_GetEmpty615=== PAUSE TestGCTaskStore_GetEmpty616=== RUN TestGCTaskStore_GetReturnsLatest617=== PAUSE TestGCTaskStore_GetReturnsLatest618=== RUN TestGCTaskStore_CompletedAllowsNewTask619=== PAUSE TestGCTaskStore_CompletedAllowsNewTask620=== RUN TestGCTaskStore_PhaseUpdates621=== PAUSE TestGCTaskStore_PhaseUpdates622=== RUN TestGCTaskStore_Fail623=== PAUSE TestGCTaskStore_Fail624=== RUN TestGracefulShutdownDrainsInflight625=== PAUSE TestGracefulShutdownDrainsInflight626=== RUN TestService_healthCheckHandler627=== PAUSE TestService_healthCheckHandler628=== RUN TestService_readinessHandler629=== PAUSE TestService_readinessHandler630=== RUN TestGenerateLandingPage631=== PAUSE TestGenerateLandingPage632=== RUN TestEnsureAbortUploadsRule633=== PAUSE TestEnsureAbortUploadsRule634=== RUN TestCacheConfigHandlerMaxNarSize635=== PAUSE TestCacheConfigHandlerMaxNarSize636=== RUN TestCreatePendingClosureRejectsOversizedNAR637=== PAUSE TestCreatePendingClosureRejectsOversizedNAR638=== RUN TestNARDeduplicationMetadataUploadBug639=== PAUSE TestNARDeduplicationMetadataUploadBug640=== RUN TestMetricsInventory641=== PAUSE TestMetricsInventory642=== RUN TestMetricsCommit643=== PAUSE TestMetricsCommit644=== RUN TestService_NativeMTLS645=== PAUSE TestService_NativeMTLS646=== RUN TestServerTLSConfig647=== PAUSE TestServerTLSConfig648=== RUN TestMultipartCleanup649=== PAUSE TestMultipartCleanup650=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded651=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded652=== RUN TestPendingCleanupUsesOneCutoff653=== PAUSE TestPendingCleanupUsesOneCutoff654=== RUN TestObjectStatsTrigger655=== PAUSE TestObjectStatsTrigger656=== RUN TestObjectStatsUpdatedOncePerCommit657=== PAUSE TestObjectStatsUpdatedOncePerCommit658=== RUN TestOrphanedObjectsGC659=== PAUSE TestOrphanedObjectsGC660=== RUN TestOrphanedObjectsGCStressTest661=== PAUSE TestOrphanedObjectsGCStressTest662=== RUN TestCreatePin_ReservedPins663=== PAUSE TestCreatePin_ReservedPins664=== RUN TestPresentReportsOnlyClosureRoots665=== PAUSE TestPresentReportsOnlyClosureRoots666=== RUN TestPresentRefreshesOnlyStaleClosures667=== PAUSE TestPresentRefreshesOnlyStaleClosures668=== RUN TestPresentNotReportedWhileGCDeletesClosure669=== PAUSE TestPresentNotReportedWhileGCDeletesClosure670=== RUN TestParseSingleRange671=== PAUSE TestParseSingleRange672=== RUN TestProxyHeadersOnlyTrustedOnSocket6732026/11/09 12:01:17 INFO Starting HTTP server address=proxy.sock6742026/11/09 12:01:17 INFO Starting HTTP server address=127.0.0.1:491716752026/11/09 12:01:17 WARN mTLS auth: subject not in bound subjects subject="CN=someone"6762026/11/09 12:01:17 INFO Shutdown signal received, draining in-flight requests timeout=10s677--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.16s)678=== RUN TestIsValidCachePath679=== PAUSE TestIsValidCachePath680=== RUN TestReadProxyNarinfo681=== PAUSE TestReadProxyNarinfo682=== RUN TestReadProxyNarinfoAlreadyDecompressed683=== PAUSE TestReadProxyNarinfoAlreadyDecompressed684=== RUN TestReadProxyContentNegotiation685=== PAUSE TestReadProxyContentNegotiation686=== RUN TestReadProxyNarStreaming687=== PAUSE TestReadProxyNarStreaming688=== RUN TestReadProxy404689=== PAUSE TestReadProxy404690=== RUN TestReadProxyInvalidPath691=== PAUSE TestReadProxyInvalidPath692=== RUN TestReadProxyHead693=== PAUSE TestReadProxyHead694=== RUN TestReadProxyOutlastsServerWriteTimeout695=== PAUSE TestReadProxyOutlastsServerWriteTimeout696=== RUN TestReadProxyConditionalGet697=== PAUSE TestReadProxyConditionalGet698=== RUN TestReadProxyRootRedirectsToIndexHTML699=== PAUSE TestReadProxyRootRedirectsToIndexHTML700=== RUN TestReadProxyDisabled701=== PAUSE TestReadProxyDisabled702=== RUN TestReadRedirectNar703=== PAUSE TestReadRedirectNar704=== RUN TestReadRedirectKeepsNarinfoProxied705=== PAUSE TestReadRedirectKeepsNarinfoProxied706=== RUN TestReadProxyRangeRequest707=== PAUSE TestReadProxyRangeRequest708=== RUN TestReadRedirectUsesPublicS3URL709=== PAUSE TestReadRedirectUsesPublicS3URL710=== RUN TestPush_OverlappingRootsStoreOneRowPerKey711=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey712=== RUN TestPush_CompleteCommitsEveryRoot713=== PAUSE TestPush_CompleteCommitsEveryRoot714=== RUN TestPush_RepeatedRootCommitsOnce715=== PAUSE TestPush_RepeatedRootCommitsOnce716=== RUN TestPush_CompleteWaitsForCleanupOfThePush717=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush718=== RUN TestPush_RootsAreLockedInByteOrder719=== PAUSE TestPush_RootsAreLockedInByteOrder720=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit721=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit722=== RUN TestPush_RejectsBadRequests723=== PAUSE TestPush_RejectsBadRequests724=== RUN TestPush_SignsNarinfosOfItsPendingObjects725=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects726=== RUN TestSharedNarBothUploadsComplete727=== PAUSE TestSharedNarBothUploadsComplete728=== RUN TestCompleteMultipartUpload_ErrorButObjectExists729=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists730=== RUN TestCompletedNarNotReofferedAcrossClosures731=== PAUSE TestCompletedNarNotReofferedAcrossClosures732=== RUN TestPresignedUploadRegisteredBeforeCommit733=== PAUSE TestPresignedUploadRegisteredBeforeCommit734=== RUN TestService_Rustfstest735=== PAUSE TestService_Rustfstest736=== RUN TestParseSize737=== PAUSE TestParseSize738=== RUN TestSkippedUploadsHandler739=== PAUSE TestSkippedUploadsHandler740=== RUN TestSystemdListenerNotActivated741--- PASS: TestSystemdListenerNotActivated (0.00s)742=== RUN TestWatchdogBeatsWhenHealthy743--- PASS: TestWatchdogBeatsWhenHealthy (0.03s)744=== RUN TestWatchdogSkipsWhenUnhealthy7452026/11/09 12:01:18 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7462026/11/09 12:01:18 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7472026/11/09 12:01:18 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7482026/11/09 12:01:18 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7492026/11/09 12:01:18 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7502026/11/09 12:01:18 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7512026/11/09 12:01:18 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7522026/11/09 12:01:18 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7532026/11/09 12:01:18 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7542026/11/09 12:01:18 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"755--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)756=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle757=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle758=== RUN TestProxyWriteTimeout759=== PAUSE TestProxyWriteTimeout760=== RUN TestPendingClosureWriteTimeout761=== PAUSE TestPendingClosureWriteTimeout762=== RUN TestIsValidUploadKey763=== PAUSE TestIsValidUploadKey764=== RUN TestUploadHandlersRejectInvalidKeys765=== PAUSE TestUploadHandlersRejectInvalidKeys766=== RUN TestUploadHandlersRejectOversizedBody767=== PAUSE TestUploadHandlersRejectOversizedBody768=== RUN TestService_cleanupPendingClosuresHandler769=== PAUSE TestService_cleanupPendingClosuresHandler770=== RUN TestService_createPendingClosureHandler771=== PAUSE TestService_createPendingClosureHandler772=== RUN TestService_verifyS3Integrity773=== PAUSE TestService_verifyS3Integrity774=== RUN TestService_verifyS3ReuploadsStaleNarinfo775=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo776=== RUN TestCompleteMultipartUnregistered777=== PAUSE TestCompleteMultipartUnregistered778=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT779=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT780=== CONT TestPush_CompleteWaitsForCleanupOfThePush781=== CONT TestPush_RepeatedRootCommitsOnce782=== CONT TestGCTaskStore_PhaseUpdates783--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)784=== CONT TestSkippedUploadsHandler785=== CONT TestGracefulShutdownDrainsInflight786=== CONT TestService_healthCheckHandler787=== CONT TestGCTaskStore_Fail788--- PASS: TestGCTaskStore_Fail (0.00s)789=== CONT TestGCTaskStore_CompletedAllowsNewTask790--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)791=== CONT TestGCTaskStore_GetReturnsLatest792--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)793=== CONT TestPresignedUploadRegisteredBeforeCommit794=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle795=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT796=== CONT TestCompleteMultipartUnregistered797=== CONT TestService_verifyS3ReuploadsStaleNarinfo798=== RUN TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed7992026/11/09 12:01:18 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000800=== CONT TestGCTaskStore_GetEmpty801--- PASS: TestGCTaskStore_GetEmpty (0.00s)802=== CONT TestCompletedNarNotReofferedAcrossClosures803=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed804=== RUN TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed805=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed806=== RUN TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost807=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost808=== RUN TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed809=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed810=== RUN TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed811=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed812=== CONT TestService_verifyS3Integrity813=== CONT TestPush_RejectsBadRequests814=== CONT TestService_createPendingClosureHandler815=== CONT TestService_cleanupPendingClosuresHandler816=== CONT TestUploadHandlersRejectOversizedBody817=== CONT TestUploadHandlersRejectInvalidKeys818=== CONT TestIsValidUploadKey819=== CONT TestPendingClosureWriteTimeout820=== CONT TestProxyWriteTimeout821=== RUN TestProxyWriteTimeout/narinfo822=== PAUSE TestProxyWriteTimeout/narinfo823=== CONT TestGCTaskStore_ConflictDifferentParams8242026/11/09 12:01:18 INFO Starting HTTP server address=127.0.0.1:49173825=== CONT TestCompleteMultipartUpload_ErrorButObjectExists826=== CONT TestAbortSucceeded827=== CONT TestParseSize828=== CONT TestService_Rustfstest829=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info830=== RUN TestIsValidUploadKey/narinfo831=== RUN TestPendingClosureWriteTimeout/empty832--- PASS: TestSkippedUploadsHandler (0.00s)833--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)834=== CONT TestSharedNarBothUploadsComplete835=== RUN TestProxyWriteTimeout/1_GiB_nar836=== CONT TestPush_SignsNarinfosOfItsPendingObjects8372026/11/09 12:01:18 INFO Shutdown signal received, draining in-flight requests timeout=10s838=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info839=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal840=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal841=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key842=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key843=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key844=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key845=== PAUSE TestIsValidUploadKey/narinfo846=== RUN TestIsValidUploadKey/nar_zst847=== PAUSE TestIsValidUploadKey/nar_zst848=== RUN TestIsValidUploadKey/nar_xz849=== PAUSE TestIsValidUploadKey/nar_xz850=== RUN TestIsValidUploadKey/nar_plain851=== PAUSE TestIsValidUploadKey/nar_plain852=== RUN TestIsValidUploadKey/listing853=== PAUSE TestIsValidUploadKey/listing854=== RUN TestIsValidUploadKey/build_log855=== PAUSE TestIsValidUploadKey/build_log856=== RUN TestIsValidUploadKey/build_log_home-manager_file857=== PAUSE TestIsValidUploadKey/build_log_home-manager_file858=== RUN TestIsValidUploadKey/build_log_plus_in_name859=== PAUSE TestIsValidUploadKey/build_log_plus_in_name860=== RUN TestIsValidUploadKey/build_log_question_mark861=== PAUSE TestIsValidUploadKey/build_log_question_mark862=== RUN TestIsValidUploadKey/build_log_equals863=== PAUSE TestIsValidUploadKey/build_log_equals864=== RUN TestIsValidUploadKey/realisation865=== PAUSE TestIsValidUploadKey/realisation866=== RUN TestIsValidUploadKey/realisation_plus_in_output867=== PAUSE TestIsValidUploadKey/realisation_plus_in_output868=== RUN TestIsValidUploadKey/nix-cache-info869=== PAUSE TestIsValidUploadKey/nix-cache-info870=== RUN TestIsValidUploadKey/index.html871=== PAUSE TestIsValidUploadKey/index.html872=== RUN TestIsValidUploadKey/narinfo_key,_nar_type873=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type874=== RUN TestIsValidUploadKey/nar_key,_narinfo_type875=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type876=== RUN TestIsValidUploadKey/listing_key,_narinfo_type877=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type878=== RUN TestIsValidUploadKey/traversal879=== PAUSE TestIsValidUploadKey/traversal880=== RUN TestIsValidUploadKey/traversal_nar881=== PAUSE TestIsValidUploadKey/traversal_nar882=== RUN TestIsValidUploadKey/absolute883=== PAUSE TestIsValidUploadKey/absolute884=== RUN TestIsValidUploadKey/empty_key885=== PAUSE TestIsValidUploadKey/empty_key886=== RUN TestIsValidUploadKey/unknown_type887=== PAUSE TestIsValidUploadKey/unknown_type888=== CONT TestPush_OverlappingRootsStoreOneRowPerKey889--- PASS: TestParseSize (0.00s)890--- PASS: TestAbortSucceeded (0.00s)891=== CONT TestReadRedirectUsesPublicS3URL892=== CONT TestPresentNotReportedWhileGCDeletesClosure893=== PAUSE TestPendingClosureWriteTimeout/empty894=== CONT TestPush_CompleteCommitsEveryRoot895=== PAUSE TestProxyWriteTimeout/1_GiB_nar896=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh897=== RUN TestPendingClosureWriteTimeout/400_objects898=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh899=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale900=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale901=== RUN TestProxyWriteTimeout/10_GiB_nar902=== PAUSE TestProxyWriteTimeout/10_GiB_nar903=== RUN TestProxyWriteTimeout/unknown_size904=== PAUSE TestProxyWriteTimeout/unknown_size905=== CONT TestReadProxyRangeRequest906=== CONT TestReadRedirectKeepsNarinfoProxied907=== PAUSE TestPendingClosureWriteTimeout/400_objects908=== RUN TestPendingClosureWriteTimeout/670k_objects909=== PAUSE TestPendingClosureWriteTimeout/670k_objects910=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline911=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline912=== CONT TestReadRedirectNar913=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart914=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart915=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts916=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts917=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure918=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure919=== CONT TestReadProxyDisabled920--- PASS: TestGracefulShutdownDrainsInflight (0.16s)921=== CONT TestReadProxyRootRedirectsToIndexHTML9222026/11/09 12:01:18 INFO Received push request method=POST path=/api/pushes9232026/11/09 12:01:18 INFO Received uploads request method=POST path=/api/pending_closures9242026/11/09 12:01:19 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst9252026/11/09 12:01:19 INFO Received uploads request method=POST path=/api/pending_closures926--- PASS: TestPresignedUploadRegisteredBeforeCommit (1.04s)927=== CONT TestReadProxyConditionalGet9282026-11-09 12:01:19.250 UTC [27465] ERROR: Push does not exist: id=19292026-11-09 12:01:19.250 UTC [27465] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE9302026-11-09 12:01:19.250 UTC [27465] STATEMENT: SELECT commit_push($1)931--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (1.06s)932=== CONT TestResolveDBConnectionString933--- PASS: TestService_healthCheckHandler (1.07s)934=== CONT TestCompleteMultipartUploadRetriesTransientFailure935=== RUN TestResolveDBConnectionString/flag_wins936=== PAUSE TestResolveDBConnectionString/flag_wins937=== RUN TestResolveDBConnectionString/file_when_flag_empty938=== PAUSE TestResolveDBConnectionString/file_when_flag_empty939=== RUN TestResolveDBConnectionString/missing_file_is_an_error940=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error941=== RUN TestResolveDBConnectionString/PGHOST_allows_empty942=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty943=== RUN TestResolveDBConnectionString/nothing_configured944=== PAUSE TestResolveDBConnectionString/nothing_configured945=== CONT TestReadProxyOutlastsServerWriteTimeout9462026/11/09 12:01:19 INFO Received uploads request method=POST path=/api/pending_closures947--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (1.51s)948=== CONT TestRetryableCompletionError949=== RUN TestRetryableCompletionError/nil950=== PAUSE TestRetryableCompletionError/nil951=== RUN TestRetryableCompletionError/bad_gateway952=== PAUSE TestRetryableCompletionError/bad_gateway953=== RUN TestRetryableCompletionError/invalid_part954=== PAUSE TestRetryableCompletionError/invalid_part955=== RUN TestRetryableCompletionError/access_denied956=== PAUSE TestRetryableCompletionError/access_denied957=== RUN TestRetryableCompletionError/throttled958=== PAUSE TestRetryableCompletionError/throttled959=== RUN TestRetryableCompletionError/context_canceled960=== PAUSE TestRetryableCompletionError/context_canceled961=== RUN TestRetryableCompletionError/degraded_quorum962=== PAUSE TestRetryableCompletionError/degraded_quorum963=== RUN TestRetryableCompletionError/transport_failure964=== PAUSE TestRetryableCompletionError/transport_failure965=== RUN TestRetryableCompletionError/no_such_upload966=== PAUSE TestRetryableCompletionError/no_such_upload967=== RUN TestRetryableCompletionError/deadline_exceeded968=== PAUSE TestRetryableCompletionError/deadline_exceeded969=== CONT TestReadProxyHead9702026/11/09 12:01:19 INFO Received push request method=POST path=/api/pushes9712026/11/09 12:01:20 INFO Received complete push request method=POST path=/api/pushes/1/complete9722026/11/09 12:01:20 INFO Completed push id=1 objects=4 duration=23.101792ms973--- PASS: TestPush_RepeatedRootCommitsOnce (1.85s)974=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock9752026/11/09 12:01:20 INFO Received uploads request method=POST path=/api/pending_closures9762026/11/09 12:01:20 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9772026/11/09 12:01:20 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst978--- PASS: TestCompleteMultipartUnregistered (2.23s)979=== CONT TestReadProxyInvalidPath9802026/11/09 12:01:20 INFO Received cleanup request method=DELETE path=/api/pending_closures9812026/11/09 12:01:20 INFO Aborted multipart uploads count=0 kept=09822026/11/09 12:01:20 INFO Received uploads request method=POST path=/api/pending_closures9832026/11/09 12:01:20 INFO Received cleanup request method=DELETE path=/api/pending_closures9842026/11/09 12:01:20 INFO Aborted multipart uploads count=1 kept=09852026/11/09 12:01:20 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9862026-11-09 12:01:20.762 UTC [27467] ERROR: Closure does not exist: id=19872026-11-09 12:01:20.762 UTC [27467] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE9882026-11-09 12:01:20.762 UTC [27467] STATEMENT: -- name: CommitPendingClosure :one989 SELECT commit_pending_closure($1::bigint)::bigint990 991--- PASS: TestService_cleanupPendingClosuresHandler (2.57s)992=== CONT TestReadProxy4049932026/11/09 12:01:20 INFO Received uploads request method=POST path=/api/pending_closures994=== RUN TestPush_RejectsBadRequests/no_roots995=== PAUSE TestPush_RejectsBadRequests/no_roots996=== RUN TestPush_RejectsBadRequests/no_objects997=== PAUSE TestPush_RejectsBadRequests/no_objects998=== RUN TestPush_RejectsBadRequests/bad_root999=== PAUSE TestPush_RejectsBadRequests/bad_root1000=== RUN TestPush_RejectsBadRequests/root_not_in_objects1001=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1002=== CONT TestReadProxyNarStreaming10032026/11/09 12:01:21 INFO Received uploads request method=POST path=/api/pending_closures10042026/11/09 12:01:21 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10052026/11/09 12:01:21 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=ZGQ5NTdhZjYtYWRmOS00MzVkLThhOTctMTkyMGFkNjU2YzZhLjM4N2FhMGFlLWQ5NjctNDBjNy05NTBkLWU5YzQ0Njc1MGU0MXgxNzk0MjI1NjgwMjA5NDk3MDAw parts=1010062026/11/09 12:01:21 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10072026/11/09 12:01:21 INFO Completed upload id=1 objects=2 duration=10.491292ms10082026/11/09 12:01:21 INFO Received uploads request method=POST path=/api/pending_closures10092026/11/09 12:01:21 INFO Received uploads request method=POST path=/api/pending_closures10102026/11/09 12:01:21 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo10112026/11/09 12:01:21 WARN Found objects in DB but missing from S3, will re-upload count=11012--- PASS: TestService_verifyS3Integrity (3.50s)1013=== CONT TestReadProxyContentNegotiation10142026/11/09 12:01:21 INFO Received uploads request method=POST path=/api/pending_closures10152026/11/09 12:01:21 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10162026/11/09 12:01:22 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10172026/11/09 12:01:22 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ZGQ5NTdhZjYtYWRmOS00MzVkLThhOTctMTkyMGFkNjU2YzZhLjg0YzZjOGE5LTAzODMtNGI0MC05ZWNhLTRjODEyYmNlZmUwN3gxNzk0MjI1NjgxNzY5OTQ0MDAw10182026/11/09 12:01:22 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ZGQ5NTdhZjYtYWRmOS00MzVkLThhOTctMTkyMGFkNjU2YzZhLjg0YzZjOGE5LTAzODMtNGI0MC05ZWNhLTRjODEyYmNlZmUwN3gxNzk0MjI1NjgxNzY5OTQ0MDAw parts=11019--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (3.80s)1020=== CONT TestReadProxyNarinfoAlreadyDecompressed1021--- PASS: TestReadRedirectKeepsNarinfoProxied (3.80s)1022=== CONT TestReadProxyNarinfo10232026/11/09 12:01:22 INFO Received uploads request method=POST path=/api/pending_closures10242026/11/09 12:01:22 INFO Received uploads request method=POST path=/api/pending_closures10252026/11/09 12:01:22 INFO Received uploads request method=POST path=/api/pending_closures10262026/11/09 12:01:22 INFO Received push request method=POST path=/api/pushes10272026/11/09 12:01:22 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10282026/11/09 12:01:22 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10292026/11/09 12:01:22 INFO Signed narinfos id=1 count=110302026/11/09 12:01:22 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10312026/11/09 12:01:22 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10322026/11/09 12:01:22 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"10332026/11/09 12:01:22 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10342026/11/09 12:01:22 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"10352026/11/09 12:01:22 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10362026/11/09 12:01:22 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=110372026/11/09 12:01:22 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10382026/11/09 12:01:22 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo1039--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (4.36s)1040=== CONT TestIsValidCachePath1041=== RUN TestIsValidCachePath/narinfo1042=== PAUSE TestIsValidCachePath/narinfo1043=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1044=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1045=== RUN TestIsValidCachePath/nar_zst1046=== PAUSE TestIsValidCachePath/nar_zst1047=== RUN TestIsValidCachePath/nar_xz1048=== PAUSE TestIsValidCachePath/nar_xz1049=== RUN TestIsValidCachePath/nar_bz21050=== PAUSE TestIsValidCachePath/nar_bz21051=== RUN TestIsValidCachePath/nar_uncompressed1052=== PAUSE TestIsValidCachePath/nar_uncompressed1053=== RUN TestIsValidCachePath/ls1054=== PAUSE TestIsValidCachePath/ls1055=== RUN TestIsValidCachePath/log1056=== PAUSE TestIsValidCachePath/log1057=== RUN TestIsValidCachePath/realisation1058=== PAUSE TestIsValidCachePath/realisation1059=== RUN TestIsValidCachePath/nix-cache-info1060=== PAUSE TestIsValidCachePath/nix-cache-info1061=== RUN TestIsValidCachePath/index.html1062=== PAUSE TestIsValidCachePath/index.html1063=== RUN TestIsValidCachePath/traversal_parent1064=== PAUSE TestIsValidCachePath/traversal_parent1065=== RUN TestIsValidCachePath/traversal_in_middle1066=== PAUSE TestIsValidCachePath/traversal_in_middle1067=== RUN TestIsValidCachePath/invalid_char_e1068=== PAUSE TestIsValidCachePath/invalid_char_e1069=== RUN TestIsValidCachePath/invalid_char_u1070=== PAUSE TestIsValidCachePath/invalid_char_u1071=== RUN TestIsValidCachePath/random_path1072=== PAUSE TestIsValidCachePath/random_path1073=== RUN TestIsValidCachePath/empty1074=== PAUSE TestIsValidCachePath/empty1075=== RUN TestIsValidCachePath/leading_slash1076=== PAUSE TestIsValidCachePath/leading_slash1077=== RUN TestIsValidCachePath/wrong_extension1078=== PAUSE TestIsValidCachePath/wrong_extension1079=== RUN TestIsValidCachePath/short_hash1080=== PAUSE TestIsValidCachePath/short_hash1081=== CONT TestConnectWaitsForAPeerMigration10822026/11/09 12:01:22 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=ZGQ5NTdhZjYtYWRmOS00MzVkLThhOTctMTkyMGFkNjU2YzZhLjFkNzc5NzhhLTQ5ZGUtNGExNy05MWJkLTcyNzZiMTk4NjJhYngxNzk0MjI1NjgwOTYwMTkwMDAw parts=1210832026/11/09 12:01:22 INFO Received uploads request method=POST path=/api/pending_closures1084--- PASS: TestCompletedNarNotReofferedAcrossClosures (4.47s)1085=== CONT TestParseSingleRange1086=== RUN TestParseSingleRange/none1087=== PAUSE TestParseSingleRange/none1088=== RUN TestParseSingleRange/unknown_unit1089=== PAUSE TestParseSingleRange/unknown_unit1090=== RUN TestParseSingleRange/multi-range_ignored1091=== PAUSE TestParseSingleRange/multi-range_ignored1092=== RUN TestParseSingleRange/malformed_no_dash1093=== PAUSE TestParseSingleRange/malformed_no_dash1094=== RUN TestParseSingleRange/malformed_both_empty1095=== PAUSE TestParseSingleRange/malformed_both_empty1096=== RUN TestParseSingleRange/malformed_end_before_start1097=== PAUSE TestParseSingleRange/malformed_end_before_start1098=== RUN TestParseSingleRange/closed1099=== PAUSE TestParseSingleRange/closed1100=== RUN TestParseSingleRange/open-ended1101=== PAUSE TestParseSingleRange/open-ended1102=== RUN TestParseSingleRange/end_clamped_to_size1103=== PAUSE TestParseSingleRange/end_clamped_to_size1104=== RUN TestParseSingleRange/suffix1105=== PAUSE TestParseSingleRange/suffix1106=== RUN TestParseSingleRange/suffix_exceeds_size1107=== PAUSE TestParseSingleRange/suffix_exceeds_size1108=== RUN TestParseSingleRange/single_byte1109=== PAUSE TestParseSingleRange/single_byte1110=== RUN TestParseSingleRange/start_past_EOF1111=== PAUSE TestParseSingleRange/start_past_EOF1112=== RUN TestParseSingleRange/start_far_past_EOF1113=== PAUSE TestParseSingleRange/start_far_past_EOF1114=== CONT TestMultipartCleanup1115--- PASS: TestReadRedirectUsesPublicS3URL (4.55s)1116=== CONT TestNARDeduplicationMetadataUploadBug11172026/11/09 12:01:23 INFO Received push request method=POST path=/api/pushes1118--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (4.98s)1119=== CONT TestPresentRefreshesOnlyStaleClosures1120--- PASS: TestReadProxyRangeRequest (5.21s)1121=== CONT TestPresentReportsOnlyClosureRoots11222026/11/09 12:01:23 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11232026/11/09 12:01:23 INFO Received push request method=POST path=/api/pushes11242026/11/09 12:01:23 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=ZGQ5NTdhZjYtYWRmOS00MzVkLThhOTctMTkyMGFkNjU2YzZhLjIyZmJlZGNkLTlkMTQtNDhiZi05MTkwLWRmNmYwY2VmYjcwN3gxNzk0MjI1NjgyMzA1NzkwMDAw parts=1011252026/11/09 12:01:23 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11262026/11/09 12:01:23 INFO Completed upload id=1 objects=2 duration=9.584083ms11272026/11/09 12:01:23 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000011282026/11/09 12:01:23 INFO Received uploads request method=POST path=/api/pending_closures11292026/11/09 12:01:23 INFO Starting cleanup of old closures method=DELETE path=/api/closures11302026/11/09 12:01:23 INFO Aborted multipart uploads count=0 kept=011312026/11/09 12:01:23 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=011322026/11/09 12:01:23 INFO Received complete push request method=POST path=/api/pushes/1/complete11332026/11/09 12:01:23 INFO Vacuumed table table=pending_closures11342026/11/09 12:01:23 INFO Completed push id=1 objects=6 duration=42.435542ms11352026/11/09 12:01:23 INFO Vacuumed table table=pending_objects1136--- PASS: TestPush_CompleteCommitsEveryRoot (5.56s)1137=== CONT TestGCTaskStore_DeduplicateSameParams1138--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1139=== CONT TestServerTLSConfig1140=== RUN TestServerTLSConfig/no_client_CA1141=== PAUSE TestServerTLSConfig/no_client_CA1142=== RUN TestServerTLSConfig/missing_CA_file1143=== PAUSE TestServerTLSConfig/missing_CA_file1144=== RUN TestServerTLSConfig/not_a_PEM_file1145=== PAUSE TestServerTLSConfig/not_a_PEM_file1146=== CONT TestCreatePin_ReservedPins11472026/11/09 12:01:23 INFO Vacuumed table table=multipart_uploads11482026/11/09 12:01:23 INFO Vacuumed table table=closures11492026/11/09 12:01:23 INFO Vacuumed table table=objects11502026/11/09 12:01:23 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001151--- PASS: TestService_createPendingClosureHandler (5.71s)1152=== CONT TestService_NativeMTLS11532026/11/09 12:01:23 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:49246/oidc11542026/11/09 12:01:23 INFO Received uploads request method=POST path=/api/pending_closures11552026/11/09 12:01:24 INFO Received uploads request method=POST path=/api/pending_closures1156--- PASS: TestReadProxyDisabled (5.83s)1157=== CONT TestGCTaskStore_StartNew1158--- PASS: TestGCTaskStore_StartNew (0.00s)1159=== CONT TestOrphanedObjectsGCStressTest1160--- PASS: TestReadRedirectNar (6.26s)1161=== CONT TestGCEndsOnShutdown1162=== RUN TestGCEndsOnShutdown/before_the_run1163=== PAUSE TestGCEndsOnShutdown/before_the_run1164=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1165=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1166=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1167=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1168=== CONT TestMetricsCommit1169--- PASS: TestReadProxyRootRedirectsToIndexHTML (6.51s)1170=== CONT TestOrphanedObjectsGC1171--- PASS: TestService_Rustfstest (6.82s)1172=== CONT TestObjectStatsUpdatedOncePerCommit11732026/11/09 12:01:25 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11742026/11/09 12:01:25 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=ZGQ5NTdhZjYtYWRmOS00MzVkLThhOTctMTkyMGFkNjU2YzZhLmM1Njc5OTU1LWU5ZWEtNDRkYi05NWNkLTQxMmQwNzFhYjI3M3gxNzk0MjI1NjgzOTc2MDEyMDAw parts=1211752026/11/09 12:01:25 INFO Received uploads request method=POST path=/api/pending_closures1176--- PASS: TestReadProxyConditionalGet (6.98s)1177=== CONT TestCommitRacingPendingCleanupKeepsObjects11782026/11/09 12:01:26 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11792026/11/09 12:01:26 WARN Rate limiter enabled after throttle name=s3-test rate=511802026/11/09 12:01:26 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1181=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1182 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101183 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001184--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (8.14s)1185=== CONT TestPushWaitsForSweepHoldingRow11862026/11/09 12:01:26 INFO Completed multipart upload object_key=nar/cccccccccccccccccccccccccccccc0100000000000000000000.nar.zst upload_id=ZGQ5NTdhZjYtYWRmOS00MzVkLThhOTctMTkyMGFkNjU2YzZhLjYyOGFkYjdkLWFiODEtNDliMy05MmU4LTYwZTBmYjYyOGIyY3gxNzk0MjI1Njg1ODM2MDExMDAw parts=21187--- PASS: TestCompleteMultipartUploadRetriesTransientFailure (7.27s)1188--- PASS: TestReadProxyHead (6.83s)1189=== CONT TestSweepRechecksPendingAfterLocking1190=== CONT TestGetExistingObjectsLocksRows1191--- PASS: TestReadProxyInvalidPath (6.64s)1192=== CONT TestObjectStatsTrigger11932026/11/09 12:01:27 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11942026/11/09 12:01:27 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=ZGQ5NTdhZjYtYWRmOS00MzVkLThhOTctMTkyMGFkNjU2YzZhLmEzM2JhODVhLTA2MDctNDA5MC04NTY0LTRlZjY4NmM2M2NkMXgxNzk0MjI1Njg0MDA2MDIzMDAw parts=121195--- PASS: TestSharedNarBothUploadsComplete (9.22s)1196=== CONT TestPendingCleanupUsesOneCutoff1197--- PASS: TestReadProxyNarStreaming (6.59s)1198=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded1199--- PASS: TestReadProxy404 (7.19s)1200=== CONT TestMetricsInventory1201--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (8.03s)1202=== CONT TestClientCADerivations1203--- PASS: TestReadProxyContentNegotiation (6.53s)1204=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit12052026/11/09 12:01:28 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>1206--- PASS: TestReadProxyNarinfo (6.47s)1207=== CONT TestRegisterCompletedObjectNeedsPendingRow1208--- PASS: TestReadProxyNarinfoAlreadyDecompressed (6.68s)1209=== CONT TestEnsureAbortUploadsRule12102026/11/09 12:01:29 INFO Received uploads request method=POST path=/api/pending_closures12112026/11/09 12:01:29 INFO Received cleanup request method=DELETE path=/api/pending_closures12122026/11/09 12:01:29 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket39/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""12132026/11/09 12:01:29 INFO Aborted multipart uploads count=0 kept=112142026/11/09 12:01:29 INFO Received cleanup request method=DELETE path=/api/pending_closures12152026/11/09 12:01:29 INFO Aborted multipart uploads count=1 kept=01216--- PASS: TestMultipartCleanup (6.64s)1217=== CONT TestSweepSkipsRowsLockedByPush1218--- PASS: TestConnectWaitsForAPeerMigration (6.73s)1219=== CONT TestCreatePendingClosureRejectsOversizedNAR12202026/11/09 12:01:29 INFO Received uploads request method=POST path=/api/pending_closures1221--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1222=== CONT TestFailedS3DeleteKeepsTombstone1223=== NAME TestNARDeduplicationMetadataUploadBug1224 metadata_upload_test.go:48: First store path: /private/var/tb/8/scratch/cde53c32ef764c64/build/TestNARDeduplicationMetadataUploadBug3493884799/001/store/pqpc9fbzmin3zsxc77xx7i6faw35vn70-file1.txt1225--- PASS: TestPresentRefreshesOnlyStaleClosures (6.39s)1226=== CONT TestCacheConfigHandlerMaxNarSize1227--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1228=== CONT TestForceGCDuringPushOffersSweptObject1229=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows1230=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows1231=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check1232=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check1233=== CONT TestPushDedupSurvivesConcurrentGC1234--- PASS: TestReadProxyOutlastsServerWriteTimeout (10.46s)1235=== CONT TestGCMetrics12362026/11/09 12:01:29 INFO Received push request method=POST path=/api/pushes12372026/11/09 12:01:29 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12382026/11/09 12:01:29 INFO Uploading pqpc9fbzmin3zsxc77xx7i6faw35vn70-file1.txt (160B)12392026/11/09 12:01:29 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"12402026/11/09 12:01:29 WARN Failed to register uploaded object key=pqpc9fbzmin3zsxc77xx7i6faw35vn70.ls error="server returned 404: 404 page not found\n"12412026/11/09 12:01:29 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12422026/11/09 12:01:29 INFO Signed narinfos id=1 count=112432026/11/09 12:01:29 INFO Uploading 1 narinfos12442026/11/09 12:01:29 INFO Received complete push request method=POST path=/api/pushes/1/complete12452026/11/09 12:01:29 WARN Failed to register uploaded object key=pqpc9fbzmin3zsxc77xx7i6faw35vn70.narinfo error="server returned 404: 404 page not found\n"12462026/11/09 12:01:29 INFO Completed push id=1 objects=3 duration=17.070333ms12472026/11/09 12:01:29 INFO Upload complete. (215ms)1248=== NAME TestNARDeduplicationMetadataUploadBug1249 metadata_upload_test.go:54: Retrieved narinfo from S3:1250 StorePath: /private/var/tb/8/scratch/cde53c32ef764c64/build/TestNARDeduplicationMetadataUploadBug3493884799/001/store/pqpc9fbzmin3zsxc77xx7i6faw35vn70-file1.txt1251 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1252 Compression: zstd1253 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1254 NarSize: 1601255 References: 1256 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1257 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1258 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1259 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}1260--- PASS: TestPresentReportsOnlyClosureRoots (6.43s)1261=== CONT TestGCBugBareHashReferences1262=== NAME TestNARDeduplicationMetadataUploadBug1263 metadata_upload_test.go:64: Second store path (same content): /private/var/tb/8/scratch/cde53c32ef764c64/build/TestNARDeduplicationMetadataUploadBug3493884799/001/store/jf4rqrs8b711ix4n3hz096axds1y0jdd-file2.txt12642026/11/09 12:01:30 WARN mTLS auth: subject not in bound subjects subject="CN=reader"12652026/11/09 12:01:30 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1266--- PASS: TestService_NativeMTLS (6.13s)1267=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection12682026/11/09 12:01:30 INFO Received push request method=POST path=/api/pushes12692026/11/09 12:01:30 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)12702026/11/09 12:01:30 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign12712026/11/09 12:01:30 WARN Failed to register uploaded object key=jf4rqrs8b711ix4n3hz096axds1y0jdd.ls error="server returned 404: 404 page not found\n"12722026/11/09 12:01:30 INFO Signed narinfos id=2 count=112732026/11/09 12:01:30 INFO Uploading 1 narinfos12742026/11/09 12:01:30 INFO Received complete push request method=POST path=/api/pushes/2/complete12752026/11/09 12:01:30 WARN Failed to register uploaded object key=jf4rqrs8b711ix4n3hz096axds1y0jdd.narinfo error="server returned 404: 404 page not found\n"12762026/11/09 12:01:30 INFO Completed push id=2 objects=3 duration=2.171708ms12772026/11/09 12:01:30 INFO Upload complete. (146ms)1278=== NAME TestNARDeduplicationMetadataUploadBug1279 metadata_upload_test.go:76: Retrieved narinfo from S3:1280 StorePath: /private/var/tb/8/scratch/cde53c32ef764c64/build/TestNARDeduplicationMetadataUploadBug3493884799/001/store/jf4rqrs8b711ix4n3hz096axds1y0jdd-file2.txt1281 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1282 Compression: zstd1283 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1284 NarSize: 1601285 References: 1286 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1287 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1288 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1289 {"version":1,"root":{"type":"regular","size":44}}1290--- PASS: TestNARDeduplicationMetadataUploadBug (7.36s)1291=== CONT TestGCAdvisoryLockBlocksConcurrentRun12922026/11/09 12:01:30 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux12932026/11/09 12:01:30 WARN Refused reserved pin name=worker-x86_64-linux12942026/11/09 12:01:30 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux12952026/11/09 12:01:30 INFO Received create pin request method=POST path=/api/pins/my-app12962026/11/09 12:01:30 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1297--- PASS: TestCreatePin_ReservedPins (6.42s)1298=== CONT TestGCSweepDeliversEachKeyOnce12992026/11/09 12:01:30 INFO Received push request method=POST path=/api/pushes13002026/11/09 12:01:30 INFO Received complete push request method=POST path=/api/pushes/1/complete13012026/11/09 12:01:30 INFO Completed push id=1 objects=4 duration=34.86725ms13022026/11/09 12:01:30 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete13032026/11/09 12:01:30 INFO Completed upload id=2 objects=2 duration=3.064541ms1304--- PASS: TestMetricsCommit (6.31s)1305=== CONT TestTombstonedObjectOfferedWithoutWaiting1306--- PASS: TestObjectStatsUpdatedOncePerCommit (6.43s)1307=== CONT TestClientFallsBackToClosures13082026/11/09 12:01:31 INFO Received uploads request method=POST path=/api/pending_closures13092026/11/09 12:01:32 INFO Aborted multipart uploads count=0 kept=01310--- PASS: TestPushWaitsForSweepHoldingRow (5.77s)1311=== CONT TestGCSweepSkipsPendingObjects13122026/11/09 12:01:32 WARN Force mode enabled - objects will be deleted immediately without grace period13132026/11/09 12:01:32 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=013142026/11/09 12:01:32 INFO Vacuumed table table=pending_closures13152026/11/09 12:01:32 INFO Vacuumed table table=pending_objects13162026/11/09 12:01:32 INFO Vacuumed table table=multipart_uploads13172026/11/09 12:01:32 INFO Vacuumed table table=closures13182026/11/09 12:01:32 INFO Vacuumed table table=objects1319--- PASS: TestGetExistingObjectsLocksRows (5.71s)1320--- PASS: TestCommitRacingPendingCleanupKeepsObjects (6.05s)1321=== CONT TestClientPushesUseOnePush1322=== CONT TestDeduplicatedObjectsRecordedAsPending13232026/11/09 12:01:32 INFO Aborted multipart uploads count=0 kept=013242026/11/09 12:01:32 WARN Force mode enabled - objects will be deleted immediately without grace period13252026/11/09 12:01:32 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=013262026/11/09 12:01:32 INFO Vacuumed table table=pending_closures13272026/11/09 12:01:32 INFO Vacuumed table table=pending_objects13282026/11/09 12:01:32 INFO Vacuumed table table=multipart_uploads1329=== NAME TestOrphanedObjectsGC1330 orphaned_objects_gc_test.go:287: GC Test Summary:1331 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A1332 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B1333 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)1334 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)1335 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects1336--- PASS: TestOrphanedObjectsGC (8.11s)13372026/11/09 12:01:32 INFO Vacuumed table table=closures1338=== CONT TestPinProtectsFromGC13392026/11/09 12:01:33 INFO Vacuumed table table=objects1340--- PASS: TestSweepRechecksPendingAfterLocking (6.47s)1341=== CONT TestLeadEndsOnShutdown1342--- PASS: TestObjectStatsTrigger (6.08s)1343=== CONT TestLeadIncumbentAnnouncesAtOnce13442026/11/09 12:01:33 INFO Received uploads request method=POST path=/api/pending_closures13452026/11/09 12:01:33 INFO Received uploads request method=POST path=/api/pending_closures13462026/11/09 12:01:33 INFO Received cleanup request method=DELETE path=/api/pending_closures13472026/11/09 12:01:33 INFO Received uploads request method=POST path=/api/pending_closures1348--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (6.06s)1349=== CONT TestLeadElectsOneAndHandsOver1350--- PASS: TestMetricsInventory (6.07s)1351=== CONT TestClientSharedPathCommittedMidPush13522026/11/09 12:01:34 INFO Received push request method=POST path=/api/pushes13532026/11/09 12:01:34 INFO Received complete push request method=POST path=/api/pushes/1/complete13542026/11/09 12:01:34 INFO Completed push id=1 objects=4 duration=41.346625ms13552026/11/09 12:01:34 INFO Received push request method=POST path=/api/pushes1356=== NAME TestClientCADerivations1357 client_ca_test.go:136: Built CA derivation: /private/var/tb/8/scratch/cde53c32ef764c64/build/TestClientCADerivations3902239821/001/store/n27bjn716bagf97ih618804c0ag22kgi-ca-test1358 client_ca_test.go:139: Found 1 dependencies (including self)13592026/11/09 12:01:34 INFO Aborted multipart uploads count=0 kept=013602026/11/09 12:01:34 WARN Force mode enabled - objects will be deleted immediately without grace period13612026/11/09 12:01:34 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=013622026/11/09 12:01:34 INFO Vacuumed table table=pending_closures1363--- PASS: TestRegisterCompletedObjectNeedsPendingRow (6.35s)1364=== CONT TestClientMultipleUploads13652026/11/09 12:01:34 INFO Vacuumed table table=pending_objects13662026/11/09 12:01:34 INFO Vacuumed table table=multipart_uploads13672026/11/09 12:01:34 INFO Received push request method=POST path=/api/pushes13682026/11/09 12:01:34 INFO Vacuumed table table=closures13692026/11/09 12:01:34 INFO Vacuumed table table=objects13702026/11/09 12:01:34 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)13712026/11/09 12:01:34 INFO Received complete push request method=POST path=/api/pushes/2/complete13722026/11/09 12:01:34 INFO Uploading n27bjn716bagf97ih618804c0ag22kgi-ca-test (144B)13732026/11/09 12:01:34 INFO Completed push id=2 objects=4 duration=7.291125ms1374--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (6.75s)1375=== CONT TestClientWithDependencies13762026/11/09 12:01:35 WARN Failed to register uploaded object key=n27bjn716bagf97ih618804c0ag22kgi.ls error="server returned 404: 404 page not found\n"13772026/11/09 12:01:35 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"13782026/11/09 12:01:35 WARN Failed to register uploaded object key=log/skbgnn79qi2l4lzcqmmji6l07l3ww6gg-ca-test.drv error="server returned 404: 404 page not found\n"13792026/11/09 12:01:35 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13802026/11/09 12:01:35 INFO Signed narinfos id=1 count=113812026/11/09 12:01:35 INFO Uploading 1 narinfos13822026/11/09 12:01:35 INFO Received complete push request method=POST path=/api/pushes/1/complete13832026/11/09 12:01:35 WARN Failed to register uploaded object key=n27bjn716bagf97ih618804c0ag22kgi.narinfo error="server returned 404: 404 page not found\n"13842026/11/09 12:01:35 INFO Completed push id=1 objects=4 duration=25.638417ms13852026/11/09 12:01:35 INFO Upload complete. (289ms)1386=== NAME TestClientCADerivations1387 client_ca_test.go:180: Narinfo contains CA field: StorePath: /private/var/tb/8/scratch/cde53c32ef764c64/build/TestClientCADerivations3902239821/001/store/n27bjn716bagf97ih618804c0ag22kgi-ca-test1388 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1389 Compression: zstd1390 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1391 NarSize: 1441392 References: 1393 Deriver: /private/var/tb/8/scratch/cde53c32ef764c64/build/TestClientCADerivations3902239821/001/store/skbgnn79qi2l4lzcqmmji6l07l3ww6gg-ca-test.drv1394 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1395 client_ca_test.go:185: Checking for realisation files in S3...1396 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1397 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache1398 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket57?endpoint=http://localhost:65531®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/private/var/tb/8/scratch/cde53c32ef764c64/build/TestClientCADerivations3902239821/001/store'1399 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 114002026/11/09 12:01:35 INFO Installed lifecycle rule aborting incomplete NAR uploads bucket=bucket60 days=21401--- PASS: TestEnsureAbortUploadsRule (6.58s)1402=== CONT TestCacheConfigHandler1403=== RUN TestCacheConfigHandler/full_config,_no_issuer1404=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1405=== RUN TestCacheConfigHandler/no_cache_url_configured1406=== PAUSE TestCacheConfigHandler/no_cache_url_configured1407=== RUN TestCacheConfigHandler/no_signing_keys1408=== PAUSE TestCacheConfigHandler/no_signing_keys1409=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1410=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1411=== CONT TestCacheStatsHandler1412--- PASS: TestClientCADerivations (7.29s)1413=== CONT TestPush_RootsAreLockedInByteOrder14142026/11/09 12:01:35 INFO Aborted multipart uploads count=0 kept=014152026/11/09 12:01:35 WARN Force mode enabled - objects will be deleted immediately without grace period14162026/11/09 12:01:35 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=014172026/11/09 12:01:35 INFO Vacuumed table table=pending_closures14182026/11/09 12:01:35 INFO Vacuumed table table=pending_objects14192026/11/09 12:01:35 INFO Vacuumed table table=multipart_uploads14202026/11/09 12:01:35 INFO Vacuumed table table=closures14212026/11/09 12:01:35 INFO Vacuumed table table=objects14222026/11/09 12:01:35 INFO Aborted multipart uploads count=0 kept=014232026/11/09 12:01:35 WARN Force mode enabled - objects will be deleted immediately without grace period14242026/11/09 12:01:35 INFO Received uploads request method=POST path=/api/pending_closures14252026/11/09 12:01:35 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=014262026/11/09 12:01:35 INFO Vacuumed table table=pending_closures14272026/11/09 12:01:35 INFO Vacuumed table table=pending_objects14282026/11/09 12:01:35 INFO Vacuumed table table=multipart_uploads14292026/11/09 12:01:35 INFO Vacuumed table table=closures14302026/11/09 12:01:36 INFO Vacuumed table table=objects1431--- PASS: TestSweepSkipsRowsLockedByPush (6.69s)1432=== CONT TestClientErrorHandling1433=== RUN TestClientErrorHandling/InvalidStorePath1434=== PAUSE TestClientErrorHandling/InvalidStorePath1435=== RUN TestClientErrorHandling/InvalidAuthToken1436=== PAUSE TestClientErrorHandling/InvalidAuthToken1437=== RUN TestClientErrorHandling/ServerNotAvailable1438=== PAUSE TestClientErrorHandling/ServerNotAvailable1439=== CONT TestService_AuthMiddleware_OIDC14402026/11/09 12:01:36 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:49415/oidc14412026/11/09 12:01:36 INFO Aborted multipart uploads count=0 kept=014422026/11/09 12:01:36 WARN Force mode enabled - objects will be deleted immediately without grace period14432026/11/09 12:01:36 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."14442026/11/09 12:01:36 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."1445--- PASS: TestFailedS3DeleteKeepsTombstone (6.79s)1446=== CONT TestService_ReadScope_PublicByDefault14472026/11/09 12:01:36 INFO Received uploads request method=POST path=/api/pending_closures14482026/11/09 12:01:36 INFO Aborted multipart uploads count=0 kept=014492026/11/09 12:01:36 INFO Aborted multipart uploads count=0 kept=014502026/11/09 12:01:36 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=014512026/11/09 12:01:36 WARN Force mode enabled - objects will be deleted immediately without grace period14522026/11/09 12:01:36 INFO Vacuumed table table=pending_closures14532026/11/09 12:01:36 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=014542026/11/09 12:01:36 INFO Vacuumed table table=pending_closures14552026/11/09 12:01:36 INFO Vacuumed table table=pending_objects14562026/11/09 12:01:36 INFO Vacuumed table table=multipart_uploads14572026/11/09 12:01:36 INFO Vacuumed table table=pending_objects14582026/11/09 12:01:36 INFO Vacuumed table table=closures14592026/11/09 12:01:36 INFO Vacuumed table table=multipart_uploads14602026/11/09 12:01:36 INFO Vacuumed table table=objects1461--- PASS: TestGCMetrics (6.84s)1462=== CONT TestClientIntegration14632026/11/09 12:01:36 INFO Vacuumed table table=closures14642026/11/09 12:01:36 INFO Vacuumed table table=objects14652026/11/09 12:01:36 INFO Aborted multipart uploads count=0 kept=014662026/11/09 12:01:36 WARN Force mode enabled - objects will be deleted immediately without grace period14672026/11/09 12:01:36 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=014682026/11/09 12:01:36 INFO Vacuumed table table=pending_closures14692026/11/09 12:01:36 INFO Vacuumed table table=pending_objects14702026/11/09 12:01:36 INFO Vacuumed table table=multipart_uploads14712026/11/09 12:01:36 INFO Vacuumed table table=closures14722026/11/09 12:01:36 INFO Vacuumed table table=objects1473--- PASS: TestPushDedupSurvivesConcurrentGC (7.05s)1474=== CONT TestService_RequireScope_OIDC14752026/11/09 12:01:36 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:49426/oidc1476--- PASS: TestGCBugBareHashReferences (7.12s)1477=== CONT TestService_AuthMiddleware_MTLSBoundSubjects14782026/11/09 12:01:37 INFO Received uploads request method=POST path=/api/pending_closures1479--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (7.26s)1480=== CONT TestService_ReadAuthMiddleware14812026/11/09 12:01:37 ERROR failed to check GC advisory lock error="query pg_locks: failed to connect to `user=_tribuchetbld8 database=niks3`: /nonexistent/.s.PGSQL.5432 (/nonexistent): dial error: dial unix /nonexistent/.s.PGSQL.5432: connect: no such file or directory"1482--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (7.13s)1483=== CONT TestGenerateLandingPage1484--- PASS: TestGenerateLandingPage (0.00s)1485=== CONT TestService_readinessHandler14862026/11/09 12:01:37 INFO Aborted multipart uploads count=0 kept=014872026/11/09 12:01:37 WARN Force mode enabled - objects will be deleted immediately without grace period14882026/11/09 12:01:37 INFO Received uploads request method=POST path=/api/pending_closures1489--- PASS: TestTombstonedObjectOfferedWithoutWaiting (7.08s)1490=== CONT TestService_AuthMiddleware_MTLSProxyHeader14912026/11/09 12:01:38 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=3 objects-deleted-after-grace-period=3 objects-failed-to-delete=014922026/11/09 12:01:38 INFO Vacuumed table table=pending_closures14932026/11/09 12:01:38 INFO Vacuumed table table=pending_objects14942026/11/09 12:01:38 INFO Vacuumed table table=multipart_uploads14952026/11/09 12:01:38 INFO Vacuumed table table=closures14962026/11/09 12:01:38 INFO Vacuumed table table=objects1497--- PASS: TestGCSweepDeliversEachKeyOnce (8.21s)1498=== CONT TestService_AuthMiddleware14992026/11/09 12:01:38 INFO Received uploads request method=POST path=/api/pending_closures15002026/11/09 12:01:38 INFO Aborted multipart uploads count=0 kept=015012026/11/09 12:01:38 WARN Force mode enabled - objects will be deleted immediately without grace period15022026/11/09 12:01:38 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=015032026/11/09 12:01:38 INFO Vacuumed table table=pending_closures15042026/11/09 12:01:38 INFO Vacuumed table table=pending_objects15052026/11/09 12:01:38 INFO Vacuumed table table=multipart_uploads15062026/11/09 12:01:38 INFO Vacuumed table table=closures15072026/11/09 12:01:38 INFO Vacuumed table table=objects1508--- PASS: TestGCSweepSkipsPendingObjects (6.79s)1509=== CONT TestDeleteClosuresRacingPins15102026/11/09 12:01:38 INFO Received uploads request method=POST path=/api/pending_closures15112026/11/09 12:01:38 INFO Received uploads request method=POST path=/api/pending_closures15122026/11/09 12:01:38 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)15132026/11/09 12:01:38 INFO Uploading qx9h9fjfv4nmci1w0pcv9j578nk3nazp-b (256B)15142026/11/09 12:01:38 INFO Uploading h00j1vcxwdbxrbw15xmvy4rk1cxj9rzq-shared-dep (136B)15152026/11/09 12:01:39 WARN Failed to register uploaded object key=h00j1vcxwdbxrbw15xmvy4rk1cxj9rzq.ls error="server returned 404: 404 page not found\n"15162026/11/09 12:01:39 WARN Failed to register uploaded object key=2v1kyfk0nhhndn8sm0j5ivnzzblr1rkk.ls error="server returned 404: 404 page not found\n"15172026/11/09 12:01:39 WARN Failed to register uploaded object key=qx9h9fjfv4nmci1w0pcv9j578nk3nazp.ls error="server returned 404: 404 page not found\n"15182026/11/09 12:01:39 INFO Received uploads request method=POST path=/api/pending_closures15192026/11/09 12:01:39 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"15202026/11/09 12:01:39 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign15212026/11/09 12:01:39 WARN Failed to register uploaded object key=nar/177qk08jbgrd79bzlqajrr01wsh7ph2hr48a7llgy5m405zw6mmg.nar.zst error="server returned 404: 404 page not found\n"15222026/11/09 12:01:39 INFO Signed narinfos id=1 count=215232026/11/09 12:01:39 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign15242026/11/09 12:01:39 INFO Signed narinfos id=2 count=215252026/11/09 12:01:39 INFO Uploading 4 narinfos1526--- PASS: TestDeduplicatedObjectsRecordedAsPending (6.79s)1527=== CONT TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed15282026/11/09 12:01:39 WARN Failed to register uploaded object key=qx9h9fjfv4nmci1w0pcv9j578nk3nazp.narinfo error="server returned 404: 404 page not found\n"15292026/11/09 12:01:39 WARN Failed to register uploaded object key=h00j1vcxwdbxrbw15xmvy4rk1cxj9rzq.narinfo error="server returned 404: 404 page not found\n"15302026/11/09 12:01:39 WARN Failed to register uploaded object key=2v1kyfk0nhhndn8sm0j5ivnzzblr1rkk.narinfo error="server returned 404: 404 page not found\n"15312026/11/09 12:01:39 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete15322026/11/09 12:01:39 WARN Failed to register uploaded object key=h00j1vcxwdbxrbw15xmvy4rk1cxj9rzq.narinfo error="server returned 404: 404 page not found\n"15332026/11/09 12:01:39 INFO Completed upload id=1 objects=6 duration=15.060666ms15342026/11/09 12:01:39 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete15352026/11/09 12:01:39 INFO Completed upload id=2 objects=6 duration=896.667µs15362026/11/09 12:01:39 INFO Upload complete. (345ms)1537=== NAME TestClientFallsBackToClosures1538 client_pushes_test.go:112: Retrieved narinfo from S3:1539 StorePath: /private/var/tb/8/scratch/cde53c32ef764c64/build/TestClientFallsBackToClosures1052570651/001/store/h00j1vcxwdbxrbw15xmvy4rk1cxj9rzq-shared-dep1540 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1541 Compression: zstd1542 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821543 NarSize: 1361544 References: 1545 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1546 client_pushes_test.go:112: Retrieved narinfo from S3:1547 StorePath: /private/var/tb/8/scratch/cde53c32ef764c64/build/TestClientFallsBackToClosures1052570651/001/store/2v1kyfk0nhhndn8sm0j5ivnzzblr1rkk-a1548 URL: nar/177qk08jbgrd79bzlqajrr01wsh7ph2hr48a7llgy5m405zw6mmg.nar.zst1549 Compression: zstd1550 NarHash: sha256:177qk08jbgrd79bzlqajrr01wsh7ph2hr48a7llgy5m405zw6mmg1551 NarSize: 2561552 References: /private/var/tb/8/scratch/cde53c32ef764c64/build/TestClientFallsBackToClosures1052570651/001/store/h00j1vcxwdbxrbw15xmvy4rk1cxj9rzq-shared-dep1553 CA: text:sha256:1zpkd51nmh0kmcwml1r7pviiw91yjqgrp4a5vj19l3cbcfr292y91554 client_pushes_test.go:112: Retrieved narinfo from S3:1555 StorePath: /private/var/tb/8/scratch/cde53c32ef764c64/build/TestClientFallsBackToClosures1052570651/001/store/qx9h9fjfv4nmci1w0pcv9j578nk3nazp-b1556 URL: nar/177qk08jbgrd79bzlqajrr01wsh7ph2hr48a7llgy5m405zw6mmg.nar.zst1557 Compression: zstd1558 NarHash: sha256:177qk08jbgrd79bzlqajrr01wsh7ph2hr48a7llgy5m405zw6mmg1559 NarSize: 2561560 References: /private/var/tb/8/scratch/cde53c32ef764c64/build/TestClientFallsBackToClosures1052570651/001/store/h00j1vcxwdbxrbw15xmvy4rk1cxj9rzq-shared-dep1561 CA: text:sha256:1zpkd51nmh0kmcwml1r7pviiw91yjqgrp4a5vj19l3cbcfr292y91562--- PASS: TestClientFallsBackToClosures (7.75s)1563=== CONT TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed15642026/11/09 12:01:39 INFO Aborted multipart uploads count=1 kept=015652026/11/09 12:01:39 INFO Received cleanup request method=DELETE path=/api/pending_closures15662026/11/09 12:01:39 INFO Aborted multipart uploads count=1 kept=01567--- PASS: TestPendingCleanupUsesOneCutoff (12.10s)1568=== CONT TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed15692026/11/09 12:01:39 INFO lead: acquired remote=192.0.2.1:123415702026/11/09 12:01:39 INFO lead: released remote=192.0.2.1:12341571--- PASS: TestLeadIncumbentAnnouncesAtOnce (6.78s)1572=== CONT TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost15732026/11/09 12:01:39 INFO Received push request method=POST path=/api/pushes1574=== NAME TestPinProtectsFromGC1575 client_integration_test.go:778: Pinned store path: /private/var/tb/8/scratch/cde53c32ef764c64/build/TestPinProtectsFromGC279273268/001/store/zqdd7pxs5a9w8yd59krhiqfn4cbmzqi1-pinned-file.txt1576 client_integration_test.go:779: Unpinned store path: /private/var/tb/8/scratch/cde53c32ef764c64/build/TestPinProtectsFromGC279273268/001/store/gqxqqncdjxq2j94bbdpvyfcrzjnk8fhi-unpinned-file.txt15772026/11/09 12:01:39 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)15782026/11/09 12:01:39 INFO Uploading jjlimj5ah3kd3cs36z92q142i9q06a79-b (256B)15792026/11/09 12:01:39 INFO Uploading 7clz6g6ljd58fxfx331dw55xm8x3jal7-shared-dep (136B)15802026/11/09 12:01:40 WARN Failed to register uploaded object key=jjlimj5ah3kd3cs36z92q142i9q06a79.ls error="server returned 404: 404 page not found\n"15812026/11/09 12:01:40 WARN Failed to register uploaded object key=7clz6g6ljd58fxfx331dw55xm8x3jal7.ls error="server returned 404: 404 page not found\n"15822026/11/09 12:01:40 WARN Failed to register uploaded object key=nar/0v57fmahnv6cq2w49immhqbx3a74xflhf1fcypy1h3fflydpyk3g.nar.zst error="server returned 404: 404 page not found\n"15832026/11/09 12:01:40 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"15842026/11/09 12:01:40 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15852026/11/09 12:01:40 WARN Failed to register uploaded object key=397376pys7z1xiixnsk7grb46bcqwmk2.ls error="server returned 404: 404 page not found\n"15862026/11/09 12:01:40 INFO Signed narinfos id=1 count=315872026/11/09 12:01:40 INFO Uploading 3 narinfos15882026/11/09 12:01:40 INFO Received push request method=POST path=/api/pushes15892026/11/09 12:01:40 WARN Failed to register uploaded object key=jjlimj5ah3kd3cs36z92q142i9q06a79.narinfo error="server returned 404: 404 page not found\n"15902026/11/09 12:01:40 WARN Failed to register uploaded object key=397376pys7z1xiixnsk7grb46bcqwmk2.narinfo error="server returned 404: 404 page not found\n"15912026/11/09 12:01:40 INFO Received complete push request method=POST path=/api/pushes/1/complete15922026/11/09 12:01:40 WARN Failed to register uploaded object key=7clz6g6ljd58fxfx331dw55xm8x3jal7.narinfo error="server returned 404: 404 page not found\n"15932026/11/09 12:01:40 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15942026/11/09 12:01:40 INFO Uploading zqdd7pxs5a9w8yd59krhiqfn4cbmzqi1-pinned-file.txt (128B)15952026/11/09 12:01:40 INFO Completed push id=1 objects=8 duration=46.320042ms15962026/11/09 12:01:40 INFO Upload complete. (326ms)15972026/11/09 12:01:40 WARN Failed to register uploaded object key=zqdd7pxs5a9w8yd59krhiqfn4cbmzqi1.ls error="server returned 404: 404 page not found\n"1598=== NAME TestClientPushesUseOnePush1599 client_pushes_test.go:97: Retrieved narinfo from S3:1600 StorePath: /private/var/tb/8/scratch/cde53c32ef764c64/build/TestClientPushesUseOnePush266643134/001/store/7clz6g6ljd58fxfx331dw55xm8x3jal7-shared-dep1601 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1602 Compression: zstd1603 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821604 NarSize: 1361605 References: 1606 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1607 client_pushes_test.go:97: Retrieved narinfo from S3:1608 StorePath: /private/var/tb/8/scratch/cde53c32ef764c64/build/TestClientPushesUseOnePush266643134/001/store/397376pys7z1xiixnsk7grb46bcqwmk2-a1609 URL: nar/0v57fmahnv6cq2w49immhqbx3a74xflhf1fcypy1h3fflydpyk3g.nar.zst1610 Compression: zstd1611 NarHash: sha256:0v57fmahnv6cq2w49immhqbx3a74xflhf1fcypy1h3fflydpyk3g1612 NarSize: 2561613 References: /private/var/tb/8/scratch/cde53c32ef764c64/build/TestClientPushesUseOnePush266643134/001/store/7clz6g6ljd58fxfx331dw55xm8x3jal7-shared-dep1614 CA: text:sha256:14dbgm9w918c5gyzqm4hszz3dxiglhph6x51ic5nm9xxrpqfg9fb1615 client_pushes_test.go:97: Retrieved narinfo from S3:1616 StorePath: /private/var/tb/8/scratch/cde53c32ef764c64/build/TestClientPushesUseOnePush266643134/001/store/jjlimj5ah3kd3cs36z92q142i9q06a79-b1617 URL: nar/0v57fmahnv6cq2w49immhqbx3a74xflhf1fcypy1h3fflydpyk3g.nar.zst1618 Compression: zstd1619 NarHash: sha256:0v57fmahnv6cq2w49immhqbx3a74xflhf1fcypy1h3fflydpyk3g1620 NarSize: 2561621 References: /private/var/tb/8/scratch/cde53c32ef764c64/build/TestClientPushesUseOnePush266643134/001/store/7clz6g6ljd58fxfx331dw55xm8x3jal7-shared-dep1622 CA: text:sha256:14dbgm9w918c5gyzqm4hszz3dxiglhph6x51ic5nm9xxrpqfg9fb16232026/11/09 12:01:40 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16242026/11/09 12:01:40 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"16252026/11/09 12:01:40 INFO Signed narinfos id=1 count=116262026/11/09 12:01:40 INFO Uploading 1 narinfos16272026/11/09 12:01:40 INFO lead: acquired remote=192.0.2.1:123416282026/11/09 12:01:40 INFO Received complete push request method=POST path=/api/pushes/1/complete16292026/11/09 12:01:40 WARN Failed to register uploaded object key=zqdd7pxs5a9w8yd59krhiqfn4cbmzqi1.narinfo error="server returned 404: 404 page not found\n"16302026/11/09 12:01:40 INFO Completed push id=1 objects=3 duration=24.815667ms1631--- PASS: TestClientPushesUseOnePush (8.04s)16322026/11/09 12:01:40 INFO Upload complete. (309ms)1633=== CONT TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed16342026/11/09 12:01:40 INFO Received push request method=POST path=/api/pushes16352026/11/09 12:01:40 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16362026/11/09 12:01:40 INFO Uploading gqxqqncdjxq2j94bbdpvyfcrzjnk8fhi-unpinned-file.txt (128B)16372026/11/09 12:01:40 WARN Failed to register uploaded object key=gqxqqncdjxq2j94bbdpvyfcrzjnk8fhi.ls error="server returned 404: 404 page not found\n"16382026/11/09 12:01:40 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign16392026/11/09 12:01:40 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"16402026/11/09 12:01:40 INFO Signed narinfos id=2 count=116412026/11/09 12:01:40 INFO Uploading 1 narinfos16422026/11/09 12:01:40 INFO lead: acquired remote=192.0.2.1:123416432026/11/09 12:01:40 INFO Received complete push request method=POST path=/api/pushes/2/complete16442026/11/09 12:01:40 WARN Failed to register uploaded object key=gqxqqncdjxq2j94bbdpvyfcrzjnk8fhi.narinfo error="server returned 404: 404 page not found\n"16452026/11/09 12:01:40 INFO Completed push id=2 objects=3 duration=1.08725ms16462026/11/09 12:01:40 INFO Upload complete. (218ms)16472026/11/09 12:01:40 INFO Starting cleanup of old closures method=DELETE path=/api/closures16482026/11/09 12:01:40 INFO Garbage collection started16492026/11/09 12:01:40 INFO Aborted multipart uploads count=0 kept=016502026/11/09 12:01:40 WARN Force mode enabled - objects will be deleted immediately without grace period16512026/11/09 12:01:41 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=016522026/11/09 12:01:41 INFO Vacuumed table table=pending_closures16532026/11/09 12:01:41 INFO Vacuumed table table=pending_objects16542026/11/09 12:01:41 INFO Vacuumed table table=multipart_uploads16552026/11/09 12:01:41 INFO Vacuumed table table=closures16562026/11/09 12:01:41 INFO Vacuumed table table=objects16572026/11/09 12:01:41 INFO lead: released remote=192.0.2.1:12341658--- PASS: TestLeadEndsOnShutdown (8.28s)1659=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info16602026/11/09 12:01:41 INFO Received uploads request method=POST path=/1661=== CONT TestIsValidUploadKey/narinfo1662=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1663=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key16642026/11/09 12:01:41 INFO Received request for more parts method=POST path=/1665=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key16662026/11/09 12:01:41 INFO Received complete multipart upload request method=POST path=/1667=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal16682026/11/09 12:01:41 INFO Received uploads request method=POST path=/1669--- PASS: TestUploadHandlersRejectInvalidKeys (0.08s)1670 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.01s)1671 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1672 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.01s)1673 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1674=== CONT TestIsValidUploadKey/build_log_plus_in_name1675=== CONT TestIsValidUploadKey/index.html1676=== CONT TestIsValidUploadKey/nix-cache-info1677=== CONT TestIsValidUploadKey/realisation_plus_in_output1678=== CONT TestIsValidUploadKey/realisation1679=== CONT TestIsValidUploadKey/build_log_equals1680=== CONT TestIsValidUploadKey/build_log_question_mark1681=== CONT TestIsValidUploadKey/traversal_nar1682=== CONT TestIsValidUploadKey/traversal1683=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1684=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1685=== CONT TestIsValidUploadKey/listing1686=== CONT TestIsValidUploadKey/build_log_home-manager_file1687=== CONT TestIsValidUploadKey/build_log1688=== CONT TestIsValidUploadKey/nar_xz1689=== CONT TestIsValidUploadKey/nar_plain1690=== CONT TestIsValidUploadKey/empty_key1691=== CONT TestIsValidUploadKey/unknown_type1692=== CONT TestIsValidUploadKey/absolute1693=== CONT TestIsValidUploadKey/nar_zst1694--- PASS: TestIsValidUploadKey (0.08s)1695 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1696 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1697 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1698 --- PASS: TestIsValidUploadKey/index.html (0.00s)1699 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1700 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1701 --- PASS: TestIsValidUploadKey/realisation (0.00s)1702 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1703 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1704 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1705 --- PASS: TestIsValidUploadKey/traversal (0.00s)1706 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1707 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1708 --- PASS: TestIsValidUploadKey/listing (0.00s)1709 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1710 --- PASS: TestIsValidUploadKey/build_log (0.00s)1711 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1712 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1713 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1714 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1715 --- PASS: TestIsValidUploadKey/absolute (0.00s)1716 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1717=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh17182026/11/09 12:01:41 INFO Received push request method=POST path=/api/pushes1719=== NAME TestClientMultipleUploads1720 client_integration_test.go:405: Created store path 0: /private/var/tb/8/scratch/cde53c32ef764c64/build/TestClientMultipleUploads2407306562/001/store/0543j0v88wpag79y54slanqjhb28mz9g-test-file-0.txt17212026/11/09 12:01:41 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)17222026/11/09 12:01:41 INFO Uploading kcsjp82yg4whgb8lv1s7d8w432y3h3if-shared-dep (136B)17232026/11/09 12:01:41 INFO Uploading xw4c3p7hr1q4zaz75xfyi7scyqsrlwnk-top (264B)17242026/11/09 12:01:41 WARN Failed to register uploaded object key=xw4c3p7hr1q4zaz75xfyi7scyqsrlwnk.ls error="server returned 404: 404 page not found\n"17252026/11/09 12:01:41 WARN Failed to register uploaded object key=nar/1w251wcm68q1h23cll4nvkxkgkzxq8lq4fcipdj1ffwkllxnm3cl.nar.zst error="server returned 404: 404 page not found\n"17262026/11/09 12:01:41 WARN Failed to register uploaded object key=kcsjp82yg4whgb8lv1s7d8w432y3h3if.ls error="server returned 404: 404 page not found\n"17272026/11/09 12:01:41 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17282026/11/09 12:01:41 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"17292026/11/09 12:01:41 INFO Signed narinfos id=1 count=217302026/11/09 12:01:41 INFO Uploading 2 narinfos1731 client_integration_test.go:405: Created store path 1: /private/var/tb/8/scratch/cde53c32ef764c64/build/TestClientMultipleUploads2407306562/001/store/agv7m7fxm6k769ci43g301k3cdbrfzcd-test-file-1.txt17322026/11/09 12:01:41 WARN Failed to register uploaded object key=xw4c3p7hr1q4zaz75xfyi7scyqsrlwnk.narinfo error="server returned 404: 404 page not found\n"17332026/11/09 12:01:41 INFO Received complete push request method=POST path=/api/pushes/1/complete17342026/11/09 12:01:41 WARN Failed to register uploaded object key=kcsjp82yg4whgb8lv1s7d8w432y3h3if.narinfo error="server returned 404: 404 page not found\n"1735 client_integration_test.go:405: Created store path 2: /private/var/tb/8/scratch/cde53c32ef764c64/build/TestClientMultipleUploads2407306562/001/store/33k5nwwgvsfhwfqwgb8nsxfm9w0wjgsz-test-file-2.txt17362026/11/09 12:01:41 INFO Completed push id=1 objects=6 duration=33.961541ms17372026/11/09 12:01:41 INFO Upload complete. (300ms)1738=== NAME TestClientSharedPathCommittedMidPush1739 client_integration_test.go:727: Retrieved narinfo from S3:1740 StorePath: /private/var/tb/8/scratch/cde53c32ef764c64/build/TestClientSharedPathCommittedMidPush2972993418/001/store/kcsjp82yg4whgb8lv1s7d8w432y3h3if-shared-dep1741 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1742 Compression: zstd1743 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821744 NarSize: 1361745 References: 1746 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1747 client_integration_test.go:727: Retrieved narinfo from S3:1748 StorePath: /private/var/tb/8/scratch/cde53c32ef764c64/build/TestClientSharedPathCommittedMidPush2972993418/001/store/xw4c3p7hr1q4zaz75xfyi7scyqsrlwnk-top1749 URL: nar/1w251wcm68q1h23cll4nvkxkgkzxq8lq4fcipdj1ffwkllxnm3cl.nar.zst1750 Compression: zstd1751 NarHash: sha256:1w251wcm68q1h23cll4nvkxkgkzxq8lq4fcipdj1ffwkllxnm3cl1752 NarSize: 2641753 References: /private/var/tb/8/scratch/cde53c32ef764c64/build/TestClientSharedPathCommittedMidPush2972993418/001/store/kcsjp82yg4whgb8lv1s7d8w432y3h3if-shared-dep1754 CA: text:sha256:0csp64m10q94hii7lbcz610dg00iy14rbyikpfj7zgfkh3i82maa1755--- PASS: TestClientSharedPathCommittedMidPush (7.72s)1756=== CONT TestProxyWriteTimeout/narinfo1757=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale17582026/11/09 12:01:41 INFO lead: released remote=192.0.2.1:123417592026/11/09 12:01:41 INFO Received push request method=POST path=/api/pushes17602026/11/09 12:01:41 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)17612026/11/09 12:01:41 INFO lead: acquired remote=192.0.2.1:123417622026/11/09 12:01:41 INFO Uploading 33k5nwwgvsfhwfqwgb8nsxfm9w0wjgsz-test-file-2.txt (160B)17632026/11/09 12:01:41 INFO Uploading agv7m7fxm6k769ci43g301k3cdbrfzcd-test-file-1.txt (160B)17642026/11/09 12:01:41 INFO Uploading 0543j0v88wpag79y54slanqjhb28mz9g-test-file-0.txt (160B)17652026/11/09 12:01:41 WARN Failed to register uploaded object key=agv7m7fxm6k769ci43g301k3cdbrfzcd.ls error="server returned 404: 404 page not found\n"17662026/11/09 12:01:41 WARN Failed to register uploaded object key=0543j0v88wpag79y54slanqjhb28mz9g.ls error="server returned 404: 404 page not found\n"17672026/11/09 12:01:41 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"17682026/11/09 12:01:41 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"17692026/11/09 12:01:41 WARN Failed to register uploaded object key=33k5nwwgvsfhwfqwgb8nsxfm9w0wjgsz.ls error="server returned 404: 404 page not found\n"17702026/11/09 12:01:41 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17712026/11/09 12:01:41 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"17722026/11/09 12:01:41 INFO Signed narinfos id=1 count=317732026/11/09 12:01:41 INFO Uploading 3 narinfos17742026/11/09 12:01:41 WARN Failed to register uploaded object key=agv7m7fxm6k769ci43g301k3cdbrfzcd.narinfo error="server returned 404: 404 page not found\n"17752026/11/09 12:01:41 WARN Failed to register uploaded object key=33k5nwwgvsfhwfqwgb8nsxfm9w0wjgsz.narinfo error="server returned 404: 404 page not found\n"17762026/11/09 12:01:41 INFO Received complete push request method=POST path=/api/pushes/1/complete17772026/11/09 12:01:41 WARN Failed to register uploaded object key=0543j0v88wpag79y54slanqjhb28mz9g.narinfo error="server returned 404: 404 page not found\n"17782026/11/09 12:01:42 INFO Completed push id=1 objects=9 duration=17.487833ms17792026/11/09 12:01:42 INFO Upload complete. (273ms)1780=== NAME TestClientMultipleUploads1781 client_integration_test.go:416: Uploaded 3 paths in 312.160125ms1782--- PASS: TestCacheStatsHandler (6.67s)1783=== CONT TestProxyWriteTimeout/unknown_size1784=== CONT TestProxyWriteTimeout/10_GiB_nar1785=== CONT TestProxyWriteTimeout/1_GiB_nar1786--- PASS: TestProxyWriteTimeout (0.07s)1787 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1788 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1789 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1790 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1791=== CONT TestPendingClosureWriteTimeout/empty1792=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1793=== NAME TestClientWithDependencies1794 client_integration_test.go:660: Built derivation: /private/var/tb/8/scratch/cde53c32ef764c64/build/TestClientWithDependencies1173455835/001/store/wcq884k5q396vyhznygvhzgjxcnnf9mj-test-script1795--- PASS: TestClientMultipleUploads (7.15s)1796=== CONT TestPendingClosureWriteTimeout/670k_objects1797=== CONT TestPendingClosureWriteTimeout/400_objects1798=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart17992026/11/09 12:01:42 INFO Received complete multipart upload request method=POST path=/1800=== NAME TestClientWithDependencies1801 client_integration_test.go:662: Found 1 dependencies (including self)1802=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts18032026/11/09 12:01:42 INFO Received request for more parts method=POST path=/1804=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure18052026/11/09 12:01:42 INFO Received uploads request method=POST path=/18062026/11/09 12:01:42 INFO Received push request method=POST path=/api/pushes18072026/11/09 12:01:42 INFO Received push request method=POST path=/api/pushes18082026/11/09 12:01:42 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18092026/11/09 12:01:42 INFO Uploading wcq884k5q396vyhznygvhzgjxcnnf9mj-test-script (136B)1810=== NAME TestOrphanedObjectsGCStressTest1811 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains18122026/11/09 12:01:42 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"18132026/11/09 12:01:42 WARN Failed to register uploaded object key=wcq884k5q396vyhznygvhzgjxcnnf9mj.ls error="server returned 404: 404 page not found\n"18142026/11/09 12:01:42 WARN Failed to register uploaded object key=log/hcrrjlrxb0955gwf31cmcqrdnw226ckz-test-script.drv error="server returned 404: 404 page not found\n"18152026/11/09 12:01:42 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18162026-11-09 12:01:42.642 UTC [27780] ERROR: could not obtain lock on row in relation "closures"18172026-11-09 12:01:42.642 UTC [27780] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT18182026/11/09 12:01:42 INFO Signed narinfos id=1 count=118192026/11/09 12:01:42 INFO Uploading 1 narinfos18202026-11-09 12:01:42.650 UTC [27780] ERROR: could not obtain lock on row in relation "closures"18212026-11-09 12:01:42.650 UTC [27780] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT18222026-11-09 12:01:42.650 UTC [27780] ERROR: could not obtain lock on row in relation "closures"18232026-11-09 12:01:42.650 UTC [27780] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT18242026-11-09 12:01:42.655 UTC [27780] ERROR: could not obtain lock on row in relation "closures"18252026-11-09 12:01:42.655 UTC [27780] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT18262026-11-09 12:01:42.656 UTC [27780] ERROR: could not obtain lock on row in relation "closures"18272026-11-09 12:01:42.656 UTC [27780] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT18282026/11/09 12:01:42 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=01829=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1830=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1831=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1832=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1833=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1834=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1835=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1836=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1837=== CONT TestResolveDBConnectionString/flag_wins1838=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1839=== CONT TestResolveDBConnectionString/nothing_configured1840=== CONT TestResolveDBConnectionString/missing_file_is_an_error1841=== CONT TestResolveDBConnectionString/file_when_flag_empty1842=== CONT TestRetryableCompletionError/nil1843=== CONT TestRetryableCompletionError/context_canceled1844=== CONT TestRetryableCompletionError/deadline_exceeded1845=== CONT TestRetryableCompletionError/no_such_upload1846=== CONT TestRetryableCompletionError/transport_failure1847=== CONT TestRetryableCompletionError/degraded_quorum1848=== CONT TestRetryableCompletionError/access_denied1849=== CONT TestRetryableCompletionError/throttled1850=== CONT TestRetryableCompletionError/invalid_part1851=== CONT TestRetryableCompletionError/bad_gateway1852--- PASS: TestRetryableCompletionError (0.01s)1853 --- PASS: TestRetryableCompletionError/nil (0.00s)1854 --- PASS: TestRetryableCompletionError/context_canceled (0.00s)1855 --- PASS: TestRetryableCompletionError/deadline_exceeded (0.00s)1856 --- PASS: TestRetryableCompletionError/no_such_upload (0.00s)1857 --- PASS: TestRetryableCompletionError/transport_failure (0.00s)1858 --- PASS: TestRetryableCompletionError/degraded_quorum (0.00s)1859 --- PASS: TestRetryableCompletionError/access_denied (0.00s)1860 --- PASS: TestRetryableCompletionError/throttled (0.00s)1861 --- PASS: TestRetryableCompletionError/invalid_part (0.00s)1862 --- PASS: TestRetryableCompletionError/bad_gateway (0.00s)1863=== CONT TestPush_RejectsBadRequests/no_roots1864--- PASS: TestResolveDBConnectionString (0.02s)1865 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1866 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1867 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1868 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1869 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)18702026/11/09 12:01:42 INFO Received push request method=POST path=/api/pushes1871=== CONT TestPush_RejectsBadRequests/bad_root18722026/11/09 12:01:42 INFO Received push request method=POST path=/api/pushes1873=== CONT TestPush_RejectsBadRequests/root_not_in_objects18742026/11/09 12:01:42 INFO Received push request method=POST path=/api/pushes1875=== CONT TestPush_RejectsBadRequests/no_objects18762026/11/09 12:01:42 INFO Received create pin request method=POST path=/api/pins/myapp18772026/11/09 12:01:42 INFO Received push request method=POST path=/api/pushes1878=== CONT TestIsValidCachePath/narinfo1879--- PASS: TestPush_RejectsBadRequests (2.98s)1880 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)1881 --- PASS: TestPush_RejectsBadRequests/bad_root (0.02s)1882 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)1883 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)1884=== CONT TestIsValidCachePath/index.html18852026/11/09 12:01:42 INFO Received complete push request method=POST path=/api/pushes/1/complete1886=== CONT TestIsValidCachePath/short_hash1887=== CONT TestIsValidCachePath/wrong_extension1888=== CONT TestIsValidCachePath/leading_slash1889=== CONT TestIsValidCachePath/empty1890=== CONT TestIsValidCachePath/random_path1891=== CONT TestIsValidCachePath/invalid_char_u1892=== CONT TestIsValidCachePath/invalid_char_e1893=== CONT TestIsValidCachePath/traversal_in_middle1894=== CONT TestIsValidCachePath/traversal_parent1895=== CONT TestIsValidCachePath/nar_uncompressed1896=== CONT TestIsValidCachePath/nix-cache-info1897=== CONT TestIsValidCachePath/realisation1898=== CONT TestIsValidCachePath/log1899=== CONT TestIsValidCachePath/ls1900=== CONT TestIsValidCachePath/nar_xz1901=== CONT TestIsValidCachePath/nar_bz21902=== CONT TestIsValidCachePath/nar_zst1903=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars19042026/11/09 12:01:42 WARN Failed to register uploaded object key=wcq884k5q396vyhznygvhzgjxcnnf9mj.narinfo error="server returned 404: 404 page not found\n"1905--- PASS: TestIsValidCachePath (0.00s)1906 --- PASS: TestIsValidCachePath/narinfo (0.00s)1907 --- PASS: TestIsValidCachePath/index.html (0.00s)1908 --- PASS: TestIsValidCachePath/short_hash (0.00s)1909 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1910 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1911 --- PASS: TestIsValidCachePath/empty (0.00s)1912 --- PASS: TestIsValidCachePath/random_path (0.00s)1913 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1914 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1915 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1916 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1917 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1918 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1919 --- PASS: TestIsValidCachePath/realisation (0.00s)1920 --- PASS: TestIsValidCachePath/log (0.00s)1921 --- PASS: TestIsValidCachePath/ls (0.00s)1922 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1923 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1924 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1925 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1926=== CONT TestParseSingleRange/none1927=== CONT TestParseSingleRange/open-ended1928=== CONT TestParseSingleRange/start_far_past_EOF1929=== CONT TestParseSingleRange/start_past_EOF1930=== CONT TestParseSingleRange/single_byte1931=== CONT TestParseSingleRange/suffix_exceeds_size1932=== CONT TestParseSingleRange/suffix1933=== CONT TestParseSingleRange/end_clamped_to_size1934=== CONT TestParseSingleRange/malformed_both_empty1935=== CONT TestParseSingleRange/closed1936=== CONT TestParseSingleRange/malformed_end_before_start1937=== CONT TestParseSingleRange/multi-range_ignored1938=== CONT TestParseSingleRange/malformed_no_dash1939=== CONT TestParseSingleRange/unknown_unit1940=== CONT TestServerTLSConfig/no_client_CA1941--- PASS: TestParseSingleRange (0.02s)1942 --- PASS: TestParseSingleRange/none (0.00s)1943 --- PASS: TestParseSingleRange/open-ended (0.00s)1944 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1945 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1946 --- PASS: TestParseSingleRange/single_byte (0.00s)1947 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1948 --- PASS: TestParseSingleRange/suffix (0.00s)1949 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1950 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1951 --- PASS: TestParseSingleRange/closed (0.00s)1952 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1953 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1954 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1955 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1956=== CONT TestServerTLSConfig/not_a_PEM_file1957--- PASS: TestPush_RootsAreLockedInByteOrder (7.35s)1958=== CONT TestServerTLSConfig/missing_CA_file1959=== CONT TestGCEndsOnShutdown/before_the_run1960=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1961--- PASS: TestServerTLSConfig (0.00s)1962 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1963 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1964 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.02s)1965=== NAME TestOrphanedObjectsGCStressTest1966 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion19672026/11/09 12:01:42 INFO Completed push id=1 objects=4 duration=140.433292ms19682026/11/09 12:01:42 INFO Upload complete. (758ms)19692026/11/09 12:01:42 INFO Created/updated pin name=myapp store_path=/private/var/tb/8/scratch/cde53c32ef764c64/build/TestPinProtectsFromGC279273268/001/store/zqdd7pxs5a9w8yd59krhiqfn4cbmzqi1-pinned-file.txt narinfo_key=zqdd7pxs5a9w8yd59krhiqfn4cbmzqi1.narinfo19702026/11/09 12:01:42 INFO Starting cleanup of old closures method=DELETE path=/api/closures19712026/11/09 12:01:42 INFO Garbage collection started1972=== NAME TestClientWithDependencies1973 client_integration_test.go:664: Skipping nix copy test - isolated store (/private/var/tb/8/scratch/cde53c32ef764c64/build/TestClientWithDependencies1173455835/001/store) requires matching store prefix1974--- PASS: TestClientWithDependencies (7.92s)1975=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete19762026/11/09 12:01:42 INFO Aborted multipart uploads count=0 kept=019772026/11/09 12:01:42 INFO lead: released remote=192.0.2.1:123419782026/11/09 12:01:42 WARN Force mode enabled - objects will be deleted immediately without grace period1979--- PASS: TestLeadElectsOneAndHandsOver (9.12s)1980=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows19812026/11/09 12:01:42 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=019822026/11/09 12:01:42 INFO Vacuumed table table=pending_closures19832026/11/09 12:01:42 INFO Vacuumed table table=pending_objects19842026/11/09 12:01:42 INFO Vacuumed table table=multipart_uploads1985--- PASS: TestService_ReadScope_PublicByDefault (6.80s)1986=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check19872026/11/09 12:01:42 INFO Vacuumed table table=closures19882026/11/09 12:01:42 INFO Vacuumed table table=objects1989=== NAME TestClientIntegration1990 client_integration_test.go:291: Created store path: /private/var/tb/8/scratch/cde53c32ef764c64/build/TestClientIntegration1812520421/002/store/52fq9xwzawbwcalwgf32sh78r92z002m-test-file.txt1991=== CONT TestCacheConfigHandler/full_config,_no_issuer1992=== CONT TestCacheConfigHandler/no_signing_keys1993--- PASS: TestUploadHandlersRejectOversizedBody (0.15s)1994 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.02s)1995 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.02s)1996 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (1.64s)1997=== CONT TestCacheConfigHandler/no_cache_url_configured1998=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1999=== CONT TestClientErrorHandling/InvalidStorePath2000--- PASS: TestCacheConfigHandler (0.00s)2001 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)2002 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)2003 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)2004 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)2005=== RUN TestService_RequireScope_OIDC/builder_may_write2006=== PAUSE TestService_RequireScope_OIDC/builder_may_write2007=== RUN TestService_RequireScope_OIDC/builder_may_not_admin2008=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin2009=== RUN TestService_RequireScope_OIDC/ops_may_admin2010=== PAUSE TestService_RequireScope_OIDC/ops_may_admin2011=== RUN TestService_RequireScope_OIDC/ops_may_not_write2012=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write2013=== RUN TestService_RequireScope_OIDC/reader_may_not_write2014=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write2015=== RUN TestService_RequireScope_OIDC/static_token_may_admin2016=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin2017=== RUN TestService_RequireScope_OIDC/static_token_may_write2018=== PAUSE TestService_RequireScope_OIDC/static_token_may_write2019=== RUN TestService_RequireScope_OIDC/reader_may_read2020=== PAUSE TestService_RequireScope_OIDC/reader_may_read2021=== RUN TestService_RequireScope_OIDC/writer_implies_read2022=== PAUSE TestService_RequireScope_OIDC/writer_implies_read2023=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read2024=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read2025=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc2026=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc2027=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc2028=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc2029=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read2030=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read2031=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read2032=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read2033=== CONT TestClientErrorHandling/ServerNotAvailable20342026/11/09 12:01:43 INFO Received push request method=POST path=/api/pushes20352026/11/09 12:01:43 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)20362026/11/09 12:01:43 INFO Uploading 52fq9xwzawbwcalwgf32sh78r92z002m-test-file.txt (152B)20372026/11/09 12:01:44 WARN Failed to register uploaded object key=52fq9xwzawbwcalwgf32sh78r92z002m.ls error="server returned 404: 404 page not found\n"20382026/11/09 12:01:44 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign20392026/11/09 12:01:44 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"20402026/11/09 12:01:44 INFO Signed narinfos id=1 count=120412026/11/09 12:01:44 INFO Uploading 1 narinfos20422026/11/09 12:01:44 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20432026/11/09 12:01:44 INFO Received complete push request method=POST path=/api/pushes/1/complete20442026/11/09 12:01:44 WARN Failed to register uploaded object key=52fq9xwzawbwcalwgf32sh78r92z002m.narinfo error="server returned 404: 404 page not found\n"20452026/11/09 12:01:44 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"20462026/11/09 12:01:44 WARN mTLS auth: bound subjects configured but subject DN unavailable20472026/11/09 12:01:44 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"2048--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (7.03s)2049=== CONT TestClientErrorHandling/InvalidAuthToken20502026/11/09 12:01:44 INFO Completed push id=1 objects=3 duration=15.872458ms20512026/11/09 12:01:44 INFO Upload complete. (235ms)20522026/11/09 12:01:44 INFO All 1 paths already cached2053=== NAME TestClientIntegration2054 client_integration_test.go:317: Retrieved narinfo from S3:2055 StorePath: /private/var/tb/8/scratch/cde53c32ef764c64/build/TestClientIntegration1812520421/002/store/52fq9xwzawbwcalwgf32sh78r92z002m-test-file.txt2056 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst2057 Compression: zstd2058 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk12059 NarSize: 1522060 References: 2061 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk12062 client_integration_test.go:318: Retrieved .ls file from S3 (compressed size: 77 bytes)2063 client_integration_test.go:318: Decompressed .ls content (64 bytes):2064 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}20652026/11/09 12:01:44 WARN Request failed, retrying attempt=2 backoff=186.993378ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2066--- PASS: TestService_ReadAuthMiddleware (7.03s)2067=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2068=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected20692026/11/09 12:01:44 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]2070=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2071=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected20722026/11/09 12:01:44 WARN Authentication failed token_preview=eyJhbGciOi...KACtqNXRhQ token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2073=== CONT TestService_RequireScope_OIDC/builder_may_write20742026/11/09 12:01:44 WARN Request failed, retrying attempt=3 backoff=363.817116ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2075=== CONT TestService_RequireScope_OIDC/reader_may_read2076=== CONT TestService_RequireScope_OIDC/static_token_may_write2077=== CONT TestService_RequireScope_OIDC/static_token_may_admin2078=== CONT TestService_RequireScope_OIDC/reader_may_not_write2079=== CONT TestService_RequireScope_OIDC/ops_may_not_write2080--- PASS: TestService_AuthMiddleware_OIDC (6.68s)2081 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2082 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2083 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2084 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)2085=== CONT TestService_RequireScope_OIDC/ops_may_admin2086=== CONT TestService_RequireScope_OIDC/writer_implies_read2087=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2088=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc2089=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read2090=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read20912026/11/09 12:01:44 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]2092=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc2093=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2094--- PASS: TestService_RequireScope_OIDC (7.06s)2095 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2096 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2097 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2098 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2099 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2100 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2101 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2102 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2103 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2104 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)2105 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)2106 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)2107 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)2108 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)21092026/11/09 12:01:44 INFO Received push request method=POST path=/api/pushes21102026/11/09 12:01:44 INFO Object in database but missing from S3 key=52fq9xwzawbwcalwgf32sh78r92z002m.ls21112026/11/09 12:01:44 WARN Found objects in DB but missing from S3, will re-upload count=121122026/11/09 12:01:44 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)21132026/11/09 12:01:44 INFO Received complete push request method=POST path=/api/pushes/2/complete21142026/11/09 12:01:44 WARN Failed to register uploaded object key=52fq9xwzawbwcalwgf32sh78r92z002m.ls error="server returned 404: 404 page not found\n"21152026/11/09 12:01:44 INFO Completed push id=2 objects=3 duration=1.576041ms21162026/11/09 12:01:44 INFO Upload complete. (195ms)2117=== NAME TestClientIntegration2118 client_integration_test.go:335: Retrieved .ls file from S3 (compressed size: 62 bytes)2119 client_integration_test.go:335: Decompressed .ls content (49 bytes):2120 {"version":1,"root":{"type":"regular","size":39}}21212026/11/09 12:01:44 WARN readiness check failed error="closed pool"2122--- PASS: TestService_readinessHandler (7.28s)21232026/11/09 12:01:44 WARN Request failed, retrying attempt=4 backoff=837.238521ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2124=== NAME TestPinProtectsFromGC2125 client_integration_test.go:887: Pin successfully protected closure from garbage collection2126--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (7.00s)21272026/11/09 12:01:44 INFO Received push request method=POST path=/api/pushes21282026/11/09 12:01:44 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)2129--- PASS: TestPinProtectsFromGC (11.99s)21302026/11/09 12:01:45 INFO Received complete push request method=POST path=/api/pushes/3/complete21312026/11/09 12:01:45 WARN Failed to register uploaded object key=52fq9xwzawbwcalwgf32sh78r92z002m.ls error="server returned 404: 404 page not found\n"21322026/11/09 12:01:45 INFO Completed push id=3 objects=3 duration=1ms21332026/11/09 12:01:45 INFO Upload complete. (175ms)2134=== NAME TestClientIntegration2135 client_integration_test.go:352: Retrieved .ls file from S3 (compressed size: 62 bytes)2136 client_integration_test.go:352: Decompressed .ls content (49 bytes):2137 {"version":1,"root":{"type":"regular","size":39}}2138 client_integration_test.go:363: Testing garbage collection...21392026/11/09 12:01:45 INFO Starting cleanup of old closures method=DELETE path=/api/closures21402026/11/09 12:01:45 INFO Garbage collection started21412026/11/09 12:01:45 INFO Aborted multipart uploads count=0 kept=021422026/11/09 12:01:45 WARN Force mode enabled - objects will be deleted immediately without grace period21432026/11/09 12:01:45 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"2144--- PASS: TestService_AuthMiddleware (6.89s)21452026/11/09 12:01:45 WARN Request failed, retrying attempt=5 backoff=1.567044664s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present21462026/11/09 12:01:45 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=3 objects-failed-to-delete=021472026/11/09 12:01:45 INFO Vacuumed table table=pending_closures21482026/11/09 12:01:45 INFO Vacuumed table table=pending_objects21492026/11/09 12:01:45 INFO Vacuumed table table=multipart_uploads21502026/11/09 12:01:45 INFO Vacuumed table table=closures21512026/11/09 12:01:45 INFO Vacuumed table table=objects21522026/11/09 12:01:46 INFO Received uploads request method=POST path=/api/pending_closures21532026/11/09 12:01:46 INFO Received uploads request method=POST path=/api/pending_closures21542026/11/09 12:01:47 INFO Received uploads request method=POST path=/api/pending_closures21552026/11/09 12:01:47 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02156=== NAME TestClientIntegration2157 client_integration_test.go:370: Objects in database after GC:2158 client_integration_test.go:370: Successfully deleted all objects with GC --force21592026/11/09 12:01:47 WARN Request failed, retrying attempt=1 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2160--- PASS: TestClientIntegration (10.72s)21612026/11/09 12:01:47 WARN Request failed, retrying attempt=2 backoff=218.482439ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21622026/11/09 12:01:47 INFO Received uploads request method=POST path=/api/pending_closures21632026/11/09 12:01:47 WARN Request failed, retrying attempt=3 backoff=400.873346ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21642026/11/09 12:01:47 INFO Received uploads request method=POST path=/api/pending_closures21652026/11/09 12:01:47 WARN Request failed, retrying attempt=4 backoff=777.48927ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21662026/11/09 12:01:48 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21672026/11/09 12:01:48 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000100000000000000000000.nar.zst upload_id=ZGQ5NTdhZjYtYWRmOS00MzVkLThhOTctMTkyMGFkNjU2YzZhLmFhYTUzNTEwLWFkOGMtNDU0Ni05ZWRlLTZmMTBiNDIwYzA0ZHgxNzk0MjI1NzA2MzE2MTY5MDAw parts=1021682026/11/09 12:01:48 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21692026/11/09 12:01:48 INFO Completed upload id=1 objects=3 duration=19.285667ms21702026/11/09 12:01:48 WARN Request failed, retrying attempt=5 backoff=1.468639338s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21712026/11/09 12:01:48 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21722026/11/09 12:01:48 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000400000000000000000000.nar.zst upload_id=ZGQ5NTdhZjYtYWRmOS00MzVkLThhOTctMTkyMGFkNjU2YzZhLjAxOTlmYWI0LTMwZWMtNDE0My1iMzE5LTMwYzUzZTljZjdmMngxNzk0MjI1NzA2Njg3NTM3MDAw parts=1021732026/11/09 12:01:48 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21742026/11/09 12:01:48 INFO Completed upload id=1 objects=3 duration=14.611042ms21752026/11/09 12:01:48 INFO Received uploads request method=POST path=/api/pending_closures21762026/11/09 12:01:49 INFO Received uploads request method=POST path=/api/pending_closures21772026/11/09 12:01:49 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000100000000000000000000.nar.zst21782026/11/09 12:01:49 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0001.narinfo21792026/11/09 12:01:49 INFO Received uploads request method=POST path=/api/pending_closures21802026/11/09 12:01:49 INFO Received complete multipart upload request method=POST path=/api/multipart/complete2181--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2182 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (7.58s)2183 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (7.57s)21842026/11/09 12:01:49 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000500000000000000000000.nar.zst upload_id=ZGQ5NTdhZjYtYWRmOS00MzVkLThhOTctMTkyMGFkNjU2YzZhLjk4YTk1M2Q2LWIyNjgtNDMzYy05NWIxLTI3MmYxMjhmZTNkMngxNzk0MjI1NzA3MjQ4NDYwMDAw parts=1021852026/11/09 12:01:49 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21862026/11/09 12:01:49 INFO Completed upload id=1 objects=3 duration=15.017834ms21872026/11/09 12:01:49 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21882026/11/09 12:01:49 INFO Aborted multipart uploads count=0 kept=021892026/11/09 12:01:49 WARN Force mode enabled - objects will be deleted immediately without grace period21902026/11/09 12:01:49 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:65531/bucket101/?delete=\": context canceled"21912026/11/09 12:01:49 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000300000000000000000000.nar.zst upload_id=ZGQ5NTdhZjYtYWRmOS00MzVkLThhOTctMTkyMGFkNjU2YzZhLmZkZDQwZGFkLTliNjEtNGI5Mi1hNzcwLWVlMWJkZWVmNzVmYXgxNzk0MjI1NzA3NTkwMjg2MDAw parts=1021922026/11/09 12:01:49 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21932026/11/09 12:01:49 INFO Completed upload id=1 objects=3 duration=9.151833ms21942026/11/09 12:01:49 INFO Received uploads request method=POST path=/api/pending_closures21952026/11/09 12:01:49 INFO Received uploads request method=POST path=/api/pending_closures21962026/11/09 12:01:49 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000500000000000000000000.nar.zst21972026/11/09 12:01:49 WARN Found objects in DB but missing from S3, will re-upload count=121982026/11/09 12:01:49 INFO Received complete multipart upload request method=POST path=/api/multipart/complete2199--- PASS: TestPendingClosureWriteTimeout (0.08s)2200 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2201 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2202 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2203 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (7.97s)22042026/11/09 12:01:50 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000200000000000000000000.nar.zst upload_id=ZGQ5NTdhZjYtYWRmOS00MzVkLThhOTctMTkyMGFkNjU2YzZhLmQ1MzRmOGQ0LTdmOTktNDJkNC05MTgwLTgyN2NiZTQyMmQ1ZngxNzk0MjI1NzA3OTg3OTM4MDAw parts=1022052026/11/09 12:01:50 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: sending request: request failed after retries: Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused"22062026/11/09 12:01:50 WARN Request failed, retrying attempt=1 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22072026/11/09 12:01:50 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22082026/11/09 12:01:50 INFO Completed upload id=1 objects=3 duration=17.671208ms22092026/11/09 12:01:50 INFO Received uploads request method=POST path=/api/pending_closures22102026/11/09 12:01:50 WARN Request failed, retrying attempt=2 backoff=192.099022ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22112026/11/09 12:01:50 INFO Received uploads request method=POST path=/api/pending_closures22122026/11/09 12:01:50 INFO Aborted multipart uploads count=0 kept=022132026/11/09 12:01:50 WARN Force mode enabled - objects will be deleted immediately without grace period22142026/11/09 12:01:50 WARN Request failed, retrying attempt=3 backoff=404.753278ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22152026/11/09 12:01:50 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=022162026/11/09 12:01:50 INFO Vacuumed table table=pending_closures22172026/11/09 12:01:50 INFO Vacuumed table table=pending_objects22182026/11/09 12:01:50 INFO Vacuumed table table=multipart_uploads22192026/11/09 12:01:50 INFO Vacuumed table table=closures22202026/11/09 12:01:50 INFO Vacuumed table table=objects22212026/11/09 12:01:50 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22222026/11/09 12:01:50 INFO Aborted multipart uploads count=0 kept=022232026/11/09 12:01:50 WARN Force mode enabled - objects will be deleted immediately without grace period22242026-11-09 12:01:50.768 UTC [27841] ERROR: canceling statement due to user request22252026-11-09 12:01:50.768 UTC [27841] STATEMENT: -- name: MarkStaleObjects :execrows2226 WITH RECURSIVE ct AS (2227 SELECT timezone('UTC', now()) AS now2228 ),2229 closure_reach AS (2230 -- Start with all closure keys2231 SELECT o.key, o.refs2232 FROM objects o2233 INNER JOIN closures c ON o.key = c.key2234 UNION2235 -- Recursively add all referenced objects2236 SELECT o.key, o.refs2237 FROM objects o2238 INNER JOIN closure_reach cr ON o.key = ANY(cr.refs)2239 ),2240 reachable_objects AS (2241 SELECT DISTINCT key FROM closure_reach2242 ),2243 stale_objects AS (2244 SELECT o.key2245 FROM objects AS o, ct2246 WHERE2247 NOT EXISTS (2248 SELECT 12249 FROM reachable_objects ro2250 WHERE ro.key = o.key2251 )2252 AND NOT EXISTS (2253 SELECT 12254 FROM pending_objects AS po2255 WHERE po.key = o.key2256 )2257 AND o.deleted_at IS NULL -- Only mark fresh objects2258 ORDER BY o.key COLLATE "C" -- lock in key order, like commit_pending_closure2259 FOR UPDATE2260 )2261 UPDATE objects2262 SET2263 deleted_at = ct.now,2264 first_deleted_at = COALESCE(first_deleted_at, ct.now)2265 FROM stale_objects, ct2266 WHERE objects.key = stale_objects.key2267 2268--- PASS: TestGCEndsOnShutdown (0.02s)2269 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (6.74s)2270 --- PASS: TestGCEndsOnShutdown/before_the_run (7.25s)2271 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (8.00s)22722026/11/09 12:01:50 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f100400000000000000000000.nar.zst upload_id=ZGQ5NTdhZjYtYWRmOS00MzVkLThhOTctMTkyMGFkNjU2YzZhLjZhNDAzZDI1LTc3ZGEtNGEwZS05Y2FjLWU0MDQ1OTlmMjE2N3gxNzk0MjI1NzA4OTgyOTE5MDAw parts=1022732026/11/09 12:01:50 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete22742026/11/09 12:01:50 INFO Completed upload id=2 objects=3 duration=1.455375ms22752026/11/09 12:01:50 WARN Request failed, retrying attempt=4 backoff=722.948304ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22762026-11-09 12:01:51.023 UTC [27365] LOG: checkpoint starting: wal22772026/11/09 12:01:51 INFO Received uploads request method=POST path=/api/pending_closures22782026/11/09 12:01:51 INFO Received uploads request method=POST path=/api/pending_closures22792026/11/09 12:01:51 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000400000000000000000000.nar.zst22802026/11/09 12:01:51 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0004.narinfo22812026/11/09 12:01:51 INFO Aborted multipart uploads count=0 kept=022822026/11/09 12:01:51 WARN Force mode enabled - objects will be deleted immediately without grace period22832026/11/09 12:01:51 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=02284--- PASS: TestDeleteClosuresRacingPins (12.26s)22852026/11/09 12:01:51 INFO Vacuumed table table=pending_closures22862026/11/09 12:01:51 INFO Vacuumed table table=pending_objects22872026/11/09 12:01:51 INFO Vacuumed table table=multipart_uploads22882026/11/09 12:01:51 INFO Vacuumed table table=closures22892026/11/09 12:01:51 INFO Vacuumed table table=objects2290--- PASS: TestForceGCDuringPushOffersSweptObject (0.01s)2291 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (7.91s)2292 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (8.31s)22932026/11/09 12:01:51 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22942026/11/09 12:01:51 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f100300000000000000000000.nar.zst upload_id=ZGQ5NTdhZjYtYWRmOS00MzVkLThhOTctMTkyMGFkNjU2YzZhLjdlOGM3NzI3LTRmMzItNDYyZC05YTQwLTA5NzE5YzEwODAzM3gxNzk0MjI1NzA5NzQwODAwMDAw parts=1022952026/11/09 12:01:51 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete22962026/11/09 12:01:51 INFO Completed upload id=2 objects=3 duration=388.25µs22972026/11/09 12:01:51 INFO Received uploads request method=POST path=/api/pending_closures22982026/11/09 12:01:51 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000300000000000000000000.nar.zst22992026/11/09 12:01:51 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0003.narinfo23002026/11/09 12:01:51 WARN Request failed, retrying attempt=5 backoff=1.556663674s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2301--- PASS: TestService_verifyS3ReuploadsStaleNarinfo (0.00s)2302 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed (10.02s)2303 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed (10.34s)2304 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed (9.97s)2305 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed (11.89s)2306 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost (11.75s)23072026/11/09 12:01:51 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"23082026/11/09 12:01:51 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"23092026/11/09 12:01:53 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures23102026/11/09 12:01:53 WARN Request failed, retrying attempt=2 backoff=197.310823ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures23112026/11/09 12:01:53 WARN Request failed, retrying attempt=3 backoff=436.525305ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures23122026/11/09 12:01:53 WARN Request failed, retrying attempt=4 backoff=799.549688ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures23132026/11/09 12:01:54 WARN Request failed, retrying attempt=5 backoff=1.692219527s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2314--- PASS: TestClientErrorHandling (0.00s)2315 --- PASS: TestClientErrorHandling/InvalidStorePath (7.58s)2316 --- PASS: TestClientErrorHandling/InvalidAuthToken (7.72s)2317 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.88s)2318=== NAME TestOrphanedObjectsGCStressTest2319 orphaned_objects_gc_test.go:503: Stress test completed successfully:2320 orphaned_objects_gc_test.go:504: - Active objects preserved: 202321 orphaned_objects_gc_test.go:505: - Objects deleted: 2102322 orphaned_objects_gc_test.go:506: - Total GC'd: 2102323--- PASS: TestOrphanedObjectsGCStressTest (33.77s)2324PASS2325{"timestamp":"2026-11-09T12:01:57.957689Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:49582","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(4)"}2326{"timestamp":"2026-11-09T12:01:57.958332Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:49683","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(7)"}2327{"timestamp":"2026-11-09T12:01:57.957455Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:49209","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(2)"}23282026-11-09 12:01:58.093 UTC [27360] LOG: received smart shutdown request23292026-11-09 12:01:58.095 UTC [27360] LOG: background worker "logical replication launcher" (PID 27370) exited with exit code 123302026-11-09 12:01:59.730 UTC [27365] LOG: checkpoint complete: wrote 11815 buffers (72.1%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 33 recycled; write=7.880 s, sync=0.699 s, total=8.708 s; sync files=36397, longest=0.001 s, average=0.001 s; distance=533334 kB, estimate=533334 kB; lsn=0/223599B0, redo lsn=0/22062A0823312026-11-09 12:01:59.731 UTC [27365] LOG: shutting down23322026-11-09 12:01:59.731 UTC [27365] LOG: checkpoint starting: shutdown immediate23332026-11-09 12:01:59.742 UTC [27365] LOG: checkpoint complete: wrote 29 buffers (0.2%), wrote 1 SLRU buffers; 0 WAL file(s) added, 0 removed, 0 recycled; write=0.005 s, sync=0.006 s, total=0.012 s; sync files=18, longest=0.003 s, average=0.001 s; distance=3036 kB, estimate=480304 kB; lsn=0/22359A28, redo lsn=0/22359A2823342026-11-09 12:01:59.752 UTC [27360] LOG: database system is shut down2335Running OIDC tests...2336=== RUN TestAudienceForIssuer2337=== PAUSE TestAudienceForIssuer2338=== RUN TestGlobMatch2339=== PAUSE TestGlobMatch2340=== RUN TestValidateToken_ValidToken2341=== PAUSE TestValidateToken_ValidToken2342=== RUN TestValidateToken_WrongAudience2343=== PAUSE TestValidateToken_WrongAudience2344=== RUN TestValidateToken_Expired2345=== PAUSE TestValidateToken_Expired2346=== RUN TestValidateToken_BoundClaimsMismatch2347=== PAUSE TestValidateToken_BoundClaimsMismatch2348=== RUN TestValidateToken_BoundSubjectMismatch2349=== PAUSE TestValidateToken_BoundSubjectMismatch2350=== RUN TestValidateToken_MultipleProviders2351=== PAUSE TestValidateToken_MultipleProviders2352=== RUN TestValidateToken_NoMatchingProvider2353=== PAUSE TestValidateToken_NoMatchingProvider2354=== RUN TestValidateToken_KubernetesServiceAccount2355=== PAUSE TestValidateToken_KubernetesServiceAccount2356=== RUN TestNewValidator_KubernetesRequiresCA2357=== PAUSE TestNewValidator_KubernetesRequiresCA2358=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2359=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2360=== RUN TestPins_ReservedForMatchingRule2361=== PAUSE TestPins_ReservedForMatchingRule2362=== RUN TestPins_TopLevelShorthand2363=== PAUSE TestPins_TopLevelShorthand2364=== RUN TestPins_ConfigValidation2365=== PAUSE TestPins_ConfigValidation2366=== RUN TestScopes_LegacyProviderDefaultsToWrite2367=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2368=== RUN TestScopes_Rules2369=== PAUSE TestScopes_Rules2370=== RUN TestScopes_ConfigValidation2371=== PAUSE TestScopes_ConfigValidation2372=== CONT TestAudienceForIssuer2373--- PASS: TestAudienceForIssuer (0.00s)2374=== CONT TestValidateToken_BoundClaimsMismatch2375=== CONT TestPins_ConfigValidation2376=== CONT TestValidateToken_Expired2377=== CONT TestValidateToken_WrongAudience2378=== CONT TestValidateToken_ValidToken2379=== CONT TestGlobMatch2380=== RUN TestGlobMatch/foo_foo2381=== PAUSE TestGlobMatch/foo_foo2382=== RUN TestGlobMatch/foo_bar2383=== PAUSE TestGlobMatch/foo_bar2384=== RUN TestGlobMatch/*_2385=== PAUSE TestGlobMatch/*_2386=== RUN TestGlobMatch/*_anything2387=== PAUSE TestGlobMatch/*_anything2388=== RUN TestGlobMatch/foo*_foo2389=== PAUSE TestGlobMatch/foo*_foo2390=== RUN TestGlobMatch/foo*_foobar2391=== PAUSE TestGlobMatch/foo*_foobar2392=== RUN TestGlobMatch/foo*_bar2393=== PAUSE TestGlobMatch/foo*_bar2394=== RUN TestGlobMatch/*bar_bar2395=== PAUSE TestGlobMatch/*bar_bar2396=== RUN TestGlobMatch/*bar_foobar2397=== PAUSE TestGlobMatch/*bar_foobar2398=== RUN TestGlobMatch/*bar_foo2399=== PAUSE TestGlobMatch/*bar_foo2400=== RUN TestGlobMatch/foo*bar_foobar2401=== PAUSE TestGlobMatch/foo*bar_foobar2402=== RUN TestGlobMatch/foo*bar_foo123bar2403=== PAUSE TestGlobMatch/foo*bar_foo123bar2404=== RUN TestGlobMatch/foo*bar_foobarbaz2405=== PAUSE TestGlobMatch/foo*bar_foobarbaz2406=== RUN TestGlobMatch/*/*_foo/bar2407=== PAUSE TestGlobMatch/*/*_foo/bar2408=== RUN TestGlobMatch/*/*_foo2409=== PAUSE TestGlobMatch/*/*_foo2410=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2411=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2412=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02413=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02414=== RUN TestGlobMatch/refs/*/main_refs/heads/main2415=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2416=== RUN TestGlobMatch/fo?_foo2417=== PAUSE TestGlobMatch/fo?_foo2418=== RUN TestGlobMatch/fo?_fo2419=== PAUSE TestGlobMatch/fo?_fo2420=== RUN TestGlobMatch/fo?_fooo2421=== PAUSE TestGlobMatch/fo?_fooo2422=== RUN TestGlobMatch/?oo_foo2423=== PAUSE TestGlobMatch/?oo_foo2424=== RUN TestGlobMatch/?oo_boo2425=== PAUSE TestGlobMatch/?oo_boo2426=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2427=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2428=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2429=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2430=== CONT TestGlobMatch/foo_foo2431=== CONT TestPins_ReservedForMatchingRule2432=== CONT TestGlobMatch/*/*_foo/bar2433=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2434=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2435=== CONT TestGlobMatch/?oo_boo2436=== CONT TestGlobMatch/?oo_foo2437=== CONT TestGlobMatch/fo?_fooo2438=== CONT TestGlobMatch/fo?_fo2439=== CONT TestGlobMatch/fo?_foo2440=== CONT TestGlobMatch/refs/*/main_refs/heads/main2441=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02442=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2443=== CONT TestGlobMatch/*/*_foo2444=== CONT TestGlobMatch/*bar_bar2445=== CONT TestGlobMatch/foo*bar_foobarbaz2446=== CONT TestGlobMatch/foo*bar_foo123bar2447=== CONT TestGlobMatch/foo*bar_foobar2448=== CONT TestGlobMatch/*bar_foo2449=== CONT TestGlobMatch/*bar_foobar2450=== CONT TestGlobMatch/foo*_foo2451=== CONT TestGlobMatch/foo*_bar2452=== CONT TestGlobMatch/foo*_foobar2453=== CONT TestGlobMatch/*_2454=== CONT TestGlobMatch/*_anything2455=== CONT TestGlobMatch/foo_bar2456--- PASS: TestGlobMatch (0.00s)2457 --- PASS: TestGlobMatch/foo_foo (0.00s)2458 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2459 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2460 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2461 --- PASS: TestGlobMatch/?oo_boo (0.00s)2462 --- PASS: TestGlobMatch/?oo_foo (0.00s)2463 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2464 --- PASS: TestGlobMatch/fo?_fo (0.00s)2465 --- PASS: TestGlobMatch/fo?_foo (0.00s)2466 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2467 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2468 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2469 --- PASS: TestGlobMatch/*/*_foo (0.00s)2470 --- PASS: TestGlobMatch/*bar_bar (0.00s)2471 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2472 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2473 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2474 --- PASS: TestGlobMatch/*bar_foo (0.00s)2475 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2476 --- PASS: TestGlobMatch/foo*_foo (0.00s)2477 --- PASS: TestGlobMatch/foo*_bar (0.00s)2478 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2479 --- PASS: TestGlobMatch/*_ (0.00s)2480 --- PASS: TestGlobMatch/*_anything (0.00s)2481 --- PASS: TestGlobMatch/foo_bar (0.00s)2482=== CONT TestPins_TopLevelShorthand2483--- PASS: TestPins_ConfigValidation (0.01s)2484=== CONT TestValidateToken_MultipleProviders2485=== CONT TestValidateToken_NoMatchingProvider2486=== CONT TestValidateToken_BoundSubjectMismatch2487=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2488=== CONT TestNewValidator_KubernetesRequiresCA2489=== CONT TestScopes_Rules2490=== CONT TestScopes_ConfigValidation2491--- PASS: TestScopes_ConfigValidation (0.00s)2492=== CONT TestScopes_LegacyProviderDefaultsToWrite2493=== CONT TestValidateToken_KubernetesServiceAccount24942026/11/09 12:02:01 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC12324952026/11/09 12:02:01 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:49709/oidc24962026/11/09 12:02:01 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:49707/oidc24972026/11/09 12:02:01 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:49714/oidc2498--- PASS: TestValidateToken_BoundClaimsMismatch (0.07s)2499--- PASS: TestValidateToken_ValidToken (0.08s)2500--- PASS: TestValidateToken_Expired (0.08s)25012026/11/09 12:02:01 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:49712/oidc2502--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.07s)2503--- PASS: TestScopes_Rules (0.06s)25042026/11/09 12:02:01 http: TLS handshake error from 127.0.0.1:49718: read tcp 127.0.0.1:49713->127.0.0.1:49718: use of closed network connection2505--- PASS: TestNewValidator_KubernetesRequiresCA (0.07s)25062026/11/09 12:02:01 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:49720/oidc2507--- PASS: TestPins_TopLevelShorthand (0.09s)25082026/11/09 12:02:01 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:497222509--- PASS: TestValidateToken_KubernetesServiceAccount (0.06s)25102026/11/09 12:02:01 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:49719/oidc2511--- PASS: TestValidateToken_NoMatchingProvider (0.11s)25122026/11/09 12:02:01 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:49726/oidc2513--- PASS: TestPins_ReservedForMatchingRule (0.12s)25142026/11/09 12:02:01 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:49728/oidc2515--- PASS: TestValidateToken_BoundSubjectMismatch (0.11s)25162026/11/09 12:02:01 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:49731/oidc25172026/11/09 12:02:01 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:49733/oidc2518--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.12s)2519--- PASS: TestValidateToken_WrongAudience (0.15s)25202026/11/09 12:02:01 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:49730/oidc25212026/11/09 12:02:01 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:49735/oidc2522--- PASS: TestValidateToken_MultipleProviders (0.19s)2523PASS2524Running hook tests...2525=== RUN TestSendPathsEmpty2526=== PAUSE TestSendPathsEmpty2527=== RUN TestQueueEnqueueAndFetch2528=== PAUSE TestQueueEnqueueAndFetch2529=== RUN TestQueueDeduplication2530=== PAUSE TestQueueDeduplication2531=== RUN TestQueueRemove2532=== PAUSE TestQueueRemove2533=== RUN TestQueueFetchBatchLimit2534=== PAUSE TestQueueFetchBatchLimit2535=== RUN TestQueueRetryMovesToBack2536=== PAUSE TestQueueRetryMovesToBack2537=== RUN TestQueueFetchRemoveLifecycle2538=== PAUSE TestQueueFetchRemoveLifecycle2539=== RUN TestQueueConcurrentWriters2540=== PAUSE TestQueueConcurrentWriters2541=== RUN TestQueueRemoveLargeClosure2542=== PAUSE TestQueueRemoveLargeClosure2543=== RUN TestServerClientIntegration2544--- PASS: TestServerClientIntegration (0.00s)2545=== RUN TestServerQueueError25462026/11/09 12:02:01 ERROR Failed to queue paths error="permission denied" count=12547--- PASS: TestServerQueueError (0.00s)2548=== RUN TestGetListenerSocketActivation2549 server_test.go:145: systemd socket activation does not exist on darwin2550--- SKIP: TestGetListenerSocketActivation (0.00s)2551=== RUN TestServerStalledClientDoesNotBlockShutdown2552=== PAUSE TestServerStalledClientDoesNotBlockShutdown2553=== RUN TestServerBacksOffOnAcceptErrors2554=== PAUSE TestServerBacksOffOnAcceptErrors2555=== RUN TestDrainIsolatesPoisonPath2556=== PAUSE TestDrainIsolatesPoisonPath2557=== RUN TestRunNotBlockedByPoisonHead2558=== PAUSE TestRunNotBlockedByPoisonHead2559=== RUN TestDrainGivesUpWhenServerDown2560=== PAUSE TestDrainGivesUpWhenServerDown2561=== RUN TestFailedPathPrunedByLaterClosure2562=== PAUSE TestFailedPathPrunedByLaterClosure2563=== RUN TestWorkerUploadsAndRemoves2564=== PAUSE TestWorkerUploadsAndRemoves2565=== RUN TestWorkerSkipsGCdPaths2566=== PAUSE TestWorkerSkipsGCdPaths2567=== RUN TestWorkerPrunesClosureDeps2568=== PAUSE TestWorkerPrunesClosureDeps2569=== RUN TestDrainTimeout2570=== PAUSE TestDrainTimeout2571=== RUN TestWorkerRemoveFailureIsNotProgress2572=== PAUSE TestWorkerRemoveFailureIsNotProgress2573=== RUN TestWorkerKeepsPathItCannotStat2574=== PAUSE TestWorkerKeepsPathItCannotStat2575=== CONT TestSendPathsEmpty2576=== CONT TestDrainIsolatesPoisonPath2577=== CONT TestWorkerUploadsAndRemoves2578--- PASS: TestSendPathsEmpty (0.00s)2579=== CONT TestServerBacksOffOnAcceptErrors25802026/11/09 12:02:01 ERROR Accept failed error="too many open files"2581=== CONT TestServerStalledClientDoesNotBlockShutdown2582=== CONT TestQueueRemoveLargeClosure2583=== CONT TestQueueConcurrentWriters2584=== CONT TestQueueFetchRemoveLifecycle2585=== CONT TestQueueRetryMovesToBack2586=== CONT TestQueueFetchBatchLimit2587=== CONT TestQueueEnqueueAndFetch2588=== CONT TestQueueRemove2589=== CONT TestWorkerSkipsGCdPaths2590=== CONT TestWorkerKeepsPathItCannotStat2591=== CONT TestWorkerRemoveFailureIsNotProgress2592=== CONT TestQueueDeduplication2593=== CONT TestDrainTimeout2594=== CONT TestWorkerPrunesClosureDeps2595=== CONT TestFailedPathPrunedByLaterClosure2596=== CONT TestDrainGivesUpWhenServerDown25972026/11/09 12:02:01 ERROR Accept failed error="too many open files"2598=== CONT TestRunNotBlockedByPoisonHead25992026/11/09 12:02:01 WARN Cannot stat store path, will retry later path=/private/var/tb/8/scratch/cde53c32ef764c64/build/TestWorkerKeepsPathItCannotStat733276786/002/locked/aaa error="stat /private/var/tb/8/scratch/cde53c32ef764c64/build/TestWorkerKeepsPathItCannotStat733276786/002/locked/aaa: permission denied"26002026/11/09 12:02:01 INFO Upload queue status pending=326012026/11/09 12:02:01 INFO Uploading batch count=126022026/11/09 12:02:01 ERROR Upload failed error="upload failed" count=126032026/11/09 12:02:01 WARN Cannot stat store path, will retry later path=/private/var/tb/8/scratch/cde53c32ef764c64/build/TestWorkerKeepsPathItCannotStat733276786/002/locked/aaa error="stat /private/var/tb/8/scratch/cde53c32ef764c64/build/TestWorkerKeepsPathItCannotStat733276786/002/locked/aaa: permission denied"26042026/11/09 12:02:01 INFO Upload queue status pending=226052026/11/09 12:02:01 INFO Uploading batch count=22606--- PASS: TestQueueDeduplication (0.01s)2607--- PASS: TestQueueRemove (0.01s)26082026/11/09 12:02:01 WARN Cannot stat store path, will retry later path=/private/var/tb/8/scratch/cde53c32ef764c64/build/TestWorkerKeepsPathItCannotStat733276786/002/locked/aaa error="stat /private/var/tb/8/scratch/cde53c32ef764c64/build/TestWorkerKeepsPathItCannotStat733276786/002/locked/aaa: permission denied"26092026/11/09 12:02:01 INFO Uploading batch count=126102026/11/09 12:02:01 ERROR Upload failed error="upload failed" count=12611--- PASS: TestQueueFetchBatchLimit (0.01s)26122026/11/09 12:02:01 ERROR Drain finished with paths left in queue remaining=126132026/11/09 12:02:01 INFO Uploading batch count=22614--- PASS: TestQueueFetchRemoveLifecycle (0.02s)26152026/11/09 12:02:01 INFO Uploading batch count=126162026/11/09 12:02:01 INFO Upload queue status pending=226172026/11/09 12:02:01 INFO Uploading batch count=426182026/11/09 12:02:01 ERROR Upload failed error="upload failed" count=426192026/11/09 12:02:01 INFO Uploading batch count=126202026/11/09 12:02:01 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/8/scratch/cde53c32ef764c64/build/TestDrainIsolatesPoisonPath3824607797/002/bbb26212026/11/09 12:02:01 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/8/scratch/cde53c32ef764c64/build/TestWorkerSkipsGCdPaths2225878800/002/nonexistent26222026/11/09 12:02:01 INFO Uploading batch count=12623--- PASS: TestQueueRetryMovesToBack (0.02s)2624--- PASS: TestQueueEnqueueAndFetch (0.01s)26252026/11/09 12:02:01 INFO Upload queue status pending=226262026/11/09 12:02:01 INFO Uploading batch count=126272026/11/09 12:02:01 INFO Uploading batch count=226282026/11/09 12:02:01 ERROR Upload failed error="upload failed" count=226292026/11/09 12:02:01 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/8/scratch/cde53c32ef764c64/build/TestDrainGivesUpWhenServerDown1044335592/002/a26302026/11/09 12:02:01 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/8/scratch/cde53c32ef764c64/build/TestDrainGivesUpWhenServerDown1044335592/002/b26312026/11/09 12:02:01 INFO Uploading batch count=226322026/11/09 12:02:01 ERROR Upload failed error="upload failed" count=22633--- PASS: TestWorkerKeepsPathItCannotStat (0.01s)26342026/11/09 12:02:01 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/8/scratch/cde53c32ef764c64/build/TestDrainGivesUpWhenServerDown1044335592/002/c26352026/11/09 12:02:01 INFO Uploading batch count=126362026/11/09 12:02:01 ERROR Upload failed error="upload failed" count=126372026/11/09 12:02:01 ERROR Accept failed error="too many open files"26382026/11/09 12:02:01 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/8/scratch/cde53c32ef764c64/build/TestDrainGivesUpWhenServerDown1044335592/002/d2639--- PASS: TestFailedPathPrunedByLaterClosure (0.01s)26402026/11/09 12:02:01 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/8/scratch/cde53c32ef764c64/build/TestWorkerRemoveFailureIsNotProgress372746790/002/nonexistent26412026/11/09 12:02:01 INFO Uploading batch count=126422026/11/09 12:02:01 ERROR Upload failed error="upload failed" count=126432026/11/09 12:02:01 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=126442026/11/09 12:02:01 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/8/scratch/cde53c32ef764c64/build/TestWorkerRemoveFailureIsNotProgress372746790/002/nonexistent26452026/11/09 12:02:01 INFO Uploading batch count=226462026/11/09 12:02:01 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=126472026/11/09 12:02:01 ERROR Upload failed error="upload failed" count=226482026/11/09 12:02:01 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/8/scratch/cde53c32ef764c64/build/TestDrainGivesUpWhenServerDown1044335592/002/e26492026/11/09 12:02:01 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/8/scratch/cde53c32ef764c64/build/TestWorkerRemoveFailureIsNotProgress372746790/002/nonexistent26502026/11/09 12:02:01 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=126512026/11/09 12:02:01 ERROR Drain finished with paths left in queue remaining=126522026/11/09 12:02:01 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/8/scratch/cde53c32ef764c64/build/TestDrainGivesUpWhenServerDown1044335592/002/f26532026/11/09 12:02:01 INFO Uploading batch count=126542026/11/09 12:02:01 ERROR Upload failed error="upload failed" count=126552026/11/09 12:02:01 ERROR Drain finished with paths left in queue remaining=126562026/11/09 12:02:01 ERROR Drain finished with paths left in queue remaining=102657--- PASS: TestWorkerRemoveFailureIsNotProgress (0.01s)2658--- PASS: TestDrainIsolatesPoisonPath (0.02s)2659--- PASS: TestDrainGivesUpWhenServerDown (0.01s)2660--- PASS: TestWorkerUploadsAndRemoves (0.03s)2661--- PASS: TestWorkerSkipsGCdPaths (0.03s)2662--- PASS: TestWorkerPrunesClosureDeps (0.03s)26632026/11/09 12:02:01 ERROR Accept failed error="too many open files"2664--- PASS: TestQueueRemoveLargeClosure (0.04s)2665--- PASS: TestQueueConcurrentWriters (0.04s)26662026/11/09 12:02:01 ERROR Accept failed error="too many open files"26672026/11/09 12:02:02 ERROR Accept failed error="too many open files"26682026/11/09 12:02:02 ERROR Failed to decode request error="read unix /private/var/tb/8/scratch/cde53c32ef764c64/build/hook3983932801/test.sock->: i/o timeout"26692026/11/09 12:02:02 ERROR Failed to write response error="write unix /private/var/tb/8/scratch/cde53c32ef764c64/build/hook3983932801/test.sock->: i/o timeout"2670--- PASS: TestServerStalledClientDoesNotBlockShutdown (0.20s)26712026/11/09 12:02:02 ERROR Upload failed error="context deadline exceeded" count=226722026/11/09 12:02:02 ERROR Drain finished with paths left in queue remaining=42673--- PASS: TestDrainTimeout (0.21s)26742026/11/09 12:02:02 ERROR Accept failed error="too many open files"26752026/11/09 12:02:02 ERROR Accept failed error="too many open files"2676--- PASS: TestServerBacksOffOnAcceptErrors (0.64s)26772026/11/09 12:02:02 INFO Uploading batch count=126782026/11/09 12:02:02 INFO Uploading batch count=126792026/11/09 12:02:02 INFO Uploading batch count=126802026/11/09 12:02:02 ERROR Upload failed error="upload failed" count=126812026/11/09 12:02:02 INFO Uploading batch count=126822026/11/09 12:02:02 ERROR Upload failed error="upload failed" count=126832026/11/09 12:02:02 INFO Uploading batch count=126842026/11/09 12:02:02 ERROR Upload failed error="upload failed" count=126852026/11/09 12:02:02 INFO Uploading batch count=126862026/11/09 12:02:02 ERROR Upload failed error="upload failed" count=126872026/11/09 12:02:02 ERROR Drain finished with paths left in queue remaining=12688--- PASS: TestRunNotBlockedByPoisonHead (1.03s)2689PASS2690Running signing tests...2691=== RUN TestExternalSigner2692=== PAUSE TestExternalSigner2693=== RUN TestExternalSignerWrongPublicKey2694=== PAUSE TestExternalSignerWrongPublicKey2695=== RUN TestExternalSignerErrors2696=== PAUSE TestExternalSignerErrors2697=== RUN TestExternalSignerRestartsAfterCrash2698=== PAUSE TestExternalSignerRestartsAfterCrash2699=== RUN TestExternalSignerProgramErrorKeepsProcess2700=== PAUSE TestExternalSignerProgramErrorKeepsProcess2701=== RUN TestExternalSignerClose2702=== PAUSE TestExternalSignerClose2703=== RUN TestExternalSignerRejectsInvalidPublicKey2704=== PAUSE TestExternalSignerRejectsInvalidPublicKey2705=== RUN TestExternalSignerCancellation2706=== PAUSE TestExternalSignerCancellation2707=== RUN TestGenerateFingerprint2708=== PAUSE TestGenerateFingerprint2709=== RUN TestParseSigningKey2710=== PAUSE TestParseSigningKey2711=== RUN TestSign2712=== PAUSE TestSign2713=== RUN TestSignBatch2714=== PAUSE TestSignBatch2715=== RUN TestNilKeyPublicKey2716=== PAUSE TestNilKeyPublicKey2717=== RUN TestSignErrors2718=== PAUSE TestSignErrors2719=== CONT TestExternalSigner2720=== CONT TestExternalSignerProgramErrorKeepsProcess2721=== CONT TestExternalSignerWrongPublicKey2722=== CONT TestSignBatch2723=== CONT TestExternalSignerCancellation2724=== CONT TestSign2725=== CONT TestParseSigningKey2726=== RUN TestParseSigningKey/valid_32-byte_key2727=== PAUSE TestParseSigningKey/valid_32-byte_key2728=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2729=== CONT TestGenerateFingerprint2730=== RUN TestGenerateFingerprint/basic_with_references2731=== CONT TestExternalSignerErrors2732=== CONT TestExternalSignerRestartsAfterCrash2733=== CONT TestSignErrors2734=== CONT TestExternalSignerRejectsInvalidPublicKey2735=== RUN TestExternalSignerRejectsInvalidPublicKey/#002736=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002737=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2738=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2739=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2740=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2741=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2742=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2743=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2744=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2745=== CONT TestExternalSignerRejectsInvalidPublicKey/#002746=== CONT TestExternalSignerClose2747=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2748=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2749=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2750=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2751--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2752 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2753 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2754 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2755 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2756 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2757--- PASS: TestSign (0.00s)2758=== CONT TestNilKeyPublicKey2759=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2760=== PAUSE TestGenerateFingerprint/basic_with_references2761=== RUN TestExternalSignerErrors/exit_at_startup2762=== PAUSE TestExternalSignerErrors/exit_at_startup2763=== RUN TestExternalSignerErrors/wrong_id2764=== PAUSE TestExternalSignerErrors/wrong_id2765=== RUN TestExternalSignerErrors/null2766=== PAUSE TestExternalSignerErrors/null2767=== RUN TestExternalSignerErrors/wrong_signatures_shape2768=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2769--- PASS: TestSignBatch (0.00s)2770--- PASS: TestNilKeyPublicKey (0.00s)2771=== RUN TestSignErrors/nil_key2772=== PAUSE TestSignErrors/nil_key2773=== RUN TestSignErrors/nil_narinfo2774=== RUN TestGenerateFingerprint/no_references2775=== RUN TestExternalSignerErrors/invalid_signature_base642776=== RUN TestParseSigningKey/no_colon2777=== PAUSE TestParseSigningKey/no_colon2778=== RUN TestParseSigningKey/empty_name2779=== PAUSE TestParseSigningKey/empty_name2780=== RUN TestParseSigningKey/invalid_base642781=== PAUSE TestParseSigningKey/invalid_base642782=== RUN TestParseSigningKey/wrong_length2783=== PAUSE TestParseSigningKey/wrong_length2784=== CONT TestParseSigningKey/valid_32-byte_key2785=== PAUSE TestSignErrors/nil_narinfo2786=== RUN TestSignErrors/invalid_narinfo2787=== PAUSE TestSignErrors/invalid_narinfo2788=== RUN TestSignErrors/canceled2789=== PAUSE TestSignErrors/canceled2790=== CONT TestSignErrors/nil_key2791=== CONT TestParseSigningKey/wrong_length2792=== CONT TestSignErrors/invalid_narinfo2793=== PAUSE TestExternalSignerErrors/invalid_signature_base642794=== CONT TestParseSigningKey/empty_name2795=== CONT TestParseSigningKey/invalid_base642796=== PAUSE TestGenerateFingerprint/no_references2797=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2798=== RUN TestExternalSignerErrors/wrong_signature_length2799=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2800=== PAUSE TestExternalSignerErrors/wrong_signature_length2801=== RUN TestExternalSignerErrors/exit_on_request2802=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2803=== PAUSE TestExternalSignerErrors/exit_on_request2804=== RUN TestExternalSignerErrors/invalid_JSON2805=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2806=== PAUSE TestExternalSignerErrors/invalid_JSON2807=== RUN TestGenerateFingerprint/invalid_nar_hash_length2808=== RUN TestExternalSignerErrors/wrong_shape2809=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2810=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2811=== RUN TestGenerateFingerprint/invalid_store_path_prefix2812=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2813=== RUN TestGenerateFingerprint/invalid_reference_prefix2814=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2815=== CONT TestParseSigningKey/no_colon2816=== CONT TestSignErrors/nil_narinfo2817=== CONT TestSignErrors/canceled2818=== PAUSE TestExternalSignerErrors/wrong_shape2819=== CONT TestGenerateFingerprint/basic_with_references2820=== CONT TestGenerateFingerprint/invalid_reference_prefix2821=== CONT TestGenerateFingerprint/invalid_store_path_prefix2822=== CONT TestGenerateFingerprint/invalid_nar_hash_length2823=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2824=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2825=== CONT TestGenerateFingerprint/no_references2826--- PASS: TestParseSigningKey (0.00s)2827 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2828 --- PASS: TestParseSigningKey/wrong_length (0.00s)2829 --- PASS: TestParseSigningKey/empty_name (0.00s)2830 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2831 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2832 --- PASS: TestParseSigningKey/no_colon (0.00s)2833=== RUN TestExternalSignerErrors/missing_signatures2834=== PAUSE TestExternalSignerErrors/missing_signatures2835=== RUN TestExternalSignerErrors/null_signatures2836=== PAUSE TestExternalSignerErrors/null_signatures2837=== RUN TestExternalSignerErrors/too_few_signatures2838=== PAUSE TestExternalSignerErrors/too_few_signatures2839=== RUN TestExternalSignerErrors/missing_signature_name2840=== PAUSE TestExternalSignerErrors/missing_signature_name2841=== RUN TestExternalSignerErrors/wrong_signature_name2842=== PAUSE TestExternalSignerErrors/wrong_signature_name2843=== RUN TestExternalSignerErrors/unrequested_key2844=== PAUSE TestExternalSignerErrors/unrequested_key2845=== RUN TestExternalSignerErrors/program_error2846=== PAUSE TestExternalSignerErrors/program_error2847=== CONT TestExternalSignerErrors/exit_at_startup2848=== CONT TestExternalSignerErrors/wrong_signature_length2849=== CONT TestExternalSignerErrors/invalid_JSON2850=== CONT TestExternalSignerErrors/wrong_shape2851--- PASS: TestSignErrors (0.00s)2852 --- PASS: TestSignErrors/nil_key (0.00s)2853 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2854 --- PASS: TestSignErrors/nil_narinfo (0.00s)2855 --- PASS: TestSignErrors/canceled (0.00s)2856=== CONT TestExternalSignerErrors/program_error2857=== CONT TestExternalSignerErrors/wrong_id2858=== CONT TestExternalSignerErrors/missing_signature_name2859=== CONT TestExternalSignerErrors/missing_signatures2860=== CONT TestExternalSignerErrors/null_signatures2861=== CONT TestExternalSignerErrors/invalid_signature_base642862=== CONT TestExternalSignerErrors/wrong_signatures_shape2863=== CONT TestExternalSignerErrors/too_few_signatures2864=== CONT TestExternalSignerErrors/null2865=== CONT TestExternalSignerErrors/unrequested_key2866=== CONT TestExternalSignerErrors/wrong_signature_name2867=== CONT TestExternalSignerErrors/exit_on_request2868--- PASS: TestGenerateFingerprint (0.00s)2869 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2870 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2871 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2872 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2873 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2874 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2875 --- PASS: TestGenerateFingerprint/no_references (0.00s)2876--- PASS: TestExternalSignerWrongPublicKey (0.21s)2877--- PASS: TestExternalSignerCancellation (0.43s)2878--- PASS: TestExternalSignerProgramErrorKeepsProcess (0.60s)2879--- PASS: TestExternalSignerRestartsAfterCrash (0.81s)2880/private/var/tb/8/scratch/cde53c32ef764c64/build/TestExternalSignerRestartsAfterCrash332605251/001/sign program: line 7: /private/var/tb/8/scratch/cde53c32ef764c64/build/TestExternalSignerRestartsAfterCrash332605251/001/sign program.starts: No such file or directory2881--- PASS: TestExternalSigner (0.99s)2882--- PASS: TestExternalSignerClose (1.18s)2883--- PASS: TestExternalSignerErrors (0.00s)2884 --- PASS: TestExternalSignerErrors/invalid_JSON (1.38s)2885 --- PASS: TestExternalSignerErrors/wrong_signature_length (1.57s)2886 --- PASS: TestExternalSignerErrors/exit_on_request (1.76s)2887 --- PASS: TestExternalSignerErrors/missing_signature_name (1.95s)2888 --- PASS: TestExternalSignerErrors/missing_signatures (2.14s)2889 --- PASS: TestExternalSignerErrors/wrong_signature_name (2.33s)2890 --- PASS: TestExternalSignerErrors/wrong_shape (2.53s)2891 --- PASS: TestExternalSignerErrors/exit_at_startup (2.72s)2892 --- PASS: TestExternalSignerErrors/too_few_signatures (2.91s)2893 --- PASS: TestExternalSignerErrors/wrong_id (3.10s)2894 --- PASS: TestExternalSignerErrors/null_signatures (3.29s)2895 --- PASS: TestExternalSignerErrors/null (3.48s)2896 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (3.66s)2897 --- PASS: TestExternalSignerErrors/unrequested_key (3.86s)2898 --- PASS: TestExternalSignerErrors/program_error (4.05s)2899 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (4.24s)2900PASS2901Running OpenBao signer tests...2902=== RUN TestSign2903=== PAUSE TestSign2904=== RUN TestSignErrors2905=== PAUSE TestSignErrors2906=== RUN TestServe2907=== PAUSE TestServe2908=== RUN TestServeRejectsGarbage2909=== PAUSE TestServeRejectsGarbage2910=== CONT TestSign2911=== CONT TestSignErrors2912=== RUN TestSignErrors/invalid_json2913=== PAUSE TestSignErrors/invalid_json2914=== RUN TestSignErrors/no_prefix2915=== PAUSE TestSignErrors/no_prefix2916=== RUN TestSignErrors/invalid_base642917=== PAUSE TestSignErrors/invalid_base642918=== RUN TestSignErrors/http_error2919=== CONT TestServeRejectsGarbage2920=== CONT TestServe2921=== PAUSE TestSignErrors/http_error2922=== CONT TestSignErrors/invalid_json2923--- PASS: TestServeRejectsGarbage (0.00s)2924=== CONT TestSignErrors/http_error2925=== CONT TestSignErrors/invalid_base642926--- PASS: TestServe (0.00s)2927=== CONT TestSignErrors/no_prefix2928--- PASS: TestSign (0.00s)2929--- PASS: TestSignErrors (0.00s)2930 --- PASS: TestSignErrors/invalid_json (0.00s)2931 --- PASS: TestSignErrors/no_prefix (0.00s)2932 --- PASS: TestSignErrors/invalid_base64 (0.00s)2933 --- PASS: TestSignErrors/http_error (0.00s)2934PASS