niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #433
· 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_FailedPartBufferNotReused20=== PAUSE TestUploadMultipart_FailedPartBufferNotReused21=== RUN TestPartSizeForNAR22=== PAUSE TestPartSizeForNAR23=== RUN TestUploadMultipart_SupersededByPeer24=== PAUSE TestUploadMultipart_SupersededByPeer25=== RUN TestDumpPathCaseHackMatchesNix26--- PASS: TestDumpPathCaseHackMatchesNix (0.05s)27=== RUN TestDumpPathCaseHackCollision28--- PASS: TestDumpPathCaseHackCollision (0.00s)29=== RUN TestSupersededNARStillUploadsListing30=== PAUSE TestSupersededNARStillUploadsListing31=== RUN TestDumpPathMatchesNix32=== PAUSE TestDumpPathMatchesNix33=== RUN TestDumpPathSingleFile34=== PAUSE TestDumpPathSingleFile35=== RUN TestDumpPathWriterError36=== PAUSE TestDumpPathWriterError37=== RUN TestEncodeNixBase3238=== PAUSE TestEncodeNixBase3239=== RUN TestEncodeNixBase32WithRealHash40=== PAUSE TestEncodeNixBase32WithRealHash41=== RUN TestConvertHashToNix3242=== PAUSE TestConvertHashToNix3243=== RUN TestGetStorePathHash44=== PAUSE TestGetStorePathHash45=== RUN TestPathInfoHashCompatibility46=== PAUSE TestPathInfoHashCompatibility47=== RUN TestParsePathInfoJSON48=== PAUSE TestParsePathInfoJSON49=== RUN TestParsePathInfoJSONMultiplePaths50=== PAUSE TestParsePathInfoJSONMultiplePaths51=== RUN TestPathInfoCACompatibility52=== PAUSE TestPathInfoCACompatibility53=== RUN TestRateLimiterFeedback54=== PAUSE TestRateLimiterFeedback55=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess56=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess57=== RUN TestRegisterUploadedObject_BoundedAgainstSilentServer58=== PAUSE TestRegisterUploadedObject_BoundedAgainstSilentServer59=== RUN TestResolveStorePath60=== PAUSE TestResolveStorePath61=== RUN TestDoWithRetry_BodyReplayedViaGetBody62=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody63=== RUN TestRetryTimeoutOutlastsMaxRetries64=== PAUSE TestRetryTimeoutOutlastsMaxRetries65=== RUN TestDoWithRetry_FinalResponseBodyReadable66=== PAUSE TestDoWithRetry_FinalResponseBodyReadable67=== RUN TestShellSplit68=== PAUSE TestShellSplit69=== RUN TestShellSplitErrors70=== PAUSE TestShellSplitErrors71=== RUN TestStreamPushReportsEveryPath72=== PAUSE TestStreamPushReportsEveryPath73=== RUN TestStreamPushBatchesUnderLoad74=== PAUSE TestStreamPushBatchesUnderLoad75=== RUN TestStreamPushIsolatesFailures76=== PAUSE TestStreamPushIsolatesFailures77=== RUN TestStreamPushGivesUpOnDeadServer78=== PAUSE TestStreamPushGivesUpOnDeadServer79=== RUN TestStreamPushRequestLine80=== PAUSE TestStreamPushRequestLine81=== RUN TestStreamPushReportsSignatures82=== PAUSE TestStreamPushReportsSignatures83=== RUN TestStreamPushReportsSkippedPaths84=== PAUSE TestStreamPushReportsSkippedPaths85=== RUN TestClientSignaturesByStorePath86=== PAUSE TestClientSignaturesByStorePath87=== RUN TestStreamPushStopsWhenCanceled88=== PAUSE TestStreamPushStopsWhenCanceled89=== RUN TestSetClientTLS90=== PAUSE TestSetClientTLS91=== RUN TestSetClientTLSDoesNotMutateDefaultTransport92=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport93=== RUN TestSetClientTLSErrors94=== PAUSE TestSetClientTLSErrors95=== RUN TestStaticToken96=== PAUSE TestStaticToken97=== RUN TestFileTokenReadsAndCaches98=== PAUSE TestFileTokenReadsAndCaches99=== RUN TestFileTokenMissing100=== PAUSE TestFileTokenMissing101=== RUN TestFileTokenEmpty102=== PAUSE TestFileTokenEmpty103=== RUN TestScriptTokenNoExpiryRerunsEveryCall104=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall105=== RUN TestScriptTokenCachesUntilRefresh106=== PAUSE TestScriptTokenCachesUntilRefresh107=== RUN TestScriptTokenEmptyToken108=== PAUSE TestScriptTokenEmptyToken109=== RUN TestScriptTokenBadJSON110=== PAUSE TestScriptTokenBadJSON111=== RUN TestScriptTokenScriptFails112=== PAUSE TestScriptTokenScriptFails113=== RUN TestScriptTokenEmptyCommand114=== PAUSE TestScriptTokenEmptyCommand115=== CONT TestDoServerRequestAttachesToken116=== CONT TestStaticToken117=== CONT TestShellSplit118--- PASS: TestStaticToken (0.00s)119=== CONT TestSetClientTLSErrors120=== CONT TestPathInfoCACompatibility121=== RUN TestPathInfoCACompatibility/null_ca_field122=== CONT TestScriptTokenCachesUntilRefresh123--- PASS: TestShellSplit (0.00s)124=== CONT TestSetClientTLS125=== CONT TestDoWithRetry_BodyReplayedViaGetBody126=== CONT TestStreamPushStopsWhenCanceled127=== CONT TestClientSignaturesByStorePath128=== CONT TestStreamPushReportsSkippedPaths129=== CONT TestStreamPushReportsSignatures130=== CONT TestStreamPushRequestLine131=== CONT TestStreamPushGivesUpOnDeadServer132=== CONT TestStreamPushIsolatesFailures133=== CONT TestStreamPushBatchesUnderLoad134=== CONT TestStreamPushReportsEveryPath135=== CONT TestShellSplitErrors136=== CONT TestScriptTokenEmptyCommand137=== CONT TestScriptTokenScriptFails138=== CONT TestScriptTokenBadJSON139=== CONT TestScriptTokenEmptyToken140=== CONT TestResolveStorePath141=== CONT TestDoWithRetry_FinalResponseBodyReadable1422026/10/25 19:06:14 ERROR Upload failed error="bad path" count=3143=== CONT TestScriptTokenNoExpiryRerunsEveryCall144=== CONT TestRetryTimeoutOutlastsMaxRetries145=== CONT TestSetClientTLSDoesNotMutateDefaultTransport146=== PAUSE TestPathInfoCACompatibility/null_ca_field147--- PASS: TestStreamPushStopsWhenCanceled (0.00s)148=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess149=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer150=== CONT TestRateLimiterFeedback151=== CONT TestFileTokenEmpty152=== RUN TestPathInfoCACompatibility/old_string_format_-_text153--- PASS: TestClientSignaturesByStorePath (0.00s)154--- PASS: TestShellSplitErrors (0.00s)155--- PASS: TestScriptTokenEmptyCommand (0.00s)156--- PASS: TestStreamPushReportsEveryPath (0.00s)157--- PASS: TestStreamPushIsolatesFailures (0.00s)158=== RUN TestRateLimiterFeedback/429_enables_limiter159=== PAUSE TestRateLimiterFeedback/429_enables_limiter160=== RUN TestRateLimiterFeedback/503_enables_limiter161=== CONT TestSupersededNARStillUploadsListing162=== PAUSE TestRateLimiterFeedback/503_enables_limiter163=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter1642026/10/25 19:06:14 WARN Rate limiter enabled after throttle name=server-test rate=51652026/10/25 19:06:14 ERROR Upload failed error="connection refused" count=201662026/10/25 19:06:14 ERROR Server seems unavailable, giving up on batch untried=171672026/10/25 19:06:14 ERROR Upload failed error=boom count=11682026/10/25 19:06:14 ERROR Upload failed error=boom count=1169=== RUN TestSetClientTLSErrors/missing_cert_file1702026/10/25 19:06:14 WARN Rate limiter enabled after throttle name=server-test rate=51712026/10/25 19:06:14 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:553111722026/10/25 19:06:14 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:553151732026/10/25 19:06:14 WARN Rate limiter enabled after throttle name=server-test rate=5174=== RUN TestSupersededNARStillUploadsListing/small_NAR175--- PASS: TestFileTokenEmpty (0.00s)176=== CONT TestParsePathInfoJSONMultiplePaths177=== CONT TestParsePathInfoJSON178=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter1792026/10/25 19:06:14 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:55314180=== CONT TestPathInfoHashCompatibility181=== CONT TestGetStorePathHash182=== RUN TestGetStorePathHash/valid_store_path183=== CONT TestConvertHashToNix32184=== CONT TestEncodeNixBase32WithRealHash185=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text1862026/10/25 19:06:14 WARN Rate limiter backed off name=server-test rate=5187=== RUN TestSetClientTLS/rejects_connection_without_client_cert188=== PAUSE TestSetClientTLSErrors/missing_cert_file189=== RUN TestSetClientTLSErrors/missing_key_file190=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths191=== CONT TestDumpPathWriterError192=== PAUSE TestSetClientTLSErrors/missing_key_file193=== RUN TestSetClientTLSErrors/missing_ca_file194=== PAUSE TestSetClientTLSErrors/missing_ca_file195=== RUN TestSetClientTLSErrors/invalid_ca_file196=== PAUSE TestSetClientTLSErrors/invalid_ca_file197=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths198=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths199=== CONT TestEncodeNixBase32200=== RUN TestEncodeNixBase32/test_string_hash201=== PAUSE TestEncodeNixBase32/test_string_hash202=== RUN TestEncodeNixBase32/empty_input203=== PAUSE TestGetStorePathHash/valid_store_path204=== CONT TestDumpPathMatchesNix205=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert206=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA207=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA208=== RUN TestSetClientTLS/preserves_debug_logging_transport209=== PAUSE TestSetClientTLS/preserves_debug_logging_transport210=== CONT TestFilterOversizedClosures211=== RUN TestFilterOversizedClosures/no_limit_keeps_everything212=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything213=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped214=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped215=== RUN TestFilterOversizedClosures/all_closures_skipped216=== PAUSE TestFilterOversizedClosures/all_closures_skipped217=== CONT TestUploadMultipart_SupersededByPeer218=== RUN TestUploadMultipart_SupersededByPeer/exists219=== PAUSE TestUploadMultipart_SupersededByPeer/exists220=== RUN TestGetStorePathHash/basename_without_hyphen_should_error221=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error2222026/10/25 19:06:14 WARN Rate limiter backed off name=server-test rate=52232026/10/25 19:06:14 WARN Request returned retryable status, retrying attempt=2 backoff=0s status=503 url=http://127.0.0.1:55311224=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)225=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)226=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon227=== CONT TestUploadMultipart_FailedPartBufferNotReused228=== CONT TestDumpPathSingleFile229=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon230=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI231=== PAUSE TestEncodeNixBase32/empty_input2322026/10/25 19:06:14 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:55315233--- PASS: TestResolveStorePath (0.00s)234--- PASS: TestStreamPushGivesUpOnDeadServer (0.01s)235--- PASS: TestDoServerRequestAttachesToken (0.01s)236=== PAUSE TestSupersededNARStillUploadsListing/small_NAR237=== RUN TestSupersededNARStillUploadsListing/dump_cut_short238=== PAUSE TestSupersededNARStillUploadsListing/dump_cut_short239=== RUN TestSupersededNARStillUploadsListing/listing_upload_fails240--- PASS: TestStreamPushReportsSkippedPaths (0.01s)241=== RUN TestParsePathInfoJSON/Nix_format242=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter243=== RUN TestConvertHashToNix32/SRI_format_to_Nix32244=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32245=== RUN TestConvertHashToNix32/already_Nix32_format246=== PAUSE TestConvertHashToNix32/already_Nix32_format247=== RUN TestConvertHashToNix32/invalid_format248=== PAUSE TestConvertHashToNix32/invalid_format249=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive250=== RUN TestUploadMultipart_SupersededByPeer/missing251=== CONT TestPartSizeForNAR252=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error253=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI254=== CONT TestUploadMultipart_PartsInParallel255=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths256=== PAUSE TestSupersededNARStillUploadsListing/listing_upload_fails257=== PAUSE TestParsePathInfoJSON/Nix_format258=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error259=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter260=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica261=== CONT TestRegisterUploadedObjectReusesConnections262=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive263=== RUN TestPathInfoCACompatibility/new_structured_format_-_text264=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text265=== RUN TestPartSizeForNAR/zero_stays_at_minimum266=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum2672026/10/25 19:06:14 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:55315268=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha5122692026/10/25 19:06:14 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:55315270=== RUN TestParsePathInfoJSON/Lix_format271=== PAUSE TestUploadMultipart_SupersededByPeer/missing2722026/10/25 19:06:14 INFO Garbage collection started273--- PASS: TestStreamPushReportsSignatures (0.01s)274--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)275--- PASS: TestScriptTokenScriptFails (0.01s)276--- PASS: TestEncodeNixBase32WithRealHash (0.00s)277--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.01s)278--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.01s)279=== CONT TestFileTokenReadsAndCaches280=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512281=== CONT TestFileTokenMissing282--- PASS: TestFileTokenReadsAndCaches (0.00s)283=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry284--- PASS: TestFileTokenMissing (0.00s)285=== CONT TestSetClientTLSErrors/missing_cert_file286=== CONT TestSetClientTLSErrors/missing_ca_file287=== CONT TestCaseHackSuffix288=== CONT TestSetClientTLSErrors/invalid_ca_file289=== CONT TestSetClientTLSErrors/missing_key_file290=== CONT TestSetClientTLS/rejects_connection_without_client_cert291=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun292--- PASS: TestScriptTokenEmptyToken (0.02s)293=== CONT TestFilterOversizedClosures/no_limit_keeps_everything294=== CONT TestFilterOversizedClosures/all_closures_skipped2952026/10/25 19:06:14 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=50296=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped297=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error298=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method299=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method3002026/10/25 19:06:14 WARN Skipping closure: path exceeds server max NAR size top_level_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper oversized_path=/nix/store/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb-vm-image nar_size=5000 max_nar_size=2000301--- PASS: TestFilterOversizedClosures (0.00s)302 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)303 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)304 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)305=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA306--- PASS: TestSetClientTLSErrors (0.01s)307 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)308 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)309 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)310 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)311=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error312=== CONT TestSetClientTLS/preserves_debug_logging_transport313=== CONT TestEncodeNixBase32/test_string_hash314=== CONT TestEncodeNixBase32/empty_input315=== CONT TestConvertHashToNix32/SRI_format_to_Nix32316=== CONT TestConvertHashToNix32/invalid_format317=== CONT TestConvertHashToNix32/already_Nix32_format318=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths319=== RUN TestPartSizeForNAR/small_stays_at_minimum320=== PAUSE TestPartSizeForNAR/small_stays_at_minimum321=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum322=== CONT TestSupersededNARStillUploadsListing/small_NAR323=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum324=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts325=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts326=== RUN TestPartSizeForNAR/1_TiB327=== PAUSE TestPartSizeForNAR/1_TiB328=== RUN TestPartSizeForNAR/5_TiB_S3_max_object329=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object330=== RUN TestPartSizeForNAR/capped_at_5_GiB331=== PAUSE TestPartSizeForNAR/capped_at_5_GiB332--- PASS: TestEncodeNixBase32 (0.00s)333 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)334 --- PASS: TestEncodeNixBase32/empty_input (0.00s)335=== CONT TestSupersededNARStillUploadsListing/listing_upload_fails336--- PASS: TestConvertHashToNix32 (0.00s)337 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)338 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)339 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)3402026/10/25 19:06:14 WARN Request returned retryable status, retrying attempt=3 backoff=1ms status=502 url=http://127.0.0.1:553153412026/10/25 19:06:14 WARN Rate limiter enabled after throttle name=s3-test rate=53422026/10/25 19:06:14 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:55358343=== PAUSE TestParsePathInfoJSON/Lix_format344=== RUN TestParsePathInfoJSON/empty_input345=== PAUSE TestParsePathInfoJSON/empty_input346=== RUN TestParsePathInfoJSON/whitespace_only347=== PAUSE TestParsePathInfoJSON/whitespace_only348=== RUN TestParsePathInfoJSON/invalid_JSON349=== PAUSE TestParsePathInfoJSON/invalid_JSON350=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths351--- PASS: TestParsePathInfoJSONMultiplePaths (0.01s)352 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)353 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)354=== CONT TestSupersededNARStillUploadsListing/dump_cut_short3552026/10/25 19:06:14 INFO Garbage collection started3562026/10/25 19:06:14 INFO Uploading abc-hello (1.0GB)3572026/10/25 19:06:14 INFO Uploading abc-hello (1.0GB)3582026/10/25 19:06:14 WARN Request returned retryable status, retrying attempt=4 backoff=1ms status=502 url=http://127.0.0.1:553153592026/10/25 19:06:14 WARN Request returned retryable status, retrying attempt=5 backoff=1ms status=502 url=http://127.0.0.1:55315360--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.01s)361=== CONT TestRateLimiterFeedback/429_enables_limiter362--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.01s)363=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter364=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter365--- PASS: TestScriptTokenBadJSON (0.03s)366=== CONT TestRateLimiterFeedback/503_enables_limiter367=== CONT TestUploadMultipart_SupersededByPeer/exists3682026/10/25 19:06:14 WARN Request returned retryable status, retrying attempt=6 backoff=1ms status=502 url=http://127.0.0.1:553153692026/10/25 19:06:14 WARN Rate limiter enabled after throttle name=server-test rate=53702026/10/25 19:06:14 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=429 url=http://127.0.0.1:554103712026/10/25 19:06:14 WARN Rate limiter enabled after throttle name=server-test rate=53722026/10/25 19:06:14 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:554163732026/10/25 19:06:14 WARN Rate limiter backed off name=server-test rate=53742026/10/25 19:06:14 WARN Rate limiter enabled after throttle name=s3-test rate=5375=== CONT TestUploadMultipart_SupersededByPeer/missing3762026/10/25 19:06:14 WARN Rate limiter backed off name=server-test rate=53772026/10/25 19:06:14 INFO Garbage collection progress phase=running_on_another_replica failed_uploads_deleted=0 old_closures_deleted=0 objects_marked=0 objects_deleted=0 objects_failed=0378=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)379=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512380=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI381=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon382=== CONT TestPathInfoCACompatibility/null_ca_field383=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method384=== CONT TestPathInfoCACompatibility/new_structured_format_-_text385=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive386=== CONT TestPathInfoCACompatibility/old_string_format_-_text387=== CONT TestGetStorePathHash/valid_store_path388=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error389=== CONT TestGetStorePathHash/basename_without_hyphen_should_error390=== CONT TestPartSizeForNAR/zero_stays_at_minimum391=== CONT TestPartSizeForNAR/capped_at_5_GiB392=== CONT TestPartSizeForNAR/5_TiB_S3_max_object393=== CONT TestPartSizeForNAR/1_TiB394=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts395=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum396=== CONT TestPartSizeForNAR/small_stays_at_minimum397=== CONT TestParsePathInfoJSON/whitespace_only398=== CONT TestParsePathInfoJSON/empty_input399=== CONT TestParsePathInfoJSON/Lix_format400=== CONT TestParsePathInfoJSON/invalid_JSON401=== CONT TestParsePathInfoJSON/Nix_format402--- PASS: TestRateLimiterFeedback (0.01s)403 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)404 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)405 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)406 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)407=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error408--- PASS: TestPathInfoHashCompatibility (0.01s)409 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)410 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)411 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)412 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)413--- PASS: TestPathInfoCACompatibility (0.02s)414 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)415 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)416 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)417 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)418 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)419--- PASS: TestGetStorePathHash (0.01s)420 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)421 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)422 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)423 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)424--- PASS: TestPartSizeForNAR (0.01s)425 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)426 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)427 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)428 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)429 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)430 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)431 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)432--- PASS: TestParsePathInfoJSON (0.01s)433 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)434 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)435 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)436 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)437 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)4382026/10/25 19:06:14 http: TLS handshake error from 127.0.0.1:55357: remote error: tls: bad certificate4392026/10/25 19:06:14 WARN Request returned retryable status, retrying attempt=7 backoff=1ms status=502 url=http://127.0.0.1:55315440--- PASS: TestStreamPushRequestLine (0.04s)4412026/10/25 19:06:14 WARN Garbage collection finished on another replica. Its statistics are not available here442--- PASS: TestUploadMultipart_SupersededByPeer (0.01s)443 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)444 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)445--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.02s)4462026/10/25 19:06:14 WARN Request returned retryable status, retrying attempt=8 backoff=1ms status=502 url=http://127.0.0.1:553154472026/10/25 19:06:14 WARN Request returned retryable status, retrying attempt=9 backoff=1ms status=502 url=http://127.0.0.1:553154482026/10/25 19:06:14 WARN Request returned retryable status, retrying attempt=10 backoff=1ms status=502 url=http://127.0.0.1:55315449--- PASS: TestSetClientTLS (0.01s)450 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.02s)451 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.02s)452 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.03s)4532026/10/25 19:06:14 WARN Request returned retryable status, retrying attempt=11 backoff=1ms status=502 url=http://127.0.0.1:553154542026/10/25 19:06:14 WARN Request returned retryable status, retrying attempt=12 backoff=1ms status=502 url=http://127.0.0.1:553154552026/10/25 19:06:14 WARN Request returned retryable status, retrying attempt=13 backoff=1ms status=502 url=http://127.0.0.1:55315456--- PASS: TestRegisterUploadedObjectReusesConnections (0.04s)4572026/10/25 19:06:14 WARN Request returned retryable status, retrying attempt=14 backoff=1ms status=502 url=http://127.0.0.1:553154582026/10/25 19:06:14 WARN Request returned retryable status, retrying attempt=15 backoff=1ms status=502 url=http://127.0.0.1:553154592026/10/25 19:06:14 WARN Request returned retryable status, retrying attempt=16 backoff=1ms status=502 url=http://127.0.0.1:55315460--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.05s)461--- PASS: TestScriptTokenCachesUntilRefresh (0.06s)4622026/10/25 19:06:14 WARN Request returned retryable status, retrying attempt=17 backoff=1ms status=502 url=http://127.0.0.1:55315463--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.06s)464--- PASS: TestDumpPathSingleFile (0.05s)465--- PASS: TestCaseHackSuffix (0.04s)4662026/10/25 19:06:14 INFO Uploading abc-hello (1.0GB)467--- PASS: TestDumpPathWriterError (0.07s)4682026/10/25 19:06:14 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:55404/part/2\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:55404/part/24692026/10/25 19:06:14 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:55404/part/3\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:55404/part/34702026/10/25 19:06:14 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:55404/part/4\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:55404/part/44712026/10/25 19:06:14 ERROR Failed to close zstd encoder error="io: read/write on closed pipe"472--- PASS: TestDumpPathMatchesNix (0.09s)473--- PASS: TestStreamPushBatchesUnderLoad (0.10s)474--- PASS: TestSupersededNARStillUploadsListing (0.01s)475 --- PASS: TestSupersededNARStillUploadsListing/small_NAR (0.02s)476 --- PASS: TestSupersededNARStillUploadsListing/listing_upload_fails (0.02s)477 --- PASS: TestSupersededNARStillUploadsListing/dump_cut_short (0.56s)478--- PASS: TestUploadMultipart_FailedPartBufferNotReused (0.58s)479--- PASS: TestUploadMultipart_PartsInParallel (0.62s)480--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)4812026/10/25 19:06:15 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:55317/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:55317/api/uploads/complete4822026/10/25 19:06:15 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4832026/10/25 19:06:15 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:55317/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:55317/api/uploads/complete4842026/10/25 19:06:15 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4852026/10/25 19:06:15 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:55317/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:55317/api/uploads/complete4862026/10/25 19:06:15 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"487--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (1.00s)488PASS489Running server tests...490The files belonging to this database system will be owned by user "_tribuchetbld3".491This user must also own the server process.492493The database cluster will be initialized with locale "C".494The default database encoding has accordingly been set to "SQL_ASCII".495The default text search configuration will be set to "english".496497Data page checksums are enabled.498499creating directory /private/var/tb/3/scratch/0f9658a1e8df3254/build/postgres2810504824/data ... ok500creating subdirectories ... ok501selecting dynamic shared memory implementation ... posix502selecting default "max_connections" ... 100503selecting default "shared_buffers" ... 128MB504selecting default time zone ... UTC505creating configuration files ... ok506running bootstrap script ... ok507performing post-bootstrap initialization ... ok508syncing data to disk ... ok509510initdb: warning: enabling "trust" authentication for local connections511initdb: 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.512513Success. You can now start the database server using:514515 pg_ctl -D /private/var/tb/3/scratch/0f9658a1e8df3254/build/postgres2810504824/data -l logfile start516517/private/var/tb/3/scratch/0f9658a1e8df3254/build/postgres2810504824:5432 - no response5182026-10-25 19:06:15.840 UTC [21224] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit5192026-10-25 19:06:15.840 UTC [21224] LOG: listening on Unix socket "/private/var/tb/3/scratch/0f9658a1e8df3254/build/postgres2810504824/.s.PGSQL.5432"5202026-10-25 19:06:15.843 UTC [21231] LOG: database system was shut down at 2026-10-25 19:06:15 UTC5212026-10-25 19:06:15.843 UTC [21224] LOG: database system is ready to accept connections522/private/var/tb/3/scratch/0f9658a1e8df3254/build/postgres2810504824:5432 - accepting connections523{"timestamp":"2026-10-25T19:06:16.059621Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"ba314ef7-374c-470e-bc8d-5527fc964f3b","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(3)"}524=== RUN TestService_AuthMiddleware525=== PAUSE TestService_AuthMiddleware526=== RUN TestService_AuthMiddleware_MTLSProxyHeader527=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader528=== RUN TestService_AuthMiddleware_MTLSBoundSubjects529=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects530=== RUN TestService_ReadAuthMiddleware531=== PAUSE TestService_ReadAuthMiddleware532=== RUN TestService_AuthMiddleware_OIDC533=== PAUSE TestService_AuthMiddleware_OIDC534=== RUN TestService_RequireScope_OIDC535=== PAUSE TestService_RequireScope_OIDC536=== RUN TestService_ReadScope_PublicByDefault537=== PAUSE TestService_ReadScope_PublicByDefault538=== RUN TestCacheConfigHandler539=== PAUSE TestCacheConfigHandler540=== RUN TestCacheStatsHandler541=== PAUSE TestCacheStatsHandler542=== RUN TestClientCADerivations543=== PAUSE TestClientCADerivations544=== RUN TestClientErrorHandling545=== PAUSE TestClientErrorHandling546=== RUN TestClientIntegration547=== PAUSE TestClientIntegration548=== RUN TestClientMultipleUploads549=== PAUSE TestClientMultipleUploads550=== RUN TestClientWithDependencies551=== PAUSE TestClientWithDependencies552=== RUN TestClientSharedPathCommittedMidPush553=== PAUSE TestClientSharedPathCommittedMidPush554=== RUN TestPinProtectsFromGC555=== PAUSE TestPinProtectsFromGC556=== RUN TestClientPushesUseOnePush557=== PAUSE TestClientPushesUseOnePush558=== RUN TestClientFallsBackToClosures559=== PAUSE TestClientFallsBackToClosures560=== RUN TestDeleteClosuresRacingPins561=== PAUSE TestDeleteClosuresRacingPins562=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock563=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock564=== RUN TestResolveDBConnectionString565=== PAUSE TestResolveDBConnectionString566=== RUN TestConnectWaitsForAPeerMigration567=== PAUSE TestConnectWaitsForAPeerMigration568=== RUN TestLeadElectsOneAndHandsOver569=== PAUSE TestLeadElectsOneAndHandsOver570=== RUN TestLeadIncumbentWinsAfterRestart5712026/10/25 19:06:16 INFO lead: acquired remote=192.0.2.1:12345722026/10/25 19:06:16 INFO lead: released remote=192.0.2.1:12345732026/10/25 19:06:16 INFO lead: acquired remote=192.0.2.1:12345742026/10/25 19:06:18 INFO lead: released remote=192.0.2.1:1234575--- PASS: TestLeadIncumbentWinsAfterRestart (1.92s)576=== RUN TestLeadIncumbentAnnouncesAtOnce577=== PAUSE TestLeadIncumbentAnnouncesAtOnce578=== RUN TestLeadEndsOnShutdown579=== PAUSE TestLeadEndsOnShutdown580=== RUN TestLeadEndsWhenItsConnectionHangs5812026/10/25 19:06:18 INFO lead: acquired remote=192.0.2.1:12345822026-10-25 19:06:19.449 UTC [21267] FATAL: terminating connection due to administrator command5832026/10/25 19:06:19 INFO lead: acquired remote=192.0.2.1:12345842026/10/25 19:06:20 WARN lead: lock connection lost error="timeout: context deadline exceeded"5852026/10/25 19:06:20 INFO lead: released remote=192.0.2.1:12345862026/10/25 19:06:20 INFO lead: released remote=192.0.2.1:1234587--- PASS: TestLeadEndsWhenItsConnectionHangs (2.76s)588=== RUN TestGCAdvisoryLockBlocksConcurrentRun589=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun590=== RUN TestGCBugBareHashReferences591=== PAUSE TestGCBugBareHashReferences592=== RUN TestGCMetrics593=== PAUSE TestGCMetrics594=== RUN TestPushDedupSurvivesConcurrentGC595=== PAUSE TestPushDedupSurvivesConcurrentGC596=== RUN TestDeduplicatedObjectsRecordedAsPending597=== PAUSE TestDeduplicatedObjectsRecordedAsPending598=== RUN TestGCSweepSkipsPendingObjects599=== PAUSE TestGCSweepSkipsPendingObjects600=== RUN TestTombstonedObjectOfferedWithoutWaiting601=== PAUSE TestTombstonedObjectOfferedWithoutWaiting602=== RUN TestGCSweepDeliversEachKeyOnce603=== PAUSE TestGCSweepDeliversEachKeyOnce604=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection605=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection606=== RUN TestForceGCDuringPushOffersSweptObject607=== PAUSE TestForceGCDuringPushOffersSweptObject608=== RUN TestFailedS3DeleteKeepsTombstone609=== PAUSE TestFailedS3DeleteKeepsTombstone610=== RUN TestSweepSkipsRowsLockedByPush611=== PAUSE TestSweepSkipsRowsLockedByPush612=== RUN TestRegisterCompletedObjectNeedsPendingRow613=== PAUSE TestRegisterCompletedObjectNeedsPendingRow614=== RUN TestGetExistingObjectsLocksRows615=== PAUSE TestGetExistingObjectsLocksRows616=== RUN TestSweepRechecksPendingAfterLocking617=== PAUSE TestSweepRechecksPendingAfterLocking618=== RUN TestPushWaitsForSweepHoldingRow619=== PAUSE TestPushWaitsForSweepHoldingRow620=== RUN TestCommitRacingPendingCleanupKeepsObjects621=== PAUSE TestCommitRacingPendingCleanupKeepsObjects622=== RUN TestGCEndsOnShutdown623=== PAUSE TestGCEndsOnShutdown624=== RUN TestGCTaskStore_StartNew625=== PAUSE TestGCTaskStore_StartNew626=== RUN TestGCTaskStore_DeduplicateSameParams627=== PAUSE TestGCTaskStore_DeduplicateSameParams628=== RUN TestGCTaskStore_ConflictDifferentParams629=== PAUSE TestGCTaskStore_ConflictDifferentParams630=== RUN TestGCTaskStore_GetEmpty631=== PAUSE TestGCTaskStore_GetEmpty632=== RUN TestGCTaskStore_GetReturnsLatest633=== PAUSE TestGCTaskStore_GetReturnsLatest634=== RUN TestGCTaskStore_CompletedAllowsNewTask635=== PAUSE TestGCTaskStore_CompletedAllowsNewTask636=== RUN TestGCTaskStore_PhaseUpdates637=== PAUSE TestGCTaskStore_PhaseUpdates638=== RUN TestGCTaskStore_Fail639=== PAUSE TestGCTaskStore_Fail640=== RUN TestGracefulShutdownDrainsInflight641=== PAUSE TestGracefulShutdownDrainsInflight642=== RUN TestService_healthCheckHandler643=== PAUSE TestService_healthCheckHandler644=== RUN TestService_readinessHandler645=== PAUSE TestService_readinessHandler646=== RUN TestGenerateLandingPage647=== PAUSE TestGenerateLandingPage648=== RUN TestCacheConfigHandlerMaxNarSize649=== PAUSE TestCacheConfigHandlerMaxNarSize650=== RUN TestCreatePendingClosureRejectsOversizedNAR651=== PAUSE TestCreatePendingClosureRejectsOversizedNAR652=== RUN TestNARDeduplicationMetadataUploadBug653=== PAUSE TestNARDeduplicationMetadataUploadBug654=== RUN TestMetricsInventory655=== PAUSE TestMetricsInventory656=== RUN TestMetricsCommit657=== PAUSE TestMetricsCommit658=== RUN TestService_NativeMTLS659=== PAUSE TestService_NativeMTLS660=== RUN TestServerTLSConfig661=== PAUSE TestServerTLSConfig662=== RUN TestMultipartCleanup663=== PAUSE TestMultipartCleanup664=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded665=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded666=== RUN TestPendingCleanupUsesOneCutoff667=== PAUSE TestPendingCleanupUsesOneCutoff668=== RUN TestObjectStatsTrigger669=== PAUSE TestObjectStatsTrigger670=== RUN TestObjectStatsUpdatedOncePerCommit671=== PAUSE TestObjectStatsUpdatedOncePerCommit672=== RUN TestOrphanedObjectsGC673=== PAUSE TestOrphanedObjectsGC674=== RUN TestOrphanedObjectsGCStressTest675=== PAUSE TestOrphanedObjectsGCStressTest676=== RUN TestCreatePin_ReservedPins677=== PAUSE TestCreatePin_ReservedPins678=== RUN TestPresentReportsOnlyClosureRoots679=== PAUSE TestPresentReportsOnlyClosureRoots680=== RUN TestPresentRefreshesOnlyStaleClosures681=== PAUSE TestPresentRefreshesOnlyStaleClosures682=== RUN TestPresentNotReportedWhileGCDeletesClosure683=== PAUSE TestPresentNotReportedWhileGCDeletesClosure684=== RUN TestParseSingleRange685=== PAUSE TestParseSingleRange686=== RUN TestProxyHeadersOnlyTrustedOnSocket6872026/10/25 19:06:21 INFO Starting HTTP server address=127.0.0.1:554526882026/10/25 19:06:21 INFO Starting HTTP server address=proxy.sock6892026/10/25 19:06:21 WARN mTLS auth: subject not in bound subjects subject="CN=someone"6902026/10/25 19:06:21 INFO Shutdown signal received, draining in-flight requests timeout=10s691--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.16s)692=== RUN TestIsValidCachePath693=== PAUSE TestIsValidCachePath694=== RUN TestReadProxyNarinfo695=== PAUSE TestReadProxyNarinfo696=== RUN TestReadProxyNarinfoAlreadyDecompressed697=== PAUSE TestReadProxyNarinfoAlreadyDecompressed698=== RUN TestReadProxyContentNegotiation699=== PAUSE TestReadProxyContentNegotiation700=== RUN TestReadProxyNarStreaming701=== PAUSE TestReadProxyNarStreaming702=== RUN TestReadProxy404703=== PAUSE TestReadProxy404704=== RUN TestReadProxyInvalidPath705=== PAUSE TestReadProxyInvalidPath706=== RUN TestReadProxyHead707=== PAUSE TestReadProxyHead708=== RUN TestReadProxyOutlastsServerWriteTimeout709=== PAUSE TestReadProxyOutlastsServerWriteTimeout710=== RUN TestReadProxyConditionalGet711=== PAUSE TestReadProxyConditionalGet712=== RUN TestReadProxyRootRedirectsToIndexHTML713=== PAUSE TestReadProxyRootRedirectsToIndexHTML714=== RUN TestReadProxyDisabled715=== PAUSE TestReadProxyDisabled716=== RUN TestReadRedirectNar717=== PAUSE TestReadRedirectNar718=== RUN TestReadRedirectKeepsNarinfoProxied719=== PAUSE TestReadRedirectKeepsNarinfoProxied720=== RUN TestReadProxyRangeRequest721=== PAUSE TestReadProxyRangeRequest722=== RUN TestReadRedirectUsesPublicS3URL723=== PAUSE TestReadRedirectUsesPublicS3URL724=== RUN TestPush_OverlappingRootsStoreOneRowPerKey725=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey726=== RUN TestPush_CompleteCommitsEveryRoot727=== PAUSE TestPush_CompleteCommitsEveryRoot728=== RUN TestPush_RepeatedRootCommitsOnce729=== PAUSE TestPush_RepeatedRootCommitsOnce730=== RUN TestPush_CompleteWaitsForCleanupOfThePush731=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush732=== RUN TestPush_RootsAreLockedInByteOrder733=== PAUSE TestPush_RootsAreLockedInByteOrder734=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit735=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit736=== RUN TestPush_RejectsBadRequests737=== PAUSE TestPush_RejectsBadRequests738=== RUN TestPush_SignsNarinfosOfItsPendingObjects739=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects740=== RUN TestRedundantMultipartUpload741=== PAUSE TestRedundantMultipartUpload742=== RUN TestCompleteMultipartUpload_ErrorButObjectExists743=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists744=== RUN TestCompletedNarNotReofferedAcrossClosures745=== PAUSE TestCompletedNarNotReofferedAcrossClosures746=== RUN TestPresignedUploadRegisteredBeforeCommit747=== PAUSE TestPresignedUploadRegisteredBeforeCommit748=== RUN TestService_Rustfstest749=== PAUSE TestService_Rustfstest750=== RUN TestParseSize751=== PAUSE TestParseSize752=== RUN TestSkippedUploadsHandler753=== PAUSE TestSkippedUploadsHandler754=== RUN TestSystemdListenerNotActivated755--- PASS: TestSystemdListenerNotActivated (0.00s)756=== RUN TestWatchdogBeatsWhenHealthy757--- PASS: TestWatchdogBeatsWhenHealthy (0.03s)758=== RUN TestWatchdogSkipsWhenUnhealthy7592026/10/25 19:06:21 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7602026/10/25 19:06:21 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7612026/10/25 19:06:21 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7622026/10/25 19:06:21 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7632026/10/25 19:06:21 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7642026/10/25 19:06:21 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7652026/10/25 19:06:21 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7662026/10/25 19:06:21 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7672026/10/25 19:06:21 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7682026/10/25 19:06:21 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"769--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)770=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle771=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle772=== RUN TestProxyWriteTimeout773=== PAUSE TestProxyWriteTimeout774=== RUN TestPendingClosureWriteTimeout775=== PAUSE TestPendingClosureWriteTimeout776=== RUN TestIsValidUploadKey777=== PAUSE TestIsValidUploadKey778=== RUN TestUploadHandlersRejectInvalidKeys779=== PAUSE TestUploadHandlersRejectInvalidKeys780=== RUN TestUploadHandlersRejectOversizedBody781=== PAUSE TestUploadHandlersRejectOversizedBody782=== RUN TestService_cleanupPendingClosuresHandler783=== PAUSE TestService_cleanupPendingClosuresHandler784=== RUN TestService_createPendingClosureHandler785=== PAUSE TestService_createPendingClosureHandler786=== RUN TestService_verifyS3Integrity787=== PAUSE TestService_verifyS3Integrity788=== RUN TestCompleteMultipartUnregistered789=== PAUSE TestCompleteMultipartUnregistered790=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT791=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT792=== CONT TestParseSingleRange793=== CONT TestMultipartCleanup794=== RUN TestParseSingleRange/none795=== PAUSE TestParseSingleRange/none796=== RUN TestParseSingleRange/unknown_unit797=== CONT TestService_AuthMiddleware798=== CONT TestCompleteMultipartUnregistered799=== CONT TestPresentNotReportedWhileGCDeletesClosure800=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale801=== CONT TestPresentRefreshesOnlyStaleClosures802=== CONT TestPresentReportsOnlyClosureRoots803=== CONT TestCreatePin_ReservedPins804=== CONT TestOrphanedObjectsGCStressTest805=== CONT TestOrphanedObjectsGC806=== CONT TestObjectStatsUpdatedOncePerCommit807=== CONT TestObjectStatsTrigger808=== CONT TestPendingCleanupUsesOneCutoff809=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit810=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded811=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT812=== CONT TestService_verifyS3Integrity813=== CONT TestService_createPendingClosureHandler814=== CONT TestService_cleanupPendingClosuresHandler815=== CONT TestUploadHandlersRejectOversizedBody816=== CONT TestUploadHandlersRejectInvalidKeys817=== CONT TestIsValidUploadKey818=== RUN TestIsValidUploadKey/narinfo819=== CONT TestProxyWriteTimeout820=== PAUSE TestParseSingleRange/unknown_unit821=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale822=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info823=== RUN TestProxyWriteTimeout/narinfo824=== PAUSE TestProxyWriteTimeout/narinfo825=== CONT TestPendingClosureWriteTimeout826=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh827=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh828=== RUN TestProxyWriteTimeout/1_GiB_nar829=== PAUSE TestProxyWriteTimeout/1_GiB_nar830=== RUN TestProxyWriteTimeout/10_GiB_nar831=== PAUSE TestProxyWriteTimeout/10_GiB_nar832=== RUN TestProxyWriteTimeout/unknown_size833=== PAUSE TestProxyWriteTimeout/unknown_size834=== RUN TestPendingClosureWriteTimeout/empty835=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info836=== PAUSE TestIsValidUploadKey/narinfo837=== RUN TestIsValidUploadKey/nar_zst838=== PAUSE TestPendingClosureWriteTimeout/empty839=== RUN TestPendingClosureWriteTimeout/400_objects840=== RUN TestParseSingleRange/multi-range_ignored841=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal842=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle843=== CONT TestSkippedUploadsHandler8442026/10/25 19:06:21 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000845=== PAUSE TestPendingClosureWriteTimeout/400_objects846=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal847=== PAUSE TestParseSingleRange/multi-range_ignored848=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key849=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key850=== RUN TestPendingClosureWriteTimeout/670k_objects851=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key852=== PAUSE TestIsValidUploadKey/nar_zst853=== RUN TestIsValidUploadKey/nar_xz854=== RUN TestParseSingleRange/malformed_no_dash855=== PAUSE TestPendingClosureWriteTimeout/670k_objects856=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline857=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline858=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key859=== CONT TestParseSize860--- PASS: TestParseSize (0.00s)861=== CONT TestPresignedUploadRegisteredBeforeCommit862--- PASS: TestSkippedUploadsHandler (0.05s)863=== CONT TestCompletedNarNotReofferedAcrossClosures864=== PAUSE TestIsValidUploadKey/nar_xz865=== RUN TestIsValidUploadKey/nar_plain866=== PAUSE TestIsValidUploadKey/nar_plain867=== RUN TestIsValidUploadKey/listing868=== PAUSE TestIsValidUploadKey/listing869=== RUN TestIsValidUploadKey/build_log870=== PAUSE TestIsValidUploadKey/build_log871=== RUN TestIsValidUploadKey/build_log_home-manager_file872=== PAUSE TestIsValidUploadKey/build_log_home-manager_file873=== RUN TestIsValidUploadKey/build_log_plus_in_name874=== PAUSE TestParseSingleRange/malformed_no_dash875=== RUN TestParseSingleRange/malformed_both_empty876=== PAUSE TestParseSingleRange/malformed_both_empty877=== RUN TestParseSingleRange/malformed_end_before_start878=== PAUSE TestParseSingleRange/malformed_end_before_start879=== RUN TestParseSingleRange/closed880=== PAUSE TestParseSingleRange/closed881=== RUN TestParseSingleRange/open-ended882=== PAUSE TestParseSingleRange/open-ended883=== RUN TestParseSingleRange/end_clamped_to_size884=== PAUSE TestParseSingleRange/end_clamped_to_size885=== RUN TestParseSingleRange/suffix886=== PAUSE TestParseSingleRange/suffix887=== RUN TestParseSingleRange/suffix_exceeds_size888=== PAUSE TestParseSingleRange/suffix_exceeds_size889=== RUN TestParseSingleRange/single_byte890=== PAUSE TestParseSingleRange/single_byte891=== RUN TestParseSingleRange/start_past_EOF892=== PAUSE TestParseSingleRange/start_past_EOF893=== RUN TestParseSingleRange/start_far_past_EOF894=== PAUSE TestParseSingleRange/start_far_past_EOF895=== PAUSE TestIsValidUploadKey/build_log_plus_in_name896=== RUN TestIsValidUploadKey/build_log_question_mark897=== PAUSE TestIsValidUploadKey/build_log_question_mark898=== RUN TestIsValidUploadKey/build_log_equals899=== PAUSE TestIsValidUploadKey/build_log_equals900=== RUN TestIsValidUploadKey/realisation901=== PAUSE TestIsValidUploadKey/realisation902=== RUN TestIsValidUploadKey/realisation_plus_in_output903=== PAUSE TestIsValidUploadKey/realisation_plus_in_output904=== RUN TestIsValidUploadKey/nix-cache-info905=== PAUSE TestIsValidUploadKey/nix-cache-info906=== RUN TestIsValidUploadKey/index.html907=== PAUSE TestIsValidUploadKey/index.html908=== RUN TestIsValidUploadKey/narinfo_key,_nar_type909=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type910=== RUN TestIsValidUploadKey/nar_key,_narinfo_type911=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type912=== RUN TestIsValidUploadKey/listing_key,_narinfo_type913=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type914=== RUN TestIsValidUploadKey/traversal915=== PAUSE TestIsValidUploadKey/traversal916=== RUN TestIsValidUploadKey/traversal_nar917=== PAUSE TestIsValidUploadKey/traversal_nar918=== RUN TestIsValidUploadKey/absolute919=== PAUSE TestIsValidUploadKey/absolute920=== RUN TestIsValidUploadKey/empty_key921=== PAUSE TestIsValidUploadKey/empty_key922=== RUN TestIsValidUploadKey/unknown_type923=== PAUSE TestIsValidUploadKey/unknown_type924=== CONT TestCompleteMultipartUpload_ErrorButObjectExists925=== CONT TestService_Rustfstest926=== CONT TestRedundantMultipartUpload927=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure928=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure929=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart930=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart931=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts932=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts933=== CONT TestPush_SignsNarinfosOfItsPendingObjects9342026/10/25 19:06:21 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55455/oidc935--- PASS: TestPresentRefreshesOnlyStaleClosures (0.77s)936=== CONT TestPush_RejectsBadRequests9372026/10/25 19:06:22 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"938--- PASS: TestService_AuthMiddleware (1.00s)939=== CONT TestGCTaskStore_GetReturnsLatest940--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)941=== CONT TestTombstonedObjectOfferedWithoutWaiting9422026/10/25 19:06:22 INFO Received cleanup request method=DELETE path=/api/pending_closures9432026/10/25 19:06:22 INFO Aborted multipart uploads count=0 kept=09442026/10/25 19:06:22 INFO Received uploads request method=POST path=/api/pending_closures9452026/10/25 19:06:22 INFO Received cleanup request method=DELETE path=/api/pending_closures9462026/10/25 19:06:22 INFO Aborted multipart uploads count=1 kept=09472026/10/25 19:06:22 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9482026-10-25 19:06:22.732 UTC [21323] ERROR: Closure does not exist: id=19492026-10-25 19:06:22.732 UTC [21323] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE9502026-10-25 19:06:22.732 UTC [21323] STATEMENT: -- name: CommitPendingClosure :one951 SELECT commit_pending_closure($1::bigint)::bigint952 953--- PASS: TestService_cleanupPendingClosuresHandler (1.49s)954=== CONT TestServerTLSConfig955=== RUN TestServerTLSConfig/no_client_CA956=== PAUSE TestServerTLSConfig/no_client_CA957=== RUN TestServerTLSConfig/missing_CA_file958=== PAUSE TestServerTLSConfig/missing_CA_file959=== RUN TestServerTLSConfig/not_a_PEM_file960=== PAUSE TestServerTLSConfig/not_a_PEM_file961=== CONT TestGCTaskStore_GetEmpty962--- PASS: TestGCTaskStore_GetEmpty (0.00s)963=== CONT TestService_NativeMTLS9642026/10/25 19:06:22 INFO Received uploads request method=POST path=/api/pending_closures9652026/10/25 19:06:23 INFO Received cleanup request method=DELETE path=/api/pending_closures9662026/10/25 19:06:23 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket7/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""9672026/10/25 19:06:23 INFO Aborted multipart uploads count=0 kept=19682026/10/25 19:06:23 INFO Received cleanup request method=DELETE path=/api/pending_closures9692026/10/25 19:06:23 INFO Aborted multipart uploads count=1 kept=0970--- PASS: TestMultipartCleanup (1.84s)971=== CONT TestMetricsCommit972--- PASS: TestObjectStatsUpdatedOncePerCommit (2.31s)973=== CONT TestMetricsInventory9742026/10/25 19:06:23 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9752026/10/25 19:06:23 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst976--- PASS: TestCompleteMultipartUnregistered (2.41s)977=== CONT TestGCTaskStore_ConflictDifferentParams978--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)979=== CONT TestGCTaskStore_DeduplicateSameParams980--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)981=== CONT TestGCTaskStore_StartNew982--- PASS: TestGCTaskStore_StartNew (0.00s)983=== CONT TestGCEndsOnShutdown984=== RUN TestGCEndsOnShutdown/before_the_run985=== PAUSE TestGCEndsOnShutdown/before_the_run986=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete987=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete988=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark989=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark990=== CONT TestClientPushesUseOnePush991--- PASS: TestPresentReportsOnlyClosureRoots (2.69s)992=== CONT TestGCSweepSkipsPendingObjects9932026/10/25 19:06:24 INFO Received uploads request method=POST path=/api/pending_closures994--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (3.39s)995=== CONT TestNARDeduplicationMetadataUploadBug9962026/10/25 19:06:24 INFO Received uploads request method=POST path=/api/pending_closures997--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (3.83s)998=== CONT TestCreatePendingClosureRejectsOversizedNAR9992026/10/25 19:06:25 INFO Received uploads request method=POST path=/api/pending_closures1000--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1001=== CONT TestCacheConfigHandlerMaxNarSize1002--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1003=== CONT TestCommitRacingPendingCleanupKeepsObjects1004=== NAME TestOrphanedObjectsGC1005 orphaned_objects_gc_test.go:287: GC Test Summary:1006 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A1007 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B1008 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)1009 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)1010 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects1011--- PASS: TestOrphanedObjectsGC (3.87s)1012=== CONT TestGenerateLandingPage1013--- PASS: TestGenerateLandingPage (0.00s)1014=== CONT TestPushWaitsForSweepHoldingRow10152026/10/25 19:06:25 INFO Received uploads request method=POST path=/api/pending_closures10162026/10/25 19:06:25 INFO Received push request method=POST path=/api/pushes10172026/10/25 19:06:25 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10182026/10/25 19:06:25 INFO Signed narinfos id=1 count=110192026/10/25 19:06:25 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10202026/10/25 19:06:25 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10212026/10/25 19:06:25 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"10222026/10/25 19:06:25 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10232026/10/25 19:06:25 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"10242026/10/25 19:06:25 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10252026/10/25 19:06:25 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=110262026/10/25 19:06:25 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10272026/10/25 19:06:25 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo1028--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (4.38s)1029=== CONT TestService_readinessHandler1030--- PASS: TestObjectStatsTrigger (4.71s)1031=== CONT TestSweepRechecksPendingAfterLocking10322026/10/25 19:06:26 INFO Received push request method=POST path=/api/pushes10332026/10/25 19:06:26 INFO Received complete push request method=POST path=/api/pushes/1/complete10342026/10/25 19:06:26 INFO Completed push id=1 objects=4 duration=17.172833ms10352026/10/25 19:06:26 INFO Received push request method=POST path=/api/pushes10362026/10/25 19:06:26 INFO Aborted multipart uploads count=0 kept=010372026/10/25 19:06:26 WARN Force mode enabled - objects will be deleted immediately without grace period10382026/10/25 19:06:26 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=010392026/10/25 19:06:26 INFO Received uploads request method=POST path=/api/pending_closures10402026/10/25 19:06:26 INFO Vacuumed table table=pending_closures10412026/10/25 19:06:26 INFO Vacuumed table table=pending_objects10422026/10/25 19:06:26 INFO Received uploads request method=POST path=/api/pending_closures10432026/10/25 19:06:26 INFO Vacuumed table table=multipart_uploads10442026/10/25 19:06:26 INFO Received cleanup request method=DELETE path=/api/pending_closures10452026/10/25 19:06:26 INFO Vacuumed table table=closures10462026/10/25 19:06:26 INFO Vacuumed table table=objects10472026/10/25 19:06:26 INFO Received complete push request method=POST path=/api/pushes/2/complete10482026/10/25 19:06:26 INFO Completed push id=2 objects=4 duration=4.618625ms1049--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (5.54s)1050=== CONT TestGetExistingObjectsLocksRows10512026/10/25 19:06:26 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10522026/10/25 19:06:26 INFO Received uploads request method=POST path=/api/pending_closures10532026/10/25 19:06:26 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=NzM2YjZiMzMtZjRjMC00M2Q5LWIxYmQtN2U3ZWE3ZGY4MzEzLmQyNTdjN2QyLTZiYzUtNGE3MC04YjgyLWIzYWQ2YzFmNzhjY3gxNzkyOTU1MTg1MzE2NTI5MDAw parts=1010542026/10/25 19:06:27 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10552026/10/25 19:06:27 INFO Completed upload id=1 objects=2 duration=12.6385ms10562026/10/25 19:06:27 INFO Received uploads request method=POST path=/api/pending_closures10572026/10/25 19:06:27 INFO Received uploads request method=POST path=/api/pending_closures10582026/10/25 19:06:27 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo10592026/10/25 19:06:27 WARN Found objects in DB but missing from S3, will re-upload count=11060--- PASS: TestService_verifyS3Integrity (5.79s)1061=== CONT TestRegisterCompletedObjectNeedsPendingRow10622026/10/25 19:06:27 INFO Received uploads request method=POST path=/api/pending_closures10632026/10/25 19:06:27 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10642026/10/25 19:06:27 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10652026/10/25 19:06:27 INFO Received uploads request method=POST path=/api/pending_closures10662026/10/25 19:06:27 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NzM2YjZiMzMtZjRjMC00M2Q5LWIxYmQtN2U3ZWE3ZGY4MzEzLjE0NmFiNjY4LTZmODAtNDAyOC1iNDJjLWJhYThmZGZmYWRhZHgxNzkyOTU1MTg3MzIxOTEzMDAw10672026/10/25 19:06:27 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NzM2YjZiMzMtZjRjMC00M2Q5LWIxYmQtN2U3ZWE3ZGY4MzEzLjE0NmFiNjY4LTZmODAtNDAyOC1iNDJjLWJhYThmZGZmYWRhZHgxNzkyOTU1MTg3MzIxOTEzMDAw parts=11068--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (6.34s)1069=== CONT TestDeduplicatedObjectsRecordedAsPending10702026/10/25 19:06:27 INFO Received uploads request method=POST path=/api/pending_closures10712026/10/25 19:06:28 INFO Received uploads request method=POST path=/api/pending_closures10722026/10/25 19:06:28 INFO Received uploads request method=POST path=/api/pending_closures10732026/10/25 19:06:28 INFO Received uploads request method=POST path=/api/pending_closures10742026/10/25 19:06:28 INFO Received uploads request method=POST path=/api/pending_closures10752026/10/25 19:06:28 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst10762026/10/25 19:06:28 INFO Received uploads request method=POST path=/api/pending_closures1077--- PASS: TestPresignedUploadRegisteredBeforeCommit (7.27s)1078=== CONT TestSweepSkipsRowsLockedByPush1079--- PASS: TestService_Rustfstest (7.48s)1080=== CONT TestService_healthCheckHandler10812026/10/25 19:06:29 INFO Received uploads request method=POST path=/api/pending_closures10822026/10/25 19:06:29 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux10832026/10/25 19:06:29 WARN Refused reserved pin name=worker-x86_64-linux10842026/10/25 19:06:29 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux10852026/10/25 19:06:29 INFO Received create pin request method=POST path=/api/pins/my-app10862026/10/25 19:06:29 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1087--- PASS: TestCreatePin_ReservedPins (8.40s)1088=== CONT TestLeadElectsOneAndHandsOver10892026/10/25 19:06:29 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1090=== RUN TestPush_RejectsBadRequests/root_not_in_objects1091=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1092=== RUN TestPush_RejectsBadRequests/no_roots1093=== PAUSE TestPush_RejectsBadRequests/no_roots1094=== RUN TestPush_RejectsBadRequests/no_objects1095=== PAUSE TestPush_RejectsBadRequests/no_objects1096=== RUN TestPush_RejectsBadRequests/bad_root1097=== PAUSE TestPush_RejectsBadRequests/bad_root1098=== CONT TestFailedS3DeleteKeepsTombstone10992026/10/25 19:06:30 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11002026/10/25 19:06:30 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=NzM2YjZiMzMtZjRjMC00M2Q5LWIxYmQtN2U3ZWE3ZGY4MzEzLjgwMzZmMjA0LTBjN2YtNDg4Yi04MzY1LThmN2JmNjJlM2FmZXgxNzkyOTU1MTg4MDc4ODkzMDAw parts=1011012026/10/25 19:06:30 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11022026/10/25 19:06:30 INFO Completed upload id=1 objects=2 duration=33.442333ms11032026/10/25 19:06:30 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000011042026/10/25 19:06:30 INFO Received uploads request method=POST path=/api/pending_closures11052026/10/25 19:06:30 INFO Starting cleanup of old closures method=DELETE path=/api/closures11062026/10/25 19:06:30 INFO Aborted multipart uploads count=0 kept=011072026/10/25 19:06:30 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=011082026/10/25 19:06:30 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=NzM2YjZiMzMtZjRjMC00M2Q5LWIxYmQtN2U3ZWE3ZGY4MzEzLmQxZDYwMzRkLTQ3OTUtNGQ4NC1iZTUzLWNkYjViNjE3ZDJjN3gxNzkyOTU1MTg3Njc2MDMyMDAw parts=1211092026/10/25 19:06:30 INFO Received uploads request method=POST path=/api/pending_closures11102026/10/25 19:06:30 INFO Vacuumed table table=pending_closures11112026/10/25 19:06:30 INFO Received uploads request method=POST path=/api/pending_closures11122026/10/25 19:06:30 INFO Vacuumed table table=pending_objects11132026/10/25 19:06:30 INFO Vacuumed table table=multipart_uploads11142026/10/25 19:06:30 INFO Vacuumed table table=closures11152026/10/25 19:06:30 INFO Received uploads request method=POST path=/api/pending_closures11162026/10/25 19:06:30 INFO Vacuumed table table=objects11172026/10/25 19:06:30 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001118--- PASS: TestService_createPendingClosureHandler (9.23s)1119=== CONT TestGracefulShutdownDrainsInflight11202026/10/25 19:06:30 INFO Starting HTTP server address=127.0.0.1:5553111212026/10/25 19:06:30 INFO Shutdown signal received, draining in-flight requests timeout=10s1122--- PASS: TestTombstonedObjectOfferedWithoutWaiting (8.26s)1123=== CONT TestForceGCDuringPushOffersSweptObject1124=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows1125=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows1126=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check1127=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check1128=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection1129--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1130=== CONT TestLeadIncumbentAnnouncesAtOnce11312026/10/25 19:06:30 WARN mTLS auth: subject not in bound subjects subject="CN=reader"11322026/10/25 19:06:30 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1133--- PASS: TestService_NativeMTLS (8.16s)1134=== CONT TestGCSweepDeliversEachKeyOnce11352026/10/25 19:06:31 INFO Received push request method=POST path=/api/pushes11362026/10/25 19:06:31 INFO Received complete push request method=POST path=/api/pushes/1/complete11372026/10/25 19:06:31 INFO Completed push id=1 objects=4 duration=59.025666ms11382026/10/25 19:06:31 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete11392026/10/25 19:06:31 INFO Completed upload id=2 objects=2 duration=1.526916ms1140--- PASS: TestMetricsCommit (8.44s)1141=== CONT TestPushDedupSurvivesConcurrentGC11422026/10/25 19:06:31 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11432026/10/25 19:06:31 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=NzM2YjZiMzMtZjRjMC00M2Q5LWIxYmQtN2U3ZWE3ZGY4MzEzLjUyM2U1YzAwLTZkOWQtNGE5Ni04ZTMxLWYyMzhhN2UyMTc1OHgxNzkyOTU1MTg5MjE3Mzk1MDAw parts=1211442026/10/25 19:06:31 INFO Received uploads request method=POST path=/api/pending_closures1145--- PASS: TestCompletedNarNotReofferedAcrossClosures (10.59s)1146=== CONT TestGCBugBareHashReferences11472026/10/25 19:06:32 WARN Rate limiter enabled after throttle name=s3-test rate=511482026/10/25 19:06:32 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1149=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1150 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101151 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001152--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (10.98s)1153=== CONT TestGCAdvisoryLockBlocksConcurrentRun1154--- PASS: TestMetricsInventory (8.78s)1155=== CONT TestLeadEndsOnShutdown11562026/10/25 19:06:32 INFO Received uploads request method=POST path=/api/pending_closures11572026/10/25 19:06:32 INFO Received push request method=POST path=/api/pushes11582026/10/25 19:06:32 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)11592026/10/25 19:06:32 INFO Uploading wrc6iab00311yyq5dk5vakrqv1x4h815-a (256B)11602026/10/25 19:06:32 INFO Uploading mla7rcbwxvyiinqdn580dk2q325qdmyi-shared-dep (136B)11612026/10/25 19:06:32 INFO Aborted multipart uploads count=0 kept=011622026/10/25 19:06:32 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11632026/10/25 19:06:32 WARN Force mode enabled - objects will be deleted immediately without grace period11642026/10/25 19:06: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=011652026/10/25 19:06:32 WARN Failed to register uploaded object key=w9vbij1q3a1y98iy0f5dg8bn92pcqwir.ls error="server returned 404: 404 page not found\n"11662026/10/25 19:06:32 WARN Failed to register uploaded object key=nar/0nbicizdq8mnc4ns48pgq33l14nm9525xzs3wz5cwjdhx86m35h0.nar.zst error="server returned 404: 404 page not found\n"11672026/10/25 19:06:32 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"11682026/10/25 19:06:32 WARN Failed to register uploaded object key=wrc6iab00311yyq5dk5vakrqv1x4h815.ls error="server returned 404: 404 page not found\n"11692026/10/25 19:06:32 INFO Aborted multipart uploads count=1 kept=011702026/10/25 19:06:32 WARN Failed to register uploaded object key=mla7rcbwxvyiinqdn580dk2q325qdmyi.ls error="server returned 404: 404 page not found\n"11712026/10/25 19:06:32 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11722026/10/25 19:06:32 INFO Signed narinfos id=1 count=311732026/10/25 19:06:32 INFO Vacuumed table table=pending_closures11742026/10/25 19:06:32 INFO Uploading 3 narinfos11752026/10/25 19:06:32 INFO Received cleanup request method=DELETE path=/api/pending_closures11762026/10/25 19:06:32 INFO Aborted multipart uploads count=1 kept=011772026/10/25 19:06:32 INFO Vacuumed table table=pending_objects11782026/10/25 19:06:32 INFO Vacuumed table table=multipart_uploads1179--- PASS: TestPendingCleanupUsesOneCutoff (11.58s)1180=== CONT TestGCMetrics11812026/10/25 19:06:32 INFO Vacuumed table table=closures11822026/10/25 19:06:32 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=NzM2YjZiMzMtZjRjMC00M2Q5LWIxYmQtN2U3ZWE3ZGY4MzEzLjIxODRkOGYwLTliMTktNDFlMS1hOTIwLTA3M2VjY2RiZTQ2OXgxNzkyOTU1MTkwMzQwMTUzMDAw error="Get \"http://127.0.0.1:1/bucket22/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"11832026/10/25 19:06:32 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=NzM2YjZiMzMtZjRjMC00M2Q5LWIxYmQtN2U3ZWE3ZGY4MzEzLmUwYTlmNDliLTYwZmItNDZiMi05NzNhLTFmZTMyODY5OTg2ZHgxNzkyOTU1MTkwMjczMjEyMDAw parts=1211842026/10/25 19:06:32 INFO Received cleanup request method=DELETE path=/api/pending_closures11852026/10/25 19:06:32 WARN Failed to register uploaded object key=w9vbij1q3a1y98iy0f5dg8bn92pcqwir.narinfo error="server returned 404: 404 page not found\n"11862026/10/25 19:06:32 WARN Failed to register uploaded object key=wrc6iab00311yyq5dk5vakrqv1x4h815.narinfo error="server returned 404: 404 page not found\n"11872026/10/25 19:06:32 INFO Received complete push request method=POST path=/api/pushes/1/complete11882026/10/25 19:06:32 WARN Failed to register uploaded object key=mla7rcbwxvyiinqdn580dk2q325qdmyi.narinfo error="server returned 404: 404 page not found\n"11892026/10/25 19:06:32 INFO Aborted multipart uploads count=1 kept=011902026/10/25 19:06:32 INFO Vacuumed table table=objects1191--- PASS: TestRedundantMultipartUpload (11.59s)1192=== CONT TestGCTaskStore_PhaseUpdates1193--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1194=== CONT TestGCTaskStore_Fail1195--- PASS: TestGCTaskStore_Fail (0.00s)1196=== CONT TestReadProxyRootRedirectsToIndexHTML11972026/10/25 19:06:32 INFO Completed push id=1 objects=8 duration=39.363209ms11982026/10/25 19:06:32 INFO Upload complete. (375ms)1199=== NAME TestClientPushesUseOnePush1200 client_pushes_test.go:97: Retrieved narinfo from S3:1201 StorePath: /private/var/tb/3/scratch/0f9658a1e8df3254/build/TestClientPushesUseOnePush3242752935/001/store/mla7rcbwxvyiinqdn580dk2q325qdmyi-shared-dep1202 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1203 Compression: zstd1204 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821205 NarSize: 1361206 References: 1207 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1208 client_pushes_test.go:97: Retrieved narinfo from S3:1209 StorePath: /private/var/tb/3/scratch/0f9658a1e8df3254/build/TestClientPushesUseOnePush3242752935/001/store/wrc6iab00311yyq5dk5vakrqv1x4h815-a1210 URL: nar/0nbicizdq8mnc4ns48pgq33l14nm9525xzs3wz5cwjdhx86m35h0.nar.zst1211 Compression: zstd1212 NarHash: sha256:0nbicizdq8mnc4ns48pgq33l14nm9525xzs3wz5cwjdhx86m35h01213 NarSize: 2561214 References: /private/var/tb/3/scratch/0f9658a1e8df3254/build/TestClientPushesUseOnePush3242752935/001/store/mla7rcbwxvyiinqdn580dk2q325qdmyi-shared-dep1215 CA: text:sha256:0z0s46yla620xaw5wyzdaa07jxzy8l9k7z1rigvwnwfvmggzp2kh1216 client_pushes_test.go:97: Retrieved narinfo from S3:1217 StorePath: /private/var/tb/3/scratch/0f9658a1e8df3254/build/TestClientPushesUseOnePush3242752935/001/store/w9vbij1q3a1y98iy0f5dg8bn92pcqwir-b1218 URL: nar/0nbicizdq8mnc4ns48pgq33l14nm9525xzs3wz5cwjdhx86m35h0.nar.zst1219 Compression: zstd1220 NarHash: sha256:0nbicizdq8mnc4ns48pgq33l14nm9525xzs3wz5cwjdhx86m35h01221 NarSize: 2561222 References: /private/var/tb/3/scratch/0f9658a1e8df3254/build/TestClientPushesUseOnePush3242752935/001/store/mla7rcbwxvyiinqdn580dk2q325qdmyi-shared-dep1223 CA: text:sha256:0z0s46yla620xaw5wyzdaa07jxzy8l9k7z1rigvwnwfvmggzp2kh1224--- PASS: TestGCSweepSkipsPendingObjects (9.01s)1225=== CONT TestPush_RootsAreLockedInByteOrder1226--- PASS: TestClientPushesUseOnePush (9.36s)1227=== CONT TestPush_CompleteWaitsForCleanupOfThePush1228=== NAME TestNARDeduplicationMetadataUploadBug1229 metadata_upload_test.go:48: First store path: /private/var/tb/3/scratch/0f9658a1e8df3254/build/TestNARDeduplicationMetadataUploadBug2739356440/001/store/pz4z1ks2lf79bpwkrxnlc9sxfyvfv0kq-file1.txt12302026/10/25 19:06:33 INFO Received push request method=POST path=/api/pushes12312026/10/25 19:06:33 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12322026/10/25 19:06:33 INFO Uploading pz4z1ks2lf79bpwkrxnlc9sxfyvfv0kq-file1.txt (160B)12332026/10/25 19:06:33 INFO Aborted multipart uploads count=0 kept=012342026/10/25 19:06:33 WARN Failed to register uploaded object key=pz4z1ks2lf79bpwkrxnlc9sxfyvfv0kq.ls error="server returned 404: 404 page not found\n"12352026/10/25 19:06:33 WARN Force mode enabled - objects will be deleted immediately without grace period12362026/10/25 19:06:33 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=012372026/10/25 19:06:33 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12382026/10/25 19:06:33 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"12392026/10/25 19:06:33 INFO Signed narinfos id=1 count=112402026/10/25 19:06:33 INFO Uploading 1 narinfos12412026/10/25 19:06:33 INFO Vacuumed table table=pending_closures12422026/10/25 19:06:33 INFO Received complete push request method=POST path=/api/pushes/1/complete12432026/10/25 19:06:33 INFO Vacuumed table table=pending_objects12442026/10/25 19:06:33 WARN Failed to register uploaded object key=pz4z1ks2lf79bpwkrxnlc9sxfyvfv0kq.narinfo error="server returned 404: 404 page not found\n"12452026/10/25 19:06:33 INFO Vacuumed table table=multipart_uploads12462026/10/25 19:06:33 INFO Vacuumed table table=closures12472026/10/25 19:06:33 INFO Vacuumed table table=objects12482026/10/25 19:06:33 INFO Completed push id=1 objects=3 duration=48.316083ms12492026/10/25 19:06:33 INFO Upload complete. (333ms)1250 metadata_upload_test.go:54: Retrieved narinfo from S3:1251 StorePath: /private/var/tb/3/scratch/0f9658a1e8df3254/build/TestNARDeduplicationMetadataUploadBug2739356440/001/store/pz4z1ks2lf79bpwkrxnlc9sxfyvfv0kq-file1.txt1252 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1253 Compression: zstd1254 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1255 NarSize: 1601256 References: 1257 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1258 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1259--- PASS: TestCommitRacingPendingCleanupKeepsObjects (8.56s)1260=== CONT TestPush_RepeatedRootCommitsOnce1261=== NAME TestNARDeduplicationMetadataUploadBug1262 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1263 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}12642026/10/25 19:06:33 INFO Received uploads request method=POST path=/api/pending_closures1265 metadata_upload_test.go:64: Second store path (same content): /private/var/tb/3/scratch/0f9658a1e8df3254/build/TestNARDeduplicationMetadataUploadBug2739356440/001/store/w9vxgmlrggvswq5566fdh259b7gk2qvy-file2.txt12662026/10/25 19:06:33 INFO Received push request method=POST path=/api/pushes12672026/10/25 19:06:33 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)12682026/10/25 19:06:33 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign12692026/10/25 19:06:33 WARN Failed to register uploaded object key=w9vxgmlrggvswq5566fdh259b7gk2qvy.ls error="server returned 404: 404 page not found\n"12702026/10/25 19:06:33 INFO Signed narinfos id=2 count=112712026/10/25 19:06:33 INFO Uploading 1 narinfos12722026/10/25 19:06:33 INFO Received complete push request method=POST path=/api/pushes/2/complete12732026/10/25 19:06:33 WARN Failed to register uploaded object key=w9vxgmlrggvswq5566fdh259b7gk2qvy.narinfo error="server returned 404: 404 page not found\n"12742026/10/25 19:06:33 INFO Completed push id=2 objects=3 duration=599.042µs12752026/10/25 19:06:33 INFO Upload complete. (147ms)1276 metadata_upload_test.go:76: Retrieved narinfo from S3:1277 StorePath: /private/var/tb/3/scratch/0f9658a1e8df3254/build/TestNARDeduplicationMetadataUploadBug2739356440/001/store/w9vxgmlrggvswq5566fdh259b7gk2qvy-file2.txt1278 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1279 Compression: zstd1280 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1281 NarSize: 1601282 References: 1283 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1284 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1285 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1286 {"version":1,"root":{"type":"regular","size":44}}1287--- PASS: TestNARDeduplicationMetadataUploadBug (9.33s)1288=== CONT TestPush_CompleteCommitsEveryRoot12892026/10/25 19:06:33 WARN readiness check failed error="closed pool"1290--- PASS: TestService_readinessHandler (8.26s)1291=== CONT TestConnectWaitsForAPeerMigration1292--- PASS: TestPushWaitsForSweepHoldingRow (9.09s)1293=== CONT TestPush_OverlappingRootsStoreOneRowPerKey12942026/10/25 19:06:34 INFO Aborted multipart uploads count=0 kept=012952026/10/25 19:06:34 WARN Force mode enabled - objects will be deleted immediately without grace period12962026/10/25 19:06:34 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=012972026/10/25 19:06:34 INFO Vacuumed table table=pending_closures12982026/10/25 19:06:34 INFO Vacuumed table table=pending_objects12992026/10/25 19:06:34 INFO Vacuumed table table=multipart_uploads13002026/10/25 19:06:34 INFO Vacuumed table table=closures13012026/10/25 19:06:34 INFO Vacuumed table table=objects1302--- PASS: TestSweepRechecksPendingAfterLocking (8.69s)1303=== CONT TestResolveDBConnectionString1304=== RUN TestResolveDBConnectionString/flag_wins1305=== PAUSE TestResolveDBConnectionString/flag_wins1306=== RUN TestResolveDBConnectionString/file_when_flag_empty1307=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1308=== RUN TestResolveDBConnectionString/missing_file_is_an_error1309=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1310=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1311=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1312=== RUN TestResolveDBConnectionString/nothing_configured1313=== PAUSE TestResolveDBConnectionString/nothing_configured1314=== CONT TestReadRedirectUsesPublicS3URL1315--- PASS: TestGetExistingObjectsLocksRows (7.91s)1316=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock1317--- PASS: TestRegisterCompletedObjectNeedsPendingRow (7.94s)1318=== CONT TestReadProxyRangeRequest13192026/10/25 19:06:35 INFO Received uploads request method=POST path=/api/pending_closures1320--- PASS: TestDeduplicatedObjectsRecordedAsPending (7.75s)1321=== CONT TestDeleteClosuresRacingPins13222026/10/25 19:06:35 INFO Aborted multipart uploads count=0 kept=013232026/10/25 19:06:35 WARN Force mode enabled - objects will be deleted immediately without grace period13242026/10/25 19:06: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=013252026/10/25 19:06:35 INFO Vacuumed table table=pending_closures13262026/10/25 19:06:35 INFO Vacuumed table table=pending_objects13272026/10/25 19:06:35 INFO Vacuumed table table=multipart_uploads13282026/10/25 19:06:35 INFO Vacuumed table table=closures13292026/10/25 19:06:35 INFO Vacuumed table table=objects13302026/10/25 19:06:35 INFO Aborted multipart uploads count=0 kept=013312026/10/25 19:06:35 WARN Force mode enabled - objects will be deleted immediately without grace period1332--- PASS: TestService_healthCheckHandler (7.25s)1333=== CONT TestReadRedirectKeepsNarinfoProxied13342026/10/25 19:06:36 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=013352026/10/25 19:06:36 INFO Vacuumed table table=pending_closures13362026/10/25 19:06:36 INFO Vacuumed table table=pending_objects13372026/10/25 19:06:36 INFO Vacuumed table table=multipart_uploads13382026/10/25 19:06:36 INFO Vacuumed table table=closures13392026/10/25 19:06:36 INFO Vacuumed table table=objects1340--- PASS: TestSweepSkipsRowsLockedByPush (7.70s)1341=== CONT TestReadRedirectNar13422026/10/25 19:06:36 INFO lead: acquired remote=192.0.2.1:123413432026/10/25 19:06:36 INFO Received uploads request method=POST path=/api/pending_closures13442026/10/25 19:06:36 INFO Aborted multipart uploads count=0 kept=013452026/10/25 19:06:36 WARN Force mode enabled - objects will be deleted immediately without grace period13462026/10/25 19:06:36 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."13472026/10/25 19:06:36 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."1348--- PASS: TestFailedS3DeleteKeepsTombstone (6.93s)1349=== CONT TestClientFallsBackToClosures13502026/10/25 19:06:37 INFO lead: acquired remote=192.0.2.1:123413512026/10/25 19:06:37 INFO lead: released remote=192.0.2.1:12341352--- PASS: TestLeadIncumbentAnnouncesAtOnce (6.45s)1353=== CONT TestReadProxyDisabled13542026/10/25 19:06:37 INFO Received uploads request method=POST path=/api/pending_closures1355=== NAME TestOrphanedObjectsGCStressTest1356 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains1357--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (7.04s)1358=== CONT TestGCTaskStore_CompletedAllowsNewTask1359--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1360=== CONT TestClientErrorHandling1361=== RUN TestClientErrorHandling/InvalidStorePath1362=== PAUSE TestClientErrorHandling/InvalidStorePath1363=== RUN TestClientErrorHandling/InvalidAuthToken1364=== PAUSE TestClientErrorHandling/InvalidAuthToken1365=== RUN TestClientErrorHandling/ServerNotAvailable1366=== PAUSE TestClientErrorHandling/ServerNotAvailable1367=== CONT TestClientIntegration1368=== NAME TestOrphanedObjectsGCStressTest1369 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion13702026/10/25 19:06:37 INFO lead: released remote=192.0.2.1:123413712026/10/25 19:06:37 INFO lead: acquired remote=192.0.2.1:123413722026/10/25 19:06:37 INFO Aborted multipart uploads count=0 kept=013732026/10/25 19:06:37 WARN Force mode enabled - objects will be deleted immediately without grace period13742026/10/25 19:06:38 INFO Received uploads request method=POST path=/api/pending_closures13752026/10/25 19:06: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=013762026/10/25 19:06:38 INFO Vacuumed table table=pending_closures13772026/10/25 19:06:38 INFO Vacuumed table table=pending_objects13782026/10/25 19:06:38 INFO Vacuumed table table=multipart_uploads13792026/10/25 19:06:38 INFO Vacuumed table table=closures13802026/10/25 19:06:38 INFO Vacuumed table table=objects1381--- PASS: TestGCSweepDeliversEachKeyOnce (7.54s)1382=== CONT TestCacheStatsHandler13832026/10/25 19:06:38 INFO Aborted multipart uploads count=0 kept=013842026/10/25 19:06:38 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=013852026/10/25 19:06:38 INFO Vacuumed table table=pending_closures13862026/10/25 19:06:38 INFO Vacuumed table table=pending_objects13872026/10/25 19:06:38 INFO Vacuumed table table=multipart_uploads13882026/10/25 19:06:38 INFO Vacuumed table table=closures13892026/10/25 19:06:38 INFO Vacuumed table table=objects1390--- PASS: TestGCBugBareHashReferences (6.77s)1391=== CONT TestClientCADerivations13922026/10/25 19:06:38 INFO Aborted multipart uploads count=0 kept=013932026/10/25 19:06:38 WARN Force mode enabled - objects will be deleted immediately without grace period13942026/10/25 19:06: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=013952026/10/25 19:06:38 INFO Vacuumed table table=pending_closures13962026/10/25 19:06:38 INFO Vacuumed table table=pending_objects13972026/10/25 19:06:38 INFO Vacuumed table table=multipart_uploads13982026/10/25 19:06:38 INFO lead: released remote=192.0.2.1:12341399--- PASS: TestLeadElectsOneAndHandsOver (9.09s)1400=== CONT TestService_AuthMiddleware_MTLSBoundSubjects14012026/10/25 19:06:38 ERROR failed to check GC advisory lock error="query pg_locks: failed to connect to `user=_tribuchetbld3 database=niks3`: /nonexistent/.s.PGSQL.5432 (/nonexistent): dial error: dial unix /nonexistent/.s.PGSQL.5432: connect: no such file or directory"1402--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (6.52s)14032026/10/25 19:06:38 INFO Vacuumed table table=closures1404=== CONT TestClientMultipleUploads14052026/10/25 19:06:38 INFO Vacuumed table table=objects1406--- PASS: TestPushDedupSurvivesConcurrentGC (7.24s)1407=== CONT TestPinProtectsFromGC14082026/10/25 19:06:39 INFO lead: acquired remote=192.0.2.1:123414092026/10/25 19:06:39 INFO Received push request method=POST path=/api/pushes14102026-10-25 19:06:39.595 UTC [21515] ERROR: could not obtain lock on row in relation "closures"14112026-10-25 19:06:39.595 UTC [21515] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT14122026-10-25 19:06:39.598 UTC [21515] ERROR: could not obtain lock on row in relation "closures"14132026-10-25 19:06:39.598 UTC [21515] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT14142026-10-25 19:06:39.599 UTC [21515] ERROR: could not obtain lock on row in relation "closures"14152026-10-25 19:06:39.599 UTC [21515] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT14162026-10-25 19:06:39.603 UTC [21515] ERROR: could not obtain lock on row in relation "closures"14172026-10-25 19:06:39.603 UTC [21515] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT14182026-10-25 19:06:39.609 UTC [21515] ERROR: could not obtain lock on row in relation "closures"14192026-10-25 19:06:39.609 UTC [21515] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT1420--- PASS: TestPush_RootsAreLockedInByteOrder (6.72s)1421=== CONT TestClientSharedPathCommittedMidPush14222026/10/25 19:06:39 INFO Aborted multipart uploads count=0 kept=014232026/10/25 19:06:39 WARN Force mode enabled - objects will be deleted immediately without grace period14242026/10/25 19:06:39 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=014252026/10/25 19:06:39 INFO Vacuumed table table=pending_closures14262026/10/25 19:06:39 INFO Vacuumed table table=pending_objects14272026/10/25 19:06:39 INFO Vacuumed table table=multipart_uploads14282026/10/25 19:06:39 INFO Vacuumed table table=closures14292026/10/25 19:06:39 INFO Vacuumed table table=objects1430--- PASS: TestGCMetrics (7.01s)1431=== CONT TestService_AuthMiddleware_OIDC14322026/10/25 19:06:39 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55630/oidc1433--- PASS: TestReadProxyRootRedirectsToIndexHTML (7.17s)1434=== CONT TestClientWithDependencies14352026/10/25 19:06:40 INFO lead: released remote=192.0.2.1:12341436--- PASS: TestLeadEndsOnShutdown (7.76s)1437=== CONT TestCacheConfigHandler1438=== RUN TestCacheConfigHandler/full_config,_no_issuer1439=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1440=== RUN TestCacheConfigHandler/no_cache_url_configured1441=== PAUSE TestCacheConfigHandler/no_cache_url_configured1442=== RUN TestCacheConfigHandler/no_signing_keys1443=== PAUSE TestCacheConfigHandler/no_signing_keys1444=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1445=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1446=== CONT TestService_ReadScope_PublicByDefault14472026/10/25 19:06:40 INFO Received push request method=POST path=/api/pushes14482026/10/25 19:06:40 INFO Received push request method=POST path=/api/pushes14492026-10-25 19:06:40.791 UTC [21528] ERROR: Push does not exist: id=114502026-10-25 19:06:40.791 UTC [21528] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE14512026-10-25 19:06:40.791 UTC [21528] STATEMENT: SELECT commit_push($1)1452--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (7.78s)1453=== CONT TestReadProxyNarStreaming14542026/10/25 19:06:40 INFO Received complete push request method=POST path=/api/pushes/1/complete14552026/10/25 19:06:40 INFO Completed push id=1 objects=6 duration=40.126125ms1456--- PASS: TestPush_CompleteCommitsEveryRoot (6.93s)1457=== CONT TestService_RequireScope_OIDC14582026/10/25 19:06:41 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55644/oidc14592026/10/25 19:06:41 INFO Received push request method=POST path=/api/pushes14602026/10/25 19:06:41 INFO Received complete push request method=POST path=/api/pushes/1/complete14612026/10/25 19:06:41 INFO Completed push id=1 objects=4 duration=34.87775ms1462--- PASS: TestPush_RepeatedRootCommitsOnce (7.57s)1463=== CONT TestReadProxyConditionalGet14642026/10/25 19:06:41 INFO Received push request method=POST path=/api/pushes1465--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (7.28s)1466=== CONT TestReadProxyOutlastsServerWriteTimeout1467--- PASS: TestReadRedirectUsesPublicS3URL (7.15s)1468=== CONT TestReadProxyInvalidPath1469--- PASS: TestConnectWaitsForAPeerMigration (8.18s)1470=== CONT TestReadProxy4041471--- PASS: TestReadProxyRangeRequest (7.54s)1472=== CONT TestReadProxyHead1473--- PASS: TestReadRedirectKeepsNarinfoProxied (7.20s)1474=== CONT TestReadProxyNarinfo1475--- PASS: TestReadRedirectNar (7.31s)1476=== CONT TestReadProxyContentNegotiation1477--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (8.94s)1478=== CONT TestService_AuthMiddleware_MTLSProxyHeader1479--- PASS: TestReadProxyDisabled (7.20s)1480=== CONT TestReadProxyNarinfoAlreadyDecompressed14812026/10/25 19:06:44 INFO Received uploads request method=POST path=/api/pending_closures14822026/10/25 19:06:44 INFO Received uploads request method=POST path=/api/pending_closures14832026/10/25 19:06:44 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)14842026/10/25 19:06:44 INFO Uploading 983z5kihxcrqhcn0hnwd52zrynmi3lww-shared-dep (136B)14852026/10/25 19:06:44 INFO Uploading hfsbhma2bmvklrpcfj2qr14kri0c5kz4-b (256B)14862026/10/25 19:06:44 WARN Failed to register uploaded object key=wv8zilid74a1787rdn372xdv75g3j6ip.ls error="server returned 404: 404 page not found\n"14872026/10/25 19:06:44 WARN Failed to register uploaded object key=983z5kihxcrqhcn0hnwd52zrynmi3lww.ls error="server returned 404: 404 page not found\n"14882026/10/25 19:06:44 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"14892026/10/25 19:06:44 WARN Failed to register uploaded object key=nar/0swrxrzcqfv5s7xy7inkbpgabr6s8c4xhn7lzr0s87gi5jdzia8h.nar.zst error="server returned 404: 404 page not found\n"14902026/10/25 19:06:44 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign14912026/10/25 19:06:44 WARN Failed to register uploaded object key=hfsbhma2bmvklrpcfj2qr14kri0c5kz4.ls error="server returned 404: 404 page not found\n"14922026/10/25 19:06:44 INFO Signed narinfos id=1 count=214932026/10/25 19:06:44 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign14942026/10/25 19:06:44 INFO Signed narinfos id=2 count=214952026/10/25 19:06:44 INFO Uploading 4 narinfos14962026/10/25 19:06:44 WARN Failed to register uploaded object key=hfsbhma2bmvklrpcfj2qr14kri0c5kz4.narinfo error="server returned 404: 404 page not found\n"14972026/10/25 19:06:44 WARN Failed to register uploaded object key=wv8zilid74a1787rdn372xdv75g3j6ip.narinfo error="server returned 404: 404 page not found\n"14982026/10/25 19:06:44 WARN Failed to register uploaded object key=983z5kihxcrqhcn0hnwd52zrynmi3lww.narinfo error="server returned 404: 404 page not found\n"14992026/10/25 19:06:44 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete15002026/10/25 19:06:44 WARN Failed to register uploaded object key=983z5kihxcrqhcn0hnwd52zrynmi3lww.narinfo error="server returned 404: 404 page not found\n"15012026/10/25 19:06:44 INFO Completed upload id=1 objects=6 duration=24.096291ms15022026/10/25 19:06:44 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete15032026/10/25 19:06:44 INFO Completed upload id=2 objects=6 duration=858.375µs15042026/10/25 19:06:44 INFO Upload complete. (418ms)1505=== NAME TestClientFallsBackToClosures1506 client_pushes_test.go:112: Retrieved narinfo from S3:1507 StorePath: /private/var/tb/3/scratch/0f9658a1e8df3254/build/TestClientFallsBackToClosures2887945562/001/store/983z5kihxcrqhcn0hnwd52zrynmi3lww-shared-dep1508 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1509 Compression: zstd1510 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821511 NarSize: 1361512 References: 1513 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1514 client_pushes_test.go:112: Retrieved narinfo from S3:1515 StorePath: /private/var/tb/3/scratch/0f9658a1e8df3254/build/TestClientFallsBackToClosures2887945562/001/store/wv8zilid74a1787rdn372xdv75g3j6ip-a1516 URL: nar/0swrxrzcqfv5s7xy7inkbpgabr6s8c4xhn7lzr0s87gi5jdzia8h.nar.zst1517 Compression: zstd1518 NarHash: sha256:0swrxrzcqfv5s7xy7inkbpgabr6s8c4xhn7lzr0s87gi5jdzia8h1519 NarSize: 2561520 References: /private/var/tb/3/scratch/0f9658a1e8df3254/build/TestClientFallsBackToClosures2887945562/001/store/983z5kihxcrqhcn0hnwd52zrynmi3lww-shared-dep1521 CA: text:sha256:0m8fpkmpm2kjwyd38szn2z1k6krsjs2rd75r2xhxmxyfxv2f1a3v1522 client_pushes_test.go:112: Retrieved narinfo from S3:1523 StorePath: /private/var/tb/3/scratch/0f9658a1e8df3254/build/TestClientFallsBackToClosures2887945562/001/store/hfsbhma2bmvklrpcfj2qr14kri0c5kz4-b1524 URL: nar/0swrxrzcqfv5s7xy7inkbpgabr6s8c4xhn7lzr0s87gi5jdzia8h.nar.zst1525 Compression: zstd1526 NarHash: sha256:0swrxrzcqfv5s7xy7inkbpgabr6s8c4xhn7lzr0s87gi5jdzia8h1527 NarSize: 2561528 References: /private/var/tb/3/scratch/0f9658a1e8df3254/build/TestClientFallsBackToClosures2887945562/001/store/983z5kihxcrqhcn0hnwd52zrynmi3lww-shared-dep1529 CA: text:sha256:0m8fpkmpm2kjwyd38szn2z1k6krsjs2rd75r2xhxmxyfxv2f1a3v1530=== NAME TestClientIntegration1531 client_integration_test.go:286: Created store path: /private/var/tb/3/scratch/0f9658a1e8df3254/build/TestClientIntegration1672464605/002/store/n4z6x2bh41liykcn4cwldcsyp6capghg-test-file.txt1532--- PASS: TestCacheStatsHandler (6.57s)1533=== CONT TestIsValidCachePath1534=== RUN TestIsValidCachePath/narinfo1535=== PAUSE TestIsValidCachePath/narinfo1536=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1537=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1538=== RUN TestIsValidCachePath/nar_zst1539=== PAUSE TestIsValidCachePath/nar_zst1540=== RUN TestIsValidCachePath/nar_xz1541--- PASS: TestClientFallsBackToClosures (8.03s)1542=== CONT TestService_ReadAuthMiddleware1543=== PAUSE TestIsValidCachePath/nar_xz1544=== RUN TestIsValidCachePath/nar_bz21545=== PAUSE TestIsValidCachePath/nar_bz21546=== RUN TestIsValidCachePath/nar_uncompressed1547=== PAUSE TestIsValidCachePath/nar_uncompressed1548=== RUN TestIsValidCachePath/ls1549=== PAUSE TestIsValidCachePath/ls1550=== RUN TestIsValidCachePath/log1551=== PAUSE TestIsValidCachePath/log1552=== RUN TestIsValidCachePath/realisation1553=== PAUSE TestIsValidCachePath/realisation1554=== RUN TestIsValidCachePath/nix-cache-info1555=== PAUSE TestIsValidCachePath/nix-cache-info1556=== RUN TestIsValidCachePath/index.html1557=== PAUSE TestIsValidCachePath/index.html1558=== RUN TestIsValidCachePath/traversal_parent1559=== PAUSE TestIsValidCachePath/traversal_parent1560=== RUN TestIsValidCachePath/traversal_in_middle1561=== PAUSE TestIsValidCachePath/traversal_in_middle1562=== RUN TestIsValidCachePath/invalid_char_e1563=== PAUSE TestIsValidCachePath/invalid_char_e1564=== RUN TestIsValidCachePath/invalid_char_u1565=== PAUSE TestIsValidCachePath/invalid_char_u1566=== RUN TestIsValidCachePath/random_path1567=== PAUSE TestIsValidCachePath/random_path1568=== RUN TestIsValidCachePath/empty1569=== PAUSE TestIsValidCachePath/empty1570=== RUN TestIsValidCachePath/leading_slash1571=== PAUSE TestIsValidCachePath/leading_slash1572=== RUN TestIsValidCachePath/wrong_extension1573=== PAUSE TestIsValidCachePath/wrong_extension1574=== RUN TestIsValidCachePath/short_hash1575=== PAUSE TestIsValidCachePath/short_hash1576=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale15772026/10/25 19:06:45 INFO Received push request method=POST path=/api/pushes15782026/10/25 19:06:45 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15792026/10/25 19:06:45 INFO Uploading n4z6x2bh41liykcn4cwldcsyp6capghg-test-file.txt (152B)15802026/10/25 19:06:45 WARN Failed to register uploaded object key=n4z6x2bh41liykcn4cwldcsyp6capghg.ls error="server returned 404: 404 page not found\n"15812026/10/25 19:06:45 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15822026/10/25 19:06:45 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"15832026/10/25 19:06:45 INFO Signed narinfos id=1 count=115842026/10/25 19:06:45 INFO Uploading 1 narinfos15852026/10/25 19:06:45 INFO Received complete push request method=POST path=/api/pushes/1/complete15862026/10/25 19:06:45 WARN Failed to register uploaded object key=n4z6x2bh41liykcn4cwldcsyp6capghg.narinfo error="server returned 404: 404 page not found\n"15872026/10/25 19:06:45 INFO Completed push id=1 objects=3 duration=30.764209ms15882026/10/25 19:06:45 INFO Upload complete. (246ms)15892026/10/25 19:06:45 INFO All 1 paths already cached1590=== NAME TestClientIntegration1591 client_integration_test.go:312: Retrieved narinfo from S3:1592 StorePath: /private/var/tb/3/scratch/0f9658a1e8df3254/build/TestClientIntegration1672464605/002/store/n4z6x2bh41liykcn4cwldcsyp6capghg-test-file.txt1593 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1594 Compression: zstd1595 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11596 NarSize: 1521597 References: 1598 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11599 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)1600 client_integration_test.go:313: Decompressed .ls content (64 bytes):1601 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1602 client_integration_test.go:316: Testing garbage collection...16032026/10/25 19:06:45 INFO Starting cleanup of old closures method=DELETE path=/api/closures16042026/10/25 19:06:45 INFO Garbage collection started16052026/10/25 19:06:45 INFO Aborted multipart uploads count=0 kept=016062026/10/25 19:06:45 WARN Force mode enabled - objects will be deleted immediately without grace period1607=== NAME TestClientCADerivations1608 client_ca_test.go:136: Built CA derivation: /private/var/tb/3/scratch/0f9658a1e8df3254/build/TestClientCADerivations1102112650/001/store/fkzm4p28cnli03knb3gfb6dc9s3mnhfn-ca-test16092026/10/25 19:06: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=016102026/10/25 19:06:46 INFO Vacuumed table table=pending_closures1611 client_ca_test.go:139: Found 1 dependencies (including self)1612=== NAME TestClientMultipleUploads1613 client_integration_test.go:358: Created store path 0: /private/var/tb/3/scratch/0f9658a1e8df3254/build/TestClientMultipleUploads513575938/001/store/z3fjci0x1g0a2yas3jv3wdkny3v5ydm1-test-file-0.txt16142026/10/25 19:06:46 INFO Vacuumed table table=pending_objects16152026/10/25 19:06:46 INFO Vacuumed table table=multipart_uploads16162026/10/25 19:06:46 INFO Vacuumed table table=closures16172026/10/25 19:06:46 INFO Vacuumed table table=objects1618 client_integration_test.go:358: Created store path 1: /private/var/tb/3/scratch/0f9658a1e8df3254/build/TestClientMultipleUploads513575938/001/store/pv147m5x2f0hkksr1nfnc0mqs9zirgqw-test-file-1.txt16192026/10/25 19:06:46 INFO Received push request method=POST path=/api/pushes16202026/10/25 19:06:46 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16212026/10/25 19:06:46 INFO Uploading fkzm4p28cnli03knb3gfb6dc9s3mnhfn-ca-test (144B)16222026/10/25 19:06:46 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"16232026/10/25 19:06:46 WARN mTLS auth: bound subjects configured but subject DN unavailable16242026/10/25 19:06:46 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1625 client_integration_test.go:358: Created store path 2: /private/var/tb/3/scratch/0f9658a1e8df3254/build/TestClientMultipleUploads513575938/001/store/v0vg175i1mqh7nk650wf92w5v7s5lkhd-test-file-2.txt1626--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (7.56s)1627=== CONT TestProxyWriteTimeout/narinfo16282026/10/25 19:06:46 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"16292026/10/25 19:06:46 WARN Failed to register uploaded object key=fkzm4p28cnli03knb3gfb6dc9s3mnhfn.ls error="server returned 404: 404 page not found\n"16302026/10/25 19:06:46 WARN Failed to register uploaded object key=log/sgi9vjrq9r23nf3yprnp5gkybqmizk13-ca-test.drv error="server returned 404: 404 page not found\n"1631=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh16322026/10/25 19:06:46 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16332026/10/25 19:06:46 INFO Signed narinfos id=1 count=116342026/10/25 19:06:46 INFO Uploading 1 narinfos16352026/10/25 19:06:46 INFO Received complete push request method=POST path=/api/pushes/1/complete16362026/10/25 19:06:46 WARN Failed to register uploaded object key=fkzm4p28cnli03knb3gfb6dc9s3mnhfn.narinfo error="server returned 404: 404 page not found\n"1637=== NAME TestPinProtectsFromGC1638 client_integration_test.go:731: Pinned store path: /private/var/tb/3/scratch/0f9658a1e8df3254/build/TestPinProtectsFromGC1595554872/001/store/rbvarpjnmvgxphmsfjsl6jj08fhz9q2l-pinned-file.txt1639 client_integration_test.go:732: Unpinned store path: /private/var/tb/3/scratch/0f9658a1e8df3254/build/TestPinProtectsFromGC1595554872/001/store/yqdgmdryiv0w1vyx3avf53632m42ji02-unpinned-file.txt16402026/10/25 19:06:46 INFO Received push request method=POST path=/api/pushes16412026/10/25 19:06:46 INFO Completed push id=1 objects=4 duration=12.876875ms16422026/10/25 19:06:46 INFO Upload complete. (312ms)1643=== NAME TestClientCADerivations1644 client_ca_test.go:180: Narinfo contains CA field: StorePath: /private/var/tb/3/scratch/0f9658a1e8df3254/build/TestClientCADerivations1102112650/001/store/fkzm4p28cnli03knb3gfb6dc9s3mnhfn-ca-test1645 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1646 Compression: zstd1647 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1648 NarSize: 1441649 References: 1650 Deriver: /private/var/tb/3/scratch/0f9658a1e8df3254/build/TestClientCADerivations1102112650/001/store/sgi9vjrq9r23nf3yprnp5gkybqmizk13-ca-test.drv1651 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1652 client_ca_test.go:185: Checking for realisation files in S3...16532026/10/25 19:06:46 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)1654 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations16552026/10/25 19:06:46 INFO Uploading z3fjci0x1g0a2yas3jv3wdkny3v5ydm1-test-file-0.txt (160B)16562026/10/25 19:06:46 INFO Uploading v0vg175i1mqh7nk650wf92w5v7s5lkhd-test-file-2.txt (160B)1657 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache16582026/10/25 19:06:46 INFO Uploading pv147m5x2f0hkksr1nfnc0mqs9zirgqw-test-file-1.txt (160B)16592026/10/25 19:06:46 WARN Failed to register uploaded object key=z3fjci0x1g0a2yas3jv3wdkny3v5ydm1.ls error="server returned 404: 404 page not found\n"16602026/10/25 19:06:46 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"16612026/10/25 19:06:46 WARN Failed to register uploaded object key=v0vg175i1mqh7nk650wf92w5v7s5lkhd.ls error="server returned 404: 404 page not found\n"16622026/10/25 19:06:46 WARN Failed to register uploaded object key=pv147m5x2f0hkksr1nfnc0mqs9zirgqw.ls error="server returned 404: 404 page not found\n"16632026/10/25 19:06:46 INFO Received push request method=POST path=/api/pushes16642026/10/25 19:06:46 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"16652026/10/25 19:06:46 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16662026/10/25 19:06:46 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"16672026/10/25 19:06:46 INFO Signed narinfos id=1 count=316682026/10/25 19:06:46 INFO Uploading 3 narinfos16692026/10/25 19:06:46 WARN Failed to register uploaded object key=z3fjci0x1g0a2yas3jv3wdkny3v5ydm1.narinfo error="server returned 404: 404 page not found\n"16702026/10/25 19:06:46 WARN Failed to register uploaded object key=v0vg175i1mqh7nk650wf92w5v7s5lkhd.narinfo error="server returned 404: 404 page not found\n"16712026/10/25 19:06:46 INFO Received complete push request method=POST path=/api/pushes/1/complete16722026/10/25 19:06:46 WARN Failed to register uploaded object key=pv147m5x2f0hkksr1nfnc0mqs9zirgqw.narinfo error="server returned 404: 404 page not found\n"1673 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket71?endpoint=http://localhost:55432®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/private/var/tb/3/scratch/0f9658a1e8df3254/build/TestClientCADerivations1102112650/001/store'1674 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 116752026/10/25 19:06:46 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16762026/10/25 19:06:46 INFO Uploading rbvarpjnmvgxphmsfjsl6jj08fhz9q2l-pinned-file.txt (128B)16772026/10/25 19:06:46 INFO Completed push id=1 objects=9 duration=47.504708ms16782026/10/25 19:06:46 INFO Upload complete. (308ms)1679=== NAME TestClientMultipleUploads1680 client_integration_test.go:369: Uploaded 3 paths in 338.815375ms16812026/10/25 19:06:46 WARN Failed to register uploaded object key=rbvarpjnmvgxphmsfjsl6jj08fhz9q2l.ls error="server returned 404: 404 page not found\n"16822026/10/25 19:06:46 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16832026/10/25 19:06:46 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"16842026/10/25 19:06:46 INFO Signed narinfos id=1 count=116852026/10/25 19:06:46 INFO Uploading 1 narinfos16862026/10/25 19:06:46 INFO Received complete push request method=POST path=/api/pushes/1/complete16872026/10/25 19:06:46 WARN Failed to register uploaded object key=rbvarpjnmvgxphmsfjsl6jj08fhz9q2l.narinfo error="server returned 404: 404 page not found\n"1688--- PASS: TestClientMultipleUploads (8.04s)1689=== CONT TestProxyWriteTimeout/unknown_size16902026/10/25 19:06:46 INFO Completed push id=1 objects=3 duration=30.034917ms16912026/10/25 19:06:46 INFO Upload complete. (398ms)1692=== CONT TestProxyWriteTimeout/1_GiB_nar1693=== CONT TestPendingClosureWriteTimeout/empty1694=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1695--- PASS: TestClientCADerivations (8.15s)16962026/10/25 19:06:46 INFO Received uploads request method=POST path=/1697=== CONT TestProxyWriteTimeout/10_GiB_nar1698--- PASS: TestProxyWriteTimeout (0.00s)1699 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1700 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1701 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1702 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1703=== CONT TestPendingClosureWriteTimeout/670k_objects1704=== CONT TestPendingClosureWriteTimeout/400_objects1705=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1706=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key17072026/10/25 19:06:46 INFO Received request for more parts method=POST path=/1708=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key17092026/10/25 19:06:46 INFO Received complete multipart upload request method=POST path=/1710=== CONT TestParseSingleRange/none1711=== CONT TestIsValidUploadKey/narinfo1712=== CONT TestParseSingleRange/start_far_past_EOF1713=== CONT TestParseSingleRange/start_past_EOF1714=== CONT TestParseSingleRange/single_byte1715=== CONT TestParseSingleRange/suffix_exceeds_size1716=== CONT TestParseSingleRange/suffix1717=== CONT TestParseSingleRange/end_clamped_to_size1718=== CONT TestParseSingleRange/open-ended1719=== CONT TestParseSingleRange/closed1720=== CONT TestParseSingleRange/malformed_end_before_start1721=== CONT TestParseSingleRange/malformed_both_empty1722=== CONT TestParseSingleRange/malformed_no_dash1723=== CONT TestParseSingleRange/multi-range_ignored1724=== CONT TestParseSingleRange/unknown_unit1725=== CONT TestIsValidUploadKey/unknown_type1726=== CONT TestIsValidUploadKey/empty_key1727=== CONT TestIsValidUploadKey/absolute1728--- PASS: TestParseSingleRange (0.05s)1729 --- PASS: TestParseSingleRange/none (0.00s)1730 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1731 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1732 --- PASS: TestParseSingleRange/single_byte (0.00s)1733 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1734 --- PASS: TestParseSingleRange/suffix (0.00s)1735 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1736 --- PASS: TestParseSingleRange/open-ended (0.00s)1737 --- PASS: TestParseSingleRange/closed (0.00s)1738 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1739 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1740 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1741 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1742 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1743=== CONT TestIsValidUploadKey/traversal_nar1744=== CONT TestIsValidUploadKey/traversal1745=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1746=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1747=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1748=== CONT TestIsValidUploadKey/index.html1749=== CONT TestIsValidUploadKey/nix-cache-info1750=== CONT TestIsValidUploadKey/realisation_plus_in_output1751=== CONT TestIsValidUploadKey/realisation1752=== CONT TestIsValidUploadKey/build_log_equals1753=== CONT TestIsValidUploadKey/build_log_question_mark1754=== CONT TestIsValidUploadKey/build_log_plus_in_name1755=== CONT TestIsValidUploadKey/build_log_home-manager_file1756=== CONT TestIsValidUploadKey/build_log1757=== CONT TestIsValidUploadKey/listing1758=== CONT TestIsValidUploadKey/nar_plain1759=== CONT TestIsValidUploadKey/nar_xz1760=== CONT TestIsValidUploadKey/nar_zst1761--- PASS: TestIsValidUploadKey (0.05s)1762 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1763 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1764 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1765 --- PASS: TestIsValidUploadKey/absolute (0.00s)1766 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1767 --- PASS: TestIsValidUploadKey/traversal (0.00s)1768 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1769 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1770 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1771 --- PASS: TestIsValidUploadKey/index.html (0.00s)1772 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1773 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1774 --- PASS: TestIsValidUploadKey/realisation (0.00s)1775 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1776 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1777 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1778 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1779 --- PASS: TestIsValidUploadKey/build_log (0.00s)1780 --- PASS: TestIsValidUploadKey/listing (0.00s)1781 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1782 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1783 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1784=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal17852026/10/25 19:06:46 INFO Received uploads request method=POST path=/1786--- PASS: TestUploadHandlersRejectInvalidKeys (0.05s)1787 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1788 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.01s)1789 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1790 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.01s)1791=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure17922026/10/25 19:06:46 INFO Received uploads request method=POST path=/17932026/10/25 19:06:46 INFO Received push request method=POST path=/api/pushes17942026/10/25 19:06:46 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17952026/10/25 19:06:46 INFO Uploading yqdgmdryiv0w1vyx3avf53632m42ji02-unpinned-file.txt (128B)17962026/10/25 19:06:46 WARN Failed to register uploaded object key=yqdgmdryiv0w1vyx3avf53632m42ji02.ls error="server returned 404: 404 page not found\n"17972026/10/25 19:06:46 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign17982026/10/25 19:06:46 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"17992026/10/25 19:06:47 INFO Signed narinfos id=2 count=118002026/10/25 19:06:47 INFO Uploading 1 narinfos1801=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1802=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1803=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1804=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1805=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1806=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1807=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured18082026/10/25 19:06:47 INFO Received complete push request method=POST path=/api/pushes/2/complete1809=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1810=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts18112026/10/25 19:06:47 WARN Failed to register uploaded object key=yqdgmdryiv0w1vyx3avf53632m42ji02.narinfo error="server returned 404: 404 page not found\n"18122026/10/25 19:06:47 INFO Completed push id=2 objects=3 duration=618.459µs18132026/10/25 19:06:47 INFO Received request for more parts method=POST path=/18142026/10/25 19:06:47 INFO Upload complete. (195ms)1815=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart18162026/10/25 19:06:47 INFO Received complete multipart upload request method=POST path=/1817=== CONT TestServerTLSConfig/no_client_CA1818=== CONT TestServerTLSConfig/not_a_PEM_file18192026/10/25 19:06:47 INFO Starting cleanup of old closures method=DELETE path=/api/closures18202026/10/25 19:06:47 INFO Garbage collection started18212026/10/25 19:06:47 INFO Aborted multipart uploads count=0 kept=018222026/10/25 19:06:47 WARN Force mode enabled - objects will be deleted immediately without grace period1823=== CONT TestServerTLSConfig/missing_CA_file1824--- PASS: TestServerTLSConfig (0.00s)1825 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1826 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.03s)1827 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1828=== CONT TestGCEndsOnShutdown/before_the_run1829=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1830--- PASS: TestUploadHandlersRejectOversizedBody (0.08s)1831 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.02s)1832 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.02s)1833 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.27s)18342026/10/25 19:06:47 INFO Received push request method=POST path=/api/pushes1835--- PASS: TestService_ReadScope_PublicByDefault (7.23s)1836=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete18372026/10/25 19:06:47 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)18382026/10/25 19:06:47 INFO Uploading 3n5h3q5spf975pwmwvzkdapk4qsf120x-top (264B)18392026/10/25 19:06:47 INFO Uploading 1b6hni080wcar93nb8kvxdw634cl9r8q-shared-dep (136B)18402026/10/25 19:06:47 WARN Failed to register uploaded object key=3n5h3q5spf975pwmwvzkdapk4qsf120x.ls error="server returned 404: 404 page not found\n"18412026/10/25 19:06:47 WARN Failed to register uploaded object key=nar/01rn984kahngc8bjjjgvyk4y9xdv0p0lsi6x47qx5s00k31y8iij.nar.zst error="server returned 404: 404 page not found\n"18422026/10/25 19:06:47 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"18432026/10/25 19:06:47 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18442026/10/25 19:06:47 WARN Failed to register uploaded object key=1b6hni080wcar93nb8kvxdw634cl9r8q.ls error="server returned 404: 404 page not found\n"18452026/10/25 19:06:47 INFO Signed narinfos id=1 count=218462026/10/25 19:06:47 INFO Uploading 2 narinfos18472026/10/25 19:06:47 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=01848=== NAME TestClientIntegration1849 client_integration_test.go:323: Objects in database after GC:1850 client_integration_test.go:323: Successfully deleted all objects with GC --force18512026/10/25 19:06:47 WARN Failed to register uploaded object key=3n5h3q5spf975pwmwvzkdapk4qsf120x.narinfo error="server returned 404: 404 page not found\n"18522026/10/25 19:06:47 INFO Received complete push request method=POST path=/api/pushes/1/complete18532026/10/25 19:06:47 WARN Failed to register uploaded object key=1b6hni080wcar93nb8kvxdw634cl9r8q.narinfo error="server returned 404: 404 page not found\n"18542026/10/25 19:06:47 INFO Completed push id=1 objects=6 duration=40.216584ms18552026/10/25 19:06:47 INFO Upload complete. (351ms)1856=== NAME TestClientSharedPathCommittedMidPush1857 client_integration_test.go:680: Retrieved narinfo from S3:1858 StorePath: /private/var/tb/3/scratch/0f9658a1e8df3254/build/TestClientSharedPathCommittedMidPush3956192699/001/store/1b6hni080wcar93nb8kvxdw634cl9r8q-shared-dep1859 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1860 Compression: zstd1861 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821862 NarSize: 1361863 References: 1864 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1865 client_integration_test.go:680: Retrieved narinfo from S3:1866 StorePath: /private/var/tb/3/scratch/0f9658a1e8df3254/build/TestClientSharedPathCommittedMidPush3956192699/001/store/3n5h3q5spf975pwmwvzkdapk4qsf120x-top1867 URL: nar/01rn984kahngc8bjjjgvyk4y9xdv0p0lsi6x47qx5s00k31y8iij.nar.zst1868 Compression: zstd1869 NarHash: sha256:01rn984kahngc8bjjjgvyk4y9xdv0p0lsi6x47qx5s00k31y8iij1870 NarSize: 2641871 References: /private/var/tb/3/scratch/0f9658a1e8df3254/build/TestClientSharedPathCommittedMidPush3956192699/001/store/1b6hni080wcar93nb8kvxdw634cl9r8q-shared-dep1872 CA: text:sha256:080a913v10gl61wgw1pk90idfmabigw3pjqwzj46csp5zcnq1gp718732026/10/25 19:06:47 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=01874--- PASS: TestClientIntegration (10.06s)1875=== CONT TestPush_RejectsBadRequests/root_not_in_objects18762026/10/25 19:06:47 INFO Received push request method=POST path=/api/pushes1877=== CONT TestPush_RejectsBadRequests/no_objects18782026/10/25 19:06:47 INFO Received push request method=POST path=/api/pushes1879=== CONT TestPush_RejectsBadRequests/bad_root18802026/10/25 19:06:47 INFO Received push request method=POST path=/api/pushes1881=== CONT TestPush_RejectsBadRequests/no_roots18822026/10/25 19:06:47 INFO Received push request method=POST path=/api/pushes1883--- PASS: TestPush_RejectsBadRequests (8.03s)1884 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)1885 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)1886 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)1887 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)1888=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows18892026/10/25 19:06:47 INFO Vacuumed table table=pending_closures1890--- PASS: TestClientSharedPathCommittedMidPush (7.98s)1891=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check18922026/10/25 19:06:47 INFO Vacuumed table table=pending_objects18932026/10/25 19:06:47 INFO Vacuumed table table=multipart_uploads18942026/10/25 19:06:47 INFO Vacuumed table table=closures18952026/10/25 19:06:47 INFO Vacuumed table table=objects1896--- PASS: TestDeleteClosuresRacingPins (12.60s)1897=== CONT TestResolveDBConnectionString/flag_wins1898=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1899=== CONT TestResolveDBConnectionString/nothing_configured1900=== CONT TestResolveDBConnectionString/missing_file_is_an_error1901=== CONT TestResolveDBConnectionString/file_when_flag_empty1902--- PASS: TestResolveDBConnectionString (0.00s)1903 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1904 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1905 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1906 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1907 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)1908=== CONT TestClientErrorHandling/InvalidStorePath1909--- PASS: TestReadProxyNarStreaming (7.24s)1910=== CONT TestClientErrorHandling/ServerNotAvailable1911=== NAME TestClientWithDependencies1912 client_integration_test.go:613: Built derivation: /private/var/tb/3/scratch/0f9658a1e8df3254/build/TestClientWithDependencies3374743923/001/store/if1pwp5q43bid70xvvnx8f94951kl4sx-test-script1913 client_integration_test.go:615: Found 1 dependencies (including self)1914=== RUN TestService_RequireScope_OIDC/builder_may_write1915=== PAUSE TestService_RequireScope_OIDC/builder_may_write1916=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1917=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1918=== RUN TestService_RequireScope_OIDC/ops_may_admin1919=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1920=== RUN TestService_RequireScope_OIDC/ops_may_not_write1921=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1922=== RUN TestService_RequireScope_OIDC/reader_may_not_write1923=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1924=== RUN TestService_RequireScope_OIDC/static_token_may_admin1925=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1926=== RUN TestService_RequireScope_OIDC/static_token_may_write1927=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1928=== RUN TestService_RequireScope_OIDC/reader_may_read1929=== PAUSE TestService_RequireScope_OIDC/reader_may_read1930=== RUN TestService_RequireScope_OIDC/writer_implies_read1931=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1932=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1933=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1934=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1935=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc1936=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1937=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1938=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1939=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1940=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1941=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1942=== CONT TestClientErrorHandling/InvalidAuthToken19432026/10/25 19:06:48 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/present19442026/10/25 19:06:48 INFO Received push request method=POST path=/api/pushes19452026/10/25 19:06:48 WARN Request failed, retrying attempt=2 backoff=217.240118ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present19462026/10/25 19:06:48 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)19472026/10/25 19:06:48 INFO Uploading if1pwp5q43bid70xvvnx8f94951kl4sx-test-script (136B)19482026/10/25 19:06:48 WARN Failed to register uploaded object key=if1pwp5q43bid70xvvnx8f94951kl4sx.ls error="server returned 404: 404 page not found\n"19492026/10/25 19:06:48 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"19502026/10/25 19:06:48 WARN Failed to register uploaded object key=log/c401v2ica93pp3cxrrf7rpbv60c6sd8d-test-script.drv error="server returned 404: 404 page not found\n"19512026/10/25 19:06:48 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19522026/10/25 19:06:48 INFO Signed narinfos id=1 count=119532026/10/25 19:06:48 INFO Uploading 1 narinfos19542026/10/25 19:06:48 INFO Received complete push request method=POST path=/api/pushes/1/complete19552026/10/25 19:06:48 WARN Failed to register uploaded object key=if1pwp5q43bid70xvvnx8f94951kl4sx.narinfo error="server returned 404: 404 page not found\n"1956--- PASS: TestReadProxyConditionalGet (7.38s)1957=== CONT TestCacheConfigHandler/full_config,_no_issuer19582026/10/25 19:06:48 INFO Completed push id=1 objects=4 duration=34.986709ms1959=== CONT TestCacheConfigHandler/no_signing_keys19602026/10/25 19:06:48 INFO Upload complete. (314ms)1961=== CONT TestCacheConfigHandler/no_cache_url_configured1962=== NAME TestClientWithDependencies1963 client_integration_test.go:617: Skipping nix copy test - isolated store (/private/var/tb/3/scratch/0f9658a1e8df3254/build/TestClientWithDependencies3374743923/001/store) requires matching store prefix1964=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1965--- PASS: TestCacheConfigHandler (0.00s)1966 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1967 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1968 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1969 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1970=== CONT TestIsValidCachePath/narinfo1971=== CONT TestIsValidCachePath/index.html1972=== CONT TestIsValidCachePath/short_hash1973=== CONT TestIsValidCachePath/wrong_extension1974=== CONT TestIsValidCachePath/leading_slash1975=== CONT TestIsValidCachePath/empty1976=== CONT TestIsValidCachePath/random_path1977=== CONT TestIsValidCachePath/invalid_char_u1978=== CONT TestIsValidCachePath/invalid_char_e1979=== CONT TestIsValidCachePath/traversal_in_middle19802026/10/25 19:06:48 WARN Request failed, retrying attempt=3 backoff=401.325321ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present1981=== CONT TestIsValidCachePath/traversal_parent1982=== CONT TestIsValidCachePath/nar_uncompressed1983=== CONT TestIsValidCachePath/nix-cache-info1984=== CONT TestIsValidCachePath/realisation1985=== CONT TestIsValidCachePath/log1986=== CONT TestIsValidCachePath/ls1987=== CONT TestIsValidCachePath/nar_zst1988=== CONT TestIsValidCachePath/nar_bz21989=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1990=== CONT TestIsValidCachePath/nar_xz1991--- PASS: TestIsValidCachePath (0.03s)1992 --- PASS: TestIsValidCachePath/narinfo (0.00s)1993 --- PASS: TestIsValidCachePath/index.html (0.00s)1994 --- PASS: TestIsValidCachePath/short_hash (0.00s)1995 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1996 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1997 --- PASS: TestIsValidCachePath/empty (0.00s)1998 --- PASS: TestIsValidCachePath/random_path (0.00s)1999 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)2000 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)2001 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)2002 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)2003 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)2004 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)2005 --- PASS: TestIsValidCachePath/realisation (0.00s)2006 --- PASS: TestIsValidCachePath/log (0.00s)2007 --- PASS: TestIsValidCachePath/ls (0.00s)2008 --- PASS: TestIsValidCachePath/nar_zst (0.00s)2009 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)2010 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)2011 --- PASS: TestIsValidCachePath/nar_xz (0.00s)2012=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2013=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected20142026/10/25 19:06:48 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]2015=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2016=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected20172026/10/25 19:06:48 WARN Authentication failed token_preview=eyJhbGciOi...eeq_1jQOwQ token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2018=== CONT TestService_RequireScope_OIDC/builder_may_write2019=== CONT TestService_RequireScope_OIDC/reader_may_read2020=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read2021=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read20222026/10/25 19:06:48 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]2023=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc2024=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc2025=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2026--- PASS: TestService_AuthMiddleware_OIDC (7.23s)2027 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2028 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.01s)2029 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2030 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.01s)2031=== CONT TestService_RequireScope_OIDC/writer_implies_read2032=== CONT TestService_RequireScope_OIDC/reader_may_not_write2033=== CONT TestService_RequireScope_OIDC/static_token_may_write2034=== CONT TestService_RequireScope_OIDC/static_token_may_admin2035=== CONT TestService_RequireScope_OIDC/ops_may_admin2036=== CONT TestService_RequireScope_OIDC/ops_may_not_write2037=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2038--- PASS: TestService_RequireScope_OIDC (7.40s)2039 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2040 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2041 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)2042 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)2043 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)2044 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)2045 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2046 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2047 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2048 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2049 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2050 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2051 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2052 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2053--- PASS: TestClientWithDependencies (8.65s)20542026/10/25 19:06:49 WARN Request failed, retrying attempt=4 backoff=819.774471ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20552026/10/25 19:06:49 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=020562026/10/25 19:06:49 INFO Received create pin request method=POST path=/api/pins/myapp2057--- PASS: TestReadProxyInvalidPath (7.38s)20582026/10/25 19:06:49 INFO Created/updated pin name=myapp store_path=/private/var/tb/3/scratch/0f9658a1e8df3254/build/TestPinProtectsFromGC1595554872/001/store/rbvarpjnmvgxphmsfjsl6jj08fhz9q2l-pinned-file.txt narinfo_key=rbvarpjnmvgxphmsfjsl6jj08fhz9q2l.narinfo20592026/10/25 19:06:49 INFO Starting cleanup of old closures method=DELETE path=/api/closures20602026/10/25 19:06:49 INFO Garbage collection started20612026/10/25 19:06:49 INFO Aborted multipart uploads count=0 kept=020622026/10/25 19:06:49 WARN Force mode enabled - objects will be deleted immediately without grace period20632026/10/25 19:06:49 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=020642026/10/25 19:06:49 INFO Vacuumed table table=pending_closures20652026/10/25 19:06:49 INFO Vacuumed table table=pending_objects20662026/10/25 19:06:49 INFO Vacuumed table table=multipart_uploads20672026/10/25 19:06:49 INFO Vacuumed table table=closures20682026/10/25 19:06:49 INFO Vacuumed table table=objects20692026/10/25 19:06:49 WARN Request failed, retrying attempt=5 backoff=1.505267077s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2070--- PASS: TestReadProxyHead (7.47s)2071--- PASS: TestReadProxy404 (8.08s)20722026/10/25 19:06:50 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>2073--- PASS: TestReadProxyNarinfo (7.21s)2074--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (7.04s)2075--- PASS: TestReadProxyContentNegotiation (7.57s)2076=== NAME TestPinProtectsFromGC2077 client_integration_test.go:840: Pin successfully protected closure from garbage collection2078--- PASS: TestPinProtectsFromGC (12.53s)2079--- PASS: TestReadProxyNarinfoAlreadyDecompressed (7.14s)20802026/10/25 19:06:51 WARN Request failed, retrying attempt=1 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20812026/10/25 19:06:51 WARN Request failed, retrying attempt=2 backoff=200.302786ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2082--- PASS: TestService_ReadAuthMiddleware (6.52s)20832026/10/25 19:06:51 WARN Request failed, retrying attempt=3 backoff=380.389395ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20842026/10/25 19:06:52 WARN Request failed, retrying attempt=4 backoff=723.180524ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20852026/10/25 19:06:52 INFO Received uploads request method=POST path=/api/pending_closures2086--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.01s)2087 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (7.30s)2088 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (6.25s)20892026/10/25 19:06:52 WARN Request failed, retrying attempt=5 backoff=1.753070785s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2090--- PASS: TestPendingClosureWriteTimeout (0.05s)2091 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2092 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2093 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2094 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (6.28s)2095--- PASS: TestReadProxyOutlastsServerWriteTimeout (11.68s)20962026/10/25 19:06:54 INFO Aborted multipart uploads count=0 kept=020972026/10/25 19:06:54 WARN Force mode enabled - objects will be deleted immediately without grace period20982026/10/25 19:06:54 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:55432/bucket95/?delete=\": context canceled"20992026/10/25 19:06:54 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"21002026/10/25 19:06:54 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-config21012026/10/25 19:06:54 WARN Request failed, retrying attempt=2 backoff=208.04091ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21022026/10/25 19:06:54 INFO Aborted multipart uploads count=0 kept=021032026/10/25 19:06:54 WARN Force mode enabled - objects will be deleted immediately without grace period21042026-10-25 19:06:54.884 UTC [21672] ERROR: canceling statement due to user request21052026-10-25 19:06:54.884 UTC [21672] STATEMENT: -- name: MarkStaleObjects :execrows2106 WITH RECURSIVE ct AS (2107 SELECT timezone('UTC', now()) AS now2108 ),2109 closure_reach AS (2110 -- Start with all closure keys2111 SELECT o.key, o.refs2112 FROM objects o2113 INNER JOIN closures c ON o.key = c.key2114 UNION2115 -- Recursively add all referenced objects2116 SELECT o.key, o.refs2117 FROM objects o2118 INNER JOIN closure_reach cr ON o.key = ANY(cr.refs)2119 ),2120 reachable_objects AS (2121 SELECT DISTINCT key FROM closure_reach2122 ),2123 stale_objects AS (2124 SELECT o.key2125 FROM objects AS o, ct2126 WHERE2127 NOT EXISTS (2128 SELECT 12129 FROM reachable_objects ro2130 WHERE ro.key = o.key2131 )2132 AND NOT EXISTS (2133 SELECT 12134 FROM pending_objects AS po2135 WHERE po.key = o.key2136 )2137 AND o.deleted_at IS NULL -- Only mark fresh objects2138 ORDER BY o.key COLLATE "C" -- lock in key order, like commit_pending_closure2139 FOR UPDATE2140 )2141 UPDATE objects2142 SET2143 deleted_at = ct.now,2144 first_deleted_at = COALESCE(first_deleted_at, ct.now)2145 FROM stale_objects, ct2146 WHERE objects.key = stale_objects.key2147 2148--- PASS: TestGCEndsOnShutdown (0.00s)2149 --- PASS: TestGCEndsOnShutdown/before_the_run (6.17s)2150 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (6.79s)2151 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (7.72s)21522026/10/25 19:06:54 WARN Request failed, retrying attempt=3 backoff=387.585642ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21532026/10/25 19:06:55 WARN Request failed, retrying attempt=4 backoff=753.230254ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21542026/10/25 19:06:55 INFO Received uploads request method=POST path=/api/pending_closures21552026/10/25 19:06:55 INFO Aborted multipart uploads count=0 kept=021562026/10/25 19:06:55 WARN Force mode enabled - objects will be deleted immediately without grace period21572026/10/25 19:06:56 WARN Request failed, retrying attempt=5 backoff=1.477221125s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21582026/10/25 19:06:56 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=021592026/10/25 19:06:56 INFO Vacuumed table table=pending_closures21602026/10/25 19:06:56 INFO Vacuumed table table=pending_objects21612026/10/25 19:06:56 INFO Vacuumed table table=multipart_uploads21622026/10/25 19:06:56 INFO Vacuumed table table=closures21632026/10/25 19:06:56 INFO Vacuumed table table=objects21642026/10/25 19:06:56 INFO Received uploads request method=POST path=/api/pending_closures21652026/10/25 19:06:56 INFO Aborted multipart uploads count=0 kept=021662026/10/25 19:06:56 WARN Force mode enabled - objects will be deleted immediately without grace period21672026/10/25 19:06:56 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=021682026/10/25 19:06:56 INFO Vacuumed table table=pending_closures21692026/10/25 19:06:56 INFO Vacuumed table table=pending_objects21702026/10/25 19:06:56 INFO Vacuumed table table=multipart_uploads21712026/10/25 19:06:56 INFO Vacuumed table table=closures21722026/10/25 19:06:56 INFO Vacuumed table table=objects2173--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2174 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (9.35s)2175 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (9.59s)21762026/10/25 19:06:57 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_closures21772026/10/25 19:06:57 WARN Request failed, retrying attempt=2 backoff=205.853163ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2178=== NAME TestOrphanedObjectsGCStressTest2179 orphaned_objects_gc_test.go:503: Stress test completed successfully:2180 orphaned_objects_gc_test.go:504: - Active objects preserved: 202181 orphaned_objects_gc_test.go:505: - Objects deleted: 2102182 orphaned_objects_gc_test.go:506: - Total GC'd: 2102183--- PASS: TestOrphanedObjectsGCStressTest (36.52s)21842026/10/25 19:06:57 WARN Request failed, retrying attempt=3 backoff=367.2294ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21852026/10/25 19:06:58 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"21862026/10/25 19:06:58 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"21872026/10/25 19:06:58 WARN Request failed, retrying attempt=4 backoff=801.664301ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21882026/10/25 19:06:59 WARN Request failed, retrying attempt=5 backoff=1.559373735s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2189--- PASS: TestClientErrorHandling (0.00s)2190 --- PASS: TestClientErrorHandling/InvalidStorePath (9.73s)2191 --- PASS: TestClientErrorHandling/InvalidAuthToken (9.77s)2192 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.63s)2193PASS21942026-10-25 19:07:00.800 UTC [21224] LOG: received smart shutdown request21952026-10-25 19:07:00.801 UTC [21224] LOG: background worker "logical replication launcher" (PID 21234) exited with exit code 121962026-10-25 19:07:00.821 UTC [21229] LOG: shutting down21972026-10-25 19:07:00.822 UTC [21229] LOG: checkpoint starting: shutdown immediate21982026-10-25 19:07:02.139 UTC [21229] LOG: checkpoint complete: wrote 12824 buffers (78.3%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 31 recycled; write=0.640 s, sync=0.663 s, total=1.318 s; sync files=34045, longest=0.013 s, average=0.001 s; distance=502017 kB, estimate=502017 kB; lsn=0/201CD508, redo lsn=0/201CD50821992026-10-25 19:07:02.146 UTC [21224] LOG: database system is shut down2200Running OIDC tests...2201=== RUN TestAudienceForIssuer2202=== PAUSE TestAudienceForIssuer2203=== RUN TestGlobMatch2204=== PAUSE TestGlobMatch2205=== RUN TestValidateToken_ValidToken2206=== PAUSE TestValidateToken_ValidToken2207=== RUN TestValidateToken_WrongAudience2208=== PAUSE TestValidateToken_WrongAudience2209=== RUN TestValidateToken_Expired2210=== PAUSE TestValidateToken_Expired2211=== RUN TestValidateToken_BoundClaimsMismatch2212=== PAUSE TestValidateToken_BoundClaimsMismatch2213=== RUN TestValidateToken_BoundSubjectMismatch2214=== PAUSE TestValidateToken_BoundSubjectMismatch2215=== RUN TestValidateToken_MultipleProviders2216=== PAUSE TestValidateToken_MultipleProviders2217=== RUN TestValidateToken_NoMatchingProvider2218=== PAUSE TestValidateToken_NoMatchingProvider2219=== RUN TestValidateToken_KubernetesServiceAccount2220=== PAUSE TestValidateToken_KubernetesServiceAccount2221=== RUN TestNewValidator_KubernetesRequiresCA2222=== PAUSE TestNewValidator_KubernetesRequiresCA2223=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2224=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2225=== RUN TestPins_ReservedForMatchingRule2226=== PAUSE TestPins_ReservedForMatchingRule2227=== RUN TestPins_TopLevelShorthand2228=== PAUSE TestPins_TopLevelShorthand2229=== RUN TestPins_ConfigValidation2230=== PAUSE TestPins_ConfigValidation2231=== RUN TestScopes_LegacyProviderDefaultsToWrite2232=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2233=== RUN TestScopes_Rules2234=== PAUSE TestScopes_Rules2235=== RUN TestScopes_ConfigValidation2236=== PAUSE TestScopes_ConfigValidation2237=== CONT TestAudienceForIssuer2238--- PASS: TestAudienceForIssuer (0.00s)2239=== CONT TestValidateToken_ValidToken2240=== CONT TestValidateToken_BoundClaimsMismatch2241=== CONT TestPins_ConfigValidation2242=== CONT TestValidateToken_WrongAudience2243=== CONT TestValidateToken_Expired2244=== CONT TestGlobMatch2245=== RUN TestGlobMatch/foo_foo2246=== PAUSE TestGlobMatch/foo_foo2247=== RUN TestGlobMatch/foo_bar2248=== PAUSE TestGlobMatch/foo_bar2249=== RUN TestGlobMatch/*_2250=== PAUSE TestGlobMatch/*_2251=== RUN TestGlobMatch/*_anything2252=== PAUSE TestGlobMatch/*_anything2253=== RUN TestGlobMatch/foo*_foo2254=== PAUSE TestGlobMatch/foo*_foo2255=== RUN TestGlobMatch/foo*_foobar2256=== PAUSE TestGlobMatch/foo*_foobar2257=== RUN TestGlobMatch/foo*_bar2258=== PAUSE TestGlobMatch/foo*_bar2259=== RUN TestGlobMatch/*bar_bar2260=== PAUSE TestGlobMatch/*bar_bar2261=== RUN TestGlobMatch/*bar_foobar2262=== PAUSE TestGlobMatch/*bar_foobar2263=== RUN TestGlobMatch/*bar_foo2264=== PAUSE TestGlobMatch/*bar_foo2265=== RUN TestGlobMatch/foo*bar_foobar2266=== PAUSE TestGlobMatch/foo*bar_foobar2267=== RUN TestGlobMatch/foo*bar_foo123bar2268=== PAUSE TestGlobMatch/foo*bar_foo123bar2269=== RUN TestGlobMatch/foo*bar_foobarbaz2270=== PAUSE TestGlobMatch/foo*bar_foobarbaz2271=== RUN TestGlobMatch/*/*_foo/bar2272=== PAUSE TestGlobMatch/*/*_foo/bar2273=== RUN TestGlobMatch/*/*_foo2274=== PAUSE TestGlobMatch/*/*_foo2275=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2276=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2277=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02278=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02279=== RUN TestGlobMatch/refs/*/main_refs/heads/main2280=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2281=== RUN TestGlobMatch/fo?_foo2282=== PAUSE TestGlobMatch/fo?_foo2283=== RUN TestGlobMatch/fo?_fo2284=== PAUSE TestGlobMatch/fo?_fo2285=== RUN TestGlobMatch/fo?_fooo2286=== PAUSE TestGlobMatch/fo?_fooo2287=== RUN TestGlobMatch/?oo_foo2288=== PAUSE TestGlobMatch/?oo_foo2289=== RUN TestGlobMatch/?oo_boo2290=== PAUSE TestGlobMatch/?oo_boo2291=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2292=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2293=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2294=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2295=== CONT TestGlobMatch/foo_foo2296=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2297=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2298=== CONT TestGlobMatch/?oo_boo2299=== CONT TestGlobMatch/?oo_foo2300=== CONT TestGlobMatch/fo?_fooo2301=== CONT TestGlobMatch/fo?_fo2302=== CONT TestGlobMatch/fo?_foo2303=== CONT TestGlobMatch/refs/*/main_refs/heads/main2304=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02305=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2306=== CONT TestGlobMatch/*/*_foo2307=== CONT TestGlobMatch/*/*_foo/bar2308=== CONT TestGlobMatch/foo*bar_foobarbaz2309=== CONT TestGlobMatch/foo*bar_foo123bar2310=== CONT TestGlobMatch/foo*bar_foobar2311=== CONT TestGlobMatch/*bar_foo2312=== CONT TestGlobMatch/*bar_foobar2313=== CONT TestGlobMatch/*bar_bar2314=== CONT TestGlobMatch/foo*_bar2315=== CONT TestGlobMatch/foo*_foobar2316=== CONT TestGlobMatch/foo*_foo2317=== CONT TestGlobMatch/*_anything2318=== CONT TestGlobMatch/*_2319=== CONT TestGlobMatch/foo_bar2320--- PASS: TestGlobMatch (0.00s)2321 --- PASS: TestGlobMatch/foo_foo (0.00s)2322 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2323 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2324 --- PASS: TestGlobMatch/?oo_boo (0.00s)2325 --- PASS: TestGlobMatch/?oo_foo (0.00s)2326 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2327 --- PASS: TestGlobMatch/fo?_fo (0.00s)2328 --- PASS: TestGlobMatch/fo?_foo (0.00s)2329 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2330 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2331 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2332 --- PASS: TestGlobMatch/*/*_foo (0.00s)2333 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2334 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2335 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2336 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2337 --- PASS: TestGlobMatch/*bar_foo (0.00s)2338 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2339 --- PASS: TestGlobMatch/*bar_bar (0.00s)2340 --- PASS: TestGlobMatch/foo*_bar (0.00s)2341 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2342 --- PASS: TestGlobMatch/foo*_foo (0.00s)2343 --- PASS: TestGlobMatch/*_anything (0.00s)2344 --- PASS: TestGlobMatch/*_ (0.00s)2345 --- PASS: TestGlobMatch/foo_bar (0.00s)2346=== CONT TestValidateToken_MultipleProviders2347=== CONT TestValidateToken_NoMatchingProvider2348=== CONT TestValidateToken_BoundSubjectMismatch2349=== CONT TestPins_ReservedForMatchingRule2350--- PASS: TestPins_ConfigValidation (0.01s)2351=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2352=== CONT TestPins_TopLevelShorthand2353=== CONT TestNewValidator_KubernetesRequiresCA2354=== CONT TestValidateToken_KubernetesServiceAccount2355=== CONT TestScopes_ConfigValidation2356--- PASS: TestScopes_ConfigValidation (0.00s)2357=== CONT TestScopes_Rules2358=== CONT TestScopes_LegacyProviderDefaultsToWrite23592026/10/25 19:07:03 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:5591023602026/10/25 19:07:03 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55912/oidc2361--- PASS: TestValidateToken_KubernetesServiceAccount (0.06s)23622026/10/25 19:07:03 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232363--- PASS: TestValidateToken_BoundSubjectMismatch (0.09s)23642026/10/25 19:07:03 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55916/oidc2365--- PASS: TestValidateToken_Expired (0.10s)2366--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.09s)23672026/10/25 19:07:03 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55919/oidc23682026/10/25 19:07:03 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55921/oidc2369--- PASS: TestValidateToken_WrongAudience (0.11s)2370--- PASS: TestValidateToken_BoundClaimsMismatch (0.11s)23712026/10/25 19:07:03 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55923/oidc2372--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.09s)23732026/10/25 19:07:03 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55926/oidc23742026/10/25 19:07:03 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55925/oidc2375--- PASS: TestPins_ReservedForMatchingRule (0.13s)23762026/10/25 19:07:03 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55930/oidc2377--- PASS: TestScopes_Rules (0.11s)2378--- PASS: TestValidateToken_ValidToken (0.14s)23792026/10/25 19:07:03 http: TLS handshake error from 127.0.0.1:55934: read tcp 127.0.0.1:55933->127.0.0.1:55934: use of closed network connection2380--- PASS: TestNewValidator_KubernetesRequiresCA (0.13s)23812026/10/25 19:07:03 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:55929/oidc23822026/10/25 19:07:03 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55936/oidc2383--- PASS: TestValidateToken_NoMatchingProvider (0.15s)2384--- PASS: TestPins_TopLevelShorthand (0.14s)23852026/10/25 19:07:03 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:55931/oidc23862026/10/25 19:07:03 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:55939/oidc2387--- PASS: TestValidateToken_MultipleProviders (0.16s)2388PASS2389Running hook tests...2390=== RUN TestSendPathsEmpty2391=== PAUSE TestSendPathsEmpty2392=== RUN TestQueueEnqueueAndFetch2393=== PAUSE TestQueueEnqueueAndFetch2394=== RUN TestQueueDeduplication2395=== PAUSE TestQueueDeduplication2396=== RUN TestQueueRemove2397=== PAUSE TestQueueRemove2398=== RUN TestQueueFetchBatchLimit2399=== PAUSE TestQueueFetchBatchLimit2400=== RUN TestQueueRetryMovesToBack2401=== PAUSE TestQueueRetryMovesToBack2402=== RUN TestQueueFetchRemoveLifecycle2403=== PAUSE TestQueueFetchRemoveLifecycle2404=== RUN TestQueueConcurrentWriters2405=== PAUSE TestQueueConcurrentWriters2406=== RUN TestQueueRemoveLargeClosure2407=== PAUSE TestQueueRemoveLargeClosure2408=== RUN TestServerClientIntegration2409--- PASS: TestServerClientIntegration (0.00s)2410=== RUN TestServerQueueError24112026/10/25 19:07:04 ERROR Failed to queue paths error="permission denied" count=12412--- PASS: TestServerQueueError (0.00s)2413=== RUN TestGetListenerSocketActivation2414 server_test.go:145: systemd socket activation does not exist on darwin2415--- SKIP: TestGetListenerSocketActivation (0.00s)2416=== RUN TestServerStalledClientDoesNotBlockShutdown2417=== PAUSE TestServerStalledClientDoesNotBlockShutdown2418=== RUN TestServerBacksOffOnAcceptErrors2419=== PAUSE TestServerBacksOffOnAcceptErrors2420=== RUN TestDrainIsolatesPoisonPath2421=== PAUSE TestDrainIsolatesPoisonPath2422=== RUN TestRunNotBlockedByPoisonHead2423=== PAUSE TestRunNotBlockedByPoisonHead2424=== RUN TestDrainGivesUpWhenServerDown2425=== PAUSE TestDrainGivesUpWhenServerDown2426=== RUN TestFailedPathPrunedByLaterClosure2427=== PAUSE TestFailedPathPrunedByLaterClosure2428=== RUN TestWorkerUploadsAndRemoves2429=== PAUSE TestWorkerUploadsAndRemoves2430=== RUN TestWorkerSkipsGCdPaths2431=== PAUSE TestWorkerSkipsGCdPaths2432=== RUN TestWorkerPrunesClosureDeps2433=== PAUSE TestWorkerPrunesClosureDeps2434=== RUN TestDrainTimeout2435=== PAUSE TestDrainTimeout2436=== RUN TestWorkerRemoveFailureIsNotProgress2437=== PAUSE TestWorkerRemoveFailureIsNotProgress2438=== RUN TestWorkerKeepsPathItCannotStat2439=== PAUSE TestWorkerKeepsPathItCannotStat2440=== CONT TestSendPathsEmpty2441=== CONT TestDrainIsolatesPoisonPath2442--- PASS: TestSendPathsEmpty (0.00s)2443=== CONT TestServerBacksOffOnAcceptErrors24442026/10/25 19:07:04 ERROR Accept failed error="too many open files"2445=== CONT TestServerStalledClientDoesNotBlockShutdown2446=== CONT TestQueueRemoveLargeClosure2447=== CONT TestQueueConcurrentWriters2448=== CONT TestQueueFetchRemoveLifecycle2449=== CONT TestQueueRetryMovesToBack2450=== CONT TestQueueFetchBatchLimit2451=== CONT TestQueueRemove2452=== CONT TestQueueDeduplication2453=== CONT TestQueueEnqueueAndFetch2454=== CONT TestWorkerSkipsGCdPaths2455=== CONT TestFailedPathPrunedByLaterClosure2456=== CONT TestWorkerKeepsPathItCannotStat2457=== CONT TestWorkerUploadsAndRemoves2458=== CONT TestWorkerRemoveFailureIsNotProgress2459=== CONT TestDrainTimeout2460=== CONT TestWorkerPrunesClosureDeps2461=== CONT TestDrainGivesUpWhenServerDown2462=== CONT TestRunNotBlockedByPoisonHead24632026/10/25 19:07:04 ERROR Accept failed error="too many open files"24642026/10/25 19:07:04 INFO Upload queue status pending=224652026/10/25 19:07:04 INFO Uploading batch count=124662026/10/25 19:07:04 INFO Uploading batch count=224672026/10/25 19:07:04 ERROR Upload failed error="upload failed" count=224682026/10/25 19:07:04 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/3/scratch/0f9658a1e8df3254/build/TestDrainGivesUpWhenServerDown3362715127/002/a2469--- PASS: TestQueueFetchRemoveLifecycle (0.01s)2470--- PASS: TestQueueFetchBatchLimit (0.01s)24712026/10/25 19:07:04 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/3/scratch/0f9658a1e8df3254/build/TestDrainGivesUpWhenServerDown3362715127/002/b24722026/10/25 19:07:04 INFO Upload queue status pending=224732026/10/25 19:07:04 INFO Upload queue status pending=324742026/10/25 19:07:04 INFO Uploading batch count=224752026/10/25 19:07:04 ERROR Upload failed error="upload failed" count=224762026/10/25 19:07:04 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/3/scratch/0f9658a1e8df3254/build/TestDrainGivesUpWhenServerDown3362715127/002/c24772026/10/25 19:07:04 INFO Uploading batch count=124782026/10/25 19:07:04 ERROR Upload failed error="upload failed" count=124792026/10/25 19:07:04 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/3/scratch/0f9658a1e8df3254/build/TestWorkerSkipsGCdPaths2919507614/002/nonexistent24802026/10/25 19:07:04 INFO Uploading batch count=124812026/10/25 19:07:04 ERROR Upload failed error="upload failed" count=124822026/10/25 19:07:04 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/3/scratch/0f9658a1e8df3254/build/TestDrainGivesUpWhenServerDown3362715127/002/d24832026/10/25 19:07:04 INFO Uploading batch count=124842026/10/25 19:07:04 INFO Uploading batch count=224852026/10/25 19:07:04 ERROR Upload failed error="upload failed" count=224862026/10/25 19:07:04 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/3/scratch/0f9658a1e8df3254/build/TestDrainGivesUpWhenServerDown3362715127/002/e24872026/10/25 19:07:04 INFO Uploading batch count=124882026/10/25 19:07:04 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/3/scratch/0f9658a1e8df3254/build/TestDrainGivesUpWhenServerDown3362715127/002/f2489--- PASS: TestQueueDeduplication (0.01s)24902026/10/25 19:07:04 INFO Uploading batch count=124912026/10/25 19:07:04 ERROR Drain finished with paths left in queue remaining=1024922026/10/25 19:07:04 ERROR Accept failed error="too many open files"24932026/10/25 19:07:04 INFO Uploading batch count=224942026/10/25 19:07:04 WARN Cannot stat store path, will retry later path=/private/var/tb/3/scratch/0f9658a1e8df3254/build/TestWorkerKeepsPathItCannotStat1867568795/002/locked/aaa error="stat /private/var/tb/3/scratch/0f9658a1e8df3254/build/TestWorkerKeepsPathItCannotStat1867568795/002/locked/aaa: permission denied"2495--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)2496--- PASS: TestQueueEnqueueAndFetch (0.02s)24972026/10/25 19:07:04 INFO Upload queue status pending=224982026/10/25 19:07:04 INFO Uploading batch count=224992026/10/25 19:07:04 WARN Cannot stat store path, will retry later path=/private/var/tb/3/scratch/0f9658a1e8df3254/build/TestWorkerKeepsPathItCannotStat1867568795/002/locked/aaa error="stat /private/var/tb/3/scratch/0f9658a1e8df3254/build/TestWorkerKeepsPathItCannotStat1867568795/002/locked/aaa: permission denied"25002026/10/25 19:07:04 INFO Uploading batch count=425012026/10/25 19:07:04 ERROR Upload failed error="upload failed" count=42502--- PASS: TestQueueRemove (0.02s)25032026/10/25 19:07:04 WARN Cannot stat store path, will retry later path=/private/var/tb/3/scratch/0f9658a1e8df3254/build/TestWorkerKeepsPathItCannotStat1867568795/002/locked/aaa error="stat /private/var/tb/3/scratch/0f9658a1e8df3254/build/TestWorkerKeepsPathItCannotStat1867568795/002/locked/aaa: permission denied"25042026/10/25 19:07:04 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/3/scratch/0f9658a1e8df3254/build/TestDrainIsolatesPoisonPath3537896226/002/bbb25052026/10/25 19:07:04 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/3/scratch/0f9658a1e8df3254/build/TestWorkerRemoveFailureIsNotProgress4137485866/002/nonexistent25062026/10/25 19:07:04 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=125072026/10/25 19:07:04 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/3/scratch/0f9658a1e8df3254/build/TestWorkerRemoveFailureIsNotProgress4137485866/002/nonexistent25082026/10/25 19:07:04 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=125092026/10/25 19:07:04 ERROR Drain finished with paths left in queue remaining=125102026/10/25 19:07:04 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/3/scratch/0f9658a1e8df3254/build/TestWorkerRemoveFailureIsNotProgress4137485866/002/nonexistent25112026/10/25 19:07:04 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=125122026/10/25 19:07:04 ERROR Drain finished with paths left in queue remaining=12513--- PASS: TestQueueRetryMovesToBack (0.02s)25142026/10/25 19:07:04 INFO Uploading batch count=125152026/10/25 19:07:04 ERROR Upload failed error="upload failed" count=12516--- PASS: TestWorkerRemoveFailureIsNotProgress (0.02s)25172026/10/25 19:07:04 INFO Uploading batch count=125182026/10/25 19:07:04 ERROR Upload failed error="upload failed" count=125192026/10/25 19:07:04 INFO Uploading batch count=125202026/10/25 19:07:04 ERROR Upload failed error="upload failed" count=12521--- PASS: TestDrainGivesUpWhenServerDown (0.02s)25222026/10/25 19:07:04 ERROR Drain finished with paths left in queue remaining=12523--- PASS: TestWorkerKeepsPathItCannotStat (0.02s)2524--- PASS: TestDrainIsolatesPoisonPath (0.02s)2525--- PASS: TestWorkerPrunesClosureDeps (0.03s)2526--- PASS: TestWorkerSkipsGCdPaths (0.03s)25272026/10/25 19:07:04 ERROR Accept failed error="too many open files"2528--- PASS: TestWorkerUploadsAndRemoves (0.04s)2529--- PASS: TestQueueRemoveLargeClosure (0.05s)25302026/10/25 19:07:04 ERROR Accept failed error="too many open files"25312026/10/25 19:07:04 ERROR Accept failed error="too many open files"2532--- PASS: TestQueueConcurrentWriters (0.16s)25332026/10/25 19:07:04 ERROR Failed to decode request error="read unix /private/var/tb/3/scratch/0f9658a1e8df3254/build/hook2247884692/test.sock->: i/o timeout"25342026/10/25 19:07:04 ERROR Failed to write response error="write unix /private/var/tb/3/scratch/0f9658a1e8df3254/build/hook2247884692/test.sock->: i/o timeout"2535--- PASS: TestServerStalledClientDoesNotBlockShutdown (0.20s)25362026/10/25 19:07:04 ERROR Upload failed error="context deadline exceeded" count=225372026/10/25 19:07:04 ERROR Drain finished with paths left in queue remaining=42538--- PASS: TestDrainTimeout (0.22s)25392026/10/25 19:07:04 ERROR Accept failed error="too many open files"25402026/10/25 19:07:04 ERROR Accept failed error="too many open files"2541--- PASS: TestServerBacksOffOnAcceptErrors (0.64s)25422026/10/25 19:07:05 INFO Uploading batch count=125432026/10/25 19:07:05 INFO Uploading batch count=125442026/10/25 19:07:05 INFO Uploading batch count=125452026/10/25 19:07:05 ERROR Upload failed error="upload failed" count=125462026/10/25 19:07:05 INFO Uploading batch count=125472026/10/25 19:07:05 ERROR Upload failed error="upload failed" count=125482026/10/25 19:07:05 INFO Uploading batch count=125492026/10/25 19:07:05 ERROR Upload failed error="upload failed" count=125502026/10/25 19:07:05 INFO Uploading batch count=125512026/10/25 19:07:05 ERROR Upload failed error="upload failed" count=125522026/10/25 19:07:05 ERROR Drain finished with paths left in queue remaining=12553--- PASS: TestRunNotBlockedByPoisonHead (1.02s)2554PASS2555Running signing tests...2556=== RUN TestExternalSigner2557=== PAUSE TestExternalSigner2558=== RUN TestExternalSignerWrongPublicKey2559=== PAUSE TestExternalSignerWrongPublicKey2560=== RUN TestExternalSignerErrors2561=== PAUSE TestExternalSignerErrors2562=== RUN TestExternalSignerRestartsAfterCrash2563=== PAUSE TestExternalSignerRestartsAfterCrash2564=== RUN TestExternalSignerProgramErrorKeepsProcess2565=== PAUSE TestExternalSignerProgramErrorKeepsProcess2566=== RUN TestExternalSignerClose2567=== PAUSE TestExternalSignerClose2568=== RUN TestExternalSignerRejectsInvalidPublicKey2569=== PAUSE TestExternalSignerRejectsInvalidPublicKey2570=== RUN TestExternalSignerCancellation2571=== PAUSE TestExternalSignerCancellation2572=== RUN TestGenerateFingerprint2573=== PAUSE TestGenerateFingerprint2574=== RUN TestParseSigningKey2575=== PAUSE TestParseSigningKey2576=== RUN TestSign2577=== PAUSE TestSign2578=== RUN TestSignBatch2579=== PAUSE TestSignBatch2580=== RUN TestNilKeyPublicKey2581=== PAUSE TestNilKeyPublicKey2582=== RUN TestSignErrors2583=== PAUSE TestSignErrors2584=== CONT TestExternalSigner2585=== CONT TestExternalSignerCancellation2586=== CONT TestSignBatch2587=== CONT TestExternalSignerProgramErrorKeepsProcess2588=== CONT TestParseSigningKey2589=== RUN TestParseSigningKey/valid_32-byte_key2590=== PAUSE TestParseSigningKey/valid_32-byte_key2591=== CONT TestGenerateFingerprint2592=== RUN TestGenerateFingerprint/basic_with_references2593=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2594=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2595=== CONT TestSign2596=== CONT TestExternalSignerErrors2597=== RUN TestParseSigningKey/no_colon2598=== RUN TestExternalSignerErrors/exit_at_startup2599=== PAUSE TestParseSigningKey/no_colon2600=== RUN TestParseSigningKey/empty_name2601=== PAUSE TestParseSigningKey/empty_name2602=== PAUSE TestExternalSignerErrors/exit_at_startup2603=== RUN TestExternalSignerErrors/too_few_signatures2604=== PAUSE TestExternalSignerErrors/too_few_signatures2605=== RUN TestExternalSignerErrors/exit_on_request2606=== RUN TestParseSigningKey/invalid_base642607=== CONT TestExternalSignerRejectsInvalidPublicKey2608=== RUN TestExternalSignerRejectsInvalidPublicKey/#002609=== CONT TestExternalSignerClose2610=== CONT TestSignErrors2611=== CONT TestNilKeyPublicKey2612--- PASS: TestNilKeyPublicKey (0.00s)2613=== PAUSE TestGenerateFingerprint/basic_with_references2614=== RUN TestGenerateFingerprint/no_references2615=== PAUSE TestGenerateFingerprint/no_references2616=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2617=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2618=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2619=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2620=== RUN TestGenerateFingerprint/invalid_nar_hash_length2621=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2622=== RUN TestGenerateFingerprint/invalid_store_path_prefix2623=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2624=== RUN TestGenerateFingerprint/invalid_reference_prefix2625=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2626=== CONT TestGenerateFingerprint/basic_with_references2627=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2628=== CONT TestGenerateFingerprint/no_references2629=== CONT TestGenerateFingerprint/invalid_nar_hash_length2630=== CONT TestExternalSignerWrongPublicKey2631=== PAUSE TestExternalSignerErrors/exit_on_request2632=== RUN TestExternalSignerErrors/invalid_JSON2633=== PAUSE TestExternalSignerErrors/invalid_JSON2634=== RUN TestExternalSignerErrors/missing_signatures2635=== PAUSE TestParseSigningKey/invalid_base642636=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002637=== RUN TestParseSigningKey/wrong_length2638=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2639=== PAUSE TestParseSigningKey/wrong_length2640=== CONT TestParseSigningKey/valid_32-byte_key2641=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2642=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2643=== CONT TestParseSigningKey/empty_name2644=== CONT TestParseSigningKey/wrong_length2645=== CONT TestGenerateFingerprint/invalid_reference_prefix2646=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2647=== PAUSE TestExternalSignerErrors/missing_signatures2648=== RUN TestExternalSignerErrors/null_signatures2649=== PAUSE TestExternalSignerErrors/null_signatures2650=== RUN TestExternalSignerErrors/unrequested_key2651=== PAUSE TestExternalSignerErrors/unrequested_key2652=== CONT TestExternalSignerRestartsAfterCrash2653=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2654=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2655=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2656=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2657=== CONT TestGenerateFingerprint/invalid_store_path_prefix2658--- PASS: TestGenerateFingerprint (0.00s)2659 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2660 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2661 --- PASS: TestGenerateFingerprint/no_references (0.00s)2662 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2663 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2664 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2665 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2666=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2667=== CONT TestParseSigningKey/no_colon2668=== CONT TestParseSigningKey/invalid_base642669=== RUN TestExternalSignerErrors/wrong_signature_name2670=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2671=== PAUSE TestExternalSignerErrors/wrong_signature_name2672=== CONT TestExternalSignerRejectsInvalidPublicKey/#002673=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2674=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2675=== RUN TestExternalSignerErrors/invalid_signature_base642676=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2677=== PAUSE TestExternalSignerErrors/invalid_signature_base642678=== RUN TestExternalSignerErrors/wrong_signature_length2679=== PAUSE TestExternalSignerErrors/wrong_signature_length2680=== RUN TestExternalSignerErrors/null2681=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2682=== PAUSE TestExternalSignerErrors/null2683=== RUN TestExternalSignerErrors/wrong_id2684=== PAUSE TestExternalSignerErrors/wrong_id2685=== RUN TestExternalSignerErrors/wrong_signatures_shape2686--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2687 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2688 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2689 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2690 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2691 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2692=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2693=== RUN TestExternalSignerErrors/wrong_shape2694=== PAUSE TestExternalSignerErrors/wrong_shape2695=== RUN TestExternalSignerErrors/missing_signature_name2696=== PAUSE TestExternalSignerErrors/missing_signature_name2697=== RUN TestExternalSignerErrors/program_error2698=== PAUSE TestExternalSignerErrors/program_error2699=== CONT TestExternalSignerErrors/invalid_signature_base642700=== CONT TestExternalSignerErrors/exit_at_startup2701=== CONT TestExternalSignerErrors/wrong_signatures_shape2702=== CONT TestExternalSignerErrors/wrong_id2703=== CONT TestExternalSignerErrors/wrong_signature_length2704=== CONT TestExternalSignerErrors/missing_signatures2705--- PASS: TestSign (0.00s)2706=== CONT TestExternalSignerErrors/missing_signature_name2707=== CONT TestExternalSignerErrors/invalid_JSON2708=== RUN TestSignErrors/nil_key2709=== PAUSE TestSignErrors/nil_key2710=== RUN TestSignErrors/nil_narinfo2711=== CONT TestExternalSignerErrors/wrong_shape2712=== CONT TestExternalSignerErrors/program_error2713=== CONT TestExternalSignerErrors/exit_on_request2714=== CONT TestExternalSignerErrors/unrequested_key2715=== CONT TestExternalSignerErrors/wrong_signature_name2716=== CONT TestExternalSignerErrors/null2717=== CONT TestExternalSignerErrors/null_signatures2718=== CONT TestExternalSignerErrors/too_few_signatures2719=== PAUSE TestSignErrors/nil_narinfo2720=== RUN TestSignErrors/invalid_narinfo2721--- PASS: TestSignBatch (0.00s)2722--- PASS: TestParseSigningKey (0.00s)2723 --- PASS: TestParseSigningKey/empty_name (0.00s)2724 --- PASS: TestParseSigningKey/wrong_length (0.00s)2725 --- PASS: TestParseSigningKey/no_colon (0.00s)2726 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2727 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2728 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2729=== PAUSE TestSignErrors/invalid_narinfo2730=== RUN TestSignErrors/canceled2731=== PAUSE TestSignErrors/canceled2732=== CONT TestSignErrors/nil_key2733=== CONT TestSignErrors/nil_narinfo2734=== CONT TestSignErrors/invalid_narinfo2735=== CONT TestSignErrors/canceled2736--- PASS: TestSignErrors (0.00s)2737 --- PASS: TestSignErrors/nil_key (0.00s)2738 --- PASS: TestSignErrors/nil_narinfo (0.00s)2739 --- PASS: TestSignErrors/canceled (0.00s)2740 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2741--- PASS: TestExternalSignerCancellation (0.24s)2742--- PASS: TestExternalSignerProgramErrorKeepsProcess (0.41s)2743--- PASS: TestExternalSignerWrongPublicKey (0.80s)2744--- PASS: TestExternalSignerClose (1.37s)2745--- PASS: TestExternalSignerRestartsAfterCrash (1.76s)2746/private/var/tb/3/scratch/0f9658a1e8df3254/build/TestExternalSignerRestartsAfterCrash4068352273/001/sign program: line 7: /private/var/tb/3/scratch/0f9658a1e8df3254/build/TestExternalSignerRestartsAfterCrash4068352273/001/sign program.starts: No such file or directory2747--- PASS: TestExternalSigner (2.32s)2748--- PASS: TestExternalSignerErrors (0.00s)2749 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (0.59s)2750 --- PASS: TestExternalSignerErrors/invalid_JSON (0.99s)2751 --- PASS: TestExternalSignerErrors/wrong_shape (1.17s)2752 --- PASS: TestExternalSignerErrors/wrong_signature_name (1.55s)2753 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (1.93s)2754 --- PASS: TestExternalSignerErrors/null (2.11s)2755 --- PASS: TestExternalSignerErrors/program_error (2.49s)2756 --- PASS: TestExternalSignerErrors/null_signatures (2.69s)2757 --- PASS: TestExternalSignerErrors/missing_signatures (2.87s)2758 --- PASS: TestExternalSignerErrors/missing_signature_name (3.06s)2759 --- PASS: TestExternalSignerErrors/wrong_id (3.25s)2760 --- PASS: TestExternalSignerErrors/exit_at_startup (3.43s)2761 --- PASS: TestExternalSignerErrors/wrong_signature_length (3.67s)2762 --- PASS: TestExternalSignerErrors/too_few_signatures (3.85s)2763 --- PASS: TestExternalSignerErrors/exit_on_request (4.04s)2764 --- PASS: TestExternalSignerErrors/unrequested_key (4.24s)2765PASS2766Running OpenBao signer tests...2767=== RUN TestSign2768=== PAUSE TestSign2769=== RUN TestSignErrors2770=== PAUSE TestSignErrors2771=== RUN TestServe2772=== PAUSE TestServe2773=== RUN TestServeRejectsGarbage2774=== PAUSE TestServeRejectsGarbage2775=== CONT TestSign2776=== CONT TestServe2777=== CONT TestServeRejectsGarbage2778=== CONT TestSignErrors2779=== RUN TestSignErrors/http_error2780=== PAUSE TestSignErrors/http_error2781=== RUN TestSignErrors/invalid_json2782--- PASS: TestServeRejectsGarbage (0.00s)2783=== PAUSE TestSignErrors/invalid_json2784=== RUN TestSignErrors/no_prefix2785=== PAUSE TestSignErrors/no_prefix2786=== RUN TestSignErrors/invalid_base642787=== PAUSE TestSignErrors/invalid_base642788=== CONT TestSignErrors/http_error2789=== CONT TestSignErrors/no_prefix2790=== CONT TestSignErrors/invalid_base642791=== CONT TestSignErrors/invalid_json2792--- PASS: TestServe (0.00s)2793--- PASS: TestSign (0.00s)2794--- PASS: TestSignErrors (0.00s)2795 --- PASS: TestSignErrors/no_prefix (0.00s)2796 --- PASS: TestSignErrors/http_error (0.00s)2797 --- PASS: TestSignErrors/invalid_json (0.00s)2798 --- PASS: TestSignErrors/invalid_base64 (0.00s)2799PASS